channelz: include channelz identifier in logs #5192

easwars · 2022-02-10T23:17:41Z

Summary of changes:

channelz package
- Define an opaque Identifier to uniquely identify entities in the channelz database.
  - This type will be returned from RegisterXxx functions and will be accepted by log/trace functions.
- Make RegisterXxx and RemoveEntry functions work gracefully when channelz is not turned ON.
- logging functions will prefix channel identifiers to all log messages
Change the WithChannelzParentID dialoption to accept a *channelz.Identifier.
Change ChannelzParentID field in balancer.BuildOptions to be of type *channelz.Identifier.
Define a type alias in the external channelz package pointing to the identifier type defined in internal channelz package. This is required since the channelz identifier can be specified through a DialOption and through balancer.BuildOptions.
Cleanup some channelz tests.

RELEASE NOTES:

TBD

easwars · 2022-02-11T22:50:52Z

Sample new output:

easwars@easwars-macbookpro3:grpc-go $ go test google.golang.org/grpc/test -run Test/CZChannelAddressResolutionChange -v -count=1
=== RUN   Test
=== RUN   Test/CZChannelAddressResolutionChange
    channelz_test.go:1578: Running test in tcp-clear environment...
    tlogger.go:116: INFO clientconn.go:106 [core] Channel(id:2) created  (t=+2.625959ms)
    tlogger.go:116: INFO clientconn.go:1624 [core] [Channel #2] original dial target is: "whatever:///localhost:53417"  (t=+2.696964ms)
    tlogger.go:116: INFO clientconn.go:1631 [core] [Channel #2] parsed dial target is: {Scheme:whatever Authority: Endpoint:localhost:53417 URL:{Scheme:whatever Opaque: User: Host: Path:/localhost:53417 RawPath: ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+2.7737ms)
    tlogger.go:116: INFO clientconn.go:260 [core] [Channel #2] Channel authority set to "localhost:53417"  (t=+2.791539ms)
    tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #2] Resolver state updated: {
          "Addresses": [
            {
              "Addr": "localhost:53417",
              "ServerName": "",
              "Attributes": null,
              "BalancerAttributes": null,
              "Type": 0,
              "Metadata": null
            } 
          ],
          "ServiceConfig": null,
          "Attributes": null
        } (resolver returned new addresses)  (t=+3.019052ms)
    tlogger.go:116: INFO clientconn.go:710 [core] [Channel #2] ClientConn switching balancer to "pick_first"  (t=+3.063565ms)
    tlogger.go:116: INFO clientconn.go:730 [core] [Channel #2] Channel switches to new LB policy "pick_first"  (t=+3.110774ms)
    tlogger.go:116: INFO clientconn.go:775 [core] Subchannel(id:4) created  (t=+3.145144ms)
    tlogger.go:116: INFO clientconn.go:775 [core] Subchannel(id:4) created  (t=+3.155856ms)
    tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #2] Resolver state updated: {
          "Addresses": [
            {
              "Addr": "localhost:53417",
              "ServerName": "",
              "Attributes": null,
              "BalancerAttributes": null,
              "Type": 0,
              "Metadata": null
            } 
          ],
          "ServiceConfig": {
            "Config": {
              "Config": null,
              "LB": "round_robin",
              "Methods": {}
            },
            "Err": null
          },
          "Attributes": null
        } (service config updated)  (t=+3.293836ms)
    tlogger.go:116: INFO clientconn.go:710 [core] [Channel #2] ClientConn switching balancer to "round_robin"  (t=+3.31081ms)
    tlogger.go:116: INFO clientconn.go:730 [core] [Channel #2] Channel switches to new LB policy "round_robin"  (t=+3.345689ms)
    tlogger.go:116: INFO clientconn.go:1145 [core] [Channel #2 SubChannel #4] Subchannel Connectivity change to CONNECTING  (t=+3.396241ms)
    tlogger.go:116: INFO clientconn.go:775 [core] Subchannel(id:5) created  (t=+3.502475ms)
    tlogger.go:116: INFO clientconn.go:775 [core] Subchannel(id:5) created  (t=+3.5557ms)
    tlogger.go:116: INFO clientconn.go:1256 [core] [Channel #2 SubChannel #4] Subchannel picks a new address "localhost:53417" to connect  (t=+3.677217ms)
    tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #2] Resolver state updated: {
          "Addresses": [
            {
              "Addr": "localhost:53417",
              "ServerName": "",
              "Attributes": null,
              "BalancerAttributes": null,
              "Type": 0,
              "Metadata": null
            } 
          ],
          "ServiceConfig": {
            "Config": {
              "Config": null,
              "LB": null,
              "Methods": {
                "/grpc.testing.TestService/EmptyCall": {
                  "WaitForReady": false,
                  "Timeout": 1000000,
                  "MaxReqSize": null,
                  "MaxRespSize": null,
                  "RetryPolicy": null
                }
              }
            },
            "Err": null
          },
          "Attributes": null
        } (service config updated)  (t=+3.792369ms)
    tlogger.go:116: INFO clientconn.go:710 [core] [Channel #2] ClientConn switching balancer to "pick_first"  (t=+3.878329ms)
    tlogger.go:116: INFO clientconn.go:1145 [core] [Channel #2 SubChannel #4] Subchannel Connectivity change to SHUTDOWN  (t=+3.911966ms)
    tlogger.go:116: INFO clientconn.go:1145 [core] [Channel #2 SubChannel #5] Subchannel Connectivity change to CONNECTING  (t=+3.95491ms)
    tlogger.go:116: INFO clientconn.go:730 [core] [Channel #2] Channel switches to new LB policy "pick_first"  (t=+3.990968ms)
    tlogger.go:116: INFO clientconn.go:775 [core] Subchannel(id:6) created  (t=+4.049364ms)
    tlogger.go:116: INFO clientconn.go:775 [core] Subchannel(id:6) created  (t=+4.068165ms)
    tlogger.go:116: INFO clientconn.go:1502 [core] Subchannel(id:4) deleted  (t=+4.157582ms)
    tlogger.go:116: INFO clientconn.go:1502 [core] Subchannel(id:4) deleted  (t=+4.171082ms)
    tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #2] Resolver state updated: {
          "Addresses": [],
          "ServiceConfig": {
            "Config": {
              "Config": null,
              "LB": null,
              "Methods": {
                "/grpc.testing.TestService/EmptyCall": {
                  "WaitForReady": false,
                  "Timeout": 1000000, 
                  "MaxReqSize": null, 
                  "MaxRespSize": null,
                  "RetryPolicy": null 
                }
              }
            },
            "Err": null
          },
          "Attributes": null
        } (resolver returned an empty address list)  (t=+4.205262ms)
    tlogger.go:116: INFO clientconn.go:415 [core] [Channel #2] Channel Connectivity change to TRANSIENT_FAILURE  (t=+4.266614ms)
    tlogger.go:116: INFO clientconn.go:1145 [core] [Channel #2 SubChannel #6] Subchannel Connectivity change to CONNECTING  (t=+4.314414ms)
    tlogger.go:116: INFO clientconn.go:1256 [core] [Channel #2 SubChannel #5] Subchannel picks a new address "localhost:53417" to connect  (t=+4.388689ms)
    tlogger.go:116: INFO clientconn.go:1145 [core] [Channel #2 SubChannel #5] Subchannel Connectivity change to SHUTDOWN  (t=+4.474886ms)
    tlogger.go:116: INFO clientconn.go:415 [core] [Channel #2] Channel Connectivity change to SHUTDOWN  (t=+4.495081ms)
    tlogger.go:116: INFO clientconn.go:1256 [core] [Channel #2 SubChannel #6] Subchannel picks a new address "localhost:53417" to connect  (t=+4.521638ms)
    tlogger.go:116: INFO clientconn.go:1502 [core] Subchannel(id:5) deleted  (t=+4.627133ms)
    tlogger.go:116: INFO clientconn.go:1502 [core] Subchannel(id:5) deleted  (t=+4.645405ms)
    tlogger.go:116: INFO clientconn.go:1145 [core] [Channel #2 SubChannel #6] Subchannel Connectivity change to SHUTDOWN  (t=+4.715508ms)
    tlogger.go:116: INFO clientconn.go:1502 [core] Subchannel(id:6) deleted  (t=+4.802514ms)
    tlogger.go:116: INFO clientconn.go:1502 [core] Subchannel(id:6) deleted  (t=+4.820853ms)
    tlogger.go:116: INFO clientconn.go:1100 [core] Channel(id:2) deleted  (t=+4.836578ms)

easwars · 2022-02-11T22:59:18Z

There is a small inconsistency between logs which show up as a result of calling one of the log functions to the ones which show up as a result of calling the trace function.

This is from the trace function:

    tlogger.go:116: INFO clientconn.go:1502 [core] Subchannel(id:5) deleted  (t=+4.645405ms)

This is from the log function with the prefix.

    tlogger.go:116: INFO clientconn.go:1145 [core] [Channel #2 SubChannel #6] Subchannel Connectivity change to SHUTDOWN  (t=+4.715508ms)

Based on our offline discussion, I initially attempted to remove calls to AddTraceEvent from clientconn.go etc and have them just call the logging functions. But tracing function actually adds a dependency between the parent and the child and this is checked in some of the channelz tests. So, I ended up not doing it.

So, this small inconsistency exists. But I think, this is still better than what we have currently, and we can possibly address it in the future.

menghanl · 2022-02-11T23:03:49Z

Why are two log lines for subchannel created/deleted? E.g.

    tlogger.go:116: INFO clientconn.go:775 [core] Subchannel(id:4) created  (t=+3.145144ms)
    tlogger.go:116: INFO clientconn.go:775 [core] Subchannel(id:4) created  (t=+3.155856ms)

easwars · 2022-02-11T23:08:57Z

Why are two log lines for subchannel created/deleted? E.g.

    tlogger.go:116: INFO clientconn.go:775 [core] Subchannel(id:4) created  (t=+3.145144ms)
    tlogger.go:116: INFO clientconn.go:775 [core] Subchannel(id:4) created  (t=+3.155856ms)

We add a trace event on the subChannel with an event on the parent. The AddTraceEvent function logs every trace description. So, it logs the one for the subChannel and the one for the channel. We can modify the message so that it looks different, by maybe including the channel ID for the event on the parent. What do you think?

menghanl · 2022-02-11T23:26:35Z

Maybe the parent can say "creating"?
[channel #2] creating subchannel(id:4)

easwars · 2022-02-11T23:32:21Z

Maybe the parent can say "creating"? [channel #2] creating subchannel(id:4)

The [channel #2] prefix is added by the log functions. The tracing routines are unable to do that since the log function also eventually calls the tracing function, so we would end up getting the same prefix twice.

Also, having the trace function add similar prefix is slightly tricky since it has to the same the same for the parent as well, and it will have to look up the channelz database to determine the parent and do this. If you think it is worth it, I can try doing it.

menghanl · 2022-02-16T22:23:11Z

clientconn.go

-			cc.channelzID = channelz.RegisterChannel(&channelzChannel{cc}, 0, target)
-			channelz.Info(logger, cc.channelzID, "Channel Created")
+	pid := cc.dopts.channelzParentID
+	cc.channelzID = channelz.RegisterChannel(&channelzChannel{cc}, pid, target)


If channelz is not turned on, those IDs will all be nil, and then the logs will all have [channel(id:0)], right?

Actually, they all have [] (empty string)

tlogger.go:116: INFO clientconn.go:106 [core] Channel(id:0) created (t=+498.514µs) tlogger.go:116: INFO clientconn.go:1624 [core] [] original dial target is: "whatever:///test.server" (t=+559.064µs)

Maybe we can generate channelz IDs even if channelz is off. It's just a self incrementing int anyway.

Made the change to generate channelz IDs even when channelz is OFF. This also required changes to some tests. I've captured these changes as a separate commit. 786e6be

Did you try deleting the ==nil checks in channelz ID's methods?
Should all channelz IDs be non-nil now? Maybe not true in tests. But still might be interesting to try.

menghanl · 2022-02-16T22:51:54Z

clientconn.go

@@ -1319,7 +1321,7 @@ func (ac *addrConn) createTransport(addr resolver.Address, copts transport.Conne
 	newTr, err := transport.NewClientTransport(connectCtx, ac.cc.ctx, addr, copts, func() { prefaceReceived.Fire() }, onGoAway, onClose)
 	if err != nil {
 		// newTr is either nil, or closed.
-		channelz.Warningf(logger, ac.channelzID, "grpc: addrConn.createTransport failed to connect to %v. Err: %v", addr, err)
+		channelz.Warningf(logger, ac.channelzID, "grpc: addrConn.createTransport failed to connect to %s. Err: %v", pretty.ToJSON(addr), err)


What's before and after?

And maybe define a String() on Address (it can be implemented as pretty.ToJSON)?

On inconsistency between channelz.Warningf and channelz.AddTraceEvent.
I don't even remember why we need channelz.Warningf. Can't they all just call channelz.AddTraceEvent?

Implemented a String() method on Address which calls pretty.ToJSON.

With regards to channelz.Warningf vs channelz.AddTraceEvent, I think the former is much easier to call, and we seem to be using the latter only when we want to trace event on a child to add a reference in the parent as well (or the other way around).

channelz.Warningf and channelz.AddTraceEvent are almost the same I think. AddTraceEvent just copy the Warningf parameters to a struct.
I'm OK to keep Warningf as a thin wrapper, and so it looks more like logging.

How about the IsOn() checks in Warningf? Can those be deleted?
AddTraceEvent also checks IsOn() anyway.

Made the logging funcs thin wrappers around AddTraceEvent.

menghanl · 2022-02-16T22:56:51Z

clientconn.go

-		channelz.AddTraceEvent(logger, ac.channelzID, 0, &channelz.TraceEventDesc{
-			Desc:     "Subchannel Deleted",
+	channelz.AddTraceEvent(logger, ac.channelzID, 0, &channelz.TraceEventDesc{
+		Desc:     fmt.Sprintf("Subchannel(id:%d) deleted", ac.channelzID.Int()),


The id part in the Desc seems to be duplicate with the other parameter ac.channelzID.
And this Desc is also used in channelz trace events. So you will see in subchannel 2's events, one called subchannel 2 deleted.

Can channelz.AddTraceEvent prepend the channelz ID before calling log?

Can channelz.AddTraceEvent prepend the channelz ID before calling log?

The issue is that the implementation of the logging functions call AddTraceEvent. And the prepend the channelz ID in the logging functions.

The other issue is that trace events have pointers to parent events. But these dont have the parent's ID.

Can we change it so that the channelz ID is prepended before calling the real logging functions (grpclog's logging functions)?

And parent is optional, right?

Yes, parent is optional. And we specify parent in trace descriptions in only very few cases:

nested channel add/delete

subchannel add/delete

I pushed a commit to change prepending of ID to be done right before the actual calling function. But this still doesn't help with duplicate entries like this:

tlogger.go:116: INFO clientconn.go:1499 [core] [Channel #1 Channel #2 SubChannel #3] Subchannel(id:3) deleted (t=+1.623202ms) tlogger.go:116: INFO clientconn.go:1499 [core] [Channel #1 Channel #2 SubChannel #3] Subchannel(id:3) deleted (t=+1.632913ms)

Or almost duplicate entries like this:

tlogger.go:116: INFO clientconn.go:1099 [core] [Channel #1 Channel #2] Channel(id:2) deleted (t=+1.660121ms) tlogger.go:116: INFO clientconn.go:1099 [core] [Channel #1 Channel #2] Nested channel(id:2) deleted (t=+1.691113ms)

The reason for the above is because we specify a parent trace description. And in the first log output, the trace description on the actual entity and the parent are the same Subchannel(id:3) deleted. And since we cannot determine the parent ID in AddTraceEvent, we end up printing the parent's trace description also with the child's ID.

A few options to make things better:

Get rid of including the parent information in the ID. But include some other detail (like target name for channel, IP address for subchannel etc). This would mean that the following print

tlogger.go:116: INFO clientconn.go:1499 [core] [Channel #1 Channel #2 SubChannel #3] Subchannel(id:3) deleted (t=+1.623202ms)

would instead look something like:

tlogger.go:116: INFO clientconn.go:1499 [core] [SubChannel #3 IP-Address] Subchannel(id:3) deleted (t=+1.623202ms)

This will still not get rid of the duplicate entry. But it will make the description for every entity a little bit more meaningful, and the option below helps with duplicate entries.

When including parent trace descriptions, ensure that the entries are not duplicate. So, when creating a subChannel for example, on the actual subchannel, we can say something like:

[SubChannel #3 IP-Address] Subchannel(id:3) created

and for the parent trace description, we can include information about the parent in the message itself. So, it would be something like this:

[SubChannel #3] Subchannel(id:3) created within Channel(id:2)

What do you think?

internal/channelz/funcs.go

internal/channelz/id.go

server.go

menghanl

LGTM except for the ongoing discussion in previous comments.

easwars · 2022-02-18T00:08:52Z

Made the changes discussed in our offline discussion:

AddTraceEvent will log only the bottom most event
The trace events which include will not include the id in the description of the entity. So, subChannel creation log will look like:

    tlogger.go:116: INFO clientconn.go:774 [core] [Channel #1 Channel #2 SubChannel #3] Subchannel created  (t=+1.002757ms)

And there will not be a duplicate entry. The trace description added on the parent will include the id of the child though, this still makes sense from the perspective of someone looking at channelz traces.

menghanl

LGTM. Can you post the new logs after the change?

menghanl · 2022-02-18T00:19:13Z

And another reason to not include IPs for SubChannel: the IP can change.

easwars · 2022-02-18T00:29:33Z

LGTM. Can you post the new logs after the change?

easwars@easwars-macbookpro3:grpc-go $ go test google.golang.org/grpc/test -run Test/CZChannelAddressResolutionChange -v -count=1
=== RUN   Test
=== RUN   Test/CZChannelAddressResolutionChange
    channelz_test.go:1578: Running test in tcp-clear environment...
    tlogger.go:116: INFO server.go:588 [core] [Server #1] Server created  (t=+2.637637ms)
    tlogger.go:116: INFO clientconn.go:105 [core] [Channel #2] Channel created  (t=+2.750886ms)
    tlogger.go:116: INFO clientconn.go:1621 [core] [Channel #2] original dial target is: "whatever:///localhost:56424"  (t=+2.862607ms)
    tlogger.go:116: INFO server.go:776 [core] [Server #1 ListenSocket #3] ListenSocket created  (t=+2.887146ms)
    tlogger.go:116: INFO clientconn.go:1628 [core] [Channel #2] parsed dial target is: {Scheme:whatever Authority: Endpoint:localhost:56424 URL:{Scheme:whatever Opaque: User: Host: Path:/localhost:56424 RawPath: ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+2.986547ms)
    tlogger.go:116: INFO clientconn.go:259 [core] [Channel #2] Channel authority set to "localhost:56424"  (t=+3.018305ms)
    tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #2] Resolver state updated: {
          "Addresses": [
            {
              "Addr": "localhost:56424",
              "ServerName": "",
              "Attributes": null,
              "BalancerAttributes": null,
              "Type": 0,
              "Metadata": null
            } 
          ],
          "ServiceConfig": null,
          "Attributes": null
        } (resolver returned new addresses)  (t=+3.244212ms)
    tlogger.go:116: INFO clientconn.go:709 [core] [Channel #2] ClientConn switching balancer to "pick_first"  (t=+3.266469ms)
    tlogger.go:116: INFO clientconn.go:729 [core] [Channel #2] Channel switches to new LB policy "pick_first"  (t=+3.318412ms)
    tlogger.go:116: INFO clientconn.go:774 [core] [Channel #2 SubChannel #4] Subchannel created  (t=+3.369847ms)
    tlogger.go:116: INFO clientconn.go:1144 [core] [Channel #2 SubChannel #4] Subchannel Connectivity change to CONNECTING  (t=+3.500717ms)
    tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #2] Resolver state updated: {
          "Addresses": [
            {
              "Addr": "localhost:56424",
              "ServerName": "",
              "Attributes": null,
              "BalancerAttributes": null,
              "Type": 0,
              "Metadata": null
            } 
          ],
          "ServiceConfig": {
            "Config": {
              "Config": null,
              "LB": "round_robin",
              "Methods": {}
            },
            "Err": null
          },
          "Attributes": null
        } (service config updated)  (t=+3.59037ms)
    tlogger.go:116: INFO clientconn.go:414 [core] [Channel #2] Channel Connectivity change to CONNECTING  (t=+3.627039ms)
    tlogger.go:116: INFO clientconn.go:1255 [core] [Channel #2 SubChannel #4] Subchannel picks a new address "localhost:56424" to connect  (t=+3.672127ms)
    tlogger.go:116: INFO clientconn.go:709 [core] [Channel #2] ClientConn switching balancer to "round_robin"  (t=+3.778722ms)
    tlogger.go:116: INFO clientconn.go:1144 [core] [Channel #2 SubChannel #4] Subchannel Connectivity change to SHUTDOWN  (t=+3.800398ms)
    tlogger.go:116: INFO clientconn.go:729 [core] [Channel #2] Channel switches to new LB policy "round_robin"  (t=+3.850526ms)
    tlogger.go:116: INFO clientconn.go:774 [core] [Channel #2 SubChannel #5] Subchannel created  (t=+3.949929ms)
    tlogger.go:116: INFO clientconn.go:1499 [core] [Channel #2 SubChannel #4] Subchannel deleted  (t=+4.09977ms)
    tlogger.go:116: INFO clientconn.go:1144 [core] [Channel #2 SubChannel #5] Subchannel Connectivity change to CONNECTING  (t=+4.211298ms)
    tlogger.go:116: INFO clientconn.go:1255 [core] [Channel #2 SubChannel #5] Subchannel picks a new address "localhost:56424" to connect  (t=+4.258739ms)
    tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #2] Resolver state updated: {
          "Addresses": [
            {
              "Addr": "localhost:56424",
              "ServerName": "",
              "Attributes": null,
              "BalancerAttributes": null,
              "Type": 0,
              "Metadata": null
            }
          ],
          "ServiceConfig": {
            "Config": {
              "Config": null,
              "LB": null,
              "Methods": {
                "/grpc.testing.TestService/EmptyCall": {
                  "WaitForReady": false,
                  "Timeout": 1000000, 
                  "MaxReqSize": null, 
                  "MaxRespSize": null,
                  "RetryPolicy": null 
                }
              }
            },
            "Err": null
          },
          "Attributes": null
        } (service config updated)  (t=+4.291951ms)
    tlogger.go:116: INFO clientconn.go:709 [core] [Channel #2] ClientConn switching balancer to "pick_first"  (t=+4.38321ms)
    tlogger.go:116: INFO clientconn.go:1144 [core] [Channel #2 SubChannel #5] Subchannel Connectivity change to SHUTDOWN  (t=+4.412371ms)
    tlogger.go:116: INFO clientconn.go:729 [core] [Channel #2] Channel switches to new LB policy "pick_first"  (t=+4.46831ms)
    tlogger.go:116: INFO clientconn.go:774 [core] [Channel #2 SubChannel #6] Subchannel created  (t=+4.505149ms)
    tlogger.go:116: INFO clientconn.go:414 [core] [Channel #2] Channel Connectivity change to IDLE  (t=+4.517566ms)
    tlogger.go:116: INFO resolver_conn_wrapper.go:175 [core] [Channel #2] Resolver state updated: {
          "Addresses": [],
          "ServiceConfig": {
            "Config": {
              "Config": null,
              "LB": null,
              "Methods": {
                "/grpc.testing.TestService/EmptyCall": {
                  "WaitForReady": false,
                  "Timeout": 1000000, 
                  "MaxReqSize": null, 
                  "MaxRespSize": null,
                  "RetryPolicy": null 
                }
              }
            },
            "Err": null
          },
          "Attributes": null
        } (resolver returned an empty address list)  (t=+4.568956ms)
    tlogger.go:116: INFO clientconn.go:414 [core] [Channel #2] Channel Connectivity change to TRANSIENT_FAILURE  (t=+4.638989ms)
    tlogger.go:116: INFO clientconn.go:1144 [core] [Channel #2 SubChannel #6] Subchannel Connectivity change to CONNECTING  (t=+4.700158ms)
    tlogger.go:116: INFO clientconn.go:414 [core] [Channel #2] Channel Connectivity change to SHUTDOWN  (t=+4.734411ms)
    tlogger.go:116: INFO clientconn.go:1499 [core] [Channel #2 SubChannel #5] Subchannel deleted  (t=+4.751302ms)
    tlogger.go:116: INFO clientconn.go:1255 [core] [Channel #2 SubChannel #6] Subchannel picks a new address "localhost:56424" to connect  (t=+4.773223ms)
    tlogger.go:116: INFO clientconn.go:1144 [core] [Channel #2 SubChannel #6] Subchannel Connectivity change to SHUTDOWN  (t=+4.797088ms)
    tlogger.go:116: INFO clientconn.go:1499 [core] [Channel #2 SubChannel #6] Subchannel deleted  (t=+4.819007ms)
    tlogger.go:116: INFO clientconn.go:1099 [core] [Channel #2] Channel deleted  (t=+4.835902ms)
    tlogger.go:116: INFO types.go:68 [channelz] attempt to delete child with id 4 from a parent (id=2) that doesn't currently exist  (t=+4.865398ms)
    tlogger.go:116: INFO types.go:68 [channelz] attempt to delete child with id 5 from a parent (id=2) that doesn't currently exist  (t=+4.885296ms)
    tlogger.go:116: INFO types.go:68 [channelz] attempt to delete child with id 4 from a parent (id=2) that doesn't currently exist  (t=+4.893645ms)
    tlogger.go:116: INFO types.go:68 [channelz] attempt to delete child with id 6 from a parent (id=2) that doesn't currently exist  (t=+4.901657ms)
    tlogger.go:116: INFO types.go:68 [channelz] attempt to delete child with id 5 from a parent (id=2) that doesn't currently exist  (t=+4.937717ms)
    tlogger.go:116: INFO types.go:68 [channelz] attempt to delete child with id 6 from a parent (id=2) that doesn't currently exist  (t=+4.955415ms)
    tlogger.go:116: INFO types.go:62 [channelz] attempt to add child of type *channelz.normalSocket with id 8 to a parent (id=5) that doesn't currently exist  (t=+4.981471ms)
    tlogger.go:116: INFO types.go:68 [channelz] attempt to delete child with id 8 from a parent (id=5) that doesn't currently exist  (t=+5.070706ms)
    tlogger.go:116: INFO types.go:62 [channelz] attempt to add child of type *channelz.normalSocket with id 9 to a parent (id=4) that doesn't currently exist  (t=+5.10906ms)
    tlogger.go:116: INFO server.go:727 [core] [Server #1 ListenSocket #3] ListenSocket deleted  (t=+5.169307ms)
    tlogger.go:116: INFO types.go:68 [channelz] attempt to delete child with id 9 from a parent (id=4) that doesn't currently exist  (t=+5.236087ms)
    tlogger.go:116: WARNING clientconn.go:1321 [core] [Channel #2 SubChannel #6] grpc: addrConn.createTransport failed to connect to {
          "Addr": "localhost:56424",
          "ServerName": "localhost:56424",
          "Attributes": null,
          "BalancerAttributes": null,
          "Type": 0,
          "Metadata": null
        }. Err: connection error: desc = "transport: Error while dialing dial tcp [::1]:56424: connect: connection refused"  (t=+6.343248ms)
--- PASS: Test (0.06s)
    --- PASS: Test/CZChannelAddressResolutionChange (0.06s)
PASS
ok      google.golang.org/grpc/test     0.256s

easwars · 2022-02-18T00:31:40Z

And another reason to not include IPs for SubChannel: the IP can change.

That is true.

easwars force-pushed the better_channelz_logging branch from 07ec1d6 to 606f3e1 Compare February 11, 2022 22:20

include entity identifier in channelz logs

116dade

easwars force-pushed the better_channelz_logging branch from 606f3e1 to 116dade Compare February 11, 2022 22:33

make vet happy

afa010c

easwars added this to the 1.45 Release milestone Feb 11, 2022

easwars added Type: API Change Breaking API changes (experimental APIs only!) Type: Internal Cleanup Refactors, etc labels Feb 11, 2022

easwars marked this pull request as ready for review February 11, 2022 22:55

easwars requested a review from menghanl February 11, 2022 22:55

easwars assigned menghanl Feb 11, 2022

undo changes to Serve()

3e5c516

menghanl reviewed Feb 16, 2022

View reviewed changes

menghanl assigned easwars and unassigned menghanl Feb 16, 2022

easwars added 3 commits February 17, 2022 12:06

review comments: assign channelz IDs even when channelz is turned OFF

786e6be

other review comments

136f132

fix tabs

774ce6a

easwars assigned menghanl and unassigned easwars Feb 17, 2022

menghanl reviewed Feb 17, 2022

View reviewed changes

menghanl assigned easwars and unassigned menghanl Feb 17, 2022

move prepending channelz id to right before actual logging functions

e76ebc8

easwars assigned menghanl and unassigned easwars Feb 17, 2022

easwars added 3 commits February 17, 2022 15:10

make channelz logging functions thin wrappers around AddTraceEvent

821b3c1

remove nil checks in Identifier type's methods

1f0bef1

more improvements

bf04fcf

menghanl approved these changes Feb 18, 2022

View reviewed changes

add creation/deletion logs for server

8a624b7

easwars modified the milestones: 1.45 Release, 1.46 Release Feb 22, 2022

easwars merged commit a73725f into grpc:master Feb 23, 2022

easwars deleted the better_channelz_logging branch February 23, 2022 15:30

github-actions bot locked as resolved and limited conversation to collaborators Aug 23, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

channelz: include channelz identifier in logs #5192

channelz: include channelz identifier in logs #5192

easwars commented Feb 10, 2022 •

edited

easwars commented Feb 11, 2022 •

edited by menghanl

easwars commented Feb 11, 2022

menghanl commented Feb 11, 2022

easwars commented Feb 11, 2022

menghanl commented Feb 11, 2022

easwars commented Feb 11, 2022 •

edited

menghanl Feb 16, 2022

menghanl Feb 16, 2022 •

edited

menghanl Feb 16, 2022

easwars Feb 17, 2022

menghanl Feb 17, 2022

menghanl Feb 16, 2022

menghanl Feb 16, 2022

easwars Feb 17, 2022

menghanl Feb 17, 2022

easwars Feb 17, 2022

menghanl Feb 16, 2022

easwars Feb 17, 2022

menghanl Feb 17, 2022

easwars Feb 17, 2022

menghanl left a comment

easwars commented Feb 18, 2022

menghanl left a comment

menghanl commented Feb 18, 2022

easwars commented Feb 18, 2022

easwars commented Feb 18, 2022

channelz: include channelz identifier in logs #5192

channelz: include channelz identifier in logs #5192

Conversation

easwars commented Feb 10, 2022 • edited

easwars commented Feb 11, 2022 • edited by menghanl

easwars commented Feb 11, 2022

menghanl commented Feb 11, 2022

easwars commented Feb 11, 2022

menghanl commented Feb 11, 2022

easwars commented Feb 11, 2022 • edited

Choose a reason for hiding this comment

menghanl Feb 16, 2022 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

menghanl left a comment

Choose a reason for hiding this comment

easwars commented Feb 18, 2022

menghanl left a comment

Choose a reason for hiding this comment

menghanl commented Feb 18, 2022

easwars commented Feb 18, 2022

easwars commented Feb 18, 2022

easwars commented Feb 10, 2022 •

edited

easwars commented Feb 11, 2022 •

edited by menghanl

easwars commented Feb 11, 2022 •

edited

menghanl Feb 16, 2022 •

edited