From 86b02554b5d15d2d860cc0796e98656712098d7e Mon Sep 17 00:00:00 2001
From: Marten Seemann <martenseemann@gmail.com>
Date: Fri, 27 Mar 2020 20:22:47 +0700
Subject: [PATCH] use the relative_time when logging qlog events

---
 qlog/event.go      |  6 +++---
 qlog/event_test.go |  8 +++-----
 qlog/qlog.go       | 28 +++++++++++++++++-----------
 qlog/qlog_test.go  |  2 +-
 qlog/trace.go      | 10 +++++++---
 5 files changed, 31 insertions(+), 23 deletions(-)

diff --git a/qlog/event.go b/qlog/event.go
index 97a7d78c4..5e114fece 100644
--- a/qlog/event.go
+++ b/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)
diff --git a/qlog/event_test.go b/qlog/event_test.go
index 5112f2132..6a1f84a42 100644
--- a/qlog/event_test.go
+++ b/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(time.Unix(0, int64(1e6*decoded[0].(float64)))).To(BeTemporally("~", now, 2*time.Microsecond))
+		Expect(eventFields[0]).To(Equal("relative_time"))
+		Expect(decoded[0].(float64)).To(Equal(1.337))
 
 		// 2nd field
 		Expect(eventFields[1]).To(Equal("category"))
diff --git a/qlog/qlog.go b/qlog/qlog.go
index 7c3e22178..e165b479a 100644
--- a/qlog/qlog.go
+++ b/qlog/qlog.go
@@ -37,9 +37,10 @@ type Tracer interface {
 }
 
 type tracer struct {
-	w           io.WriteCloser
-	odcid       protocol.ConnectionID
-	perspective protocol.Perspective
+	w             io.WriteCloser
+	odcid         protocol.ConnectionID
+	perspective   protocol.Perspective
+	referenceTime time.Time
 
 	suffix     []byte
 	events     chan event
@@ -52,11 +53,12 @@ var _ Tracer = &tracer{}
 // NewTracer creates a new tracer to record a qlog.
 func NewTracer(w io.WriteCloser, p protocol.Perspective, odcid protocol.ConnectionID) Tracer {
 	t := &tracer{
-		w:           w,
-		perspective: p,
-		odcid:       odcid,
-		runStopped:  make(chan struct{}),
-		events:      make(chan event, eventChanSize),
+		w:             w,
+		perspective:   p,
+		odcid:         odcid,
+		runStopped:    make(chan struct{}),
+		events:        make(chan event, eventChanSize),
+		referenceTime: time.Now(),
 	}
 	go t.run()
 	return t
@@ -70,8 +72,12 @@ func (t *tracer) run() {
 		traces: traces{
 			{
 				VantagePoint: vantagePoint{Type: t.perspective},
-				CommonFields: commonFields{ODCID: connectionID(t.odcid), GroupID: connectionID(t.odcid)},
-				EventFields:  eventFields[:],
+				CommonFields: commonFields{
+					ODCID:         connectionID(t.odcid),
+					GroupID:       connectionID(t.odcid),
+					ReferenceTime: t.referenceTime,
+				},
+				EventFields: eventFields[:],
 			},
 		}}
 	if err := enc.Encode(tl); err != nil {
@@ -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,
 	}
 }
diff --git a/qlog/qlog_test.go b/qlog/qlog_test.go
index 72091f11e..952525a33 100644
--- a/qlog/qlog_test.go
+++ b/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{}),
diff --git a/qlog/trace.go b/qlog/trace.go
index 2d3628d02..33a103401 100644
--- a/qlog/trace.go
+++ b/qlog/trace.go
@@ -1,6 +1,8 @@
 package qlog
 
 import (
+	"time"
+
 	"github.com/francoispqt/gojay"
 
 	"github.com/lucas-clemente/quic-go/internal/protocol"
@@ -34,15 +36,17 @@ func (p vantagePoint) MarshalJSONObject(enc *gojay.Encoder) {
 }
 
 type commonFields struct {
-	ODCID        connectionID
-	GroupID      connectionID
-	ProtocolType string
+	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 }