Flow control: WINDOW_UPDATE swallowed on closed streams

[Kriechi]

Imagine the following scenario:

• client sends HEADERS for a request + end_stream to the server
• server sends HEADERS for response and starts sending a few DATA frames
• client continuously sends WINDOW_UPDATE for the consumed data
• server sends more DATA frames
• client sends RST_STREAM to cancel this stream
• client has a few unprocessed DATA frames in it's incoming buffer
• and the server might have already sent a few more before having canceled the stream

The problem here seems to be that the client thinks the stream is already closed. Receiving DATA frames on a closed streams causes a h2.exceptions.StreamClosedError
https://github.com/python-hyper/hyper-h2/blob/306609aa72c5ad4860a72fc4caa5db9ef5ab5b26/h2/stream.py#L317

This exception is then swallowed and replaced with more generic error handling
https://github.com/python-hyper/hyper-h2/blob/306609aa72c5ad4860a72fc4caa5db9ef5ab5b26/h2/connection.py#L1487

This means the client is completely unaware that it just tried to process a DATA frame, yet it did!
Since there was no proper DataReceived event for the user to handle, nobody will call acknowledge_received_data to update the flow control and send a WINDOW_UPDATE.

Now we have effectively starved the whole h2 connection because one "rogue" stream was taking all the available connection flow window and nobody is able to update it because the information about the DATA frame is swallowed by the exception handling.

A short PoC script
It wraps one of the H2Connection functions to add a debug print for the root cause and it prints the remaining flow window size. After a few seconds this will go to 0, and therefore halting all streams in the connection.

The expected output of the script is a continuous output of DATA frames of stream 1, every second or so, with 61 bytes, and then many smaller ones for the additional requests.

If you call the script without any CLI args, it only create the first continuous stream, just to demontrate that the acknowledge_received_data works in principle.

If you call the script with a single CLI arg foo, the script will generate a few more requests, and then send a RST_STREAM shortly after. This causes a lot of unprocessed DATA frames to be swallowed, and the input flow window will shortly after be starved to 0.

#!/usr/bin/env python3

import certifi
import h2.connection
import h2.events

import traceback
import sys
import errno
import socket
import ssl
import time

SERVER_NAME = 'http2.golang.org'

socket.setdefaulttimeout(15)

class FoobarH2Connection(h2.connection.H2Connection):
    def _receive_data_frame(self, frame):
        try:
            return super()._receive_data_frame(frame)
        except Exception as e:
            print("Exception detected - swallowing the DataFrame and flow_controlled_length:", e.__dict__, c._inbound_flow_control_window_manager.current_window_size)
            raise e

c = FoobarH2Connection()
c.initiate_connection()

ctx = ssl.create_default_context(cafile=certifi.where())
ctx.set_alpn_protocols(['h2', 'http/1.1'])

s = socket.create_connection((SERVER_NAME, 443))
s = ctx.wrap_socket(s, server_hostname=SERVER_NAME)

s.sendall(c.data_to_send())

headers = [
    (':method', 'GET'),
    (':path', '/clockstream'),
    (':authority', SERVER_NAME),
    (':scheme', 'https'),
]
c.send_headers(1, headers, end_stream=True)
s.sendall(c.data_to_send())

count = 2
while True:
    data = s.recv(65536 * 1024)
    if not data:
        break

    count += 1
    if count % 2 == 1 and len(sys.argv) > 1:
        headers = [
            (':method', 'GET'),
            (':path', '/file/gopher.png'),
            (':authority', SERVER_NAME),
            (':scheme', 'https'),
        ]
        c.send_headers(count, headers, end_stream=True)
        s.sendall(c.data_to_send())
        time.sleep(0.25)
        c.reset_stream(count)

    events = c.receive_data(data)
    for event in events:
        if isinstance(event, h2.events.DataReceived):
            print(event, c._inbound_flow_control_window_manager.current_window_size)
            c.acknowledge_received_data(event.flow_controlled_length, event.stream_id)

    s.sendall(c.data_to_send())

The output on my system is:

Exception detected - swallowing the DataFrame and flow_controlled_length: <class 'h2.exceptions.StreamClosedError'> {'stream_id': 3, 'error_code': <ErrorCodes.STREAM_CLOSED: 5>, '_events': []} 49151
Exception detected - swallowing the DataFrame and flow_controlled_length: <class 'h2.exceptions.StreamClosedError'> {'stream_id': 3, 'error_code': <ErrorCodes.STREAM_CLOSED: 5>, '_events': []} 47867
<DataReceived stream_id:1, flow_controlled_length:1180, data:23207e314b42206f66206a756e6b20746f20666f> 46687
Exception detected - swallowing the DataFrame and flow_controlled_length: <class 'h2.exceptions.StreamClosedError'> {'stream_id': 3, 'error_code': <ErrorCodes.STREAM_CLOSED: 5>, '_events': []} 46687
Exception detected - swallowing the DataFrame and flow_controlled_length: <class 'h2.exceptions.StreamClosedError'> {'stream_id': 5, 'error_code': <ErrorCodes.STREAM_CLOSED: 5>, '_events': []} 30303
Exception detected - swallowing the DataFrame and flow_controlled_length: <class 'h2.exceptions.StreamClosedError'> {'stream_id': 5, 'error_code': <ErrorCodes.STREAM_CLOSED: 5>, '_events': []} 29019
Exception detected - swallowing the DataFrame and flow_controlled_length: <class 'h2.exceptions.StreamClosedError'> {'stream_id': 5, 'error_code': <ErrorCodes.STREAM_CLOSED: 5>, '_events': []} 29019
Exception detected - swallowing the DataFrame and flow_controlled_length: <class 'h2.exceptions.StreamClosedError'> {'stream_id': 7, 'error_code': <ErrorCodes.STREAM_CLOSED: 5>, '_events': []} 12635
Exception detected - swallowing the DataFrame and flow_controlled_length: <class 'h2.exceptions.StreamClosedError'> {'stream_id': 7, 'error_code': <ErrorCodes.STREAM_CLOSED: 5>, '_events': []} 11351
Exception detected - swallowing the DataFrame and flow_controlled_length: <class 'h2.exceptions.StreamClosedError'> {'stream_id': 7, 'error_code': <ErrorCodes.STREAM_CLOSED: 5>, '_events': []} 11351
Exception detected - swallowing the DataFrame and flow_controlled_length: <class 'h2.exceptions.StreamClosedError'> {'stream_id': 9, 'error_code': <ErrorCodes.STREAM_CLOSED: 5>, '_events': []} 0
...
<after 15 seconds we fail as expected with a socket.timeout: The read operation timed out>

ref mitmproxy/mitmproxy#3780

[Lukasa]

Yup, this is definitely an issue: if h2 is mad about a Data frame and wants to except, it probably has to auto-acknowledge that data and prepare a WINDOW_UPDATE frame to cover it. I don’t think I have the bandwidth to write this patch, but it’d be great if the community could.

[vmagamedov]

@Kriechi do you plan to submit a PR to fix this issue? I can volunteer to fix this issue.

[Kriechi]

@vmagamedov yes - in fact I already have something - just need to write tests.
Thanks! I'd be happy to have you as reviewer on the PR - will probably submit later tonight.