http-client-branch: review comment - update debug statements as per new internal DebugLogger
--- a/src/java.net.http/share/classes/jdk/internal/net/http/AbstractAsyncSSLConnection.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/AbstractAsyncSSLConnection.java Mon Apr 16 16:44:12 2018 +0100
@@ -39,7 +39,6 @@
import jdk.internal.net.http.common.Utils;
import static jdk.internal.net.http.common.Utils.ServerName;
-
/**
* Asynchronous version of SSLConnection.
*
@@ -65,8 +64,8 @@
protected final SSLParameters sslParameters;
// Setting this property disables HTTPS hostname verification. Use with care.
- private static final boolean disableHostnameVerification = Utils.isHostnameVerificationDisabled();
-
+ private static final boolean disableHostnameVerification
+ = Utils.isHostnameVerificationDisabled();
AbstractAsyncSSLConnection(InetSocketAddress addr,
HttpClientImpl client,
--- a/src/java.net.http/share/classes/jdk/internal/net/http/AbstractSubscription.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/AbstractSubscription.java Mon Apr 16 16:44:12 2018 +0100
@@ -30,7 +30,6 @@
/**
* A {@link Flow.Subscription} wrapping a {@link Demand} instance.
- *
*/
abstract class AbstractSubscription implements Flow.Subscription {
@@ -41,5 +40,4 @@
* @return the subscription's demand.
*/
protected Demand demand() { return demand; }
-
}
--- a/src/java.net.http/share/classes/jdk/internal/net/http/AsyncSSLConnection.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/AsyncSSLConnection.java Mon Apr 16 16:44:12 2018 +0100
@@ -31,7 +31,6 @@
import jdk.internal.net.http.common.SSLTube;
import jdk.internal.net.http.common.Utils;
-
/**
* Asynchronous version of SSLConnection.
*/
--- a/src/java.net.http/share/classes/jdk/internal/net/http/AsyncSSLTunnelConnection.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/AsyncSSLTunnelConnection.java Mon Apr 16 16:44:12 2018 +0100
@@ -25,7 +25,6 @@
package jdk.internal.net.http;
-import java.lang.System.Logger.Level;
import java.net.InetSocketAddress;
import java.nio.channels.SocketChannel;
import java.util.concurrent.CompletableFuture;
@@ -55,14 +54,14 @@
@Override
public CompletableFuture<Void> connectAsync() {
- debug.log(Level.DEBUG, "Connecting plain tunnel connection");
+ if (debug.on()) debug.log("Connecting plain tunnel connection");
// This will connect the PlainHttpConnection flow, so that
// its HttpSubscriber and HttpPublisher are subscribed to the
// SocketTube
return plainConnection
.connectAsync()
.thenApply( unused -> {
- debug.log(Level.DEBUG, "creating SSLTube");
+ if (debug.on()) debug.log("creating SSLTube");
// create the SSLTube wrapping the SocketTube, with the given engine
flow = new SSLTube(engine,
client().theExecutor(),
--- a/src/java.net.http/share/classes/jdk/internal/net/http/ConnectionPool.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/ConnectionPool.java Mon Apr 16 16:44:12 2018 +0100
@@ -43,6 +43,7 @@
import java.util.concurrent.Flow;
import java.util.stream.Collectors;
import jdk.internal.net.http.common.FlowTube;
+import jdk.internal.net.http.common.Logger;
import jdk.internal.net.http.common.Utils;
/**
@@ -52,8 +53,7 @@
static final long KEEP_ALIVE = Utils.getIntegerNetProperty(
"jdk.httpclient.keepalive.timeout", 1200); // seconds
- static final boolean DEBUG = Utils.DEBUG; // Revisit: temporary dev flag.
- final System.Logger debug = Utils.getDebugLogger(this::dbgString, DEBUG);
+ final Logger debug = Utils.getDebugLogger(this::dbgString, Utils.DEBUG);
// Pools of idle connections
@@ -184,7 +184,7 @@
// while the connection is sitting in the pool.
CleanupTrigger cleanup = new CleanupTrigger(conn);
FlowTube flow = conn.getConnectionFlow();
- debug.log(Level.DEBUG, "registering %s", cleanup);
+ if (debug.on()) debug.log("registering %s", cleanup);
flow.connectFlows(cleanup, cleanup);
return cleanup;
}
@@ -420,10 +420,9 @@
}
void cleanup(HttpConnection c, Throwable error) {
- debug.log(Level.DEBUG,
- "%s : ConnectionPool.cleanup(%s)",
- String.valueOf(c.getConnectionFlow()),
- error);
+ if (debug.on())
+ debug.log("%s : ConnectionPool.cleanup(%s)",
+ String.valueOf(c.getConnectionFlow()), error);
synchronized(this) {
if (c instanceof PlainHttpConnection) {
removeFromPool(c, plainPool);
@@ -484,7 +483,5 @@
public String toString() {
return "CleanupTrigger(" + connection.getConnectionFlow() + ")";
}
-
}
-
}
--- a/src/java.net.http/share/classes/jdk/internal/net/http/CookieFilter.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/CookieFilter.java Mon Apr 16 16:44:12 2018 +0100
@@ -52,11 +52,9 @@
// add the returned cookies
HttpHeadersImpl systemHeaders = r.getSystemHeaders();
if (cookies.isEmpty()) {
- Log.logTrace("Request: no cookie to add for {0}",
- r.uri());
+ Log.logTrace("Request: no cookie to add for {0}", r.uri());
} else {
- Log.logTrace("Request: adding cookies for {0}",
- r.uri());
+ Log.logTrace("Request: adding cookies for {0}", r.uri());
}
for (Map.Entry<String,List<String>> entry : cookies.entrySet()) {
final String hdrname = entry.getKey();
@@ -72,8 +70,7 @@
}
}
} else {
- Log.logTrace("Request: No cookie manager found for {0}",
- r.uri());
+ Log.logTrace("Request: No cookie manager found for {0}", r.uri());
}
}
--- a/src/java.net.http/share/classes/jdk/internal/net/http/Exchange.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/Exchange.java Mon Apr 16 16:44:12 2018 +0100
@@ -42,6 +42,8 @@
import java.net.http.HttpHeaders;
import java.net.http.HttpResponse;
import java.net.http.HttpTimeoutException;
+
+import jdk.internal.net.http.common.Logger;
import jdk.internal.net.http.common.MinimalFuture;
import jdk.internal.net.http.common.Utils;
import jdk.internal.net.http.common.Log;
@@ -63,8 +65,7 @@
*/
final class Exchange<T> {
- static final boolean DEBUG = Utils.DEBUG; // Revisit: temporary dev flag.
- final System.Logger debug = Utils.getDebugLogger(this::dbgString, DEBUG);
+ final Logger debug = Utils.getDebugLogger(this::dbgString, Utils.DEBUG);
final HttpRequestImpl request;
final HttpClientImpl client;
@@ -184,7 +185,7 @@
ExchangeImpl<?> impl = exchImpl;
if (impl != null) {
// propagate the exception to the impl
- debug.log(Level.DEBUG, "Cancelling exchImpl: %s", exchImpl);
+ if (debug.on()) debug.log("Cancelling exchImpl: %s", exchImpl);
impl.cancel(cause);
} else {
// no impl yet. record the exception
@@ -216,7 +217,7 @@
if (cause == null) return;
if (impl != null) {
// The exception is raised by propagating it to the impl.
- debug.log(Level.DEBUG, "Cancelling exchImpl: %s", impl);
+ if (debug.on()) debug.log("Cancelling exchImpl: %s", impl);
impl.cancel(cause);
failed = null;
} else {
@@ -246,11 +247,9 @@
// potential concurrent calls to cancel() or cancel(IOException)
private CompletableFuture<? extends ExchangeImpl<T>>
establishExchange(HttpConnection connection) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG,
- "establishing exchange for %s,%n\t proxy=%s",
- request,
- request.proxy());
+ if (debug.on()) {
+ debug.log("establishing exchange for %s,%n\t proxy=%s",
+ request, request.proxy());
}
// check if we have been cancelled first.
Throwable t = getCancelCause();
@@ -426,10 +425,10 @@
// check for 101 switching protocols
// 101 responses are not supposed to contain a body.
// => should we fail if there is one?
- debug.log(Level.DEBUG, "Upgrading async %s", e.connection());
+ if (debug.on()) debug.log("Upgrading async %s", e.connection());
return e.readBodyAsync(this::ignoreBody, false, parentExecutor)
.thenCompose((T v) -> {// v is null
- debug.log(Level.DEBUG, "Ignored body");
+ debug.log("Ignored body");
// we pass e::getBuffer to allow the ByteBuffers to accumulate
// while we build the Http2Connection
return Http2Connection.createAsync(e.connection(),
@@ -477,7 +476,8 @@
s.cancelImpl(t);
return MinimalFuture.failedFuture(t);
}
- debug.log(Level.DEBUG, "Getting response async %s", s);
+ if (debug.on())
+ debug.log("Getting response async %s", s);
return s.getResponseAsync(null);
});}
);
--- a/src/java.net.http/share/classes/jdk/internal/net/http/ExchangeImpl.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/ExchangeImpl.java Mon Apr 16 16:44:12 2018 +0100
@@ -26,11 +26,11 @@
package jdk.internal.net.http;
import java.io.IOException;
-import java.lang.System.Logger.Level;
import java.util.concurrent.CompletableFuture;
import java.util.concurrent.Executor;
import java.util.function.Function;
import java.net.http.HttpResponse;
+import jdk.internal.net.http.common.Logger;
import jdk.internal.net.http.common.MinimalFuture;
import static java.net.http.HttpClient.Version.HTTP_1_1;
import jdk.internal.net.http.common.Utils;
@@ -50,9 +50,8 @@
*/
abstract class ExchangeImpl<T> {
- static final boolean DEBUG = Utils.DEBUG; // Revisit: temporary dev flag.
- private static final System.Logger DEBUG_LOGGER =
- Utils.getDebugLogger("ExchangeImpl"::toString, DEBUG);
+ private static final Logger debug =
+ Utils.getDebugLogger("ExchangeImpl"::toString, Utils.DEBUG);
final Exchange<T> exchange;
@@ -80,13 +79,15 @@
get(Exchange<U> exchange, HttpConnection connection)
{
if (exchange.version() == HTTP_1_1) {
- DEBUG_LOGGER.log(Level.DEBUG, "get: HTTP/1.1: new Http1Exchange");
+ if (debug.on())
+ debug.log("get: HTTP/1.1: new Http1Exchange");
return createHttp1Exchange(exchange, connection);
} else {
- Http2ClientImpl c2 = exchange.client().client2(); // TODO: improve
+ Http2ClientImpl c2 = exchange.client().client2(); // #### improve
HttpRequestImpl request = exchange.request();
CompletableFuture<Http2Connection> c2f = c2.getConnectionFor(request);
- DEBUG_LOGGER.log(Level.DEBUG, "get: Trying to get HTTP/2 connection");
+ if (debug.on())
+ debug.log("get: Trying to get HTTP/2 connection");
return c2f.handle((h2c, t) -> createExchangeImpl(h2c, t, exchange, connection))
.thenCompose(Function.identity());
}
@@ -98,28 +99,32 @@
Exchange<U> exchange,
HttpConnection connection)
{
- DEBUG_LOGGER.log(Level.DEBUG, "handling HTTP/2 connection creation result");
+ if (debug.on())
+ debug.log("handling HTTP/2 connection creation result");
boolean secure = exchange.request().secure();
if (t != null) {
- DEBUG_LOGGER.log(Level.DEBUG,
- "handling HTTP/2 connection creation failed: %s",
- (Object)t);
+ if (debug.on())
+ debug.log("handling HTTP/2 connection creation failed: %s",
+ (Object)t);
t = Utils.getCompletionCause(t);
if (t instanceof Http2Connection.ALPNException) {
Http2Connection.ALPNException ee = (Http2Connection.ALPNException)t;
AbstractAsyncSSLConnection as = ee.getConnection();
- DEBUG_LOGGER.log(Level.DEBUG, "downgrading to HTTP/1.1 with: %s", as);
+ if (debug.on())
+ debug.log("downgrading to HTTP/1.1 with: %s", as);
CompletableFuture<? extends ExchangeImpl<U>> ex =
createHttp1Exchange(exchange, as);
return ex;
} else {
- DEBUG_LOGGER.log(Level.DEBUG, "HTTP/2 connection creation failed "
- + "with unexpected exception: %s", (Object)t);
+ if (debug.on())
+ debug.log("HTTP/2 connection creation failed "
+ + "with unexpected exception: %s", (Object)t);
return MinimalFuture.failedFuture(t);
}
}
if (secure && c== null) {
- DEBUG_LOGGER.log(Level.DEBUG, "downgrading to HTTP/1.1 ");
+ if (debug.on())
+ debug.log("downgrading to HTTP/1.1 ");
CompletableFuture<? extends ExchangeImpl<U>> ex =
createHttp1Exchange(exchange, null);
return ex;
@@ -127,14 +132,15 @@
if (c == null) {
// no existing connection. Send request with HTTP 1 and then
// upgrade if successful
- DEBUG_LOGGER.log(Level.DEBUG, "new Http1Exchange, try to upgrade");
+ if (debug.on())
+ debug.log("new Http1Exchange, try to upgrade");
return createHttp1Exchange(exchange, connection)
.thenApply((e) -> {
exchange.h2Upgrade();
return e;
});
} else {
- DEBUG_LOGGER.log(Level.DEBUG, "creating HTTP/2 streams");
+ if (debug.on()) debug.log("creating HTTP/2 streams");
Stream<U> s = c.createStream(exchange);
CompletableFuture<? extends ExchangeImpl<U>> ex = MinimalFuture.completedFuture(s);
return ex;
--- a/src/java.net.http/share/classes/jdk/internal/net/http/Http1AsyncReceiver.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/Http1AsyncReceiver.java Mon Apr 16 16:44:12 2018 +0100
@@ -42,6 +42,7 @@
import java.util.function.Consumer;
import jdk.internal.net.http.common.Demand;
import jdk.internal.net.http.common.FlowTube.TubeSubscriber;
+import jdk.internal.net.http.common.Logger;
import jdk.internal.net.http.common.SequentialScheduler;
import jdk.internal.net.http.common.ConnectionExpiredException;
import jdk.internal.net.http.common.Utils;
@@ -53,8 +54,7 @@
*/
class Http1AsyncReceiver {
- static final boolean DEBUG = Utils.DEBUG; // Revisit: temporary dev flag.
- final System.Logger debug = Utils.getDebugLogger(this::dbgString, DEBUG);
+ final Logger debug = Utils.getDebugLogger(this::dbgString, Utils.DEBUG);
/**
* A delegate that can asynchronously receive data from an upstream flow,
@@ -208,8 +208,9 @@
// Then start emptying the queue, if possible.
while ((buf = queue.peek()) != null && !stopRequested) {
Http1AsyncDelegate delegate = this.delegate;
- debug.log(Level.DEBUG, "Got %s bytes for delegate %s",
- buf.remaining(), delegate);
+ if (debug.on())
+ debug.log("Got %s bytes for delegate %s",
+ buf.remaining(), delegate);
if (!hasDemand(delegate)) {
// The scheduler will be invoked again later when the demand
// becomes positive.
@@ -217,18 +218,19 @@
}
assert delegate != null;
- debug.log(Level.DEBUG, "Forwarding %s bytes to delegate %s",
- buf.remaining(), delegate);
+ if (debug.on())
+ debug.log("Forwarding %s bytes to delegate %s",
+ buf.remaining(), delegate);
// The delegate has demand: feed it the next buffer.
if (!delegate.tryAsyncReceive(buf)) {
final long remaining = buf.remaining();
- debug.log(Level.DEBUG, () -> {
+ if (debug.on()) debug.log(() -> {
// If the scheduler is stopped, the queue may already
// be empty and the reference may already be released.
String remstr = scheduler.isStopped() ? "" :
" remaining in ref: "
+ remaining;
- remstr = remstr
+ remstr += remstr
+ " total remaining: " + remaining();
return "Delegate done: " + remaining;
});
@@ -251,7 +253,7 @@
} catch (Throwable t) {
Throwable x = error;
if (x == null) error = t; // will be handled in the finally block
- debug.log(Level.DEBUG, "Unexpected error caught in flush()", t);
+ if (debug.on()) debug.log("Unexpected error caught in flush()", t);
} finally {
// Handles any pending error.
// The most recently subscribed delegate will get the error.
@@ -277,9 +279,9 @@
if (delegate != null && x != null && (stopRequested || queue.isEmpty())) {
// forward error only after emptying the queue.
final Object captured = delegate;
- debug.log(Level.DEBUG, () -> "flushing " + x
- + "\n\t delegate: " + captured
- + "\t\t queue.isEmpty: " + queue.isEmpty());
+ if (debug.on())
+ debug.log(() -> "flushing " + x + "\n\t delegate: " + captured
+ + "\t\t queue.isEmpty: " + queue.isEmpty());
scheduler.stop();
delegate.onReadError(x);
if (stopRequested) {
@@ -304,9 +306,10 @@
Http1AsyncDelegate delegate = this.delegate;
boolean more = this.canRequestMore.get();
boolean hasDemand = hasDemand(delegate);
- debug.log(Level.DEBUG, () -> "checkRequestMore: "
- + "canRequestMore=" + more + ", hasDemand=" + hasDemand
- + (delegate == null ? ", delegate=null" : ""));
+ if (debug.on())
+ debug.log("checkRequestMore: " + "canRequestMore=" + more
+ + ", hasDemand=" + hasDemand
+ + (delegate == null ? ", delegate=null" : ""));
if (hasDemand) {
subscriber.requestMore();
}
@@ -322,7 +325,8 @@
if (delegate == null) return false;
AbstractSubscription subscription = delegate.subscription();
long demand = subscription.demand().get();
- debug.log(Level.DEBUG, "downstream subscription demand is %s", demand);
+ if (debug.on())
+ debug.log("downstream subscription demand is %s", demand);
return demand > 0;
}
@@ -346,7 +350,8 @@
onReadError(x);
};
Runnable cancel = () -> {
- debug.log(Level.DEBUG, "Downstream subscription cancelled by %s", pending);
+ if (debug.on())
+ debug.log("Downstream subscription cancelled by %s", pending);
// The connection should be closed, as some data may
// be left over in the stream.
try {
@@ -368,10 +373,11 @@
pending.onSubscribe(subscription);
this.delegate = delegate = pending;
final Object captured = delegate;
- debug.log(Level.DEBUG, () -> "delegate is now " + captured
- + ", demand=" + subscription.demand().get()
- + ", canRequestMore=" + canRequestMore.get()
- + ", queue.isEmpty=" + queue.isEmpty());
+ if (debug.on())
+ debug.log("delegate is now " + captured
+ + ", demand=" + subscription.demand().get()
+ + ", canRequestMore=" + canRequestMore.get()
+ + ", queue.isEmpty=" + queue.isEmpty());
return true;
}
return false;
@@ -382,7 +388,7 @@
}
void clear() {
- debug.log(Level.DEBUG, "cleared");
+ if (debug.on()) debug.log("cleared");
this.pendingDelegateRef.set(null);
this.delegate = null;
this.owner = null;
@@ -395,9 +401,9 @@
if (queue.isEmpty()) {
canRequestMore.set(true);
}
- debug.log(Level.DEBUG, () ->
- "Subscribed pending " + delegate + " queue.isEmpty: "
- + queue.isEmpty());
+ if (debug.on())
+ debug.log("Subscribed pending " + delegate + " queue.isEmpty: "
+ + queue.isEmpty());
// Everything may have been received already. Make sure
// we parse it.
if (client.isSelectorThread()) {
@@ -415,7 +421,7 @@
void unsubscribe(Http1AsyncDelegate delegate) {
synchronized(this) {
if (this.delegate == delegate) {
- debug.log(Level.DEBUG, "Unsubscribed %s", delegate);
+ if (debug.on()) debug.log("Unsubscribed %s", delegate);
this.delegate = null;
}
}
@@ -423,7 +429,8 @@
// Callback: Consumer of ByteBuffer
private void asyncReceive(ByteBuffer buf) {
- debug.log(Level.DEBUG, "Putting %s bytes into the queue", buf.remaining());
+ if (debug.on())
+ debug.log("Putting %s bytes into the queue", buf.remaining());
received.addAndGet(buf.remaining());
queue.offer(buf);
@@ -437,7 +444,7 @@
void onReadError(Throwable ex) {
Http1AsyncDelegate delegate;
Throwable recorded;
- debug.log(Level.DEBUG, "onError: %s", (Object) ex);
+ if (debug.on()) debug.log("onError: %s", (Object) ex);
synchronized (this) {
delegate = this.delegate;
recorded = error;
@@ -463,9 +470,9 @@
error = ex;
}
final Throwable t = (recorded == null ? ex : recorded);
- debug.log(Level.DEBUG, () -> "recorded " + t
- + "\n\t delegate: " + delegate
- + "\t\t queue.isEmpty: " + queue.isEmpty(), ex);
+ if (debug.on())
+ debug.log("recorded " + t + "\n\t delegate: " + delegate
+ + "\t\t queue.isEmpty: " + queue.isEmpty(), ex);
}
if (queue.isEmpty() || pendingDelegateRef.get() != null || stopRequested) {
// This callback is called from within the selector thread.
@@ -476,7 +483,7 @@
}
void stop() {
- debug.log(Level.DEBUG, "stopping");
+ if (debug.on()) debug.log("stopping");
scheduler.stop();
// make sure ref count is handled properly by
// closing the delegate.
@@ -520,13 +527,14 @@
if (s == null) return;
if (canRequestMore.compareAndSet(true, false)) {
if (!completed && !dropped) {
- debug.log(Level.DEBUG,
- "Http1TubeSubscriber: requesting one more from upstream");
+ if (debug.on())
+ debug.log("Http1TubeSubscriber: requesting one more from upstream");
s.request(1);
return;
}
}
- debug.log(Level.DEBUG, "Http1TubeSubscriber: no need to request more");
+ if (debug.on())
+ debug.log("Http1TubeSubscriber: no need to request more");
}
@Override
@@ -550,7 +558,7 @@
}
public void dropSubscription() {
- debug.log(Level.DEBUG, "Http1TubeSubscriber: dropSubscription");
+ if (debug.on()) debug.log("Http1TubeSubscriber: dropSubscription");
// we could probably set subscription to null here...
// then we might not need the 'dropped' boolean?
dropped = true;
@@ -585,14 +593,14 @@
int size = Utils.remaining(qbb, Integer.MAX_VALUE);
int remaining = b.remaining();
int free = b.capacity() - b.position() - remaining;
- debug.log(Level.DEBUG,
- "Flushing %s bytes from queue into initial buffer (remaining=%s, free=%s)",
- size, remaining, free);
+ if (debug.on())
+ debug.log("Flushing %s bytes from queue into initial buffer "
+ + "(remaining=%s, free=%s)", size, remaining, free);
// check whether the initial buffer has enough space
if (size > free) {
- debug.log(Level.DEBUG,
- "Allocating new buffer for initial: %s", (size + remaining));
+ if (debug.on())
+ debug.log("Allocating new buffer for initial: %s", (size + remaining));
// allocates a new buffer and copy initial to it
b = ByteBuffer.allocate(size + remaining);
Utils.copy(initial, b);
@@ -641,8 +649,9 @@
// we can clear the refs
queue.clear();
final ByteBuffer bb = b;
- debug.log(Level.DEBUG, () -> "Initial buffer now has " + bb.remaining()
- + " pos=" + bb.position() + " limit=" + bb.limit());
+ if (debug.on())
+ debug.log("Initial buffer now has " + bb.remaining()
+ + " pos=" + bb.position() + " limit=" + bb.limit());
return b;
}
--- a/src/java.net.http/share/classes/jdk/internal/net/http/Http1Exchange.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/Http1Exchange.java Mon Apr 16 16:44:12 2018 +0100
@@ -41,6 +41,7 @@
import jdk.internal.net.http.common.Demand;
import jdk.internal.net.http.common.Log;
import jdk.internal.net.http.common.FlowTube;
+import jdk.internal.net.http.common.Logger;
import jdk.internal.net.http.common.SequentialScheduler;
import jdk.internal.net.http.common.MinimalFuture;
import jdk.internal.net.http.common.Utils;
@@ -51,8 +52,7 @@
*/
class Http1Exchange<T> extends ExchangeImpl<T> {
- static final boolean DEBUG = Utils.DEBUG; // Revisit: temporary dev flag.
- final System.Logger debug = Utils.getDebugLogger(this::dbgString, DEBUG);
+ final Logger debug = Utils.getDebugLogger(this::dbgString, Utils.DEBUG);
final HttpRequestImpl request; // main request
final Http1Request requestAction;
private volatile Http1Response<T> response;
@@ -118,8 +118,8 @@
final MinimalFuture<Flow.Subscription> whenSubscribed = new MinimalFuture<>();
private volatile Flow.Subscription subscription;
volatile boolean complete;
- private final System.Logger debug;
- Http1BodySubscriber(System.Logger debug) {
+ private final Logger debug;
+ Http1BodySubscriber(Logger debug) {
assert debug != null;
this.debug = debug;
}
@@ -128,8 +128,9 @@
static final List<ByteBuffer> COMPLETED = List.of(ByteBuffer.allocate(0));
final void request(long n) {
- debug.log(Level.DEBUG, () ->
- "Http1BodySubscriber requesting " + n + ", from " + subscription);
+ if (debug.on())
+ debug.log("Http1BodySubscriber requesting %d, from %s",
+ n, subscription);
subscription.request(n);
}
@@ -147,12 +148,12 @@
subscription.cancel();
} catch(Throwable t) {
String msg = "Ignoring exception raised when canceling BodyPublisher subscription";
- debug.log(Level.DEBUG, "%s: %s", msg, t);
+ if (debug.on()) debug.log("%s: %s", msg, t);
Log.logError("{0}: {1}", msg, (Object)t);
}
}
- static Http1BodySubscriber completeSubscriber(System.Logger debug) {
+ static Http1BodySubscriber completeSubscriber(Logger debug) {
return new Http1BodySubscriber(debug) {
@Override public void onSubscribe(Flow.Subscription subscription) { error(); }
@Override public void onNext(ByteBuffer item) { error(); }
@@ -230,7 +231,7 @@
private void connectFlows(HttpConnection connection) {
FlowTube tube = connection.getConnectionFlow();
- debug.log(Level.DEBUG, "%s connecting flows", tube);
+ if (debug.on()) debug.log("%s connecting flows", tube);
// Connect the flow to our Http1TubeSubscriber:
// asyncReceiver.subscriber().
@@ -242,12 +243,12 @@
CompletableFuture<ExchangeImpl<T>> sendHeadersAsync() {
// create the response before sending the request headers, so that
// the response can set the appropriate receivers.
- debug.log(Level.DEBUG, "Sending headers only");
+ if (debug.on()) debug.log("Sending headers only");
if (response == null) {
response = new Http1Response<>(connection, this, asyncReceiver);
}
- debug.log(Level.DEBUG, "response created in advance");
+ if (debug.on()) debug.log("response created in advance");
// If the first attempt to read something triggers EOF, or
// IOException("channel reset by peer"), we're going to retry.
// Instruct the asyncReceiver to throw ConnectionExpiredException
@@ -256,7 +257,7 @@
CompletableFuture<Void> connectCF;
if (!connection.connected()) {
- debug.log(Level.DEBUG, "initiating connect async");
+ if (debug.on()) debug.log("initiating connect async");
connectCF = connection.connectAsync();
synchronized (lock) {
operations.add(connectCF);
@@ -272,18 +273,18 @@
try {
connectFlows(connection);
- debug.log(Level.DEBUG, "requestAction.headers");
+ if (debug.on()) debug.log("requestAction.headers");
List<ByteBuffer> data = requestAction.headers();
synchronized (lock) {
state = State.HEADERS;
}
- debug.log(Level.DEBUG, "setting outgoing with headers");
+ if (debug.on()) debug.log("setting outgoing with headers");
assert outgoing.isEmpty() : "Unexpected outgoing:" + outgoing;
appendToOutgoing(data);
cf.complete(null);
return cf;
} catch (Throwable t) {
- debug.log(Level.DEBUG, "Failed to send headers: %s", t);
+ if (debug.on()) debug.log("Failed to send headers: %s", t);
connection.close();
cf.completeExceptionally(t);
return cf;
@@ -332,10 +333,9 @@
+ request.timeout().get().getNano() / 1000000) : -1,
cause);
boolean acknowledged = cf.completeExceptionally(cause);
- debug.log(Level.DEBUG,
- () -> acknowledged
- ? ("completed response with " + cause)
- : ("response already completed, ignoring " + cause));
+ if (debug.on())
+ debug.log(acknowledged ? ("completed response with " + cause)
+ : ("response already completed, ignoring " + cause));
}
return cf;
}
@@ -446,8 +446,8 @@
CompletableFuture<?> cf = toComplete.poll();
exec.execute(() -> {
if (cf.completeExceptionally(x)) {
- debug.log(Level.DEBUG, "completed cf with %s",
- (Object) x);
+ if (debug.on())
+ debug.log("completed cf with %s", (Object) x);
}
});
}
@@ -484,7 +484,7 @@
}
private void appendToOutgoing(DataPair dp) {
- debug.log(Level.DEBUG, "appending to outgoing " + dp);
+ if (debug.on()) debug.log("appending to outgoing " + dp);
outgoing.add(dp);
writePublisher.writeScheduler.runOrSchedule();
}
@@ -497,10 +497,10 @@
private void requestMoreBody() {
try {
- debug.log(Level.DEBUG, "requesting more body from the subscriber");
+ if (debug.on()) debug.log("requesting more body from the subscriber");
bodySubscriber.request(1);
} catch (Throwable t) {
- debug.log(Level.DEBUG, "Subscription::request failed", t);
+ if (debug.on()) debug.log("Subscription::request failed", t);
cancelImpl(t);
bodySentCF.completeExceptionally(t);
}
@@ -531,13 +531,13 @@
case HEADERS:
state = State.BODY;
// completeAsync, since dependent tasks should run in another thread
- debug.log(Level.DEBUG, "initiating completion of headersSentCF");
+ if (debug.on()) debug.log("initiating completion of headersSentCF");
headersSentCF.completeAsync(() -> this, exec);
break;
case BODY:
if (dp.data == Http1BodySubscriber.COMPLETED) {
state = State.COMPLETING;
- debug.log(Level.DEBUG, "initiating completion of bodySentCF");
+ if (debug.on()) debug.log("initiating completion of bodySentCF");
bodySentCF.completeAsync(() -> this, exec);
} else {
exec.execute(this::requestMoreBody);
@@ -558,7 +558,7 @@
/** A Publisher of HTTP/1.1 headers and request body. */
final class Http1Publisher implements FlowTube.TubePublisher {
- final System.Logger debug = Utils.getDebugLogger(this::dbgString);
+ final Logger debug = Utils.getDebugLogger(this::dbgString);
volatile Flow.Subscriber<? super List<ByteBuffer>> subscriber;
volatile boolean cancelled;
final Http1WriteSubscription subscription = new Http1WriteSubscription();
@@ -573,7 +573,7 @@
assert subscriber == null;
subscriber = s;
- debug.log(Level.DEBUG, "got subscriber: %s", s);
+ if (debug.on()) debug.log("got subscriber: %s", s);
s.onSubscribe(subscription);
}
@@ -593,17 +593,17 @@
@Override
public void run() {
assert state != State.COMPLETED : "Unexpected state:" + state;
- debug.log(Level.DEBUG, "WriteTask");
+ if (debug.on()) debug.log("WriteTask");
if (subscriber == null) {
- debug.log(Level.DEBUG, "no subscriber yet");
+ if (debug.on()) debug.log("no subscriber yet");
return;
}
- debug.log(Level.DEBUG, () -> "hasOutgoing = " + hasOutgoing());
+ if (debug.on()) debug.log(() -> "hasOutgoing = " + hasOutgoing());
while (hasOutgoing() && demand.tryDecrement()) {
DataPair dp = getOutgoing();
if (dp.throwable != null) {
- debug.log(Level.DEBUG, "onError");
+ if (debug.on()) debug.log("onError");
// Do not call the subscriber's onError, it is not required.
writeScheduler.stop();
} else {
@@ -613,15 +613,15 @@
assert state == State.COMPLETING : "Unexpected state:" + state;
state = State.COMPLETED;
}
- debug.log(Level.DEBUG,
- "completed, stopping %s", writeScheduler);
+ if (debug.on())
+ debug.log("completed, stopping %s", writeScheduler);
writeScheduler.stop();
// Do nothing more. Just do not publish anything further.
// The next Subscriber will eventually take over.
} else {
- debug.log(Level.DEBUG, () ->
- "onNext with " + Utils.remaining(data) + " bytes");
+ if (debug.on())
+ debug.log("onNext with " + Utils.remaining(data) + " bytes");
subscriber.onNext(data);
}
}
@@ -636,14 +636,14 @@
if (cancelled)
return; //no-op
demand.increase(n);
- debug.log(Level.DEBUG,
- "subscription request(%d), demand=%s", n, demand);
+ if (debug.on())
+ debug.log("subscription request(%d), demand=%s", n, demand);
writeScheduler.runOrSchedule(client.theExecutor());
}
@Override
public void cancel() {
- debug.log(Level.DEBUG, "subscription cancelled");
+ if (debug.on()) debug.log("subscription cancelled");
if (cancelled)
return; //no-op
cancelled = true;
--- a/src/java.net.http/share/classes/jdk/internal/net/http/Http1Request.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/Http1Request.java Mon Apr 16 16:44:12 2018 +0100
@@ -41,6 +41,7 @@
import jdk.internal.net.http.Http1Exchange.Http1BodySubscriber;
import jdk.internal.net.http.common.HttpHeadersImpl;
import jdk.internal.net.http.common.Log;
+import jdk.internal.net.http.common.Logger;
import jdk.internal.net.http.common.Utils;
import static java.nio.charset.StandardCharsets.US_ASCII;
@@ -393,7 +394,7 @@
@Override
public void onNext(ByteBuffer item) {
- debug.log(Level.DEBUG, "onNext");
+ if (debug.on()) debug.log("onNext");
Objects.requireNonNull(item);
if (complete) {
Throwable t = new IllegalStateException("subscription already completed");
@@ -417,7 +418,7 @@
@Override
public void onError(Throwable throwable) {
- debug.log(Level.DEBUG, "onError");
+ if (debug.on()) debug.log("onError");
if (complete) // TODO: error?
return;
@@ -427,7 +428,7 @@
@Override
public void onComplete() {
- debug.log(Level.DEBUG, "onComplete");
+ if (debug.on()) debug.log("onComplete");
if (complete) {
Throwable t = new IllegalStateException("subscription already completed");
http1Exchange.appendToOutgoing(t);
@@ -463,7 +464,6 @@
return ByteBuffer.wrap(header);
}
- static final boolean DEBUG = Utils.DEBUG; // Revisit: temporary dev flag.
- final System.Logger debug = Utils.getDebugLogger(this::toString, DEBUG);
+ final Logger debug = Utils.getDebugLogger(this::toString, Utils.DEBUG);
}
--- a/src/java.net.http/share/classes/jdk/internal/net/http/Http1Response.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/Http1Response.java Mon Apr 16 16:44:12 2018 +0100
@@ -41,6 +41,7 @@
import java.net.http.HttpResponse;
import jdk.internal.net.http.ResponseContent.BodyParser;
import jdk.internal.net.http.common.Log;
+import jdk.internal.net.http.common.Logger;
import jdk.internal.net.http.common.MinimalFuture;
import jdk.internal.net.http.common.Utils;
@@ -71,8 +72,8 @@
// Revisit: can we get rid of this?
static enum State {INITIAL, READING_HEADERS, READING_BODY, DONE}
private volatile State readProgress = State.INITIAL;
- static final boolean DEBUG = Utils.DEBUG; // Revisit: temporary dev flag.
- final System.Logger debug = Utils.getDebugLogger(this::dbgString, DEBUG);
+
+ final Logger debug = Utils.getDebugLogger(this::dbgString, Utils.DEBUG);
final static AtomicLong responseCount = new AtomicLong();
final long id = responseCount.incrementAndGet();
@@ -117,12 +118,14 @@
// increment the reference count on the HttpClientImpl
// to prevent the SelectorManager thread from exiting
// until our operation is complete.
- debug.log(Level.DEBUG, "Operation started: incrementing ref count for %s", client);
+ if (debug.on())
+ debug.log("Operation started: incrementing ref count for %s", client);
client.reference();
state = 0x01;
} else {
- debug.log(Level.DEBUG, "Operation ref count for %s is already %s",
- client, ((state & 0x2) == 0x2) ? "released." : "incremented!" );
+ if (debug.on())
+ debug.log("Operation ref count for %s is already %s",
+ client, ((state & 0x2) == 0x2) ? "released." : "incremented!" );
assert (state & 0x01) == 0 : "reference count already incremented";
}
}
@@ -133,20 +136,24 @@
// to allow the SelectorManager thread to exit if no
// other operation is pending and the facade is no
// longer referenced.
- debug.log(Level.DEBUG, "Operation finished: decrementing ref count for %s", client);
+ if (debug.on())
+ debug.log("Operation finished: decrementing ref count for %s", client);
client.unreference();
} else if (state == 0) {
- debug.log(Level.DEBUG, "Operation finished: releasing ref count for %s", client);
+ if (debug.on())
+ debug.log("Operation finished: releasing ref count for %s", client);
} else if ((state & 0x02) == 0x02) {
- debug.log(Level.DEBUG, "ref count for %s already released", client);
+ if (debug.on())
+ debug.log("ref count for %s already released", client);
}
state |= 0x02;
}
}
- public CompletableFuture<Response> readHeadersAsync(Executor executor) {
- debug.log(Level.DEBUG, () -> "Reading Headers: (remaining: "
- + asyncReceiver.remaining() +") " + readProgress);
+ public CompletableFuture<Response> readHeadersAsync(Executor executor) {
+ if (debug.on())
+ debug.log("Reading Headers: (remaining: "
+ + asyncReceiver.remaining() +") " + readProgress);
// with expect continue we will resume reading headers + body.
asyncReceiver.unsubscribe(bodyReader);
bodyReader.reset();
@@ -159,9 +166,9 @@
Function<State, Response> lambda = (State completed) -> {
assert completed == State.READING_HEADERS;
- debug.log(Level.DEBUG, () ->
- "Reading Headers: creating Response object;"
- + " state is now " + readProgress);
+ if (debug.on())
+ debug.log("Reading Headers: creating Response object;"
+ + " state is now " + readProgress);
asyncReceiver.unsubscribe(headersReader);
responseCode = hd.responseCode();
headers = hd.headers();
@@ -385,8 +392,7 @@
t = Utils.getCompletionCause(t);
try {
if (t == null) {
- debug.log(Level.DEBUG, () ->
- "Finished reading body: " + s);
+ if (debug.on()) debug.log("Finished reading body: " + s);
assert s == State.READING_BODY;
}
if (t != null) {
@@ -404,7 +410,7 @@
});
connection.addTrailingOperation(trailingOp);
} catch (Throwable t) {
- debug.log(Level.DEBUG, () -> "Failed reading body: " + t);
+ if (debug.on()) debug.log("Failed reading body: " + t);
try {
subscriber.onError(t);
cf.completeExceptionally(t);
@@ -451,8 +457,8 @@
// connection.setAsyncCallbacks(null, null, null);
// don't return the connection to the cache if EOF happened.
- debug.log(Level.DEBUG, () -> connection.getConnectionFlow()
- + ": return to HTTP/1.1 pool");
+ if (debug.on())
+ debug.log(connection.getConnectionFlow() + ": return to HTTP/1.1 pool");
connection.closeOrReturnToCache(eof == null ? headers : null);
}
}
@@ -481,8 +487,11 @@
+ (cf == null ? "null"
: (cf.isDone() ? "already completed"
: "not yet completed")));
- if (cf != null) cf.completeExceptionally(t);
- else { debug.log(Level.DEBUG, "onReadError", t); }
+ if (cf != null) {
+ cf.completeExceptionally(t);
+ } else {
+ debug.log(Level.DEBUG, "onReadError", t);
+ }
debug.log(Level.DEBUG, () -> "closing connection: cause is " + t);
connection.close();
}
@@ -610,18 +619,19 @@
assert parser != null : "no parser";
try {
count += b.remaining();
- debug.log(Level.DEBUG, () -> "Sending " + b.remaining()
- + "/" + b.capacity() + " bytes to header parser");
+ if (debug.on())
+ debug.log("Sending " + b.remaining() + "/" + b.capacity()
+ + " bytes to header parser");
if (parser.parse(b)) {
count -= b.remaining();
- debug.log(Level.DEBUG, () ->
- "Parsing headers completed. bytes=" + count);
+ if (debug.on())
+ debug.log("Parsing headers completed. bytes=" + count);
onComplete.accept(State.READING_HEADERS);
cf.complete(State.READING_HEADERS);
}
} catch (Throwable t) {
- debug.log(Level.DEBUG,
- () -> "Header parser failed to handle buffer: " + t);
+ if (debug.on())
+ debug.log("Header parser failed to handle buffer: " + t);
cf.completeExceptionally(t);
}
}
@@ -633,8 +643,8 @@
if (error != null) {
CompletableFuture<State> cf = this.cf;
if (cf != null) {
- debug.log(Level.DEBUG,
- () -> "close: completing header parser CF with " + error);
+ if (debug.on())
+ debug.log("close: completing header parser CF with " + error);
cf.completeExceptionally(error);
}
}
@@ -703,12 +713,13 @@
assert cf != null : "parsing not started";
assert parser != null : "no parser";
try {
- debug.log(Level.DEBUG, () -> "Sending " + b.remaining()
- + "/" + b.capacity() + " bytes to body parser");
+ if (debug.on())
+ debug.log("Sending " + b.remaining() + "/" + b.capacity()
+ + " bytes to body parser");
parser.accept(b);
} catch (Throwable t) {
- debug.log(Level.DEBUG,
- () -> "Body parser failed to handle buffer: " + t);
+ if (debug.on())
+ debug.log("Body parser failed to handle buffer: " + t);
if (!cf.isDone()) {
cf.completeExceptionally(t);
}
@@ -733,12 +744,12 @@
// in order to make sure the client reference count
// is decremented
if (error != null) {
- debug.log(Level.DEBUG,
- () -> "close: completing body parser CF with " + error);
+ if (debug.on())
+ debug.log("close: completing body parser CF with " + error);
cf.completeExceptionally(error);
} else {
- debug.log(Level.DEBUG,
- () -> "close: completing body parser CF");
+ if (debug.on())
+ debug.log("close: completing body parser CF");
cf.complete(State.READING_BODY);
}
}
@@ -748,6 +759,5 @@
public String toString() {
return super.toString() + "/parser=" + String.valueOf(parser);
}
-
}
}
--- a/src/java.net.http/share/classes/jdk/internal/net/http/Http2ClientImpl.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/Http2ClientImpl.java Mon Apr 16 16:44:12 2018 +0100
@@ -25,19 +25,17 @@
package jdk.internal.net.http;
-import java.lang.System.Logger.Level;
import java.net.InetSocketAddress;
import java.net.URI;
import java.util.Base64;
import java.util.Collections;
import java.util.HashSet;
-import java.util.HashMap;
import java.util.Map;
import java.util.Set;
import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.CompletableFuture;
-
import jdk.internal.net.http.common.Log;
+import jdk.internal.net.http.common.Logger;
import jdk.internal.net.http.common.MinimalFuture;
import jdk.internal.net.http.common.Utils;
import jdk.internal.net.http.frame.SettingsFrame;
@@ -52,9 +50,8 @@
*/
class Http2ClientImpl {
- static final boolean DEBUG = Utils.DEBUG; // Revisit: temporary dev flag.
- final static System.Logger debug =
- Utils.getDebugLogger("Http2ClientImpl"::toString, DEBUG);
+ final static Logger debug =
+ Utils.getDebugLogger("Http2ClientImpl"::toString, Utils.DEBUG);
private final HttpClientImpl client;
@@ -99,11 +96,13 @@
Http2Connection connection = connections.get(key);
if (connection != null) {
if (connection.closed) {
- debug.log(Level.DEBUG, "removing found closed connection: %s", connection);
+ if (debug.on())
+ debug.log("removing found closed connection: %s", connection);
connections.remove(key);
} else {
// fast path if connection already exists
- debug.log(Level.DEBUG, "found connection in the pool: %s", connection);
+ if (debug.on())
+ debug.log("found connection in the pool: %s", connection);
return MinimalFuture.completedFuture(connection);
}
}
@@ -111,7 +110,7 @@
if (!req.secure() || failures.contains(key)) {
// secure: negotiate failed before. Use http/1.1
// !secure: no connection available in cache. Attempt upgrade
- debug.log(Level.DEBUG, "not found in connection pool");
+ if (debug.on()) debug.log("not found in connection pool");
return MinimalFuture.completedFuture(null);
}
}
@@ -138,9 +137,10 @@
* has not been sent as part of the initial alpn negotiation
*/
boolean offerConnection(Http2Connection c) {
- debug.log(Level.DEBUG, "offering to the connection pool: %s", c);
+ if (debug.on()) debug.log("offering to the connection pool: %s", c);
if (c.closed) {
- debug.log(Level.DEBUG, "skipping offered closed connection: %s", c);
+ if (debug.on())
+ debug.log("skipping offered closed connection: %s", c);
return false;
}
@@ -149,24 +149,28 @@
Http2Connection c1 = connections.putIfAbsent(key, c);
if (c1 != null) {
c.setSingleStream(true);
- debug.log(Level.DEBUG, "existing entry in connection pool for %s", key);
+ if (debug.on())
+ debug.log("existing entry in connection pool for %s", key);
return false;
}
- debug.log(Level.DEBUG, "put in the connection pool: %s", c);
+ if (debug.on())
+ debug.log("put in the connection pool: %s", c);
return true;
}
}
void deleteConnection(Http2Connection c) {
- debug.log(Level.DEBUG, "removing from the connection pool: %s", c);
+ if (debug.on())
+ debug.log("removing from the connection pool: %s", c);
synchronized (this) {
connections.remove(c.key());
- debug.log(Level.DEBUG, "removed from the connection pool: %s", c);
+ if (debug.on())
+ debug.log("removed from the connection pool: %s", c);
}
}
void stop() {
- debug.log(Level.DEBUG, "stopping");
+ if (debug.on()) debug.log("stopping");
connections.values().forEach(this::close);
connections.clear();
}
--- a/src/java.net.http/share/classes/jdk/internal/net/http/Http2Connection.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/Http2Connection.java Mon Apr 16 16:44:12 2018 +0100
@@ -56,6 +56,7 @@
import jdk.internal.net.http.common.FlowTube.TubeSubscriber;
import jdk.internal.net.http.common.HttpHeadersImpl;
import jdk.internal.net.http.common.Log;
+import jdk.internal.net.http.common.Logger;
import jdk.internal.net.http.common.MinimalFuture;
import jdk.internal.net.http.common.SequentialScheduler;
import jdk.internal.net.http.common.Utils;
@@ -113,13 +114,11 @@
*/
class Http2Connection {
- static final boolean DEBUG = Utils.DEBUG; // Revisit: temporary dev flag.
- static final boolean DEBUG_HPACK = Utils.DEBUG_HPACK; // Revisit: temporary dev flag.
- final System.Logger debug = Utils.getDebugLogger(this::dbgString, DEBUG);
- final static System.Logger DEBUG_LOGGER =
- Utils.getDebugLogger("Http2Connection"::toString, DEBUG);
- private final System.Logger debugHpack =
- Utils.getHpackLogger(this::dbgString, DEBUG_HPACK);
+ final Logger debug = Utils.getDebugLogger(this::dbgString, Utils.DEBUG);
+ final static Logger DEBUG_LOGGER =
+ Utils.getDebugLogger("Http2Connection"::toString, Utils.DEBUG);
+ private final Logger debugHpack =
+ Utils.getHpackLogger(this::dbgString, Utils.DEBUG_HPACK);
static final ByteBuffer EMPTY_TRIGGER = ByteBuffer.allocate(0);
private boolean singleStream; // used only for stream 1, then closed
@@ -164,15 +163,16 @@
{
// if preface is not sent, buffers data in the pending list
if (!prefaceSent) {
- debug.log(Level.DEBUG, "Preface is not sent: buffering %d",
- buf.remaining());
+ if (debug.on())
+ debug.log("Preface not sent: buffering %d", buf.remaining());
synchronized (this) {
if (!prefaceSent) {
if (pending == null) pending = new ArrayList<>();
pending.add(buf);
- debug.log(Level.DEBUG, () -> "there are now "
- + Utils.remaining(pending)
- + " bytes buffered waiting for preface to be sent");
+ if (debug.on())
+ debug.log("there are now %d bytes buffered waiting for preface to be sent"
+ + Utils.remaining(pending)
+ );
return false;
}
}
@@ -189,7 +189,7 @@
this.pending = null;
if (pending != null) {
// flush pending data
- debug.log(Level.DEBUG, () -> "Processing buffered data: "
+ if (debug.on()) debug.log(() -> "Processing buffered data: "
+ Utils.remaining(pending));
for (ByteBuffer b : pending) {
decoder.decode(b);
@@ -197,7 +197,7 @@
}
// push the received buffer to the frames decoder.
if (buf != EMPTY_TRIGGER) {
- debug.log(Level.DEBUG, "Processing %d", buf.remaining());
+ if (debug.on()) debug.log("Processing %d", buf.remaining());
decoder.decode(buf);
}
return true;
@@ -260,9 +260,11 @@
this.serverSettings = SettingsFrame.getDefaultSettings();
this.hpackOut = new Encoder(serverSettings.getParameter(HEADER_TABLE_SIZE));
this.hpackIn = new Decoder(clientSettings.getParameter(HEADER_TABLE_SIZE));
- debugHpack.log(Level.DEBUG, () -> "For the record:" + super.toString());
- debugHpack.log(Level.DEBUG, "Decoder created: %s", hpackIn);
- debugHpack.log(Level.DEBUG, "Encoder created: %s", hpackOut);
+ if (debugHpack.on()) {
+ debugHpack.log("For the record:" + super.toString());
+ debugHpack.log("Decoder created: %s", hpackIn);
+ debugHpack.log("Encoder created: %s", hpackOut);
+ }
this.windowUpdater = new ConnectionWindowUpdateSender(this,
client2.getConnectionWindowSize(clientSettings));
}
@@ -374,7 +376,7 @@
SSLEngine engine = aconn.getEngine();
assert Objects.equals(alpn, engine.getApplicationProtocol());
- DEBUG_LOGGER.log(Level.DEBUG, "checkSSLConfig: alpn: %s", alpn );
+ DEBUG_LOGGER.log("checkSSLConfig: alpn: %s", alpn );
if (alpn == null || !alpn.equals("h2")) {
String msg;
@@ -480,7 +482,7 @@
private void decodeHeaders(HeaderFrame frame, DecodingCallback decoder)
throws IOException
{
- debugHpack.log(Level.DEBUG, "decodeHeaders(%s)", decoder);
+ if (debugHpack.on()) debugHpack.log("decodeHeaders(%s)", decoder);
boolean endOfHeaders = frame.getFlag(HeaderFrame.END_HEADERS);
@@ -528,8 +530,8 @@
ByteBuffer b = bs.get();
if (b.hasRemaining()) {
long c = ++count;
- debug.log(Level.DEBUG, () -> "H2 Receiving Initial("
- + c +"): " + b.remaining());
+ if (debug.on())
+ debug.log(() -> "H2 Receiving Initial(" + c +"): " + b.remaining());
framesController.processReceivedData(framesDecoder, b);
}
}
@@ -537,18 +539,19 @@
// the Http2TubeSubscriber scheduler ensures that the order of incoming
// buffers is preserved.
if (b == EMPTY_TRIGGER) {
- debug.log(Level.DEBUG, "H2 Received EMPTY_TRIGGER");
+ if (debug.on()) debug.log("H2 Received EMPTY_TRIGGER");
boolean prefaceSent = framesController.prefaceSent;
assert prefaceSent;
// call framesController.processReceivedData to potentially
// trigger the processing of all the data buffered there.
framesController.processReceivedData(framesDecoder, buffer);
- debug.log(Level.DEBUG, "H2 processed buffered data");
+ if (debug.on()) debug.log("H2 processed buffered data");
} else {
long c = ++count;
- debug.log(Level.DEBUG, "H2 Receiving(%d): %d", c, b.remaining());
+ if (debug.on())
+ debug.log("H2 Receiving(%d): %d", c, b.remaining());
framesController.processReceivedData(framesDecoder, buffer);
- debug.log(Level.DEBUG, "H2 processed(%d)", c);
+ if (debug.on()) debug.log("H2 processed(%d)", c);
}
} catch (Throwable e) {
String msg = Utils.stackTrace(e);
@@ -562,7 +565,7 @@
}
void shutdown(Throwable t) {
- debug.log(Level.DEBUG, () -> "Shutting down h2c (closed="+closed+"): " + t);
+ if (debug.on()) debug.log(() -> "Shutting down h2c (closed="+closed+"): " + t);
if (closed == true) return;
synchronized (this) {
if (closed == true) return;
@@ -605,8 +608,8 @@
protocolError(((MalformedFrame) frame).getErrorCode(),
((MalformedFrame) frame).getMessage());
} else {
- debug.log(Level.DEBUG, () -> "Reset stream: "
- + ((MalformedFrame) frame).getMessage());
+ if (debug.on())
+ debug.log(() -> "Reset stream: " + ((MalformedFrame) frame).getMessage());
resetStream(streamid, ((MalformedFrame) frame).getErrorCode());
}
return;
@@ -734,7 +737,7 @@
}
void closeStream(int streamid) {
- debug.log(Level.DEBUG, "Closed stream %d", streamid);
+ if (debug.on()) debug.log("Closed stream %d", streamid);
Stream<?> s = streams.remove(streamid);
if (s != null) {
// decrement the reference count on the HttpClientImpl
@@ -876,8 +879,9 @@
// cause any pending data stored before the preface was sent to be
// flushed (see PrefaceController).
Log.logTrace("finished sending connection preface");
- debug.log(Level.DEBUG, "Triggering processing of buffered data"
- + " after sending connection preface");
+ if (debug.on())
+ debug.log("Triggering processing of buffered data"
+ + " after sending connection preface");
subscriber.onNext(List.of(EMPTY_TRIGGER));
}
@@ -1088,9 +1092,9 @@
try {
while (!queue.isEmpty() && !scheduler.isStopped()) {
ByteBuffer buffer = queue.poll();
- debug.log(Level.DEBUG,
- "sending %d to Http2Connection.asyncReceive",
- buffer.remaining());
+ if (debug.on())
+ debug.log("sending %d to Http2Connection.asyncReceive",
+ buffer.remaining());
asyncReceive(buffer);
}
} catch (Throwable t) {
@@ -1099,7 +1103,7 @@
} finally {
Throwable x = error;
if (x != null) {
- debug.log(Level.DEBUG, "Stopping scheduler", x);
+ if (debug.on()) debug.log("Stopping scheduler", x);
scheduler.stop();
Http2Connection.this.shutdown(x);
}
@@ -1116,16 +1120,17 @@
dropped = false;
// TODO FIXME: request(1) should be done by the delegate.
if (!completed) {
- debug.log(Level.DEBUG, "onSubscribe: requesting Long.MAX_VALUE for reading");
+ if (debug.on())
+ debug.log("onSubscribe: requesting Long.MAX_VALUE for reading");
subscription.request(Long.MAX_VALUE);
} else {
- debug.log(Level.DEBUG, "onSubscribe: already completed");
+ if (debug.on()) debug.log("onSubscribe: already completed");
}
}
@Override
public void onNext(List<ByteBuffer> item) {
- debug.log(Level.DEBUG, () -> "onNext: got " + Utils.remaining(item)
+ if (debug.on()) debug.log(() -> "onNext: got " + Utils.remaining(item)
+ " bytes in " + item.size() + " buffers");
queue.addAll(item);
scheduler.runOrSchedule(client().theExecutor());
@@ -1133,7 +1138,7 @@
@Override
public void onError(Throwable throwable) {
- debug.log(Level.DEBUG, () -> "onError: " + throwable);
+ if (debug.on()) debug.log(() -> "onError: " + throwable);
error = throwable;
completed = true;
scheduler.runOrSchedule(client().theExecutor());
@@ -1141,7 +1146,7 @@
@Override
public void onComplete() {
- debug.log(Level.DEBUG, "EOF");
+ if (debug.on()) debug.log("EOF");
error = new EOFException("EOF reached while reading");
completed = true;
scheduler.runOrSchedule(client().theExecutor());
@@ -1149,7 +1154,7 @@
@Override
public void dropSubscription() {
- debug.log(Level.DEBUG, "dropSubscription");
+ if (debug.on()) debug.log("dropSubscription");
// we could probably set subscription to null here...
// then we might not need the 'dropped' boolean?
dropped = true;
--- a/src/java.net.http/share/classes/jdk/internal/net/http/HttpClientFacade.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/HttpClientFacade.java Mon Apr 16 16:44:12 2018 +0100
@@ -48,8 +48,7 @@
* An HttpClientFacade is a simple class that wraps an HttpClient implementation
* and delegates everything to its implementation delegate.
*/
-final class HttpClientFacade extends HttpClient
- implements Trackable {
+final class HttpClientFacade extends HttpClient implements Trackable {
final HttpClientImpl impl;
--- a/src/java.net.http/share/classes/jdk/internal/net/http/HttpClientImpl.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/HttpClientImpl.java Mon Apr 16 16:44:12 2018 +0100
@@ -71,6 +71,7 @@
import java.net.http.HttpResponse.PushPromiseHandler;
import java.net.http.WebSocket;
import jdk.internal.net.http.common.Log;
+import jdk.internal.net.http.common.Logger;
import jdk.internal.net.http.common.Pair;
import jdk.internal.net.http.common.Utils;
import jdk.internal.net.http.common.OperationTrackers.Trackable;
@@ -85,12 +86,11 @@
*/
final class HttpClientImpl extends HttpClient implements Trackable {
- static final boolean DEBUG = Utils.DEBUG; // Revisit: temporary dev flag.
- static final boolean DEBUGELAPSED = Utils.TESTING || DEBUG; // Revisit: temporary dev flag.
- static final boolean DEBUGTIMEOUT = false; // Revisit: temporary dev flag.
- final System.Logger debug = Utils.getDebugLogger(this::dbgString, DEBUG);
- final System.Logger debugelapsed = Utils.getDebugLogger(this::dbgString, DEBUGELAPSED);
- final System.Logger debugtimeout = Utils.getDebugLogger(this::dbgString, DEBUGTIMEOUT);
+ static final boolean DEBUGELAPSED = Utils.TESTING || Utils.DEBUG; // dev flag
+ static final boolean DEBUGTIMEOUT = false; // dev flag
+ final Logger debug = Utils.getDebugLogger(this::dbgString, Utils.DEBUG);
+ final Logger debugelapsed = Utils.getDebugLogger(this::dbgString, DEBUGELAPSED);
+ final Logger debugtimeout = Utils.getDebugLogger(this::dbgString, DEBUGTIMEOUT);
static final AtomicLong CLIENT_IDS = new AtomicLong();
// Define the default factory as a static inner class
@@ -244,8 +244,9 @@
this.userProxySelector = Optional.ofNullable(builder.proxy);
this.proxySelector = userProxySelector
.orElseGet(HttpClientImpl::getDefaultProxySelector);
- debug.log(Level.DEBUG, "proxySelector is %s (user-supplied=%s)",
- this.proxySelector, userProxySelector.isPresent());
+ if (debug.on())
+ debug.log("proxySelector is %s (user-supplied=%s)",
+ this.proxySelector, userProxySelector.isPresent());
authenticator = builder.authenticator;
if (builder.version == null) {
version = HttpClient.Version.HTTP_2;
@@ -467,8 +468,8 @@
}
private void debugCompleted(String tag, long startNanos, HttpRequest req) {
- if (debugelapsed.isLoggable(Level.DEBUG)) {
- debugelapsed.log(Level.DEBUG, () -> tag + " elapsed "
+ if (debugelapsed.on()) {
+ debugelapsed.log(tag + " elapsed "
+ (System.nanoTime() - startNanos)/1000_000L
+ " millis for " + req.method()
+ " to " + req.uri());
@@ -524,7 +525,8 @@
long start = DEBUGELAPSED ? System.nanoTime() : 0;
reference();
try {
- debugelapsed.log(Level.DEBUG, "ClientImpl (async) send %s", userRequest);
+ if (debugelapsed.on())
+ debugelapsed.log("ClientImpl (async) send %s", userRequest);
Executor executor = acc == null
? this.executor
@@ -586,8 +588,8 @@
private volatile boolean closed;
private final List<AsyncEvent> registrations;
private final List<AsyncTriggerEvent> deregistrations;
- private final System.Logger debug;
- private final System.Logger debugtimeout;
+ private final Logger debug;
+ private final Logger debugtimeout;
HttpClientImpl owner;
ConnectionPool pool;
@@ -616,7 +618,7 @@
// SelectorAttachment::resetInterestOps later on.
// But if we reach here when trying to resume an
// event then it's better to fail fast.
- debug.log(Level.DEBUG, "No key for channel");
+ if (debug.on()) debug.log("No key for channel");
e.abort(new IOException("No key for channel"));
}
} else {
@@ -644,7 +646,7 @@
}
synchronized void shutdown() {
- debug.log(Level.DEBUG, "SelectorManager shutting down");
+ if (debug.on()) debug.log("SelectorManager shutting down");
closed = true;
try {
selector.close();
@@ -697,10 +699,9 @@
}
} catch (IOException e) {
Log.logTrace("HttpClientImpl: " + e);
- debug.log(Level.DEBUG, () ->
- "Got " + e.getClass().getName()
- + " while handling"
- + " registration events");
+ if (debug.on())
+ debug.log("Got " + e.getClass().getName()
+ + " while handling registration events");
chan.close();
// let the event abort deal with it
errorList.add(new Pair<>(event, e));
@@ -736,13 +737,15 @@
// Timeouts will have milliseconds granularity. It is important
// to handle them in a timely fashion.
long nextTimeout = owner.purgeTimeoutsAndReturnNextDeadline();
- debugtimeout.log(Level.DEBUG, "next timeout: %d", nextTimeout);
+ if (debugtimeout.on())
+ debugtimeout.log("next timeout: %d", nextTimeout);
// Keep-alive have seconds granularity. It's not really an
// issue if we keep connections linger a bit more in the keep
// alive cache.
long nextExpiry = pool.purgeExpiredConnectionsAndReturnNextDeadline();
- debugtimeout.log(Level.DEBUG, "next expired: %d", nextExpiry);
+ if (debugtimeout.on())
+ debugtimeout.log("next expired: %d", nextExpiry);
assert nextTimeout >= 0;
assert nextExpiry >= 0;
@@ -760,8 +763,9 @@
// takes the least of the two.
long millis = Math.min(nextExpiry, nextTimeout);
- debugtimeout.log(Level.DEBUG, "Next deadline is %d",
- (millis == 0 ? NODEADLINE : millis));
+ if (debugtimeout.on())
+ debugtimeout.log("Next deadline is %d",
+ (millis == 0 ? NODEADLINE : millis));
//debugPrint(selector);
int n = selector.select(millis == 0 ? NODEADLINE : millis);
if (n == 0) {
@@ -825,8 +829,8 @@
String err = Utils.stackTrace(e);
Log.logError("HttpClientImpl: fatal error: " + err);
}
- debug.log(Level.DEBUG, "shutting down", e);
- if (Utils.ASSERTIONSENABLED && !debug.isLoggable(Level.DEBUG)) {
+ if (debug.on()) debug.log("shutting down", e);
+ if (Utils.ASSERTIONSENABLED && !debug.on()) {
e.printStackTrace(System.err); // always print the stack
}
} finally {
@@ -883,8 +887,8 @@
private final SelectableChannel chan;
private final Selector selector;
private final Set<AsyncEvent> pending;
- private final static System.Logger debug =
- Utils.getDebugLogger("SelectorAttachment"::toString, DEBUG);
+ private final static Logger debug =
+ Utils.getDebugLogger("SelectorAttachment"::toString, Utils.DEBUG);
private int interestOps;
SelectorAttachment(SelectableChannel chan, Selector selector) {
@@ -901,9 +905,8 @@
boolean reRegister = (interestOps & newOps) != newOps;
interestOps |= newOps;
pending.add(e);
- debug.log(Level.DEBUG,
- "Registering %s for %d (%s)",
- e, newOps, reRegister);
+ if (debug.on())
+ debug.log("Registering %s for %d (%s)", e, newOps, reRegister);
if (reRegister) {
// first time registration happens here also
try {
@@ -965,7 +968,7 @@
assert key.interestOps() == newOps;
} catch (CancelledKeyException x) {
// channel may have been closed
- debug.log(Level.DEBUG, "key cancelled for " + chan);
+ if (debug.on()) debug.log("key cancelled for " + chan);
abortPending(x);
}
}
--- a/src/java.net.http/share/classes/jdk/internal/net/http/HttpConnection.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/HttpConnection.java Mon Apr 16 16:44:12 2018 +0100
@@ -47,6 +47,7 @@
import java.net.http.HttpHeaders;
import jdk.internal.net.http.common.Demand;
import jdk.internal.net.http.common.FlowTube;
+import jdk.internal.net.http.common.Logger;
import jdk.internal.net.http.common.SequentialScheduler;
import jdk.internal.net.http.common.SequentialScheduler.DeferredCompleter;
import jdk.internal.net.http.common.Log;
@@ -65,10 +66,9 @@
*/
abstract class HttpConnection implements Closeable {
- static final boolean DEBUG = Utils.DEBUG; // Revisit: temporary dev flag.
- final System.Logger debug = Utils.getDebugLogger(this::dbgString, DEBUG);
- final static System.Logger DEBUG_LOGGER = Utils.getDebugLogger(
- () -> "HttpConnection(SocketTube(?))", DEBUG);
+ final Logger debug = Utils.getDebugLogger(this::dbgString, Utils.DEBUG);
+ final static Logger DEBUG_LOGGER = Utils.getDebugLogger(
+ () -> "HttpConnection(SocketTube(?))", Utils.DEBUG);
/** The address this connection is connected to. Could be a server or a proxy. */
final InetSocketAddress address;
@@ -190,8 +190,9 @@
c = pool.getConnection(false, addr, proxy);
if (c != null && c.isOpen() /* may have been eof/closed when in the pool */) {
final HttpConnection conn = c;
- DEBUG_LOGGER.log(Level.DEBUG, () -> conn.getConnectionFlow()
- + ": plain connection retrieved from HTTP/1.1 pool");
+ if (DEBUG_LOGGER.on())
+ DEBUG_LOGGER.log(conn.getConnectionFlow()
+ + ": plain connection retrieved from HTTP/1.1 pool");
return c;
} else {
return getPlainConnection(addr, proxy, request, client);
@@ -202,8 +203,9 @@
}
if (c != null && c.isOpen()) {
final HttpConnection conn = c;
- DEBUG_LOGGER.log(Level.DEBUG, () -> conn.getConnectionFlow()
- + ": SSL connection retrieved from HTTP/1.1 pool");
+ if (DEBUG_LOGGER.on())
+ DEBUG_LOGGER.log(conn.getConnectionFlow()
+ + ": SSL connection retrieved from HTTP/1.1 pool");
return c;
} else {
String[] alpn = null;
@@ -349,9 +351,8 @@
abstract FlowTube getConnectionFlow();
/**
- * A publisher that makes it possible to publish (write)
- * ordered (normal priority) and unordered (high priority)
- * buffers downstream.
+ * A publisher that makes it possible to publish (write) ordered (normal
+ * priority) and unordered (high priority) buffers downstream.
*/
final class PlainHttpPublisher implements HttpPublisher {
final Object reading;
@@ -402,16 +403,16 @@
public void request(long n) {
if (n <= 0) throw new IllegalArgumentException("non-positive request");
demand.increase(n);
- debug.log(Level.DEBUG, () -> "HttpPublisher: got request of "
- + n + " from "
- + getConnectionFlow());
+ if (debug.on())
+ debug.log("HttpPublisher: got request of " + n + " from "
+ + getConnectionFlow());
writeScheduler.runOrSchedule();
}
@Override
public void cancel() {
- debug.log(Level.DEBUG, () -> "HttpPublisher: cancelled by "
- + getConnectionFlow());
+ if (debug.on())
+ debug.log("HttpPublisher: cancelled by " + getConnectionFlow());
}
private boolean isEmpty() {
@@ -426,10 +427,11 @@
void flush() {
while (!isEmpty() && demand.tryDecrement()) {
List<ByteBuffer> elem = poll();
- debug.log(Level.DEBUG, () -> "HttpPublisher: sending "
- + Utils.remaining(elem) + " bytes ("
- + elem.size() + " buffers) to "
- + getConnectionFlow());
+ if (debug.on())
+ debug.log("HttpPublisher: sending "
+ + Utils.remaining(elem) + " bytes ("
+ + elem.size() + " buffers) to "
+ + getConnectionFlow());
subscriber.onNext(elem);
}
}
@@ -439,7 +441,7 @@
public void enqueue(List<ByteBuffer> buffers) throws IOException {
queue.add(buffers);
int bytes = buffers.stream().mapToInt(ByteBuffer::remaining).sum();
- debug.log(Level.DEBUG, "added %d bytes to the write queue", bytes);
+ debug.log("added %d bytes to the write queue", bytes);
}
@Override
@@ -447,17 +449,17 @@
// Unordered frames are sent before existing frames.
int bytes = buffers.stream().mapToInt(ByteBuffer::remaining).sum();
priority.add(buffers);
- debug.log(Level.DEBUG, "added %d bytes in the priority write queue", bytes);
+ debug.log("added %d bytes in the priority write queue", bytes);
}
@Override
public void signalEnqueued() throws IOException {
- debug.log(Level.DEBUG, "signalling the publisher of the write queue");
+ debug.log("signalling the publisher of the write queue");
signal();
}
}
- String dbgTag = null;
+ String dbgTag;
final String dbgString() {
FlowTube flow = getConnectionFlow();
String tag = dbgTag;
--- a/src/java.net.http/share/classes/jdk/internal/net/http/MultiExchange.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/MultiExchange.java Mon Apr 16 16:44:12 2018 +0100
@@ -44,6 +44,7 @@
import java.net.http.HttpResponse.PushPromiseHandler;
import java.net.http.HttpTimeoutException;
import jdk.internal.net.http.common.Log;
+import jdk.internal.net.http.common.Logger;
import jdk.internal.net.http.common.MinimalFuture;
import jdk.internal.net.http.common.ConnectionExpiredException;
import jdk.internal.net.http.common.Utils;
@@ -60,9 +61,8 @@
*/
class MultiExchange<T> {
- static final boolean DEBUG = Utils.DEBUG; // Revisit: temporary dev flag.
- static final System.Logger DEBUG_LOGGER =
- Utils.getDebugLogger("MultiExchange"::toString, DEBUG);
+ static final Logger debug =
+ Utils.getDebugLogger("MultiExchange"::toString, Utils.DEBUG);
private final HttpRequest userRequest; // the user request
private final HttpRequestImpl request; // a copy of the user request
@@ -339,9 +339,8 @@
// allow the retry mechanism to do its work
retryCause = cause;
if (!expiredOnce) {
- DEBUG_LOGGER.log(Level.DEBUG,
- "ConnectionExpiredException (async): retrying...",
- t);
+ if (debug.on())
+ debug.log("ConnectionExpiredException (async): retrying...", t);
expiredOnce = true;
// The connection was abruptly closed.
// We return null to retry the same request a second time.
@@ -351,9 +350,8 @@
previousreq = currentreq;
return null;
} else {
- DEBUG_LOGGER.log(Level.DEBUG,
- "ConnectionExpiredException (async): already retried once.",
- t);
+ if (debug.on())
+ debug.log("ConnectionExpiredException (async): already retried once.", t);
if (t.getCause() != null) t = t.getCause();
}
}
@@ -366,9 +364,9 @@
}
@Override
public void handle() {
- DEBUG_LOGGER.log(Level.DEBUG,
- "Cancelling MultiExchange due to timeout for request %s",
- request);
+ if (debug.on())
+ debug.log("Cancelling MultiExchange due to timeout for request %s",
+ request);
cancel(new HttpTimeoutException("request timed out"));
}
}
--- a/src/java.net.http/share/classes/jdk/internal/net/http/PlainHttpConnection.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/PlainHttpConnection.java Mon Apr 16 16:44:12 2018 +0100
@@ -80,12 +80,13 @@
try {
assert !connected : "Already connected";
assert !chan.isBlocking() : "Unexpected blocking channel";
- debug.log(Level.DEBUG, "ConnectEvent: finishing connect");
+ if (debug.on())
+ debug.log("ConnectEvent: finishing connect");
boolean finished = chan.finishConnect();
assert finished : "Expected channel to be connected";
- debug.log(Level.DEBUG,
- "ConnectEvent: connect finished: %s Local addr: %s",
- finished, chan.getLocalAddress());
+ if (debug.on())
+ debug.log("ConnectEvent: connect finished: %s Local addr: %s",
+ finished, chan.getLocalAddress());
connected = true;
// complete async since the event runs on the SelectorManager thread
cf.completeAsync(() -> null, client().theExecutor());
@@ -116,11 +117,11 @@
cf.completeExceptionally(e.getCause());
}
if (finished) {
- debug.log(Level.DEBUG, "connect finished without blocking");
+ if (debug.on()) debug.log("connect finished without blocking");
connected = true;
cf.complete(null);
} else {
- debug.log(Level.DEBUG, "registering connect event");
+ if (debug.on()) debug.log("registering connect event");
client().registerEvent(new ConnectEvent(cf));
}
} catch (Throwable throwable) {
@@ -159,14 +160,14 @@
private boolean trySetReceiveBufferSize(int bufsize) {
try {
chan.setOption(StandardSocketOptions.SO_RCVBUF, bufsize);
- debug.log(Level.DEBUG,
- "Receive buffer size is %s",
- chan.getOption(StandardSocketOptions.SO_RCVBUF));
+ if (debug.on())
+ debug.log("Receive buffer size is %s",
+ chan.getOption(StandardSocketOptions.SO_RCVBUF));
return true;
} catch(IOException x) {
- debug.log(Level.DEBUG,
- "Failed to set receive buffer size to %d on %s",
- bufsize, chan);
+ if (debug.on())
+ debug.log("Failed to set receive buffer size to %d on %s",
+ bufsize, chan);
}
return false;
}
@@ -193,8 +194,8 @@
}
try {
Log.logTrace("Closing: " + toString());
- debug.log(Level.DEBUG, () -> "Closing channel: "
- + client().debugInterestOps(chan));
+ if (debug.on())
+ debug.log("Closing channel: " + client().debugInterestOps(chan));
chan.close();
tube.signalClosed();
} catch (IOException e) {
--- a/src/java.net.http/share/classes/jdk/internal/net/http/PlainTunnelingConnection.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/PlainTunnelingConnection.java Mon Apr 16 16:44:12 2018 +0100
@@ -61,10 +61,10 @@
@Override
public CompletableFuture<Void> connectAsync() {
- debug.log(Level.DEBUG, "Connecting plain connection");
+ if (debug.on()) debug.log("Connecting plain connection");
return delegate.connectAsync()
.thenCompose((Void v) -> {
- debug.log(Level.DEBUG, "sending HTTP/1.1 CONNECT");
+ if (debug.on()) debug.log("sending HTTP/1.1 CONNECT");
HttpClientImpl client = client();
assert client != null;
HttpRequestImpl req = new HttpRequestImpl("CONNECT", address, proxyHeaders);
@@ -76,7 +76,7 @@
.responseAsyncImpl(delegate)
.thenCompose((Response resp) -> {
CompletableFuture<Void> cf = new MinimalFuture<>();
- debug.log(Level.DEBUG, "got response: %d", resp.statusCode());
+ if (debug.on()) debug.log("got response: %d", resp.statusCode());
if (resp.statusCode() == 407) {
return connectExchange.ignoreBody().handle((r,t) -> {
// close delegate after reading body: we won't
--- a/src/java.net.http/share/classes/jdk/internal/net/http/RawChannelTube.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/RawChannelTube.java Mon Apr 16 16:44:12 2018 +0100
@@ -27,6 +27,7 @@
import jdk.internal.net.http.common.Demand;
import jdk.internal.net.http.common.FlowTube;
+import jdk.internal.net.http.common.Logger;
import jdk.internal.net.http.common.Utils;
import jdk.internal.net.http.websocket.RawChannel;
@@ -61,7 +62,7 @@
final AtomicBoolean inputClosed = new AtomicBoolean();
final AtomicBoolean closed = new AtomicBoolean();
final String dbgTag;
- final System.Logger debug;
+ final Logger debug;
private static final Cleaner cleaner =
Utils.ASSERTIONSENABLED && Utils.DEBUG_WS ? Cleaner.create() : null;
@@ -106,7 +107,7 @@
}
private void connectFlows() {
- debug.log(Level.DEBUG, "connectFlows");
+ if (debug.on()) debug.log("connectFlows");
tube.connectFlows(writePublisher, readSubscriber);
}
@@ -119,11 +120,11 @@
}
@Override
public void request(long n) {
- debug.log(Level.DEBUG, "WriteSubscription::request %d", n);
+ if (debug.on()) debug.log("WriteSubscription::request %d", n);
demand.increase(n);
RawEvent event;
while ((event = writePublisher.events.poll()) != null) {
- debug.log(Level.DEBUG, "WriteSubscriber: handling event");
+ if (debug.on()) debug.log("WriteSubscriber: handling event");
event.handle();
if (demand.isFulfilled()) break;
}
@@ -131,11 +132,11 @@
@Override
public void cancel() {
cancelled = true;
- debug.log(Level.DEBUG, "WriteSubscription::cancel");
+ if (debug.on()) debug.log("WriteSubscription::cancel");
shutdownOutput();
RawEvent event;
while ((event = writePublisher.events.poll()) != null) {
- debug.log(Level.DEBUG, "WriteSubscriber: handling event");
+ if (debug.on()) debug.log("WriteSubscriber: handling event");
event.handle();
}
}
@@ -146,7 +147,7 @@
volatile WriteSubscription writeSubscription;
@Override
public void subscribe(Flow.Subscriber<? super List<ByteBuffer>> subscriber) {
- debug.log(Level.DEBUG, "WritePublisher::subscribe");
+ if (debug.on()) debug.log("WritePublisher::subscribe");
WriteSubscription subscription = new WriteSubscription(subscriber);
subscriber.onSubscribe(subscription);
writeSubscription = subscription;
@@ -169,7 +170,7 @@
while (!buffers.isEmpty() || error != null || closed.get() || completed) {
RawEvent event = events.poll();
if (event == null) break;
- debug.log(Level.DEBUG, "ReadSubscriber: handling event");
+ if (debug.on()) debug.log("ReadSubscriber: handling event");
event.handle();
}
}
@@ -184,11 +185,11 @@
n = initialRequest;
initialRequest = 0;
}
- debug.log(Level.DEBUG, "ReadSubscriber::onSubscribe");
+ if (debug.on()) debug.log("ReadSubscriber::onSubscribe");
if (n > 0) {
Throwable error = errorRef.get();
if (error == null && !closed.get() && !completed) {
- debug.log(Level.DEBUG, "readSubscription: requesting " + n);
+ if (debug.on()) debug.log("readSubscription: requesting " + n);
subscription.request(n);
}
}
@@ -197,7 +198,7 @@
@Override
public void onNext(List<ByteBuffer> item) {
- debug.log(Level.DEBUG, () -> "ReadSubscriber::onNext "
+ if (debug.on()) debug.log(() -> "ReadSubscriber::onNext "
+ Utils.remaining(item) + " bytes");
buffers.addAll(item);
checkEvents();
@@ -206,7 +207,7 @@
@Override
public void onError(Throwable throwable) {
if (closed.get() || errorRef.compareAndSet(null, throwable)) {
- debug.log(Level.DEBUG, "ReadSubscriber::onError", throwable);
+ if (debug.on()) debug.log("ReadSubscriber::onError", throwable);
if (buffers.isEmpty()) {
checkEvents();
shutdownInput();
@@ -216,7 +217,7 @@
@Override
public void onComplete() {
- debug.log(Level.DEBUG, "ReadSubscriber::onComplete");
+ if (debug.on()) debug.log("ReadSubscriber::onComplete");
completed = true;
if (buffers.isEmpty()) {
checkEvents();
@@ -236,7 +237,7 @@
public void registerEvent(RawEvent event) throws IOException {
int interestOps = event.interestOps();
if ((interestOps & SelectionKey.OP_WRITE) != 0) {
- debug.log(Level.DEBUG, "register write event");
+ if (debug.on()) debug.log("register write event");
if (outputClosed.get()) throw new IOException("closed output");
writePublisher.events.add(event);
WriteSubscription writeSubscription = writePublisher.writeSubscription;
@@ -249,7 +250,7 @@
}
}
if ((interestOps & SelectionKey.OP_READ) != 0) {
- debug.log(Level.DEBUG, "register read event");
+ if (debug.on()) debug.log("register read event");
if (inputClosed.get()) throw new IOException("closed input");
readSubscriber.events.add(event);
readSubscriber.checkEvents();
@@ -267,7 +268,7 @@
}
}
assert readSubscription != null;
- debug.log(Level.DEBUG, "readSubscription: requesting 1");
+ if (debug.on()) debug.log("readSubscription: requesting 1");
readSubscription.request(1);
}
}
@@ -293,23 +294,23 @@
* remaining bytes if no data available at the moment.
*/
public ByteBuffer read() throws IOException {
- debug.log(Level.DEBUG, "read");
+ if (debug.on()) debug.log("read");
Flow.Subscription readSubscription = readSubscriber.readSubscription;
if (readSubscription == null) return Utils.EMPTY_BYTEBUFFER;
ByteBuffer buffer = readSubscriber.buffers.poll();
if (buffer != null) {
- debug.log(Level.DEBUG, () -> "read: " + buffer.remaining());
+ if (debug.on()) debug.log("read: " + buffer.remaining());
return buffer;
}
Throwable error = readSubscriber.errorRef.get();
if (error != null) error = Utils.getIOException(error);
if (error instanceof EOFException) {
- debug.log(Level.DEBUG, "read: EOFException");
+ if (debug.on()) debug.log("read: EOFException");
shutdownInput();
return null;
}
if (error != null) {
- debug.log(Level.DEBUG, "read: " + error);
+ if (debug.on()) debug.log("read: " + error);
if (closed.get()) {
return null;
}
@@ -317,15 +318,15 @@
throw Utils.getIOException(error);
}
if (readSubscriber.completed) {
- debug.log(Level.DEBUG, "read: EOF");
+ if (debug.on()) debug.log("read: EOF");
shutdownInput();
return null;
}
if (inputClosed.get()) {
- debug.log(Level.DEBUG, "read: CLOSED");
+ if (debug.on()) debug.log("read: CLOSED");
throw new IOException("closed output");
}
- debug.log(Level.DEBUG, "read: nothing to read");
+ if (debug.on()) debug.log("read: nothing to read");
return Utils.EMPTY_BYTEBUFFER;
}
@@ -335,27 +336,27 @@
*/
public long write(ByteBuffer[] srcs, int offset, int length) throws IOException {
if (outputClosed.get()) {
- debug.log(Level.DEBUG, "write: CLOSED");
+ if (debug.on()) debug.log("write: CLOSED");
throw new IOException("closed output");
}
WriteSubscription writeSubscription = writePublisher.writeSubscription;
if (writeSubscription == null) {
- debug.log(Level.DEBUG, "write: unsubscribed: 0");
+ if (debug.on()) debug.log("write: unsubscribed: 0");
return 0;
}
if (writeSubscription.cancelled) {
- debug.log(Level.DEBUG, "write: CANCELLED");
+ if (debug.on()) debug.log("write: CANCELLED");
shutdownOutput();
throw new IOException("closed output");
}
if (writeSubscription.demand.tryDecrement()) {
List<ByteBuffer> buffers = copy(srcs, offset, length);
long res = Utils.remaining(buffers);
- debug.log(Level.DEBUG, "write: writing %d", res);
+ if (debug.on()) debug.log("write: writing %d", res);
writeSubscription.subscriber.onNext(buffers);
return res;
} else {
- debug.log(Level.DEBUG, "write: no demand: 0");
+ if (debug.on()) debug.log("write: no demand: 0");
return 0;
}
}
@@ -375,7 +376,7 @@
*/
public void shutdownInput() {
if (inputClosed.compareAndSet(false, true)) {
- debug.log(Level.DEBUG, "shutdownInput");
+ if (debug.on()) debug.log("shutdownInput");
// TransportImpl will eventually call RawChannel::close.
// We must not call it here as this would close the socket
// and can cause an exception to back fire before
@@ -398,7 +399,7 @@
*/
public void shutdownOutput() {
if (outputClosed.compareAndSet(false, true)) {
- debug.log(Level.DEBUG, "shutdownOutput");
+ if (debug.on()) debug.log("shutdownOutput");
// TransportImpl will eventually call RawChannel::close.
// We must not call it here as this would close the socket
// and can cause an exception to back fire before
@@ -415,7 +416,7 @@
@Override
public void close() {
if (closed.compareAndSet(false, true)) {
- debug.log(Level.DEBUG, "close");
+ if (debug.on()) debug.log("close");
connection.client().webSocketClose();
connection.close();
}
--- a/src/java.net.http/share/classes/jdk/internal/net/http/ResponseContent.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/ResponseContent.java Mon Apr 16 16:44:12 2018 +0100
@@ -34,6 +34,8 @@
import java.util.function.Consumer;
import java.net.http.HttpHeaders;
import java.net.http.HttpResponse;
+
+import jdk.internal.net.http.common.Logger;
import jdk.internal.net.http.common.Utils;
/**
@@ -44,8 +46,6 @@
*/
class ResponseContent {
- static final boolean DEBUG = Utils.DEBUG; // Revisit: temporary dev flag.
-
final HttpResponse.BodySubscriber<?> pusher;
final int contentLength;
final HttpHeaders headers;
@@ -118,7 +118,7 @@
class ChunkedBodyParser implements BodyParser {
final ByteBuffer READMORE = Utils.EMPTY_BYTEBUFFER;
final Consumer<Throwable> onComplete;
- final System.Logger debug = Utils.getDebugLogger(this::dbgString, DEBUG);
+ final Logger debug = Utils.getDebugLogger(this::dbgString, Utils.DEBUG);
final String dbgTag = ResponseContent.this.dbgTag + "/ChunkedBodyParser";
volatile Throwable closedExceptionally;
@@ -139,16 +139,16 @@
@Override
public void onSubscribe(AbstractSubscription sub) {
- debug.log(Level.DEBUG, () -> "onSubscribe: "
- + pusher.getClass().getName());
+ if (debug.on())
+ debug.log("onSubscribe: " + pusher.getClass().getName());
pusher.onSubscribe(this.sub = sub);
}
@Override
public void accept(ByteBuffer b) {
if (closedExceptionally != null) {
- debug.log(Level.DEBUG, () -> "already closed: "
- + closedExceptionally);
+ if (debug.on())
+ debug.log("already closed: " + closedExceptionally);
return;
}
boolean completed = false;
@@ -165,14 +165,14 @@
boolean hasDemand = sub.demand().tryDecrement();
assert hasDemand;
pusher.onNext(Collections.unmodifiableList(out));
- debug.log(Level.DEBUG, "Chunks sent");
+ if (debug.on()) debug.log("Chunks sent");
}
- debug.log(Level.DEBUG, "done!");
+ if (debug.on()) debug.log("done!");
assert closedExceptionally == null;
assert state == ChunkState.DONE;
onFinished.run();
pusher.onComplete();
- debug.log(Level.DEBUG, "subscriber completed");
+ if (debug.on()) debug.log("subscriber completed");
completed = true;
onComplete.accept(closedExceptionally); // should be null
break;
@@ -189,12 +189,12 @@
boolean hasDemand = sub.demand().tryDecrement();
assert hasDemand;
pusher.onNext(Collections.unmodifiableList(out));
- debug.log(Level.DEBUG, "Chunk sent");
+ if (debug.on()) debug.log("Chunk sent");
}
assert state == ChunkState.DONE || !b.hasRemaining();
} catch(Throwable t) {
- debug.log(Level.DEBUG,
- "Error while processing buffer: %s", (Object)t );
+ if (debug.on())
+ debug.log("Error while processing buffer: %s", (Object)t );
closedExceptionally = t;
if (!completed) onComplete.accept(t);
}
@@ -267,11 +267,11 @@
int toconsume = bytesToConsume;
ChunkState st = state;
if (st == ChunkState.READING_LENGTH && chunklen == -1) {
- debug.log(Level.DEBUG, () -> "Trying to read chunk len"
+ if (debug.on()) debug.log(() -> "Trying to read chunk len"
+ " (remaining in buffer:"+chunk.remaining()+")");
int clen = chunklen = tryReadChunkLen(chunk);
if (clen == -1) return READMORE;
- debug.log(Level.DEBUG, "Got chunk len %d", clen);
+ if (debug.on()) debug.log("Got chunk len %d", clen);
cr = false; partialChunklen = 0;
unfulfilled = bytesremaining = clen;
if (clen == 0) toconsume = bytesToConsume = 2; // that was the last chunk
@@ -279,9 +279,9 @@
}
if (toconsume > 0) {
- debug.log(Level.DEBUG,
- "Trying to consume bytes: %d (remaining in buffer: %s)",
- toconsume, chunk.remaining());
+ if (debug.on())
+ debug.log("Trying to consume bytes: %d (remaining in buffer: %s)",
+ toconsume, chunk.remaining());
if (tryConsumeBytes(chunk) > 0) {
return READMORE;
}
@@ -296,7 +296,7 @@
// consumed the trailing CRLF
int clen = chunklen;
assert clen == 0;
- debug.log(Level.DEBUG, "No more chunks: %d", clen);
+ if (debug.on()) debug.log("No more chunks: %d", clen);
// the DONE state is not really needed but it helps with
// assertions...
state = ChunkState.DONE;
@@ -310,11 +310,13 @@
ByteBuffer returnBuffer = READMORE; // May be a hunk or a chunk
if (unfulfilled > 0) {
int bytesread = chunk.remaining();
- debug.log(Level.DEBUG, "Reading chunk: available %d, needed %d",
- bytesread, unfulfilled);
+ if (debug.on())
+ debug.log("Reading chunk: available %d, needed %d",
+ bytesread, unfulfilled);
int bytes2return = Math.min(bytesread, unfulfilled);
- debug.log(Level.DEBUG, "Returning chunk bytes: %d", bytes2return);
+ if (debug.on())
+ debug.log( "Returning chunk bytes: %d", bytes2return);
returnBuffer = Utils.sliceWithLimitedCapacity(chunk, bytes2return).asReadOnlyBuffer();
unfulfilled = bytesremaining -= bytes2return;
if (unfulfilled == 0) bytesToConsume = 2;
@@ -323,9 +325,9 @@
assert unfulfilled >= 0;
if (unfulfilled == 0) {
- debug.log(Level.DEBUG,
- "No more bytes to read - %d yet to consume.",
- unfulfilled);
+ if (debug.on())
+ debug.log("No more bytes to read - %d yet to consume.",
+ unfulfilled);
// check whether the trailing CRLF is consumed, try to
// consume it if not. If tryConsumeBytes needs more bytes
// then we will come back here later - skipping the block
@@ -338,11 +340,11 @@
partialChunklen = 0;
cr = false;
state = ChunkState.READING_LENGTH;
- debug.log(Level.DEBUG, "Ready to read next chunk");
+ if (debug.on()) debug.log("Ready to read next chunk");
}
}
if (returnBuffer == READMORE) {
- debug.log(Level.DEBUG, "Need more data");
+ if (debug.on()) debug.log("Need more data");
}
return returnBuffer;
}
@@ -358,8 +360,8 @@
if (b1 != null) {
//assert b1.hasRemaining() || b1 == READMORE;
if (b1.hasRemaining()) {
- debug.log(Level.DEBUG, "Sending chunk to consumer (%d)",
- b1.remaining());
+ if (debug.on())
+ debug.log("Sending chunk to consumer (%d)", b1.remaining());
out.add(b1);
}
return false; // we haven't parsed the final chunk yet.
@@ -386,7 +388,7 @@
class FixedLengthBodyParser implements BodyParser {
final int contentLength;
final Consumer<Throwable> onComplete;
- final System.Logger debug = Utils.getDebugLogger(this::dbgString, DEBUG);
+ final Logger debug = Utils.getDebugLogger(this::dbgString, Utils.DEBUG);
final String dbgTag = ResponseContent.this.dbgTag + "/FixedLengthBodyParser";
volatile int remaining;
volatile Throwable closedExceptionally;
@@ -402,9 +404,9 @@
@Override
public void onSubscribe(AbstractSubscription sub) {
- debug.log(Level.DEBUG, () -> "length="
- + contentLength +", onSubscribe: "
- + pusher.getClass().getName());
+ if (debug.on())
+ debug.log("length=" + contentLength +", onSubscribe: "
+ + pusher.getClass().getName());
pusher.onSubscribe(this.sub = sub);
try {
if (contentLength == 0) {
@@ -425,15 +427,16 @@
@Override
public void accept(ByteBuffer b) {
if (closedExceptionally != null) {
- debug.log(Level.DEBUG, () -> "already closed: "
- + closedExceptionally);
+ if (debug.on())
+ debug.log("already closed: " + closedExceptionally);
return;
}
boolean completed = false;
try {
int unfulfilled = remaining;
- debug.log(Level.DEBUG, "Parser got %d bytes (%d remaining / %d)",
- b.remaining(), unfulfilled, contentLength);
+ if (debug.on())
+ debug.log("Parser got %d bytes (%d remaining / %d)",
+ b.remaining(), unfulfilled, contentLength);
assert unfulfilled != 0 || contentLength == 0 || b.remaining() == 0;
if (unfulfilled == 0 && contentLength > 0) return;
@@ -451,7 +454,8 @@
}
if (unfulfilled == 0) {
// We're done! All data has been received.
- debug.log(Level.DEBUG, "Parser got all expected bytes: completing");
+ if (debug.on())
+ debug.log("Parser got all expected bytes: completing");
assert closedExceptionally == null;
onFinished.run();
pusher.onComplete();
@@ -461,7 +465,7 @@
assert b.remaining() == 0;
}
} catch (Throwable t) {
- debug.log(Level.DEBUG, "Unexpected exception", t);
+ if (debug.on()) debug.log("Unexpected exception", t);
closedExceptionally = t;
if (!completed) {
onComplete.accept(t);
--- a/src/java.net.http/share/classes/jdk/internal/net/http/ResponseSubscribers.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/ResponseSubscribers.java Mon Apr 16 16:44:12 2018 +0100
@@ -60,6 +60,7 @@
import java.util.stream.Stream;
import java.net.http.HttpResponse.BodySubscriber;
import jdk.internal.net.http.common.Log;
+import jdk.internal.net.http.common.Logger;
import jdk.internal.net.http.common.MinimalFuture;
import jdk.internal.net.http.common.Utils;
import static java.nio.charset.StandardCharsets.UTF_8;
@@ -293,14 +294,13 @@
public static class HttpResponseInputStream extends InputStream
implements BodySubscriber<InputStream>
{
- final static boolean DEBUG = Utils.DEBUG;
final static int MAX_BUFFERS_IN_QUEUE = 1; // lock-step with the producer
// An immutable ByteBuffer sentinel to mark that the last byte was received.
private static final ByteBuffer LAST_BUFFER = ByteBuffer.wrap(new byte[0]);
private static final List<ByteBuffer> LAST_LIST = List.of(LAST_BUFFER);
- private static final System.Logger DEBUG_LOGGER =
- Utils.getDebugLogger("HttpResponseInputStream"::toString, DEBUG);
+ private static final Logger debug =
+ Utils.getDebugLogger("HttpResponseInputStream"::toString, Utils.DEBUG);
// A queue of yet unprocessed ByteBuffers received from the flow API.
private final BlockingQueue<List<ByteBuffer>> buffers;
@@ -348,10 +348,10 @@
// Take a new list of buffers from the queue, blocking
// if none is available yet...
- DEBUG_LOGGER.log(Level.DEBUG, "Taking list of Buffers");
+ if (debug.on()) debug.log("Taking list of Buffers");
List<ByteBuffer> lb = buffers.take();
currentListItr = lb.iterator();
- DEBUG_LOGGER.log(Level.DEBUG, "List of Buffers Taken");
+ if (debug.on()) debug.log("List of Buffers Taken");
// Check whether an exception was encountered upstream
if (closed || failed != null)
@@ -367,7 +367,7 @@
// Request another upstream item ( list of buffers )
Flow.Subscription s = subscription;
if (s != null) {
- DEBUG_LOGGER.log(Level.DEBUG, "Increased demand by 1");
+ if (debug.on()) debug.log("Increased demand by 1");
s.request(1);
}
assert currentListItr != null;
@@ -375,7 +375,7 @@
}
assert currentListItr != null;
assert currentListItr.hasNext();
- DEBUG_LOGGER.log(Level.DEBUG, "Next Buffer");
+ if (debug.on()) debug.log("Next Buffer");
currentBuffer = currentListItr.next();
} catch (InterruptedException ex) {
// continue
@@ -430,8 +430,9 @@
return;
}
assert buffers.remainingCapacity() > 1; // should contain at least 2
- DEBUG_LOGGER.log(Level.DEBUG, () -> "onSubscribe: requesting "
- + Math.max(1, buffers.remainingCapacity() - 1));
+ if (debug.on())
+ debug.log("onSubscribe: requesting "
+ + Math.max(1, buffers.remainingCapacity() - 1));
s.request(Math.max(1, buffers.remainingCapacity() - 1));
}
} catch (Throwable t) {
@@ -450,11 +451,11 @@
public void onNext(List<ByteBuffer> t) {
Objects.requireNonNull(t);
try {
- DEBUG_LOGGER.log(Level.DEBUG, "next item received");
+ if (debug.on()) debug.log("next item received");
if (!buffers.offer(t)) {
throw new IllegalStateException("queue is full");
}
- DEBUG_LOGGER.log(Level.DEBUG, "item offered");
+ if (debug.on()) debug.log("item offered");
} catch (Throwable ex) {
failed = ex;
try {
--- a/src/java.net.http/share/classes/jdk/internal/net/http/SocketTube.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/SocketTube.java Mon Apr 16 16:44:12 2018 +0100
@@ -41,6 +41,7 @@
import java.util.function.Supplier;
import jdk.internal.net.http.common.Demand;
import jdk.internal.net.http.common.FlowTube;
+import jdk.internal.net.http.common.Logger;
import jdk.internal.net.http.common.SequentialScheduler;
import jdk.internal.net.http.common.SequentialScheduler.DeferredCompleter;
import jdk.internal.net.http.common.SequentialScheduler.RestartableTask;
@@ -53,8 +54,7 @@
*/
final class SocketTube implements FlowTube {
- static final boolean DEBUG = Utils.DEBUG; // revisit: temporary developer's flag
- final System.Logger debug = Utils.getDebugLogger(this::dbgString, DEBUG);
+ final Logger debug = Utils.getDebugLogger(this::dbgString, Utils.DEBUG);
static final AtomicLong IDS = new AtomicLong();
private final HttpClientImpl client;
@@ -179,7 +179,7 @@
// particular in what concerns the events states, especially when displaying
// a read event state from a write event callback and conversely.
void debugState(String when) {
- if (debug.isLoggable(Level.DEBUG)) {
+ if (debug.on()) {
StringBuilder state = new StringBuilder();
InternalReadPublisher.InternalReadSubscription sub =
@@ -202,7 +202,7 @@
.append("], Writing: [ops=").append(wops)
.append(", demand=").append(wd)
.append("]");
- debug.log(Level.DEBUG, state.toString());
+ debug.log(state.toString());
}
}
@@ -240,14 +240,14 @@
}
@Override
public final void abort(IOException error) {
- debug().log(Level.DEBUG, () -> "abort: " + error);
+ debug().log(() -> "abort: " + error);
pause(); // pause, then signal
signalError(error); // should not be resumed after abort (not checked)
}
protected abstract void signalEvent();
protected abstract void signalError(Throwable error);
- abstract System.Logger debug();
+ abstract Logger debug();
}
// ===================================================================== //
@@ -274,7 +274,7 @@
@Override
public void onSubscribe(Flow.Subscription subscription) {
WriteSubscription previous = this.subscription;
- debug.log(Level.DEBUG, "subscribed for writing");
+ if (debug.on()) debug.log("subscribed for writing");
try {
boolean needEvent = current == null;
if (needEvent) {
@@ -284,7 +284,8 @@
}
this.subscription = new WriteSubscription(subscription);
if (needEvent) {
- debug.log(Level.DEBUG, "write: registering startSubscription event");
+ if (debug.on())
+ debug.log("write: registering startSubscription event");
client.registerEvent(startSubscription);
}
} catch (Throwable t) {
@@ -331,9 +332,9 @@
"should " + (inSelectorThread ? "" : "not ")
+ " be in the selector thread";
long remaining = Utils.remaining(bufs);
- debug.log(Level.DEBUG, "trying to write: %d", remaining);
+ if (debug.on()) debug.log("trying to write: %d", remaining);
long written = writeAvailable(bufs);
- debug.log(Level.DEBUG, "wrote: %d", written);
+ if (debug.on()) debug.log("wrote: %d", written);
assert written >= 0 : "negative number of bytes written:" + written;
assert written <= remaining;
if (remaining - written == 0) {
@@ -361,11 +362,11 @@
// Invoked in the selector manager thread.
void startSubscription() {
try {
- debug.log(Level.DEBUG, "write: starting subscription");
+ if (debug.on()) debug.log("write: starting subscription");
assert client.isSelectorThread();
// make sure read registrations are handled before;
readPublisher.subscriptionImpl.handlePending();
- debug.log(Level.DEBUG, "write: offloading requestMore");
+ if (debug.on()) debug.log("write: offloading requestMore");
// start writing;
client.theExecutor().execute(this::requestMore);
} catch(Throwable t) {
@@ -390,22 +391,23 @@
// be paused if there is nothing more to write.
List<ByteBuffer> bufs = current;
long remaining = bufs == null ? 0 : Utils.remaining(bufs);
- debug.log(Level.DEBUG, "write completed, %d yet to send", remaining);
+ if (debug.on())
+ debug.log( "write completed, %d yet to send", remaining);
debugState("InternalWriteSubscriber::onComplete");
}
void resumeWriteEvent(boolean inSelectorThread) {
- debug.log(Level.DEBUG, "scheduling write event");
+ if (debug.on()) debug.log("scheduling write event");
resumeEvent(writeEvent, this::signalError);
}
void signalWritable() {
- debug.log(Level.DEBUG, "channel is writable");
+ if (debug.on()) debug.log("channel is writable");
tryFlushCurrent(true);
}
void signalError(Throwable error) {
- debug.log(Level.DEBUG, () -> "write error: " + error);
+ debug.log(() -> "write error: " + error);
completed = true;
readPublisher.signalError(error);
}
@@ -434,10 +436,7 @@
}
@Override
- System.Logger debug() {
- return debug;
- }
-
+ Logger debug() { return debug; }
}
final class WriteSubscription implements Flow.Subscription {
@@ -462,7 +461,7 @@
void dropSubscription() {
synchronized (InternalWriteSubscriber.this) {
cancelled = true;
- debug.log(Level.DEBUG, "write: resetting demand to 0");
+ if (debug.on()) debug.log("write: resetting demand to 0");
writeDemand.reset();
}
}
@@ -480,14 +479,15 @@
requestMore = writeDemand.increaseIfFulfilled();
}
if (requestMore) {
- debug.log(Level.DEBUG, "write: requesting more...");
+ if (debug.on()) debug.log("write: requesting more...");
upstreamSubscription.request(1);
} else {
- debug.log(Level.DEBUG, "write: no need to request more: %d", d);
+ if (debug.on())
+ debug.log("write: no need to request more: %d", d);
}
} catch (Throwable t) {
- debug.log(Level.DEBUG, () ->
- "write: error while requesting more: " + t);
+ if (debug.on())
+ debug.log("write: error while requesting more: " + t);
cancelled = true;
signalError(t);
subscription.cancel();
@@ -496,7 +496,6 @@
}
}
}
-
}
// ===================================================================== //
@@ -536,9 +535,9 @@
ReadSubscription previous = pendingSubscription.getAndSet(target);
if (previous != null && previous != target) {
- debug.log(Level.DEBUG,
- () -> "read publisher: dropping pending subscriber: "
- + previous.subscriber);
+ if (debug.on())
+ debug.log("read publisher: dropping pending subscriber: "
+ + previous.subscriber);
previous.errorRef.compareAndSet(null, errorRef.get());
previous.signalOnSubscribe();
if (subscriptionImpl.completed) {
@@ -548,13 +547,13 @@
}
}
- debug.log(Level.DEBUG, "read publisher got subscriber");
+ if (debug.on()) debug.log("read publisher got subscriber");
subscriptionImpl.signalSubscribe();
debugState("leaving read.subscribe: ");
}
void signalError(Throwable error) {
- debug.log(Level.DEBUG, () -> "error signalled " + error);
+ if (debug.on()) debug.log("error signalled " + error);
if (!errorRef.compareAndSet(null, error)) {
return;
}
@@ -585,8 +584,8 @@
if (!cancelled) {
impl.request(n);
} else {
- debug.log(Level.DEBUG,
- "subscription cancelled, ignoring request %d", n);
+ if (debug.on())
+ debug.log("subscription cancelled, ignoring request %d", n);
}
}
@@ -599,12 +598,11 @@
}
Throwable error = errorRef.get();
if (error != null) {
- debug.log(Level.DEBUG, () ->
- "forwarding error to subscriber: "
- + error);
+ if (debug.on())
+ debug.log("forwarding error to subscriber: " + error);
subscriber.onError(error);
} else {
- debug.log(Level.DEBUG, "completing subscriber");
+ if (debug.on()) debug.log("completing subscriber");
subscriber.onComplete();
}
}
@@ -616,7 +614,7 @@
subscribed = true;
}
subscriber.onSubscribe(this);
- debug.log(Level.DEBUG, "onSubscribe called");
+ if (debug.on()) debug.log("onSubscribe called");
if (errorRef.get() != null) {
signalCompletion();
}
@@ -645,13 +643,12 @@
if (readScheduler.isStopped() || completed) {
// if already completed or stopped we can handle any
// pending connection directly from here.
- debug.log(Level.DEBUG,
- "handling pending subscription while completed");
+ if (debug.on())
+ debug.log("handling pending subscription while completed");
handlePending();
} else {
try {
- debug.log(Level.DEBUG,
- "registering subscribe event");
+ if (debug.on()) debug.log("registering subscribe event");
client.registerEvent(subscribeEvent);
} catch (Throwable t) {
signalError(t);
@@ -662,13 +659,13 @@
final void handleSubscribeEvent() {
assert client.isSelectorThread();
- debug.log(Level.DEBUG, "subscribe event raised");
+ debug.log("subscribe event raised");
readScheduler.runOrSchedule();
if (readScheduler.isStopped() || completed) {
// if already completed or stopped we can handle any
// pending connection directly from here.
- debug.log(Level.DEBUG,
- "handling pending subscription when completed");
+ if (debug.on())
+ debug.log("handling pending subscription when completed");
handlePending();
}
}
@@ -686,7 +683,7 @@
if (n > 0L) {
boolean wasFulfilled = demand.increase(n);
if (wasFulfilled) {
- debug.log(Level.DEBUG, "got some demand for reading");
+ if (debug.on()) debug.log("got some demand for reading");
resumeReadEvent();
// if demand has been changed from fulfilled
// to unfulfilled register read event;
@@ -704,12 +701,12 @@
}
private void resumeReadEvent() {
- debug.log(Level.DEBUG, "resuming read event");
+ if (debug.on()) debug.log("resuming read event");
resumeEvent(readEvent, this::signalError);
}
private void pauseReadEvent() {
- debug.log(Level.DEBUG, "pausing read event");
+ if (debug.on()) debug.log("pausing read event");
pauseEvent(readEvent, this::signalError);
}
@@ -723,7 +720,7 @@
if (!errorRef.compareAndSet(null, error)) {
return;
}
- debug.log(Level.DEBUG, () -> "got read error: " + error);
+ if (debug.on()) debug.log("got read error: " + error);
readScheduler.runOrSchedule();
}
@@ -745,7 +742,8 @@
// make sure we have a subscriber
if (handlePending()) {
- debug.log(Level.DEBUG, "pending subscriber subscribed");
+ if (debug.on())
+ debug.log("pending subscriber subscribed");
return;
}
@@ -756,9 +754,9 @@
Throwable error = errorRef.get();
if (current == null) {
assert error != null;
- debug.log(Level.DEBUG,
- "error raised before subscriber subscribed: %s",
- (Object)error);
+ if (debug.on())
+ debug.log("error raised before subscriber subscribed: %s",
+ (Object)error);
return;
}
TubeSubscriber subscriber = current.subscriber;
@@ -766,8 +764,9 @@
completed = true;
// safe to pause here because we're finished anyway.
pauseReadEvent();
- debug.log(Level.DEBUG, () -> "Sending error " + error
- + " to subscriber " + subscriber);
+ if (debug.on())
+ debug.log("Sending error " + error
+ + " to subscriber " + subscriber);
current.errorRef.compareAndSet(null, error);
current.signalCompletion();
readScheduler.stop();
@@ -783,7 +782,7 @@
List<ByteBuffer> bytes = readAvailable();
if (bytes == EOF) {
if (!completed) {
- debug.log(Level.DEBUG, "got read EOF");
+ if (debug.on()) debug.log("got read EOF");
completed = true;
// safe to pause here because we're finished
// anyway.
@@ -796,8 +795,8 @@
} else if (Utils.remaining(bytes) > 0) {
// the subscriber is responsible for offloading
// to another thread if needed.
- debug.log(Level.DEBUG, () -> "read bytes: "
- + Utils.remaining(bytes));
+ if (debug.on())
+ debug.log("read bytes: " + Utils.remaining(bytes));
assert !current.completed;
subscriber.onNext(bytes);
// we could continue looping until the demand
@@ -812,7 +811,7 @@
return;
} else {
// nothing available!
- debug.log(Level.DEBUG, "no more bytes available");
+ if (debug.on()) debug.log("no more bytes available");
// re-increment the demand and resume the read
// event. This ensures that this loop is
// executed again when the socket becomes
@@ -827,7 +826,7 @@
continue;
}
} else {
- debug.log(Level.DEBUG, "no more demand for reading");
+ if (debug.on()) debug.log("no more demand for reading");
// the event is paused just after firing, so it should
// still be paused here, unless the demand was just
// incremented from 0 to n, in which case, the
@@ -842,7 +841,7 @@
}
}
} catch (Throwable t) {
- debug.log(Level.DEBUG, "Unexpected exception in read loop", t);
+ if (debug.on()) debug.log("Unexpected exception in read loop", t);
signalError(t);
} finally {
handlePending();
@@ -852,21 +851,22 @@
boolean handlePending() {
ReadSubscription pending = pendingSubscription.getAndSet(null);
if (pending == null) return false;
- debug.log(Level.DEBUG, "handling pending subscription for %s",
- pending.subscriber);
+ if (debug.on())
+ debug.log("handling pending subscription for %s",
+ pending.subscriber);
ReadSubscription current = subscription;
if (current != null && current != pending && !completed) {
current.subscriber.dropSubscription();
}
- debug.log(Level.DEBUG, "read demand reset to 0");
+ if (debug.on()) debug.log("read demand reset to 0");
subscriptionImpl.demand.reset(); // subscriber will increase demand if it needs to.
pending.errorRef.compareAndSet(null, errorRef.get());
if (!readScheduler.isStopped()) {
subscription = pending;
} else {
- debug.log(Level.DEBUG, "socket tube is already stopped");
+ if (debug.on()) debug.log("socket tube is already stopped");
}
- debug.log(Level.DEBUG, "calling onSubscribe");
+ if (debug.on()) debug.log("calling onSubscribe");
pending.signalOnSubscribe();
if (completed) {
pending.errorRef.compareAndSet(null, errorRef.get());
@@ -901,11 +901,8 @@
}
@Override
- System.Logger debug() {
- return debug;
- }
+ Logger debug() { return debug; }
}
-
}
// ===================================================================== //
@@ -1059,7 +1056,7 @@
@Override
public void connectFlows(TubePublisher writePublisher,
TubeSubscriber readSubscriber) {
- debug.log(Level.DEBUG, "connecting flows");
+ if (debug.on()) debug.log("connecting flows");
this.subscribe(readSubscriber);
writePublisher.subscribe(this);
}
--- a/src/java.net.http/share/classes/jdk/internal/net/http/Stream.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/Stream.java Mon Apr 16 16:44:12 2018 +0100
@@ -95,8 +95,7 @@
*/
class Stream<T> extends ExchangeImpl<T> {
- final static boolean DEBUG = Utils.DEBUG; // Revisit: temporary developer's flag
- final System.Logger debug = Utils.getDebugLogger(this::dbgString, DEBUG);
+ final Logger debug = Utils.getDebugLogger(this::dbgString, Utils.DEBUG);
final ConcurrentLinkedQueue<Http2Frame> inputQ = new ConcurrentLinkedQueue<>();
final SequentialScheduler sched =
@@ -164,7 +163,7 @@
// can't process anything yet
return;
} else {
- debug.log(Level.DEBUG, "subscribing user subscriber");
+ if (debug.on()) debug.log("subscribing user subscriber");
subscriber.onSubscribe(userSubscription);
}
}
@@ -184,7 +183,7 @@
if (size == 0 && finished) {
inputQ.remove();
Log.logTrace("responseSubscriber.onComplete");
- debug.log(Level.DEBUG, "incoming: onComplete");
+ if (debug.on()) debug.log("incoming: onComplete");
sched.stop();
subscriber.onComplete();
onCompleteCalled = true;
@@ -193,11 +192,11 @@
} else if (userSubscription.tryDecrement()) {
inputQ.remove();
Log.logTrace("responseSubscriber.onNext {0}", size);
- debug.log(Level.DEBUG, "incoming: onNext(%d)", size);
+ if (debug.on()) debug.log("incoming: onNext(%d)", size);
subscriber.onNext(dsts);
if (consumed(df)) {
Log.logTrace("responseSubscriber.onComplete");
- debug.log(Level.DEBUG, "incoming: onComplete");
+ if (debug.on()) debug.log("incoming: onComplete");
sched.stop();
subscriber.onComplete();
onCompleteCalled = true;
@@ -218,10 +217,12 @@
sched.stop();
try {
if (!onCompleteCalled) {
- debug.log(Level.DEBUG, "calling subscriber.onError: %s", (Object)t);
+ if (debug.on())
+ debug.log("calling subscriber.onError: %s", (Object)t);
subscriber.onError(t);
} else {
- debug.log(Level.DEBUG, "already completed: dropping error %s", (Object)t);
+ if (debug.on())
+ debug.log("already completed: dropping error %s", (Object)t);
}
} catch (Throwable x) {
Log.logError("Subscriber::onError threw exception: {0}", (Object)t);
@@ -349,7 +350,7 @@
* Data frames will be removed by response body thread.
*/
void incoming(Http2Frame frame) throws IOException {
- debug.log(Level.DEBUG, "incoming: %s", frame);
+ if (debug.on()) debug.log("incoming: %s", frame);
if ((frame instanceof HeaderFrame)) {
HeaderFrame hframe = (HeaderFrame)frame;
if (hframe.endHeaders()) {
@@ -490,9 +491,9 @@
acceptor = pushGroup.acceptPushRequest(pushRequest);
accepted = acceptor.accepted();
} catch (Throwable t) {
- debug.log(Level.DEBUG,
- "PushPromiseHandler::applyPushPromise threw exception %s",
- (Object)t);
+ if (debug.on())
+ debug.log("PushPromiseHandler::applyPushPromise threw exception %s",
+ (Object)t);
}
if (!accepted) {
// cancel / reject
@@ -635,7 +636,7 @@
@Override
CompletableFuture<ExchangeImpl<T>> sendHeadersAsync() {
- debug.log(Level.DEBUG, "sendHeadersOnly()");
+ if (debug.on()) debug.log("sendHeadersOnly()");
if (Log.requests() && request != null) {
Log.logRequest(request.toString());
}
@@ -654,11 +655,11 @@
@Override
void released() {
if (streamid > 0) {
- debug.log(Level.DEBUG, "Released stream %d", streamid);
+ if (debug.on()) debug.log("Released stream %d", streamid);
// remove this stream from the Http2Connection map.
connection.closeStream(streamid);
} else {
- debug.log(Level.DEBUG, "Can't release stream %d", streamid);
+ if (debug.on()) debug.log("Can't release stream %d", streamid);
}
}
@@ -671,13 +672,13 @@
void registerStream(int id) {
this.streamid = id;
connection.putStream(this, streamid);
- debug.log(Level.DEBUG, "Registered stream %d", id);
+ if (debug.on()) debug.log("Registered stream %d", id);
}
void signalWindowUpdate() {
RequestSubscriber subscriber = requestSubscriber;
assert subscriber != null;
- debug.log(Level.DEBUG, "Signalling window update");
+ if (debug.on()) debug.log("Signalling window update");
subscriber.sendScheduler.runOrSchedule();
}
@@ -714,13 +715,15 @@
throw new IllegalStateException("already subscribed");
}
this.subscription = subscription;
- debug.log(Level.DEBUG, "RequestSubscriber: onSubscribe, request 1");
+ if (debug.on())
+ debug.log("RequestSubscriber: onSubscribe, request 1");
subscription.request(1);
}
@Override
public void onNext(ByteBuffer item) {
- debug.log(Level.DEBUG, "RequestSubscriber: onNext(%d)", item.remaining());
+ if (debug.on())
+ debug.log("RequestSubscriber: onNext(%d)", item.remaining());
int size = outgoing.size();
assert size == 0 : "non-zero size: " + size;
onNextImpl(item);
@@ -740,7 +743,8 @@
@Override
public void onError(Throwable throwable) {
- debug.log(Level.DEBUG, () -> "RequestSubscriber: onError: " + throwable);
+ if (debug.on())
+ debug.log(() -> "RequestSubscriber: onError: " + throwable);
// ensure that errors are handled within the flow.
if (errorRef.compareAndSet(null, throwable)) {
sendScheduler.runOrSchedule();
@@ -749,7 +753,7 @@
@Override
public void onComplete() {
- debug.log(Level.DEBUG, "RequestSubscriber: onComplete");
+ if (debug.on()) debug.log("RequestSubscriber: onComplete");
int size = outgoing.size();
assert size == 0 || size == 1 : "non-zero or one size: " + size;
// last byte of request body has been obtained.
@@ -786,12 +790,12 @@
// handle bytes to send downstream
while (item.hasRemaining()) {
- debug.log(Level.DEBUG, "trySend: %d", item.remaining());
+ if (debug.on()) debug.log("trySend: %d", item.remaining());
assert !endStreamSent : "internal error, send data after END_STREAM flag";
DataFrame df = getDataFrame(item);
if (df == null) {
- debug.log(Level.DEBUG, "trySend: can't send yet: %d",
- item.remaining());
+ if (debug.on())
+ debug.log("trySend: can't send yet: %d", item.remaining());
return; // the send window is exhausted: come back later
}
@@ -811,7 +815,8 @@
endStreamSent = true;
}
}
- debug.log(Level.DEBUG, "trySend: sending: %d", df.getDataLength());
+ if (debug.on())
+ debug.log("trySend: sending: %d", df.getDataLength());
connection.sendDataFrame(df);
}
assert !item.hasRemaining();
@@ -819,10 +824,10 @@
assert b == item;
} while (outgoing.peekFirst() != null);
- debug.log(Level.DEBUG, "trySend: request 1");
+ if (debug.on()) debug.log("trySend: request 1");
subscription.request(1);
} catch (Throwable ex) {
- debug.log(Level.DEBUG, "trySend: ", ex);
+ if (debug.on()) debug.log("trySend: ", ex);
sendScheduler.stop();
subscription.cancel();
requestBodyCF.completeExceptionally(ex);
@@ -1012,7 +1017,7 @@
void onSubscriptionError(Throwable t) {
errorRef.compareAndSet(null, t);
- debug.log(Level.DEBUG, "Got subscription error: %s", (Object)t);
+ if (debug.on()) debug.log("Got subscription error: %s", (Object)t);
// This is the special case where the subscriber
// has requested an illegal number of items.
// In this case, the error doesn't come from
@@ -1031,7 +1036,7 @@
// This method sends a RST_STREAM frame
void cancelImpl(Throwable e) {
errorRef.compareAndSet(null, e);
- debug.log(Level.DEBUG, "cancelling stream {0}: {1}", streamid, e);
+ if (debug.on()) debug.log("cancelling stream {0}: {1}", streamid, e);
if (Log.trace()) {
Log.logTrace("cancelling stream {0}: {1}\n", streamid, e);
}
--- a/src/java.net.http/share/classes/jdk/internal/net/http/WindowController.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/WindowController.java Mon Apr 16 16:44:12 2018 +0100
@@ -33,6 +33,8 @@
import java.util.LinkedHashMap;
import java.util.List;
import java.util.concurrent.locks.ReentrantLock;
+
+import jdk.internal.net.http.common.Logger;
import jdk.internal.net.http.common.Utils;
/**
@@ -49,9 +51,8 @@
*/
final class WindowController {
- static final boolean DEBUG = Utils.DEBUG; // Revisit: temporary developer's flag
- static final System.Logger DEBUG_LOGGER =
- Utils.getDebugLogger("WindowController"::toString, DEBUG);
+ static final Logger debug =
+ Utils.getDebugLogger("WindowController"::toString, Utils.DEBUG);
/**
* Default initial connection Flow-Control Send Window size, as per HTTP/2.
@@ -140,10 +141,10 @@
Math.min(streamSize, connectionWindowSize));
if (x <= 0) { // stream window size may be negative
- DEBUG_LOGGER.log(Level.DEBUG,
- "Stream %d requesting %d but only %d available (stream: %d, connection: %d)",
- streamid, requestAmount, Math.min(streamSize, connectionWindowSize),
- streamSize, connectionWindowSize);
+ if (debug.on())
+ debug.log("Stream %d requesting %d but only %d available (stream: %d, connection: %d)",
+ streamid, requestAmount, Math.min(streamSize, connectionWindowSize),
+ streamSize, connectionWindowSize);
// If there's not enough window size available, put the
// caller in a pending list.
pending.put(streamid, Map.entry(stream, requestAmount));
@@ -157,10 +158,10 @@
streamSize -= x;
streams.put(streamid, streamSize);
connectionWindowSize -= x;
- DEBUG_LOGGER.log(Level.DEBUG,
- "Stream %d amount allocated %d, now %d available (stream: %d, connection: %d)",
- streamid, x, Math.min(streamSize, connectionWindowSize),
- streamSize, connectionWindowSize);
+ if (debug.on())
+ debug.log("Stream %d amount allocated %d, now %d available (stream: %d, connection: %d)",
+ streamid, x, Math.min(streamSize, connectionWindowSize),
+ streamSize, connectionWindowSize);
return x;
} finally {
controllerLock.unlock();
@@ -186,9 +187,9 @@
if (size < 0)
return false;
connectionWindowSize = size;
- DEBUG_LOGGER.log(Level.DEBUG,
- "Connection window size is now %d (amount added %d)",
- size, amount);
+ if (debug.on())
+ debug.log("Connection window size is now %d (amount added %d)",
+ size, amount);
// Notify waiting streams, until the new increased window size is
// effectively exhausted.
@@ -241,17 +242,17 @@
Integer size = streams.get(streamid);
if (size == null) {
// The stream may have been cancelled.
- DEBUG_LOGGER.log(Level.DEBUG,
- "WARNING: No entry found for streamid: %s. May be cancelled?",
- streamid);
+ if (debug.on())
+ debug.log("WARNING: No entry found for streamid: %s. May be cancelled?",
+ streamid);
} else {
size += amount;
if (size < 0)
return false;
streams.put(streamid, size);
- DEBUG_LOGGER.log(Level.DEBUG,
- "Stream %s window size is now %s (amount added %d)",
- streamid, size, amount);
+ if (debug.on())
+ debug.log("Stream %s window size is now %s (amount added %d)",
+ streamid, size, amount);
Map.Entry<Stream<?>, Integer> p = pending.get(streamid);
if (p != null) {
@@ -293,9 +294,9 @@
Integer size = entry.getValue();
size += adjustAmount;
streams.put(streamid, size);
- DEBUG_LOGGER.log(Level.DEBUG,
- "Stream %s window size is now %s (adjusting amount %d)",
- streamid, size, adjustAmount);
+ if (debug.on())
+ debug.log("Stream %s window size is now %s (adjusting amount %d)",
+ streamid, size, adjustAmount);
}
}
} finally {
--- a/src/java.net.http/share/classes/jdk/internal/net/http/WindowUpdateSender.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/WindowUpdateSender.java Mon Apr 16 16:44:12 2018 +0100
@@ -25,18 +25,16 @@
package jdk.internal.net.http;
-import java.lang.System.Logger.Level;
+import jdk.internal.net.http.common.Logger;
import jdk.internal.net.http.frame.SettingsFrame;
import jdk.internal.net.http.frame.WindowUpdateFrame;
import jdk.internal.net.http.common.Utils;
-
import java.util.concurrent.atomic.AtomicInteger;
abstract class WindowUpdateSender {
- final static boolean DEBUG = Utils.DEBUG;
- final System.Logger debug =
- Utils.getDebugLogger(this::dbgString, DEBUG);
+ final Logger debug =
+ Utils.getDebugLogger(this::dbgString, Utils.DEBUG);
final int limit;
final Http2Connection connection;
@@ -60,14 +58,15 @@
// or
// - remaining window size reached max frame size.
limit = Math.min(v0, v1);
- debug.log(Level.DEBUG, "maxFrameSize=%d, initWindowSize=%d, limit=%d",
- maxFrameSize, initWindowSize, limit);
+ if (debug.on())
+ debug.log("maxFrameSize=%d, initWindowSize=%d, limit=%d",
+ maxFrameSize, initWindowSize, limit);
}
abstract int getStreamId();
void update(int delta) {
- debug.log(Level.DEBUG, "update: %d", delta);
+ if (debug.on()) debug.log("update: %d", delta);
if (received.addAndGet(delta) > limit) {
synchronized (this) {
int tosend = received.get();
@@ -80,7 +79,7 @@
}
void sendWindowUpdate(int delta) {
- debug.log(Level.DEBUG, "sending window update: %d", delta);
+ if (debug.on()) debug.log("sending window update: %d", delta);
connection.sendUnorderedFrame(new WindowUpdateFrame(getStreamId(), delta));
}
--- a/src/java.net.http/share/classes/jdk/internal/net/http/common/DebugLogger.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/common/DebugLogger.java Mon Apr 16 16:44:12 2018 +0100
@@ -44,7 +44,7 @@
* <p> See {@link Utils#getDebugLogger(Supplier, boolean)} and
* {@link Utils#getHpackLogger(Supplier, boolean)}.
*/
-class DebugLogger implements Logger {
+final 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";
@@ -120,7 +120,7 @@
}
@Override
- public boolean isOn() {
+ public final boolean on() {
return debugOn;
}
--- a/src/java.net.http/share/classes/jdk/internal/net/http/common/Logger.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/common/Logger.java Mon Apr 16 16:44:12 2018 +0100
@@ -25,8 +25,6 @@
package jdk.internal.net.http.common;
-import java.util.Objects;
-import java.util.ResourceBundle;
import java.util.function.Supplier;
/**
@@ -34,13 +32,11 @@
* debugging purposes in the {@link java.net.http} module.
* <p>
* Though not enforced, this interface is designed for emitting
- * debug messages with Level.DEBUG, when system assertions are
- * turned on.
+ * debug messages with Level.DEBUG.
* <p>
- * It defines {@code log} methods that default to {@code Level.DEBUG}
- * and always return {@code true}, so that they can be called in
- * assert statements like:
- * <pre>{@code assert debug.log("some %s with %d %s", message(), one(), params());}</pre>
+ * It defines {@code log} methods that default to {@code Level.DEBUG},
+ * so that they can be called in statements like:
+ * <pre>{@code debug.log("some %s with %d %s", message(), one(), params());}</pre>
*
* @implSpec
* This interface is implemented by loggers returned by
@@ -56,7 +52,7 @@
* @implSpec The default implementation for this method calls
* {@code this.isLoggable(Level.DEBUG);}
*/
- public default boolean isOn() {
+ public default boolean on() {
return isLoggable(Level.DEBUG);
}
@@ -71,12 +67,9 @@
* System.LoggerFinder#getLocalizedLogger(java.lang.String,
* java.util.ResourceBundle, java.lang.Module) localized logger});
* can be {@code null}.
- *
- * @return Always return true.
*/
- public default boolean log(String msg) {
+ public default void log(String msg) {
log(Level.DEBUG, msg);
- return true;
}
/**
@@ -88,12 +81,9 @@
* @param msgSupplier a supplier function that produces a message.
*
* @throws NullPointerException if {@code msgSupplier} is {@code null}.
- *
- * @return Always return true.
*/
- public default boolean log(Supplier<String> msgSupplier) {
+ public default void log(Supplier<String> msgSupplier) {
log(Level.DEBUG, msgSupplier);
- return true;
}
/**
@@ -105,12 +95,9 @@
* @param obj the object to log.
*
* @throws NullPointerException if {@code obj} is {@code null}.
- *
- * @return Always return true.
*/
- public default boolean log(Object obj) {
+ public default void log(Object obj) {
log(Level.DEBUG, obj);
- return true;
}
/**
@@ -126,12 +113,9 @@
* can be {@code null}.
* @param thrown a {@code Throwable} associated with the log message;
* can be {@code null}.
- *
- * @return Always return true.
*/
- public default boolean log(String msg, Throwable thrown) {
+ public default void log(String msg, Throwable thrown) {
this.log(Level.DEBUG, msg, thrown);
- return true;
}
/**
@@ -145,12 +129,9 @@
* can be {@code null}.
*
* @throws NullPointerException if {@code msgSupplier} is {@code null}.
- *
- * @return Always return true.
*/
- public default boolean log(Supplier<String> msgSupplier, Throwable thrown) {
+ public default void log(Supplier<String> msgSupplier, Throwable thrown) {
log(Level.DEBUG, msgSupplier, thrown);
- return true;
}
/**
@@ -168,12 +149,8 @@
* can be {@code null}.
* @param params an optional list of parameters to the message (may be
* none).
- *
- * @return Always return true.
*/
- public default boolean log(String format, Object... params) {
+ public default void log(String format, Object... params) {
log(Level.DEBUG, format, params);
- return true;
}
-
}
--- a/src/java.net.http/share/classes/jdk/internal/net/http/common/SSLFlowDelegate.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/common/SSLFlowDelegate.java Mon Apr 16 16:44:12 2018 +0100
@@ -84,9 +84,8 @@
*/
public class SSLFlowDelegate {
- static final boolean DEBUG = Utils.DEBUG; // Revisit: temporary dev flag.
- final System.Logger debug =
- Utils.getDebugLogger(this::dbgString, DEBUG);
+ final Logger debug =
+ Utils.getDebugLogger(this::dbgString, Utils.DEBUG);
final Executor exec;
final Reader reader;
@@ -173,7 +172,7 @@
if (alpnCF.isDone())
return;
String alpn = engine.getApplicationProtocol();
- debug.log(Level.DEBUG, "setALPN = %s", alpn);
+ if (debug.on()) debug.log("setALPN = %s", alpn);
alpnCF.complete(alpn);
}
@@ -218,10 +217,9 @@
final SequentialScheduler scheduler;
static final int TARGET_BUFSIZE = 16 * 1024;
volatile ByteBuffer readBuf;
- volatile boolean completing = false;
+ volatile boolean completing;
final Object readBufferLock = new Object();
- final System.Logger debugr =
- Utils.getDebugLogger(this::dbgString, DEBUG);
+ final Logger debugr = Utils.getDebugLogger(this::dbgString, Utils.DEBUG);
class ReaderDownstreamPusher implements Runnable {
@Override public void run() { processData(); }
@@ -248,8 +246,9 @@
*/
@Override
public void incoming(List<ByteBuffer> buffers, boolean complete) {
- debugr.log(Level.DEBUG, () -> "Adding " + Utils.remaining(buffers)
- + " bytes to read buffer");
+ if (debugr.on())
+ debugr.log("Adding %d bytes to read buffer",
+ Utils.remaining(buffers));
addToReadBuf(buffers, complete);
scheduler.runOrSchedule();
}
@@ -298,7 +297,7 @@
}
void stop() {
- debugr.log(Level.DEBUG, "stop");
+ if (debugr.on()) debugr.log("stop");
scheduler.stop();
}
@@ -307,7 +306,8 @@
// work function where it all happens
void processData() {
try {
- debugr.log(Level.DEBUG, () -> "processData:"
+ if (debugr.on())
+ debugr.log("processData:"
+ " readBuf remaining:" + readBuf.remaining()
+ ", state:" + states(handshakeState)
+ ", engine handshake status:" + engine.getHandshakeStatus());
@@ -320,15 +320,17 @@
synchronized (readBufferLock) {
complete = this.completing;
result = unwrapBuffer(readBuf);
- debugr.log(Level.DEBUG, "Unwrapped: %s", result.result);
+ if (debugr.on())
+ debugr.log("Unwrapped: %s", result.result);
}
if (result.bytesProduced() > 0) {
- debugr.log(Level.DEBUG, "sending %d", result.bytesProduced());
+ if (debugr.on())
+ debugr.log("sending %d", result.bytesProduced());
count.addAndGet(result.bytesProduced());
outgoing(result.destBuffer, false);
}
if (result.status() == Status.BUFFER_UNDERFLOW) {
- debugr.log(Level.DEBUG, "BUFFER_UNDERFLOW");
+ if (debugr.on()) debugr.log("BUFFER_UNDERFLOW");
// not enough data in the read buffer...
requestMore();
synchronized (readBufferLock) {
@@ -338,18 +340,18 @@
}
}
if (complete && result.status() == Status.CLOSED) {
- debugr.log(Level.DEBUG, "Closed: completing");
+ if (debugr.on()) debugr.log("Closed: completing");
outgoing(Utils.EMPTY_BB_LIST, true);
return;
}
if (result.handshaking() && !complete) {
- debugr.log(Level.DEBUG, "handshaking");
+ if (debugr.on()) debugr.log("handshaking");
if (doHandshake(result, READER)) {
resumeActivity();
}
handshaking = true;
} else {
- if ((handshakeState.getAndSet(NOT_HANDSHAKING) & ~DOING_TASKS) == HANDSHAKING) {
+ if ((handshakeState.getAndSet(NOT_HANDSHAKING)& ~DOING_TASKS) == HANDSHAKING) {
setALPN();
handshaking = false;
resumeActivity();
@@ -368,7 +370,7 @@
}
}
if (complete) {
- debugr.log(Level.DEBUG, "completing");
+ if (debugr.on()) debugr.log("completing");
// Complete the alpnCF, if not already complete, regardless of
// whether or not the ALPN is available, there will be no more
// activity.
@@ -471,8 +473,7 @@
// queues of buffers received from upstream waiting
// to be processed by the SSLEngine
final List<ByteBuffer> writeList;
- final System.Logger debugw =
- Utils.getDebugLogger(this::dbgString, DEBUG);
+ final Logger debugw = Utils.getDebugLogger(this::dbgString, Utils.DEBUG);
volatile boolean completing;
boolean completed; // only accessed in processData
@@ -491,15 +492,16 @@
assert complete ? buffers == Utils.EMPTY_BB_LIST : true;
assert buffers != Utils.EMPTY_BB_LIST ? complete == false : true;
if (complete) {
- debugw.log(Level.DEBUG, "adding SENTINEL");
+ if (debugw.on()) debugw.log("adding SENTINEL");
completing = true;
writeList.add(SENTINEL);
} else {
writeList.addAll(buffers);
}
- debugw.log(Level.DEBUG, () -> "added " + buffers.size()
- + " (" + Utils.remaining(buffers)
- + " bytes) to the writeList");
+ if (debugw.on())
+ debugw.log("added " + buffers.size()
+ + " (" + Utils.remaining(buffers)
+ + " bytes) to the writeList");
scheduler.runOrSchedule();
}
@@ -508,7 +510,7 @@
}
protected void onSubscribe() {
- debugw.log(Level.DEBUG, "onSubscribe initiating handshaking");
+ if (debugw.on()) debugw.log("onSubscribe initiating handshaking");
addData(HS_TRIGGER); // initiates handshaking
}
@@ -517,7 +519,7 @@
}
void stop() {
- debugw.log(Level.DEBUG, "stop");
+ if (debugw.on()) debugw.log("stop");
scheduler.stop();
}
@@ -551,14 +553,16 @@
boolean completing = isCompleting();
try {
- debugw.log(Level.DEBUG, () -> "processData, writeList remaining:"
- + Utils.remaining(writeList) + ", hsTriggered:"
- + hsTriggered() + ", needWrap:" + needWrap());
+ if (debugw.on())
+ debugw.log("processData, writeList remaining:"
+ + Utils.remaining(writeList) + ", hsTriggered:"
+ + hsTriggered() + ", needWrap:" + needWrap());
while (Utils.remaining(writeList) > 0 || hsTriggered() || needWrap()) {
ByteBuffer[] outbufs = writeList.toArray(Utils.EMPTY_BB_ARRAY);
EngineResult result = wrapBuffers(outbufs);
- debugw.log(Level.DEBUG, "wrapBuffer returned %s", result.result);
+ if (debugw.on())
+ debugw.log("wrapBuffer returned %s", result.result);
if (result.status() == Status.CLOSED) {
if (!upstreamCompleted) {
@@ -577,7 +581,7 @@
boolean handshaking = false;
if (result.handshaking()) {
- debugw.log(Level.DEBUG, "handshaking");
+ if (debugw.on()) debugw.log("handshaking");
doHandshake(result, WRITER); // ok to ignore return
handshaking = true;
} else {
@@ -615,16 +619,17 @@
@SuppressWarnings("fallthrough")
EngineResult wrapBuffers(ByteBuffer[] src) throws SSLException {
- debugw.log(Level.DEBUG, () -> "wrapping " + Utils.remaining(src) + " bytes");
+ if (debugw.on())
+ debugw.log("wrapping " + Utils.remaining(src) + " bytes");
ByteBuffer dst = getNetBuffer();
while (true) {
SSLEngineResult sslResult = engine.wrap(src, dst);
- debugw.log(Level.DEBUG, () -> "SSLResult: " + sslResult);
+ if (debugw.on()) debugw.log("SSLResult: " + sslResult);
switch (sslResult.getStatus()) {
case BUFFER_OVERFLOW:
// Shouldn't happen. We allocated buffer with packet size
// get it again if net buffer size was changed
- debugw.log(Level.DEBUG, "BUFFER_OVERFLOW");
+ if (debugw.on()) debugw.log("BUFFER_OVERFLOW");
int appSize = engine.getSession().getApplicationBufferSize();
ByteBuffer b = ByteBuffer.allocate(appSize + dst.position());
dst.flip();
@@ -632,26 +637,26 @@
dst = b;
break; // try again
case CLOSED:
- debugw.log(Level.DEBUG, "CLOSED");
+ if (debugw.on()) debugw.log("CLOSED");
// fallthrough. There could be some remaining data in dst.
// CLOSED will be handled by the caller.
case OK:
dst.flip();
final ByteBuffer dest = dst;
- debugw.log(Level.DEBUG, () -> "OK => produced: "
- + dest.remaining()
- + " not wrapped: "
- + Utils.remaining(src));
+ if (debugw.on())
+ debugw.log("OK => produced: %d, not wrapped: %d",
+ dest.remaining(), Utils.remaining(src));
return new EngineResult(sslResult, dest);
case BUFFER_UNDERFLOW:
// Shouldn't happen. Doesn't returns when wrap()
// underflow handled externally
// assert false : "Buffer Underflow";
- debug.log(Level.DEBUG, "BUFFER_UNDERFLOW");
+ if (debug.on()) debug.log("BUFFER_UNDERFLOW");
return new EngineResult(sslResult);
default:
- debugw.log(Level.DEBUG, "ASSERT");
- assert false;
+ if (debugw.on())
+ debugw.log("result: %s", sslResult.getStatus());
+ assert false : "result:" + sslResult.getStatus();
}
}
}
@@ -662,8 +667,9 @@
private void sendResultBytes(EngineResult result) {
if (result.bytesProduced() > 0) {
- debugw.log(Level.DEBUG, "Sending %d bytes downstream",
- result.bytesProduced());
+ if (debugw.on())
+ debugw.log("Sending %d bytes downstream",
+ result.bytesProduced());
outgoing(result.destBuffer, false);
}
}
@@ -677,7 +683,7 @@
}
private void handleError(Throwable t) {
- debug.log(Level.DEBUG, "handleError", t);
+ if (debug.on()) debug.log("handleError", t);
readerCF.completeExceptionally(t);
writerCF.completeExceptionally(t);
// no-op if already completed
@@ -766,7 +772,7 @@
if ((s & DOING_TASKS) > 0) // someone else was doing tasks
return false;
- debug.log(Level.DEBUG, "obtaining and initiating task execution");
+ if (debug.on()) debug.log("obtaining and initiating task execution");
List<Runnable> tasks = obtainTasks();
executeTasks(tasks);
return false; // executeTasks will resume activity
@@ -822,16 +828,16 @@
// FIXME: acknowledge a received CLOSE request from peer
EngineResult doClosure(EngineResult r) throws IOException {
- debug.log(Level.DEBUG,
- "doClosure(%s): %s [isOutboundDone: %s, isInboundDone: %s]",
- r.result, engine.getHandshakeStatus(),
- engine.isOutboundDone(), engine.isInboundDone());
+ if (debug.on())
+ debug.log("doClosure(%s): %s [isOutboundDone: %s, isInboundDone: %s]",
+ r.result, engine.getHandshakeStatus(),
+ engine.isOutboundDone(), engine.isInboundDone());
if (engine.getHandshakeStatus() == HandshakeStatus.NEED_WRAP) {
// we have received TLS close_notify and need to send
// an acknowledgement back. We're calling doHandshake
// to finish the close handshake.
if (engine.isInboundDone() && !engine.isOutboundDone()) {
- debug.log(Level.DEBUG, "doClosure: close_notify received");
+ if (debug.on()) debug.log("doClosure: close_notify received");
close_notify_received = true;
doHandshake(r, READER);
}
--- a/src/java.net.http/share/classes/jdk/internal/net/http/common/SSLTube.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/common/SSLTube.java Mon Apr 16 16:44:12 2018 +0100
@@ -25,7 +25,6 @@
package jdk.internal.net.http.common;
-import java.lang.System.Logger.Level;
import java.nio.ByteBuffer;
import java.util.List;
import java.util.Objects;
@@ -67,9 +66,8 @@
*/
public class SSLTube implements FlowTube {
- static final boolean DEBUG = Utils.DEBUG; // revisit: temporary developer's flag.
- final System.Logger debug =
- Utils.getDebugLogger(this::dbgString, DEBUG);
+ final Logger debug =
+ Utils.getDebugLogger(this::dbgString, Utils.DEBUG);
private final FlowTube tube;
private final SSLSubscriberWrapper readSubscriber;
@@ -171,13 +169,13 @@
// onComplete/onError are not called before onSubscribed.
final static class DelegateWrapper implements FlowTube.TubeSubscriber {
private final FlowTube.TubeSubscriber delegate;
- private final System.Logger debug;
+ private final Logger debug;
volatile boolean subscribedCalled;
volatile boolean subscribedDone;
volatile boolean completed;
volatile Throwable error;
DelegateWrapper(Flow.Subscriber<? super List<ByteBuffer>> delegate,
- System.Logger debug) {
+ Logger debug) {
this.delegate = FlowTube.asTubeSubscriber(delegate);
this.debug = debug;
}
@@ -212,13 +210,13 @@
finished = completed;
}
if (x != null) {
- debug.log(Level.DEBUG,
- "Subscriber completed before subscribe: forwarding %s",
- (Object)x);
+ if (debug.on())
+ debug.log("Subscriber completed before subscribe: forwarding %s",
+ (Object)x);
delegate.onError(x);
} else if (finished) {
- debug.log(Level.DEBUG,
- "Subscriber completed before subscribe: calling onComplete()");
+ if (debug.on())
+ debug.log("Subscriber completed before subscribe: calling onComplete()");
delegate.onComplete();
}
}
@@ -226,9 +224,9 @@
@Override
public void onError(Throwable t) {
if (completed) {
- debug.log(Level.DEBUG,
- "Subscriber already completed: ignoring %s",
- (Object)t);
+ if (debug.on())
+ debug.log("Subscriber already completed: ignoring %s",
+ (Object)t);
return;
}
boolean subscribed;
@@ -241,9 +239,9 @@
if (subscribed) {
delegate.onError(t);
} else {
- debug.log(Level.DEBUG,
- "Subscriber not yet subscribed: stored %s",
- (Object)t);
+ if (debug.on())
+ debug.log("Subscriber not yet subscribed: stored %s",
+ (Object)t);
}
}
@@ -257,11 +255,11 @@
subscribed = subscribedDone;
}
if (subscribed) {
- debug.log(Level.DEBUG, "DelegateWrapper: completing subscriber");
+ if (debug.on()) debug.log("DelegateWrapper: completing subscriber");
delegate.onComplete();
} else {
- debug.log(Level.DEBUG,
- "Subscriber not yet subscribed: stored completed=true");
+ if (debug.on())
+ debug.log("Subscriber not yet subscribed: stored completed=true");
}
}
@@ -291,8 +289,9 @@
// we're going to wait for onSubscribe to be called.
//
void setDelegate(Flow.Subscriber<? super List<ByteBuffer>> delegate) {
- debug.log(Level.DEBUG, "SSLSubscriberWrapper (reader) got delegate: %s",
- delegate);
+ if (debug.on())
+ debug.log("SSLSubscriberWrapper (reader) got delegate: %s",
+ delegate);
assert delegate != null;
DelegateWrapper delegateWrapper = new DelegateWrapper(delegate, debug);
DelegateWrapper previous;
@@ -307,7 +306,8 @@
previous.dropSubscription();
}
if (subscription == null) {
- debug.log(Level.DEBUG, "SSLSubscriberWrapper (reader) no subscription yet");
+ if (debug.on())
+ debug.log("SSLSubscriberWrapper (reader) no subscription yet");
return;
}
if (handleNow || !sslDelegate.resumeReader()) {
@@ -331,9 +331,9 @@
previous = subscribed;
}
if (subscription == null) {
- debug.log(Level.DEBUG,
- "SSLSubscriberWrapper (reader) %s",
- "processPendingSubscriber: no subscription yet");
+ if (debug.on())
+ debug.log("SSLSubscriberWrapper (reader) " +
+ "processPendingSubscriber: no subscription yet");
return;
}
delegateWrapper = pendingDelegate.getAndSet(null);
@@ -354,9 +354,9 @@
@Override
public void onSubscribe(Flow.Subscription subscription) {
- debug.log(Level.DEBUG,
- "SSLSubscriberWrapper (reader) onSubscribe(%s)",
- subscription);
+ if (debug.on())
+ debug.log("SSLSubscriberWrapper (reader) onSubscribe(%s)",
+ subscription);
onSubscribeImpl(subscription);
}
@@ -371,9 +371,9 @@
}
if (subscriberImpl == null && pending == null) {
- debug.log(Level.DEBUG,
- "SSLSubscriberWrapper (reader) onSubscribeImpl: %s",
- "no delegate yet");
+ if (debug.on())
+ debug.log("SSLSubscriberWrapper (reader) onSubscribeImpl: "
+ + "no delegate yet");
return;
}
@@ -382,17 +382,17 @@
// subscribed delegate. This is obviously a re-subscribe.
// We are in the downstream reader flow, so we should call
// onSubscribe directly.
- debug.log(Level.DEBUG,
- "SSLSubscriberWrapper (reader) onSubscribeImpl: %s",
- "resubscribing");
+ if (debug.on())
+ debug.log("SSLSubscriberWrapper (reader) onSubscribeImpl: "
+ + "resubscribing");
onNewSubscription(subscriberImpl, subscription);
} else {
// We have some pending subscriber: subscribe it now that we have
// a subscription. If we already had a previous delegate then
// it will get a dropSubscription().
- debug.log(Level.DEBUG,
- "SSLSubscriberWrapper (reader) onSubscribeImpl: %s",
- "subscribing pending");
+ if (debug.on())
+ debug.log("SSLSubscriberWrapper (reader) onSubscribeImpl: "
+ + "subscribing pending");
processPendingSubscriber();
}
}
@@ -439,7 +439,8 @@
errorRef.compareAndSet(null, throwable);
Throwable failed = errorRef.get();
finished = true;
- debug.log(Level.DEBUG, "%s: onErrorImpl: %s", this, throwable);
+ if (debug.on())
+ debug.log("%s: onErrorImpl: %s", this, throwable);
DelegateWrapper subscriberImpl;
synchronized (this) {
subscriberImpl = subscribed;
@@ -447,7 +448,8 @@
if (subscriberImpl != null) {
subscriberImpl.onError(failed);
} else {
- debug.log(Level.DEBUG, "%s: delegate null, stored %s", this, failed);
+ if (debug.on())
+ debug.log("%s: delegate null, stored %s", this, failed);
}
// now if we have any pending subscriber, we should forward
// the error to them immediately as the read scheduler will
@@ -486,11 +488,11 @@
}
if (handshakeFailed()) {
- debug.log(Level.DEBUG,
- "handshake: %s, inbound done: %s outbound done: %s",
- engine.getHandshakeStatus(),
- engine.isInboundDone(),
- engine.isOutboundDone());
+ if (debug.on())
+ debug.log("handshake: %s, inbound done: %s outbound done: %s",
+ engine.getHandshakeStatus(),
+ engine.isInboundDone(),
+ engine.isOutboundDone());
onErrorImpl(new SSLHandshakeException(
"Remote host terminated the handshake"));
} else if (subscriberImpl != null) {
@@ -506,7 +508,7 @@
@Override
public void connectFlows(TubePublisher writePub,
TubeSubscriber readSub) {
- debug.log(Level.DEBUG, "connecting flows");
+ if (debug.on()) debug.log("connecting flows");
readSubscriber.setDelegate(readSub);
writePub.subscribe(this);
}
@@ -521,7 +523,7 @@
void setSubscription(Flow.Subscription sub) {
long demand = writeDemand.get(); // FIXME: isn't it a racy way of passing the demand?
delegate = sub;
- debug.log(Level.DEBUG, "setSubscription: demand=%d", demand);
+ if (debug.on()) debug.log("setSubscription: demand=%d", demand);
if (demand > 0)
sub.request(demand);
}
@@ -529,7 +531,7 @@
@Override
public void request(long n) {
writeDemand.increase(n);
- debug.log(Level.DEBUG, "request: n=%d", n);
+ if (debug.on()) debug.log("request: n=%d", n);
Flow.Subscription sub = delegate;
if (sub != null && n > 0) {
sub.request(n);
@@ -558,8 +560,8 @@
Objects.requireNonNull(item);
boolean decremented = writeDemand.tryDecrement();
assert decremented : "Unexpected writeDemand: ";
- debug.log(Level.DEBUG,
- "sending %d buffers to SSL flow delegate", item.size());
+ if (debug.on())
+ debug.log("sending %d buffers to SSL flow delegate", item.size());
sslDelegate.upstreamWriter().onNext(item);
}
--- a/src/java.net.http/share/classes/jdk/internal/net/http/common/SubscriberWrapper.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/common/SubscriberWrapper.java Mon Apr 16 16:44:12 2018 +0100
@@ -60,9 +60,8 @@
implements FlowTube.TubeSubscriber, Closeable, Flow.Processor<List<ByteBuffer>,List<ByteBuffer>>
// TODO: SSLTube Subscriber will never change? Does this really need to be a TS?
{
- static final boolean DEBUG = Utils.DEBUG; // Revisit: temporary dev flag.
- final System.Logger logger =
- Utils.getDebugLogger(this::dbgString, DEBUG);
+ final Logger debug =
+ Utils.getDebugLogger(this::dbgString, Utils.DEBUG);
public enum SchedulingAction { CONTINUE, RETURN, RESCHEDULE }
@@ -217,21 +216,21 @@
if (complete) {
assert Utils.remaining(buffers) == 0;
boolean closing = closing();
- logger.log(Level.DEBUG,
- "completionAcknowledged upstreamCompleted:%s,"
- + " downstreamCompleted:%s, closing:%s",
- upstreamCompleted, downstreamCompleted, closing);
+ if (debug.on())
+ debug.log("completionAcknowledged upstreamCompleted:%s,"
+ + " downstreamCompleted:%s, closing:%s",
+ upstreamCompleted, downstreamCompleted, closing);
if (!upstreamCompleted && !closing) {
throw new IllegalStateException("upstream not completed");
}
completionAcknowledged = true;
} else {
- logger.log(Level.DEBUG, () -> "Adding "
- + Utils.remaining(buffers) + " to outputQ queue");
+ if (debug.on())
+ debug.log("Adding %d to outputQ queue", Utils.remaining(buffers));
outputQ.add(buffers);
}
- logger.log(Level.DEBUG, () -> "pushScheduler"
- + (pushScheduler.isStopped() ? " is stopped!" : " is alive"));
+ if (debug.on())
+ debug.log("pushScheduler" +(pushScheduler.isStopped() ? " is stopped!" : " is alive"));
pushScheduler.runOrSchedule();
}
@@ -267,7 +266,8 @@
private void run1() {
if (downstreamCompleted) {
- logger.log(Level.DEBUG, "DownstreamPusher: downstream is already completed");
+ if (debug.on())
+ debug.log("DownstreamPusher: downstream is already completed");
return;
}
switch (enterScheduling()) {
@@ -287,8 +287,8 @@
return;
downstreamCompleted = true;
}
- logger.log(Level.DEBUG,
- () -> "DownstreamPusher: forwarding error downstream: " + error);
+ if (debug.on())
+ debug.log("DownstreamPusher: forwarding error downstream: " + error);
pushScheduler.stop();
outputQ.clear();
downstreamSubscriber.onError(error);
@@ -297,22 +297,20 @@
// OK - no error, let's proceed
if (!outputQ.isEmpty()) {
- logger.log(Level.DEBUG,
- "DownstreamPusher: queue not empty, downstreamSubscription: %s",
- downstreamSubscription);
+ if (debug.on())
+ debug.log("DownstreamPusher: queue not empty, downstreamSubscription: %s",
+ downstreamSubscription);
} else {
- logger.log(Level.DEBUG,
- "DownstreamPusher: queue empty, downstreamSubscription: %s",
- downstreamSubscription);
+ if (debug.on())
+ debug.log("DownstreamPusher: queue empty, downstreamSubscription: %s",
+ downstreamSubscription);
}
- final boolean dbgOn = logger.isLoggable(Level.DEBUG);
while (!outputQ.isEmpty() && downstreamSubscription.tryDecrement()) {
List<ByteBuffer> b = outputQ.poll();
- if (dbgOn) logger.log(Level.DEBUG,
- "DownstreamPusher: Pushing "
- + Utils.remaining(b)
- + " bytes downstream");
+ if (debug.on())
+ debug.log("DownstreamPusher: Pushing %d bytes downstream",
+ Utils.remaining(b));
downstreamSubscriber.onNext(b);
}
upstreamWindowUpdate();
@@ -324,9 +322,10 @@
long downstreamQueueSize = outputQ.size();
long upstreamWindowSize = upstreamWindow.get();
long n = upstreamWindowUpdate(upstreamWindowSize, downstreamQueueSize);
- logger.log(Level.DEBUG, "upstreamWindowUpdate, "
- + "downstreamQueueSize:%d, upstreamWindow:%d",
- downstreamQueueSize, upstreamWindowSize);
+ if (debug.on())
+ debug.log("upstreamWindowUpdate, "
+ + "downstreamQueueSize:%d, upstreamWindow:%d",
+ downstreamQueueSize, upstreamWindowSize);
if (n > 0)
upstreamRequest(n);
}
@@ -338,16 +337,16 @@
}
this.upstreamSubscription = subscription;
upstreamRequest(upstreamWindowUpdate(0, 0));
- logger.log(Level.DEBUG,
- "calling downstreamSubscriber::onSubscribe on %s",
- downstreamSubscriber);
+ if (debug.on())
+ debug.log("calling downstreamSubscriber::onSubscribe on %s",
+ downstreamSubscriber);
downstreamSubscriber.onSubscribe(downstreamSubscription);
onSubscribe();
}
@Override
public void onNext(List<ByteBuffer> item) {
- logger.log(Level.DEBUG, "onNext");
+ if (debug.on()) debug.log("onNext");
long prev = upstreamWindow.getAndDecrement();
if (prev <= 0)
throw new IllegalStateException("invalid onNext call");
@@ -356,7 +355,7 @@
}
private void upstreamRequest(long n) {
- logger.log(Level.DEBUG, "requesting %d", n);
+ if (debug.on()) debug.log("requesting %d", n);
upstreamWindow.getAndAdd(n);
upstreamSubscription.request(n);
}
@@ -373,7 +372,7 @@
@Override
public void onError(Throwable throwable) {
- logger.log(Level.DEBUG, () -> "onError: " + throwable);
+ if (debug.on()) debug.log("onError: " + throwable);
errorCommon(Objects.requireNonNull(throwable));
}
@@ -381,7 +380,7 @@
assert throwable != null ||
(throwable = new AssertionError("null throwable")) != null;
if (errorRef.compareAndSet(null, throwable)) {
- logger.log(Level.DEBUG, "error", throwable);
+ if (debug.on()) debug.log("error", throwable);
pushScheduler.runOrSchedule();
upstreamCompleted = true;
cf.completeExceptionally(throwable);
@@ -409,7 +408,7 @@
@Override
public void onComplete() {
- logger.log(Level.DEBUG, () -> "upstream completed: " + toString());
+ if (debug.on()) debug.log("upstream completed: " + toString());
upstreamCompleted = true;
incomingCaller(Utils.EMPTY_BB_LIST, true);
// pushScheduler will call checkCompletion()
@@ -436,7 +435,7 @@
return;
}
if (completionAcknowledged) {
- logger.log(Level.DEBUG, "calling downstreamSubscriber.onComplete()");
+ if (debug.on()) debug.log("calling downstreamSubscriber.onComplete()");
downstreamSubscriber.onComplete();
// Fix me subscriber.onComplete.run();
downstreamCompleted = true;
--- a/src/java.net.http/share/classes/jdk/internal/net/http/frame/FramesDecoder.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/frame/FramesDecoder.java Mon Apr 16 16:44:12 2018 +0100
@@ -32,6 +32,7 @@
import java.util.ArrayList;
import java.util.List;
import jdk.internal.net.http.common.Log;
+import jdk.internal.net.http.common.Logger;
import jdk.internal.net.http.common.Utils;
import static java.nio.charset.StandardCharsets.UTF_8;
@@ -46,9 +47,8 @@
*/
public class FramesDecoder {
- static final boolean DEBUG = Utils.DEBUG; // Revisit: temporary dev flag.
- static final System.Logger DEBUG_LOGGER =
- Utils.getDebugLogger("FramesDecoder"::toString, DEBUG);
+ static final Logger debug =
+ Utils.getDebugLogger("FramesDecoder"::toString, Utils.DEBUG);
@FunctionalInterface
public interface FrameProcessor {
@@ -110,13 +110,14 @@
*/
public void decode(ByteBuffer inBoundBuffer) throws IOException {
if (closed) {
- DEBUG_LOGGER.log(Level.DEBUG, "closed: ignoring buffer (%s bytes)",
- inBoundBuffer.remaining());
+ if (debug.on())
+ debug.log("closed: ignoring buffer (%s bytes)",
+ inBoundBuffer.remaining());
inBoundBuffer.position(inBoundBuffer.limit());
return;
}
int remaining = inBoundBuffer.remaining();
- DEBUG_LOGGER.log(Level.DEBUG, "decodes: %d", remaining);
+ if (debug.on()) debug.log("decodes: %d", remaining);
if (remaining > 0) {
if (currentBuffer == null) {
currentBuffer = inBoundBuffer;
@@ -137,21 +138,20 @@
b.position(position);
if (b != currentBuffer)
tailSize += remaining;
- DEBUG_LOGGER.log(Level.DEBUG, "copied: %d", remaining);
+ if (debug.on()) debug.log("copied: %d", remaining);
} else {
- DEBUG_LOGGER.log(Level.DEBUG, "added: %d", remaining);
+ if (debug.on()) debug.log("added: %d", remaining);
tailBuffers.add(inBoundBuffer);
tailSize += remaining;
}
}
}
- DEBUG_LOGGER.log(Level.DEBUG, "Tail size is now: %d, current=",
- tailSize,
- (currentBuffer == null ? 0 :
- currentBuffer.remaining()));
+ if (debug.on())
+ debug.log("Tail size is now: %d, current=", tailSize,
+ (currentBuffer == null ? 0 : currentBuffer.remaining()));
Http2Frame frame;
while ((frame = nextFrame()) != null) {
- DEBUG_LOGGER.log(Level.DEBUG, "Got frame: %s", frame);
+ if (debug.on()) debug.log("Got frame: %s", frame);
frameProcessor.processFrame(frame);
frameProcessed();
}
@@ -176,9 +176,9 @@
}
frameHeaderParsed = true;
} else {
- DEBUG_LOGGER.log(Level.DEBUG,
- "Not enough data to parse header, needs: %d, has: %d",
- Http2Frame.FRAME_HEADER_SIZE, available);
+ if (debug.on())
+ debug.log("Not enough data to parse header, needs: %d, has: %d",
+ Http2Frame.FRAME_HEADER_SIZE, available);
return null;
}
}
@@ -192,9 +192,9 @@
return frame;
}
} else {
- DEBUG_LOGGER.log(Level.DEBUG,
- "Not enough data to parse frame body, needs: %d, has: %d",
- frameLength, available);
+ if (debug.on())
+ debug.log("Not enough data to parse frame body, needs: %d, has: %d",
+ frameLength, available);
return null; // no data for the whole frame header
}
}
@@ -308,7 +308,7 @@
}
tailSize = 0;
currentBuffer = null;
- DEBUG_LOGGER.log(Level.DEBUG, "closed %s, ignoring %d bytes", msg, bytes);
+ if (debug.on()) debug.log("closed %s, ignoring %d bytes", msg, bytes);
}
public void skipBytes(int bytecount) {
--- a/src/java.net.http/share/classes/jdk/internal/net/http/websocket/MessageDecoder.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/websocket/MessageDecoder.java Mon Apr 16 16:44:12 2018 +0100
@@ -25,6 +25,7 @@
package jdk.internal.net.http.websocket;
+import jdk.internal.net.http.common.Logger;
import jdk.internal.net.http.common.Utils;
import jdk.internal.net.http.websocket.Frame.Opcode;
@@ -33,7 +34,6 @@
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;
@@ -50,9 +50,8 @@
/* Exposed for testing purposes */
class MessageDecoder implements Frame.Consumer {
- private static final boolean DEBUG = Utils.DEBUG_WS;
- private static final System.Logger debug =
- Utils.getWebSocketLogger("[Input]"::toString, DEBUG);
+ private static final Logger debug =
+ Utils.getWebSocketLogger("[Input]"::toString, Utils.DEBUG_WS);
private final MessageStreamConsumer output;
private final UTF8AccumulatingDecoder decoder = new UTF8AccumulatingDecoder();
@@ -73,16 +72,16 @@
@Override
public void fin(boolean value) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "fin %s", value);
+ if (debug.on()) {
+ debug.log("fin %s", value);
}
fin = value;
}
@Override
public void rsv1(boolean value) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "rsv1 %s", value);
+ if (debug.on()) {
+ debug.log("rsv1 %s", value);
}
if (value) {
throw new FailWebSocketException("Unexpected rsv1 bit");
@@ -91,8 +90,8 @@
@Override
public void rsv2(boolean value) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "rsv2 %s", value);
+ if (debug.on()) {
+ debug.log("rsv2 %s", value);
}
if (value) {
throw new FailWebSocketException("Unexpected rsv2 bit");
@@ -101,8 +100,8 @@
@Override
public void rsv3(boolean value) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "rsv3 %s", value);
+ if (debug.on()) {
+ debug.log("rsv3 %s", value);
}
if (value) {
throw new FailWebSocketException("Unexpected rsv3 bit");
@@ -111,8 +110,8 @@
@Override
public void opcode(Opcode v) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "opcode %s", v);
+ if (debug.on()) {
+ debug.log("opcode %s", v);
}
if (v == Opcode.PING || v == Opcode.PONG || v == Opcode.CLOSE) {
if (!fin) {
@@ -141,8 +140,8 @@
@Override
public void mask(boolean value) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "mask %s", value);
+ if (debug.on()) {
+ debug.log("mask %s", value);
}
if (value) {
throw new FailWebSocketException("Masked frame received");
@@ -151,8 +150,8 @@
@Override
public void payloadLen(long value) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "payloadLen %s", value);
+ if (debug.on()) {
+ debug.log("payloadLen %s", value);
}
if (opcode.isControl()) {
if (value > Frame.MAX_CONTROL_FRAME_PAYLOAD_LENGTH) {
@@ -181,8 +180,8 @@
@Override
public void payloadData(ByteBuffer data) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "payload %s", data);
+ if (debug.on()) {
+ debug.log("payload %s", data);
}
unconsumedPayloadLen -= data.remaining();
boolean lastPayloadChunk = unconsumedPayloadLen == 0;
@@ -228,8 +227,8 @@
@Override
public void endFrame() {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "end frame");
+ if (debug.on()) {
+ debug.log("end frame");
}
if (opcode.isControl()) {
binaryData.flip();
--- a/src/java.net.http/share/classes/jdk/internal/net/http/websocket/MessageEncoder.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/websocket/MessageEncoder.java Mon Apr 16 16:44:12 2018 +0100
@@ -25,11 +25,11 @@
package jdk.internal.net.http.websocket;
+import jdk.internal.net.http.common.Logger;
import jdk.internal.net.http.common.Utils;
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;
@@ -49,9 +49,8 @@
*/
public class MessageEncoder {
- private static final boolean DEBUG = Utils.DEBUG_WS;
- private static final System.Logger debug =
- Utils.getWebSocketLogger("[Output]"::toString, DEBUG);
+ private static final Logger debug =
+ Utils.getWebSocketLogger("[Output]"::toString, Utils.DEBUG_WS);
private final SecureRandom maskingKeySource = new SecureRandom();
private final Frame.HeaderWriter headerWriter = new Frame.HeaderWriter();
@@ -129,8 +128,8 @@
public boolean encodeText(CharBuffer src, boolean last, ByteBuffer dst)
throws IOException
{
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "encode text src=[pos=%s lim=%s cap=%s] last=%s dst=%s",
+ if (debug.on()) {
+ debug.log("encode text src=[pos=%s lim=%s cap=%s] last=%s dst=%s",
src.position(), src.limit(), src.capacity(), last, dst);
}
if (closed) {
@@ -147,20 +146,20 @@
charsetEncoder.reset();
}
while (true) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "put");
+ if (debug.on()) {
+ debug.log("put");
}
if (!putAvailable(headerBuffer, dst)) {
return false;
}
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "mask");
+ if (debug.on()) {
+ debug.log("mask");
}
if (maskAvailable(intermediateBuffer, dst) < 0) {
return false;
}
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "moreText");
+ if (debug.on()) {
+ debug.log("moreText");
}
if (!moreText) {
previousFin = last;
@@ -188,8 +187,8 @@
throw new IOException("Malformed text message", e);
}
}
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "frame #%s", headerCount);
+ if (debug.on()) {
+ debug.log("frame #%s", headerCount);
}
intermediateBuffer.flip();
Opcode opcode = previousFin && headerCount == 0
@@ -217,8 +216,8 @@
public boolean encodeBinary(ByteBuffer src, boolean last, ByteBuffer dst)
throws IOException
{
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "encode binary src=%s last=%s dst=%s",
+ if (debug.on()) {
+ debug.log("encode binary src=%s last=%s dst=%s",
src, last, dst);
}
if (closed) {
@@ -257,8 +256,8 @@
public boolean encodePing(ByteBuffer src, ByteBuffer dst)
throws IOException
{
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "encode ping src=%s dst=%s", src, dst);
+ if (debug.on()) {
+ debug.log("encode ping src=%s dst=%s", src, dst);
}
if (closed) {
throw new IOException("Output closed");
@@ -285,8 +284,8 @@
public boolean encodePong(ByteBuffer src, ByteBuffer dst)
throws IOException
{
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "encode pong src=%s dst=%s",
+ if (debug.on()) {
+ debug.log("encode pong src=%s dst=%s",
src, dst);
}
if (closed) {
@@ -314,29 +313,29 @@
public boolean encodeClose(int statusCode, CharBuffer reason, ByteBuffer dst)
throws IOException
{
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "encode close statusCode=%s reason=[pos=%s lim=%s cap=%s] dst=%s",
+ if (debug.on()) {
+ debug.log("encode close statusCode=%s reason=[pos=%s lim=%s cap=%s] dst=%s",
statusCode, reason.position(), reason.limit(), reason.capacity(), dst);
}
if (closed) {
throw new IOException("Output closed");
}
if (!started) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "reason [pos=%s lim=%s cap=%s]",
+ if (debug.on()) {
+ debug.log("reason [pos=%s lim=%s cap=%s]",
reason.position(), reason.limit(), reason.capacity());
}
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.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "flushing");
+ if (debug.on()) {
+ debug.log("flushing");
}
r = charsetEncoder.flush(intermediateBuffer);
}
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "encoding result: %s", r);
+ if (debug.on()) {
+ debug.log("encoding result: %s", r);
}
if (r.isError()) {
try {
@@ -354,8 +353,8 @@
setupHeader(Opcode.CLOSE, true, intermediateBuffer.remaining());
started = true;
closed = true;
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "intermediateBuffer=%s", intermediateBuffer);
+ if (debug.on()) {
+ debug.log("intermediateBuffer=%s", intermediateBuffer);
}
}
if (!putAvailable(headerBuffer, dst)) {
@@ -365,8 +364,8 @@
}
private void setupHeader(Opcode opcode, boolean fin, long payloadLen) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "frame opcode=%s fin=%s len=%s",
+ if (debug.on()) {
+ debug.log("frame opcode=%s fin=%s len=%s",
opcode, fin, payloadLen);
}
headerBuffer.clear();
--- a/src/java.net.http/share/classes/jdk/internal/net/http/websocket/TransportImpl.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/websocket/TransportImpl.java Mon Apr 16 16:44:12 2018 +0100
@@ -26,6 +26,7 @@
package jdk.internal.net.http.websocket;
import jdk.internal.net.http.common.Demand;
+import jdk.internal.net.http.common.Logger;
import jdk.internal.net.http.common.MinimalFuture;
import jdk.internal.net.http.common.SequentialScheduler;
import jdk.internal.net.http.common.SequentialScheduler.CompleteRestartableTask;
@@ -51,9 +52,8 @@
// -- Debugging infrastructure --
- private static final boolean DEBUG = Utils.DEBUG_WS;
- private static final System.Logger debug =
- Utils.getWebSocketLogger("[Transport]"::toString, DEBUG);
+ private static final Logger debug =
+ Utils.getWebSocketLogger("[Transport]"::toString, Utils.DEBUG_WS);
/* Used for correlating enters to and exists from a method */
private final AtomicLong counter = new AtomicLong();
@@ -99,8 +99,8 @@
private ByteBuffer createWriteBuffer() {
String name = "jdk.httpclient.websocket.writeBufferSize";
int capacity = Utils.getIntegerNetProperty(name, 16384);
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "write buffer capacity %s", capacity);
+ if (debug.on()) {
+ debug.log("write buffer capacity %s", capacity);
}
// TODO (optimization?): allocateDirect if SSL?
@@ -108,12 +108,12 @@
}
private boolean write() throws IOException {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "writing to the channel");
+ if (debug.on()) {
+ debug.log("writing to the channel");
}
long count = channel.write(dstArray, 0, dstArray.length);
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "%s bytes written", count);
+ if (debug.on()) {
+ debug.log("%s bytes written", count);
}
for (ByteBuffer b : dstArray) {
if (b.hasRemaining()) {
@@ -129,9 +129,9 @@
T attachment,
BiConsumer<? super T, ? super Throwable> action) {
long id = 0;
- if (debug.isLoggable(Level.DEBUG)) {
+ if (debug.on()) {
id = counter.incrementAndGet();
- debug.log(Level.DEBUG, "enter send text %s message.length=%s last=%s",
+ debug.log("enter send text %s message.length=%s last=%s",
id, message.length(), isLast);
}
// TODO (optimization?):
@@ -151,8 +151,8 @@
action.accept(null, e);
f.completeExceptionally(e);
}
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "exit send text %s returned %s", id, f);
+ if (debug.on()) {
+ debug.log("exit send text %s returned %s", id, f);
}
return f;
}
@@ -163,9 +163,9 @@
T attachment,
BiConsumer<? super T, ? super Throwable> action) {
long id = 0;
- if (debug.isLoggable(Level.DEBUG)) {
+ if (debug.on()) {
id = counter.incrementAndGet();
- debug.log(Level.DEBUG, "enter send binary %s message.remaining=%s last=%s",
+ debug.log("enter send binary %s message.remaining=%s last=%s",
id, message.remaining(), isLast);
}
MinimalFuture<T> f = new MinimalFuture<>();
@@ -176,8 +176,8 @@
action.accept(null, e);
f.completeExceptionally(e);
}
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "exit send binary %s returned %s", id, f);
+ if (debug.on()) {
+ debug.log("exit send binary %s returned %s", id, f);
}
return f;
}
@@ -187,9 +187,9 @@
T attachment,
BiConsumer<? super T, ? super Throwable> action) {
long id = 0;
- if (debug.isLoggable(Level.DEBUG)) {
+ if (debug.on()) {
id = counter.incrementAndGet();
- debug.log(Level.DEBUG, "enter send ping %s message.remaining=%s",
+ debug.log("enter send ping %s message.remaining=%s",
id, message.remaining());
}
MinimalFuture<T> f = new MinimalFuture<>();
@@ -200,8 +200,8 @@
action.accept(null, e);
f.completeExceptionally(e);
}
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "exit send ping %s returned %s", id, f);
+ if (debug.on()) {
+ debug.log("exit send ping %s returned %s", id, f);
}
return f;
}
@@ -211,9 +211,9 @@
T attachment,
BiConsumer<? super T, ? super Throwable> action) {
long id = 0;
- if (debug.isLoggable(Level.DEBUG)) {
+ if (debug.on()) {
id = counter.incrementAndGet();
- debug.log(Level.DEBUG, "enter send pong %s message.remaining=%s",
+ debug.log("enter send pong %s message.remaining=%s",
id, message.remaining());
}
MinimalFuture<T> f = new MinimalFuture<>();
@@ -224,8 +224,8 @@
action.accept(null, e);
f.completeExceptionally(e);
}
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "exit send pong %s returned %s", id, f);
+ if (debug.on()) {
+ debug.log("exit send pong %s returned %s", id, f);
}
return f;
}
@@ -235,9 +235,9 @@
T attachment,
BiConsumer<? super T, ? super Throwable> action) {
long id = 0;
- if (debug.isLoggable(Level.DEBUG)) {
+ if (debug.on()) {
id = counter.incrementAndGet();
- debug.log(Level.DEBUG, "enter send pong %s supplier=%s",
+ debug.log("enter send pong %s supplier=%s",
id, message);
}
MinimalFuture<T> f = new MinimalFuture<>();
@@ -248,8 +248,8 @@
action.accept(null, e);
f.completeExceptionally(e);
}
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "exit send pong %s returned %s", id, f);
+ if (debug.on()) {
+ debug.log("exit send pong %s returned %s", id, f);
}
return f;
}
@@ -260,9 +260,9 @@
T attachment,
BiConsumer<? super T, ? super Throwable> action) {
long id = 0;
- if (debug.isLoggable(Level.DEBUG)) {
+ if (debug.on()) {
id = counter.incrementAndGet();
- debug.log(Level.DEBUG, "enter send close %s statusCode=%s reason.length=%s",
+ debug.log("enter send close %s statusCode=%s reason.length=%s",
id, statusCode, reason.length());
}
MinimalFuture<T> f = new MinimalFuture<>();
@@ -273,16 +273,16 @@
action.accept(null, e);
f.completeExceptionally(e);
}
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "exit send close %s returned %s", id, f);
+ if (debug.on()) {
+ debug.log("exit send close %s returned %s", id, f);
}
return f;
}
@Override
public void request(long n) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "request %s", n);
+ if (debug.on()) {
+ debug.log("request %s", n);
}
if (demand.increase(n)) {
receiveScheduler.runOrSchedule();
@@ -299,8 +299,8 @@
@Override
public void closeOutput() throws IOException {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "closeOutput");
+ if (debug.on()) {
+ debug.log("closeOutput");
}
synchronized (closeLock) {
if (!outputClosed) {
@@ -324,8 +324,8 @@
*/
@Override
public void closeInput() throws IOException {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "closeInput");
+ if (debug.on()) {
+ debug.log("closeInput");
}
synchronized (closeLock) {
if (!inputClosed) {
@@ -518,14 +518,14 @@
// 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.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "enter send task");
+ if (debug.on()) {
+ debug.log("enter send task");
}
while (!queue.isEmpty()) {
try {
if (dst.hasRemaining()) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "%s bytes remaining in buffer %s",
+ if (debug.on()) {
+ debug.log("%s bytes remaining in buffer %s",
dst.remaining(), dst);
}
// The previous part of the binary representation of the
@@ -537,8 +537,8 @@
if (firstPass) {
firstPass = false;
queue.peek(loadCallback);
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "load message");
+ if (debug.on()) {
+ debug.log("load message");
}
}
dst.clear();
@@ -553,8 +553,8 @@
removeAndComplete(null);
}
} catch (Throwable t) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "send task exception %s", (Object) t);
+ if (debug.on()) {
+ debug.log("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
@@ -564,40 +564,40 @@
removeAndComplete(t);
}
}
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "exit send task");
+ if (debug.on()) {
+ debug.log("exit send task");
}
}
private boolean tryCompleteWrite() throws IOException {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "enter writing");
+ if (debug.on()) {
+ debug.log("enter writing");
}
boolean finished = false;
loop:
while (true) {
final ChannelState ws = writeState.get();
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "write state: %s", ws);
+ if (debug.on()) {
+ debug.log("write state: %s", ws);
}
switch (ws) {
case WAITING:
break loop;
case UNREGISTERED:
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "registering write event");
+ if (debug.on()) {
+ debug.log("registering write event");
}
channel.registerEvent(writeEvent);
writeState.compareAndSet(UNREGISTERED, WAITING);
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "registered write event");
+ if (debug.on()) {
+ debug.log("registered write event");
}
break loop;
case AVAILABLE:
boolean written = write();
if (written) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "finished writing to the channel");
+ if (debug.on()) {
+ debug.log("finished writing to the channel");
}
finished = true;
break loop; // All done
@@ -611,16 +611,16 @@
throw new InternalError(String.valueOf(ws));
}
}
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "exit writing");
+ if (debug.on()) {
+ debug.log("exit writing");
}
return finished;
}
@SuppressWarnings("unchecked")
private void removeAndComplete(Throwable error) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "removeAndComplete error=%s", (Object) error);
+ if (debug.on()) {
+ debug.log("removeAndComplete error=%s", (Object) error);
}
queue.remove();
if (error != null) {
@@ -648,15 +648,15 @@
@Override
public void run() {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "enter receive task");
+ if (debug.on()) {
+ debug.log("enter receive task");
}
loop:
while (!receiveScheduler.isStopped()) {
ChannelState rs = readState;
if (data.hasRemaining()) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "remaining bytes received %s",
+ if (debug.on()) {
+ debug.log("remaining bytes received %s",
data.remaining());
}
if (!demand.isFulfilled()) {
@@ -677,8 +677,8 @@
}
break loop;
}
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "receive state: %s", rs);
+ if (debug.on()) {
+ debug.log("receive state: %s", rs);
}
switch (rs) {
case WAITING:
@@ -714,8 +714,8 @@
throw new InternalError(String.valueOf(rs));
}
}
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "exit receive task");
+ if (debug.on()) {
+ debug.log("exit receive task");
}
}
}
@@ -729,15 +729,15 @@
@Override
public void handle() {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "write event");
+ if (debug.on()) {
+ debug.log("write event");
}
ChannelState s;
do {
s = writeState.get();
if (s == CLOSED) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "write state %s", s);
+ if (debug.on()) {
+ debug.log("write state %s", s);
}
break;
}
@@ -755,8 +755,8 @@
@Override
public void handle() {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "read event");
+ if (debug.on()) {
+ debug.log("read event");
}
readState = AVAILABLE;
receiveScheduler.runOrSchedule();
--- a/src/java.net.http/share/classes/jdk/internal/net/http/websocket/WebSocketImpl.java Mon Apr 16 13:57:06 2018 +0100
+++ b/src/java.net.http/share/classes/jdk/internal/net/http/websocket/WebSocketImpl.java Mon Apr 16 16:44:12 2018 +0100
@@ -27,6 +27,7 @@
import jdk.internal.net.http.common.Demand;
import jdk.internal.net.http.common.Log;
+import jdk.internal.net.http.common.Logger;
import jdk.internal.net.http.common.MinimalFuture;
import jdk.internal.net.http.common.SequentialScheduler;
import jdk.internal.net.http.common.Utils;
@@ -73,9 +74,8 @@
*/
public final class WebSocketImpl implements WebSocket {
- private static final boolean DEBUG = Utils.DEBUG_WS;
- private static final System.Logger debug =
- Utils.getWebSocketLogger("[WebSocket]"::toString, DEBUG);
+ private static final Logger debug =
+ Utils.getWebSocketLogger("[WebSocket]"::toString, Utils.DEBUG_WS);
private final AtomicLong sendCounter = new AtomicLong();
private final AtomicLong receiveCounter = new AtomicLong();
@@ -173,9 +173,9 @@
boolean last) {
Objects.requireNonNull(message);
long id = 0;
- if (debug.isLoggable(Level.DEBUG)) {
+ if (debug.on()) {
id = sendCounter.incrementAndGet();
- debug.log(Level.DEBUG, "enter send text %s payload length=%s last=%s",
+ debug.log("enter send text %s payload length=%s last=%s",
id, message.length(), last);
}
CompletableFuture<WebSocket> result;
@@ -185,8 +185,8 @@
result = transport.sendText(message, last, this,
(r, e) -> clearPendingTextOrBinary());
}
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "exit send text %s returned %s", id, result);
+ if (debug.on()) {
+ debug.log("exit send text %s returned %s", id, result);
}
return replaceNull(result);
@@ -197,9 +197,9 @@
boolean last) {
Objects.requireNonNull(message);
long id = 0;
- if (debug.isLoggable(Level.DEBUG)) {
+ if (debug.on()) {
id = sendCounter.incrementAndGet();
- debug.log(Level.DEBUG, "enter send binary %s payload=%s last=%s",
+ debug.log("enter send binary %s payload=%s last=%s",
id, message, last);
}
CompletableFuture<WebSocket> result;
@@ -209,8 +209,8 @@
result = transport.sendBinary(message, last, this,
(r, e) -> clearPendingTextOrBinary());
}
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "exit send binary %s returned %s", id, result);
+ if (debug.on()) {
+ debug.log("exit send binary %s returned %s", id, result);
}
return replaceNull(result);
}
@@ -237,9 +237,9 @@
public CompletableFuture<WebSocket> sendPing(ByteBuffer message) {
Objects.requireNonNull(message);
long id = 0;
- if (debug.isLoggable(Level.DEBUG)) {
+ if (debug.on()) {
id = sendCounter.incrementAndGet();
- debug.log(Level.DEBUG, "enter send ping %s payload=%s", id, message);
+ debug.log("enter send ping %s payload=%s", id, message);
}
CompletableFuture<WebSocket> result;
if (!setPendingPingOrPong()) {
@@ -248,8 +248,8 @@
result = transport.sendPing(message, this,
(r, e) -> clearPendingPingOrPong());
}
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "exit send ping %s returned %s", id, result);
+ if (debug.on()) {
+ debug.log("exit send ping %s returned %s", id, result);
}
return replaceNull(result);
}
@@ -258,9 +258,9 @@
public CompletableFuture<WebSocket> sendPong(ByteBuffer message) {
Objects.requireNonNull(message);
long id = 0;
- if (debug.isLoggable(Level.DEBUG)) {
+ if (debug.on()) {
id = sendCounter.incrementAndGet();
- debug.log(Level.DEBUG, "enter send pong %s payload=%s", id, message);
+ debug.log("enter send pong %s payload=%s", id, message);
}
CompletableFuture<WebSocket> result;
if (!setPendingPingOrPong()) {
@@ -269,8 +269,8 @@
result = transport.sendPong(message, this,
(r, e) -> clearPendingPingOrPong());
}
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "exit send pong %s returned %s", id, result);
+ if (debug.on()) {
+ debug.log("exit send pong %s returned %s", id, result);
}
return replaceNull(result);
}
@@ -288,10 +288,9 @@
String reason) {
Objects.requireNonNull(reason);
long id = 0;
- if (debug.isLoggable(Level.DEBUG)) {
+ if (debug.on()) {
id = sendCounter.incrementAndGet();
- debug.log(Level.DEBUG,
- "enter send close %s statusCode=%s reason.length=%s",
+ debug.log("enter send close %s statusCode=%s reason.length=%s",
id, statusCode, reason.length());
}
CompletableFuture<WebSocket> result;
@@ -308,8 +307,8 @@
} else {
result = sendClose0(statusCode, reason);
}
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "exit send close %s returned %s", id, result);
+ if (debug.on()) {
+ debug.log("exit send close %s returned %s", id, result);
}
return replaceNull(result);
}
@@ -342,9 +341,9 @@
private void processCloseError(Throwable e) {
if (e == null) {
- debug.log(Level.DEBUG, "send close completed successfully");
+ debug.log("send close completed successfully");
} else {
- debug.log(Level.DEBUG, "send close completed with error", e);
+ debug.log("send close completed with error", e);
}
outputClosed.set(true);
try {
@@ -354,8 +353,8 @@
@Override
public void request(long n) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "request %s", n);
+ if (debug.on()) {
+ debug.log("request %s", n);
}
if (demand.increase(n)) {
receiveScheduler.runOrSchedule();
@@ -379,8 +378,8 @@
@Override
public void abort() {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "abort");
+ if (debug.on()) {
+ debug.log("abort");
}
inputClosed = true;
outputClosed.set(true);
@@ -418,14 +417,14 @@
@Override
public void run() {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "enter receive task");
+ if (debug.on()) {
+ debug.log("enter receive task");
}
loop:
while (!receiveScheduler.isStopped()) {
State s = state.get();
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "receive state: %s", s);
+ if (debug.on()) {
+ debug.log("receive state: %s", s);
}
try {
switch (s) {
@@ -472,14 +471,14 @@
signalError(t);
}
}
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "exit receive task");
+ if (debug.on()) {
+ debug.log("exit receive task");
}
}
private void processError() throws IOException {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "processError");
+ if (debug.on()) {
+ debug.log("processError");
}
transport.closeInput();
receiveScheduler.stop();
@@ -487,42 +486,41 @@
if (err instanceof FailWebSocketException) {
int code1 = ((FailWebSocketException) err).getStatusCode();
err = new ProtocolException().initCause(err);
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "failing %s with error=%s statusCode=%s",
+ if (debug.on()) {
+ debug.log("failing %s with error=%s statusCode=%s",
WebSocketImpl.this, err, code1);
}
sendCloseSilently(code1);
}
long id = 0;
- if (debug.isLoggable(Level.DEBUG)) {
+ if (debug.on()) {
id = receiveCounter.incrementAndGet();
- debug.log(Level.DEBUG, "enter onError %s error=%s", id, err);
+ debug.log("enter onError %s error=%s", id, err);
}
try {
listener.onError(WebSocketImpl.this, err);
} finally {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "exit onError %s", id);
+ if (debug.on()) {
+ debug.log("exit onError %s", id);
}
}
}
private void processClose() throws IOException {
- debug.log(Level.DEBUG, "processClose");
+ debug.log("processClose");
transport.closeInput();
receiveScheduler.stop();
CompletionStage<?> cs = null; // when the listener is ready to close
long id = 0;
- if (debug.isLoggable(Level.DEBUG)) {
+ if (debug.on()) {
id = receiveCounter.incrementAndGet();
- debug.log(Level.DEBUG,
- "enter onClose %s statusCode=%s reason.length=%s",
+ debug.log("enter onClose %s statusCode=%s reason.length=%s",
id, statusCode, reason.length());
}
try {
cs = listener.onClose(WebSocketImpl.this, statusCode, reason);
} finally {
- debug.log(Level.DEBUG, "exit onClose %s returned %s", id, cs);
+ debug.log("exit onClose %s returned %s", id, cs);
}
if (cs == null) {
cs = DONE;
@@ -530,16 +528,15 @@
int code;
if (statusCode == NO_STATUS_CODE || statusCode == CLOSED_ABNORMALLY) {
code = NORMAL_CLOSURE;
- debug.log(Level.DEBUG, "using statusCode %s instead of %s",
+ debug.log("using statusCode %s instead of %s",
statusCode, code);
} else {
code = statusCode;
}
cs.whenComplete((r, e) -> {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG,
- "CompletionStage returned by onClose completed result=%s error=%s",
+ if (debug.on()) {
+ debug.log("CompletionStage returned by onClose completed result=%s error=%s",
r, e);
}
sendCloseSilently(code);
@@ -548,24 +545,24 @@
private void processPong() {
long id = 0;
- if (debug.isLoggable(Level.DEBUG)) {
+ if (debug.on()) {
id = receiveCounter.incrementAndGet();
- debug.log(Level.DEBUG, "enter onPong %s payload=%s",
+ debug.log("enter onPong %s payload=%s",
id, binaryData);
}
CompletionStage<?> cs = null;
try {
cs = listener.onPong(WebSocketImpl.this, binaryData);
} finally {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "exit onPong %s returned %s", id, cs);
+ if (debug.on()) {
+ debug.log("exit onPong %s returned %s", id, cs);
}
}
}
private void processPing() {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "processPing");
+ if (debug.on()) {
+ debug.log("processPing");
}
// A full copy of this (small) data is made. This way sending a
// replying Pong could be done in parallel with the listener
@@ -588,66 +585,65 @@
}
}
long id = 0;
- if (debug.isLoggable(Level.DEBUG)) {
+ if (debug.on()) {
id = receiveCounter.incrementAndGet();
- debug.log(Level.DEBUG, "enter onPing %s payload=%s", id, slice);
+ debug.log("enter onPing %s payload=%s", id, slice);
}
CompletionStage<?> cs = null;
try {
cs = listener.onPing(WebSocketImpl.this, slice);
} finally {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "exit onPing %s returned %s", id, cs);
+ if (debug.on()) {
+ debug.log("exit onPing %s returned %s", id, cs);
}
}
}
private void processBinary() {
long id = 0;
- if (debug.isLoggable(Level.DEBUG)) {
+ if (debug.on()) {
id = receiveCounter.incrementAndGet();
- debug.log(Level.DEBUG, "enter onBinary %s payload=%s last=%s",
+ debug.log("enter onBinary %s payload=%s last=%s",
id, binaryData, last);
}
CompletionStage<?> cs = null;
try {
cs = listener.onBinary(WebSocketImpl.this, binaryData, last);
} finally {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "exit onBinary %s returned %s", id, cs);
+ if (debug.on()) {
+ debug.log("exit onBinary %s returned %s", id, cs);
}
}
}
private void processText() {
long id = 0;
- if (debug.isLoggable(Level.DEBUG)) {
+ if (debug.on()) {
id = receiveCounter.incrementAndGet();
- debug.log(Level.DEBUG,
- "enter onText %s payload.length=%s last=%s",
+ debug.log("enter onText %s payload.length=%s last=%s",
id, text.length(), last);
}
CompletionStage<?> cs = null;
try {
cs = listener.onText(WebSocketImpl.this, text, last);
} finally {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "exit onText %s returned %s", id, cs);
+ if (debug.on()) {
+ debug.log("exit onText %s returned %s", id, cs);
}
}
}
private void processOpen() {
long id = 0;
- if (debug.isLoggable(Level.DEBUG)) {
+ if (debug.on()) {
id = receiveCounter.incrementAndGet();
- debug.log(Level.DEBUG, "enter onOpen %s", id);
+ debug.log("enter onOpen %s", id);
}
try {
listener.onOpen(WebSocketImpl.this);
} finally {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "exit onOpen %s", id);
+ if (debug.on()) {
+ debug.log("exit onOpen %s", id);
}
}
}
@@ -656,8 +652,8 @@
private void sendCloseSilently(int statusCode) {
sendClose0(statusCode, "").whenComplete((r, e) -> {
if (e != null) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "automatic closure completed with error",
+ if (debug.on()) {
+ debug.log("automatic closure completed with error",
(Object) e);
}
}
@@ -698,27 +694,27 @@
break;
}
}
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "swapped automatic pong from %s to %s",
+ if (debug.on()) {
+ debug.log("swapped automatic pong from %s to %s",
message, copy);
}
return swapped;
}
private void signalOpen() {
- debug.log(Level.DEBUG, "signalOpen");
+ debug.log("signalOpen");
receiveScheduler.runOrSchedule();
}
private void signalError(Throwable error) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "signalError %s", (Object) error);
+ if (debug.on()) {
+ debug.log("signalError %s", (Object) error);
}
inputClosed = true;
outputClosed.set(true);
if (!this.error.compareAndSet(null, error) || !trySetState(ERROR)) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "signalError", error);
+ if (debug.on()) {
+ debug.log("signalError", error);
}
Log.logError(error);
} else {
@@ -727,8 +723,8 @@
}
private void close() {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "close");
+ if (debug.on()) {
+ debug.log("close");
}
Throwable first = null;
try {
@@ -752,8 +748,8 @@
e = second;
}
if (e != null) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "exception in close", e);
+ if (debug.on()) {
+ debug.log("exception in close", e);
}
}
}
@@ -766,17 +762,16 @@
this.statusCode = statusCode;
this.reason = reason;
boolean managed = trySetState(CLOSE);
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG,
- "signalClose statusCode=%s reason.length=%s: %s",
+ if (debug.on()) {
+ debug.log("signalClose statusCode=%s reason.length=%s: %s",
statusCode, reason.length(), managed);
}
if (managed) {
try {
transport.closeInput();
} catch (Throwable t) {
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "exception closing input", (Object) t);
+ if (debug.on()) {
+ debug.log("exception closing input", (Object) t);
}
}
}
@@ -845,8 +840,8 @@
break;
}
}
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "set state %s (previous %s) %s",
+ if (debug.on()) {
+ debug.log("set state %s (previous %s) %s",
newState, currentState, success);
}
return success;
@@ -863,8 +858,8 @@
// from IDLE to WAITING: the state has changed to terminal
throw new InternalError();
}
- if (debug.isLoggable(Level.DEBUG)) {
- debug.log(Level.DEBUG, "change state from %s to %s %s",
+ if (debug.on()) {
+ debug.log("change state from %s to %s %s",
expectedState, newState, success);
}
return success;