IllegalArgumentException in io.netty.util.internal.PriorityQueue #5980
Comments
|
@Scottmitch @nmittler can you have a look ? |
|
sure |
|
@rkapsi - can you tell me what your priority tree looks like when flush is invoked, and also do you have a reproducer?
|
|
@Scottmitch I don't have a reproducer but it happens pretty reliably in our production environment. There is an initial burst as soon as the server starts accepting connections and then one every once in a while. How do I get the info for the priority tree? ToString or do you need something else? |
|
Just throwing it out there but could it be a thread visibility thing because |
|
codec-http2 is not thread safe. You always have to be on the IO thread when ever you interact with it ... is this not the case in your setup? |
|
Checking... Possible that my |
If you are sure you are always on the I/O thread then it would be great to see the string represetnation of the general priority tree, and the string representation of the |
|
@Scottmitch flush() and my interactions with the encoder are on the codec's IO thread. Below are two 2016-11-04 17:54:07,120 [WorkerThread-3] Http2HttpBridgeHandler ERROR: state=State{stream=0, queue=[State{stream=39, queue=[State{stream=41, queue=[State{stream=45, queue=[State{stream=47, queue=[State{stream=49, queue=[State{stream=51, queue=[State{stream=53, queue=[State{stream=55, queue=[State{stream=57, queue=[], streamableBytes=7453, activeCountForTree=1, priorityQueueIndex=0, pseudoTimeToWrite=0, pseudoTime=0, totalQueuedWeights=0, active=true}], streamableBytes=3158, activeCountForTree=2, priorityQueueIndex=0, pseudoTimeToWrite=0, pseudoTime=0, totalQueuedWeights=220, active=true}], streamableBytes=0, activeCountForTree=2, priorityQueueIndex=0, pseudoTimeToWrite=0, pseudoTime=0, totalQueuedWeights=220, active=false}], streamableBytes=6071, activeCountForTree=3, priorityQueueIndex=0, pseudoTimeToWrite=0, pseudoTime=0, totalQueuedWeights=220, active=true}], streamableBytes=0, activeCountForTree=3, priorityQueueIndex=0, pseudoTimeToWrite=0, pseudoTime=0, totalQueuedWeights=220, active=false}], streamableBytes=0, activeCountForTree=3, priorityQueueIndex=0, pseudoTimeToWrite=0, pseudoTime=0, totalQueuedWeights=220, active=false}], streamableBytes=0, activeCountForTree=3, priorityQueueIndex=0, pseudoTimeToWrite=57792, pseudoTime=0, totalQueuedWeights=220, active=false}], streamableBytes=0, activeCountForTree=3, priorityQueueIndex=0, pseudoTimeToWrite=62349, pseudoTime=62349, totalQueuedWeights=220, active=false}], streamableBytes=0, activeCountForTree=3, priorityQueueIndex=0, pseudoTimeToWrite=322177, pseudoTime=62349, totalQueuedWeights=220, active=false}], streamableBytes=0, activeCountForTree=3, priorityQueueIndex=-1, pseudoTimeToWrite=0, pseudoTime=322177, totalQueuedWeights=220, active=false}2016-11-04 17:54:07,121 [WorkerThread-3] ExceptionHandler ERROR: name=Http2ExceptionHandler, channel=[id: 0x6dae7b41, L:/aaa.aaa.aaa.aaa:443 - R:/bbb.bbb.bbb.bbb:54938]
java.lang.IllegalArgumentException: e.priorityQueueIndex(): 0 (expected: -1)
at io.netty.util.internal.PriorityQueue.offer(PriorityQueue.java:83) ~[netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.util.internal.PriorityQueue.offer(PriorityQueue.java:32) ~[netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.handler.codec.http2.WeightedFairQueueByteDistributor$State.offer(WeightedFairQueueByteDistributor.java:299) ~[netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.handler.codec.http2.WeightedFairQueueByteDistributor.distributeToChildren(WeightedFairQueueByteDistributor.java:198) ~[netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.handler.codec.http2.WeightedFairQueueByteDistributor.distribute(WeightedFairQueueByteDistributor.java:130) ~[netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.handler.codec.http2.DefaultHttp2RemoteFlowController$WritabilityMonitor.writePendingBytes(DefaultHttp2RemoteFlowController.java:631) ~[netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.handler.codec.http2.DefaultHttp2RemoteFlowController.writePendingBytes(DefaultHttp2RemoteFlowController.java:255) ~[netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.handler.codec.http2.Http2ConnectionHandler.flush(Http2ConnectionHandler.java:161) ~[netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at com.squarespace.echo.http2.streams.Http2HttpBridgeHandler.flush(Http2HttpBridgeHandler.java:43) ~[echo-http-2.17.30.jar:?]
at io.netty.handler.codec.http2.Http2ConnectionHandler.channelWritabilityChanged(Http2ConnectionHandler.java:385) ~[netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:445) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:427) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelWritabilityChanged(AbstractChannelHandlerContext.java:420) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.ChannelInboundHandlerAdapter.channelWritabilityChanged(ChannelInboundHandlerAdapter.java:119) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:445) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:427) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelWritabilityChanged(AbstractChannelHandlerContext.java:420) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.ChannelInboundHandlerAdapter.channelWritabilityChanged(ChannelInboundHandlerAdapter.java:119) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:445) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:427) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelWritabilityChanged(AbstractChannelHandlerContext.java:420) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.ChannelInboundHandlerAdapter.channelWritabilityChanged(ChannelInboundHandlerAdapter.java:119) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:445) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:427) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelWritabilityChanged(AbstractChannelHandlerContext.java:420) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelWritabilityChanged(DefaultChannelPipeline.java:1357) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:445) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:427) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.DefaultChannelPipeline.fireChannelWritabilityChanged(DefaultChannelPipeline.java:938) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.ChannelOutboundBuffer.fireChannelWritabilityChanged(ChannelOutboundBuffer.java:599) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.ChannelOutboundBuffer.setWritable(ChannelOutboundBuffer.java:565) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.ChannelOutboundBuffer.decrementPendingOutboundBytes(ChannelOutboundBuffer.java:208) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.ChannelOutboundBuffer.remove(ChannelOutboundBuffer.java:273) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.ChannelOutboundBuffer.removeBytes(ChannelOutboundBuffer.java:352) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.socket.nio.NioSocketChannel.doWrite(NioSocketChannel.java:442) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannel$AbstractUnsafe.flush0(AbstractChannel.java:856) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.forceFlush(AbstractNioChannel.java:368) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:645) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:574) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:488) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:450) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:873) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at java.lang.Thread.run(Thread.java:745) [?:1.8.0_102]2016-11-04 18:00:29,649 [WorkerThread-5] Http2HttpBridgeHandler ERROR: state=State{stream=0, queue=[State{stream=33, queue=[State{stream=39, queue=[State{stream=41, queue=[State{stream=43, queue=[State{stream=45, queue=[State{stream=49, queue=[State{stream=51, queue=[State{stream=53, queue=[State{stream=55, queue=[State{stream=57, queue=[State{stream=59, queue=[State{stream=61, queue=[State{stream=65, queue=[State{stream=67, queue=[State{stream=69, queue=[State{stream=71, queue=[State{stream=73, queue=[State{stream=75, queue=[State{stream=77, queue=[State{stream=79, queue=[], streamableBytes=27622, activeCountForTree=1, priorityQueueIndex=0, pseudoTimeToWrite=24415, pseudoTime=0, totalQueuedWeights=0, active=true}], streamableBytes=16376, activeCountForTree=2, priorityQueueIndex=0, pseudoTimeToWrite=40801, pseudoTime=24415, totalQueuedWeights=220, active=true}], streamableBytes=52037, activeCountForTree=3, priorityQueueIndex=0, pseudoTimeToWrite=40801, pseudoTime=40801, totalQueuedWeights=220, active=true}], streamableBytes=52027, activeCountForTree=4, priorityQueueIndex=0, pseudoTimeToWrite=40811, pseudoTime=40801, totalQueuedWeights=220, active=true}], streamableBytes=52037, activeCountForTree=5, priorityQueueIndex=0, pseudoTimeToWrite=40811, pseudoTime=40811, totalQueuedWeights=220, active=true}], streamableBytes=27622, activeCountForTree=6, priorityQueueIndex=0, pseudoTimeToWrite=65226, pseudoTime=40811, totalQueuedWeights=220, active=true}], streamableBytes=51011, activeCountForTree=7, priorityQueueIndex=0, pseudoTimeToWrite=66252, pseudoTime=65226, totalQueuedWeights=220, active=true}], streamableBytes=16376, activeCountForTree=8, priorityQueueIndex=0, pseudoTimeToWrite=142704, pseudoTime=66252, totalQueuedWeights=220, active=true}], streamableBytes=52027, activeCountForTree=9, priorityQueueIndex=0, pseudoTimeToWrite=142714, pseudoTime=142704, totalQueuedWeights=220, active=true}], streamableBytes=51011, activeCountForTree=10, priorityQueueIndex=0, pseudoTimeToWrite=143740, pseudoTime=142714, totalQueuedWeights=220, active=true}], streamableBytes=52027, activeCountForTree=11, priorityQueueIndex=0, pseudoTimeToWrite=143750, pseudoTime=143740, totalQueuedWeights=220, active=true}], streamableBytes=27622, activeCountForTree=12, priorityQueueIndex=0, pseudoTimeToWrite=168165, pseudoTime=143750, totalQueuedWeights=220, active=true}], streamableBytes=52027, activeCountForTree=13, priorityQueueIndex=0, pseudoTimeToWrite=168175, pseudoTime=168165, totalQueuedWeights=220, active=true}], streamableBytes=27622, activeCountForTree=14, priorityQueueIndex=0, pseudoTimeToWrite=192590, pseudoTime=168175, totalQueuedWeights=220, active=true}], streamableBytes=16376, activeCountForTree=15, priorityQueueIndex=0, pseudoTimeToWrite=269042, pseudoTime=192590, totalQueuedWeights=220, active=true}], streamableBytes=52037, activeCountForTree=16, priorityQueueIndex=0, pseudoTimeToWrite=269042, pseudoTime=269042, totalQueuedWeights=220, active=true}], streamableBytes=51011, activeCountForTree=17, priorityQueueIndex=0, pseudoTimeToWrite=270068, pseudoTime=269042, totalQueuedWeights=220, active=true}], streamableBytes=52027, activeCountForTree=18, priorityQueueIndex=0, pseudoTimeToWrite=270078, pseudoTime=270068, totalQueuedWeights=220, active=true}], streamableBytes=27622, activeCountForTree=19, priorityQueueIndex=0, pseudoTimeToWrite=370945, pseudoTime=270078, totalQueuedWeights=220, active=true}], streamableBytes=0, activeCountForTree=19, priorityQueueIndex=0, pseudoTimeToWrite=1156657, pseudoTime=398567, totalQueuedWeights=220, active=false}], streamableBytes=0, activeCountForTree=19, priorityQueueIndex=-1, pseudoTimeToWrite=0, pseudoTime=1156657, totalQueuedWeights=220, active=false}2016-11-04 18:00:29,650 [WorkerThread-5] ExceptionHandler ERROR: name=Http2ExceptionHandler, channel=[id: 0x5e6e957c, L:/aaa.aaa.aaa.aaa:443 - R:/bbb.bbb.bbb.bbb:55169]
java.lang.IllegalArgumentException: e.priorityQueueIndex(): 0 (expected: -1)
at io.netty.util.internal.PriorityQueue.offer(PriorityQueue.java:83) ~[netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.util.internal.PriorityQueue.offer(PriorityQueue.java:32) ~[netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.handler.codec.http2.WeightedFairQueueByteDistributor$State.offer(WeightedFairQueueByteDistributor.java:299) ~[netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.handler.codec.http2.WeightedFairQueueByteDistributor.distributeToChildren(WeightedFairQueueByteDistributor.java:198) ~[netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.handler.codec.http2.WeightedFairQueueByteDistributor.distribute(WeightedFairQueueByteDistributor.java:130) ~[netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.handler.codec.http2.DefaultHttp2RemoteFlowController$WritabilityMonitor.writePendingBytes(DefaultHttp2RemoteFlowController.java:631) ~[netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.handler.codec.http2.DefaultHttp2RemoteFlowController.writePendingBytes(DefaultHttp2RemoteFlowController.java:255) ~[netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.handler.codec.http2.Http2ConnectionHandler.flush(Http2ConnectionHandler.java:161) ~[netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at com.squarespace.echo.http2.streams.Http2HttpBridgeHandler.flush(Http2HttpBridgeHandler.java:43) ~[echo-http-2.17.30.jar:?]
at io.netty.handler.codec.http2.Http2ConnectionHandler.channelWritabilityChanged(Http2ConnectionHandler.java:385) ~[netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:445) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:427) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelWritabilityChanged(AbstractChannelHandlerContext.java:420) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.ChannelInboundHandlerAdapter.channelWritabilityChanged(ChannelInboundHandlerAdapter.java:119) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:445) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:427) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelWritabilityChanged(AbstractChannelHandlerContext.java:420) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.ChannelInboundHandlerAdapter.channelWritabilityChanged(ChannelInboundHandlerAdapter.java:119) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:445) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:427) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelWritabilityChanged(AbstractChannelHandlerContext.java:420) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.ChannelInboundHandlerAdapter.channelWritabilityChanged(ChannelInboundHandlerAdapter.java:119) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:445) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:427) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelWritabilityChanged(AbstractChannelHandlerContext.java:420) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelWritabilityChanged(DefaultChannelPipeline.java:1357) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:445) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelWritabilityChanged(AbstractChannelHandlerContext.java:427) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.DefaultChannelPipeline.fireChannelWritabilityChanged(DefaultChannelPipeline.java:938) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.ChannelOutboundBuffer$2.run(ChannelOutboundBuffer.java:593) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:418) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:454) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:873) [netty-all-4.1.7.Final-SNAPSHOT.jar:4.1.7.Final-SNAPSHOT]
at java.lang.Thread.run(Thread.java:745) [?:1.8.0_102]public class Http2HttpBridgeHandler extends Http2ConnectionHandler {
@Override
public void flush(ChannelHandlerContext ctx) throws Http2Exception {
try {
super.flush(ctx);
} catch (Throwable t) {
if (LOG.isErrorEnabled()) {
Http2ConnectionEncoder encoder = encoder();
String value = toString(encoder);
LOG.error("state={}", value);
}
throw t;
}
}
private static String toString(Http2ConnectionEncoder encoder) {
DefaultHttp2RemoteFlowController flow = (DefaultHttp2RemoteFlowController)encoder.flowController();
WeightedFairQueueByteDistributor distributor = streamByteDistributor(flow);
Object connectionState = connectionState(distributor);
return toString(connectionState);
}
private static String toString(Object state) {
ToStringHelper helper = MoreObjects.toStringHelper(state);
try {
Class<?> clazz = state.getClass();
Field[] fields = clazz.getDeclaredFields();
for (Field field : fields) {
field.setAccessible(true);
String name = field.getName();
Object value = field.get(state);
if (name.equals("stream")) {
helper.add(name, ((Http2Stream)value).id());
} else if (name.equals("queue")) {
List<Object> dst = new ArrayList<>();
for (Object element : (Queue<?>)value) {
dst.add(toString(element));
}
helper.add(name, dst);
} else if (!name.contains("$")) {
helper.add(name, value);
}
}
} catch (Exception err) {
LOG.error("Exception: {}", state, err);
}
return helper.toString();
}
private static WeightedFairQueueByteDistributor streamByteDistributor(DefaultHttp2RemoteFlowController flow) {
return (WeightedFairQueueByteDistributor)value(flow, "streamByteDistributor");
}
private static Object connectionState(WeightedFairQueueByteDistributor distributor) {
return value(distributor, "connectionState");
}
private static Object value(Object dst, String name) {
if (dst != null) {
try {
Class<?> clazz = dst.getClass();
Field field = clazz.getDeclaredField(name);
field.setAccessible(true);
return field.get(dst);
} catch (Exception err) {
LOG.error("Exception: obj={}, name={}", dst, name, err);
}
}
return null;
}
} |
Here is where it is created in The root of the tree is here: Here is the implementation: |
|
@Scottmitch great. That's exactly what I toString'd. Look for the two codeblocks right before the stacktraces. They're rendered as a single line. Copy & Paste them into some Text Editor. |
|
@rkapsi - can you show me the state before too (I realize this will impact performance, only do this if you are OK with this in your environment) @Override
public void flush(ChannelHandlerContext ctx) throws Http2Exception {
String beforeState = null;
if (LOG.isErrorEnabled()) {
Http2ConnectionEncoder encoder = encoder();
beforeState = toString(encoder);
}
try {
super.flush(ctx);
} catch (Throwable t) {
if (LOG.isErrorEnabled()) {
Http2ConnectionEncoder encoder = encoder();
String value = toString(encoder);
LOG.error("before state={}", beforeState);
LOG.error("after state={}", value);
}
throw t;
}
} |
016-11-04 19:00:56,334 [WorkerThread-0] Http2HttpBridgeHandler ERROR:
before=State{stream=0, queue=[State{stream=3, queue=[State{stream=11, queue=[State{stream=13, queue=[State{stream=17, queue=[State{stream=19, queue=[State{stream=23, queue=[State{stream=25, queue=[State{stream=27, queue=[State{stream=29, queue=[], streamableBytes=96568, activeCountForTree=1, priorityQueueIndex=0, pseudoTimeToWrite=32010, pseudoTime=16005, totalQueuedWeights=0, active=true}], streamableBytes=1669, activeCountForTree=2, priorityQueueIndex=0, pseudoTimeToWrite=32010, pseudoTime=32010, totalQueuedWeights=220, active=true}], streamableBytes=104854, activeCountForTree=3, priorityQueueIndex=0, pseudoTimeToWrite=32010, pseudoTime=32010, totalQueuedWeights=220, active=true}], streamableBytes=36936, activeCountForTree=4, priorityQueueIndex=0, pseudoTimeToWrite=146597, pseudoTime=32010, totalQueuedWeights=220, active=true}], streamableBytes=56007, activeCountForTree=5, priorityQueueIndex=0, pseudoTimeToWrite=146597, pseudoTime=146597, totalQueuedWeights=220, active=true}], streamableBytes=98185, activeCountForTree=6, priorityQueueIndex=0, pseudoTimeToWrite=179084, pseudoTime=146597, totalQueuedWeights=220, active=true}], streamableBytes=27101, activeCountForTree=7, priorityQueueIndex=0, pseudoTimeToWrite=179084, pseudoTime=179084, totalQueuedWeights=220, active=true}], streamableBytes=0, activeCountForTree=7, priorityQueueIndex=0, pseudoTimeToWrite=481469, pseudoTime=179084, totalQueuedWeights=220, active=false}], streamableBytes=0, activeCountForTree=7, priorityQueueIndex=0, pseudoTimeToWrite=657600, pseudoTime=528718, totalQueuedWeights=220, active=false}], streamableBytes=0, activeCountForTree=7, priorityQueueIndex=-1, pseudoTimeToWrite=0, pseudoTime=657600, totalQueuedWeights=220, active=false},
after=State{stream=0, queue=[State{stream=3, queue=[State{stream=11, queue=[State{stream=17, queue=[State{stream=19, queue=[State{stream=23, queue=[State{stream=25, queue=[State{stream=27, queue=[State{stream=29, queue=[], streamableBytes=96568, activeCountForTree=1, priorityQueueIndex=0, pseudoTimeToWrite=32010, pseudoTime=16005, totalQueuedWeights=0, active=true}], streamableBytes=1669, activeCountForTree=2, priorityQueueIndex=0, pseudoTimeToWrite=32010, pseudoTime=32010, totalQueuedWeights=220, active=true}], streamableBytes=104854, activeCountForTree=3, priorityQueueIndex=0, pseudoTimeToWrite=32010, pseudoTime=32010, totalQueuedWeights=220, active=true}], streamableBytes=36936, activeCountForTree=4, priorityQueueIndex=0, pseudoTimeToWrite=146597, pseudoTime=32010, totalQueuedWeights=220, active=true}], streamableBytes=56007, activeCountForTree=5, priorityQueueIndex=0, pseudoTimeToWrite=146597, pseudoTime=146597, totalQueuedWeights=220, active=true}], streamableBytes=98185, activeCountForTree=6, priorityQueueIndex=0, pseudoTimeToWrite=179084, pseudoTime=146597, totalQueuedWeights=220, active=true}], streamableBytes=0, activeCountForTree=6, priorityQueueIndex=0, pseudoTimeToWrite=555819, pseudoTime=206185, totalQueuedWeights=220, active=false}], streamableBytes=0, activeCountForTree=6, priorityQueueIndex=0, pseudoTimeToWrite=657600, pseudoTime=555819, totalQueuedWeights=220, active=false}], streamableBytes=0, activeCountForTree=6, priorityQueueIndex=-1, pseudoTimeToWrite=0, pseudoTime=657600, totalQueuedWeights=220, active=false}2016-11-04 19:05:36,067 [WorkerThread-6] Http2HttpBridgeHandler ERROR:
before=State{stream=0, queue=[State{stream=1, queue=[State{stream=3, queue=[State{stream=5, queue=[State{stream=7, queue=[State{stream=13, queue=[State{stream=15, queue=[State{stream=19, queue=[State{stream=23, queue=[], streamableBytes=113, activeCountForTree=1, priorityQueueIndex=0, pseudoTimeToWrite=339, pseudoTime=339, totalQueuedWeights=0, active=true}], streamableBytes=0, activeCountForTree=1, priorityQueueIndex=0, pseudoTimeToWrite=565, pseudoTime=452, totalQueuedWeights=220, active=false}], streamableBytes=0, activeCountForTree=1, priorityQueueIndex=0, pseudoTimeToWrite=452, pseudoTime=565, totalQueuedWeights=220, active=false}], streamableBytes=0, activeCountForTree=1, priorityQueueIndex=0, pseudoTimeToWrite=678, pseudoTime=452, totalQueuedWeights=220, active=false}], streamableBytes=0, activeCountForTree=1, priorityQueueIndex=0, pseudoTimeToWrite=791, pseudoTime=678, totalQueuedWeights=220, active=false}], streamableBytes=113, activeCountForTree=2, priorityQueueIndex=0, pseudoTimeToWrite=791, pseudoTime=791, totalQueuedWeights=220, active=true}], streamableBytes=0, activeCountForTree=2, priorityQueueIndex=0, pseudoTimeToWrite=791, pseudoTime=791, totalQueuedWeights=220, active=false}], streamableBytes=0, activeCountForTree=2, priorityQueueIndex=0, pseudoTimeToWrite=791, pseudoTime=791, totalQueuedWeights=220, active=false}], streamableBytes=0, activeCountForTree=2, priorityQueueIndex=-1, pseudoTimeToWrite=0, pseudoTime=791, totalQueuedWeights=220, active=false},
after=State{stream=0, queue=[State{stream=1, queue=[State{stream=3, queue=[State{stream=7, queue=[State{stream=13, queue=[State{stream=15, queue=[State{stream=19, queue=[State{stream=23, queue=[], streamableBytes=113, activeCountForTree=1, priorityQueueIndex=0, pseudoTimeToWrite=339, pseudoTime=339, totalQueuedWeights=0, active=true}], streamableBytes=0, activeCountForTree=1, priorityQueueIndex=0, pseudoTimeToWrite=565, pseudoTime=452, totalQueuedWeights=220, active=false}], streamableBytes=0, activeCountForTree=1, priorityQueueIndex=0, pseudoTimeToWrite=452, pseudoTime=565, totalQueuedWeights=220, active=false}], streamableBytes=0, activeCountForTree=1, priorityQueueIndex=0, pseudoTimeToWrite=678, pseudoTime=452, totalQueuedWeights=220, active=false}], streamableBytes=0, activeCountForTree=1, priorityQueueIndex=0, pseudoTimeToWrite=791, pseudoTime=678, totalQueuedWeights=220, active=false}], streamableBytes=0, activeCountForTree=1, priorityQueueIndex=0, pseudoTimeToWrite=904, pseudoTime=904, totalQueuedWeights=220, active=false}], streamableBytes=0, activeCountForTree=1, priorityQueueIndex=0, pseudoTimeToWrite=791, pseudoTime=904, totalQueuedWeights=220, active=false}], streamableBytes=0, activeCountForTree=1, priorityQueueIndex=-1, pseudoTimeToWrite=0, pseudoTime=791, totalQueuedWeights=220, active=false} |
|
The first before/after "nicely" formatted: |
|
@rkapsi - thanks! can you also tell me the |
|
@Scottmitch initial call as in the very first call or the value for before/after the exception is being thrown? |
|
@rkapsi - Just the value of the argument which triggers the call to |
|
@rkapsi - also are you using the default value for |
|
|
@Scottmitch I'm using the default value. The only non-default value I'm using is maxConcurrentStreams which is set to |
|
@rkapsi - I hacked together a unit test with one of your earlier state dumps and couldn't repo (I'm missing something), but I will try again now that you have provided the |
|
@Scottmitch would it help if... You change the |
|
It looks like the structure of the queues/tree has changed before and after ... this is a bit surprising. I would expect at least 1 element to be missing (bcz of this exception), and the queues/tree structure to have a hole ... but it looks like you are still able to traverse from the root to the leaf. For example how does Also it looks like only the state for streams 25, 27, 29, and 33 change during this allocation, so we may be able to reduce the test case to just these streams
Yes it may help to know when the exception is being thrown. |
Its starting to come back to me now ... if the data frame has the |
|
@rkapsi - I was able to reproduce the issue locally ... stand by for a PR. |
|
See #6004 |
Scottmitch
added a commit
to Scottmitch/netty
that referenced
this issue
Nov 12, 2016
Motivation: If a stream is not able to send any data (flow control window for the stream is exhausted) but has descendants who can send data then WeightedFairQueueByteDistributor may incorrectly modify the pseudo time and also double add the associated state to the parent's priority queue. The pseudo time should only be modified if a node is moved in the priority tree, and not if there happens to be no active streams in its descendent tree and a descendent is moved (e.g. removed from the tree because it wrote all data and the last data frame was EOS). Also the state objects for WeightedFairQueueByteDistributor should only appear once in any queue. If this condition is violated the pseudo time accounting would be biased at and assumptions in WeightedFairQueueByteDistributor would be invalidated. Modifications: - WeightedFairQueueByteDistributor#isActiveCountChangeForTree should not allow re-adding to the priority queue if we are currently processing a node in the distribution algorithm. The distribution algorithm will re-evaluate if the node should be re-added on the tail end of the recursion. Result: Fixes netty#5980
liuzhengyang
pushed a commit
to liuzhengyang/netty
that referenced
this issue
Sep 10, 2017
Motivation: If a stream is not able to send any data (flow control window for the stream is exhausted) but has descendants who can send data then WeightedFairQueueByteDistributor may incorrectly modify the pseudo time and also double add the associated state to the parent's priority queue. The pseudo time should only be modified if a node is moved in the priority tree, and not if there happens to be no active streams in its descendent tree and a descendent is moved (e.g. removed from the tree because it wrote all data and the last data frame was EOS). Also the state objects for WeightedFairQueueByteDistributor should only appear once in any queue. If this condition is violated the pseudo time accounting would be biased at and assumptions in WeightedFairQueueByteDistributor would be invalidated. Modifications: - WeightedFairQueueByteDistributor#isActiveCountChangeForTree should not allow re-adding to the priority queue if we are currently processing a node in the distribution algorithm. The distribution algorithm will re-evaluate if the node should be re-added on the tail end of the recursion. Result: Fixes netty#5980
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
4.1.7-SNAPSHOT
It's always the same message:
e.priorityQueueIndex(): 0 (expected: -1). It's strange because I don't seeWeightedFairQueueByteDistributor$State#priorityQueueIndex(0)ever being called (or thepriorityQueueIndexfield getting set).The text was updated successfully, but these errors were encountered: