nghttp2 icon indicating copy to clipboard operation
nghttp2 copied to clipboard

ngtcp2_conn_read_pkt: ERR_CALLBACK_FAILURE

Open ghost opened this issue 3 years ago • 9 comments

I'm following the HTTP3 testing instructions using Docker,

docker run --rm -it --network=host nghttp2-quic /usr/local/bin/h2load --npn-list h3 --connect-to 127.0.0.1:9004 https://www.example.com
starting benchmark...
spawning thread #0: 1 total client(s). 1 total requests
TLS Protocol: TLSv1.3
Cipher: TLS_AES_128_GCM_SHA256
Server Temp Key: X25519 253 bits
Application protocol: h3
ngtcp2_conn_read_pkt: ERR_CALLBACK_FAILURE

finished in 4.75ms, 0.00 req/s, 4.93KB/s
requests: 1 total, 1 started, 0 done, 0 succeeded, 1 failed, 1 errored, 0 timeout
status codes: 1 2xx, 0 3xx, 0 4xx, 0 5xx
traffic: 24B (24) total, 7B (7) headers (space savings 73.08%), 0B (0) data
UDP datagram: 3 sent, 5 received
                     min         max         mean         sd        +/- sd
time for request:        0us         0us         0us         0us     0.00%
time for connect:     3.26ms      3.26ms      3.26ms         0us   100.00%
time to 1st byte:        0us         0us         0us         0us     0.00%
req/s           :       0.00        0.00        0.00        0.00   100.00%

Is this a bug?

ghost avatar Jan 23 '22 10:01 ghost

Oh, btw I can query this server with quiche-client and get a response and I have tested the server against Firefox so I know the server is somewhat working.

ghost avatar Jan 23 '22 10:01 ghost

h2load -v option would provide more verbose log. Not sure what happened there but it looks like h2load did not like something it got. Which server are you using?

tatsuhiro-t avatar Jan 23 '22 12:01 tatsuhiro-t

I00000010 0x808db2c51d933c22 frm rx 6 Short(0x40) NEW_CONNECTION_ID(0x18) seq=1 cid=0xc662bcf590fec4a9 retire_prior_to=0 stateless_reset_token=0x763c032d6a393e6254662064eddd425c
I00000010 0x808db2c51d933c22 frm rx 6 Short(0x40) STREAM(0x0a) id=0x7 fin=0 offset=0 len=1 uni=1
I00000010 0x808db2c51d933c22 frm rx 6 Short(0x40) STREAM(0x0a) id=0x3 fin=0 offset=0 len=10 uni=1
I00000010 0x808db2c51d933c22 frm rx 6 Short(0x40) STREAM(0x0a) id=0xb fin=0 offset=0 len=4 uni=1
I00000010 0x808db2c51d933c22 frm rx 6 Short(0x40) STREAM(0x0b) id=0x0 fin=1 offset=0 len=19 uni=0
ngtcp2_conn_read_pkt: ERR_CALLBACK_FAILURE
I00000010 0x808db2c51d933c22 pkt tx pkn=1 dcid=0xf725780afbef2afa scid=0x type=Short(0x40) len=0 k=0
I00000010 0x808db2c51d933c22 frm tx 1 Short(0x40) CONNECTION_CLOSE(0x1c) error_code=NO_ERROR(0x0) frame_type=0 reason_len=0 reason=[]

ghost avatar Jan 23 '22 13:01 ghost

Thanks. It seems that HTTP/3 (possibly QPACK) does not work well here.

tatsuhiro-t avatar Jan 23 '22 13:01 tatsuhiro-t

I'm using lsquic but it's integrated in other stuff. I just removed all headers except for :status and now it works for exactly 100 requests, then it just stalls.

I've debugged it and I keep getting 1 request in 45 bytes of UDP datagram, 100 times and it works perfectly. But, anything over 100 requests just stalls.

The 101th request is only 32 bytes, not 45 like all others. Is there something happening at 100 requests? Why does it just stall and why does it suddenly send a request of size 32?

I don't have any backpressure or unhandled outgoing packets, everything succeeds on my end without errors.

ghost avatar Jan 23 '22 15:01 ghost

Yeah after 100th response I stop getting STREAM frames. I only get ACK frames but there is no 101th STREAM frame received on my end.

ghost avatar Jan 23 '22 16:01 ghost

Alright, I'm an idiot. I was not closing my streams, and 100 open was the limit. Now it works. But I still need to look at this header issue. Sorry for spamming.

ghost avatar Jan 23 '22 16:01 ghost

So you have some troubles between unknown version lsquic and h2load. I haven't seen any problem so far with lsquic in the past, but will check and see which callbacks are called.

tatsuhiro-t avatar Jan 24 '22 10:01 tatsuhiro-t

I guess that the stream was terminated in a way that ngtcp2 does not like and the entire connection was terminated. ngtcp2 client can show all received bytes, which might help understanding what's going on.

tatsuhiro-t avatar Jan 26 '22 14:01 tatsuhiro-t

This issue is stale because it has been open 30 days with no activity. Remove stale label or comment or this will be closed in 7 days.

github-actions[bot] avatar Apr 24 '24 01:04 github-actions[bot]