--- 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<String> dbgTag, Level outLevel, Level errLevel) {
+ return new DebugLogger(WS, dbgTag, outLevel, errLevel);
+ }
+
public static DebugLogger createHpackLogger(Supplier<String> dbgTag, Level outLevel, Level errLevel) {
return new DebugLogger(HPACK, dbgTag, outLevel, errLevel);
}
--- 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 <Level>:[<thread-name>] [<elapsed-time>] <dbgTag>: <formatted message>}
+ *
+ * @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<String> 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 <Level>:[<thread-name>] [<elapsed-time>] <dbgTag>: <formatted message>}
+ *
+ * @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<String> 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) {
--- 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();
}
--- 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)
--- 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<? super T, ? super Throwable> 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<? super T, ? super Throwable> 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<T> 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 <T> CompletableFuture<T> sendPing(ByteBuffer message,
T attachment,
BiConsumer<? super T, ? super Throwable> 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<T> 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 <T> CompletableFuture<T> sendPong(ByteBuffer message,
T attachment,
BiConsumer<? super T, ? super Throwable> 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<T> 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 <T> CompletableFuture<T> sendPong(Supplier<? extends ByteBuffer> message,
T attachment,
BiConsumer<? super T, ? super Throwable> 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<T> 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<? super T, ? super Throwable> 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<T> 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();
}
--- 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<WebSocket> 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<WebSocket> 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<WebSocket> 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<WebSocket> 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<WebSocket> 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<WebSocket> 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<WebSocket> 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<WebSocket> 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<WebSocket> 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<WebSocket> 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<WebSocket> 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;
}
--- 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
*/