improved SSL debug logging

This commit is contained in:
Greg Wilkins 2014-09-04 19:09:39 +10:00
parent 5b97d652e1
commit 07ec47adfa
3 changed files with 52 additions and 21 deletions

View File

@ -21,7 +21,6 @@ package org.eclipse.jetty.io.ssl;
import java.io.IOException;
import java.nio.ByteBuffer;
import java.nio.channels.ClosedChannelException;
import java.util.Arrays;
import java.util.concurrent.Executor;
import javax.net.ssl.SSLEngine;
@ -355,7 +354,7 @@ public class SslConnection extends AbstractConnection
synchronized (DecryptedEndPoint.this)
{
if (DEBUG)
LOG.debug("onIncompleteFlush {}", getEndPoint());
LOG.debug("onIncompleteFlush {}", SslConnection.this);
// If we have pending output data,
if (BufferUtil.hasContent(_encryptedOutput))
{
@ -468,8 +467,6 @@ public class SslConnection extends AbstractConnection
@Override
public synchronized int fill(ByteBuffer buffer) throws IOException
{
if (DEBUG)
LOG.debug("{} fill enter", SslConnection.this);
try
{
// Do we already have some decrypted data?
@ -496,8 +493,6 @@ public class SslConnection extends AbstractConnection
{
// Let's try reading some encrypted data... even if we have some already.
int net_filled = getEndPoint().fill(_encryptedInput);
if (DEBUG)
LOG.debug("{} filled {} encrypted bytes", SslConnection.this, net_filled);
decryption: while (true)
{
@ -507,7 +502,10 @@ public class SslConnection extends AbstractConnection
SSLEngineResult unwrapResult = _sslEngine.unwrap(_encryptedInput, app_in);
BufferUtil.flipToFlush(app_in, pos);
if (DEBUG)
LOG.debug("{} unwrap {}", SslConnection.this, unwrapResult);
{
LOG.debug("{} net={} unwrap {}", SslConnection.this, net_filled, unwrapResult.toString().replace('\n',' '));
LOG.debug("{} filled {}",SslConnection.this,BufferUtil.toHexSummary(buffer));
}
HandshakeStatus handshakeStatus = _sslEngine.getHandshakeStatus();
HandshakeStatus unwrapHandshakeStatus = unwrapResult.getHandshakeStatus();
@ -559,8 +557,9 @@ public class SslConnection extends AbstractConnection
{
_handshaken = true;
if (DEBUG)
LOG.debug("{} {} handshake completed", SslConnection.this,
_sslEngine.getUseClientMode() ? "client-side" : "resumed session server-side");
LOG.debug("{} {} handshook {}/{}", SslConnection.this,
_sslEngine.getUseClientMode() ? "client" : "resumed server",
_sslEngine.getSession().getProtocol(),_sslEngine.getSession().getCipherSuite());
}
// Check whether renegotiation is allowed
@ -661,8 +660,6 @@ public class SslConnection extends AbstractConnection
_bufferPool.release(_decryptedInput);
_decryptedInput = null;
}
if (DEBUG)
LOG.debug("{} fill exit", SslConnection.this);
}
}
@ -687,10 +684,13 @@ public class SslConnection extends AbstractConnection
// will return 0 (even if some handshake bytes were flushed and filled).
// it is the applications responsibility to call flush again - either in a busy loop
// or better yet by using EndPoint#write to do the flushing.
if (DEBUG)
LOG.debug("{} flush enter {}", SslConnection.this, Arrays.toString(appOuts));
int consumed=0;
{
for (ByteBuffer b : appOuts)
LOG.debug("{} flush {}", SslConnection.this, BufferUtil.toHexSummary(b));
}
try
{
if (_cannotAcceptMoreAppDataToFlush)
@ -711,10 +711,8 @@ public class SslConnection extends AbstractConnection
int pos = BufferUtil.flipToFill(_encryptedOutput);
SSLEngineResult wrapResult = _sslEngine.wrap(appOuts, _encryptedOutput);
if (DEBUG)
LOG.debug("{} wrap {}", SslConnection.this, wrapResult);
LOG.debug("{} wrap {}", SslConnection.this, wrapResult.toString().replace('\n',' '));
BufferUtil.flipToFlush(_encryptedOutput, pos);
if (wrapResult.bytesConsumed()>0)
consumed+=wrapResult.bytesConsumed();
boolean allConsumed=true;
// clear empty buffers to prevent position creeping up the buffer
@ -757,13 +755,13 @@ public class SslConnection extends AbstractConnection
default:
if (DEBUG)
LOG.debug("{} {} {}", this, wrapResultStatus, BufferUtil.toDetailString(_encryptedOutput));
LOG.debug("{} wrap {} {}", SslConnection.this, wrapResultStatus, BufferUtil.toHexSummary(_encryptedOutput));
if (wrapResult.getHandshakeStatus() == HandshakeStatus.FINISHED && !_handshaken)
{
_handshaken = true;
if (DEBUG)
LOG.debug("{} {} handshake completed", SslConnection.this, "server-side");
LOG.debug("{} server handshook complete {}/{}", SslConnection.this, _sslEngine.getSession().getProtocol(),_sslEngine.getSession().getCipherSuite());
}
HandshakeStatus handshakeStatus = _sslEngine.getHandshakeStatus();
@ -823,8 +821,6 @@ public class SslConnection extends AbstractConnection
}
finally
{
if (DEBUG)
LOG.debug("{} flush exit, consumed {}", SslConnection.this, consumed);
releaseEncryptedOutputBuffer();
}
}

View File

@ -1020,6 +1020,33 @@ public class BufferUtil
else
buf.append("\\x").append(TypeUtil.toHexString(b));
}
/* ------------------------------------------------------------ */
/** Convert buffer to a Hex Summary String.
* @param buffer
* @return A string showing the escaped content of the buffer around the
* position and limit (marked with <<< and >>>)
*/
public static String toHexSummary(ByteBuffer buffer)
{
if (buffer == null)
return "null";
StringBuilder buf = new StringBuilder();
buf.append("b[").append(buffer.remaining()).append("]=");
for (int i = buffer.position(); i < buffer.limit(); i++)
{
TypeUtil.toHex(buffer.get(i),buf);
if (i == buffer.position() + 24 && buffer.limit() > buffer.position() + 32)
{
buf.append("...");
i = buffer.limit() - 8;
}
}
return buf.toString();
}
private final static int[] decDivisors =
{1000000000, 100000000, 10000000, 1000000, 100000, 10000, 1000, 100, 10, 1};

View File

@ -224,6 +224,14 @@ public class SslContextFactory extends AbstractLifeCycle
public SslContextFactory(boolean trustAll)
{
setTrustAll(trustAll);
setExcludeCipherSuites(
"SSL_RSA_WITH_DES_CBC_SHA",
"SSL_DHE_RSA_WITH_DES_CBC_SHA",
"SSL_DHE_DSS_WITH_DES_CBC_SHA",
"SSL_RSA_EXPORT_WITH_RC4_40_MD5",
"SSL_RSA_EXPORT_WITH_DES40_CBC_SHA",
"SSL_DHE_RSA_EXPORT_WITH_DES40_CBC_SHA",
"SSL_DHE_DSS_EXPORT_WITH_DES40_CBC_SHA");
}
/**