HTTP/2: Redundant DATA frames being sent stall tranmission in case of strict flow control
Redundant DATA frames
When sending POST request using HTTP/2, libsoup sends a redundant DATA frame - an empty frame with EOF flag indicating end of message.
Example - HTTP/2 POST with 4429 bytes of content:
(process:33): libsoup-http2-DEBUG: 14:25:54.481: [C95-S1] [NONE] [SESSION] Request made for (...)
(process:33): nghttp2-DEBUG: 14:25:54.485: [NGHTTP2] send: available window=16384
(process:33): libsoup-http2-DEBUG: 14:25:54.485: [C95-S1] [WRITE_HEADERS] [SEND_BODY] on_data_source_read_callback stream_id=1, length=16384
(process:33): libsoup-http2-DEBUG: 14:25:54.485: [C95-S1] [WRITE_HEADERS] [SEND_BODY] Read 4429
(process:33): nghttp2-DEBUG: 14:25:54.485: [NGHTTP2] send: next frame: DATA
(process:33): nghttp2-DEBUG: 14:25:54.485: [NGHTTP2] send: start transmitting frame type=0, length=4438
(process:33): nghttp2-DEBUG: 14:25:54.486: [NGHTTP2] send: end transmission of a frame
(process:33): nghttp2-DEBUG: 14:25:54.487: [NGHTTP2] send: remote windowsize connection=61106, remote maxframsize=16384, stream(id 1)=61106
(process:33): nghttp2-DEBUG: 14:25:54.487: [NGHTTP2] send: available window=16384
(process:33): libsoup-http2-DEBUG: 14:25:54.487: [C95-S1] [WRITE_DATA] [SEND_BODY] on_data_source_read_callback stream_id=1, length=16384
(process:33): libsoup-http2-DEBUG: 14:25:54.487: [C95-S1] [WRITE_DATA] [SEND_BODY] EOF
(process:33): nghttp2-DEBUG: 14:25:54.487: [NGHTTP2] send: next frame: DATA
(process:33): nghttp2-DEBUG: 14:25:54.487: [NGHTTP2] send: start transmitting frame type=0, length=9
(process:33): nghttp2-DEBUG: 14:25:54.487: [NGHTTP2] stream: stream=1 detach item=0x7e0b72f0
(process:33): nghttp2-DEBUG: 14:25:54.487: [NGHTTP2] stream: remove stream 1 from stream 0
(process:33): nghttp2-DEBUG: 14:25:54.489: [NGHTTP2] send: end transmission of a frame
Same example, but nghttp
utility used (to see how it sends the same data without libsoup):
[ 0.155] send HEADERS frame <length=69, flags=0x24, stream_id=13>
; END_HEADERS | PRIORITY
(padlen=0, dep_stream_id=11, weight=16, exclusive=0)
; Open new stream
:method: POST
:path: (...)
:scheme: https
:authority: (...)
accept: */*
accept-encoding: gzip, deflate
user-agent: nghttp2/1.40.0
content-length: 4429
[ 0.155] send DATA frame <length=4429, flags=0x01, stream_id=13>
; END_STREAM
As we can see (flags=0x01
), the nghttp
utility sends the same data to the same endpoint using a single DATA frame with EOF instead of sending two separate ones (one for data and one for EOF) like libsoup does.
The above shows that there is a room for improvement in libsoup as in the cases where content-length
is available, it is easily able to deduce which DATA frame is the last one so that in can append EOF flag to it.
Stalled transmission due to redundant DATA frame
The fact that libsoup sends that extra, empty DATA frame with EOF to mark end of message looks to be valid in regular cases. However, when testing prime video app from amazon (run on set-top-boxes), very interesting corner-case was discovered which shows that sending that extra DATA frame may be invalid.
The above corner case manifests itself when the app (via libsoup) is making POST request over HTTP/2 with content-length=164166
and the server introduces a strict (up to the single byte) flow control. The logs are the following:
(process:33): libsoup-http2-DEBUG: 14:26:54.953: [C182-S1] [NONE] [SESSION] Request made for (...)
(process:33): nghttp2-DEBUG: 14:26:54.953: [NGHTTP2] deflatehd: deflating :method: POST
(process:33): nghttp2-DEBUG: 14:26:54.955: [NGHTTP2] deflatehd: deflating content-length: 164166
(process:33): nghttp2-DEBUG: 14:26:54.957: [NGHTTP2] send: remote windowsize connection=65535, remote maxframsize=16384, stream(id 1)=65535
(process:33): nghttp2-DEBUG: 14:26:54.957: [NGHTTP2] send: available window=16384
(process:33): libsoup-http2-DEBUG: 14:26:54.957: [C182-S1] [WRITE_HEADERS] [SEND_BODY] on_data_source_read_callback stream_id=1, length=16384
(process:33): nghttp2-DEBUG: 14:26:54.958: [NGHTTP2] send: remote windowsize connection=49151, remote maxframsize=16384, stream(id 1)=49151
(process:33): nghttp2-DEBUG: 14:26:54.958: [NGHTTP2] send: available window=16384
(process:33): libsoup-http2-DEBUG: 14:26:54.958: [C182-S1] [WRITE_DATA] [SEND_BODY] on_data_source_read_callback stream_id=1, length=16384
(process:33): nghttp2-DEBUG: 14:26:54.959: [NGHTTP2] send: remote windowsize connection=32767, remote maxframsize=16384, stream(id 1)=32767
(process:33): nghttp2-DEBUG: 14:26:54.959: [NGHTTP2] send: available window=16384
(process:33): libsoup-http2-DEBUG: 14:26:54.959: [C182-S1] [WRITE_DATA] [SEND_BODY] on_data_source_read_callback stream_id=1, length=16384
(process:33): libsoup-http2-DEBUG: 14:26:55.014: [C182-S1] [WRITE_DATA] [RECV] WINDOW_UPDATE: increment=98630, total=115014
(process:33): nghttp2-DEBUG: 14:26:55.074: [NGHTTP2] send: remote windowsize connection=2147434495, remote maxframsize=16777215, stream(id 1)=115014
(process:33): nghttp2-DEBUG: 14:26:55.074: [NGHTTP2] send: available window=16384
(process:33): libsoup-http2-DEBUG: 14:26:55.075: [C182-S1] [WRITE_DATA] [SEND_BODY] on_data_source_read_callback stream_id=1, length=16384
(process:33): nghttp2-DEBUG: 14:26:55.076: [NGHTTP2] send: remote windowsize connection=2147418111, remote maxframsize=16777215, stream(id 1)=98630
(process:33): nghttp2-DEBUG: 14:26:55.076: [NGHTTP2] send: available window=16384
(process:33): libsoup-http2-DEBUG: 14:26:55.076: [C182-S1] [WRITE_DATA] [SEND_BODY] on_data_source_read_callback stream_id=1, length=16384
(process:33): nghttp2-DEBUG: 14:26:55.077: [NGHTTP2] send: remote windowsize connection=2147401727, remote maxframsize=16777215, stream(id 1)=82246
(process:33): nghttp2-DEBUG: 14:26:55.077: [NGHTTP2] send: available window=16384
(process:33): libsoup-http2-DEBUG: 14:26:55.077: [C182-S1] [WRITE_DATA] [SEND_BODY] on_data_source_read_callback stream_id=1, length=16384
(process:33): nghttp2-DEBUG: 14:26:55.078: [NGHTTP2] send: remote windowsize connection=2147385343, remote maxframsize=16777215, stream(id 1)=65862
(process:33): nghttp2-DEBUG: 14:26:55.078: [NGHTTP2] send: available window=16384
(process:33): libsoup-http2-DEBUG: 14:26:55.078: [C182-S1] [WRITE_DATA] [SEND_BODY] on_data_source_read_callback stream_id=1, length=16384
(process:33): nghttp2-DEBUG: 14:26:55.079: [NGHTTP2] send: remote windowsize connection=2147368959, remote maxframsize=16777215, stream(id 1)=49478
(process:33): nghttp2-DEBUG: 14:26:55.079: [NGHTTP2] send: available window=16384
(process:33): libsoup-http2-DEBUG: 14:26:55.079: [C182-S1] [WRITE_DATA] [SEND_BODY] on_data_source_read_callback stream_id=1, length=16384
(process:33): nghttp2-DEBUG: 14:26:55.080: [NGHTTP2] send: remote windowsize connection=2147352575, remote maxframsize=16777215, stream(id 1)=33094
(process:33): nghttp2-DEBUG: 14:26:55.080: [NGHTTP2] send: available window=16384
(process:33): libsoup-http2-DEBUG: 14:26:55.080: [C182-S1] [WRITE_DATA] [SEND_BODY] on_data_source_read_callback stream_id=1, length=16384
(process:33): nghttp2-DEBUG: 14:26:55.081: [NGHTTP2] send: remote windowsize connection=2147336191, remote maxframsize=16777215, stream(id 1)=16710
(process:33): nghttp2-DEBUG: 14:26:55.081: [NGHTTP2] send: available window=16384
(process:33): libsoup-http2-DEBUG: 14:26:55.081: [C182-S1] [WRITE_DATA] [SEND_BODY] on_data_source_read_callback stream_id=1, length=16384
(process:33): nghttp2-DEBUG: 14:26:55.083: [NGHTTP2] send: remote windowsize connection=2147319807, remote maxframsize=16777215, stream(id 1)=326
(process:33): nghttp2-DEBUG: 14:26:55.083: [NGHTTP2] send: available window=326
(process:33): libsoup-http2-DEBUG: 14:26:55.083: [C182-S1] [WRITE_DATA] [SEND_BODY] on_data_source_read_callback stream_id=1, length=326
(process:33): nghttp2-DEBUG: 14:26:55.083: [NGHTTP2] send: next frame: DATA
(process:33): libsoup-http2-DEBUG: 14:26:55.083: [C182-S1] [WRITE_DATA] [SEND] [DATA] bytes=326, finished=0
(process:33): GLib-Net-DEBUG: 14:26:55.083: CLIENT[0x7dfa84b8]: successfully write 335 bytes to TLS connection
(process:33): nghttp2-DEBUG: 14:26:55.084: [NGHTTP2] send: end transmission of a frame
(process:33): nghttp2-DEBUG: 14:26:55.084: [NGHTTP2] send: remote windowsize connection=2147319481, remote maxframsize=16777215, stream(id 1)=0
(process:33): nghttp2-DEBUG: 14:26:55.084: [NGHTTP2] send: available window=0
(process:33): nghttp2-DEBUG: 14:26:55.084: [NGHTTP2] stream: stream=1 defer item=0x7e0f7c90 cause=04
(process:33): nghttp2-DEBUG: 14:26:55.084: [NGHTTP2] send: frame transmission deferred
As we can see, at some point, libsoup has 115014
bytes to write while at the same time the server (via WINDOW_UPDATE
) informs it that due to flow control, libsoup can write only 115014
more. From the spec PoV that makes sense - server tells libsoup that it will accept this request till the end, but not a single byte more.
Anyway, since libsoup always sends EOF in a separate DATA frame, the above leads to the situation when nghttp2 has to defer transmission of that frame as the available window=0
. One can argue that nghttp could send 0 bytes of data to the server accepting 0 bytes of data in that case. The thing is, nghttp does not posses the knowledge about the remaining bytes to be sent so it cannot do it.
Proposed fix
To fix both above problems, the following is proposed: fix.patch