qlog_test.go

Documentation: golang.org/x/net/quic

     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 quic
     8  
     9  import (
    10  	"bytes"
    11  	"encoding/hex"
    12  	"encoding/json"
    13  	"fmt"
    14  	"io"
    15  	"log/slog"
    16  	"reflect"
    17  	"testing"
    18  	"time"
    19  
    20  	"golang.org/x/net/quic/qlog"
    21  )
    22  
    23  func TestQLogHandshake(t *testing.T) {
    24  	testSides(t, "", func(t *testing.T, side connSide) {
    25  		qr := &qlogRecord{}
    26  		tc := newTestConn(t, side, qr.config)
    27  		tc.handshake()
    28  		tc.conn.Abort(nil)
    29  		tc.wantFrame("aborting connection generates CONN_CLOSE",
    30  			packetType1RTT, debugFrameConnectionCloseTransport{
    31  				code: errNo,
    32  			})
    33  		tc.writeFrames(packetType1RTT, debugFrameConnectionCloseTransport{})
    34  		tc.advanceToTimer() // let the conn finish draining
    35  
    36  		var src, dst []byte
    37  		if side == clientSide {
    38  			src = testLocalConnID(0)
    39  			dst = testLocalConnID(-1)
    40  		} else {
    41  			src = testPeerConnID(-1)
    42  			dst = testPeerConnID(0)
    43  		}
    44  		qr.wantEvents(t, jsonEvent{
    45  			"name": "connectivity:connection_started",
    46  			"data": map[string]any{
    47  				"src_cid": hex.EncodeToString(src),
    48  				"dst_cid": hex.EncodeToString(dst),
    49  			},
    50  		}, jsonEvent{
    51  			"name": "connectivity:connection_closed",
    52  			"data": map[string]any{
    53  				"trigger": "clean",
    54  			},
    55  		})
    56  	})
    57  }
    58  
    59  func TestQLogPacketFrames(t *testing.T) {
    60  	qr := &qlogRecord{}
    61  	tc := newTestConn(t, clientSide, qr.config)
    62  	tc.handshake()
    63  	tc.conn.Abort(nil)
    64  	tc.writeFrames(packetType1RTT, debugFrameConnectionCloseTransport{})
    65  	tc.advanceToTimer() // let the conn finish draining
    66  
    67  	qr.wantEvents(t, jsonEvent{
    68  		"name": "transport:packet_sent",
    69  		"data": map[string]any{
    70  			"header": map[string]any{
    71  				"packet_type":   "initial",
    72  				"packet_number": 0,
    73  				"dcid":          hex.EncodeToString(testLocalConnID(-1)),
    74  				"scid":          hex.EncodeToString(testLocalConnID(0)),
    75  			},
    76  			"frames": []any{
    77  				map[string]any{"frame_type": "crypto"},
    78  			},
    79  		},
    80  	}, jsonEvent{
    81  		"name": "transport:packet_received",
    82  		"data": map[string]any{
    83  			"header": map[string]any{
    84  				"packet_type":   "initial",
    85  				"packet_number": 0,
    86  				"dcid":          hex.EncodeToString(testLocalConnID(0)),
    87  				"scid":          hex.EncodeToString(testPeerConnID(0)),
    88  			},
    89  			"frames": []any{map[string]any{"frame_type": "crypto"}},
    90  		},
    91  	})
    92  }
    93  
    94  func TestQLogConnectionClosedTrigger(t *testing.T) {
    95  	for _, test := range []struct {
    96  		trigger  string
    97  		connOpts []any
    98  		f        func(*testConn)
    99  	}{{
   100  		trigger: "clean",
   101  		f: func(tc *testConn) {
   102  			tc.handshake()
   103  			tc.conn.Abort(nil)
   104  		},
   105  	}, {
   106  		trigger: "handshake_timeout",
   107  		connOpts: []any{
   108  			func(c *Config) {
   109  				c.HandshakeTimeout = 5 * time.Second
   110  			},
   111  		},
   112  		f: func(tc *testConn) {
   113  			tc.ignoreFrame(frameTypeCrypto)
   114  			tc.ignoreFrame(frameTypeAck)
   115  			tc.ignoreFrame(frameTypePing)
   116  			tc.advance(5 * time.Second)
   117  		},
   118  	}, {
   119  		trigger: "idle_timeout",
   120  		connOpts: []any{
   121  			func(c *Config) {
   122  				c.MaxIdleTimeout = 5 * time.Second
   123  			},
   124  		},
   125  		f: func(tc *testConn) {
   126  			tc.handshake()
   127  			tc.advance(5 * time.Second)
   128  		},
   129  	}, {
   130  		trigger: "error",
   131  		f: func(tc *testConn) {
   132  			tc.handshake()
   133  			tc.writeFrames(packetType1RTT, debugFrameConnectionCloseTransport{
   134  				code: errProtocolViolation,
   135  			})
   136  			tc.conn.Abort(nil)
   137  		},
   138  	}} {
   139  		t.Run(test.trigger, func(t *testing.T) {
   140  			qr := &qlogRecord{}
   141  			tc := newTestConn(t, clientSide, append(test.connOpts, qr.config)...)
   142  			test.f(tc)
   143  			fr, ptype := tc.readFrame()
   144  			switch fr := fr.(type) {
   145  			case debugFrameConnectionCloseTransport:
   146  				tc.writeFrames(ptype, fr)
   147  			case nil:
   148  			default:
   149  				t.Fatalf("unexpected frame: %v", fr)
   150  			}
   151  			tc.wantIdle("connection should be idle while closing")
   152  			tc.advance(5 * time.Second) // long enough for the drain timer to expire
   153  			qr.wantEvents(t, jsonEvent{
   154  				"name": "connectivity:connection_closed",
   155  				"data": map[string]any{
   156  					"trigger": test.trigger,
   157  				},
   158  			})
   159  		})
   160  	}
   161  }
   162  
   163  func TestQLogRecovery(t *testing.T) {
   164  	qr := &qlogRecord{}
   165  	tc, s := newTestConnAndLocalStream(t, clientSide, uniStream,
   166  		permissiveTransportParameters, qr.config)
   167  
   168  	// Ignore events from the handshake.
   169  	qr.ev = nil
   170  
   171  	data := make([]byte, 16)
   172  	s.Write(data)
   173  	s.CloseWrite()
   174  	tc.wantFrame("created stream 0",
   175  		packetType1RTT, debugFrameStream{
   176  			id:   newStreamID(clientSide, uniStream, 0),
   177  			fin:  true,
   178  			data: data,
   179  		})
   180  	tc.writeAckForAll()
   181  	tc.wantIdle("connection should be idle now")
   182  
   183  	// Don't check the contents of fields, but verify that recovery metrics are logged.
   184  	qr.wantEvents(t, jsonEvent{
   185  		"name": "recovery:metrics_updated",
   186  		"data": map[string]any{
   187  			"bytes_in_flight": nil,
   188  		},
   189  	}, jsonEvent{
   190  		"name": "recovery:metrics_updated",
   191  		"data": map[string]any{
   192  			"bytes_in_flight":   0,
   193  			"congestion_window": nil,
   194  			"latest_rtt":        nil,
   195  			"min_rtt":           nil,
   196  			"rtt_variance":      nil,
   197  			"smoothed_rtt":      nil,
   198  		},
   199  	})
   200  }
   201  
   202  func TestQLogLoss(t *testing.T) {
   203  	qr := &qlogRecord{}
   204  	tc, s := newTestConnAndLocalStream(t, clientSide, uniStream,
   205  		permissiveTransportParameters, qr.config)
   206  
   207  	// Ignore events from the handshake.
   208  	qr.ev = nil
   209  
   210  	data := make([]byte, 16)
   211  	s.Write(data)
   212  	s.CloseWrite()
   213  	tc.wantFrame("created stream 0",
   214  		packetType1RTT, debugFrameStream{
   215  			id:   newStreamID(clientSide, uniStream, 0),
   216  			fin:  true,
   217  			data: data,
   218  		})
   219  
   220  	const pto = false
   221  	tc.triggerLossOrPTO(packetType1RTT, pto)
   222  
   223  	qr.wantEvents(t, jsonEvent{
   224  		"name": "recovery:packet_lost",
   225  		"data": map[string]any{
   226  			"header": map[string]any{
   227  				"packet_number": nil,
   228  				"packet_type":   "1RTT",
   229  			},
   230  		},
   231  	})
   232  }
   233  
   234  func TestQLogPacketDropped(t *testing.T) {
   235  	qr := &qlogRecord{}
   236  	tc := newTestConn(t, clientSide, permissiveTransportParameters, qr.config)
   237  	tc.handshake()
   238  
   239  	// A garbage-filled datagram with a DCID matching this connection.
   240  	dgram := bytes.Join([][]byte{
   241  		{headerFormShort | fixedBit},
   242  		testLocalConnID(0),
   243  		make([]byte, 100),
   244  		[]byte{1, 2, 3, 4}, // random data, to avoid this looking like a stateless reset
   245  	}, nil)
   246  	tc.endpoint.write(&datagram{
   247  		b: dgram,
   248  	})
   249  
   250  	qr.wantEvents(t, jsonEvent{
   251  		"name": "connectivity:packet_dropped",
   252  	})
   253  }
   254  
   255  type nopCloseWriter struct {
   256  	io.Writer
   257  }
   258  
   259  func (nopCloseWriter) Close() error { return nil }
   260  
   261  type jsonEvent map[string]any
   262  
   263  func (j jsonEvent) String() string {
   264  	b, _ := json.MarshalIndent(j, "", "  ")
   265  	return string(b)
   266  }
   267  
   268  // jsonPartialEqual compares two JSON structures.
   269  // It ignores fields not set in want (see below for specifics).
   270  func jsonPartialEqual(got, want any) (equal bool) {
   271  	cmpval := func(v any) any {
   272  		// Map certain types to a common representation.
   273  		switch v := v.(type) {
   274  		case int:
   275  			// JSON uses float64s rather than ints for numbers.
   276  			// Map int->float64 so we can use integers in expectations.
   277  			return float64(v)
   278  		case jsonEvent:
   279  			return (map[string]any)(v)
   280  		case []jsonEvent:
   281  			s := []any{}
   282  			for _, e := range v {
   283  				s = append(s, e)
   284  			}
   285  			return s
   286  		}
   287  		return v
   288  	}
   289  	if want == nil {
   290  		return true // match anything
   291  	}
   292  	got = cmpval(got)
   293  	want = cmpval(want)
   294  	if reflect.TypeOf(got) != reflect.TypeOf(want) {
   295  		return false
   296  	}
   297  	switch w := want.(type) {
   298  	case map[string]any:
   299  		// JSON object: Every field in want must match a field in got.
   300  		g := got.(map[string]any)
   301  		for k := range w {
   302  			if !jsonPartialEqual(g[k], w[k]) {
   303  				return false
   304  			}
   305  		}
   306  	case []any:
   307  		// JSON slice: Every field in want must match a field in got, in order.
   308  		// So want=[2,4] matches got=[1,2,3,4] but not [4,2].
   309  		g := got.([]any)
   310  		for _, ge := range g {
   311  			if jsonPartialEqual(ge, w[0]) {
   312  				w = w[1:]
   313  				if len(w) == 0 {
   314  					return true
   315  				}
   316  			}
   317  		}
   318  		return false
   319  	default:
   320  		if !reflect.DeepEqual(got, want) {
   321  			return false
   322  		}
   323  	}
   324  	return true
   325  }
   326  
   327  // A qlogRecord records events.
   328  type qlogRecord struct {
   329  	ev []jsonEvent
   330  }
   331  
   332  func (q *qlogRecord) Write(b []byte) (int, error) {
   333  	// This relies on the property that the Handler always makes one Write call per event.
   334  	if len(b) < 1 || b[0] != 0x1e {
   335  		panic(fmt.Errorf("trace Write should start with record separator, got %q", string(b)))
   336  	}
   337  	var val map[string]any
   338  	if err := json.Unmarshal(b[1:], &val); err != nil {
   339  		panic(fmt.Errorf("log unmarshal failure: %v\n%v", err, string(b)))
   340  	}
   341  	q.ev = append(q.ev, val)
   342  	return len(b), nil
   343  }
   344  
   345  func (q *qlogRecord) Close() error { return nil }
   346  
   347  // config may be passed to newTestConn to configure the conn to use this logger.
   348  func (q *qlogRecord) config(c *Config) {
   349  	c.QLogLogger = slog.New(qlog.NewJSONHandler(qlog.HandlerOptions{
   350  		Level: QLogLevelFrame,
   351  		NewTrace: func(info qlog.TraceInfo) (io.WriteCloser, error) {
   352  			return q, nil
   353  		},
   354  	}))
   355  }
   356  
   357  // wantEvents checks that every event in want occurs in the order specified.
   358  func (q *qlogRecord) wantEvents(t *testing.T, want ...jsonEvent) {
   359  	t.Helper()
   360  	got := q.ev
   361  	if !jsonPartialEqual(got, want) {
   362  		t.Fatalf("got events:\n%v\n\nwant events:\n%v", got, want)
   363  	}
   364  }
   365
View as plain text