improved debug logging of settings

This commit is contained in:
Greg Wilkins 2014-08-13 12:00:32 +10:00
parent a97d4642ab
commit 68a3ca8e31
8 changed files with 80 additions and 41 deletions

View File

@ -41,13 +41,14 @@ public class BadMessageException extends RuntimeException
public BadMessageException(int code, String reason)
{
super(code+": "+reason);
_code=code;
_reason=reason;
}
public BadMessageException(int code, String reason, Throwable cause)
{
super(cause);
super(code+": "+reason, cause);
_code=code;
_reason=reason;
}

View File

@ -194,43 +194,57 @@ public abstract class HTTP2Session implements ISession, Parser.Listener
@Override
public boolean onSettings(SettingsFrame frame)
{
if (LOG.isDebugEnabled())
LOG.debug("Received {}", frame);
if (frame.isReply())
return false;
Map<Integer, Integer> settings = frame.getSettings();
if (settings.containsKey(SettingsFrame.HEADER_TABLE_SIZE))
// Iterate over all settings
for (Map.Entry<Integer, Integer> entry : frame.getSettings().entrySet())
{
int headerTableSize = settings.get(SettingsFrame.HEADER_TABLE_SIZE);
if (LOG.isDebugEnabled())
LOG.debug("Updated HPACK header table size to {}", headerTableSize);
generator.setHeaderTableSize(headerTableSize);
}
if (settings.containsKey(SettingsFrame.MAX_CONCURRENT_STREAMS))
{
maxLocalStreams = settings.get(SettingsFrame.MAX_CONCURRENT_STREAMS);
if (LOG.isDebugEnabled())
LOG.debug("Updated max local concurrent streams to {}", maxLocalStreams);
}
if (settings.containsKey(SettingsFrame.INITIAL_WINDOW_SIZE))
{
int initialWindow = settings.get(SettingsFrame.INITIAL_WINDOW_SIZE);
flowControl.updateInitialStreamWindow(this, initialWindow);
}
if (settings.containsKey(SettingsFrame.MAX_FRAME_SIZE))
{
int maxFrameSize = settings.get(SettingsFrame.MAX_FRAME_SIZE);
// SPEC: check the max frame size is sane.
if (maxFrameSize < Frame.DEFAULT_MAX_LENGTH || maxFrameSize > Frame.MAX_MAX_LENGTH)
int value=entry.getValue();
switch (entry.getKey())
{
onConnectionFailure(ErrorCodes.PROTOCOL_ERROR, "invalid_settings_max_frame_size");
return false;
case SettingsFrame.HEADER_TABLE_SIZE:
if (LOG.isDebugEnabled())
LOG.debug("Update HPACK header table size to {}", value);
generator.setHeaderTableSize(value);
break;
case SettingsFrame.ENABLE_PUSH:
break;
case SettingsFrame.MAX_CONCURRENT_STREAMS:
maxLocalStreams = value;
if (LOG.isDebugEnabled())
LOG.debug("Update max local concurrent streams to {}", maxLocalStreams);
break;
case SettingsFrame.INITIAL_WINDOW_SIZE:
if (LOG.isDebugEnabled())
LOG.debug("Update initial window size to {}", value);
flowControl.updateInitialStreamWindow(this, value);
break;
case SettingsFrame.MAX_FRAME_SIZE:
if (LOG.isDebugEnabled())
LOG.debug("Update max frame size to {}", value);
// SPEC: check the max frame size is sane.
if (value < Frame.DEFAULT_MAX_LENGTH || value > Frame.MAX_MAX_LENGTH)
{
onConnectionFailure(ErrorCodes.PROTOCOL_ERROR, "invalid_settings_max_frame_size");
return false;
}
generator.setMaxFrameSize(value);
break;
case SettingsFrame.MAX_HEADER_LIST_SIZE:
// TODO implement
LOG.warn("NOT IMPLEMENTED max header list size to {}", value);
break;
default:
LOG.debug("Unknown setting {}:{}",entry.getKey(),value);
}
if (LOG.isDebugEnabled())
LOG.debug("Updated max frame size to {}", maxFrameSize);
generator.setMaxFrameSize(maxFrameSize);
}
notifySettings(this, frame);

View File

@ -27,7 +27,8 @@ public class SettingsFrame extends Frame
public static final int MAX_CONCURRENT_STREAMS = 3;
public static final int INITIAL_WINDOW_SIZE = 4;
public static final int MAX_FRAME_SIZE = 5;
public static final int MAX_HEADER_LIST_SIZE = 6;
private final Map<Integer, Integer> settings;
private final boolean reply;

View File

@ -33,6 +33,7 @@ import org.eclipse.jetty.http2.frames.SettingsFrame;
import org.eclipse.jetty.http2.frames.WindowUpdateFrame;
import org.eclipse.jetty.http2.hpack.HpackDecoder;
import org.eclipse.jetty.io.ByteBufferPool;
import org.eclipse.jetty.util.TypeUtil;
import org.eclipse.jetty.util.log.Log;
import org.eclipse.jetty.util.log.Logger;
@ -76,8 +77,11 @@ public class Parser
try
{
if (LOG.isDebugEnabled())
LOG.debug("Parsing {}", buffer);
{
int l=Math.min(buffer.remaining(),16);
LOG.debug("Parsing "+TypeUtil.toHexString(buffer.array(),buffer.arrayOffset()+buffer.position(),l)+(l<buffer.remaining()?"...":""));
}
while (true)
{
switch (state)
@ -93,7 +97,17 @@ public class Parser
{
int type = headerParser.getFrameType();
if (LOG.isDebugEnabled())
LOG.debug("Parsing {} frame", FrameType.from(type));
{
int fl=headerParser.getLength();
int l=Math.min(16,Math.min(buffer.remaining(),fl));
LOG.debug(String.format("Parsing %s frame %s%s%s",
FrameType.from(type),
" ".substring(0,11-FrameType.from(type).toString().length()),
TypeUtil.toHexString(buffer.array(),buffer.arrayOffset()+buffer.position(),l),
l<fl?"...":""));
}
if (type < 0 || type >= bodyParsers.length)
{
notifyConnectionFailure(ErrorCodes.PROTOCOL_ERROR, "unknown_frame_type_" + type);
@ -124,13 +138,13 @@ public class Parser
// The content will be processed asynchronously, stop parsing;
// the asynchronous operation will eventually resume parsing.
if (LOG.isDebugEnabled())
LOG.debug("Parsed {} frame, asynchronous processing", FrameType.from(type));
LOG.debug("Parsed {} frame, asynchronous processing", FrameType.from(type));
return true;
}
case COMPLETE:
{
if (LOG.isDebugEnabled())
LOG.debug("Parsed {} frame, synchronous processing", FrameType.from(type));
LOG.debug("Parsed {} frame, synchronous processing", FrameType.from(type));
reset();
break;
}

View File

@ -25,9 +25,12 @@ import java.util.Map;
import org.eclipse.jetty.http2.ErrorCodes;
import org.eclipse.jetty.http2.Flags;
import org.eclipse.jetty.http2.frames.SettingsFrame;
import org.eclipse.jetty.util.log.Log;
import org.eclipse.jetty.util.log.Logger;
public class SettingsBodyParser extends BodyParser
{
private static final Logger LOG = Log.getLogger(SettingsBodyParser.class);
private State state = State.PREPARE;
private int cursor;
private int length;
@ -116,6 +119,8 @@ public class SettingsBodyParser extends BodyParser
if (buffer.remaining() >= 4)
{
settingValue = buffer.getInt();
if (LOG.isDebugEnabled())
LOG.debug(String.format("setting %d=%d",settingId, settingValue));
settings.put(settingId, settingValue);
state = State.SETTING_ID;
length -= 4;
@ -144,6 +149,8 @@ public class SettingsBodyParser extends BodyParser
}
if (cursor == 0)
{
if (LOG.isDebugEnabled())
LOG.debug(String.format("setting %d=%d",settingId, settingValue));
settings.put(settingId, settingValue);
state = State.SETTING_ID;
if (length == 0)

View File

@ -306,12 +306,14 @@ public class HpackContext
if (entry==_nameMap.get(lc))
_nameMap.remove(lc);
}
if (LOG.isDebugEnabled())
LOG.debug(String.format("HdrTbl[%x] entries=%d, size=%d, max=%d",hashCode(),_headerTable.size(),_headerTableSizeInBytes,_maxHeaderTableSizeInBytes));
}
@Override
public String toString()
{
return String.format("HpackContext@%x{%s}",hashCode(),_headerTable);
return String.format("HpackContext@%x{entries=%d,size=%d,max=%d}",hashCode(),_headerTable.size(),_headerTableSizeInBytes,_maxHeaderTableSizeInBytes);
}

View File

@ -1,3 +1,3 @@
org.eclipse.jetty.util.log.class=org.eclipse.jetty.util.log.StdErrLog
org.eclipse.jetty.http2.LEVEL=INFO
org.eclipse.jetty.http2.hpack.LEVEL=INFO
org.eclipse.jetty.http2.hpack.LEVEL=DEBUG

View File

@ -1,3 +1,3 @@
org.eclipse.jetty.util.log.class=org.eclipse.jetty.util.log.StdErrLog
org.eclipse.jetty.http2.LEVEL=INFO
org.eclipse.jetty.http2.LEVEL=DEBUG