Skip to content

Commit fff75ae

Browse files
GarrettGutierrez1GarrettGutierrez1
authored
channelz: log on channelz trace events and trace on channelz relevant logs. (grpc#3329)
channelz: log on channelz trace events and trace on channelz relevant logs. (grpc#3329)
1 parent a10661d commit fff75ae

17 files changed

+392
-147
lines changed

‎balancer/grpclb/grpclb_test.go

-1
Original file line numberDiff line numberDiff line change
@@ -38,7 +38,6 @@ import (
3838
lbpb "google.golang.org/grpc/balancer/grpclb/grpc_lb_v1"
3939
"google.golang.org/grpc/codes"
4040
"google.golang.org/grpc/credentials"
41-
_ "google.golang.org/grpc/grpclog/glogger"
4241
"google.golang.org/grpc/internal/grpctest"
4342
"google.golang.org/grpc/metadata"
4443
"google.golang.org/grpc/peer"

‎balancer/roundrobin/roundrobin_test.go

-1
Original file line numberDiff line numberDiff line change
@@ -31,7 +31,6 @@ import (
3131
"google.golang.org/grpc/balancer/roundrobin"
3232
"google.golang.org/grpc/codes"
3333
"google.golang.org/grpc/connectivity"
34-
_ "google.golang.org/grpc/grpclog/glogger"
3534
"google.golang.org/grpc/internal/grpctest"
3635
"google.golang.org/grpc/peer"
3736
"google.golang.org/grpc/resolver"

‎balancer_conn_wrappers.go

+2-2
Original file line numberDiff line numberDiff line change
@@ -24,8 +24,8 @@ import (
2424

2525
"google.golang.org/grpc/balancer"
2626
"google.golang.org/grpc/connectivity"
27-
"google.golang.org/grpc/grpclog"
2827
"google.golang.org/grpc/internal/buffer"
28+
"google.golang.org/grpc/internal/channelz"
2929
"google.golang.org/grpc/internal/grpcsync"
3030
"google.golang.org/grpc/resolver"
3131
)
@@ -245,7 +245,7 @@ func (acbw *acBalancerWrapper) UpdateAddresses(addrs []resolver.Address) {
245245

246246
ac, err := cc.newAddrConn(addrs, opts)
247247
if err != nil {
248-
grpclog.Warningf("acBalancerWrapper: UpdateAddresses: failed to newAddrConn: %v", err)
248+
channelz.Warningf(acbw.ac.channelzID, "acBalancerWrapper: UpdateAddresses: failed to newAddrConn: %v", err)
249249
return
250250
}
251251
acbw.ac = ac

‎channelz/service/service_test.go

+10-10
Original file line numberDiff line numberDiff line change
@@ -468,12 +468,12 @@ func (s) TestGetChannel(t *testing.T) {
468468
refNames := []string{"top channel 1", "nested channel 1", "sub channel 2", "nested channel 3"}
469469
ids := make([]int64, 4)
470470
ids[0] = channelz.RegisterChannel(&dummyChannel{}, 0, refNames[0])
471-
channelz.AddTraceEvent(ids[0], &channelz.TraceEventDesc{
471+
channelz.AddTraceEvent(ids[0], 0, &channelz.TraceEventDesc{
472472
Desc: "Channel Created",
473473
Severity: channelz.CtINFO,
474474
})
475475
ids[1] = channelz.RegisterChannel(&dummyChannel{}, ids[0], refNames[1])
476-
channelz.AddTraceEvent(ids[1], &channelz.TraceEventDesc{
476+
channelz.AddTraceEvent(ids[1], 0, &channelz.TraceEventDesc{
477477
Desc: "Channel Created",
478478
Severity: channelz.CtINFO,
479479
Parent: &channelz.TraceEventDesc{
@@ -483,7 +483,7 @@ func (s) TestGetChannel(t *testing.T) {
483483
})
484484

485485
ids[2] = channelz.RegisterSubChannel(&dummyChannel{}, ids[0], refNames[2])
486-
channelz.AddTraceEvent(ids[2], &channelz.TraceEventDesc{
486+
channelz.AddTraceEvent(ids[2], 0, &channelz.TraceEventDesc{
487487
Desc: "SubChannel Created",
488488
Severity: channelz.CtINFO,
489489
Parent: &channelz.TraceEventDesc{
@@ -492,19 +492,19 @@ func (s) TestGetChannel(t *testing.T) {
492492
},
493493
})
494494
ids[3] = channelz.RegisterChannel(&dummyChannel{}, ids[1], refNames[3])
495-
channelz.AddTraceEvent(ids[3], &channelz.TraceEventDesc{
495+
channelz.AddTraceEvent(ids[3], 0, &channelz.TraceEventDesc{
496496
Desc: "Channel Created",
497497
Severity: channelz.CtINFO,
498498
Parent: &channelz.TraceEventDesc{
499499
Desc: fmt.Sprintf("Nested Channel(id:%d) created", ids[3]),
500500
Severity: channelz.CtINFO,
501501
},
502502
})
503-
channelz.AddTraceEvent(ids[0], &channelz.TraceEventDesc{
503+
channelz.AddTraceEvent(ids[0], 0, &channelz.TraceEventDesc{
504504
Desc: fmt.Sprintf("Channel Connectivity change to %v", connectivity.Ready),
505505
Severity: channelz.CtINFO,
506506
})
507-
channelz.AddTraceEvent(ids[0], &channelz.TraceEventDesc{
507+
channelz.AddTraceEvent(ids[0], 0, &channelz.TraceEventDesc{
508508
Desc: "Resolver returns an empty address list",
509509
Severity: channelz.CtWarning,
510510
})
@@ -571,12 +571,12 @@ func (s) TestGetSubChannel(t *testing.T) {
571571
refNames := []string{"top channel 1", "sub channel 1", "socket 1", "socket 2"}
572572
ids := make([]int64, 4)
573573
ids[0] = channelz.RegisterChannel(&dummyChannel{}, 0, refNames[0])
574-
channelz.AddTraceEvent(ids[0], &channelz.TraceEventDesc{
574+
channelz.AddTraceEvent(ids[0], 0, &channelz.TraceEventDesc{
575575
Desc: "Channel Created",
576576
Severity: channelz.CtINFO,
577577
})
578578
ids[1] = channelz.RegisterSubChannel(&dummyChannel{}, ids[0], refNames[1])
579-
channelz.AddTraceEvent(ids[1], &channelz.TraceEventDesc{
579+
channelz.AddTraceEvent(ids[1], 0, &channelz.TraceEventDesc{
580580
Desc: subchanCreated,
581581
Severity: channelz.CtINFO,
582582
Parent: &channelz.TraceEventDesc{
@@ -586,11 +586,11 @@ func (s) TestGetSubChannel(t *testing.T) {
586586
})
587587
ids[2] = channelz.RegisterNormalSocket(&dummySocket{}, ids[1], refNames[2])
588588
ids[3] = channelz.RegisterNormalSocket(&dummySocket{}, ids[1], refNames[3])
589-
channelz.AddTraceEvent(ids[1], &channelz.TraceEventDesc{
589+
channelz.AddTraceEvent(ids[1], 0, &channelz.TraceEventDesc{
590590
Desc: subchanConnectivityChange,
591591
Severity: channelz.CtINFO,
592592
})
593-
channelz.AddTraceEvent(ids[1], &channelz.TraceEventDesc{
593+
channelz.AddTraceEvent(ids[1], 0, &channelz.TraceEventDesc{
594594
Desc: subChanPickNewAddress,
595595
Severity: channelz.CtINFO,
596596
})

‎clientconn.go

+23-60
Original file line numberDiff line numberDiff line change
@@ -35,7 +35,6 @@ import (
3535
"google.golang.org/grpc/codes"
3636
"google.golang.org/grpc/connectivity"
3737
"google.golang.org/grpc/credentials"
38-
"google.golang.org/grpc/grpclog"
3938
"google.golang.org/grpc/internal/backoff"
4039
"google.golang.org/grpc/internal/channelz"
4140
"google.golang.org/grpc/internal/grpcsync"
@@ -152,7 +151,7 @@ func DialContext(ctx context.Context, target string, opts ...DialOption) (conn *
152151
if channelz.IsOn() {
153152
if cc.dopts.channelzParentID != 0 {
154153
cc.channelzID = channelz.RegisterChannel(&channelzChannel{cc}, cc.dopts.channelzParentID, target)
155-
channelz.AddTraceEvent(cc.channelzID, &channelz.TraceEventDesc{
154+
channelz.AddTraceEvent(cc.channelzID, 0, &channelz.TraceEventDesc{
156155
Desc: "Channel Created",
157156
Severity: channelz.CtINFO,
158157
Parent: &channelz.TraceEventDesc{
@@ -162,10 +161,7 @@ func DialContext(ctx context.Context, target string, opts ...DialOption) (conn *
162161
})
163162
} else {
164163
cc.channelzID = channelz.RegisterChannel(&channelzChannel{cc}, 0, target)
165-
channelz.AddTraceEvent(cc.channelzID, &channelz.TraceEventDesc{
166-
Desc: "Channel Created",
167-
Severity: channelz.CtINFO,
168-
})
164+
channelz.Info(cc.channelzID, "Channel Created")
169165
}
170166
cc.csMgr.channelzID = cc.channelzID
171167
}
@@ -243,13 +239,13 @@ func DialContext(ctx context.Context, target string, opts ...DialOption) (conn *
243239

244240
// Determine the resolver to use.
245241
cc.parsedTarget = grpcutil.ParseTarget(cc.target)
246-
grpclog.Infof("parsed scheme: %q", cc.parsedTarget.Scheme)
242+
channelz.Infof(cc.channelzID, "parsed scheme: %q", cc.parsedTarget.Scheme)
247243
resolverBuilder := cc.getResolver(cc.parsedTarget.Scheme)
248244
if resolverBuilder == nil {
249245
// If resolver builder is still nil, the parsed target's scheme is
250246
// not registered. Fallback to default resolver and set Endpoint to
251247
// the original target.
252-
grpclog.Infof("scheme %q not registered, fallback to default scheme", cc.parsedTarget.Scheme)
248+
channelz.Infof(cc.channelzID, "scheme %q not registered, fallback to default scheme", cc.parsedTarget.Scheme)
253249
cc.parsedTarget = resolver.Target{
254250
Scheme: resolver.GetDefaultScheme(),
255251
Endpoint: target,
@@ -417,12 +413,7 @@ func (csm *connectivityStateManager) updateState(state connectivity.State) {
417413
return
418414
}
419415
csm.state = state
420-
if channelz.IsOn() {
421-
channelz.AddTraceEvent(csm.channelzID, &channelz.TraceEventDesc{
422-
Desc: fmt.Sprintf("Channel Connectivity change to %v", state),
423-
Severity: channelz.CtINFO,
424-
})
425-
}
416+
channelz.Infof(csm.channelzID, "Channel Connectivity change to %v", state)
426417
if csm.notifyChan != nil {
427418
// There are other goroutines waiting on this channel.
428419
close(csm.notifyChan)
@@ -672,32 +663,22 @@ func (cc *ClientConn) switchBalancer(name string) {
672663
return
673664
}
674665

675-
grpclog.Infof("ClientConn switching balancer to %q", name)
666+
channelz.Infof(cc.channelzID, "ClientConn switching balancer to %q", name)
676667
if cc.dopts.balancerBuilder != nil {
677-
grpclog.Infoln("ignoring balancer switching: Balancer DialOption used instead")
668+
channelz.Info(cc.channelzID, "ignoring balancer switching: Balancer DialOption used instead")
678669
return
679670
}
680671
if cc.balancerWrapper != nil {
681672
cc.balancerWrapper.close()
682673
}
683674

684675
builder := balancer.Get(name)
685-
if channelz.IsOn() {
686-
if builder == nil {
687-
channelz.AddTraceEvent(cc.channelzID, &channelz.TraceEventDesc{
688-
Desc: fmt.Sprintf("Channel switches to new LB policy %q due to fallback from invalid balancer name", PickFirstBalancerName),
689-
Severity: channelz.CtWarning,
690-
})
691-
} else {
692-
channelz.AddTraceEvent(cc.channelzID, &channelz.TraceEventDesc{
693-
Desc: fmt.Sprintf("Channel switches to new LB policy %q", name),
694-
Severity: channelz.CtINFO,
695-
})
696-
}
697-
}
698676
if builder == nil {
699-
grpclog.Infof("failed to get balancer builder for: %v, using pick_first instead", name)
677+
channelz.Warningf(cc.channelzID, "Channel switches to new LB policy %q due to fallback from invalid balancer name", PickFirstBalancerName)
678+
channelz.Infof(cc.channelzID, "failed to get balancer builder for: %v, using pick_first instead", name)
700679
builder = newPickfirstBuilder()
680+
} else {
681+
channelz.Infof(cc.channelzID, "Channel switches to new LB policy %q", name)
701682
}
702683

703684
cc.curBalancerName = builder.Name()
@@ -738,7 +719,7 @@ func (cc *ClientConn) newAddrConn(addrs []resolver.Address, opts balancer.NewSub
738719
}
739720
if channelz.IsOn() {
740721
ac.channelzID = channelz.RegisterSubChannel(ac, cc.channelzID, "")
741-
channelz.AddTraceEvent(ac.channelzID, &channelz.TraceEventDesc{
722+
channelz.AddTraceEvent(ac.channelzID, 0, &channelz.TraceEventDesc{
742723
Desc: "Subchannel Created",
743724
Severity: channelz.CtINFO,
744725
Parent: &channelz.TraceEventDesc{
@@ -836,7 +817,7 @@ func (ac *addrConn) connect() error {
836817
func (ac *addrConn) tryUpdateAddrs(addrs []resolver.Address) bool {
837818
ac.mu.Lock()
838819
defer ac.mu.Unlock()
839-
grpclog.Infof("addrConn: tryUpdateAddrs curAddr: %v, addrs: %v", ac.curAddr, addrs)
820+
channelz.Infof(ac.channelzID, "addrConn: tryUpdateAddrs curAddr: %v, addrs: %v", ac.curAddr, addrs)
840821
if ac.state == connectivity.Shutdown ||
841822
ac.state == connectivity.TransientFailure ||
842823
ac.state == connectivity.Idle {
@@ -856,7 +837,7 @@ func (ac *addrConn) tryUpdateAddrs(addrs []resolver.Address) bool {
856837
break
857838
}
858839
}
859-
grpclog.Infof("addrConn: tryUpdateAddrs curAddrFound: %v", curAddrFound)
840+
channelz.Infof(ac.channelzID, "addrConn: tryUpdateAddrs curAddrFound: %v", curAddrFound)
860841
if curAddrFound {
861842
ac.addrs = addrs
862843
}
@@ -1027,7 +1008,7 @@ func (cc *ClientConn) Close() error {
10271008
Severity: channelz.CtINFO,
10281009
}
10291010
}
1030-
channelz.AddTraceEvent(cc.channelzID, ted)
1011+
channelz.AddTraceEvent(cc.channelzID, 0, ted)
10311012
// TraceEvent needs to be called before RemoveEntry, as TraceEvent may add trace reference to
10321013
// the entity being deleted, and thus prevent it from being deleted right away.
10331014
channelz.RemoveEntry(cc.channelzID)
@@ -1070,15 +1051,8 @@ func (ac *addrConn) updateConnectivityState(s connectivity.State, lastErr error)
10701051
if ac.state == s {
10711052
return
10721053
}
1073-
1074-
updateMsg := fmt.Sprintf("Subchannel Connectivity change to %v", s)
10751054
ac.state = s
1076-
if channelz.IsOn() {
1077-
channelz.AddTraceEvent(ac.channelzID, &channelz.TraceEventDesc{
1078-
Desc: updateMsg,
1079-
Severity: channelz.CtINFO,
1080-
})
1081-
}
1055+
channelz.Infof(ac.channelzID, "Subchannel Connectivity change to %v", s)
10821056
ac.cc.handleSubConnStateChange(ac.acbw, s, lastErr)
10831057
}
10841058

@@ -1215,12 +1189,7 @@ func (ac *addrConn) tryAllAddrs(addrs []resolver.Address, connectDeadline time.T
12151189
}
12161190
ac.mu.Unlock()
12171191

1218-
if channelz.IsOn() {
1219-
channelz.AddTraceEvent(ac.channelzID, &channelz.TraceEventDesc{
1220-
Desc: fmt.Sprintf("Subchannel picks a new address %q to connect", addr.Addr),
1221-
Severity: channelz.CtINFO,
1222-
})
1223-
}
1192+
channelz.Infof(ac.channelzID, "Subchannel picks a new address %q to connect", addr.Addr)
12241193

12251194
newTr, reconnect, err := ac.createTransport(addr, copts, connectDeadline)
12261195
if err == nil {
@@ -1302,15 +1271,15 @@ func (ac *addrConn) createTransport(addr resolver.Address, copts transport.Conne
13021271
newTr, err := transport.NewClientTransport(connectCtx, ac.cc.ctx, target, copts, onPrefaceReceipt, onGoAway, onClose)
13031272
if err != nil {
13041273
// newTr is either nil, or closed.
1305-
grpclog.Warningf("grpc: addrConn.createTransport failed to connect to %v. Err :%v. Reconnecting...", addr, err)
1274+
channelz.Warningf(ac.channelzID, "grpc: addrConn.createTransport failed to connect to %v. Err: %v. Reconnecting...", addr, err)
13061275
return nil, nil, err
13071276
}
13081277

13091278
select {
13101279
case <-time.After(time.Until(connectDeadline)):
13111280
// We didn't get the preface in time.
13121281
newTr.Close()
1313-
grpclog.Warningf("grpc: addrConn.createTransport failed to connect to %v: didn't receive server preface in time. Reconnecting...", addr)
1282+
channelz.Warningf(ac.channelzID, "grpc: addrConn.createTransport failed to connect to %v: didn't receive server preface in time. Reconnecting...", addr)
13141283
return nil, nil, errors.New("timed out waiting for server handshake")
13151284
case <-prefaceReceived:
13161285
// We got the preface - huzzah! things are good.
@@ -1357,7 +1326,7 @@ func (ac *addrConn) startHealthCheck(ctx context.Context) {
13571326
// The health package is not imported to set health check function.
13581327
//
13591328
// TODO: add a link to the health check doc in the error message.
1360-
grpclog.Error("Health check is requested but health check function is not set.")
1329+
channelz.Error(ac.channelzID, "Health check is requested but health check function is not set.")
13611330
return
13621331
}
13631332

@@ -1387,15 +1356,9 @@ func (ac *addrConn) startHealthCheck(ctx context.Context) {
13871356
err := ac.cc.dopts.healthCheckFunc(ctx, newStream, setConnectivityState, healthCheckConfig.ServiceName)
13881357
if err != nil {
13891358
if status.Code(err) == codes.Unimplemented {
1390-
if channelz.IsOn() {
1391-
channelz.AddTraceEvent(ac.channelzID, &channelz.TraceEventDesc{
1392-
Desc: "Subchannel health check is unimplemented at server side, thus health check is disabled",
1393-
Severity: channelz.CtError,
1394-
})
1395-
}
1396-
grpclog.Error("Subchannel health check is unimplemented at server side, thus health check is disabled")
1359+
channelz.Error(ac.channelzID, "Subchannel health check is unimplemented at server side, thus health check is disabled")
13971360
} else {
1398-
grpclog.Errorf("HealthCheckFunc exits with unexpected error %v", err)
1361+
channelz.Errorf(ac.channelzID, "HealthCheckFunc exits with unexpected error %v", err)
13991362
}
14001363
}
14011364
}()
@@ -1460,7 +1423,7 @@ func (ac *addrConn) tearDown(err error) {
14601423
ac.mu.Lock()
14611424
}
14621425
if channelz.IsOn() {
1463-
channelz.AddTraceEvent(ac.channelzID, &channelz.TraceEventDesc{
1426+
channelz.AddTraceEvent(ac.channelzID, 0, &channelz.TraceEventDesc{
14641427
Desc: "Subchannel Deleted",
14651428
Severity: channelz.CtINFO,
14661429
Parent: &channelz.TraceEventDesc{

‎grpclog/glogger/glogger.go

+16
Original file line numberDiff line numberDiff line change
@@ -45,6 +45,10 @@ func (g *glogger) Infof(format string, args ...interface{}) {
4545
glog.InfoDepth(2, fmt.Sprintf(format, args...))
4646
}
4747

48+
func (g *glogger) InfoDepth(depth int, args ...interface{}) {
49+
glog.InfoDepth(depth+2, args...)
50+
}
51+
4852
func (g *glogger) Warning(args ...interface{}) {
4953
glog.WarningDepth(2, args...)
5054
}
@@ -57,6 +61,10 @@ func (g *glogger) Warningf(format string, args ...interface{}) {
5761
glog.WarningDepth(2, fmt.Sprintf(format, args...))
5862
}
5963

64+
func (g *glogger) WarningDepth(depth int, args ...interface{}) {
65+
glog.WarningDepth(depth+2, args...)
66+
}
67+
6068
func (g *glogger) Error(args ...interface{}) {
6169
glog.ErrorDepth(2, args...)
6270
}
@@ -69,6 +77,10 @@ func (g *glogger) Errorf(format string, args ...interface{}) {
6977
glog.ErrorDepth(2, fmt.Sprintf(format, args...))
7078
}
7179

80+
func (g *glogger) ErrorDepth(depth int, args ...interface{}) {
81+
glog.ErrorDepth(depth+2, args...)
82+
}
83+
7284
func (g *glogger) Fatal(args ...interface{}) {
7385
glog.FatalDepth(2, args...)
7486
}
@@ -81,6 +93,10 @@ func (g *glogger) Fatalf(format string, args ...interface{}) {
8193
glog.FatalDepth(2, fmt.Sprintf(format, args...))
8294
}
8395

96+
func (g *glogger) FatalDepth(depth int, args ...interface{}) {
97+
glog.FatalDepth(depth+2, args...)
98+
}
99+
84100
func (g *glogger) V(l int) bool {
85101
return bool(glog.V(glog.Level(l)))
86102
}

0 commit comments

Comments
 (0)