use the relative_time when logging qlog events

qlog/event.go

@@ -10,7 +10,7 @@ import (
 	"github.com/francoispqt/gojay"
 )
 
-var eventFields = [4]string{"time", "category", "event", "data"}
+var eventFields = [4]string{"relative_time", "category", "event", "data"}
 
 type events []event
 
@@ -31,7 +31,7 @@ type eventDetails interface {
 }
 
 type event struct {
-	Time time.Time
+	RelativeTime time.Duration
 	eventDetails
 }
 
@@ -39,7 +39,7 @@ var _ gojay.MarshalerJSONArray = event{}
 
 func (e event) IsNil() bool { return false }
 func (e event) MarshalJSONArray(enc *gojay.Encoder) {
-	enc.Float64(float64(e.Time.UnixNano()) / 1e6)
+	enc.Float64(float64(e.RelativeTime.Nanoseconds()) / 1e6)
 	enc.String(e.Category().String())
 	enc.String(e.Name())
 	enc.Object(e.eventDetails)

qlog/event_test.go

@@ -22,12 +22,10 @@ func (mevent) MarshalJSONObject(enc *gojay.Encoder) { enc.StringKey("event", "de
 
 var _ = Describe("Events", func() {
 	It("marshals the fields before the event details", func() {
-		now := time.Now()
-
 		buf := &bytes.Buffer{}
 		enc := gojay.NewEncoder(buf)
 		Expect(enc.Encode(event{
-			Time:         now,
+			RelativeTime: 1337 * time.Microsecond,
 			eventDetails: mevent{},
 		})).To(Succeed())
 
@@ -36,8 +34,8 @@ var _ = Describe("Events", func() {
 		Expect(decoded).To(HaveLen(4))
 
 		// 1st field
-		Expect(eventFields[0]).To(Equal("time"))
+		Expect(eventFields[0]).To(Equal("relative_time"))
-		Expect(time.Unix(0, int64(1e6*decoded[0].(float64)))).To(BeTemporally("~", now, 2*time.Microsecond))
+		Expect(decoded[0].(float64)).To(Equal(1.337))
 
 		// 2nd field
 		Expect(eventFields[1]).To(Equal("category"))

qlog/qlog.go

@@ -40,6 +40,7 @@ type tracer struct {
 	w             io.WriteCloser
 	odcid         protocol.ConnectionID
 	perspective   protocol.Perspective
+	referenceTime time.Time
 
 	suffix     []byte
 	events     chan event
@@ -57,6 +58,7 @@ func NewTracer(w io.WriteCloser, p protocol.Perspective, odcid protocol.Connecti
 		odcid:         odcid,
 		runStopped:    make(chan struct{}),
 		events:        make(chan event, eventChanSize),
+		referenceTime: time.Now(),
 	}
 	go t.run()
 	return t
@@ -70,7 +72,11 @@ func (t *tracer) run() {
 		traces: traces{
 			{
 				VantagePoint: vantagePoint{Type: t.perspective},
-				CommonFields: commonFields{ODCID: connectionID(t.odcid), GroupID: connectionID(t.odcid)},
+				CommonFields: commonFields{
+					ODCID:         connectionID(t.odcid),
+					GroupID:       connectionID(t.odcid),
+					ReferenceTime: t.referenceTime,
+				},
 				EventFields: eventFields[:],
 			},
 		}}
@@ -113,7 +119,7 @@ func (t *tracer) Export() error {
 
 func (t *tracer) recordEvent(details eventDetails) {
 	t.events <- event{
-		Time:         time.Now(),
+		RelativeTime: time.Since(t.referenceTime),
 		eventDetails: details,
 	}
 }

qlog/qlog_test.go

@@ -113,7 +113,7 @@ var _ = Describe("Tracer", func() {
 				ev := e.([]interface{})
 				Expect(ev).To(HaveLen(4))
 				entries = append(entries, entry{
-					Time:     time.Unix(0, int64(1e6*ev[0].(float64))),
+					Time:     time.Now().Add(time.Duration(ev[0].(float64)) * time.Millisecond),
 					Category: ev[1].(string),
 					Name:     ev[2].(string),
 					Event:    ev[3].(map[string]interface{}),

qlog/trace.go

@@ -1,6 +1,8 @@
 package qlog
 
 import (
+	"time"
+
 	"github.com/francoispqt/gojay"
 
 	"github.com/lucas-clemente/quic-go/internal/protocol"
@@ -37,12 +39,14 @@ type commonFields struct {
 	ODCID         connectionID
 	GroupID       connectionID
 	ProtocolType  string
+	ReferenceTime time.Time
 }
 
 func (f commonFields) MarshalJSONObject(enc *gojay.Encoder) {
 	enc.StringKey("ODCID", f.ODCID.String())
 	enc.StringKey("group_id", f.ODCID.String())
 	enc.StringKeyOmitEmpty("protocol_type", f.ProtocolType)
+	enc.Float64Key("reference_time", float64(f.ReferenceTime.UnixNano()/1e6))
 }
 
 func (f commonFields) IsNil() bool { return false }