qlog_test.go

Documentation: golang.org/x/net/internal/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  	"encoding/hex"
    11  	"encoding/json"
    12  	"fmt"
    13  	"io"
    14  	"log/slog"
    15  	"reflect"
    16  	"testing"
    17  	"time"
    18  
    19  	"golang.org/x/net/internal/quic/qlog"
    20  )
    21  
    22  func TestQLogHandshake(t *testing.T) {
    23  	testSides(t, "", func(t *testing.T, side connSide) {
    24  		qr := &qlogRecord{}
    25  		tc := newTestConn(t, side, qr.config)
    26  		tc.handshake()
    27  		tc.conn.Abort(nil)
    28  		tc.wantFrame("aborting connection generates CONN_CLOSE",
    29  			packetType1RTT, debugFrameConnectionCloseTransport{
    30  				code: errNo,
    31  			})
    32  		tc.writeFrames(packetType1RTT, debugFrameConnectionCloseTransport{})
    33  		tc.advanceToTimer() // let the conn finish draining
    34  
    35  		var src, dst []byte
    36  		if side == clientSide {
    37  			src = testLocalConnID(0)
    38  			dst = testLocalConnID(-1)
    39  		} else {
    40  			src = testPeerConnID(-1)
    41  			dst = testPeerConnID(0)
    42  		}
    43  		qr.wantEvents(t, jsonEvent{
    44  			"name": "connectivity:connection_started",
    45  			"data": map[string]any{
    46  				"src_cid": hex.EncodeToString(src),
    47  				"dst_cid": hex.EncodeToString(dst),
    48  			},
    49  		}, jsonEvent{
    50  			"name": "connectivity:connection_closed",
    51  			"data": map[string]any{
    52  				"trigger": "clean",
    53  			},
    54  		})
    55  	})
    56  }
    57  
    58  func TestQLogPacketFrames(t *testing.T) {
    59  	qr := &qlogRecord{}
    60  	tc := newTestConn(t, clientSide, qr.config)
    61  	tc.handshake()
    62  	tc.conn.Abort(nil)
    63  	tc.writeFrames(packetType1RTT, debugFrameConnectionCloseTransport{})
    64  	tc.advanceToTimer() // let the conn finish draining
    65  
    66  	qr.wantEvents(t, jsonEvent{
    67  		"name": "transport:packet_sent",
    68  		"data": map[string]any{
    69  			"header": map[string]any{
    70  				"packet_type":   "initial",
    71  				"packet_number": 0,
    72  				"dcid":          hex.EncodeToString(testLocalConnID(-1)),
    73  				"scid":          hex.EncodeToString(testLocalConnID(0)),
    74  			},
    75  			"frames": []any{
    76  				map[string]any{"frame_type": "crypto"},
    77  			},
    78  		},
    79  	}, jsonEvent{
    80  		"name": "transport:packet_received",
    81  		"data": map[string]any{
    82  			"header": map[string]any{
    83  				"packet_type":   "initial",
    84  				"packet_number": 0,
    85  				"dcid":          hex.EncodeToString(testLocalConnID(0)),
    86  				"scid":          hex.EncodeToString(testPeerConnID(0)),
    87  			},
    88  			"frames": []any{map[string]any{"frame_type": "crypto"}},
    89  		},
    90  	})
    91  }
    92  
    93  func TestQLogConnectionClosedTrigger(t *testing.T) {
    94  	for _, test := range []struct {
    95  		trigger  string
    96  		connOpts []any
    97  		f        func(*testConn)
    98  	}{{
    99  		trigger: "clean",
   100  		f: func(tc *testConn) {
   101  			tc.handshake()
   102  			tc.conn.Abort(nil)
   103  		},
   104  	}, {
   105  		trigger: "handshake_timeout",
   106  		connOpts: []any{
   107  			func(c *Config) {
   108  				c.HandshakeTimeout = 5 * time.Second
   109  			},
   110  		},
   111  		f: func(tc *testConn) {
   112  			tc.ignoreFrame(frameTypeCrypto)
   113  			tc.ignoreFrame(frameTypeAck)
   114  			tc.ignoreFrame(frameTypePing)
   115  			tc.advance(5 * time.Second)
   116  		},
   117  	}, {
   118  		trigger: "idle_timeout",
   119  		connOpts: []any{
   120  			func(c *Config) {
   121  				c.MaxIdleTimeout = 5 * time.Second
   122  			},
   123  		},
   124  		f: func(tc *testConn) {
   125  			tc.handshake()
   126  			tc.advance(5 * time.Second)
   127  		},
   128  	}, {
   129  		trigger: "error",
   130  		f: func(tc *testConn) {
   131  			tc.handshake()
   132  			tc.writeFrames(packetType1RTT, debugFrameConnectionCloseTransport{
   133  				code: errProtocolViolation,
   134  			})
   135  			tc.conn.Abort(nil)
   136  		},
   137  	}} {
   138  		t.Run(test.trigger, func(t *testing.T) {
   139  			qr := &qlogRecord{}
   140  			tc := newTestConn(t, clientSide, append(test.connOpts, qr.config)...)
   141  			test.f(tc)
   142  			fr, ptype := tc.readFrame()
   143  			switch fr := fr.(type) {
   144  			case debugFrameConnectionCloseTransport:
   145  				tc.writeFrames(ptype, fr)
   146  			case nil:
   147  			default:
   148  				t.Fatalf("unexpected frame: %v", fr)
   149  			}
   150  			tc.wantIdle("connection should be idle while closing")
   151  			tc.advance(5 * time.Second) // long enough for the drain timer to expire
   152  			qr.wantEvents(t, jsonEvent{
   153  				"name": "connectivity:connection_closed",
   154  				"data": map[string]any{
   155  					"trigger": test.trigger,
   156  				},
   157  			})
   158  		})
   159  	}
   160  }
   161  
   162  type nopCloseWriter struct {
   163  	io.Writer
   164  }
   165  
   166  func (nopCloseWriter) Close() error { return nil }
   167  
   168  type jsonEvent map[string]any
   169  
   170  func (j jsonEvent) String() string {
   171  	b, _ := json.MarshalIndent(j, "", "  ")
   172  	return string(b)
   173  }
   174  
   175  // jsonPartialEqual compares two JSON structures.
   176  // It ignores fields not set in want (see below for specifics).
   177  func jsonPartialEqual(got, want any) (equal bool) {
   178  	cmpval := func(v any) any {
   179  		// Map certain types to a common representation.
   180  		switch v := v.(type) {
   181  		case int:
   182  			// JSON uses float64s rather than ints for numbers.
   183  			// Map int->float64 so we can use integers in expectations.
   184  			return float64(v)
   185  		case jsonEvent:
   186  			return (map[string]any)(v)
   187  		case []jsonEvent:
   188  			s := []any{}
   189  			for _, e := range v {
   190  				s = append(s, e)
   191  			}
   192  			return s
   193  		}
   194  		return v
   195  	}
   196  	got = cmpval(got)
   197  	want = cmpval(want)
   198  	if reflect.TypeOf(got) != reflect.TypeOf(want) {
   199  		return false
   200  	}
   201  	switch w := want.(type) {
   202  	case nil:
   203  		// Match anything.
   204  	case map[string]any:
   205  		// JSON object: Every field in want must match a field in got.
   206  		g := got.(map[string]any)
   207  		for k := range w {
   208  			if !jsonPartialEqual(g[k], w[k]) {
   209  				return false
   210  			}
   211  		}
   212  	case []any:
   213  		// JSON slice: Every field in want must match a field in got, in order.
   214  		// So want=[2,4] matches got=[1,2,3,4] but not [4,2].
   215  		g := got.([]any)
   216  		for _, ge := range g {
   217  			if jsonPartialEqual(ge, w[0]) {
   218  				w = w[1:]
   219  				if len(w) == 0 {
   220  					return true
   221  				}
   222  			}
   223  		}
   224  		return false
   225  	default:
   226  		if !reflect.DeepEqual(got, want) {
   227  			return false
   228  		}
   229  	}
   230  	return true
   231  }
   232  
   233  // A qlogRecord records events.
   234  type qlogRecord struct {
   235  	ev []jsonEvent
   236  }
   237  
   238  func (q *qlogRecord) Write(b []byte) (int, error) {
   239  	// This relies on the property that the Handler always makes one Write call per event.
   240  	if len(b) < 1 || b[0] != 0x1e {
   241  		panic(fmt.Errorf("trace Write should start with record separator, got %q", string(b)))
   242  	}
   243  	var val map[string]any
   244  	if err := json.Unmarshal(b[1:], &val); err != nil {
   245  		panic(fmt.Errorf("log unmarshal failure: %v\n%v", err, string(b)))
   246  	}
   247  	q.ev = append(q.ev, val)
   248  	return len(b), nil
   249  }
   250  
   251  func (q *qlogRecord) Close() error { return nil }
   252  
   253  // config may be passed to newTestConn to configure the conn to use this logger.
   254  func (q *qlogRecord) config(c *Config) {
   255  	c.QLogLogger = slog.New(qlog.NewJSONHandler(qlog.HandlerOptions{
   256  		Level: QLogLevelFrame,
   257  		NewTrace: func(info qlog.TraceInfo) (io.WriteCloser, error) {
   258  			return q, nil
   259  		},
   260  	}))
   261  }
   262  
   263  // wantEvents checks that every event in want occurs in the order specified.
   264  func (q *qlogRecord) wantEvents(t *testing.T, want ...jsonEvent) {
   265  	t.Helper()
   266  	got := q.ev
   267  	if !jsonPartialEqual(got, want) {
   268  		t.Fatalf("got events:\n%v\n\nwant events:\n%v", got, want)
   269  	}
   270  }
   271
View as plain text