improve debug logs

Signed-off-by: Ludovic Orban <lorban@bitronix.be>
This commit is contained in:
Ludovic Orban 2021-03-30 16:47:52 +02:00 committed by Simone Bordet
parent 5424f67132
commit 59fe74a598
3 changed files with 33 additions and 5 deletions

View File

@ -62,6 +62,7 @@ public abstract class QuicConnection extends AbstractConnection
protected void closeSession(QuicheConnectionId quicheConnectionId, QuicSession session, Throwable x) protected void closeSession(QuicheConnectionId quicheConnectionId, QuicSession session, Throwable x)
{ {
LOG.debug("closing session of type {} cid={}", getClass().getSimpleName(), quicheConnectionId);
if (quicheConnectionId != null) if (quicheConnectionId != null)
sessions.remove(quicheConnectionId); sessions.remove(quicheConnectionId);
} }
@ -69,8 +70,11 @@ public abstract class QuicConnection extends AbstractConnection
@Override @Override
public void close() public void close()
{ {
LOG.debug("closing connection of type {}", getClass().getSimpleName());
sessions.values().forEach(QuicSession::close); sessions.values().forEach(QuicSession::close);
sessions.clear();
super.close(); super.close();
LOG.debug("closed connection of type {}", getClass().getSimpleName());
} }
@Override @Override

View File

@ -211,6 +211,8 @@ public abstract class QuicSession
public void flush() public void flush()
{ {
if (LOG.isDebugEnabled())
LOG.debug("flushing session cid={}", quicheConnectionId);
flusher.iterate(); flusher.iterate();
} }
@ -244,7 +246,7 @@ public abstract class QuicSession
public void close(Throwable x) public void close(Throwable x)
{ {
if (LOG.isDebugEnabled()) if (LOG.isDebugEnabled())
LOG.debug("closing QUIC session {}", this); LOG.debug("closing Quic session cid={}", quicheConnectionId);
try try
{ {
endpoints.values().forEach(AbstractEndPoint::close); endpoints.values().forEach(AbstractEndPoint::close);
@ -259,7 +261,7 @@ public abstract class QuicSession
quicheConnection.dispose(); quicheConnection.dispose();
} }
if (LOG.isDebugEnabled()) if (LOG.isDebugEnabled())
LOG.debug("closed QUIC session {}", this); LOG.debug("closed Quic session cid={}", quicheConnectionId);
} }
@Override @Override
@ -281,7 +283,7 @@ public abstract class QuicSession
public void onTimeoutExpired() public void onTimeoutExpired()
{ {
if (LOG.isDebugEnabled()) if (LOG.isDebugEnabled())
LOG.debug("quiche timeout callback"); LOG.debug("quiche timeout callback called cid={}", quicheConnectionId);
quicheConnection.onTimeout(); quicheConnection.onTimeout();
if (LOG.isDebugEnabled()) if (LOG.isDebugEnabled())
LOG.debug("re-iterating quiche after timeout cid={}", quicheConnectionId); 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); cipherBuffer = byteBufferPool.acquire(LibQuiche.QUICHE_MIN_CLIENT_INITIAL_LEN, true);
int pos = BufferUtil.flipToFill(cipherBuffer); int pos = BufferUtil.flipToFill(cipherBuffer);
int drained = quicheConnection.drainCipherText(cipherBuffer); int drained = quicheConnection.drainCipherText(cipherBuffer);
if (LOG.isDebugEnabled())
LOG.debug("drained {} byte(s) of cipher text from quiche", drained);
long nextTimeoutInMs = quicheConnection.nextTimeout(); long nextTimeoutInMs = quicheConnection.nextTimeout();
if (LOG.isDebugEnabled()) if (LOG.isDebugEnabled())
LOG.debug("next quiche timeout: {} ms", nextTimeoutInMs); LOG.debug("next quiche timeout: {} ms", nextTimeoutInMs);
@ -313,15 +317,25 @@ public abstract class QuicSession
else else
timeout.schedule(nextTimeoutInMs, TimeUnit.MILLISECONDS); timeout.schedule(nextTimeoutInMs, TimeUnit.MILLISECONDS);
if (drained == 0) 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); BufferUtil.flipToFlush(cipherBuffer, pos);
connection.write(this, remoteAddress, cipherBuffer); connection.write(this, remoteAddress, cipherBuffer);
if (LOG.isDebugEnabled())
LOG.debug("wrote cipher text for {}", remoteAddress);
return Action.SCHEDULED; return Action.SCHEDULED;
} }
@Override @Override
public void succeeded() public void succeeded()
{ {
if (LOG.isDebugEnabled())
LOG.debug("cipher text writing succeeded");
byteBufferPool.release(cipherBuffer); byteBufferPool.release(cipherBuffer);
super.succeeded(); super.succeeded();
} }
@ -337,6 +351,8 @@ public abstract class QuicSession
@Override @Override
protected void onCompleteFailure(Throwable cause) protected void onCompleteFailure(Throwable cause)
{ {
if (LOG.isDebugEnabled())
LOG.debug("cipher text writing failed, closing session", cause);
byteBufferPool.release(cipherBuffer); byteBufferPool.release(cipherBuffer);
QuicSession.this.close(cause); QuicSession.this.close(cause);
} }

View File

@ -107,14 +107,22 @@ public class QuicStreamEndPoint extends AbstractEndPoint
@Override @Override
public boolean flush(ByteBuffer... buffers) throws IOException public boolean flush(ByteBuffer... buffers) throws IOException
{ {
if (LOG.isDebugEnabled())
LOG.debug("flushing {} buffer(s) stream {}", buffers.length, streamId);
for (ByteBuffer buffer : buffers) for (ByteBuffer buffer : buffers)
{ {
int flushed = session.flush(streamId, buffer); int flushed = session.flush(streamId, buffer);
if (LOG.isDebugEnabled()) 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 (buffer.hasRemaining())
{
if (LOG.isDebugEnabled())
LOG.debug("incomplete flushing of stream {}", streamId);
return false; return false;
} }
}
if (LOG.isDebugEnabled())
LOG.debug("fully flushed stream {}", streamId);
return true; return true;
} }