Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

channelz: include channelz identifier in logs #5192

Merged
merged 11 commits into from Feb 23, 2022

Conversation

easwars
Copy link
Contributor

@easwars easwars commented Feb 10, 2022

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 easwars force-pushed the better_channelz_logging branch from 07ec1d6 to 606f3e1 Compare Feb 11, 2022
@easwars easwars force-pushed the better_channelz_logging branch from 606f3e1 to 116dade Compare Feb 11, 2022
@easwars easwars added this to the 1.45 Release milestone Feb 11, 2022
@easwars easwars added Type: API Change Type: Internal Cleanup labels Feb 11, 2022
@easwars
Copy link
Contributor Author

@easwars easwars commented Feb 11, 2022

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 easwars marked this pull request as ready for review Feb 11, 2022
@easwars easwars requested a review from menghanl Feb 11, 2022
@easwars
Copy link
Contributor Author

@easwars easwars commented Feb 11, 2022

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
Copy link
Contributor

@menghanl menghanl commented Feb 11, 2022

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
Copy link
Contributor Author

@easwars easwars commented Feb 11, 2022

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
Copy link
Contributor

@menghanl menghanl commented Feb 11, 2022

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

@easwars
Copy link
Contributor Author

@easwars easwars commented Feb 11, 2022

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.

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)
Copy link
Contributor

@menghanl menghanl Feb 16, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor

@menghanl menghanl Feb 16, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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)

Copy link
Contributor

@menghanl menghanl Feb 16, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor Author

@easwars easwars Feb 17, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor

@menghanl menghanl Feb 17, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

clientconn.go Outdated
@@ -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)
Copy link
Contributor

@menghanl menghanl Feb 16, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What's before and after?

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

Copy link
Contributor

@menghanl menghanl Feb 16, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?

Copy link
Contributor Author

@easwars easwars Feb 17, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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).

Copy link
Contributor

@menghanl menghanl Feb 17, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor Author

@easwars easwars Feb 17, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Made the logging funcs thin wrappers around AddTraceEvent.

clientconn.go Outdated
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()),
Copy link
Contributor

@menghanl menghanl Feb 16, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?

Copy link
Contributor Author

@easwars easwars Feb 17, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor

@menghanl menghanl Feb 17, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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?

Copy link
Contributor Author

@easwars easwars Feb 17, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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 Outdated Show resolved Hide resolved
internal/channelz/id.go Outdated Show resolved Hide resolved
server.go Outdated Show resolved Hide resolved
@menghanl menghanl assigned easwars and unassigned menghanl Feb 16, 2022
@easwars easwars assigned menghanl and unassigned easwars Feb 17, 2022
Copy link
Contributor

@menghanl menghanl left a comment

LGTM except for the ongoing discussion in previous comments.

@menghanl menghanl assigned easwars and unassigned menghanl Feb 17, 2022
@easwars easwars assigned menghanl and unassigned easwars Feb 17, 2022
@easwars
Copy link
Contributor Author

@easwars easwars commented Feb 18, 2022

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.

Copy link
Contributor

@menghanl menghanl left a comment

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

@menghanl
Copy link
Contributor

@menghanl menghanl commented Feb 18, 2022

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

@easwars
Copy link
Contributor Author

@easwars easwars commented Feb 18, 2022

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
Copy link
Contributor Author

@easwars easwars commented Feb 18, 2022

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

That is true.

@easwars easwars removed this from the 1.45 Release milestone Feb 22, 2022
@easwars easwars added this to the 1.46 Release milestone Feb 22, 2022
@easwars easwars merged commit a73725f into grpc:master Feb 23, 2022
10 checks passed
@easwars easwars deleted the better_channelz_logging branch Feb 23, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Type: API Change Type: Internal Cleanup
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants