]> git.feebdaed.xyz Git - 0xmirror/quic-go.git/commitdiff
http3: add basic server-side qlog support (#5367)
authorMarten Seemann <martenseemann@gmail.com>
Fri, 10 Oct 2025 10:35:58 +0000 (18:35 +0800)
committerGitHub <noreply@github.com>
Fri, 10 Oct 2025 10:35:58 +0000 (12:35 +0200)
* add Conn.QlogTrace

* http3: add basic qlog support on the server side

20 files changed:
.golangci.yml
connection.go
http3/client_test.go
http3/conn.go
http3/http3_helper_test.go
http3/qlog.go [new file with mode: 0644]
http3/qlog/event.go [new file with mode: 0644]
http3/qlog/event_test.go [new file with mode: 0644]
http3/qlog/frame.go [new file with mode: 0644]
http3/qlog/frame_test.go [new file with mode: 0644]
http3/response_writer.go
http3/response_writer_test.go
http3/server.go
http3/server_test.go
http3/stream.go
http3/stream_test.go
server.go
server_test.go
transport.go
transport_test.go

index 4a97047bafdfd5c12a2d139eb2596129e386d6fe..cd2a3f87f56ed7cb5d03329bbc3187b0970479c1 100644 (file)
@@ -53,6 +53,8 @@ linters:
           deny:
             - pkg: 'github.com/quic-go/quic-go/internal'
               desc: 'no dependency on quic-go/internal'
+          allow:
+            - 'github.com/quic-go/quic-go/internal/synctest'
     misspell:
       ignore-rules:
         - ect
index 1d2b9ab573fbd984012256d92f017e95611b4f0b..fde440485b00770c6c9c8ffb91fce2a5eafd9cd7 100644 (file)
@@ -221,9 +221,10 @@ type Conn struct {
        connStateMutex sync.Mutex
        connState      ConnectionState
 
-       logID   string
-       qlogger qlogwriter.Recorder
-       logger  utils.Logger
+       logID     string
+       qlogTrace qlogwriter.Trace
+       qlogger   qlogwriter.Recorder
+       logger    utils.Logger
 }
 
 var _ streamSender = &Conn{}
@@ -260,7 +261,7 @@ var newConnection = func(
        tokenGenerator *handshake.TokenGenerator,
        clientAddressValidated bool,
        rtt time.Duration,
-       qlogger qlogwriter.Recorder,
+       qlogTrace qlogwriter.Trace,
        logger utils.Logger,
        v protocol.Version,
 ) *wrappedConn {
@@ -274,10 +275,13 @@ var newConnection = func(
                tokenGenerator:      tokenGenerator,
                oneRTTStream:        newCryptoStream(),
                perspective:         protocol.PerspectiveServer,
-               qlogger:             qlogger,
+               qlogTrace:           qlogTrace,
                logger:              logger,
                version:             v,
        }
+       if qlogTrace != nil {
+               s.qlogger = qlogTrace.AddProducer()
+       }
        if origDestConnID.Len() > 0 {
                s.logID = origDestConnID.String()
        } else {
@@ -356,7 +360,7 @@ var newConnection = func(
                tlsConf,
                conf.Allow0RTT,
                s.rttStats,
-               qlogger,
+               s.qlogger,
                logger,
                s.version,
        )
@@ -381,7 +385,7 @@ var newClientConnection = func(
        initialPacketNumber protocol.PacketNumber,
        enable0RTT bool,
        hasNegotiatedVersion bool,
-       qlogger qlogwriter.Recorder,
+       qlogTrace qlogwriter.Trace,
        logger utils.Logger,
        v protocol.Version,
 ) *wrappedConn {
@@ -394,10 +398,28 @@ var newClientConnection = func(
                perspective:         protocol.PerspectiveClient,
                logID:               destConnID.String(),
                logger:              logger,
-               qlogger:             qlogger,
+               qlogTrace:           qlogTrace,
                versionNegotiated:   hasNegotiatedVersion,
                version:             v,
        }
+       if qlogTrace != nil {
+               s.qlogger = qlogTrace.AddProducer()
+       }
+       if s.qlogger != nil {
+               var srcAddr, destAddr *net.UDPAddr
+               if addr, ok := conn.LocalAddr().(*net.UDPAddr); ok {
+                       srcAddr = addr
+               }
+               if addr, ok := conn.RemoteAddr().(*net.UDPAddr); ok {
+                       destAddr = addr
+               }
+               s.qlogger.RecordEvent(qlog.StartedConnection{
+                       SrcAddr:          srcAddr,
+                       DestAddr:         destAddr,
+                       SrcConnectionID:  srcConnID,
+                       DestConnectionID: destConnID,
+               })
+       }
        s.connIDManager = newConnIDManager(
                destConnID,
                func(token protocol.StatelessResetToken) { runner.AddResetToken(token, s) },
@@ -466,7 +488,7 @@ var newClientConnection = func(
                tlsConf,
                enable0RTT,
                s.rttStats,
-               qlogger,
+               s.qlogger,
                logger,
                s.version,
        )
@@ -3039,6 +3061,12 @@ func (c *Conn) HandshakeComplete() <-chan struct{} {
        return c.handshakeCompleteChan
 }
 
+// QlogTrace returns the qlog trace of the QUIC connection.
+// It is nil if qlog is not enabled.
+func (c *Conn) QlogTrace() qlogwriter.Trace {
+       return c.qlogTrace
+}
+
 func (c *Conn) NextConnection(ctx context.Context) (*Conn, error) {
        // The handshake might fail after the server rejected 0-RTT.
        // This could happen if the Finished message is malformed or never received.
index 7386e5f83e1258dc74f55a4073ae06f564cff718..e05fc1ccd4c4eafde5cce0c95400c00b79b9cb44 100644 (file)
@@ -61,7 +61,7 @@ func encodeResponse(t *testing.T, status int) []byte {
        buf := &bytes.Buffer{}
        rstr := NewMockDatagramStream(mockCtrl)
        rstr.EXPECT().Write(gomock.Any()).Do(buf.Write).AnyTimes()
-       rw := newResponseWriter(newStream(rstr, nil, nil, func(r io.Reader, u uint64) error { return nil }), nil, false, nil)
+       rw := newResponseWriter(newStream(rstr, nil, nil, func(r io.Reader, u uint64) error { return nil }, nil), nil, false, nil)
        rw.WriteHeader(status)
        rw.Flush()
        return buf.Bytes()
@@ -326,7 +326,7 @@ func testClient1xxHandling(t *testing.T, numEarlyHints int, terminalStatus int,
        var rspBuf bytes.Buffer
        rstr := NewMockDatagramStream(gomock.NewController(t))
        rstr.EXPECT().Write(gomock.Any()).Do(rspBuf.Write).AnyTimes()
-       rw := newResponseWriter(newStream(rstr, nil, nil, func(r io.Reader, u uint64) error { return nil }), nil, false, nil)
+       rw := newResponseWriter(newStream(rstr, nil, nil, func(r io.Reader, u uint64) error { return nil }, nil), nil, false, nil)
        rw.header.Add("Link", "foo")
        rw.header.Add("Link", "bar")
        for range numEarlyHints {
@@ -405,7 +405,7 @@ func testClientGzip(t *testing.T,
        var rspBuf bytes.Buffer
        rstr := NewMockDatagramStream(gomock.NewController(t))
        rstr.EXPECT().Write(gomock.Any()).Do(rspBuf.Write).AnyTimes()
-       rw := newResponseWriter(newStream(rstr, nil, nil, func(r io.Reader, u uint64) error { return nil }), nil, false, nil)
+       rw := newResponseWriter(newStream(rstr, nil, nil, func(r io.Reader, u uint64) error { return nil }, nil), nil, false, nil)
        rw.WriteHeader(http.StatusOK)
        if responseAddContentEncoding {
                rw.header.Add("Content-Encoding", "gzip")
index 842664963c0e73a9f8302a04fd90252336afa1e4..4ca9a38593120a6fe59db937dc1c6aeee6e3fe71 100644 (file)
@@ -14,6 +14,7 @@ import (
        "time"
 
        "github.com/quic-go/quic-go"
+       "github.com/quic-go/quic-go/qlogwriter"
        "github.com/quic-go/quic-go/quicvarint"
 
        "github.com/quic-go/qpack"
@@ -51,6 +52,8 @@ type Conn struct {
 
        idleTimeout time.Duration
        idleTimer   *time.Timer
+
+       qlogger qlogwriter.Recorder
 }
 
 func newConnection(
@@ -61,6 +64,10 @@ func newConnection(
        logger *slog.Logger,
        idleTimeout time.Duration,
 ) *Conn {
+       var qlogger qlogwriter.Recorder
+       if qlogTrace := quicConn.QlogTrace(); qlogTrace != nil {
+               qlogger = qlogTrace.AddProducer()
+       }
        c := &Conn{
                ctx:              ctx,
                conn:             quicConn,
@@ -73,6 +80,7 @@ func newConnection(
                streams:          make(map[quic.StreamID]*stateTrackingStream),
                maxStreamID:      invalidStreamID,
                lastStreamID:     invalidStreamID,
+               qlogger:          qlogger,
        }
        if idleTimeout > 0 {
                c.idleTimer = time.AfterFunc(idleTimeout, c.onIdleTimer)
@@ -168,13 +176,13 @@ func (c *Conn) openRequestStream(
        trace := httptrace.ContextClientTrace(ctx)
        return newRequestStream(
                newStream(hstr, c, trace, func(r io.Reader, l uint64) error {
-                       hdr, err := c.decodeTrailers(r, l, maxHeaderBytes)
+                       hdr, err := c.decodeTrailers(r, str.StreamID(), l, maxHeaderBytes)
                        if err != nil {
                                return err
                        }
                        rsp.Trailer = hdr
                        return nil
-               }),
+               }, c.qlogger),
                requestWriter,
                reqDone,
                c.decoder,
@@ -184,8 +192,9 @@ func (c *Conn) openRequestStream(
        ), nil
 }
 
-func (c *Conn) decodeTrailers(r io.Reader, l, maxHeaderBytes uint64) (http.Header, error) {
+func (c *Conn) decodeTrailers(r io.Reader, streamID quic.StreamID, l, maxHeaderBytes uint64) (http.Header, error) {
        if l > maxHeaderBytes {
+               maybeQlogInvalidHeadersFrame(c.qlogger, streamID, l)
                return nil, fmt.Errorf("HEADERS frame too large: %d bytes (max: %d)", l, maxHeaderBytes)
        }
 
@@ -195,8 +204,12 @@ func (c *Conn) decodeTrailers(r io.Reader, l, maxHeaderBytes uint64) (http.Heade
        }
        fields, err := c.decoder.DecodeFull(b)
        if err != nil {
+               maybeQlogInvalidHeadersFrame(c.qlogger, streamID, l)
                return nil, err
        }
+       if c.qlogger != nil {
+               qlogParsedHeadersFrame(c.qlogger, streamID, l, fields)
+       }
        return parseTrailers(fields)
 }
 
index 2098d337e4ce97d4f48a43a90ba91b1d5237c42e..4e00ff55f187d7370c3ca9ee4ecceeb4841ea05b 100644 (file)
@@ -21,6 +21,7 @@ import (
 
        "github.com/quic-go/qpack"
        "github.com/quic-go/quic-go"
+       "github.com/quic-go/quic-go/qlogwriter"
 
        "github.com/stretchr/testify/require"
 )
@@ -132,19 +133,46 @@ func getTLSClientConfig() *tls.Config { return tlsClientConfig.Clone() }
 func newConnPair(t *testing.T) (client, server *quic.Conn) {
        t.Helper()
 
+       return newConnPairWithRecorder(t, nil, nil)
+}
+
+type qlogTrace struct {
+       recorder qlogwriter.Recorder
+}
+
+func (t *qlogTrace) AddProducer() qlogwriter.Recorder {
+       return t.recorder
+}
+
+func newConnPairWithRecorder(t *testing.T, clientRecorder, serverRecorder qlogwriter.Recorder) (client, server *quic.Conn) {
+       t.Helper()
+
        ln, err := quic.ListenEarly(
                newUDPConnLocalhost(t),
                getTLSConfig(),
                &quic.Config{
                        InitialStreamReceiveWindow:     maxByteCount,
                        InitialConnectionReceiveWindow: maxByteCount,
+                       Tracer: func(ctx context.Context, isClient bool, connID quic.ConnectionID) qlogwriter.Trace {
+                               return &qlogTrace{recorder: serverRecorder}
+                       },
                },
        )
        require.NoError(t, err)
 
        ctx, cancel := context.WithTimeout(context.Background(), time.Second)
        defer cancel()
-       cl, err := quic.DialEarly(ctx, newUDPConnLocalhost(t), ln.Addr(), getTLSClientConfig(), &quic.Config{})
+       cl, err := quic.DialEarly(
+               ctx,
+               newUDPConnLocalhost(t),
+               ln.Addr(),
+               getTLSClientConfig(),
+               &quic.Config{
+                       Tracer: func(ctx context.Context, isClient bool, connID quic.ConnectionID) qlogwriter.Trace {
+                               return &qlogTrace{recorder: clientRecorder}
+                       },
+               },
+       )
        require.NoError(t, err)
        t.Cleanup(func() { cl.CloseWithError(0, "") })
 
diff --git a/http3/qlog.go b/http3/qlog.go
new file mode 100644 (file)
index 0000000..ed7165a
--- /dev/null
@@ -0,0 +1,53 @@
+package http3
+
+import (
+       "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/qpack"
+)
+
+func maybeQlogInvalidHeadersFrame(qlogger qlogwriter.Recorder, streamID quic.StreamID, l uint64) {
+       if qlogger != nil {
+               qlogger.RecordEvent(qlog.FrameParsed{
+                       StreamID: streamID,
+                       Raw:      qlog.RawInfo{PayloadLength: int(l)},
+                       Frame:    qlog.Frame{Frame: qlog.HeadersFrame{}},
+               })
+       }
+}
+
+func qlogParsedHeadersFrame(qlogger qlogwriter.Recorder, streamID quic.StreamID, l uint64, hfs []qpack.HeaderField) {
+       headerFields := make([]qlog.HeaderField, len(hfs))
+       for i, hf := range hfs {
+               headerFields[i] = qlog.HeaderField{
+                       Name:  hf.Name,
+                       Value: hf.Value,
+               }
+       }
+       qlogger.RecordEvent(qlog.FrameParsed{
+               StreamID: streamID,
+               Raw:      qlog.RawInfo{PayloadLength: int(l)},
+               Frame: qlog.Frame{Frame: qlog.HeadersFrame{
+                       HeaderFields: headerFields,
+               }},
+       })
+}
+
+func qlogCreatedHeadersFrame(qlogger qlogwriter.Recorder, streamID quic.StreamID, length, payloadLength int, hfs []qlog.HeaderField) {
+       headerFields := make([]qlog.HeaderField, len(hfs))
+       for i, hf := range hfs {
+               headerFields[i] = qlog.HeaderField{
+                       Name:  hf.Name,
+                       Value: hf.Value,
+               }
+       }
+       qlogger.RecordEvent(qlog.FrameCreated{
+               StreamID: streamID,
+               Raw:      qlog.RawInfo{Length: length, PayloadLength: payloadLength},
+               Frame: qlog.Frame{Frame: qlog.HeadersFrame{
+                       HeaderFields: headerFields,
+               }},
+       })
+}
diff --git a/http3/qlog/event.go b/http3/qlog/event.go
new file mode 100644 (file)
index 0000000..d419376
--- /dev/null
@@ -0,0 +1,94 @@
+package qlog
+
+import (
+       "time"
+
+       "github.com/quic-go/quic-go"
+       "github.com/quic-go/quic-go/qlogwriter/jsontext"
+)
+
+type encoderHelper struct {
+       enc *jsontext.Encoder
+       err error
+}
+
+func (h *encoderHelper) WriteToken(t jsontext.Token) {
+       if h.err != nil {
+               return
+       }
+       h.err = h.enc.WriteToken(t)
+}
+
+type RawInfo struct {
+       Length        int // full packet length, including header and AEAD authentication tag
+       PayloadLength int // length of the packet payload, excluding AEAD tag
+}
+
+func (i RawInfo) encode(enc *jsontext.Encoder) error {
+       h := encoderHelper{enc: enc}
+       h.WriteToken(jsontext.BeginObject)
+       if i.Length != 0 {
+               h.WriteToken(jsontext.String("length"))
+               h.WriteToken(jsontext.Uint(uint64(i.Length)))
+       }
+       if i.PayloadLength != 0 {
+               h.WriteToken(jsontext.String("payload_length"))
+               h.WriteToken(jsontext.Uint(uint64(i.PayloadLength)))
+       }
+       h.WriteToken(jsontext.EndObject)
+       return h.err
+}
+
+type FrameParsed struct {
+       StreamID quic.StreamID
+       Raw      RawInfo
+       Frame    Frame
+}
+
+func (e FrameParsed) Name() string { return "http3:frame_parsed" }
+
+func (e FrameParsed) Encode(enc *jsontext.Encoder, _ time.Time) error {
+       h := encoderHelper{enc: enc}
+       h.WriteToken(jsontext.BeginObject)
+       h.WriteToken(jsontext.String("name"))
+       h.WriteToken(jsontext.String("frame_parsed"))
+       h.WriteToken(jsontext.String("stream_id"))
+       h.WriteToken(jsontext.Uint(uint64(e.StreamID)))
+       h.WriteToken(jsontext.String("raw"))
+       if err := e.Raw.encode(enc); err != nil {
+               return err
+       }
+       h.WriteToken(jsontext.String("frame"))
+       if err := e.Frame.Encode(enc); err != nil {
+               return err
+       }
+       h.WriteToken(jsontext.EndObject)
+       return h.err
+}
+
+type FrameCreated struct {
+       StreamID quic.StreamID
+       Raw      RawInfo
+       Frame    Frame
+}
+
+func (e FrameCreated) Name() string { return "http3:frame_created" }
+
+func (e FrameCreated) Encode(enc *jsontext.Encoder, _ time.Time) error {
+       h := encoderHelper{enc: enc}
+       h.WriteToken(jsontext.BeginObject)
+       h.WriteToken(jsontext.String("name"))
+       h.WriteToken(jsontext.String("frame_created"))
+       h.WriteToken(jsontext.String("stream_id"))
+       h.WriteToken(jsontext.Uint(uint64(e.StreamID)))
+       h.WriteToken(jsontext.String("raw"))
+       if err := e.Raw.encode(enc); err != nil {
+               return err
+       }
+       h.WriteToken(jsontext.String("frame"))
+       if err := e.Frame.Encode(enc); err != nil {
+               return err
+       }
+       h.WriteToken(jsontext.EndObject)
+       return h.err
+}
diff --git a/http3/qlog/event_test.go b/http3/qlog/event_test.go
new file mode 100644 (file)
index 0000000..8f7ba25
--- /dev/null
@@ -0,0 +1,98 @@
+package qlog
+
+import (
+       "bytes"
+       "encoding/json"
+       "io"
+       "testing"
+       "time"
+
+       "github.com/quic-go/quic-go"
+       "github.com/quic-go/quic-go/internal/synctest"
+       "github.com/quic-go/quic-go/qlogwriter"
+
+       "github.com/stretchr/testify/require"
+)
+
+type nopWriteCloserImpl struct{ io.Writer }
+
+func (nopWriteCloserImpl) Close() error { return nil }
+
+func nopWriteCloser(w io.Writer) io.WriteCloser {
+       return &nopWriteCloserImpl{Writer: w}
+}
+
+func testEventEncoding(t *testing.T, ev qlogwriter.Event) (string, map[string]any) {
+       t.Helper()
+       var buf bytes.Buffer
+
+       synctest.Test(t, func(t *testing.T) {
+               tr := qlogwriter.NewConnectionFileSeq(
+                       nopWriteCloser(&buf),
+                       true,
+                       quic.ConnectionIDFromBytes([]byte{1, 2, 3, 4}),
+                       []string{"http3"},
+               )
+               go tr.Run()
+               producer := tr.AddProducer()
+
+               synctest.Wait()
+               time.Sleep(42 * time.Second)
+
+               producer.RecordEvent(ev)
+               producer.Close()
+       })
+
+       return decode(t, buf.String())
+}
+
+func decode(t *testing.T, data string) (string, map[string]any) {
+       t.Helper()
+
+       var result map[string]any
+
+       lines := bytes.Split([]byte(data), []byte{'\n'})
+       require.Len(t, lines, 3) // the first line is the trace header, the second line is the event, the third line is empty
+       require.Empty(t, lines[2])
+       require.Equal(t, qlogwriter.RecordSeparator, lines[1][0], "expected record separator at start of line")
+       require.NoError(t, json.Unmarshal(lines[1][1:], &result))
+       require.Equal(t, 42*time.Second, time.Duration(result["time"].(float64)*1e6)*time.Nanosecond)
+
+       return result["name"].(string), result["data"].(map[string]any)
+}
+
+func TestFrameParsedEvent(t *testing.T) {
+       name, ev := testEventEncoding(t, FrameParsed{
+               StreamID: quic.StreamID(4),
+               Raw: RawInfo{
+                       Length:        1500,
+                       PayloadLength: 100,
+               },
+               Frame: Frame{Frame: &DataFrame{}},
+       })
+
+       require.Equal(t, "http3:frame_parsed", name)
+       require.Equal(t, float64(4), ev["stream_id"])
+       require.Equal(t, "frame_parsed", ev["name"])
+       require.Contains(t, ev, "frame")
+}
+
+func TestFrameCreatedEvent(t *testing.T) {
+       name, ev := testEventEncoding(t, FrameCreated{
+               StreamID: quic.StreamID(8),
+               Raw: RawInfo{
+                       PayloadLength: 200,
+               },
+               Frame: Frame{Frame: &HeadersFrame{
+                       HeaderFields: []HeaderField{
+                               {Name: ":status", Value: "200"},
+                               {Name: "content-type", Value: "text/html"},
+                       },
+               }},
+       })
+
+       require.Equal(t, "http3:frame_created", name)
+       require.Equal(t, float64(8), ev["stream_id"])
+       require.Equal(t, "frame_created", ev["name"])
+       require.Contains(t, ev, "frame")
+}
diff --git a/http3/qlog/frame.go b/http3/qlog/frame.go
new file mode 100644 (file)
index 0000000..8f8b9ef
--- /dev/null
@@ -0,0 +1,64 @@
+package qlog
+
+import (
+       "github.com/quic-go/quic-go/qlogwriter/jsontext"
+)
+
+// Frame represents an HTTP/3 frame.
+type Frame struct {
+       Frame any
+}
+
+func (f Frame) Encode(enc *jsontext.Encoder) error {
+       switch frame := f.Frame.(type) {
+       case *DataFrame:
+               return frame.encode(enc)
+       case *HeadersFrame:
+               return frame.encode(enc)
+       }
+       return nil
+}
+
+// A DataFrame is a DATA frame
+type DataFrame struct{}
+
+func (f *DataFrame) encode(enc *jsontext.Encoder) error {
+       h := encoderHelper{enc: enc}
+       h.WriteToken(jsontext.BeginObject)
+       h.WriteToken(jsontext.String("frame_type"))
+       h.WriteToken(jsontext.String("data"))
+       h.WriteToken(jsontext.EndObject)
+       return h.err
+}
+
+type HeaderField struct {
+       Name  string
+       Value string
+}
+
+// A HeadersFrame is a HEADERS frame
+type HeadersFrame struct {
+       HeaderFields []HeaderField
+}
+
+func (f *HeadersFrame) encode(enc *jsontext.Encoder) error {
+       h := encoderHelper{enc: enc}
+       h.WriteToken(jsontext.BeginObject)
+       h.WriteToken(jsontext.String("frame_type"))
+       h.WriteToken(jsontext.String("headers"))
+       if len(f.HeaderFields) > 0 {
+               h.WriteToken(jsontext.String("header_fields"))
+               h.WriteToken(jsontext.BeginArray)
+               for _, f := range f.HeaderFields {
+                       h.WriteToken(jsontext.BeginObject)
+                       h.WriteToken(jsontext.String("name"))
+                       h.WriteToken(jsontext.String(f.Name))
+                       h.WriteToken(jsontext.String("value"))
+                       h.WriteToken(jsontext.String(f.Value))
+                       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
new file mode 100644 (file)
index 0000000..977ee95
--- /dev/null
@@ -0,0 +1,72 @@
+package qlog
+
+import (
+       "bytes"
+       "encoding/json"
+       "testing"
+
+       "github.com/quic-go/quic-go/qlogwriter/jsontext"
+
+       "github.com/stretchr/testify/require"
+)
+
+func check(t *testing.T, f any, expected map[string]any) {
+       var buf bytes.Buffer
+       enc := jsontext.NewEncoder(&buf)
+       require.NoError(t, (Frame{Frame: f}).Encode(enc))
+       data := buf.Bytes()
+       require.True(t, json.Valid(data), "invalid JSON: %s", string(data))
+       checkEncoding(t, data, expected)
+}
+
+func checkEncoding(t *testing.T, data []byte, expected map[string]any) {
+       t.Helper()
+
+       m := make(map[string]any)
+       require.NoError(t, json.Unmarshal(data, &m))
+       require.Len(t, m, len(expected))
+
+       for key, value := range expected {
+               switch v := value.(type) {
+               case bool, string, map[string]any:
+                       require.Equal(t, v, m[key])
+               case int:
+                       require.Equal(t, float64(v), m[key])
+               case float64:
+                       require.Equal(t, v, m[key])
+               case []map[string]any: // used for header fields
+                       require.Contains(t, m, key)
+                       slice, ok := m[key].([]any)
+                       require.True(t, ok)
+                       require.Len(t, slice, len(v))
+                       for i, expectedField := range v {
+                               field, ok := slice[i].(map[string]any)
+                               require.True(t, ok)
+                               require.Equal(t, expectedField, field)
+                       }
+               default:
+                       t.Fatalf("unexpected type: %T", v)
+               }
+       }
+}
+
+func TestDataFrame(t *testing.T) {
+       check(t, &DataFrame{}, map[string]any{
+               "frame_type": "data",
+       })
+}
+
+func TestHeadersFrame(t *testing.T) {
+       check(t, &HeadersFrame{
+               HeaderFields: []HeaderField{
+                       {Name: ":status", Value: "200"},
+                       {Name: "content-type", Value: "application/json"},
+               },
+       }, map[string]any{
+               "frame_type": "headers",
+               "header_fields": []map[string]any{
+                       {"name": ":status", "value": "200"},
+                       {"name": "content-type", "value": "application/json"},
+               },
+       })
+}
index 5dc0ad3013ba90464f85210864061f266675a7f2..ed22ca2461e51d031e3b1f223bf6ba8a0d6251fc 100644 (file)
@@ -11,6 +11,8 @@ import (
        "time"
 
        "github.com/quic-go/qpack"
+       "github.com/quic-go/quic-go/http3/qlog"
+
        "golang.org/x/net/http/httpguts"
 )
 
@@ -181,6 +183,13 @@ func (w *responseWriter) doWrite(p []byte) (int, error) {
        df := &dataFrame{Length: l}
        w.buf = w.buf[:0]
        w.buf = df.Append(w.buf)
+       if w.str.qlogger != nil {
+               w.str.qlogger.RecordEvent(qlog.FrameCreated{
+                       StreamID: w.str.StreamID(),
+                       Raw:      qlog.RawInfo{Length: len(w.buf) + int(l), PayloadLength: int(l)},
+                       Frame:    qlog.Frame{Frame: qlog.DataFrame{}},
+               })
+       }
        if _, err := w.str.writeUnframed(w.buf); err != nil {
                return 0, maybeReplaceError(err)
        }
@@ -202,11 +211,15 @@ func (w *responseWriter) doWrite(p []byte) (int, error) {
 }
 
 func (w *responseWriter) writeHeader(status int) error {
+       var headerFields []qlog.HeaderField // only used for qlog
        var headers bytes.Buffer
        enc := qpack.NewEncoder(&headers)
        if err := enc.WriteField(qpack.HeaderField{Name: ":status", Value: strconv.Itoa(status)}); err != nil {
                return err
        }
+       if w.str.qlogger != nil {
+               headerFields = append(headerFields, qlog.HeaderField{Name: ":status", Value: strconv.Itoa(status)})
+       }
 
        // Handle trailer fields
        if vals, ok := w.header["Trailer"]; ok {
@@ -229,9 +242,14 @@ func (w *responseWriter) writeHeader(status int) error {
                        continue
                }
                for index := range v {
-                       if err := enc.WriteField(qpack.HeaderField{Name: strings.ToLower(k), Value: v[index]}); err != nil {
+                       name := strings.ToLower(k)
+                       value := v[index]
+                       if err := enc.WriteField(qpack.HeaderField{Name: name, Value: value}); err != nil {
                                return err
                        }
+                       if w.str.qlogger != nil {
+                               headerFields = append(headerFields, qlog.HeaderField{Name: name, Value: value})
+                       }
                }
        }
 
@@ -239,6 +257,10 @@ func (w *responseWriter) writeHeader(status int) error {
        buf = (&headersFrame{Length: uint64(headers.Len())}).Append(buf)
        buf = append(buf, headers.Bytes()...)
 
+       if w.str.qlogger != nil {
+               qlogCreatedHeadersFrame(w.str.qlogger, w.str.StreamID(), len(buf), headers.Len(), headerFields)
+       }
+
        _, err := w.str.writeUnframed(buf)
        return err
 }
@@ -311,6 +333,7 @@ func (w *responseWriter) writeTrailers() error {
        }
 
        var b bytes.Buffer
+       var headerFields []qlog.HeaderField
        enc := qpack.NewEncoder(&b)
        for trailer := range w.trailers {
                trailerName := strings.ToLower(strings.TrimPrefix(trailer, http.TrailerPrefix))
@@ -319,6 +342,9 @@ func (w *responseWriter) writeTrailers() error {
                                if err := enc.WriteField(qpack.HeaderField{Name: trailerName, Value: val}); err != nil {
                                        return err
                                }
+                               if w.str.qlogger != nil {
+                                       headerFields = append(headerFields, qlog.HeaderField{Name: trailerName, Value: val})
+                               }
                        }
                }
        }
@@ -326,6 +352,9 @@ func (w *responseWriter) writeTrailers() error {
        buf := make([]byte, 0, frameHeaderLen+b.Len())
        buf = (&headersFrame{Length: uint64(b.Len())}).Append(buf)
        buf = append(buf, b.Bytes()...)
+       if w.str.qlogger != nil {
+               qlogCreatedHeadersFrame(w.str.qlogger, w.str.StreamID(), len(buf), b.Len(), headerFields)
+       }
        _, err := w.str.writeUnframed(buf)
        w.trailerWritten = true
        return err
index 0247b6cbcba86bab3c1ace5f92dc617e8995939e..e98473d15bdfa7a302575d4f4883c46397c7aabf 100644 (file)
@@ -6,18 +6,24 @@ import (
        "net/http"
        "testing"
 
+       "github.com/quic-go/quic-go"
+       "github.com/quic-go/quic-go/http3/qlog"
+       "github.com/quic-go/quic-go/testutils/events"
+
        "github.com/quic-go/qpack"
 
+       "github.com/stretchr/testify/assert"
        "github.com/stretchr/testify/require"
        "go.uber.org/mock/gomock"
 )
 
 type testResponseWriter struct {
        *responseWriter
-       buf *bytes.Buffer
+       eventRecorder *events.Recorder
+       buf           *bytes.Buffer
 }
 
-func (rw *testResponseWriter) DecodeHeaders(t *testing.T) map[string][]string {
+func (rw *testResponseWriter) DecodeHeaders(t *testing.T, idx int) map[string][]string {
        t.Helper()
 
        rw.Flush()
@@ -25,17 +31,34 @@ func (rw *testResponseWriter) DecodeHeaders(t *testing.T) map[string][]string {
        fields := make(map[string][]string)
        decoder := qpack.NewDecoder(nil)
 
+       startLen := rw.buf.Len()
        frame, err := (&frameParser{r: rw.buf}).ParseNext()
        require.NoError(t, err)
        require.IsType(t, &headersFrame{}, frame)
-       data := make([]byte, frame.(*headersFrame).Length)
+       payloadLen := frame.(*headersFrame).Length
+       data := make([]byte, payloadLen)
+       headerFrameLen := startLen - rw.buf.Len() + len(data)
        _, err = io.ReadFull(rw.buf, data)
        require.NoError(t, err)
        hfs, err := decoder.DecodeFull(data)
        require.NoError(t, err)
+
+       // check that the decoded header fields are properly logged
+       require.GreaterOrEqual(t, len(rw.eventRecorder.Events(qlog.FrameCreated{})), idx+1)
+       require.IsType(t, qlog.HeadersFrame{}, rw.eventRecorder.Events()[idx].(qlog.FrameCreated).Frame.Frame)
+       ev := rw.eventRecorder.Events()[idx].(qlog.FrameCreated)
+       assert.Equal(t, quic.StreamID(42), ev.StreamID)
+       assert.Equal(t, headerFrameLen, ev.Raw.Length, "raw.Length")
+       assert.Equal(t, int(payloadLen), ev.Raw.PayloadLength, "raw.PayloadLength")
+
        for _, p := range hfs {
                fields[p.Name] = append(fields[p.Name], p.Value)
+               require.Contains(t,
+                       ev.Frame.Frame.(qlog.HeadersFrame).HeaderFields,
+                       qlog.HeaderField{Name: p.Name, Value: p.Value},
+               )
        }
+
        return fields
 }
 
@@ -55,14 +78,25 @@ func (rw *testResponseWriter) DecodeBody(t *testing.T) []byte {
 }
 
 func newTestResponseWriter(t *testing.T) *testResponseWriter {
+       var eventRecorder events.Recorder
        buf := &bytes.Buffer{}
        mockCtrl := gomock.NewController(t)
        str := NewMockDatagramStream(mockCtrl)
+       str.EXPECT().StreamID().Return(quic.StreamID(42)).AnyTimes()
        str.EXPECT().Write(gomock.Any()).DoAndReturn(buf.Write).AnyTimes()
        str.EXPECT().SetReadDeadline(gomock.Any()).Return(nil).AnyTimes()
        str.EXPECT().SetWriteDeadline(gomock.Any()).Return(nil).AnyTimes()
-       rw := newResponseWriter(newStream(str, nil, nil, func(r io.Reader, u uint64) error { return nil }), nil, false, nil)
-       return &testResponseWriter{responseWriter: rw, buf: buf}
+       rw := newResponseWriter(
+               newStream(str, nil, nil, func(r io.Reader, u uint64) error { return nil }, &eventRecorder),
+               nil,
+               false,
+               nil,
+       )
+       return &testResponseWriter{
+               responseWriter: rw,
+               eventRecorder:  &eventRecorder,
+               buf:            buf,
+       }
 }
 
 func TestResponseWriterInvalidStatus(t *testing.T) {
@@ -84,7 +118,7 @@ func TestResponseWriterHeader(t *testing.T) {
        // write some data
        rw.Write([]byte("foobar"))
 
-       fields := rw.DecodeHeaders(t)
+       fields := rw.DecodeHeaders(t, 0)
        require.Equal(t, []string{"418"}, fields[":status"])
        require.Equal(t, []string{"42"}, fields["content-length"])
        require.Equal(t,
@@ -98,7 +132,7 @@ func TestResponseWriterDataWithoutHeader(t *testing.T) {
        rw := newTestResponseWriter(t)
        rw.Write([]byte("foobar"))
 
-       fields := rw.DecodeHeaders(t)
+       fields := rw.DecodeHeaders(t, 0)
        require.Equal(t, []string{"200"}, fields[":status"])
        require.Equal(t, []byte("foobar"), rw.DecodeBody(t))
 }
@@ -110,7 +144,7 @@ func TestResponseWriterDataStatusWithoutBody(t *testing.T) {
        require.Zero(t, n)
        require.ErrorIs(t, err, http.ErrBodyNotAllowed)
 
-       fields := rw.DecodeHeaders(t)
+       fields := rw.DecodeHeaders(t, 0)
        require.Equal(t, []string{"304"}, fields[":status"])
        require.Empty(t, rw.DecodeBody(t))
 }
@@ -126,7 +160,7 @@ func TestResponseWriterContentLength(t *testing.T) {
        require.Zero(t, n)
        require.ErrorIs(t, err, http.ErrContentLength)
 
-       fields := rw.DecodeHeaders(t)
+       fields := rw.DecodeHeaders(t, 0)
        require.Equal(t, []string{"200"}, fields[":status"])
        require.Equal(t, []string{"6"}, fields["content-length"])
        require.Equal(t, []byte("foobar"), rw.DecodeBody(t))
@@ -153,7 +187,7 @@ func testContentTypeSniffing(t *testing.T, hdrs map[string]string, expectedConte
        }
        rw.Write([]byte("<html></html>"))
 
-       fields := rw.DecodeHeaders(t)
+       fields := rw.DecodeHeaders(t, 0)
        require.Equal(t, []string{"200"}, fields[":status"])
        if expectedContentType == "" {
                require.NotContains(t, fields, "content-type")
@@ -173,7 +207,7 @@ func TestResponseWriterEarlyHints(t *testing.T) {
        require.NoError(t, err)
 
        // Early Hints must have been received
-       fields := rw.DecodeHeaders(t)
+       fields := rw.DecodeHeaders(t, 0)
        require.Equal(t, 2, len(fields))
        require.Equal(t, []string{"103"}, fields[":status"])
        require.Equal(t,
@@ -182,7 +216,7 @@ func TestResponseWriterEarlyHints(t *testing.T) {
        )
 
        // headers sent in the informational response must also be included in the final response
-       fields = rw.DecodeHeaders(t)
+       fields = rw.DecodeHeaders(t, 1)
        require.Equal(t, 4, len(fields))
        require.Equal(t, []string{"200"}, fields[":status"])
        require.Contains(t, fields, "date")
@@ -204,7 +238,7 @@ func TestResponseWriterTrailers(t *testing.T) {
        require.NoError(t, err)
 
        // writeTrailers needs to be called after writing the full body
-       headers := rw.DecodeHeaders(t)
+       headers := rw.DecodeHeaders(t, 0)
        require.Equal(t, []string{"key"}, headers["trailer"])
        require.NotContains(t, headers, "foo")
        require.Equal(t, []byte("foobar"), rw.DecodeBody(t))
@@ -215,7 +249,7 @@ func TestResponseWriterTrailers(t *testing.T) {
        rw.Header().Set(http.TrailerPrefix+"lorem", "ipsum") // unannounced trailer with trailer prefix
        require.NoError(t, rw.writeTrailers())
 
-       trailers := rw.DecodeHeaders(t)
+       trailers := rw.DecodeHeaders(t, 2)
        require.Equal(t, []string{"value"}, trailers["key"])
        require.Equal(t, []string{"ipsum"}, trailers["lorem"])
        // trailers without the trailer prefix that were not announced are ignored
index cb53c44a7787f7d2088ed152a3d29a4d0fe55ae8..60fccc8459e3ec719f291b22c0a82c535babeb3f 100644 (file)
@@ -18,6 +18,7 @@ import (
        "time"
 
        "github.com/quic-go/quic-go"
+       "github.com/quic-go/quic-go/qlogwriter"
        "github.com/quic-go/quic-go/quicvarint"
 
        "github.com/quic-go/qpack"
@@ -463,6 +464,11 @@ 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,
@@ -535,7 +541,7 @@ func (s *Server) handleConn(conn *quic.Conn) error {
                        // handleRequest will return once the request has been handled,
                        // or the underlying connection is closed
                        defer wg.Done()
-                       s.handleRequest(hconn, str, hconn.decoder)
+                       s.handleRequest(hconn, str, hconn.decoder, qlogger)
                }()
        }
        wg.Wait()
@@ -549,7 +555,12 @@ func (s *Server) maxHeaderBytes() uint64 {
        return uint64(s.MaxHeaderBytes)
 }
 
-func (s *Server) handleRequest(conn *Conn, str datagramStream, decoder *qpack.Decoder) {
+func (s *Server) handleRequest(
+       conn *Conn,
+       str datagramStream,
+       decoder *qpack.Decoder,
+       qlogger qlogwriter.Recorder,
+) {
        var ufh unknownFrameHandlerFunc
        if s.StreamHijacker != nil {
                ufh = func(ft FrameType, e error) (processed bool, err error) {
@@ -576,12 +587,14 @@ func (s *Server) handleRequest(conn *Conn, str datagramStream, decoder *qpack.De
                return
        }
        if hf.Length > s.maxHeaderBytes() {
+               maybeQlogInvalidHeadersFrame(qlogger, str.StreamID(), hf.Length)
                str.CancelRead(quic.StreamErrorCode(ErrCodeFrameError))
                str.CancelWrite(quic.StreamErrorCode(ErrCodeFrameError))
                return
        }
        headerBlock := make([]byte, hf.Length)
        if _, err := io.ReadFull(str, headerBlock); err != nil {
+               maybeQlogInvalidHeadersFrame(qlogger, str.StreamID(), hf.Length)
                str.CancelRead(quic.StreamErrorCode(ErrCodeRequestIncomplete))
                str.CancelWrite(quic.StreamErrorCode(ErrCodeRequestIncomplete))
                return
@@ -592,6 +605,9 @@ func (s *Server) handleRequest(conn *Conn, str datagramStream, decoder *qpack.De
                conn.CloseWithError(quic.ApplicationErrorCode(ErrCodeGeneralProtocolError), "expected first frame to be a HEADERS frame")
                return
        }
+       if qlogger != nil {
+               qlogParsedHeadersFrame(qlogger, str.StreamID(), hf.Length, hfs)
+       }
        req, err := requestFromHeaders(hfs)
        if err != nil {
                str.CancelRead(quic.StreamErrorCode(ErrCodeMessageError))
@@ -609,7 +625,7 @@ func (s *Server) handleRequest(conn *Conn, str datagramStream, decoder *qpack.De
        if _, ok := req.Header["Content-Length"]; ok && req.ContentLength >= 0 {
                contentLength = req.ContentLength
        }
-       hstr := newStream(str, conn, nil, nil)
+       hstr := newStream(str, conn, nil, nil, qlogger)
        body := newRequestBody(hstr, contentLength, conn.Context(), conn.ReceivedSettings(), conn.Settings)
        req.Body = body
 
index b39993a0c5def4a84b73e1e6727d47263a1df1b3..57e1814703a90bd1d30486eaa8ea2eb20b4087f1 100644 (file)
@@ -16,7 +16,10 @@ import (
 
        "github.com/quic-go/quic-go"
        "github.com/quic-go/quic-go/http3/internal/testdata"
+       "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"
@@ -111,12 +114,29 @@ func testServerSettings(t *testing.T, enableDatagrams bool, other map[uint64]uin
 
 func TestServerRequestHandling(t *testing.T) {
        t.Run("200 with an empty handler", func(t *testing.T) {
+               var eventRecorder events.Recorder
                hfs, body := testServerRequestHandling(t,
                        func(w http.ResponseWriter, r *http.Request) {},
                        httptest.NewRequest(http.MethodGet, "https://www.example.com", nil),
+                       &eventRecorder,
                )
                require.Equal(t, hfs[":status"], []string{"200"})
                require.Empty(t, body)
+
+               require.Len(t, eventRecorder.Events(qlog.FrameParsed{}), 1)
+               require.IsType(t, qlog.HeadersFrame{}, eventRecorder.Events(qlog.FrameParsed{})[0].(qlog.FrameParsed).Frame.Frame)
+               fp := eventRecorder.Events(qlog.FrameParsed{})[0].(qlog.FrameParsed)
+               require.Equal(t, quic.StreamID(0), fp.StreamID)
+               require.NotZero(t, fp.Raw.PayloadLength)
+               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)
+               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"})
        })
 
        t.Run("content-length", func(t *testing.T) {
@@ -126,6 +146,7 @@ func TestServerRequestHandling(t *testing.T) {
                                w.Write([]byte("foobar"))
                        },
                        httptest.NewRequest(http.MethodGet, "https://www.example.com", nil),
+                       nil,
                )
                require.Equal(t, hfs[":status"], []string{"418"})
                require.Equal(t, hfs["content-length"], []string{"6"})
@@ -140,6 +161,7 @@ func TestServerRequestHandling(t *testing.T) {
                                w.Write([]byte("bar"))
                        },
                        httptest.NewRequest(http.MethodGet, "https://www.example.com", nil),
+                       nil,
                )
                require.Equal(t, hfs[":status"], []string{"200"})
                require.NotContains(t, hfs, "content-length")
@@ -152,6 +174,7 @@ func TestServerRequestHandling(t *testing.T) {
                                w.Write([]byte("foobar"))
                        },
                        httptest.NewRequest(http.MethodHead, "https://www.example.com", nil),
+                       nil,
                )
                require.Equal(t, hfs[":status"], []string{"200"})
                require.Empty(t, body)
@@ -165,6 +188,7 @@ func TestServerRequestHandling(t *testing.T) {
                                w.Write(data)
                        },
                        httptest.NewRequest(http.MethodPost, "https://www.example.com", bytes.NewBuffer([]byte("foobar"))),
+                       nil,
                )
                require.Equal(t, hfs[":status"], []string{"418"})
                require.Equal(t, []byte("foobar"), body)
@@ -174,8 +198,9 @@ func TestServerRequestHandling(t *testing.T) {
 func testServerRequestHandling(t *testing.T,
        handler http.HandlerFunc,
        req *http.Request,
+       rec qlogwriter.Recorder,
 ) (responseHeaders map[string][]string, body []byte) {
-       clientConn, serverConn := newConnPair(t)
+       clientConn, serverConn := newConnPairWithRecorder(t, nil, rec)
        str, err := clientConn.OpenStream()
        require.NoError(t, err)
        _, err = str.Write(encodeRequest(t, req))
@@ -263,7 +288,6 @@ func testServerHandlerBodyNotRead(t *testing.T, req *http.Request, handler http.
        require.NoError(t, err)
        _, err = str.Write(encodeRequest(t, req))
        require.NoError(t, err)
-       // require.NoError(t, str.Close())
 
        done := make(chan struct{})
        s := &Server{
@@ -343,24 +367,39 @@ func testServerPanickingHandler(t *testing.T, handler http.HandlerFunc) (logOutp
 
 func TestServerRequestHeaderTooLarge(t *testing.T) {
        t.Run("default value", func(t *testing.T) {
+               var eventRecorder events.Recorder
                // use 2*DefaultMaxHeaderBytes here. qpack will compress the request,
                // but the request will still end up larger than DefaultMaxHeaderBytes.
                url := bytes.Repeat([]byte{'a'}, http.DefaultMaxHeaderBytes*2)
                testServerRequestHeaderTooLarge(t,
                        httptest.NewRequest(http.MethodGet, "https://"+string(url), nil),
                        0,
+                       &eventRecorder,
                )
+               events := eventRecorder.Events(qlog.FrameParsed{})
+               require.Len(t, events, 1)
+               require.Equal(t, qlog.HeadersFrame{}, events[0].(qlog.FrameParsed).Frame.Frame)
+               // The request is QPACK-compressed, so it will be smaller than 2*http.DefaultMaxHeaderBytes
+               require.Greater(t, events[0].(qlog.FrameParsed).Raw.PayloadLength, http.DefaultMaxHeaderBytes)
+               require.Less(t, events[0].(qlog.FrameParsed).Raw.PayloadLength, http.DefaultMaxHeaderBytes*2)
        })
 
        t.Run("custom value", func(t *testing.T) {
+               var eventRecorder events.Recorder
                testServerRequestHeaderTooLarge(t,
                        httptest.NewRequest(http.MethodGet, "https://www.example.com", nil),
                        20,
+                       &eventRecorder,
                )
+               events := eventRecorder.Events(qlog.FrameParsed{})
+               require.Len(t, events, 1)
+               require.Equal(t, qlog.HeadersFrame{}, events[0].(qlog.FrameParsed).Frame.Frame)
+               require.Greater(t, events[0].(qlog.FrameParsed).Raw.PayloadLength, 20)
+               require.Less(t, events[0].(qlog.FrameParsed).Raw.PayloadLength, 40)
        })
 }
 
-func testServerRequestHeaderTooLarge(t *testing.T, req *http.Request, maxHeaderBytes int) {
+func testServerRequestHeaderTooLarge(t *testing.T, req *http.Request, maxHeaderBytes int, rec qlogwriter.Recorder) {
        var called bool
        s := &Server{
                MaxHeaderBytes: maxHeaderBytes,
@@ -368,7 +407,7 @@ func testServerRequestHeaderTooLarge(t *testing.T, req *http.Request, maxHeaderB
        }
        s.init()
 
-       clientConn, serverConn := newConnPair(t)
+       clientConn, serverConn := newConnPairWithRecorder(t, nil, rec)
        str, err := clientConn.OpenStream()
        require.NoError(t, err)
        _, err = str.Write(encodeRequest(t, req))
index 50295600c227b251a109d3d68278007b8093b2f7..21754816b54918f7d7c33dec70248829d68a7d2f 100644 (file)
@@ -10,6 +10,8 @@ import (
        "time"
 
        "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/qpack"
 )
@@ -41,15 +43,24 @@ type Stream struct {
 
        bytesRemainingInFrame uint64
 
+       qlogger qlogwriter.Recorder
+
        parseTrailer  func(io.Reader, uint64) error
        parsedTrailer bool
 }
 
-func newStream(str datagramStream, conn *Conn, trace *httptrace.ClientTrace, parseTrailer func(io.Reader, uint64) error) *Stream {
+func newStream(
+       str datagramStream,
+       conn *Conn,
+       trace *httptrace.ClientTrace,
+       parseTrailer func(io.Reader, uint64) error,
+       qlogger qlogwriter.Recorder,
+) *Stream {
        return &Stream{
                datagramStream: str,
                conn:           conn,
                buf:            make([]byte, 16),
+               qlogger:        qlogger,
                parseTrailer:   parseTrailer,
                frameParser: &frameParser{
                        closeConn: conn.CloseWithError,
@@ -82,6 +93,7 @@ func (s *Stream) Read(b []byte) (int, error) {
                                        continue
                                }
                                if s.parsedTrailer {
+                                       maybeQlogInvalidHeadersFrame(s.qlogger, s.StreamID(), f.Length)
                                        return 0, errors.New("additional HEADERS frame received after trailers")
                                }
                                s.parsedTrailer = true
@@ -113,6 +125,16 @@ func (s *Stream) hasMoreData() bool {
 func (s *Stream) Write(b []byte) (int, error) {
        s.buf = s.buf[:0]
        s.buf = (&dataFrame{Length: uint64(len(b))}).Append(s.buf)
+       if s.qlogger != nil {
+               s.qlogger.RecordEvent(qlog.FrameCreated{
+                       StreamID: s.StreamID(),
+                       Raw: qlog.RawInfo{
+                               Length:        len(s.buf) + len(b),
+                               PayloadLength: len(b),
+                       },
+                       Frame: qlog.Frame{Frame: qlog.DataFrame{}},
+               })
+       }
        if _, err := s.datagramStream.Write(s.buf); err != nil {
                return 0, err
        }
index ca18a9cd6d2b6a50c9f41302ad826a9793fc6b88..213ff70463701b60c53142bee51f88a55f37a30d 100644 (file)
@@ -13,6 +13,9 @@ import (
        "time"
 
        "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/testutils/events"
 
        "github.com/quic-go/qpack"
 
@@ -45,6 +48,7 @@ func TestStreamReadDataFrames(t *testing.T) {
                ),
                nil,
                func(r io.Reader, u uint64) error { return nil },
+               nil,
        )
 
        buf.Write(getDataFrame([]byte("foobar")))
@@ -94,6 +98,7 @@ func TestStreamInvalidFrame(t *testing.T) {
                newConnection(context.Background(), clientConn, false, false, nil, 0),
                nil,
                func(r io.Reader, u uint64) error { return nil },
+               nil,
        )
 
        _, err := str.Read([]byte{0})
@@ -113,28 +118,50 @@ func TestStreamWrite(t *testing.T) {
        var buf bytes.Buffer
        mockCtrl := gomock.NewController(t)
        qstr := NewMockDatagramStream(mockCtrl)
+       qstr.EXPECT().StreamID().Return(quic.StreamID(42)).AnyTimes()
        qstr.EXPECT().Write(gomock.Any()).DoAndReturn(buf.Write).AnyTimes()
-       str := newStream(qstr, nil, nil, func(r io.Reader, u uint64) error { return nil })
+       var eventRecorder events.Recorder
+       str := newStream(qstr, nil, nil, func(r io.Reader, u uint64) error { return nil }, &eventRecorder)
        str.Write([]byte("foo"))
        str.Write([]byte("foobar"))
 
+       startLen := buf.Len()
        fp := frameParser{r: &buf}
        f, err := fp.ParseNext()
        require.NoError(t, err)
+       f1Len := startLen - buf.Len()
        require.Equal(t, &dataFrame{Length: 3}, f)
        b := make([]byte, 3)
        _, err = io.ReadFull(&buf, b)
        require.NoError(t, err)
        require.Equal(t, []byte("foo"), b)
 
+       startLen = buf.Len()
        fp = frameParser{r: &buf}
        f, err = fp.ParseNext()
        require.NoError(t, err)
+       f2Len := startLen - buf.Len()
        require.Equal(t, &dataFrame{Length: 6}, f)
        b = make([]byte, 6)
        _, err = io.ReadFull(&buf, b)
        require.NoError(t, err)
        require.Equal(t, []byte("foobar"), b)
+
+       require.Equal(t,
+               []qlogwriter.Event{
+                       qlog.FrameCreated{
+                               StreamID: 42,
+                               Raw:      qlog.RawInfo{Length: f1Len + 3, PayloadLength: 3},
+                               Frame:    qlog.Frame{Frame: qlog.DataFrame{}},
+                       },
+                       qlog.FrameCreated{
+                               StreamID: 42,
+                               Raw:      qlog.RawInfo{Length: f2Len + 6, PayloadLength: 6},
+                               Frame:    qlog.Frame{Frame: qlog.DataFrame{}},
+                       },
+               },
+               eventRecorder.Events(qlog.FrameCreated{}),
+       )
 }
 
 func TestRequestStream(t *testing.T) {
@@ -148,6 +175,7 @@ func TestRequestStream(t *testing.T) {
                        newConnection(context.Background(), clientConn, false, false, nil, 0),
                        &httptrace.ClientTrace{},
                        func(r io.Reader, u uint64) error { return nil },
+                       nil,
                ),
                requestWriter,
                make(chan struct{}),
index 04ee52c9f944d87067687e5cad00e3c97fce24df..a632ba3425ecbba5ee1683dccd71dd838b973092 100644 (file)
--- a/server.go
+++ b/server.go
@@ -87,7 +87,7 @@ type baseServer struct {
                *handshake.TokenGenerator,
                bool, /* client address validated by an address validation token */
                time.Duration,
-               qlogwriter.Recorder,
+               qlogwriter.Trace,
                utils.Logger,
                protocol.Version,
        ) *wrappedConn
@@ -801,16 +801,14 @@ func (s *baseServer) handleInitialImpl(p receivedPacket, hdr *wire.Header) error
                cancel = cancel1
        }
        ctx = context.WithValue(ctx, ConnectionTracingKey, nextConnTracingID())
-       var qlogger qlogwriter.Recorder
+       var qlogTrace qlogwriter.Trace
        if config.Tracer != nil {
                // Use the same connection ID that is passed to the client's GetLogWriter callback.
                connID := hdr.DestConnectionID
                if origDestConnID.Len() > 0 {
                        connID = origDestConnID
                }
-               if t := config.Tracer(ctx, false, connID); t != nil {
-                       qlogger = t.AddProducer()
-               }
+               qlogTrace = config.Tracer(ctx, false, connID)
        }
        connID, err := s.connIDGenerator.GenerateConnectionID()
        if err != nil {
@@ -834,7 +832,7 @@ func (s *baseServer) handleInitialImpl(p receivedPacket, hdr *wire.Header) error
                s.tokenGenerator,
                clientAddrVerified,
                rtt,
-               qlogger,
+               qlogTrace,
                s.logger,
                hdr.Version,
        )
index 6ff14ce35775bca64ec5cb355cd4ac197db843b5..d88edddc4941e02b6a1bdf100e6b752a68557776 100644 (file)
@@ -51,7 +51,7 @@ type serverOpts struct {
                *handshake.TokenGenerator,
                bool, /* client address validated by an address validation token */
                time.Duration,
-               qlogwriter.Recorder,
+               qlogwriter.Trace,
                utils.Logger,
                protocol.Version,
        ) *wrappedConn
@@ -677,7 +677,7 @@ func (r *connConstructorRecorder) NewConn(
        _ *handshake.TokenGenerator,
        _ bool,
        _ time.Duration,
-       _ qlogwriter.Recorder,
+       _ qlogwriter.Trace,
        _ utils.Logger,
        _ protocol.Version,
 ) *wrappedConn {
@@ -908,7 +908,7 @@ func TestServerReceiveQueue(t *testing.T) {
                        _ *handshake.TokenGenerator,
                        _ bool,
                        _ time.Duration,
-                       _ qlogwriter.Recorder,
+                       _ qlogwriter.Trace,
                        _ utils.Logger,
                        _ protocol.Version,
                ) *wrappedConn {
index 0942654c343d59f0e579cde48693956584af5474..891ee21b7b2f50a1cff15b718ca1b1231f576b61 100644 (file)
@@ -292,27 +292,9 @@ func (t *Transport) doDial(
                return nil, t.closeErr
        }
 
-       var qlogger qlogwriter.Recorder
+       var qlogTrace qlogwriter.Trace
        if config.Tracer != nil {
-               if tr := config.Tracer(ctx, true, destConnID); tr != nil {
-                       qlogger = tr.AddProducer()
-               }
-       }
-
-       if qlogger != nil {
-               var srcAddr, destAddr *net.UDPAddr
-               if addr, ok := sendConn.LocalAddr().(*net.UDPAddr); ok {
-                       srcAddr = addr
-               }
-               if addr, ok := sendConn.RemoteAddr().(*net.UDPAddr); ok {
-                       destAddr = addr
-               }
-               qlogger.RecordEvent(qlog.StartedConnection{
-                       SrcAddr:          srcAddr,
-                       DestAddr:         destAddr,
-                       SrcConnectionID:  srcConnID,
-                       DestConnectionID: destConnID,
-               })
+               qlogTrace = config.Tracer(ctx, true, destConnID)
        }
 
        logger := utils.DefaultLogger.WithPrefix("client")
@@ -331,7 +313,7 @@ func (t *Transport) doDial(
                initialPacketNumber,
                use0RTT,
                hasNegotiatedVersion,
-               qlogger,
+               qlogTrace,
                logger,
                version,
        )
index 858b2f33508a5ea2a9d9a85356537a61200430c1..0938b742a8327cc7c3b91aba7f01585643462434 100644 (file)
@@ -495,7 +495,7 @@ func testTransportDial(t *testing.T, early bool) {
                _ protocol.PacketNumber,
                _ bool,
                _ bool,
-               _ qlogwriter.Recorder,
+               _ qlogwriter.Trace,
                _ utils.Logger,
                _ protocol.Version,
        ) *wrappedConn {
@@ -565,7 +565,7 @@ func TestTransportDialingVersionNegotiation(t *testing.T) {
                pn protocol.PacketNumber,
                _ bool,
                hasNegotiatedVersion bool,
-               _ qlogwriter.Recorder,
+               _ qlogwriter.Trace,
                _ utils.Logger,
                v protocol.Version,
        ) *wrappedConn {