From 59fe74a5980459a208ebcc6e9ad3b0da559b1a19 Mon Sep 17 00:00:00 2001 From: Ludovic Orban Date: Tue, 30 Mar 2021 16:47:52 +0200 Subject: [PATCH] improve debug logs Signed-off-by: Ludovic Orban --- .../jetty/http3/common/QuicConnection.java | 4 ++++ .../jetty/http3/common/QuicSession.java | 24 +++++++++++++++---- .../http3/common/QuicStreamEndPoint.java | 10 +++++++- 3 files changed, 33 insertions(+), 5 deletions(-) diff --git a/jetty-http3/http3-common/src/main/java/org/eclipse/jetty/http3/common/QuicConnection.java b/jetty-http3/http3-common/src/main/java/org/eclipse/jetty/http3/common/QuicConnection.java index d5c4cb2e95d..d84fdcbfa48 100644 --- a/jetty-http3/http3-common/src/main/java/org/eclipse/jetty/http3/common/QuicConnection.java +++ b/jetty-http3/http3-common/src/main/java/org/eclipse/jetty/http3/common/QuicConnection.java @@ -62,6 +62,7 @@ public abstract class QuicConnection extends AbstractConnection protected void closeSession(QuicheConnectionId quicheConnectionId, QuicSession session, Throwable x) { + LOG.debug("closing session of type {} cid={}", getClass().getSimpleName(), quicheConnectionId); if (quicheConnectionId != null) sessions.remove(quicheConnectionId); } @@ -69,8 +70,11 @@ public abstract class QuicConnection extends AbstractConnection @Override public void close() { + LOG.debug("closing connection of type {}", getClass().getSimpleName()); sessions.values().forEach(QuicSession::close); + sessions.clear(); super.close(); + LOG.debug("closed connection of type {}", getClass().getSimpleName()); } @Override diff --git a/jetty-http3/http3-common/src/main/java/org/eclipse/jetty/http3/common/QuicSession.java b/jetty-http3/http3-common/src/main/java/org/eclipse/jetty/http3/common/QuicSession.java index 5582b66eedc..175d58bd53d 100644 --- a/jetty-http3/http3-common/src/main/java/org/eclipse/jetty/http3/common/QuicSession.java +++ b/jetty-http3/http3-common/src/main/java/org/eclipse/jetty/http3/common/QuicSession.java @@ -211,6 +211,8 @@ public abstract class QuicSession public void flush() { + if (LOG.isDebugEnabled()) + LOG.debug("flushing session cid={}", quicheConnectionId); flusher.iterate(); } @@ -244,7 +246,7 @@ public abstract class QuicSession public void close(Throwable x) { if (LOG.isDebugEnabled()) - LOG.debug("closing QUIC session {}", this); + LOG.debug("closing Quic session cid={}", quicheConnectionId); try { endpoints.values().forEach(AbstractEndPoint::close); @@ -259,7 +261,7 @@ public abstract class QuicSession quicheConnection.dispose(); } if (LOG.isDebugEnabled()) - LOG.debug("closed QUIC session {}", this); + LOG.debug("closed Quic session cid={}", quicheConnectionId); } @Override @@ -281,7 +283,7 @@ public abstract class QuicSession public void onTimeoutExpired() { if (LOG.isDebugEnabled()) - LOG.debug("quiche timeout callback"); + LOG.debug("quiche timeout callback called cid={}", quicheConnectionId); quicheConnection.onTimeout(); if (LOG.isDebugEnabled()) LOG.debug("re-iterating quiche after timeout cid={}", quicheConnectionId); @@ -305,6 +307,8 @@ public abstract class QuicSession cipherBuffer = byteBufferPool.acquire(LibQuiche.QUICHE_MIN_CLIENT_INITIAL_LEN, true); int pos = BufferUtil.flipToFill(cipherBuffer); int drained = quicheConnection.drainCipherText(cipherBuffer); + if (LOG.isDebugEnabled()) + LOG.debug("drained {} byte(s) of cipher text from quiche", drained); long nextTimeoutInMs = quicheConnection.nextTimeout(); if (LOG.isDebugEnabled()) LOG.debug("next quiche timeout: {} ms", nextTimeoutInMs); @@ -313,15 +317,25 @@ public abstract class QuicSession else timeout.schedule(nextTimeoutInMs, TimeUnit.MILLISECONDS); if (drained == 0) - return quicheConnection.isConnectionClosed() ? Action.SUCCEEDED : Action.IDLE; + { + boolean connectionClosed = quicheConnection.isConnectionClosed(); + Action action = connectionClosed ? Action.SUCCEEDED : Action.IDLE; + if (LOG.isDebugEnabled()) + LOG.debug("connection is closed? {} -> action = {}", connectionClosed, action); + return action; + } BufferUtil.flipToFlush(cipherBuffer, pos); connection.write(this, remoteAddress, cipherBuffer); + if (LOG.isDebugEnabled()) + LOG.debug("wrote cipher text for {}", remoteAddress); return Action.SCHEDULED; } @Override public void succeeded() { + if (LOG.isDebugEnabled()) + LOG.debug("cipher text writing succeeded"); byteBufferPool.release(cipherBuffer); super.succeeded(); } @@ -337,6 +351,8 @@ public abstract class QuicSession @Override protected void onCompleteFailure(Throwable cause) { + if (LOG.isDebugEnabled()) + LOG.debug("cipher text writing failed, closing session", cause); byteBufferPool.release(cipherBuffer); QuicSession.this.close(cause); } diff --git a/jetty-http3/http3-common/src/main/java/org/eclipse/jetty/http3/common/QuicStreamEndPoint.java b/jetty-http3/http3-common/src/main/java/org/eclipse/jetty/http3/common/QuicStreamEndPoint.java index f5f88a09e03..4babf0c61aa 100644 --- a/jetty-http3/http3-common/src/main/java/org/eclipse/jetty/http3/common/QuicStreamEndPoint.java +++ b/jetty-http3/http3-common/src/main/java/org/eclipse/jetty/http3/common/QuicStreamEndPoint.java @@ -107,14 +107,22 @@ public class QuicStreamEndPoint extends AbstractEndPoint @Override public boolean flush(ByteBuffer... buffers) throws IOException { + if (LOG.isDebugEnabled()) + LOG.debug("flushing {} buffer(s) stream {}", buffers.length, streamId); for (ByteBuffer buffer : buffers) { int flushed = session.flush(streamId, buffer); if (LOG.isDebugEnabled()) - LOG.debug("flushed {} bytes to stream {}; buffer has remaining? {}", flushed, streamId, buffer.hasRemaining()); + LOG.debug("flushed {} bytes to stream {}", flushed, streamId); if (buffer.hasRemaining()) + { + if (LOG.isDebugEnabled()) + LOG.debug("incomplete flushing of stream {}", streamId); return false; + } } + if (LOG.isDebugEnabled()) + LOG.debug("fully flushed stream {}", streamId); return true; }