From ce12204bc32ed35625a3c92293365e0e54c865e8 Mon Sep 17 00:00:00 2001 From: Marten Seemann Date: Sun, 12 Oct 2025 13:16:37 +0800 Subject: [PATCH] http3: qlog sent and received SETTINGS frames (#5379) * http3: implement qlog serialization for SETTINGS frames * http3: qlog sent and received SETTINGS frames --- http3/client.go | 15 +++++++++ http3/client_test.go | 21 +++++++++++- http3/conn_test.go | 33 +++++++++++-------- http3/frames.go | 25 ++++++++++++-- http3/http3_helper_test.go | 22 +++++++++++++ http3/qlog/frame.go | 48 +++++++++++++++++++++++++++ http3/qlog/frame_test.go | 67 ++++++++++++++++++++++++++++++++++++++ http3/server.go | 25 +++++++++++--- http3/server_test.go | 6 ++-- 9 files changed, 238 insertions(+), 24 deletions(-) diff --git a/http3/client.go b/http3/client.go index 9d511cab9..1a11e0250 100644 --- a/http3/client.go +++ b/http3/client.go @@ -6,12 +6,14 @@ import ( "fmt" "io" "log/slog" + "maps" "net/http" "net/http/httptrace" "net/textproto" "time" "github.com/quic-go/quic-go" + "github.com/quic-go/quic-go/http3/qlog" "github.com/quic-go/quic-go/quicvarint" "github.com/quic-go/qpack" @@ -136,6 +138,19 @@ func (c *ClientConn) setupConn() error { b = quicvarint.Append(b, streamTypeControlStream) // send the SETTINGS frame b = (&settingsFrame{Datagram: c.enableDatagrams, Other: c.additionalSettings}).Append(b) + if c.conn.qlogger != nil { + sf := qlog.SettingsFrame{ + Other: maps.Clone(c.additionalSettings), + } + if c.enableDatagrams { + sf.Datagram = pointer(true) + } + c.conn.qlogger.RecordEvent(qlog.FrameCreated{ + StreamID: str.StreamID(), + Raw: qlog.RawInfo{Length: len(b)}, + Frame: qlog.Frame{Frame: sf}, + }) + } _, err = str.Write(b) return err } diff --git a/http3/client_test.go b/http3/client_test.go index b875754c6..2754bfaf7 100644 --- a/http3/client_test.go +++ b/http3/client_test.go @@ -13,7 +13,10 @@ import ( "github.com/quic-go/qpack" "github.com/quic-go/quic-go" + "github.com/quic-go/quic-go/http3/qlog" + "github.com/quic-go/quic-go/qlogwriter" "github.com/quic-go/quic-go/quicvarint" + "github.com/quic-go/quic-go/testutils/events" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -35,7 +38,8 @@ func testClientSettings(t *testing.T, enableDatagrams bool, other map[uint64]uin AdditionalSettings: other, } - clientConn, serverConn := newConnPair(t) + var eventRecorder events.Recorder + clientConn, serverConn := newConnPairWithRecorder(t, &eventRecorder, nil) tr.NewClientConn(clientConn) ctx, cancel := context.WithTimeout(context.Background(), time.Second) @@ -54,6 +58,21 @@ func testClientSettings(t *testing.T, enableDatagrams bool, other map[uint64]uin settingsFrame := f.(*settingsFrame) require.Equal(t, settingsFrame.Datagram, enableDatagrams) require.Equal(t, settingsFrame.Other, other) + + var datagramValue *bool + if enableDatagrams { + datagramValue = pointer(true) + } + require.Equal(t, + []qlogwriter.Event{ + qlog.FrameCreated{ + StreamID: str.StreamID(), + Raw: qlog.RawInfo{Length: 5}, + Frame: qlog.Frame{Frame: qlog.SettingsFrame{Datagram: datagramValue, Other: other}}, + }, + }, + filterQlogEventsForFrame(eventRecorder.Events(qlog.FrameCreated{}), qlog.SettingsFrame{}), + ) } func encodeResponse(t *testing.T, status int) []byte { diff --git a/http3/conn_test.go b/http3/conn_test.go index 1dd9cf2ab..487dee39f 100644 --- a/http3/conn_test.go +++ b/http3/conn_test.go @@ -17,7 +17,8 @@ import ( ) func TestConnReceiveSettings(t *testing.T) { - clientConn, serverConn := newConnPair(t) + var eventRecorder events.Recorder + clientConn, serverConn := newConnPairWithRecorder(t, nil, &eventRecorder) conn := newConnection( serverConn.Context(), @@ -52,6 +53,17 @@ func TestConnReceiveSettings(t *testing.T) { require.True(t, settings.EnableDatagrams) require.True(t, settings.EnableExtendedConnect) require.Equal(t, map[uint64]uint64{1337: 42}, settings.Other) + + require.Equal(t, + []qlogwriter.Event{ + qlog.FrameParsed{ + StreamID: controlStr.StreamID(), + Raw: qlog.RawInfo{PayloadLength: len(b) - 3}, // type and length + Frame: qlog.Frame{Frame: qlog.SettingsFrame{Datagram: pointer(true), ExtendedConnect: pointer(true), Other: map[uint64]uint64{1337: 42}}}, + }, + }, + filterQlogEventsForFrame(eventRecorder.Events(qlog.FrameParsed{}), qlog.SettingsFrame{}), + ) } func TestConnRejectDuplicateStreams(t *testing.T) { @@ -323,19 +335,14 @@ func testConnGoAway(t *testing.T, withStream bool) { t.Fatal("timeout waiting for close") } - framesParsed := clientEventRecorder.Events(qlog.FrameParsed{}) - var goawayFramesParsed []qlog.FrameParsed - for _, ev := range framesParsed { - if _, ok := ev.(qlog.FrameParsed).Frame.Frame.(qlog.GoAwayFrame); ok { - goawayFramesParsed = append(goawayFramesParsed, ev.(qlog.FrameParsed)) - } - } require.Equal(t, - []qlog.FrameParsed{{ - StreamID: 3, - Frame: qlog.Frame{Frame: qlog.GoAwayFrame{StreamID: 8}}, - }}, - goawayFramesParsed, + []qlogwriter.Event{ + qlog.FrameParsed{ + StreamID: 3, + Frame: qlog.Frame{Frame: qlog.GoAwayFrame{StreamID: 8}}, + }, + }, + filterQlogEventsForFrame(clientEventRecorder.Events(qlog.FrameParsed{}), qlog.GoAwayFrame{StreamID: 8}), ) } diff --git a/http3/frames.go b/http3/frames.go index 5a93aeaea..4c02e96e2 100644 --- a/http3/frames.go +++ b/http3/frames.go @@ -5,6 +5,7 @@ import ( "errors" "fmt" "io" + "maps" "github.com/quic-go/quic-go" "github.com/quic-go/quic-go/http3/qlog" @@ -73,7 +74,7 @@ func (p *frameParser) ParseNext(qlogger qlogwriter.Recorder) (frame, error) { case 0x1: return &headersFrame{Length: l}, nil case 0x4: - return parseSettingsFrame(p.r, l) + return parseSettingsFrame(p.r, l, p.streamID, qlogger) case 0x3: // CANCEL_PUSH case 0x5: // PUSH_PROMISE case 0x7: @@ -132,7 +133,11 @@ type settingsFrame struct { Other map[uint64]uint64 // all settings that we don't explicitly recognize } -func parseSettingsFrame(r io.Reader, l uint64) (*settingsFrame, error) { +func pointer[T any](v T) *T { + return &v +} + +func parseSettingsFrame(r io.Reader, l uint64, streamID quic.StreamID, qlogger qlogwriter.Recorder) (*settingsFrame, error) { if l > 8*(1<<10) { return nil, fmt.Errorf("unexpected size for SETTINGS frame: %d", l) } @@ -145,6 +150,7 @@ func parseSettingsFrame(r io.Reader, l uint64) (*settingsFrame, error) { } frame := &settingsFrame{} b := bytes.NewReader(buf) + var settingsFrame qlog.SettingsFrame var readDatagram, readExtendedConnect bool for b.Len() > 0 { id, err := quicvarint.Read(b) @@ -166,6 +172,9 @@ func parseSettingsFrame(r io.Reader, l uint64) (*settingsFrame, error) { return nil, fmt.Errorf("invalid value for SETTINGS_ENABLE_CONNECT_PROTOCOL: %d", val) } frame.ExtendedConnect = val == 1 + if qlogger != nil { + settingsFrame.ExtendedConnect = pointer(frame.ExtendedConnect) + } case settingDatagram: if readDatagram { return nil, fmt.Errorf("duplicate setting: %d", id) @@ -175,6 +184,9 @@ func parseSettingsFrame(r io.Reader, l uint64) (*settingsFrame, error) { return nil, fmt.Errorf("invalid value for SETTINGS_H3_DATAGRAM: %d", val) } frame.Datagram = val == 1 + if qlogger != nil { + settingsFrame.Datagram = pointer(frame.Datagram) + } default: if _, ok := frame.Other[id]; ok { return nil, fmt.Errorf("duplicate setting: %d", id) @@ -185,6 +197,15 @@ func parseSettingsFrame(r io.Reader, l uint64) (*settingsFrame, error) { frame.Other[id] = val } } + if qlogger != nil { + settingsFrame.Other = maps.Clone(frame.Other) + + qlogger.RecordEvent(qlog.FrameParsed{ + StreamID: streamID, + Raw: qlog.RawInfo{PayloadLength: len(buf)}, + Frame: qlog.Frame{Frame: settingsFrame}, + }) + } return frame, nil } diff --git a/http3/http3_helper_test.go b/http3/http3_helper_test.go index 2807bc2f3..15ec4a935 100644 --- a/http3/http3_helper_test.go +++ b/http3/http3_helper_test.go @@ -15,12 +15,14 @@ import ( "net" "net/http" "os" + "reflect" "strconv" "testing" "time" "github.com/quic-go/qpack" "github.com/quic-go/quic-go" + "github.com/quic-go/quic-go/http3/qlog" "github.com/quic-go/quic-go/qlogwriter" "github.com/stretchr/testify/require" @@ -306,3 +308,23 @@ func decodeHeader(t *testing.T, r io.Reader) map[string][]string { } return fields } + +// filterQlogEventsForFrame filters the events for the given frame type, +// for both FrameCreated and FrameParsed events. +// It returns the events that match the given frame type. +func filterQlogEventsForFrame(events []qlogwriter.Event, frame any) []qlogwriter.Event { + var filtered []qlogwriter.Event + for _, ev := range events { + switch e := ev.(type) { + case qlog.FrameCreated: + if reflect.TypeOf(e.Frame.Frame) == reflect.TypeOf(frame) { + filtered = append(filtered, ev) + } + case qlog.FrameParsed: + if reflect.TypeOf(e.Frame.Frame) == reflect.TypeOf(frame) { + filtered = append(filtered, ev) + } + } + } + return filtered +} diff --git a/http3/qlog/frame.go b/http3/qlog/frame.go index 92c6992c5..d2428900f 100644 --- a/http3/qlog/frame.go +++ b/http3/qlog/frame.go @@ -18,6 +18,8 @@ func (f Frame) encode(enc *jsontext.Encoder) error { return frame.encode(enc) case GoAwayFrame: return frame.encode(enc) + case SettingsFrame: + return frame.encode(enc) } // This shouldn't happen if the code is correctly logging frames. // Write a null token to produce valid JSON. @@ -83,3 +85,49 @@ func (f *GoAwayFrame) encode(enc *jsontext.Encoder) error { h.WriteToken(jsontext.EndObject) return h.err } + +type SettingsFrame struct { + Datagram *bool + ExtendedConnect *bool + Other map[uint64]uint64 +} + +func (f *SettingsFrame) encode(enc *jsontext.Encoder) error { + h := encoderHelper{enc: enc} + h.WriteToken(jsontext.BeginObject) + h.WriteToken(jsontext.String("frame_type")) + h.WriteToken(jsontext.String("settings")) + h.WriteToken(jsontext.String("settings")) + h.WriteToken(jsontext.BeginArray) + if f.Datagram != nil { + h.WriteToken(jsontext.BeginObject) + h.WriteToken(jsontext.String("name")) + h.WriteToken(jsontext.String("settings_h3_datagram")) + h.WriteToken(jsontext.String("value")) + h.WriteToken(jsontext.Bool(*f.Datagram)) + h.WriteToken(jsontext.EndObject) + } + if f.ExtendedConnect != nil { + h.WriteToken(jsontext.BeginObject) + h.WriteToken(jsontext.String("name")) + h.WriteToken(jsontext.String("settings_enable_connect_protocol")) + h.WriteToken(jsontext.String("value")) + h.WriteToken(jsontext.Bool(*f.ExtendedConnect)) + h.WriteToken(jsontext.EndObject) + } + if len(f.Other) > 0 { + for k, v := range f.Other { + h.WriteToken(jsontext.BeginObject) + h.WriteToken(jsontext.String("name")) + h.WriteToken(jsontext.String("unknown")) + h.WriteToken(jsontext.String("name_bytes")) + h.WriteToken(jsontext.Uint(k)) + h.WriteToken(jsontext.String("value")) + h.WriteToken(jsontext.Uint(v)) + h.WriteToken(jsontext.EndObject) + } + } + h.WriteToken(jsontext.EndArray) + h.WriteToken(jsontext.EndObject) + return h.err +} diff --git a/http3/qlog/frame_test.go b/http3/qlog/frame_test.go index 2901a3679..872f87d25 100644 --- a/http3/qlog/frame_test.go +++ b/http3/qlog/frame_test.go @@ -77,3 +77,70 @@ func TestGoAwayFrame(t *testing.T) { "id": 1337, }) } + +func pointer[T any](v T) *T { + return &v +} + +func TestSettingsFrame(t *testing.T) { + tests := []struct { + name string + frame SettingsFrame + expected map[string]any + }{ + { + name: "datagram: true", + frame: SettingsFrame{Datagram: pointer(true)}, + expected: map[string]any{ + "frame_type": "settings", + "settings": []map[string]any{{ + "name": "settings_h3_datagram", + "value": true, + }}, + }, + }, + { + name: "extended_connect: false", + frame: SettingsFrame{ExtendedConnect: pointer(false)}, + expected: map[string]any{ + "frame_type": "settings", + "settings": []map[string]any{{ + "name": "settings_enable_connect_protocol", + "value": false, + }}, + }, + }, + { + name: "datagram: false, extended_connect: false", + frame: SettingsFrame{Datagram: pointer(false), ExtendedConnect: pointer(false)}, + expected: map[string]any{ + "frame_type": "settings", + "settings": []map[string]any{ + {"name": "settings_h3_datagram", "value": false}, + {"name": "settings_enable_connect_protocol", "value": false}, + }, + }, + }, + { + name: "unknowns", + // Only test a single unknown setting. + // Testing multiple unknown settings doesn't add a lot of value, + // and would require us to deal with non-deterministic map iteration order. + frame: SettingsFrame{Other: map[uint64]uint64{0xdead: 0xbeef}}, + expected: map[string]any{ + "frame_type": "settings", + "settings": []map[string]any{{ + "name": "unknown", + "name_bytes": float64(0xdead), + "value": float64(0xbeef), + }}, + }, + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + check(t, tc.frame, tc.expected) + }) + } +} diff --git a/http3/server.go b/http3/server.go index 002f16f27..cdf69240e 100644 --- a/http3/server.go +++ b/http3/server.go @@ -7,6 +7,7 @@ import ( "fmt" "io" "log/slog" + "maps" "net" "net/http" "runtime" @@ -439,6 +440,11 @@ func (s *Server) removeListener(l *QUICListener) { // handleConn handles the HTTP/3 exchange on a QUIC connection. // It blocks until all HTTP handlers for all streams have returned. func (s *Server) handleConn(conn *quic.Conn) error { + var qlogger qlogwriter.Recorder + if qlogTrace := conn.QlogTrace(); qlogTrace != nil { + qlogger = qlogTrace.AddProducer() + } + // open the control stream and send a SETTINGS frame, it's also used to send a GOAWAY frame later // when the server is gracefully closed ctrlStr, err := conn.OpenUniStream() @@ -452,6 +458,20 @@ func (s *Server) handleConn(conn *quic.Conn) error { ExtendedConnect: true, Other: s.AdditionalSettings, }).Append(b) + if qlogger != nil { + sf := qlog.SettingsFrame{ + ExtendedConnect: pointer(true), + Other: maps.Clone(s.AdditionalSettings), + } + if s.EnableDatagrams { + sf.Datagram = pointer(true) + } + qlogger.RecordEvent(qlog.FrameCreated{ + StreamID: ctrlStr.StreamID(), + Raw: qlog.RawInfo{Length: len(b)}, + Frame: qlog.Frame{Frame: sf}, + }) + } ctrlStr.Write(b) connCtx := conn.Context() @@ -465,11 +485,6 @@ func (s *Server) handleConn(conn *quic.Conn) error { } } - var qlogger qlogwriter.Recorder - if qlogTrace := conn.QlogTrace(); qlogTrace != nil { - qlogger = qlogTrace.AddProducer() - } - hconn := newConnection( connCtx, conn, diff --git a/http3/server_test.go b/http3/server_test.go index 2cc9fd9f6..027d5e679 100644 --- a/http3/server_test.go +++ b/http3/server_test.go @@ -131,9 +131,9 @@ func TestServerRequestHandling(t *testing.T) { require.Contains(t, fp.Frame.Frame.(qlog.HeadersFrame).HeaderFields, qlog.HeaderField{Name: ":method", Value: "GET"}) require.Contains(t, fp.Frame.Frame.(qlog.HeadersFrame).HeaderFields, qlog.HeaderField{Name: ":authority", Value: "www.example.com"}) - require.Len(t, eventRecorder.Events(qlog.FrameCreated{}), 1) - require.IsType(t, qlog.HeadersFrame{}, eventRecorder.Events(qlog.FrameCreated{})[0].(qlog.FrameCreated).Frame.Frame) - fc := eventRecorder.Events(qlog.FrameCreated{})[0].(qlog.FrameCreated) + events := filterQlogEventsForFrame(eventRecorder.Events(qlog.FrameCreated{}), qlog.HeadersFrame{}) + require.Len(t, events, 1) + fc := events[0].(qlog.FrameCreated) require.Equal(t, quic.StreamID(0), fp.StreamID) require.NotZero(t, fc.Raw.PayloadLength) require.Contains(t, fc.Frame.Frame.(qlog.HeadersFrame).HeaderFields, qlog.HeaderField{Name: ":status", Value: "200"})