# HG changeset patch # User dfuchs # Date 1521034533 0 # Node ID 065641767a75b2965743c6c9de0dcc4d826e2ba6 # Parent a82058c084ef0bb751cfbc2c7fb760608e85b28f http-client-branch: change websocket to use System.Logger for debug logging diff -r a82058c084ef -r 065641767a75 src/java.net.http/share/classes/jdk/internal/net/http/common/DebugLogger.java --- a/src/java.net.http/share/classes/jdk/internal/net/http/common/DebugLogger.java Wed Mar 14 13:03:11 2018 +0000 +++ b/src/java.net.http/share/classes/jdk/internal/net/http/common/DebugLogger.java Wed Mar 14 13:35:33 2018 +0000 @@ -47,8 +47,10 @@ class DebugLogger implements Logger { // deliberately not in the same subtree than standard loggers. final static String HTTP_NAME = "jdk.internal.httpclient.debug"; + final static String WS_NAME = "jdk.internal.httpclient.websocket.debug"; final static String HPACK_NAME = "jdk.internal.httpclient.hpack.debug"; final static Logger HTTP = System.getLogger(HTTP_NAME); + final static Logger WS = System.getLogger(WS_NAME); final static Logger HPACK = System.getLogger(HPACK_NAME); final static long START_NANOS = System.nanoTime(); @@ -245,6 +247,10 @@ return new DebugLogger(HTTP, dbgTag, outLevel, errLevel); } + public static DebugLogger createWebSocketLogger(Supplier dbgTag, Level outLevel, Level errLevel) { + return new DebugLogger(WS, dbgTag, outLevel, errLevel); + } + public static DebugLogger createHpackLogger(Supplier dbgTag, Level outLevel, Level errLevel) { return new DebugLogger(HPACK, dbgTag, outLevel, errLevel); } diff -r a82058c084ef -r 065641767a75 src/java.net.http/share/classes/jdk/internal/net/http/common/Utils.java --- a/src/java.net.http/share/classes/jdk/internal/net/http/common/Utils.java Wed Mar 14 13:03:11 2018 +0000 +++ b/src/java.net.http/share/classes/jdk/internal/net/http/common/Utils.java Wed Mar 14 13:35:33 2018 +0000 @@ -85,6 +85,8 @@ // } public static final boolean DEBUG = // Revisit: temporary dev flag. getBooleanProperty(DebugLogger.HTTP_NAME, false); + public static final boolean DEBUG_WS = // Revisit: temporary dev flag. + getBooleanProperty(DebugLogger.WS_NAME, false); public static final boolean DEBUG_HPACK = // Revisit: temporary dev flag. getBooleanProperty(DebugLogger.HPACK_NAME, false); public static final boolean TESTING = DEBUG; @@ -807,6 +809,72 @@ } /** + * Get a logger for debug WebSocket traces.The logger should only be used + * with levels whose severity is {@code <= DEBUG}. + * + * By default, this logger will forward all messages logged to an internal + * logger named "jdk.internal.httpclient.websocket.debug". + * In addition, if the message severity level is >= to + * the provided {@code errLevel} it will print the messages on stderr. + * The logger will add some decoration to the printed message, in the form of + * {@code :[] [] : } + * + * @apiNote To obtain a logger that will always print things on stderr in + * addition to forwarding to the internal logger, use + * {@code getWebSocketLogger(this::dbgTag, Level.ALL);}. + * This is also equivalent to calling + * {@code getWSLogger(this::dbgTag, true);}. + * To obtain a logger that will only forward to the internal logger, + * use {@code getWebSocketLogger(this::dbgTag, Level.OFF);}. + * This is also equivalent to calling + * {@code getWSLogger(this::dbgTag, false);}. + * + * @param dbgTag A lambda that returns a string that identifies the caller + * (e.g: "WebSocket(3)") + * @param errLevel The level above which messages will be also printed on + * stderr (in addition to be forwarded to the internal logger). + * + * @return A logger for HPACK internal debug traces + */ + public static Logger getWebSocketLogger(Supplier dbgTag, Level errLevel) { + Level outLevel = Level.OFF; + return DebugLogger.createWebSocketLogger(dbgTag, outLevel, errLevel); + } + + /** + * Get a logger for debug WebSocket traces.The logger should only be used + * with levels whose severity is {@code <= DEBUG}. + * + * By default, this logger will forward all messages logged to an internal + * logger named "jdk.internal.httpclient.websocket.debug". + * In addition, the provided boolean {@code on==true}, it will print the + * messages on stderr. + * The logger will add some decoration to the printed message, in the form of + * {@code :[] [] : } + * + * @apiNote To obtain a logger that will always print things on stderr in + * addition to forwarding to the internal logger, use + * {@code getWebSocketLogger(this::dbgTag, true);}. + * This is also equivalent to calling + * {@code getWebSocketLogger(this::dbgTag, Level.ALL);}. + * To obtain a logger that will only forward to the internal logger, + * use {@code getWebSocketLogger(this::dbgTag, false);}. + * This is also equivalent to calling + * {@code getHpackLogger(this::dbgTag, Level.OFF);}. + * + * @param dbgTag A lambda that returns a string that identifies the caller + * (e.g: "WebSocket(3)") + * @param on Whether messages should also be printed on + * stderr (in addition to be forwarded to the internal logger). + * + * @return A logger for WebSocket internal debug traces + */ + public static Logger getWebSocketLogger(Supplier dbgTag, boolean on) { + Level errLevel = on ? Level.ALL : Level.OFF; + return getWebSocketLogger(dbgTag, errLevel); + } + + /** * SSLSessions returned to user are wrapped in an immutable object */ public static SSLSession immutableSession(SSLSession session) { diff -r a82058c084ef -r 065641767a75 src/java.net.http/share/classes/jdk/internal/net/http/websocket/MessageDecoder.java --- a/src/java.net.http/share/classes/jdk/internal/net/http/websocket/MessageDecoder.java Wed Mar 14 13:03:11 2018 +0000 +++ b/src/java.net.http/share/classes/jdk/internal/net/http/websocket/MessageDecoder.java Wed Mar 14 13:35:33 2018 +0000 @@ -25,6 +25,7 @@ package jdk.internal.net.http.websocket; +import jdk.internal.net.http.common.Utils; import jdk.internal.net.http.websocket.Frame.Opcode; import java.net.http.WebSocket.MessagePart; @@ -33,6 +34,7 @@ import java.nio.charset.CharacterCodingException; import static java.lang.String.format; +import java.lang.System.Logger.Level; import static java.nio.charset.StandardCharsets.UTF_8; import static java.util.Objects.requireNonNull; import static jdk.internal.net.http.common.Utils.dump; @@ -49,7 +51,10 @@ /* Exposed for testing purposes */ class MessageDecoder implements Frame.Consumer { - private final static boolean DEBUG = false; + private static final boolean DEBUG = Utils.DEBUG_WS; + private static final System.Logger debug = + Utils.getWebSocketLogger("[Input]"::toString, DEBUG); + private final MessageStreamConsumer output; private final UTF8AccumulatingDecoder decoder = new UTF8AccumulatingDecoder(); private boolean fin; @@ -70,17 +75,13 @@ @Override public void fin(boolean value) { - if (DEBUG) { - System.out.printf("[Input] fin %s%n", value); - } + debug.log(Level.DEBUG, "fin %s", value); fin = value; } @Override public void rsv1(boolean value) { - if (DEBUG) { - System.out.printf("[Input] rsv1 %s%n", value); - } + debug.log(Level.DEBUG, "rsv1 %s", value); if (value) { throw new FailWebSocketException("Unexpected rsv1 bit"); } @@ -88,9 +89,7 @@ @Override public void rsv2(boolean value) { - if (DEBUG) { - System.out.printf("[Input] rsv2 %s%n", value); - } + debug.log(Level.DEBUG, "rsv2 %s", value); if (value) { throw new FailWebSocketException("Unexpected rsv2 bit"); } @@ -98,9 +97,7 @@ @Override public void rsv3(boolean value) { - if (DEBUG) { - System.out.printf("[Input] rsv3 %s%n", value); - } + debug.log(Level.DEBUG, "rsv3 %s", value); if (value) { throw new FailWebSocketException("Unexpected rsv3 bit"); } @@ -108,9 +105,7 @@ @Override public void opcode(Opcode v) { - if (DEBUG) { - System.out.printf("[Input] opcode %s%n", v); - } + debug.log(Level.DEBUG, "opcode %s", v); if (v == Opcode.PING || v == Opcode.PONG || v == Opcode.CLOSE) { if (!fin) { throw new FailWebSocketException("Fragmented control frame " + v); @@ -138,9 +133,7 @@ @Override public void mask(boolean value) { - if (DEBUG) { - System.out.printf("[Input] mask %s%n", value); - } + debug.log(Level.DEBUG, "mask %s", value); if (value) { throw new FailWebSocketException("Masked frame received"); } @@ -148,9 +141,7 @@ @Override public void payloadLen(long value) { - if (DEBUG) { - System.out.printf("[Input] payloadLen %s%n", value); - } + debug.log(Level.DEBUG, "payloadLen %s", value); if (opcode.isControl()) { if (value > Frame.MAX_CONTROL_FRAME_PAYLOAD_LENGTH) { throw new FailWebSocketException( @@ -178,9 +169,7 @@ @Override public void payloadData(ByteBuffer data) { - if (DEBUG) { - System.out.printf("[Input] payload %s%n", data); - } + debug.log(Level.DEBUG, "payload %s", data); unconsumedPayloadLen -= data.remaining(); boolean isLast = unconsumedPayloadLen == 0; if (opcode.isControl()) { @@ -227,9 +216,7 @@ @Override public void endFrame() { - if (DEBUG) { - System.out.println("[Input] end frame"); - } + debug.log(Level.DEBUG, "end frame"); if (opcode.isControl()) { binaryData.flip(); } diff -r a82058c084ef -r 065641767a75 src/java.net.http/share/classes/jdk/internal/net/http/websocket/MessageEncoder.java --- a/src/java.net.http/share/classes/jdk/internal/net/http/websocket/MessageEncoder.java Wed Mar 14 13:03:11 2018 +0000 +++ b/src/java.net.http/share/classes/jdk/internal/net/http/websocket/MessageEncoder.java Wed Mar 14 13:35:33 2018 +0000 @@ -29,6 +29,7 @@ import jdk.internal.net.http.websocket.Frame.Opcode; import java.io.IOException; +import java.lang.System.Logger.Level; import java.nio.ByteBuffer; import java.nio.CharBuffer; import java.nio.charset.CharacterCodingException; @@ -48,7 +49,9 @@ */ public class MessageEncoder { - private final static boolean DEBUG = false; + private static final boolean DEBUG = Utils.DEBUG_WS; + private static final System.Logger debug = + Utils.getWebSocketLogger("[Output]"::toString, DEBUG); private final SecureRandom maskingKeySource = new SecureRandom(); private final Frame.HeaderWriter headerWriter = new Frame.HeaderWriter(); @@ -126,10 +129,8 @@ public boolean encodeText(CharBuffer src, boolean last, ByteBuffer dst) throws IOException { - if (DEBUG) { - System.out.printf("[Output] encodeText src.remaining()=%s, %s, %s%n", - src.remaining(), last, dst); - } + debug.log(Level.DEBUG, "encodeText src.remaining()=%s, %s, %s", + src.remaining(), last, dst); if (closed) { throw new IOException("Output closed"); } @@ -144,21 +145,15 @@ charsetEncoder.reset(); } while (true) { - if (DEBUG) { - System.out.printf("[Output] put%n"); - } + debug.log(Level.DEBUG, "put"); if (!putAvailable(headerBuffer, dst)) { return false; } - if (DEBUG) { - System.out.printf("[Output] mask%n"); - } + debug.log(Level.DEBUG, "mask"); if (maskAvailable(intermediateBuffer, dst) < 0) { return false; } - if (DEBUG) { - System.out.printf("[Output] moreText%n"); - } + debug.log(Level.DEBUG, "moreText"); if (!moreText) { previousFin = last; previousText = true; @@ -185,9 +180,7 @@ throw new IOException("Malformed text message", e); } } - if (DEBUG) { - System.out.printf("[Output] frame #%s%n", headerCount); - } + debug.log(Level.DEBUG, "frame #%s", headerCount); intermediateBuffer.flip(); Opcode opcode = previousFin && headerCount == 0 ? Opcode.TEXT : Opcode.CONTINUATION; @@ -214,10 +207,8 @@ public boolean encodeBinary(ByteBuffer src, boolean last, ByteBuffer dst) throws IOException { - if (DEBUG) { - System.out.printf("[Output] encodeBinary %s, %s, %s%n", - src, last, dst); - } + debug.log(Level.DEBUG, "encodeBinary %s, %s, %s", + src, last, dst); if (closed) { throw new IOException("Output closed"); } @@ -257,7 +248,7 @@ if (closed) { throw new IOException("Output closed"); } - if (DEBUG) System.out.printf("[Output] encodePing %s, %s%n", src, dst); + debug.log(Level.DEBUG, "encodePing %s, %s", src, dst); if (!started) { expectedLen = src.remaining(); if (expectedLen > Frame.MAX_CONTROL_FRAME_PAYLOAD_LENGTH) { @@ -283,10 +274,8 @@ if (closed) { throw new IOException("Output closed"); } - if (DEBUG) { - System.out.printf("[Output] encodePong %s, %s%n", - src, dst); - } + debug.log(Level.DEBUG, "encodePong %s, %s", + src, dst); if (!started) { expectedLen = src.remaining(); if (expectedLen > Frame.MAX_CONTROL_FRAME_PAYLOAD_LENGTH) { @@ -309,29 +298,21 @@ public boolean encodeClose(int statusCode, CharBuffer reason, ByteBuffer dst) throws IOException { - if (DEBUG) { - System.out.printf("[Output] encodeClose %s, reason.length=%s, %s%n", - statusCode, reason.length(), dst); - } + debug.log(Level.DEBUG, "encodeClose %s, reason.length=%s, %s", + statusCode, reason.length(), dst); if (closed) { throw new IOException("Output closed"); } if (!started) { - if (DEBUG) { - System.out.printf("[Output] reason size %s%n", reason.remaining()); - } + debug.log(Level.DEBUG, "reason size %s", reason.remaining()); intermediateBuffer.position(0).limit(Frame.MAX_CONTROL_FRAME_PAYLOAD_LENGTH); intermediateBuffer.putChar((char) statusCode); CoderResult r = charsetEncoder.reset().encode(reason, intermediateBuffer, true); if (r.isUnderflow()) { - if (DEBUG) { - System.out.printf("[Output] flushing%n"); - } + debug.log(Level.DEBUG, "flushing"); r = charsetEncoder.flush(intermediateBuffer); } - if (DEBUG) { - System.out.printf("[Output] encoding result: %s%n", r); - } + debug.log(Level.DEBUG, "encoding result: %s", r); if (r.isError()) { try { r.throwException(); @@ -348,10 +329,8 @@ setupHeader(Opcode.CLOSE, true, intermediateBuffer.remaining()); started = true; closed = true; - if (DEBUG) { - System.out.printf("[Output] intermediateBuffer=%s%n", - intermediateBuffer); - } + debug.log(Level.DEBUG, "intermediateBuffer=%s", + intermediateBuffer); } if (!putAvailable(headerBuffer, dst)) { return false; @@ -360,10 +339,8 @@ } private void setupHeader(Opcode opcode, boolean fin, long payloadLen) { - if (DEBUG) { - System.out.printf("[Output] frame opcode=%s fin=%s len=%s%n", - opcode, fin, payloadLen); - } + debug.log(Level.DEBUG, "frame opcode=%s fin=%s len=%s", + opcode, fin, payloadLen); headerBuffer.clear(); int mask = maskingKeySource.nextInt(); headerWriter.fin(fin) diff -r a82058c084ef -r 065641767a75 src/java.net.http/share/classes/jdk/internal/net/http/websocket/TransportImpl.java --- a/src/java.net.http/share/classes/jdk/internal/net/http/websocket/TransportImpl.java Wed Mar 14 13:03:11 2018 +0000 +++ b/src/java.net.http/share/classes/jdk/internal/net/http/websocket/TransportImpl.java Wed Mar 14 13:35:33 2018 +0000 @@ -32,6 +32,7 @@ import jdk.internal.net.http.common.Utils; import java.io.IOException; +import java.lang.System.Logger.Level; import java.nio.ByteBuffer; import java.nio.CharBuffer; import java.nio.channels.SelectionKey; @@ -50,7 +51,10 @@ // -- Debugging infrastructure -- - private final static boolean DEBUG = false; + private static final boolean DEBUG = Utils.DEBUG_WS; + private static final System.Logger debug = + Utils.getWebSocketLogger("[Transport]"::toString, DEBUG); + /* Used for correlating enters to and exists from a method */ private final AtomicLong counter = new AtomicLong(); @@ -92,21 +96,16 @@ private ByteBuffer createWriteBuffer() { String name = "jdk.httpclient.websocket.writeBufferSize"; int capacity = Utils.getIntegerNetProperty(name, 16384); - if (DEBUG) { - System.out.printf("[Transport] write buffer capacity %s%n", capacity); - } + debug.log(Level.DEBUG, "write buffer capacity %s%n", capacity); + // TODO (optimization?): allocateDirect if SSL? return ByteBuffer.allocate(capacity); } private boolean write() throws IOException { - if (DEBUG) { - System.out.printf("[Transport] writing to the channel%n"); - } + debug.log(Level.DEBUG, "writing to the channel%n"); long count = channel.write(dstArray, 0, dstArray.length); - if (DEBUG) { - System.out.printf("[Transport] %s bytes written%n", count); - } + debug.log(Level.DEBUG, "%s bytes written%n", count); for (ByteBuffer b : dstArray) { if (b.hasRemaining()) { return false; @@ -120,10 +119,10 @@ boolean isLast, T attachment, BiConsumer action) { - long id; - if (DEBUG) { + long id = 0; + if (debug.isLoggable(Level.DEBUG)) { id = counter.incrementAndGet(); - System.out.printf("[Transport] enter send text %s message.length()=%s last=%s%n", + debug.log(Level.DEBUG, "enter send text %s message.length()=%s last=%s%n", id, message.length(), isLast); } // TODO (optimization?): @@ -142,9 +141,7 @@ } catch (IOException e) { f.completeExceptionally(e); } - if (DEBUG) { - System.out.printf("[Transport] exit send text %s returned %s%n", id, f); - } + debug.log(Level.DEBUG, "exit send text %s returned %s%n", id, f); return f; } @@ -153,10 +150,10 @@ boolean isLast, T attachment, BiConsumer action) { - long id; - if (DEBUG) { + long id = 0; + if (debug.isLoggable(Level.DEBUG)) { id = counter.incrementAndGet(); - System.out.printf("[Transport] enter send binary %s message.remaining()=%s last=%s%n", + debug.log(Level.DEBUG, "enter send binary %s message.remaining()=%s last=%s%n", id, message.remaining(), isLast); } MinimalFuture f = new MinimalFuture<>(); @@ -166,9 +163,7 @@ } catch (IOException e) { f.completeExceptionally(e); } - if (DEBUG) { - System.out.printf("[Transport] exit send binary %s returned %s%n", id, f); - } + debug.log(Level.DEBUG, "exit send binary %s returned %s%n", id, f); return f; } @@ -176,10 +171,10 @@ public CompletableFuture sendPing(ByteBuffer message, T attachment, BiConsumer action) { - long id; - if (DEBUG) { + long id = 0; + if (debug.isLoggable(Level.DEBUG)) { id = counter.incrementAndGet(); - System.out.printf("[Transport] enter send ping %s message.remaining()=%s%n", + debug.log(Level.DEBUG, "enter send ping %s message.remaining()=%s%n", id, message.remaining()); } MinimalFuture f = new MinimalFuture<>(); @@ -189,9 +184,7 @@ } catch (IOException e) { f.completeExceptionally(e); } - if (DEBUG) { - System.out.printf("[Transport] exit send ping %s returned %s%n", id, f); - } + debug.log(Level.DEBUG, "exit send ping %s returned %s%n", id, f); return f; } @@ -199,10 +192,10 @@ public CompletableFuture sendPong(ByteBuffer message, T attachment, BiConsumer action) { - long id; - if (DEBUG) { + long id = 0; + if (debug.isLoggable(Level.DEBUG)) { id = counter.incrementAndGet(); - System.out.printf("[Transport] enter send pong %s message.remaining()=%s%n", + debug.log(Level.DEBUG, "enter send pong %s message.remaining()=%s%n", id, message.remaining()); } MinimalFuture f = new MinimalFuture<>(); @@ -212,9 +205,7 @@ } catch (IOException e) { f.completeExceptionally(e); } - if (DEBUG) { - System.out.printf("[Transport] exit send pong %s returned %s%n", id, f); - } + debug.log(Level.DEBUG, "exit send pong %s returned %s%n", id, f); return f; } @@ -222,11 +213,11 @@ public CompletableFuture sendPong(Supplier message, T attachment, BiConsumer action) { - long id; - if (DEBUG) { + long id = 0; + if (debug.isLoggable(Level.DEBUG)) { id = counter.incrementAndGet(); - System.out.printf("[Transport] enter send pong %s supplier=%s%n", - id, message); + debug.log(Level.DEBUG, "enter send pong %s supplier=%s%n", + id, message); } MinimalFuture f = new MinimalFuture<>(); try { @@ -235,9 +226,7 @@ } catch (IOException e) { f.completeExceptionally(e); } - if (DEBUG) { - System.out.printf("[Transport] exit send pong %s returned %s%n", id, f); - } + debug.log(Level.DEBUG, "exit send pong %s returned %s%n", id, f); return f; } @@ -246,10 +235,10 @@ String reason, T attachment, BiConsumer action) { - long id; - if (DEBUG) { + long id = 0; + if (debug.isLoggable(Level.DEBUG)) { id = counter.incrementAndGet(); - System.out.printf("[Transport] enter send close %s statusCode=%s, reason.length()=%s%n", + debug.log(Level.DEBUG, "enter send close %s statusCode=%s, reason.length()=%s", id, statusCode, reason.length()); } MinimalFuture f = new MinimalFuture<>(); @@ -259,17 +248,13 @@ } catch (IOException e) { f.completeExceptionally(e); } - if (DEBUG) { - System.out.printf("[Transport] exit send close %s returned %s%n", id, f); - } + debug.log(Level.DEBUG, "exit send close %s returned %s", id, f); return f; } @Override public void request(long n) { - if (DEBUG) { - System.out.printf("[Transport] request %s%n", n); - } + debug.log(Level.DEBUG, "request %s", n); if (demand.increase(n)) { receiveScheduler.runOrSchedule(); } @@ -285,9 +270,7 @@ @Override public void closeOutput() throws IOException { - if (DEBUG) { - System.out.printf("[Transport] closeOutput%n"); - } + debug.log(Level.DEBUG, "closeOutput"); synchronized (closeLock) { if (!outputClosed) { outputClosed = true; @@ -310,9 +293,7 @@ */ @Override public void closeInput() throws IOException { - if (DEBUG) { - System.out.printf("[Transport] closeInput%n"); - } + debug.log(Level.DEBUG, "closeInput"); synchronized (closeLock) { if (!inputClosed) { inputClosed = true; @@ -504,16 +485,12 @@ // Could have been only called in one of the following cases: // (a) A message has been added to the queue // (b) The channel is ready for writing - if (DEBUG) { - System.out.printf("[Transport] enter send task%n"); - } + debug.log(Level.DEBUG, "enter send task"); while (!queue.isEmpty()) { try { if (dst.hasRemaining()) { - if (DEBUG) { - System.out.printf("[Transport] %s bytes in buffer%n", + debug.log(Level.DEBUG, "%s bytes in buffer", dst.remaining()); - } // The previous part of the binary representation of the message // hasn't been fully written if (!tryCompleteWrite()) { @@ -523,9 +500,7 @@ if (firstPass) { firstPass = false; queue.peek(loadCallback); - if (DEBUG) { - System.out.printf("[Transport] load message%n"); - } + debug.log(Level.DEBUG, "load message"); } dst.clear(); encoded = queue.peek(encodingCallback); @@ -539,9 +514,7 @@ removeAndComplete(null); } } catch (Throwable t) { - if (DEBUG) { - System.out.printf("[Transport] send task exception %s%n", t); - } + debug.log(Level.DEBUG, "send task exception %s", (Object)t); // buffer cleanup: if there is an exception, the buffer // should appear empty for the next write as there is // nothing to write @@ -550,41 +523,29 @@ removeAndComplete(t); } } - if (DEBUG) { - System.out.printf("[Transport] exit send task%n"); - } + debug.log(Level.DEBUG, "exit send task"); } private boolean tryCompleteWrite() throws IOException { - if (DEBUG) { - System.out.printf("[Transport] enter writing%n"); - } + debug.log(Level.DEBUG, "enter writing"); boolean finished = false; loop: while (true) { final ChannelState ws = writeState.get(); - if (DEBUG) { - System.out.printf("[Transport] write state: %s%n", ws); - } + debug.log(Level.DEBUG, "write state: %s", ws); switch (ws) { case WAITING: break loop; case UNREGISTERED: - if (DEBUG) { - System.out.printf("[Transport] registering write event%n"); - } + debug.log(Level.DEBUG, "registering write event"); channel.registerEvent(writeEvent); writeState.compareAndSet(UNREGISTERED, WAITING); - if (DEBUG) { - System.out.printf("[Transport] registered write event%n"); - } + debug.log(Level.DEBUG, "registered write event"); break loop; case AVAILABLE: boolean written = write(); if (written) { - if (DEBUG) { - System.out.printf("[Transport] finished writing to the channel%n"); - } + debug.log(Level.DEBUG, "finished writing to the channel"); finished = true; break loop; // All done } else { @@ -597,18 +558,14 @@ throw new InternalError(String.valueOf(ws)); } } - if (DEBUG) { - System.out.printf("[Transport] exit writing%n"); - } + debug.log(Level.DEBUG, "exit writing"); return finished; } @SuppressWarnings("unchecked") private void removeAndComplete(Throwable error) { - if (DEBUG) { - System.out.printf("[Transport] removeAndComplete error=%s%n", - error); - } + debug.log(Level.DEBUG, "removeAndComplete error=%s", + (Object)error); queue.remove(); if (error != null) { try { @@ -635,16 +592,12 @@ @Override public void run() { - if (DEBUG) { - System.out.printf("[Transport] enter receive task%n"); - } + debug.log(Level.DEBUG, "enter receive task"); loop: while (!receiveScheduler.isStopped()) { if (data.hasRemaining()) { - if (DEBUG) { - System.out.printf("[Transport] remaining bytes received %s%n", + debug.log(Level.DEBUG, "remaining bytes received %s", data.remaining()); - } if (!demand.isFulfilled()) { try { int oldPos = data.position(); @@ -661,9 +614,7 @@ break loop; } final ChannelState rs = readState; - if (DEBUG) { - System.out.printf("[Transport] receive state: %s%n", rs); - } + debug.log(Level.DEBUG, "receive state: %s", rs); switch (rs) { case WAITING: break loop; @@ -698,9 +649,7 @@ throw new InternalError(String.valueOf(rs)); } } - if (DEBUG) { - System.out.printf("[Transport] exit receive task%n"); - } + debug.log(Level.DEBUG, "exit receive task"); } } @@ -713,16 +662,12 @@ @Override public void handle() { - if (DEBUG) { - System.out.printf("[Transport] write event%n"); - } + debug.log(Level.DEBUG, "write event"); ChannelState s; do { s = writeState.get(); if (s == CLOSED) { - if (DEBUG) { - System.out.printf("[Transport] write state %s%n", s); - } + debug.log(Level.DEBUG, "write state %s", s); break; } } while (!writeState.compareAndSet(s, AVAILABLE)); @@ -739,9 +684,7 @@ @Override public void handle() { - if (DEBUG) { - System.out.printf("[Transport] read event%n"); - } + debug.log(Level.DEBUG, "read event"); readState = AVAILABLE; receiveScheduler.runOrSchedule(); } diff -r a82058c084ef -r 065641767a75 src/java.net.http/share/classes/jdk/internal/net/http/websocket/WebSocketImpl.java --- a/src/java.net.http/share/classes/jdk/internal/net/http/websocket/WebSocketImpl.java Wed Mar 14 13:03:11 2018 +0000 +++ b/src/java.net.http/share/classes/jdk/internal/net/http/websocket/WebSocketImpl.java Wed Mar 14 13:35:33 2018 +0000 @@ -35,6 +35,7 @@ import java.io.IOException; import java.io.InterruptedIOException; import java.lang.ref.Reference; +import java.lang.System.Logger.Level; import java.net.ProtocolException; import java.net.URI; import java.net.http.WebSocket; @@ -71,7 +72,9 @@ */ public final class WebSocketImpl implements WebSocket { - private final static boolean DEBUG = false; + private static final boolean DEBUG = Utils.DEBUG_WS; + private static final System.Logger debug = + Utils.getWebSocketLogger("[Websocket]"::toString, DEBUG); private final AtomicLong sendCounter = new AtomicLong(); private final AtomicLong receiveCounter = new AtomicLong(); @@ -173,10 +176,8 @@ v = defaultValue; } } - if (DEBUG) { - System.out.printf("[WebSocket] %s=%s, using value %s%n", + debug.log(Level.DEBUG, "%s=%s, using value %s", property, value, v); - } return v; } @@ -186,10 +187,10 @@ public CompletableFuture sendText(CharSequence message, boolean isLast) { Objects.requireNonNull(message); - long id; - if (DEBUG) { + long id = 0; + if (debug.isLoggable(Level.DEBUG)) { id = sendCounter.incrementAndGet(); - System.out.printf("[WebSocket] %s send text: payload length=%s last=%s%n", + debug.log(Level.DEBUG, "%s send text: payload length=%s last=%s", id, message.length(), isLast); } CompletableFuture result; @@ -199,10 +200,10 @@ result = transport.sendText(message, isLast, this, (r, e) -> outstandingSend.set(false)); } - if (DEBUG) { - System.out.printf("[WebSocket] %s send text: returned %s%n", - id, result); - } + debug.log(Level.DEBUG, + "%s send text: returned %s", + id, result); + return replaceNull(result); } @@ -210,11 +211,12 @@ public CompletableFuture sendBinary(ByteBuffer message, boolean isLast) { Objects.requireNonNull(message); - long id; - if (DEBUG) { + long id = 0; + if (debug.isLoggable(Level.DEBUG)) { id = sendCounter.incrementAndGet(); - System.out.printf("[WebSocket] %s send binary: payload=%s last=%s%n", - id, message, isLast); + debug.log(Level.DEBUG, + "%s send binary: payload=%s last=%s", + id, message, isLast); } CompletableFuture result; if (!outstandingSend.compareAndSet(false, true)) { @@ -223,10 +225,8 @@ result = transport.sendBinary(message, isLast, this, (r, e) -> outstandingSend.set(false)); } - if (DEBUG) { - System.out.printf("[WebSocket] %s send binary: returned %s%n", - id, result); - } + debug.log(Level.DEBUG, + "%s send binary: returned %s", id, result); return replaceNull(result); } @@ -243,36 +243,31 @@ @Override public CompletableFuture sendPing(ByteBuffer message) { Objects.requireNonNull(message); - long id; - if (DEBUG) { + long id = 0; + if (debug.isLoggable(Level.DEBUG)) { id = sendCounter.incrementAndGet(); - System.out.printf("[WebSocket] %s send ping: payload=%s%n", + debug.log(Level.DEBUG, "%s send ping: payload=%s", id, message); } CompletableFuture result = transport.sendPing(message, this, (r, e) -> { }); - if (DEBUG) { - System.out.printf("[WebSocket] %s send ping: returned %s%n", - id, result); - } + debug.log(Level.DEBUG, "%s send ping: returned %s", id, result); return replaceNull(result); } @Override public CompletableFuture sendPong(ByteBuffer message) { Objects.requireNonNull(message); - long id; - if (DEBUG) { + long id = 0; + if (debug.isLoggable(Level.DEBUG)) { id = sendCounter.incrementAndGet(); - System.out.printf("[WebSocket] %s send pong: payload=%s%n", + debug.log(Level.DEBUG, "%s send pong: payload=%s", id, message); } CompletableFuture result = transport.sendPong(message, this, (r, e) -> { }); - if (DEBUG) { - System.out.printf("[WebSocket] %s send pong: returned %s%n", - id, result); - } + debug.log(Level.DEBUG, "%s send pong: returned %s", + id, result); return replaceNull(result); } @@ -280,11 +275,12 @@ public CompletableFuture sendClose(int statusCode, String reason) { Objects.requireNonNull(reason); - long id; - if (DEBUG) { + long id = 0; + if (debug.isLoggable(Level.DEBUG)) { id = sendCounter.incrementAndGet(); - System.out.printf("[WebSocket] %s send close: statusCode=%s, reason.length=%s%n", - id, statusCode, reason); + debug.log(Level.DEBUG, + "%s send close: statusCode=%s, reason.length=%s", + id, statusCode, reason); } CompletableFuture result; if (!isLegalToSendFromClient(statusCode)) { @@ -293,10 +289,8 @@ // check outputClosed result = sendClose0(statusCode, reason); } - if (DEBUG) { - System.out.printf("[WebSocket] %s send close: returned %s%n", - id, result); - } + debug.log(Level.DEBUG, "%s send close: returned %s", + id, result); return replaceNull(result); } @@ -318,12 +312,12 @@ private CompletionStage processCloseOutcome(WebSocket webSocket, Throwable e) { - if (DEBUG) { - System.out.printf("[WebSocket] send close completed, error=%s%n", e); - if (e != null) { - e.printStackTrace(System.out); - } + if (e == null) { + debug.log(Level.DEBUG, "send close completed successfully"); + } else { + debug.log(Level.DEBUG, "send close completed with error", e); } + if (e == null) { return completedFuture(webSocket); } @@ -348,9 +342,7 @@ @Override public void request(long n) { - if (DEBUG) { - System.out.printf("[WebSocket] request %s%n", n); - } + debug.log(Level.DEBUG, "request %s", n); if (demand.increase(n)) { receiveScheduler.runOrSchedule(); } @@ -373,9 +365,7 @@ @Override public void abort() { - if (DEBUG) { - System.out.printf("[WebSocket] abort %n"); - } + debug.log(Level.DEBUG, "abort "); inputClosed = true; outputClosed = true; receiveScheduler.stop(); @@ -412,15 +402,12 @@ @Override public void run() { - if (DEBUG) { - System.out.printf("[WebSocket] enter receive task%n"); - } + debug.log(Level.DEBUG, "enter receive task"); loop: while (true) { State s = state.get(); - if (DEBUG) { - System.out.printf("[WebSocket] receive state: %s%n", s); - } + debug.log(Level.DEBUG, "receive state: %s", s); + try { switch (s) { case OPEN: @@ -466,25 +453,20 @@ signalError(t); } } - if (DEBUG) { - System.out.printf("[WebSocket] exit receive task%n"); - } + debug.log(Level.DEBUG, "exit receive task"); } private void processError() throws IOException { - if (DEBUG) { - System.out.println("[WebSocket] processError"); - } + debug.log(Level.DEBUG, "processError"); transport.closeInput(); receiveScheduler.stop(); Throwable err = error.get(); if (err instanceof FailWebSocketException) { int code1 = ((FailWebSocketException) err).getStatusCode(); err = new ProtocolException().initCause(err); - if (DEBUG) { - System.out.printf("[WebSocket] failing %s with error=%s statusCode=%s%n", - WebSocketImpl.this, err, code1); - } + debug.log(Level.DEBUG, + "failing %s with error=%s statusCode=%s", + WebSocketImpl.this, err, code1); sendClose0(code1, "") // TODO handle errors from here .whenComplete( (r, e) -> { @@ -493,41 +475,36 @@ } }); } - long id; - if (DEBUG) { + long id = 0; + if (debug.isLoggable(Level.DEBUG)) { id = receiveCounter.incrementAndGet(); - System.out.printf("[WebSocket] enter onError %s error=%s%n", + debug.log(Level.DEBUG, "enter onError %s error=%s", id, err); } try { listener.onError(WebSocketImpl.this, err); } finally { - if (DEBUG) { - System.out.printf("[WebSocket] exit onError %s%n", id); - } + debug.log(Level.DEBUG, "exit onError %s", id); } } private void processClose() throws IOException { - if (DEBUG) { - System.out.println("[WebSocket] processClose"); - } + debug.log(Level.DEBUG, "processClose"); transport.closeInput(); receiveScheduler.stop(); CompletionStage cs = null; // when the listener is ready to close - long id; - if (DEBUG) { + long id = 0; + if (debug.isLoggable(Level.DEBUG)) { id = receiveCounter.incrementAndGet(); - System.out.printf("[WebSocket] enter onClose %s statusCode=%s reason.length=%s%n", + debug.log(Level.DEBUG, "enter onClose %s statusCode=%s reason.length=%s", id, statusCode, reason.length()); } try { cs = listener.onClose(WebSocketImpl.this, statusCode, reason); } finally { - if (DEBUG) { - System.out.printf("[WebSocket] exit onClose %s returned %s%n", - id, cs); - } + debug.log(Level.DEBUG, + "exit onClose %s returned %s", + id, cs); } if (cs == null) { cs = DONE; @@ -535,47 +512,44 @@ int code; if (statusCode == NO_STATUS_CODE || statusCode == CLOSED_ABNORMALLY) { code = NORMAL_CLOSURE; - if (DEBUG) { - System.out.printf("[WebSocket] using statusCode %s instead of %s%n", - statusCode, code); - } + debug.log(Level.DEBUG, + "using statusCode %s instead of %s", + statusCode, code); + } else { code = statusCode; } cs.whenComplete((r, e) -> { // TODO log sendClose0(code, "") // TODO handle errors from here .whenComplete((r1, e1) -> { - if (DEBUG) { if (e1 != null) { - e1.printStackTrace(System.out); + debug.log(Level.DEBUG, + "processClose completed with errors", + e1); } - } }); }); } private void processPong() { - long id; - if (DEBUG) { + long id = 0; + if (debug.isLoggable(Level.DEBUG)) { id = receiveCounter.incrementAndGet(); - System.out.printf("[WebSocket] enter onPong %s payload=%s%n", + debug.log(Level.DEBUG, "enter onPong %s payload=%s", id, binaryData); } CompletionStage cs = null; try { cs = listener.onPong(WebSocketImpl.this, binaryData); } finally { - if (DEBUG) { - System.out.printf("[WebSocket] exit onPong %s returned %s%n", - id, cs); - } + debug.log(Level.DEBUG, + "exit onPong %s returned %s", + id, cs); } } private void processPing() { - if (DEBUG) { - System.out.printf("[WebSocket] processPing%n"); - } + debug.log(Level.DEBUG, "processPing"); ByteBuffer slice = binaryData.slice(); // A full copy of this (small) data is made. This way sending a // replying Pong could be done in parallel with the listener @@ -594,71 +568,67 @@ WebSocketImpl.this, reporter); } - long id; - if (DEBUG) { + long id = 0; + if (debug.isLoggable(Level.DEBUG)) { id = receiveCounter.incrementAndGet(); - System.out.printf("[WebSocket] enter onPing %s payload=%s%n", + debug.log(Level.DEBUG, "enter onPing %s payload=%s", id, slice); } CompletionStage cs = null; try { cs = listener.onPing(WebSocketImpl.this, slice); } finally { - if (DEBUG) { - System.out.printf("[WebSocket] exit onPing %s returned %s%n", - id, cs); - } + debug.log(Level.DEBUG, + "exit onPing %s returned %s", + id, cs); } } private void processBinary() { - long id; - if (DEBUG) { + long id = 0; + if (debug.isLoggable(Level.DEBUG)) { id = receiveCounter.incrementAndGet(); - System.out.printf("[WebSocket] enter onBinary %s payload=%s part=%s%n", - id, binaryData, part); + debug.log(Level.DEBUG, + "enter onBinary %s payload=%s part=%s", + id, binaryData, part); } CompletionStage cs = null; try { cs = listener.onBinary(WebSocketImpl.this, binaryData, part); } finally { - if (DEBUG) { - System.out.printf("[WebSocket] exit onBinary %s returned %s%n", - id, cs); - } + debug.log(Level.DEBUG, + "exit onBinary %s returned %s", + id, cs); } } private void processText() { - long id; - if (DEBUG) { + long id = 0; + if (debug.isLoggable(Level.DEBUG)) { id = receiveCounter.incrementAndGet(); - System.out.printf("[WebSocket] enter onText %s payload.length=%s part=%s%n", - id, text.length(), part); + debug.log(Level.DEBUG, + "enter onText %s payload.length=%s part=%s", + id, text.length(), part); } CompletionStage cs = null; try { cs = listener.onText(WebSocketImpl.this, text, part); } finally { - if (DEBUG) { - System.out.printf("[WebSocket] exit onText %s returned %s%n", - id, cs); - } + debug.log(Level.DEBUG, + "exit onText %s returned %s", id, cs); } } private void processOpen() { - long id; - if (DEBUG) { + long id = 0; + if (debug.isLoggable(Level.DEBUG)) { id = receiveCounter.incrementAndGet(); - System.out.printf("[WebSocket] enter onOpen %s%n", id); + debug.log(Level.DEBUG, "enter onOpen %s", id); } try { listener.onOpen(WebSocketImpl.this); } finally { - if (DEBUG) { - System.out.printf("[WebSocket] exit onOpen %s%n", id); - } + debug.log(Level.DEBUG, "exit onOpen %s", id); } } } @@ -696,24 +666,18 @@ break; } } - if (DEBUG) { - System.out.printf("[WebSocket] swapped automatic pong from %s to %s%n", + debug.log(Level.DEBUG, "swapped automatic pong from %s to %s%n", message, copy); - } return swapped; } private void signalOpen() { - if (DEBUG) { - System.out.printf("[WebSocket] signalOpen%n"); - } + debug.log(Level.DEBUG, "signalOpen"); receiveScheduler.runOrSchedule(); } private void signalError(Throwable error) { - if (DEBUG) { - System.out.printf("[WebSocket] signalError %s%n", error); - } + debug.log(Level.DEBUG, "signalError %s", error); inputClosed = true; outputClosed = true; if (!this.error.compareAndSet(null, error) || !trySetState(ERROR)) { @@ -724,9 +688,7 @@ } private void close() { - if (DEBUG) { - System.out.println("[WebSocket] close"); - } + debug.log(Level.DEBUG, "close"); Throwable first = null; try { transport.closeInput(); @@ -748,10 +710,10 @@ } else if (second != null) { e = second; } - if (DEBUG) { - if (e != null) { - e.printStackTrace(System.out); - } + if (e != null) { + debug.log(Level.DEBUG, + "unexpected exception in close: ", + e); } } } @@ -763,17 +725,15 @@ this.statusCode = statusCode; this.reason = reason; boolean managed = trySetState(CLOSE); - if (DEBUG) { - System.out.printf("[WebSocket] signalClose statusCode=%s, reason.length()=%s: %s%n", - statusCode, reason.length(), managed); - } + debug.log(Level.DEBUG, + "signalClose statusCode=%s, reason.length()=%s: %s", + statusCode, reason.length(), managed); if (managed) { try { transport.closeInput(); } catch (Throwable t) { - if (DEBUG) { - t.printStackTrace(System.out); - } + debug.log(Level.DEBUG, + "unexpected exception closing input", t); } } } @@ -841,10 +801,9 @@ break; } } - if (DEBUG) { - System.out.printf("[WebSocket] set state %s (previous %s) %s%n", - newState, currentState, success); - } + debug.log(Level.DEBUG, + "set state %s (previous %s) %s", + newState, currentState, success); return success; } @@ -859,10 +818,9 @@ // from IDLE to WAITING: the state has changed to terminal throw new InternalError(); } - if (DEBUG) { - System.out.printf("[WebSocket] change state from %s to %s %s%n", - expectedState, newState, success); - } + debug.log(Level.DEBUG, + "change state from %s to %s %s", + expectedState, newState, success); return success; } diff -r a82058c084ef -r 065641767a75 test/jdk/java/net/httpclient/websocket/WebSocketTextTest.java --- a/test/jdk/java/net/httpclient/websocket/WebSocketTextTest.java Wed Mar 14 13:03:11 2018 +0000 +++ b/test/jdk/java/net/httpclient/websocket/WebSocketTextTest.java Wed Mar 14 13:35:33 2018 +0000 @@ -42,6 +42,8 @@ * * * @run testng/othervm + * -Djdk.internal.httpclient.websocket.debug=true + * -Djdk.internal.httpclient.debug=true * -Djdk.httpclient.websocket.writeBufferSize=1024 * -Djdk.httpclient.websocket.intermediateBufferSize=2048 WebSocketTextTest */