nghttp2.org

HTTP/2 C library and tools

BLOCKED Frame Did Not Block DATA Frame?

nghttp HTTP/2 client included in nghttp2 has a nice feature to show the incoming and outgoing HTTP/2 frames. It is extremely usable for debugging.

Here is a snippet of the log nghttp produced today:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40

[  0.359] recv HEADERS frame <length=154, flags=0x04, stream_id=1>
          ; END_HEADERS
          (padlen=0)
          ; First response header
[  0.359] recv DATA frame <length=3798, flags=0x00, stream_id=1>
[  0.362] recv DATA frame <length=4096, flags=0x00, stream_id=1>
[  0.362] send HEADERS frame <length=27, flags=0x05, stream_id=3>
          ; END_STREAM | END_HEADERS
          (padlen=0)
          ; Open new stream
[  0.364] recv DATA frame <length=4096, flags=0x00, stream_id=1>
[  0.391] recv DATA frame <length=2715, flags=0x00, stream_id=1>
[  0.392] recv DATA frame <length=0, flags=0x01, stream_id=1>
[  0.394] recv HEADERS frame <length=40, flags=0x04, stream_id=3>
          ; END_HEADERS
          (padlen=0)
          ; First response header
[  0.394] recv DATA frame <length=3798, flags=0x00, stream_id=3>
[  0.394] recv DATA frame <length=4096, flags=0x00, stream_id=3>
[  0.402] recv DATA frame <length=4096, flags=0x00, stream_id=3>
[  0.406] recv DATA frame <length=4096, flags=0x00, stream_id=3>
[  0.430] recv DATA frame <length=4096, flags=0x00, stream_id=3>
[  0.430] send WINDOW_UPDATE frame <length=4, flags=0x00, stream_id=0>
          (window_size_increment=34887)
[  0.434] recv DATA frame <length=4096, flags=0x00, stream_id=3>
[  0.435] recv DATA frame <length=4096, flags=0x00, stream_id=3>
[  0.438] recv DATA frame <length=4096, flags=0x00, stream_id=3>
[  0.442] recv DATA frame <length=4096, flags=0x00, stream_id=3>
[  0.442] send WINDOW_UPDATE frame <length=4, flags=0x00, stream_id=3>
          (window_size_increment=36566)
[  0.470] recv DATA frame <length=4096, flags=0x00, stream_id=3>
[  0.471] recv DATA frame <length=4096, flags=0x00, stream_id=3>
[  0.474] recv DATA frame <length=4096, flags=0x00, stream_id=3>
[  0.475] recv DATA frame <length=1976, flags=0x00, stream_id=3>
[  0.475] recv BLOCKED frame <length=0, flags=0x00, stream_id=0>
[  0.488] recv DATA frame <length=4096, flags=0x00, stream_id=3>
[  0.488] recv DATA frame <length=4096, flags=0x00, stream_id=3>
[  0.488] recv DATA frame <length=4096, flags=0x00, stream_id=3>
[  0.489] recv DATA frame <length=2417, flags=0x00, stream_id=3>
[  0.489] recv BLOCKED frame <length=0, flags=0x00, stream_id=3>

When you see this, you may wonder why BLOCKED frame recieved at t=0.475 was followed by DATA frame. BLOCKED with stream_id=0 means connection level window size is depleted, and server is unable to send more DATA until it receives WINDOW_UPDATE frame from client. There is no WINDOW_UPDATE between t=0.475 and t=0.488, so you may think this must be a mistake, server has a bug.

Of course not. WINDOW_UPDATE with stream_id=0 was already sent t=0.430. But due to latency, before it reached at the server, server used all available window size and sent BLOCKED frame. After that, the server finally received the WINDOW_UPDATE from client and update its window size and started to send DATA frame again.

BLOCKED and WINDOW_UPDATE frames