trpc.group/trpc-go/trpc-go@v1.0.3/rpcz/readonlyspan_test.go (about)

     1  //
     2  //
     3  // Tencent is pleased to support the open source community by making tRPC available.
     4  //
     5  // Copyright (C) 2023 THL A29 Limited, a Tencent company.
     6  // All rights reserved.
     7  //
     8  // If you have downloaded a copy of the tRPC source code from Tencent,
     9  // please note that tRPC source code is licensed under the  Apache 2.0 License,
    10  // A copy of the Apache 2.0 License is included in this file.
    11  //
    12  //
    13  
    14  package rpcz
    15  
    16  import (
    17  	"fmt"
    18  	"testing"
    19  	"time"
    20  
    21  	"github.com/stretchr/testify/require"
    22  )
    23  
    24  var (
    25  	// currentTime use to replace time.Now() for reproducibility in unit test.
    26  	currentTime, _ = time.Parse(time.StampMicro, "Nov 24 15:34:08.151326")
    27  	clientSpan     = &ReadOnlySpan{
    28  		Name:      "client",
    29  		StartTime: currentTime,
    30  		EndTime:   currentTime.Add(30 * time.Second),
    31  		Attributes: []Attribute{
    32  			{
    33  				Name:  "RPCName",
    34  				Value: "/trpc.testing.end2end.TestTRPC/EmptyCall",
    35  			},
    36  			{
    37  				Name:  "Error",
    38  				Value: fmt.Errorf(""),
    39  			},
    40  			{
    41  				Name: TRPCAttributeFilterNames,
    42  				Value: []string{
    43  					"1",
    44  					"2",
    45  					"3",
    46  				},
    47  			},
    48  		},
    49  		ChildSpans: []*ReadOnlySpan{
    50  			{
    51  				Name:      "1",
    52  				StartTime: currentTime.Add(1 * time.Second),
    53  				EndTime:   currentTime.Add(29 * time.Second),
    54  				ChildSpans: []*ReadOnlySpan{
    55  					{
    56  						Name:      "2",
    57  						StartTime: currentTime.Add(2 * time.Second),
    58  						EndTime:   currentTime.Add(28 * time.Second),
    59  						ChildSpans: []*ReadOnlySpan{
    60  							{
    61  								Name:      "3",
    62  								StartTime: currentTime.Add(3 * time.Second),
    63  								EndTime:   currentTime.Add(27 * time.Second),
    64  								ChildSpans: []*ReadOnlySpan{
    65  									{
    66  										Name:      "CallFunc",
    67  										StartTime: currentTime.Add(4 * time.Second),
    68  										EndTime:   currentTime.Add(26 * time.Second),
    69  										ChildSpans: []*ReadOnlySpan{
    70  											{
    71  												Name:      "Marshal",
    72  												StartTime: currentTime.Add(5 * time.Second),
    73  												EndTime:   currentTime.Add(6 * time.Second),
    74  											},
    75  											{
    76  												Name:      "Compress",
    77  												StartTime: currentTime.Add(7 * time.Second),
    78  												EndTime:   currentTime.Add(8 * time.Second),
    79  											},
    80  											{
    81  												Name:      "EncodeProtocolHead",
    82  												StartTime: currentTime.Add(9 * time.Second),
    83  												EndTime:   currentTime.Add(10 * time.Second),
    84  											},
    85  											{
    86  												Name:      "SendMessage",
    87  												StartTime: currentTime.Add(11 * time.Second),
    88  												EndTime:   currentTime.Add(12 * time.Second),
    89  											},
    90  											{
    91  												Name:      "ReceiveMessage",
    92  												StartTime: currentTime.Add(13 * time.Second),
    93  												EndTime:   currentTime.Add(14 * time.Second),
    94  											},
    95  											{
    96  												Name:      "DecodeProtocolHead",
    97  												StartTime: currentTime.Add(15 * time.Second),
    98  												EndTime:   currentTime.Add(16 * time.Second),
    99  											},
   100  											{
   101  												Name:      "Decompress",
   102  												StartTime: currentTime.Add(17 * time.Second),
   103  												EndTime:   currentTime.Add(18 * time.Second),
   104  											},
   105  											{
   106  												Name:      "Unmarshal",
   107  												StartTime: currentTime.Add(19 * time.Second),
   108  												EndTime:   currentTime.Add(20 * time.Second),
   109  											},
   110  										},
   111  									},
   112  								},
   113  							},
   114  						},
   115  					},
   116  				},
   117  			},
   118  		},
   119  	}
   120  	serverSpan = &ReadOnlySpan{
   121  		Name:      "server",
   122  		StartTime: currentTime,
   123  		EndTime:   currentTime.Add(30 * time.Second),
   124  		Attributes: []Attribute{
   125  			{
   126  				Name:  "RPCName",
   127  				Value: "/trpc.testing.end2end.TestTRPC/EmptyCall",
   128  			},
   129  			{
   130  				Name:  "Error",
   131  				Value: fmt.Errorf(""),
   132  			},
   133  			{
   134  				Name:  "RequestSize",
   135  				Value: 125,
   136  			},
   137  			{
   138  				Name:  "ResponseSize",
   139  				Value: 18,
   140  			},
   141  		},
   142  		ChildSpans: []*ReadOnlySpan{
   143  			{
   144  				Name:      "DecodeProtocolHead",
   145  				StartTime: currentTime.Add(1 * time.Second),
   146  				EndTime:   currentTime.Add(2 * time.Second),
   147  			},
   148  			{
   149  				Name:      "Decompress",
   150  				StartTime: currentTime.Add(3 * time.Second),
   151  				EndTime:   currentTime.Add(4 * time.Second),
   152  			},
   153  			{
   154  				Name:      "Unmarshal",
   155  				StartTime: currentTime.Add(5 * time.Second),
   156  				EndTime:   currentTime.Add(6 * time.Second),
   157  			},
   158  			{
   159  				Name:      "filter1",
   160  				StartTime: currentTime.Add(7 * time.Second),
   161  				EndTime:   currentTime.Add(20 * time.Second),
   162  				ChildSpans: []*ReadOnlySpan{
   163  					{
   164  						Name:      "filter2",
   165  						StartTime: currentTime.Add(8 * time.Second),
   166  						EndTime:   currentTime.Add(19 * time.Second),
   167  						ChildSpans: []*ReadOnlySpan{
   168  							{
   169  								Name:      "filter3",
   170  								StartTime: currentTime.Add(9 * time.Second),
   171  								EndTime:   currentTime.Add(18 * time.Second),
   172  								ChildSpans: []*ReadOnlySpan{
   173  									{
   174  										Name:      "HandleFunc",
   175  										StartTime: currentTime.Add(10 * time.Second),
   176  										EndTime:   currentTime.Add(17 * time.Second),
   177  									},
   178  								},
   179  							},
   180  						},
   181  					},
   182  				},
   183  			},
   184  			{
   185  				Name:      "Marshal",
   186  				StartTime: currentTime.Add(21 * time.Second),
   187  				EndTime:   currentTime.Add(22 * time.Second),
   188  			},
   189  			{
   190  				Name:      "Compress",
   191  				StartTime: currentTime.Add(23 * time.Second),
   192  				EndTime:   currentTime.Add(24 * time.Second),
   193  			},
   194  			{
   195  				Name:      "EncodeProtocolHead",
   196  				StartTime: currentTime.Add(25 * time.Second),
   197  				EndTime:   currentTime.Add(26 * time.Second),
   198  			},
   199  			{
   200  				Name:      "SendMessage",
   201  				StartTime: currentTime.Add(27 * time.Second),
   202  				EndTime:   currentTime.Add(28 * time.Second),
   203  			},
   204  		},
   205  	}
   206  	serverSpanHasClientChildSpan = &ReadOnlySpan{
   207  		Name:      "server",
   208  		StartTime: currentTime,
   209  		EndTime:   currentTime.Add(30 * time.Second),
   210  		ChildSpans: []*ReadOnlySpan{
   211  			{
   212  				Name:      "DecodeProtocolHead",
   213  				StartTime: currentTime.Add(1 * time.Second),
   214  				EndTime:   currentTime.Add(2 * time.Second),
   215  			},
   216  			{
   217  				Name:      "Decompress",
   218  				StartTime: currentTime.Add(3 * time.Second),
   219  				EndTime:   currentTime.Add(4 * time.Second),
   220  			},
   221  			{
   222  				Name:      "Unmarshal",
   223  				StartTime: currentTime.Add(5 * time.Second),
   224  				EndTime:   currentTime.Add(6 * time.Second),
   225  			},
   226  			{
   227  				Name:      "",
   228  				StartTime: currentTime.Add(7 * time.Second),
   229  				EndTime:   currentTime.Add(20 * time.Second),
   230  				ChildSpans: []*ReadOnlySpan{
   231  					{
   232  						Name:      "",
   233  						StartTime: currentTime.Add(8 * time.Second),
   234  						EndTime:   currentTime.Add(19 * time.Second),
   235  						ChildSpans: []*ReadOnlySpan{
   236  							{
   237  								Name:      "",
   238  								StartTime: currentTime.Add(9 * time.Second),
   239  								EndTime:   currentTime.Add(18 * time.Second),
   240  								ChildSpans: []*ReadOnlySpan{
   241  									{
   242  										Name:      "HandleFunc",
   243  										StartTime: currentTime.Add(10 * time.Second),
   244  										EndTime:   currentTime.Add(17 * time.Second),
   245  										ChildSpans: []*ReadOnlySpan{
   246  											clientSpan, clientSpan,
   247  										},
   248  									},
   249  								},
   250  							},
   251  						},
   252  					},
   253  				},
   254  			},
   255  			{
   256  				Name:      "Marshal",
   257  				StartTime: currentTime.Add(21 * time.Second),
   258  				EndTime:   currentTime.Add(22 * time.Second),
   259  			},
   260  			{
   261  				Name:      "Compress",
   262  				StartTime: currentTime.Add(23 * time.Second),
   263  				EndTime:   currentTime.Add(24 * time.Second),
   264  			},
   265  			{
   266  				Name:      "EncodeProtocolHead",
   267  				StartTime: currentTime.Add(25 * time.Second),
   268  				EndTime:   currentTime.Add(26 * time.Second),
   269  			},
   270  			{
   271  				Name:      "SendMessage",
   272  				StartTime: currentTime.Add(27 * time.Second),
   273  				EndTime:   currentTime.Add(28 * time.Second),
   274  			},
   275  		},
   276  	}
   277  	serverSpanHasEvents = &ReadOnlySpan{
   278  		Name:      "server",
   279  		StartTime: currentTime,
   280  		EndTime:   currentTime.Add(30 * time.Second),
   281  		Attributes: []Attribute{
   282  			{
   283  				Name:  "RPCName",
   284  				Value: "/trpc.testing.end2end.TestTRPC/EmptyCall",
   285  			},
   286  			{
   287  				Name:  "Error",
   288  				Value: fmt.Errorf(""),
   289  			},
   290  			{
   291  				Name:  "RequestSize",
   292  				Value: 125,
   293  			},
   294  			{
   295  				Name:  "ResponseSize",
   296  				Value: 18,
   297  			},
   298  		},
   299  		Events: []Event{
   300  			{
   301  				Name: "enter DecodeProtocolHead",
   302  				Time: currentTime.Add(500 * time.Millisecond),
   303  			},
   304  			{
   305  				Name: "handle DecodeProtocolHead",
   306  				Time: currentTime.Add(1500 * time.Millisecond),
   307  			},
   308  			{
   309  				Name: "leave DecodeProtocolHead, enter Decompress",
   310  				Time: currentTime.Add(2500 * time.Millisecond),
   311  			},
   312  			{
   313  				Name: "handle Decompress",
   314  				Time: currentTime.Add(3500 * time.Millisecond),
   315  			},
   316  			{
   317  				Name: "leave Decompress, enter Unmarshal",
   318  				Time: currentTime.Add(4500 * time.Millisecond),
   319  			},
   320  		},
   321  		ChildSpans: []*ReadOnlySpan{
   322  			{
   323  				Name:      "DecodeProtocolHead",
   324  				StartTime: currentTime.Add(1 * time.Second),
   325  				EndTime:   currentTime.Add(2 * time.Second),
   326  			},
   327  			{
   328  				Name:      "Decompress",
   329  				StartTime: currentTime.Add(3 * time.Second),
   330  				EndTime:   currentTime.Add(4 * time.Second),
   331  			},
   332  			{
   333  				Name:      "Unmarshal",
   334  				StartTime: currentTime.Add(5 * time.Second),
   335  				EndTime:   currentTime.Add(6 * time.Second),
   336  			},
   337  			{
   338  				Name:      "filter1",
   339  				StartTime: currentTime.Add(7 * time.Second),
   340  				EndTime:   currentTime.Add(20 * time.Second),
   341  				ChildSpans: []*ReadOnlySpan{
   342  					{
   343  						Name:      "HandleFunc",
   344  						StartTime: currentTime.Add(10 * time.Second),
   345  						EndTime:   currentTime.Add(17 * time.Second),
   346  					},
   347  				},
   348  			},
   349  			{
   350  				Name:      "Marshal",
   351  				StartTime: currentTime.Add(21 * time.Second),
   352  				EndTime:   currentTime.Add(22 * time.Second),
   353  			},
   354  			{
   355  				Name:      "Compress",
   356  				StartTime: currentTime.Add(23 * time.Second),
   357  				EndTime:   currentTime.Add(24 * time.Second),
   358  			},
   359  			{
   360  				Name:      "EncodeProtocolHead",
   361  				StartTime: currentTime.Add(25 * time.Second),
   362  				EndTime:   currentTime.Add(26 * time.Second),
   363  			},
   364  			{
   365  				Name:      "SendMessage",
   366  				StartTime: currentTime.Add(27 * time.Second),
   367  				EndTime:   currentTime.Add(28 * time.Second),
   368  			},
   369  		},
   370  	}
   371  )
   372  
   373  func TestReadOnlySpan_PrintDetail(t *testing.T) {
   374  	t.Run("client span", func(t *testing.T) {
   375  		require.Equal(
   376  			t,
   377  			`span: (client, 0)
   378    time: (Nov 24 15:34:08.151326, Nov 24 15:34:38.151326)
   379    duration: (0, 30s, 0)
   380    attributes: (RPCName, /trpc.testing.end2end.TestTRPC/EmptyCall),(Error, )
   381    span: (1, 0)
   382      time: (Nov 24 15:34:09.151326, Nov 24 15:34:37.151326)
   383      duration: (1s, 28s, 1s)
   384      span: (2, 0)
   385        time: (Nov 24 15:34:10.151326, Nov 24 15:34:36.151326)
   386        duration: (1s, 26s, 1s)
   387        span: (3, 0)
   388          time: (Nov 24 15:34:11.151326, Nov 24 15:34:35.151326)
   389          duration: (1s, 24s, 1s)
   390          span: (CallFunc, 0)
   391            time: (Nov 24 15:34:12.151326, Nov 24 15:34:34.151326)
   392            duration: (1s, 22s, 1s)
   393            span: (Marshal, 0)
   394              time: (Nov 24 15:34:13.151326, Nov 24 15:34:14.151326)
   395              duration: (1s, 1s, 20s)
   396            span: (Compress, 0)
   397              time: (Nov 24 15:34:15.151326, Nov 24 15:34:16.151326)
   398              duration: (3s, 1s, 18s)
   399            span: (EncodeProtocolHead, 0)
   400              time: (Nov 24 15:34:17.151326, Nov 24 15:34:18.151326)
   401              duration: (5s, 1s, 16s)
   402            span: (SendMessage, 0)
   403              time: (Nov 24 15:34:19.151326, Nov 24 15:34:20.151326)
   404              duration: (7s, 1s, 14s)
   405            span: (ReceiveMessage, 0)
   406              time: (Nov 24 15:34:21.151326, Nov 24 15:34:22.151326)
   407              duration: (9s, 1s, 12s)
   408            span: (DecodeProtocolHead, 0)
   409              time: (Nov 24 15:34:23.151326, Nov 24 15:34:24.151326)
   410              duration: (11s, 1s, 10s)
   411            span: (Decompress, 0)
   412              time: (Nov 24 15:34:25.151326, Nov 24 15:34:26.151326)
   413              duration: (13s, 1s, 8s)
   414            span: (Unmarshal, 0)
   415              time: (Nov 24 15:34:27.151326, Nov 24 15:34:28.151326)
   416              duration: (15s, 1s, 6s)
   417  `,
   418  			clientSpan.PrintDetail(""),
   419  		)
   420  
   421  	})
   422  	t.Run("server span without proxy at service impl function", func(t *testing.T) {
   423  		require.Equal(
   424  			t,
   425  			`span: (server, 0)
   426    time: (Nov 24 15:34:08.151326, Nov 24 15:34:38.151326)
   427    duration: (0, 30s, 0)
   428    attributes: (RPCName, /trpc.testing.end2end.TestTRPC/EmptyCall),(Error, ),(RequestSize, 125),(ResponseSize, 18)
   429    span: (DecodeProtocolHead, 0)
   430      time: (Nov 24 15:34:09.151326, Nov 24 15:34:10.151326)
   431      duration: (1s, 1s, 28s)
   432    span: (Decompress, 0)
   433      time: (Nov 24 15:34:11.151326, Nov 24 15:34:12.151326)
   434      duration: (3s, 1s, 26s)
   435    span: (Unmarshal, 0)
   436      time: (Nov 24 15:34:13.151326, Nov 24 15:34:14.151326)
   437      duration: (5s, 1s, 24s)
   438    span: (filter1, 0)
   439      time: (Nov 24 15:34:15.151326, Nov 24 15:34:28.151326)
   440      duration: (7s, 13s, 10s)
   441      span: (filter2, 0)
   442        time: (Nov 24 15:34:16.151326, Nov 24 15:34:27.151326)
   443        duration: (1s, 11s, 1s)
   444        span: (filter3, 0)
   445          time: (Nov 24 15:34:17.151326, Nov 24 15:34:26.151326)
   446          duration: (1s, 9s, 1s)
   447          span: (HandleFunc, 0)
   448            time: (Nov 24 15:34:18.151326, Nov 24 15:34:25.151326)
   449            duration: (1s, 7s, 1s)
   450    span: (Marshal, 0)
   451      time: (Nov 24 15:34:29.151326, Nov 24 15:34:30.151326)
   452      duration: (21s, 1s, 8s)
   453    span: (Compress, 0)
   454      time: (Nov 24 15:34:31.151326, Nov 24 15:34:32.151326)
   455      duration: (23s, 1s, 6s)
   456    span: (EncodeProtocolHead, 0)
   457      time: (Nov 24 15:34:33.151326, Nov 24 15:34:34.151326)
   458      duration: (25s, 1s, 4s)
   459    span: (SendMessage, 0)
   460      time: (Nov 24 15:34:35.151326, Nov 24 15:34:36.151326)
   461      duration: (27s, 1s, 2s)
   462  `,
   463  			serverSpan.PrintDetail(""),
   464  		)
   465  	})
   466  }
   467  
   468  func TestReadOnlySpan_PrintDetailServerWithProxy(t *testing.T) {
   469  	require.Equal(
   470  		t,
   471  		`span: (server, 0)
   472    time: (Nov 24 15:34:08.151326, Nov 24 15:34:38.151326)
   473    duration: (0, 30s, 0)
   474    span: (DecodeProtocolHead, 0)
   475      time: (Nov 24 15:34:09.151326, Nov 24 15:34:10.151326)
   476      duration: (1s, 1s, 28s)
   477    span: (Decompress, 0)
   478      time: (Nov 24 15:34:11.151326, Nov 24 15:34:12.151326)
   479      duration: (3s, 1s, 26s)
   480    span: (Unmarshal, 0)
   481      time: (Nov 24 15:34:13.151326, Nov 24 15:34:14.151326)
   482      duration: (5s, 1s, 24s)
   483    span: (, 0)
   484      time: (Nov 24 15:34:15.151326, Nov 24 15:34:28.151326)
   485      duration: (7s, 13s, 10s)
   486      span: (, 0)
   487        time: (Nov 24 15:34:16.151326, Nov 24 15:34:27.151326)
   488        duration: (1s, 11s, 1s)
   489        span: (, 0)
   490          time: (Nov 24 15:34:17.151326, Nov 24 15:34:26.151326)
   491          duration: (1s, 9s, 1s)
   492          span: (HandleFunc, 0)
   493            time: (Nov 24 15:34:18.151326, Nov 24 15:34:25.151326)
   494            duration: (1s, 7s, 1s)
   495            span: (client, 0)
   496              time: (Nov 24 15:34:08.151326, Nov 24 15:34:38.151326)
   497              duration: (-10s, 30s, -13s)
   498              attributes: (RPCName, /trpc.testing.end2end.TestTRPC/EmptyCall),(Error, )
   499              span: (1, 0)
   500                time: (Nov 24 15:34:09.151326, Nov 24 15:34:37.151326)
   501                duration: (1s, 28s, 1s)
   502                span: (2, 0)
   503                  time: (Nov 24 15:34:10.151326, Nov 24 15:34:36.151326)
   504                  duration: (1s, 26s, 1s)
   505                  span: (3, 0)
   506                    time: (Nov 24 15:34:11.151326, Nov 24 15:34:35.151326)
   507                    duration: (1s, 24s, 1s)
   508                    span: (CallFunc, 0)
   509                      time: (Nov 24 15:34:12.151326, Nov 24 15:34:34.151326)
   510                      duration: (1s, 22s, 1s)
   511                      span: (Marshal, 0)
   512                        time: (Nov 24 15:34:13.151326, Nov 24 15:34:14.151326)
   513                        duration: (1s, 1s, 20s)
   514                      span: (Compress, 0)
   515                        time: (Nov 24 15:34:15.151326, Nov 24 15:34:16.151326)
   516                        duration: (3s, 1s, 18s)
   517                      span: (EncodeProtocolHead, 0)
   518                        time: (Nov 24 15:34:17.151326, Nov 24 15:34:18.151326)
   519                        duration: (5s, 1s, 16s)
   520                      span: (SendMessage, 0)
   521                        time: (Nov 24 15:34:19.151326, Nov 24 15:34:20.151326)
   522                        duration: (7s, 1s, 14s)
   523                      span: (ReceiveMessage, 0)
   524                        time: (Nov 24 15:34:21.151326, Nov 24 15:34:22.151326)
   525                        duration: (9s, 1s, 12s)
   526                      span: (DecodeProtocolHead, 0)
   527                        time: (Nov 24 15:34:23.151326, Nov 24 15:34:24.151326)
   528                        duration: (11s, 1s, 10s)
   529                      span: (Decompress, 0)
   530                        time: (Nov 24 15:34:25.151326, Nov 24 15:34:26.151326)
   531                        duration: (13s, 1s, 8s)
   532                      span: (Unmarshal, 0)
   533                        time: (Nov 24 15:34:27.151326, Nov 24 15:34:28.151326)
   534                        duration: (15s, 1s, 6s)
   535            span: (client, 0)
   536              time: (Nov 24 15:34:08.151326, Nov 24 15:34:38.151326)
   537              duration: (-10s, 30s, -13s)
   538              attributes: (RPCName, /trpc.testing.end2end.TestTRPC/EmptyCall),(Error, )
   539              span: (1, 0)
   540                time: (Nov 24 15:34:09.151326, Nov 24 15:34:37.151326)
   541                duration: (1s, 28s, 1s)
   542                span: (2, 0)
   543                  time: (Nov 24 15:34:10.151326, Nov 24 15:34:36.151326)
   544                  duration: (1s, 26s, 1s)
   545                  span: (3, 0)
   546                    time: (Nov 24 15:34:11.151326, Nov 24 15:34:35.151326)
   547                    duration: (1s, 24s, 1s)
   548                    span: (CallFunc, 0)
   549                      time: (Nov 24 15:34:12.151326, Nov 24 15:34:34.151326)
   550                      duration: (1s, 22s, 1s)
   551                      span: (Marshal, 0)
   552                        time: (Nov 24 15:34:13.151326, Nov 24 15:34:14.151326)
   553                        duration: (1s, 1s, 20s)
   554                      span: (Compress, 0)
   555                        time: (Nov 24 15:34:15.151326, Nov 24 15:34:16.151326)
   556                        duration: (3s, 1s, 18s)
   557                      span: (EncodeProtocolHead, 0)
   558                        time: (Nov 24 15:34:17.151326, Nov 24 15:34:18.151326)
   559                        duration: (5s, 1s, 16s)
   560                      span: (SendMessage, 0)
   561                        time: (Nov 24 15:34:19.151326, Nov 24 15:34:20.151326)
   562                        duration: (7s, 1s, 14s)
   563                      span: (ReceiveMessage, 0)
   564                        time: (Nov 24 15:34:21.151326, Nov 24 15:34:22.151326)
   565                        duration: (9s, 1s, 12s)
   566                      span: (DecodeProtocolHead, 0)
   567                        time: (Nov 24 15:34:23.151326, Nov 24 15:34:24.151326)
   568                        duration: (11s, 1s, 10s)
   569                      span: (Decompress, 0)
   570                        time: (Nov 24 15:34:25.151326, Nov 24 15:34:26.151326)
   571                        duration: (13s, 1s, 8s)
   572                      span: (Unmarshal, 0)
   573                        time: (Nov 24 15:34:27.151326, Nov 24 15:34:28.151326)
   574                        duration: (15s, 1s, 6s)
   575    span: (Marshal, 0)
   576      time: (Nov 24 15:34:29.151326, Nov 24 15:34:30.151326)
   577      duration: (21s, 1s, 8s)
   578    span: (Compress, 0)
   579      time: (Nov 24 15:34:31.151326, Nov 24 15:34:32.151326)
   580      duration: (23s, 1s, 6s)
   581    span: (EncodeProtocolHead, 0)
   582      time: (Nov 24 15:34:33.151326, Nov 24 15:34:34.151326)
   583      duration: (25s, 1s, 4s)
   584    span: (SendMessage, 0)
   585      time: (Nov 24 15:34:35.151326, Nov 24 15:34:36.151326)
   586      duration: (27s, 1s, 2s)
   587  `,
   588  		serverSpanHasClientChildSpan.PrintDetail(""),
   589  	)
   590  }
   591  
   592  func TestReadOnlySpan_PrintSketch(t *testing.T) {
   593  	t.Run("client span", func(t *testing.T) {
   594  		require.Equal(
   595  			t,
   596  			`span: (client, 0)
   597    time: (Nov 24 15:34:08.151326, Nov 24 15:34:38.151326)
   598    duration: (0, 30s, 0)
   599    attributes: (RPCName, /trpc.testing.end2end.TestTRPC/EmptyCall),(Error, )
   600  `,
   601  			clientSpan.PrintSketch(""),
   602  		)
   603  	})
   604  	t.Run("server span", func(t *testing.T) {
   605  		require.Equal(
   606  			t,
   607  			`span: (server, 0)
   608    time: (Nov 24 15:34:08.151326, Nov 24 15:34:38.151326)
   609    duration: (0, 30s, 0)
   610    attributes: (RPCName, /trpc.testing.end2end.TestTRPC/EmptyCall),(Error, ),(RequestSize, 125),(ResponseSize, 18)
   611  `,
   612  			serverSpan.PrintSketch(""),
   613  		)
   614  	})
   615  }
   616  
   617  func TestParentSpanContainUnfinishedChildSpan(t *testing.T) {
   618  	t.Run("record root span to rpcz", func(t *testing.T) {
   619  		rpcz := NewRPCZ(&Config{Capacity: 10})
   620  		const (
   621  			spanID   = SpanID(1)
   622  			spanName = "server"
   623  		)
   624  		ps := newSpan(spanName, spanID, rpcz)
   625  		require.False(t, ps.startTime.IsZero())
   626  		ps.startTime = currentTime
   627  
   628  		cs, end := ps.NewChild("client")
   629  		require.False(t, cs.(*span).startTime.IsZero())
   630  		cs.(*span).startTime = currentTime.Add(time.Second)
   631  
   632  		ps.End()
   633  		require.False(t, ps.endTime.IsZero())
   634  		ps.endTime = currentTime.Add(3 * time.Second)
   635  
   636  		readOnlySpan, ok := rpcz.Query(spanID)
   637  		require.True(t, ok)
   638  		require.Contains(t, readOnlySpan.PrintDetail(""), "duration: (1s, unknown, unknown)")
   639  
   640  		end.End()
   641  		require.False(t, cs.(*span).endTime.IsZero())
   642  		cs.(*span).endTime = currentTime.Add(2 * time.Second)
   643  		readOnlySpan, ok = rpcz.Query(spanID)
   644  		require.True(t, ok)
   645  		require.NotContains(t, readOnlySpan.PrintDetail(""), "unknown")
   646  	})
   647  }
   648  
   649  func TestSpanHasEvents(t *testing.T) {
   650  	require.Equal(
   651  		t,
   652  		`span: (server, 0)
   653    time: (Nov 24 15:34:08.151326, Nov 24 15:34:38.151326)
   654    duration: (0, 30s, 0)
   655    attributes: (RPCName, /trpc.testing.end2end.TestTRPC/EmptyCall),(Error, ),(RequestSize, 125),(ResponseSize, 18)
   656    event: (enter DecodeProtocolHead, Nov 24 15:34:08.651326)
   657    span: (DecodeProtocolHead, 0)
   658      time: (Nov 24 15:34:09.151326, Nov 24 15:34:10.151326)
   659      duration: (1s, 1s, 28s)
   660    event: (handle DecodeProtocolHead, Nov 24 15:34:09.651326)
   661    event: (leave DecodeProtocolHead, enter Decompress, Nov 24 15:34:10.651326)
   662    span: (Decompress, 0)
   663      time: (Nov 24 15:34:11.151326, Nov 24 15:34:12.151326)
   664      duration: (3s, 1s, 26s)
   665    event: (handle Decompress, Nov 24 15:34:11.651326)
   666    event: (leave Decompress, enter Unmarshal, Nov 24 15:34:12.651326)
   667    span: (Unmarshal, 0)
   668      time: (Nov 24 15:34:13.151326, Nov 24 15:34:14.151326)
   669      duration: (5s, 1s, 24s)
   670    span: (filter1, 0)
   671      time: (Nov 24 15:34:15.151326, Nov 24 15:34:28.151326)
   672      duration: (7s, 13s, 10s)
   673      span: (HandleFunc, 0)
   674        time: (Nov 24 15:34:18.151326, Nov 24 15:34:25.151326)
   675        duration: (3s, 7s, 3s)
   676    span: (Marshal, 0)
   677      time: (Nov 24 15:34:29.151326, Nov 24 15:34:30.151326)
   678      duration: (21s, 1s, 8s)
   679    span: (Compress, 0)
   680      time: (Nov 24 15:34:31.151326, Nov 24 15:34:32.151326)
   681      duration: (23s, 1s, 6s)
   682    span: (EncodeProtocolHead, 0)
   683      time: (Nov 24 15:34:33.151326, Nov 24 15:34:34.151326)
   684      duration: (25s, 1s, 4s)
   685    span: (SendMessage, 0)
   686      time: (Nov 24 15:34:35.151326, Nov 24 15:34:36.151326)
   687      duration: (27s, 1s, 2s)
   688  `,
   689  		serverSpanHasEvents.PrintDetail(""),
   690  	)
   691  
   692  	s := newSpan("client", 1, nil)
   693  	s.AddEvent("send request")
   694  	s.AddEvent("receive response")
   695  	content := s.convertedToReadOnlySpan().PrintDetail("")
   696  	require.Contains(t, content, "event: (send request,")
   697  	require.Contains(t, content, "event: (receive response,")
   698  }