Skip to content

Commit 959af53

Browse files
authored
transport: set current timestamp in channelz socket metrics (#9109)
RELEASE NOTES: - channelz: Fix `LastMessageSentTimestamp` and `LastMessageReceivedTimestamp` in `SocketMetrics` to contain the correct timestamp
1 parent 94b9449 commit 959af53

4 files changed

Lines changed: 218 additions & 2 deletions

File tree

internal/transport/http2_server.go

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -44,6 +44,7 @@ import (
4444
"google.golang.org/grpc/internal/pretty"
4545
istatus "google.golang.org/grpc/internal/status"
4646
"google.golang.org/grpc/internal/syscall"
47+
transportinternal "google.golang.org/grpc/internal/transport/internal"
4748
"google.golang.org/grpc/mem"
4849

4950
"google.golang.org/grpc/codes"
@@ -1448,14 +1449,14 @@ func (t *http2Server) socketMetrics() *channelz.EphemeralSocketMetrics {
14481449
func (t *http2Server) incrMsgSent() {
14491450
if channelz.IsOn() {
14501451
t.channelz.SocketMetrics.MessagesSent.Add(1)
1451-
t.channelz.SocketMetrics.LastMessageSentTimestamp.Add(1)
1452+
t.channelz.SocketMetrics.LastMessageSentTimestamp.Store(transportinternal.TimeNowFunc())
14521453
}
14531454
}
14541455

14551456
func (t *http2Server) incrMsgRecv() {
14561457
if channelz.IsOn() {
14571458
t.channelz.SocketMetrics.MessagesReceived.Add(1)
1458-
t.channelz.SocketMetrics.LastMessageReceivedTimestamp.Add(1)
1459+
t.channelz.SocketMetrics.LastMessageReceivedTimestamp.Store(transportinternal.TimeNowFunc())
14591460
}
14601461
}
14611462

Lines changed: 25 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,25 @@
1+
/*
2+
*
3+
* Copyright 2026 gRPC authors.
4+
*
5+
* Licensed under the Apache License, Version 2.0 (the "License");
6+
* you may not use this file except in compliance with the License.
7+
* You may obtain a copy of the License at
8+
*
9+
* http://www.apache.org/licenses/LICENSE-2.0
10+
*
11+
* Unless required by applicable law or agreed to in writing, software
12+
* distributed under the License is distributed on an "AS IS" BASIS,
13+
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
14+
* See the License for the specific language governing permissions and
15+
* limitations under the License.
16+
*
17+
*/
18+
19+
// Package internal contains functionality internal to the transport package.
20+
package internal
21+
22+
// TimeNowFunc is a variable that can be set to override the default behavior of
23+
// getting the current time in nanoseconds. It is used in transport code to set
24+
// channelz timestamps, and is exposed here for testing purposes.
25+
var TimeNowFunc func() int64
Lines changed: 185 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,185 @@
1+
/*
2+
*
3+
* Copyright 2026 gRPC authors.
4+
*
5+
* Licensed under the Apache License, Version 2.0 (the "License");
6+
* you may not use this file except in compliance with the License.
7+
* You may obtain a copy of the License at
8+
*
9+
* http://www.apache.org/licenses/LICENSE-2.0
10+
*
11+
* Unless required by applicable law or agreed to in writing, software
12+
* distributed under the License is distributed on an "AS IS" BASIS,
13+
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
14+
* See the License for the specific language governing permissions and
15+
* limitations under the License.
16+
*
17+
*/
18+
19+
package transport_test
20+
21+
import (
22+
"context"
23+
"fmt"
24+
"io"
25+
"sync/atomic"
26+
"testing"
27+
"time"
28+
29+
"google.golang.org/grpc/internal"
30+
"google.golang.org/grpc/internal/channelz"
31+
"google.golang.org/grpc/internal/stubserver"
32+
transportinternal "google.golang.org/grpc/internal/transport/internal"
33+
34+
testgrpc "google.golang.org/grpc/interop/grpc_testing"
35+
testpb "google.golang.org/grpc/interop/grpc_testing"
36+
)
37+
38+
func overrideTimeNowFunc(t *testing.T, f func() int64) {
39+
orig := transportinternal.TimeNowFunc
40+
transportinternal.TimeNowFunc = f
41+
t.Cleanup(func() { transportinternal.TimeNowFunc = orig })
42+
}
43+
44+
func verifyResultWithDelay(ctx context.Context, f func() (bool, error)) error {
45+
var lastErr error
46+
for ; ctx.Err() == nil; <-time.After(10 * time.Millisecond) {
47+
var ok bool
48+
if ok, lastErr = f(); ok {
49+
return nil
50+
}
51+
}
52+
return fmt.Errorf("Timeout when waiting for channelz to contain expected data. Last seen error: %v", lastErr)
53+
}
54+
55+
func (s) TestChannelz_ServerSocketMetricsLastMessageTimestamps(t *testing.T) {
56+
channelz.TurnOn()
57+
defer internal.ChannelzTurnOffForTesting()
58+
59+
// Override timeNowFunc for the duration of the test.
60+
var curTime atomic.Int64
61+
overrideTimeNowFunc(t, func() int64 {
62+
curTime.Add(1)
63+
return curTime.Load()
64+
})
65+
66+
ctx, cancel := context.WithTimeout(context.Background(), defaultTestTimeout)
67+
defer cancel()
68+
69+
// Start a stub server that echoes back messages sent by the client. This
70+
// allows us to test both LastMessageReceivedTimestamp and
71+
// LastMessageSentTimestamp on the server side.
72+
var blockBeforeSend = make(chan struct{}, 1)
73+
ss := &stubserver.StubServer{
74+
FullDuplexCallF: func(stream testgrpc.TestService_FullDuplexCallServer) error {
75+
for {
76+
req, err := stream.Recv()
77+
if err == io.EOF {
78+
return nil
79+
}
80+
if err != nil {
81+
return err
82+
}
83+
select {
84+
case <-blockBeforeSend:
85+
case <-ctx.Done():
86+
return ctx.Err()
87+
}
88+
if err := stream.Send(&testpb.StreamingOutputCallResponse{Payload: req.GetPayload()}); err != nil {
89+
return err
90+
}
91+
}
92+
},
93+
}
94+
if err := ss.Start(nil); err != nil {
95+
t.Fatalf("Failed to start test server: %v", err)
96+
}
97+
defer ss.Stop()
98+
99+
// Wait for the server to be up and registered with channelz.
100+
var svrID int64
101+
if err := verifyResultWithDelay(ctx, func() (bool, error) {
102+
ssrvs, _ := channelz.GetServers(0, 0)
103+
for _, s := range ssrvs {
104+
for id := range s.ListenSockets() {
105+
skt := channelz.GetSocket(id)
106+
if skt != nil && skt.LocalAddr.String() == ss.Address {
107+
svrID = s.ID
108+
return true, nil
109+
}
110+
}
111+
}
112+
return false, fmt.Errorf("could not find server with address %s in channelz", ss.Address)
113+
}); err != nil {
114+
t.Fatal(err)
115+
}
116+
117+
stream, err := ss.Client.FullDuplexCall(ctx)
118+
if err != nil {
119+
t.Fatalf("FullDuplexCall() failed: %v", err)
120+
}
121+
122+
// Wait for the message from the client to be received on the server and
123+
// timestamp updated.
124+
wantTimestamp := int64(1)
125+
if err := stream.Send(&testpb.StreamingOutputCallRequest{}); err != nil {
126+
t.Fatalf("stream.Send(_) = %v, want <nil>", err)
127+
}
128+
if err := verifyResultWithDelay(ctx, func() (bool, error) {
129+
ns, _ := channelz.GetServerSockets(svrID, 0, 0)
130+
if len(ns) == 0 {
131+
return false, fmt.Errorf("no server sockets found")
132+
}
133+
sktData := &ns[0].SocketMetrics
134+
if sktData.MessagesReceived.Load() < 1 {
135+
return false, fmt.Errorf("server has not received any messages yet")
136+
}
137+
if gotTimestamp := sktData.LastMessageReceivedTimestamp.Load(); gotTimestamp != wantTimestamp {
138+
return false, fmt.Errorf("LastMessageReceivedTimestamp is %d, want %d", gotTimestamp, wantTimestamp)
139+
}
140+
return true, nil
141+
}); err != nil {
142+
t.Fatal(err)
143+
}
144+
145+
blockBeforeSend <- struct{}{}
146+
147+
// Wait for the message to be sent by the server and timestamp updated.
148+
if _, err := stream.Recv(); err != nil {
149+
t.Fatalf("stream.Recv() = %v, want <nil>", err)
150+
}
151+
wantTimestamp = int64(2)
152+
if err := verifyResultWithDelay(ctx, func() (bool, error) {
153+
ns, _ := channelz.GetServerSockets(svrID, 0, 0)
154+
sktData := &ns[0].SocketMetrics
155+
if sktData.MessagesSent.Load() == 0 {
156+
return false, fmt.Errorf("server has not sent any messages yet")
157+
}
158+
if gotTimestamp := sktData.LastMessageSentTimestamp.Load(); gotTimestamp != wantTimestamp {
159+
return false, fmt.Errorf("LastMessageSentTimestamp = %d, want = %d", gotTimestamp, wantTimestamp)
160+
}
161+
return true, nil
162+
}); err != nil {
163+
t.Fatal(err)
164+
}
165+
166+
// Send another message to verify that LastMessageReceivedTimestamp is
167+
// updated again.
168+
if err := stream.Send(&testpb.StreamingOutputCallRequest{}); err != nil {
169+
t.Fatalf("stream.Send(_) = %v, want <nil>", err)
170+
}
171+
wantTimestamp = int64(3)
172+
if err := verifyResultWithDelay(ctx, func() (bool, error) {
173+
ns, _ := channelz.GetServerSockets(svrID, 0, 0)
174+
sktData := &ns[0].SocketMetrics
175+
if sktData.MessagesReceived.Load() < 2 {
176+
return false, fmt.Errorf("server has not received second message yet")
177+
}
178+
if gotTimestamp := sktData.LastMessageReceivedTimestamp.Load(); gotTimestamp != wantTimestamp {
179+
return false, fmt.Errorf("LastMessageReceivedTimestamp is %d, want %d", gotTimestamp, wantTimestamp)
180+
}
181+
return true, nil
182+
}); err != nil {
183+
t.Fatal(err)
184+
}
185+
}

internal/transport/transport.go

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -35,6 +35,7 @@ import (
3535
"google.golang.org/grpc/codes"
3636
"google.golang.org/grpc/credentials"
3737
"google.golang.org/grpc/internal/channelz"
38+
"google.golang.org/grpc/internal/transport/internal"
3839
"google.golang.org/grpc/keepalive"
3940
"google.golang.org/grpc/mem"
4041
"google.golang.org/grpc/metadata"
@@ -46,6 +47,10 @@ import (
4647

4748
const logLevel = 2
4849

50+
func init() {
51+
internal.TimeNowFunc = func() int64 { return time.Now().UnixNano() }
52+
}
53+
4954
// recvMsg represents the received msg from the transport. All transport
5055
// protocol specific info has been removed.
5156
type recvMsg struct {

0 commit comments

Comments
 (0)