qlog.go

Documentation: golang.org/x/net/internal/quic/qlog

     1  // Copyright 2023 The Go Authors. All rights reserved.
     2  // Use of this source code is governed by a BSD-style
     3  // license that can be found in the LICENSE file.
     4  
     5  //go:build go1.21
     6  
     7  // Package qlog serializes qlog events.
     8  package qlog
     9  
    10  import (
    11  	"bytes"
    12  	"context"
    13  	"errors"
    14  	"io"
    15  	"log/slog"
    16  	"os"
    17  	"path/filepath"
    18  	"sync"
    19  	"time"
    20  )
    21  
    22  // Vantage is the vantage point of a trace.
    23  type Vantage string
    24  
    25  const (
    26  	// VantageEndpoint traces contain events not specific to a single connection.
    27  	VantageEndpoint = Vantage("endpoint")
    28  
    29  	// VantageClient traces follow a connection from the client's perspective.
    30  	VantageClient = Vantage("client")
    31  
    32  	// VantageServer traces follow a connection from the server's perspective.
    33  	VantageServer = Vantage("server")
    34  )
    35  
    36  // TraceInfo contains information about a trace.
    37  type TraceInfo struct {
    38  	// Vantage is the vantage point of the trace.
    39  	Vantage Vantage
    40  
    41  	// GroupID identifies the logical group the trace belongs to.
    42  	// For a connection trace, the group will be the same for
    43  	// both the client and server vantage points.
    44  	GroupID string
    45  }
    46  
    47  // HandlerOptions are options for a JSONHandler.
    48  type HandlerOptions struct {
    49  	// Level reports the minimum record level that will be logged.
    50  	// If Level is nil, the handler assumes QLogLevelEndpoint.
    51  	Level slog.Leveler
    52  
    53  	// Dir is the directory in which to create trace files.
    54  	// The handler will create one file per connection.
    55  	// If NewTrace is non-nil or Dir is "", the handler will not create files.
    56  	Dir string
    57  
    58  	// NewTrace is called to create a new trace.
    59  	// If NewTrace is nil and Dir is set,
    60  	// the handler will create a new file in Dir for each trace.
    61  	NewTrace func(TraceInfo) (io.WriteCloser, error)
    62  }
    63  
    64  type endpointHandler struct {
    65  	opts HandlerOptions
    66  
    67  	traceOnce sync.Once
    68  	trace     *jsonTraceHandler
    69  }
    70  
    71  // NewJSONHandler returns a handler which serializes qlog events to JSON.
    72  //
    73  // The handler will write an endpoint-wide trace,
    74  // and a separate trace for each connection.
    75  // The HandlerOptions control the location traces are written.
    76  //
    77  // It uses the streamable JSON Text Sequences mapping (JSON-SEQ)
    78  // defined in draft-ietf-quic-qlog-main-schema-04, Section 6.2.
    79  //
    80  // A JSONHandler may be used as the handler for a quic.Config.QLogLogger.
    81  // It is not a general-purpose slog handler,
    82  // and may not properly handle events from other sources.
    83  func NewJSONHandler(opts HandlerOptions) slog.Handler {
    84  	if opts.Dir == "" && opts.NewTrace == nil {
    85  		return slogDiscard{}
    86  	}
    87  	return &endpointHandler{
    88  		opts: opts,
    89  	}
    90  }
    91  
    92  func (h *endpointHandler) Enabled(ctx context.Context, level slog.Level) bool {
    93  	return enabled(h.opts.Level, level)
    94  }
    95  
    96  func (h *endpointHandler) Handle(ctx context.Context, r slog.Record) error {
    97  	h.traceOnce.Do(func() {
    98  		h.trace, _ = newJSONTraceHandler(h.opts, nil)
    99  	})
   100  	if h.trace != nil {
   101  		h.trace.Handle(ctx, r)
   102  	}
   103  	return nil
   104  }
   105  
   106  func (h *endpointHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
   107  	// Create a new trace output file for each top-level WithAttrs.
   108  	tr, err := newJSONTraceHandler(h.opts, attrs)
   109  	if err != nil {
   110  		return withAttrs(h, attrs)
   111  	}
   112  	return tr
   113  }
   114  
   115  func (h *endpointHandler) WithGroup(name string) slog.Handler {
   116  	return withGroup(h, name)
   117  }
   118  
   119  type jsonTraceHandler struct {
   120  	level slog.Leveler
   121  	w     jsonWriter
   122  	start time.Time
   123  	buf   bytes.Buffer
   124  }
   125  
   126  func newJSONTraceHandler(opts HandlerOptions, attrs []slog.Attr) (*jsonTraceHandler, error) {
   127  	w, err := newTraceWriter(opts, traceInfoFromAttrs(attrs))
   128  	if err != nil {
   129  		return nil, err
   130  	}
   131  
   132  	// For testing, it might be nice to set the start time used for relative timestamps
   133  	// to the time of the first event.
   134  	//
   135  	// At the expense of some additional complexity here, we could defer writing
   136  	// the reference_time header field until the first event is processed.
   137  	//
   138  	// Just use the current time for now.
   139  	start := time.Now()
   140  
   141  	h := &jsonTraceHandler{
   142  		w:     jsonWriter{w: w},
   143  		level: opts.Level,
   144  		start: start,
   145  	}
   146  	h.writeHeader(attrs)
   147  	return h, nil
   148  }
   149  
   150  func traceInfoFromAttrs(attrs []slog.Attr) TraceInfo {
   151  	info := TraceInfo{
   152  		Vantage: VantageEndpoint, // default if not specified
   153  	}
   154  	for _, a := range attrs {
   155  		if a.Key == "group_id" && a.Value.Kind() == slog.KindString {
   156  			info.GroupID = a.Value.String()
   157  		}
   158  		if a.Key == "vantage_point" && a.Value.Kind() == slog.KindGroup {
   159  			for _, aa := range a.Value.Group() {
   160  				if aa.Key == "type" && aa.Value.Kind() == slog.KindString {
   161  					info.Vantage = Vantage(aa.Value.String())
   162  				}
   163  			}
   164  		}
   165  	}
   166  	return info
   167  }
   168  
   169  func newTraceWriter(opts HandlerOptions, info TraceInfo) (io.WriteCloser, error) {
   170  	var w io.WriteCloser
   171  	var err error
   172  	if opts.NewTrace != nil {
   173  		w, err = opts.NewTrace(info)
   174  	} else if opts.Dir != "" {
   175  		var filename string
   176  		if info.GroupID != "" {
   177  			filename = info.GroupID + "_"
   178  		}
   179  		filename += string(info.Vantage) + ".sqlog"
   180  		if !filepath.IsLocal(filename) {
   181  			return nil, errors.New("invalid trace filename")
   182  		}
   183  		w, err = os.OpenFile(filepath.Join(opts.Dir, filename), os.O_CREATE|os.O_EXCL|os.O_WRONLY, 0666)
   184  	} else {
   185  		err = errors.New("no log destination")
   186  	}
   187  	return w, err
   188  }
   189  
   190  func (h *jsonTraceHandler) writeHeader(attrs []slog.Attr) {
   191  	h.w.writeRecordStart()
   192  	defer h.w.writeRecordEnd()
   193  
   194  	// At the time of writing this comment the most recent version is 0.4,
   195  	// but qvis only supports up to 0.3.
   196  	h.w.writeStringField("qlog_version", "0.3")
   197  	h.w.writeStringField("qlog_format", "JSON-SEQ")
   198  
   199  	// The attrs flatten both common trace event fields and Trace fields.
   200  	// This identifies the fields that belong to the Trace.
   201  	isTraceSeqField := func(s string) bool {
   202  		switch s {
   203  		case "title", "description", "configuration", "vantage_point":
   204  			return true
   205  		}
   206  		return false
   207  	}
   208  
   209  	h.w.writeObjectField("trace", func() {
   210  		h.w.writeObjectField("common_fields", func() {
   211  			h.w.writeRawField("protocol_type", `["QUIC"]`)
   212  			h.w.writeStringField("time_format", "relative")
   213  			h.w.writeTimeField("reference_time", h.start)
   214  			for _, a := range attrs {
   215  				if !isTraceSeqField(a.Key) {
   216  					h.w.writeAttr(a)
   217  				}
   218  			}
   219  		})
   220  		for _, a := range attrs {
   221  			if isTraceSeqField(a.Key) {
   222  				h.w.writeAttr(a)
   223  			}
   224  		}
   225  	})
   226  }
   227  
   228  func (h *jsonTraceHandler) Enabled(ctx context.Context, level slog.Level) bool {
   229  	return enabled(h.level, level)
   230  }
   231  
   232  func (h *jsonTraceHandler) Handle(ctx context.Context, r slog.Record) error {
   233  	h.w.writeRecordStart()
   234  	defer h.w.writeRecordEnd()
   235  	h.w.writeDurationField("time", r.Time.Sub(h.start))
   236  	h.w.writeStringField("name", r.Message)
   237  	h.w.writeObjectField("data", func() {
   238  		r.Attrs(func(a slog.Attr) bool {
   239  			h.w.writeAttr(a)
   240  			return true
   241  		})
   242  	})
   243  	return nil
   244  }
   245  
   246  func (h *jsonTraceHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
   247  	return withAttrs(h, attrs)
   248  }
   249  
   250  func (h *jsonTraceHandler) WithGroup(name string) slog.Handler {
   251  	return withGroup(h, name)
   252  }
   253  
   254  func enabled(leveler slog.Leveler, level slog.Level) bool {
   255  	var minLevel slog.Level
   256  	if leveler != nil {
   257  		minLevel = leveler.Level()
   258  	}
   259  	return level >= minLevel
   260  }
   261  
   262  type slogDiscard struct{}
   263  
   264  func (slogDiscard) Enabled(context.Context, slog.Level) bool        { return false }
   265  func (slogDiscard) Handle(ctx context.Context, r slog.Record) error { return nil }
   266  func (slogDiscard) WithAttrs(attrs []slog.Attr) slog.Handler        { return slogDiscard{} }
   267  func (slogDiscard) WithGroup(name string) slog.Handler              { return slogDiscard{} }
   268
View as plain text