http3: qlog sent and received SETTINGS frames (#5379)

* http3: implement qlog serialization for SETTINGS frames

* http3: qlog sent and received SETTINGS frames
This commit is contained in:
Marten Seemann
2025-10-12 13:16:37 +08:00
committed by GitHub
parent cd4b1307db
commit ce12204bc3
9 changed files with 238 additions and 24 deletions

View File

@@ -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
}

View File

@@ -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 {

View File

@@ -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}),
)
}

View File

@@ -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
}

View File

@@ -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
}

View File

@@ -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
}

View File

@@ -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)
})
}
}

View File

@@ -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,

View File

@@ -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"})