// Copyright 2023 The Go Authors. All rights reserved. // Use of this source code is governed by a BSD-style // license that can be found in the LICENSE file. //go:build go1.21 // Package qlog serializes qlog events. package qlog import ( "bytes" "context" "errors" "io" "log/slog" "os" "path/filepath" "sync" "time" ) // Vantage is the vantage point of a trace. type Vantage string const ( // VantageEndpoint traces contain events not specific to a single connection. VantageEndpoint = Vantage("endpoint") // VantageClient traces follow a connection from the client's perspective. VantageClient = Vantage("client") // VantageServer traces follow a connection from the server's perspective. VantageServer = Vantage("server") ) // TraceInfo contains information about a trace. type TraceInfo struct { // Vantage is the vantage point of the trace. Vantage Vantage // GroupID identifies the logical group the trace belongs to. // For a connection trace, the group will be the same for // both the client and server vantage points. GroupID string } // HandlerOptions are options for a JSONHandler. type HandlerOptions struct { // Level reports the minimum record level that will be logged. // If Level is nil, the handler assumes QLogLevelEndpoint. Level slog.Leveler // Dir is the directory in which to create trace files. // The handler will create one file per connection. // If NewTrace is non-nil or Dir is "", the handler will not create files. Dir string // NewTrace is called to create a new trace. // If NewTrace is nil and Dir is set, // the handler will create a new file in Dir for each trace. NewTrace func(TraceInfo) (io.WriteCloser, error) } type endpointHandler struct { opts HandlerOptions traceOnce sync.Once trace *jsonTraceHandler } // NewJSONHandler returns a handler which serializes qlog events to JSON. // // The handler will write an endpoint-wide trace, // and a separate trace for each connection. // The HandlerOptions control the location traces are written. // // It uses the streamable JSON Text Sequences mapping (JSON-SEQ) // defined in draft-ietf-quic-qlog-main-schema-04, Section 6.2. // // A JSONHandler may be used as the handler for a quic.Config.QLogLogger. // It is not a general-purpose slog handler, // and may not properly handle events from other sources. func NewJSONHandler(opts HandlerOptions) slog.Handler { if opts.Dir == "" && opts.NewTrace == nil { return slogDiscard{} } return &endpointHandler{ opts: opts, } } func (h *endpointHandler) Enabled(ctx context.Context, level slog.Level) bool { return enabled(h.opts.Level, level) } func (h *endpointHandler) Handle(ctx context.Context, r slog.Record) error { h.traceOnce.Do(func() { h.trace, _ = newJSONTraceHandler(h.opts, nil) }) if h.trace != nil { h.trace.Handle(ctx, r) } return nil } func (h *endpointHandler) WithAttrs(attrs []slog.Attr) slog.Handler { // Create a new trace output file for each top-level WithAttrs. tr, err := newJSONTraceHandler(h.opts, attrs) if err != nil { return withAttrs(h, attrs) } return tr } func (h *endpointHandler) WithGroup(name string) slog.Handler { return withGroup(h, name) } type jsonTraceHandler struct { level slog.Leveler w jsonWriter start time.Time buf bytes.Buffer } func newJSONTraceHandler(opts HandlerOptions, attrs []slog.Attr) (*jsonTraceHandler, error) { w, err := newTraceWriter(opts, traceInfoFromAttrs(attrs)) if err != nil { return nil, err } // For testing, it might be nice to set the start time used for relative timestamps // to the time of the first event. // // At the expense of some additional complexity here, we could defer writing // the reference_time header field until the first event is processed. // // Just use the current time for now. start := time.Now() h := &jsonTraceHandler{ w: jsonWriter{w: w}, level: opts.Level, start: start, } h.writeHeader(attrs) return h, nil } func traceInfoFromAttrs(attrs []slog.Attr) TraceInfo { info := TraceInfo{ Vantage: VantageEndpoint, // default if not specified } for _, a := range attrs { if a.Key == "group_id" && a.Value.Kind() == slog.KindString { info.GroupID = a.Value.String() } if a.Key == "vantage_point" && a.Value.Kind() == slog.KindGroup { for _, aa := range a.Value.Group() { if aa.Key == "type" && aa.Value.Kind() == slog.KindString { info.Vantage = Vantage(aa.Value.String()) } } } } return info } func newTraceWriter(opts HandlerOptions, info TraceInfo) (io.WriteCloser, error) { var w io.WriteCloser var err error if opts.NewTrace != nil { w, err = opts.NewTrace(info) } else if opts.Dir != "" { var filename string if info.GroupID != "" { filename = info.GroupID + "_" } filename += string(info.Vantage) + ".sqlog" if !filepath.IsLocal(filename) { return nil, errors.New("invalid trace filename") } w, err = os.OpenFile(filepath.Join(opts.Dir, filename), os.O_CREATE|os.O_EXCL|os.O_WRONLY, 0666) } else { err = errors.New("no log destination") } return w, err } func (h *jsonTraceHandler) writeHeader(attrs []slog.Attr) { h.w.writeRecordStart() defer h.w.writeRecordEnd() // At the time of writing this comment the most recent version is 0.4, // but qvis only supports up to 0.3. h.w.writeStringField("qlog_version", "0.3") h.w.writeStringField("qlog_format", "JSON-SEQ") // The attrs flatten both common trace event fields and Trace fields. // This identifies the fields that belong to the Trace. isTraceSeqField := func(s string) bool { switch s { case "title", "description", "configuration", "vantage_point": return true } return false } h.w.writeObjectField("trace", func() { h.w.writeObjectField("common_fields", func() { h.w.writeRawField("protocol_type", `["QUIC"]`) h.w.writeStringField("time_format", "relative") h.w.writeTimeField("reference_time", h.start) for _, a := range attrs { if !isTraceSeqField(a.Key) { h.w.writeAttr(a) } } }) for _, a := range attrs { if isTraceSeqField(a.Key) { h.w.writeAttr(a) } } }) } func (h *jsonTraceHandler) Enabled(ctx context.Context, level slog.Level) bool { return enabled(h.level, level) } func (h *jsonTraceHandler) Handle(ctx context.Context, r slog.Record) error { h.w.writeRecordStart() defer h.w.writeRecordEnd() h.w.writeDurationField("time", r.Time.Sub(h.start)) h.w.writeStringField("name", r.Message) h.w.writeObjectField("data", func() { r.Attrs(func(a slog.Attr) bool { h.w.writeAttr(a) return true }) }) return nil } func (h *jsonTraceHandler) WithAttrs(attrs []slog.Attr) slog.Handler { return withAttrs(h, attrs) } func (h *jsonTraceHandler) WithGroup(name string) slog.Handler { return withGroup(h, name) } func enabled(leveler slog.Leveler, level slog.Level) bool { var minLevel slog.Level if leveler != nil { minLevel = leveler.Level() } return level >= minLevel } type slogDiscard struct{} func (slogDiscard) Enabled(context.Context, slog.Level) bool { return false } func (slogDiscard) Handle(ctx context.Context, r slog.Record) error { return nil } func (slogDiscard) WithAttrs(attrs []slog.Attr) slog.Handler { return slogDiscard{} } func (slogDiscard) WithGroup(name string) slog.Handler { return slogDiscard{} }