Server sends GoAway to closed connection (resulting in errors on macos/bsd)

[soundofspace]

Some context: a few days ago I asked on Discord if hyper ever saw integration::http2_parallel_10 test failing in ci on Mac. But you mention you don't run that test on Mac because of weirdness there. I did tried to figure out what went wrong (as I develop on mac and was worried this might be part of a bigger problem), and found two issues. Solving one is already enough, but both solving both is probably ideal.

Problem one: calling shutdown twice on socket on mac/bsd results in ENOTCONN. Calling shutdown here happens on automatically and this is not really a Hyper problem, but more of a Tokio problem. For this I responded here and will try to work out a solution with the Tokio team

Problem two: a Hyper H2 problem. Depending on the exact order of shutdown this happens:

• Receive GoAway from client
• Client starts to close tcp
• Server reads from frame but receives pending (vs ready(None) on successful shutdown)
• Server sends GoAway to client instead of just closing
• Client responds with reset to this unexpected packet
• Macos closes socket completely now
• Server does shutdown on socket resulting in problem 1

Biggest issue here is problem 1 and if that one is fixed this is honestly not really a problem anymore. But still wanted to open this issue to track this problem and to ask the question: do we need/want to solve problem 2?

Some relevant log lines of this failing:

2025-04-18T06:49:44.442645Z TRACE Connection{peer=Client}:poll: rama_http_core::h2::codec::framed_write: polling inner shutdown done
2025-04-18T06:49:44.442646Z TRACE Connection{peer=Client}:poll: rama_http_core::h2::codec::framed_write: polling inner shutdown done success
2025-04-18T06:49:44.442647Z TRACE Connection{peer=Client}:poll: rama_http_core::h2::proto::connection: connection.state=Closed(NO_ERROR, Library)
2025-04-18T06:49:44.442648Z TRACE Connection{peer=Client}:poll: rama_http_core::h2::proto::connection: connection already closed
2025-04-18T06:49:44.442652Z TRACE rama_http_core::h2::proto::streams::streams: Streams::recv_eof
2025-04-18T06:49:44.442665Z TRACE rama_http_core::h2::server: accept poll
2025-04-18T06:49:44.442666Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::connection: connection.state=Open
2025-04-18T06:49:44.442668Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::connection: poll2
2025-04-18T06:49:44.442669Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::connection: polling ready
2025-04-18T06:49:44.442671Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::connection: polling ready done
2025-04-18T06:49:44.442673Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: rama_http_core::h2::codec::framed_read: poll
2025-04-18T06:49:44.442677Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: rama_http_core::h2::codec::framed_read: read.bytes=9
2025-04-18T06:49:44.442679Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=9}: rama_http_core::h2::codec::framed_read: decoding frame from 9B
2025-04-18T06:49:44.442681Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=9}: rama_http_core::h2::codec::framed_read: frame.kind=Settings
2025-04-18T06:49:44.442683Z DEBUG server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: rama_http_core::h2::codec::framed_read: received frame=Settings { flags: (0x1: ACK), setting_order: None }
2025-04-18T06:49:44.442686Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::connection: next_frame=Ready(Some(Ok(Settings { flags: (0x1: ACK), setting_order: None })))
2025-04-18T06:49:44.442688Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::connection: recv SETTINGS frame=Settings { flags: (0x1: ACK), setting_order: None }
received settings
2025-04-18T06:49:44.442690Z DEBUG server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::settings: received settings ACK; applying Settings { flags: (0x0), setting_order: None, initial_window_size: 1048576, max_concurrent_streams: 200, max_frame_size: 16384, max_header_list_size: 16384 }
2025-04-18T06:49:44.442691Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::streams::recv: update_initial_window_size; new=1048576; old=65535
2025-04-18T06:49:44.442693Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::streams::recv: incrementing all windows; inc=983041
2025-04-18T06:49:44.442694Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::connection: polling ready
2025-04-18T06:49:44.442696Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::connection: polling ready done
2025-04-18T06:49:44.442697Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: rama_http_core::h2::codec::framed_read: poll
2025-04-18T06:49:44.442699Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: rama_http_core::h2::codec::framed_read: read.bytes=17
2025-04-18T06:49:44.442701Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=17}: rama_http_core::h2::codec::framed_read: decoding frame from 17B
2025-04-18T06:49:44.442761Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next:FramedRead::decode_frame{offset=17}: rama_http_core::h2::codec::framed_read: frame.kind=GoAway
2025-04-18T06:49:44.442767Z DEBUG server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: rama_http_core::h2::codec::framed_read: received frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }
2025-04-18T06:49:44.442770Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::connection: next_frame=Ready(Some(Ok(GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) })))
2025-04-18T06:49:44.442772Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::connection: recv GOAWAY frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(0) }
received conintue
2025-04-18T06:49:44.442775Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::connection: polling ready
2025-04-18T06:49:44.442777Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::connection: polling ready done
2025-04-18T06:49:44.442779Z TRACE server_handshake:Connection{peer=Server}:poll:FramedRead::poll_next: rama_http_core::h2::codec::framed_read: poll
2025-04-18T06:49:44.442781Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::connection: next_frame=Pending
2025-04-18T06:49:44.442783Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::connection: doing window updates
2025-04-18T06:49:44.442785Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::streams::prioritize: poll_complete
2025-04-18T06:49:44.442786Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::streams::prioritize: schedule_pending_open
2025-04-18T06:49:44.442788Z TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::flush: rama_http_core::h2::codec::framed_write: flushing buffer
2025-04-18T06:49:44.442790Z TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::flush: rama_http_core::h2::codec::framed_write: flushing buffer done
2025-04-18T06:49:44.442792Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::connection: connection.state=Open
2025-04-18T06:49:44.442793Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::connection: poll2
2025-04-18T06:49:44.442796Z DEBUG server_handshake:Connection{peer=Server}:poll:FramedWrite::buffer{frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(1) }}: rama_http_core::h2::codec::framed_write: send frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(1) }
2025-04-18T06:49:44.442798Z TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::buffer{frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(1) }}: rama_http_core::h2::frame::go_away: encoding GO_AWAY; code=NO_ERROR
2025-04-18T06:49:44.442800Z TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::buffer{frame=GoAway { error_code: NO_ERROR, last_stream_id: StreamId(1) }}: rama_http_core::h2::codec::framed_write: encoded go_away rem=17
2025-04-18T06:49:44.442802Z DEBUG server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::connection: Connection::poll; connection error error=GoAway(b"", NO_ERROR, Library)
2025-04-18T06:49:44.442804Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::connection:     -> already going away
2025-04-18T06:49:44.442805Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::connection: connection.state=Closing(NO_ERROR, Library)
2025-04-18T06:49:44.442807Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::proto::connection: connection closing after flush
2025-04-18T06:49:44.442808Z TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::flush: rama_http_core::h2::codec::framed_write: queued_data_frame=false
2025-04-18T06:49:44.442817Z TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::flush: rama_http_core::h2::codec::framed_write: flushing buffer
2025-04-18T06:49:44.442818Z TRACE server_handshake:Connection{peer=Server}:poll:FramedWrite::flush: rama_http_core::h2::codec::framed_write: flushing buffer done
2025-04-18T06:49:44.442820Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::codec::framed_write: polling inner shutdown
pool shutdown
2025-04-18T06:49:44.442906Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::codec::framed_write: polling inner shutdown done
2025-04-18T06:49:44.442909Z TRACE server_handshake:Connection{peer=Server}:poll: rama_http_core::h2::codec::framed_write: polling inner shutdown done fail err=Os { code: 57, kind: NotConnected, message: "Socket is not connected" }
2025-04-18T06:49:44.442931Z TRACE rama_http_core::proto::h2::server: incoming connection error err=Error { kind: Io(Kind(NotConnected)) }
2025-04-18T06:49:44.442934Z TRACE rama_http_core::h2::proto::streams::streams: Streams::recv_eof
got error2: rama_http_core::Error(Io, Kind(NotConnected))

Related issues:

• integration::http2_parallel_10 sometimes crashes in ci on macos plabayo/rama#504
• TcpStream::shutdown on macOS on localhost yields error tokio-rs/tokio#4665