don't allocate a wire.Header when parsing short header packets

integrationtests/self/key_update_test.go

@@ -17,29 +17,23 @@ import (
 )
 
 var (
-	sentHeaders     []*logging.ExtendedHeader
-	receivedHeaders []*logging.ExtendedHeader
+	sentKeyPhases     []logging.KeyPhaseBit
+	receivedKeyPhases []logging.KeyPhaseBit
 )
 
 func countKeyPhases() (sent, received int) {
 	lastKeyPhase := protocol.KeyPhaseOne
-	for _, hdr := range sentHeaders {
-		if hdr.IsLongHeader {
-			continue
-		}
-		if hdr.KeyPhase != lastKeyPhase {
+	for _, keyPhase := range sentKeyPhases {
+		if keyPhase != lastKeyPhase {
 			sent++
-			lastKeyPhase = hdr.KeyPhase
+			lastKeyPhase = keyPhase
 		}
 	}
 	lastKeyPhase = protocol.KeyPhaseOne
-	for _, hdr := range receivedHeaders {
-		if hdr.IsLongHeader {
-			continue
-		}
-		if hdr.KeyPhase != lastKeyPhase {
+	for _, keyPhase := range receivedKeyPhases {
+		if keyPhase != lastKeyPhase {
 			received++
-			lastKeyPhase = hdr.KeyPhase
+			lastKeyPhase = keyPhase
 		}
 	}
 	return
@@ -65,13 +59,16 @@ func (t *connTracer) StartedConnection(local, remote net.Addr, version logging.V
 func (t *connTracer) ClosedConnection(logging.CloseReason)                     {}
 func (t *connTracer) SentTransportParameters(*logging.TransportParameters)     {}
 func (t *connTracer) ReceivedTransportParameters(*logging.TransportParameters) {}
-func (t *connTracer) SentPacket(hdr *logging.ExtendedHeader, size logging.ByteCount, ack *logging.AckFrame, frames []logging.Frame) {
-	sentHeaders = append(sentHeaders, hdr)
+func (t *connTracer) SentLongHeaderPacket(*logging.ExtendedHeader, logging.ByteCount, *logging.AckFrame, []logging.Frame) {
+}
+
+func (t *connTracer) SentShortHeaderPacket(_ logging.ConnectionID, _ logging.PacketNumber, kp logging.KeyPhaseBit, _ logging.ByteCount, _ *logging.AckFrame, _ []logging.Frame) {
+	sentKeyPhases = append(sentKeyPhases, kp)
 }
 func (t *connTracer) ReceivedVersionNegotiationPacket(*logging.Header, []logging.VersionNumber) {}
 func (t *connTracer) ReceivedRetry(*logging.Header)                                             {}
 func (t *connTracer) ReceivedPacket(hdr *logging.ExtendedHeader, size logging.ByteCount, frames []logging.Frame) {
-	receivedHeaders = append(receivedHeaders, hdr)
+	receivedKeyPhases = append(receivedKeyPhases, hdr.KeyPhase)
 }
 func (t *connTracer) BufferedPacket(logging.PacketType)                                             {}
 func (t *connTracer) DroppedPacket(logging.PacketType, logging.ByteCount, logging.PacketDropReason) {}

logging/interface.go

@@ -107,7 +107,8 @@ type ConnectionTracer interface {
 	ClosedConnection(CloseReason)
 	SentTransportParameters(*TransportParameters)
 	ReceivedTransportParameters(*TransportParameters)
-	SentPacket(hdr *ExtendedHeader, size ByteCount, ack *AckFrame, frames []Frame)
+	SentLongHeaderPacket(hdr *ExtendedHeader, size ByteCount, ack *AckFrame, frames []Frame)
+	SentShortHeaderPacket(destConnID ConnectionID, pn PacketNumber, kp KeyPhaseBit, size ByteCount, ack *AckFrame, frames []Frame)
 	ReceivedVersionNegotiationPacket(*Header, []VersionNumber)
 	ReceivedRetry(*Header)
 	ReceivedPacket(hdr *ExtendedHeader, size ByteCount, frames []Frame)

logging/multiplex.go

@@ -84,9 +84,15 @@ func (m *connTracerMultiplexer) ReceivedTransportParameters(tp *TransportParamet
 	}
 }
 
-func (m *connTracerMultiplexer) SentPacket(hdr *ExtendedHeader, size ByteCount, ack *AckFrame, frames []Frame) {
+func (m *connTracerMultiplexer) SentLongHeaderPacket(hdr *ExtendedHeader, size ByteCount, ack *AckFrame, frames []Frame) {
 	for _, t := range m.tracers {
-		t.SentPacket(hdr, size, ack, frames)
+		t.SentLongHeaderPacket(hdr, size, ack, frames)
+	}
+}
+
+func (m *connTracerMultiplexer) SentShortHeaderPacket(destConnID ConnectionID, pn PacketNumber, kp KeyPhaseBit, size ByteCount, ack *AckFrame, frames []Frame) {
+	for _, t := range m.tracers {
+		t.SentShortHeaderPacket(destConnID, pn, kp, size, ack, frames)
 	}
 }
 

logging/multiplex_test.go

@@ -126,13 +126,21 @@ var _ = Describe("Tracing", func() {
 			tracer.ReceivedTransportParameters(tp)
 		})
 
-		It("traces the SentPacket event", func() {
+		It("traces the SentLongHeaderPacket event", func() {
 			hdr := &ExtendedHeader{Header: Header{DestConnectionID: ConnectionID{1, 2, 3}}}
 			ack := &AckFrame{AckRanges: []AckRange{{Smallest: 1, Largest: 10}}}
 			ping := &PingFrame{}
-			tr1.EXPECT().SentPacket(hdr, ByteCount(1337), ack, []Frame{ping})
-			tr2.EXPECT().SentPacket(hdr, ByteCount(1337), ack, []Frame{ping})
-			tracer.SentPacket(hdr, 1337, ack, []Frame{ping})
+			tr1.EXPECT().SentLongHeaderPacket(hdr, ByteCount(1337), ack, []Frame{ping})
+			tr2.EXPECT().SentLongHeaderPacket(hdr, ByteCount(1337), ack, []Frame{ping})
+			tracer.SentLongHeaderPacket(hdr, 1337, ack, []Frame{ping})
+		})
+
+		It("traces the SentShortHeaderPacket event", func() {
+			ack := &AckFrame{AckRanges: []AckRange{{Smallest: 1, Largest: 10}}}
+			ping := &PingFrame{}
+			tr1.EXPECT().SentShortHeaderPacket(ConnectionID{1, 2, 3}, PacketNumber(123), KeyPhaseOne, ByteCount(1337), ack, []Frame{ping})
+			tr2.EXPECT().SentShortHeaderPacket(ConnectionID{1, 2, 3}, PacketNumber(123), KeyPhaseOne, ByteCount(1337), ack, []Frame{ping})
+			tracer.SentShortHeaderPacket(ConnectionID{1, 2, 3}, 123, KeyPhaseOne, 1337, ack, []Frame{ping})
 		})
 
 		It("traces the ReceivedVersionNegotiationPacket event", func() {

metrics/metrics.go

@@ -165,11 +165,9 @@ func (t *connTracer) ClosedConnection(r logging.CloseReason) {
 }
 func (t *connTracer) SentTransportParameters(*logging.TransportParameters)     {}
 func (t *connTracer) ReceivedTransportParameters(*logging.TransportParameters) {}
-func (t *connTracer) SentPacket(hdr *logging.ExtendedHeader, _ logging.ByteCount, _ *logging.AckFrame, _ []logging.Frame) {
+func (t *connTracer) SentLongHeaderPacket(hdr *logging.ExtendedHeader, _ logging.ByteCount, _ *logging.AckFrame, _ []logging.Frame) {
 	typ := logging.PacketTypeFromHeader(&hdr.Header)
-	if typ == logging.PacketType1RTT {
-		t.handshakeComplete = true
-	}
+
 	stats.RecordWithTags(
 		context.Background(),
 		[]tag.Mutator{
@@ -178,6 +176,17 @@ func (t *connTracer) SentPacket(hdr *logging.ExtendedHeader, _ logging.ByteCount
 		sentPackets.M(1),
 	)
 }
+
+func (t *connTracer) SentShortHeaderPacket(logging.ConnectionID, logging.PacketNumber, logging.KeyPhaseBit, logging.ByteCount, *logging.AckFrame, []logging.Frame) {
+	t.handshakeComplete = true
+	stats.RecordWithTags(
+		context.Background(),
+		[]tag.Mutator{
+			tag.Upsert(keyPacketType, packetType(logging.PacketType1RTT).String()),
+		},
+		sentPackets.M(1),
+	)
+}
 func (t *connTracer) ReceivedVersionNegotiationPacket(*logging.Header, []logging.VersionNumber) {}
 func (t *connTracer) ReceivedRetry(*logging.Header)                                             {}
 func (t *connTracer) ReceivedPacket(*logging.ExtendedHeader, logging.ByteCount, []logging.Frame) {

metrics/metrics_suite_test.go

@@ -0,0 +1,13 @@
+package metrics_test
+
+import (
+	"testing"
+
+	. "github.com/onsi/ginkgo"
+	. "github.com/onsi/gomega"
+)
+
+func TestMetrics(t *testing.T) {
+	RegisterFailHandler(Fail)
+	RunSpecs(t, "Metrics Suite")
+}

qlog/qlog.go

@@ -209,7 +209,7 @@ func (t *connectionTracer) recordTransportParameters(sentBy protocol.Perspective
 	t.mutex.Unlock()
 }
 
-func (t *connectionTracer) SentPacket(hdr *wire.ExtendedHeader, packetSize protocol.ByteCount, ack *logging.AckFrame, frames []logging.Frame) {
+func (t *connectionTracer) SentLongHeaderPacket(hdr *wire.ExtendedHeader, packetSize protocol.ByteCount, ack *logging.AckFrame, frames []logging.Frame) {
 	numFrames := len(frames)
 	if ack != nil {
 		numFrames++
@@ -231,6 +231,32 @@ func (t *connectionTracer) SentPacket(hdr *wire.ExtendedHeader, packetSize proto
 	t.mutex.Unlock()
 }
 
+func (t *connectionTracer) SentShortHeaderPacket(destConnID logging.ConnectionID, pn logging.PacketNumber, kp logging.KeyPhaseBit, size logging.ByteCount, ack *logging.AckFrame, frames []logging.Frame) {
+	numFrames := len(frames)
+	if ack != nil {
+		numFrames++
+	}
+	fs := make([]frame, 0, numFrames)
+	if ack != nil {
+		fs = append(fs, frame{Frame: ack})
+	}
+	for _, f := range frames {
+		fs = append(fs, frame{Frame: f})
+	}
+	t.mutex.Lock()
+	t.recordEvent(time.Now(), &eventPacketSent{
+		Header: packetHeader{
+			PacketType:       logging.PacketType1RTT,
+			DestConnectionID: destConnID,
+			PacketNumber:     pn,
+			KeyPhaseBit:      kp,
+			PacketSize:       size,
+		},
+		Frames: fs,
+	})
+	t.mutex.Unlock()
+}
+
 func (t *connectionTracer) ReceivedPacket(hdr *wire.ExtendedHeader, packetSize protocol.ByteCount, frames []logging.Frame) {
 	fs := make([]frame, len(frames))
 	for i, f := range frames {

qlog/qlog_test.go

@@ -327,8 +327,8 @@ var _ = Describe("Tracing", func() {
 				Expect(ev).ToNot(HaveKey("original_destination_connection_id"))
 			})
 
-			It("records a sent packet, without an ACK", func() {
-				tracer.SentPacket(
+			It("records a sent long header packet, without an ACK", func() {
+				tracer.SentLongHeaderPacket(
 					&logging.ExtendedHeader{
 						Header: logging.Header{
 							IsLongHeader:     true,
@@ -363,10 +363,15 @@ var _ = Describe("Tracing", func() {
 				Expect(frames[1].(map[string]interface{})).To(HaveKeyWithValue("frame_type", "stream"))
 			})
 
-			It("records a sent packet, without an ACK", func() {
-				tracer.SentPacket(
+			It("records a sent long header packet, containing an ACK", func() {
+				tracer.SentLongHeaderPacket(
 					&logging.ExtendedHeader{
-						Header:       logging.Header{DestConnectionID: protocol.ConnectionID{1, 2, 3, 4}},
+						Header: logging.Header{
+							IsLongHeader:     true,
+							Type:             protocol.PacketTypeInitial,
+							DestConnectionID: protocol.ConnectionID{1, 2, 3, 4},
+							Version:          protocol.VersionTLS,
+						},
 						PacketNumber: 1337,
 					},
 					123,
@@ -376,6 +381,55 @@ var _ = Describe("Tracing", func() {
 				entry := exportAndParseSingle()
 				ev := entry.Event
 				Expect(ev).To(HaveKey("header"))
+				Expect(ev).To(HaveKey("frames"))
+				frames := ev["frames"].([]interface{})
+				Expect(frames).To(HaveLen(2))
+				Expect(frames[0].(map[string]interface{})).To(HaveKeyWithValue("frame_type", "ack"))
+				Expect(frames[1].(map[string]interface{})).To(HaveKeyWithValue("frame_type", "max_data"))
+			})
+
+			It("records a sent short header packet, without an ACK", func() {
+				tracer.SentShortHeaderPacket(
+					protocol.ConnectionID{1, 2, 3, 4, 5, 6, 7, 8},
+					1337,
+					logging.KeyPhaseOne,
+					987,
+					nil,
+					[]logging.Frame{
+						&logging.MaxStreamDataFrame{StreamID: 42, MaximumStreamData: 987},
+						&logging.StreamFrame{StreamID: 123, Offset: 1234, Length: 6, Fin: true},
+					},
+				)
+				entry := exportAndParseSingle()
+				Expect(entry.Time).To(BeTemporally("~", time.Now(), scaleDuration(10*time.Millisecond)))
+				Expect(entry.Name).To(Equal("transport:packet_sent"))
+				ev := entry.Event
+				Expect(ev).To(HaveKey("header"))
+				hdr := ev["header"].(map[string]interface{})
+				Expect(hdr).To(HaveKeyWithValue("packet_type", "1RTT"))
+				Expect(hdr).To(HaveKeyWithValue("packet_size", float64(987)))
+				Expect(hdr).To(HaveKeyWithValue("packet_number", float64(1337)))
+				Expect(hdr).To(HaveKeyWithValue("key_phase_bit", "1"))
+				Expect(hdr).ToNot(HaveKey("scid"))
+				Expect(ev).To(HaveKey("frames"))
+				frames := ev["frames"].([]interface{})
+				Expect(frames).To(HaveLen(2))
+				Expect(frames[0].(map[string]interface{})).To(HaveKeyWithValue("frame_type", "max_stream_data"))
+				Expect(frames[1].(map[string]interface{})).To(HaveKeyWithValue("frame_type", "stream"))
+			})
+
+			It("records a sent short header packet, containing an ACK", func() {
+				tracer.SentShortHeaderPacket(
+					protocol.ConnectionID{1, 2, 3, 4},
+					1337,
+					logging.KeyPhaseOne,
+					123,
+					&logging.AckFrame{AckRanges: []logging.AckRange{{Smallest: 1, Largest: 10}}},
+					[]logging.Frame{&logging.MaxDataFrame{MaximumData: 987}},
+				)
+				entry := exportAndParseSingle()
+				ev := entry.Event
+				Expect(ev).To(HaveKey("header"))
 				hdr := ev["header"].(map[string]interface{})
 				Expect(hdr).To(HaveKeyWithValue("packet_type", "1RTT"))
 				Expect(hdr).To(HaveKeyWithValue("packet_number", float64(1337)))

session.go

@@ -1576,7 +1576,11 @@ func (s *session) logPacketContents(p *packetContents) {
 		for _, f := range p.frames {
 			frames = append(frames, logutils.ConvertFrame(f.Frame))
 		}
-		s.tracer.SentPacket(p.header, p.length, p.ack, frames)
+		if p.header.IsLongHeader {
+			s.tracer.SentLongHeaderPacket(p.header, p.length, p.ack, frames)
+		} else {
+			s.tracer.SentShortHeaderPacket(p.header.DestConnectionID, p.header.PacketNumber, p.header.KeyPhase, p.length, p.ack, frames)
+		}
 	}
 
 	// quic-go logging