Set gRPC logger to zap

[jpkrohling]

Is your feature request related to a problem? Please describe.
As part of #2102, we should provide users with logs about the underlying connections provided and used by receivers and exporters. Given that quite a few of them use gRPC clients and servers, the bootstrap procedure for the collector should have a line similar to this:

import grpcZap "github.com/grpc-ecosystem/go-grpc-middleware/logging/zap"

...
grpcZap.ReplaceGrpcLoggerV2(logger)
...

This would cause messages like this when connections fail to be established:

2020-12-01T18:01:24.938+0100	INFO	service/service.go:338	Starting processors...
2020-12-01T18:01:24.938+0100	WARN	grpclog/component.go:41	[core]grpc: addrConn.createTransport failed to connect to {localhost:14250 localhost:14250 <nil> 0 <nil>}. Err: connection error: desc = "transport: Error while dialing dial tcp [::1]:14250: connect: connection refused". Reconnecting...	{"component_kind": "exporter", "component_type": "jaeger", "component_name": "jaeger/2", "system": "grpc", "grpc_log": true}
google.golang.org/grpc/grpclog.(*componentData).WarningDepth
	/home/jpkroehling/go/pkg/mod/google.golang.org/[email protected]/grpclog/component.go:41
google.golang.org/grpc/internal/channelz.Warningf
	/home/jpkroehling/go/pkg/mod/google.golang.org/[email protected]/internal/channelz/logging.go:75
google.golang.org/grpc.(*addrConn).createTransport
	/home/jpkroehling/go/pkg/mod/google.golang.org/[email protected]/clientconn.go:1300
google.golang.org/grpc.(*addrConn).tryAllAddrs
	/home/jpkroehling/go/pkg/mod/google.golang.org/[email protected]/clientconn.go:1227
google.golang.org/grpc.(*addrConn).resetTransport
	/home/jpkroehling/go/pkg/mod/google.golang.org/[email protected]/clientconn.go:1142
2020-12-01T18:01:24.938+0100	INFO	grpclog/component.go:36	[core]Subchannel Connectivity change to TRANSIENT_FAILURE	{"component_kind": "exporter", "component_type": "jaeger", "component_name": "jaeger/2", "system": "grpc", "grpc_log": true}
2020-12-01T18:01:24.938+0100	INFO	grpclog/component.go:36	[core]Channel Connectivity change to TRANSIENT_FAILURE	{"component_kind": "exporter", "component_type": "jaeger", "component_name": "jaeger/2", "system": "grpc", "grpc_log": true}

Upon success, this would be shown:

2020-12-01T18:01:38.798+0100	INFO	grpclog/component.go:36	[core]Subchannel Connectivity change to CONNECTING	{"component_kind": "exporter", "component_type": "jaeger", "component_name": "jaeger/2", "system": "grpc", "grpc_log": true}
2020-12-01T18:01:38.798+0100	INFO	grpclog/component.go:36	[core]Subchannel picks a new address "localhost:14250" to connect	{"component_kind": "exporter", "component_type": "jaeger", "component_name": "jaeger/2", "system": "grpc", "grpc_log": true}
2020-12-01T18:01:38.799+0100	INFO	grpclog/component.go:36	[core]Channel Connectivity change to CONNECTING	{"component_kind": "exporter", "component_type": "jaeger", "component_name": "jaeger/2", "system": "grpc", "grpc_log": true}
2020-12-01T18:01:38.800+0100	INFO	grpclog/component.go:36	[core]Subchannel Connectivity change to READY	{"component_kind": "exporter", "component_type": "jaeger", "component_name": "jaeger/2", "system": "grpc", "grpc_log": true}
2020-12-01T18:01:38.800+0100	INFO	grpclog/component.go:36	[core]Channel Connectivity change to READY	{"component_kind": "exporter", "component_type": "jaeger", "component_name": "jaeger/2", "system": "grpc", "grpc_log": true}

And when there's a problem with the TLS handshake (see #1861):

2020-12-01T18:01:40.983+0100	INFO	grpclog/component.go:36	[core]Subchannel Connectivity change to CONNECTING	{"component_kind": "exporter", "component_type": "jaeger", "component_name": "jaeger/2", "system": "grpc", "grpc_log": true}
2020-12-01T18:01:40.983+0100	INFO	grpclog/component.go:36	[core]Subchannel picks a new address "localhost:14250" to connect	{"component_kind": "exporter", "component_type": "jaeger", "component_name": "jaeger/2", "system": "grpc", "grpc_log": true}
2020-12-01T18:01:40.983+0100	INFO	grpclog/component.go:36	[core]Channel Connectivity change to CONNECTING	{"component_kind": "exporter", "component_type": "jaeger", "component_name": "jaeger/2", "system": "grpc", "grpc_log": true}
2020-12-01T18:01:40.986+0100	WARN	grpclog/component.go:41	[core]grpc: addrConn.createTransport failed to connect to {localhost:14250 localhost:14250 <nil> 0 <nil>}. Err: connection error: desc = "transport: authentication handshake failed: tls: first record does not look like a TLS handshake". Reconnecting...	{"component_kind": "exporter", "component_type": "jaeger", "component_name": "jaeger/2", "system": "grpc", "grpc_log": true}
google.golang.org/grpc/grpclog.(*componentData).WarningDepth
	/home/jpkroehling/go/pkg/mod/google.golang.org/[email protected]/grpclog/component.go:41
google.golang.org/grpc/internal/channelz.Warningf
	/home/jpkroehling/go/pkg/mod/google.golang.org/[email protected]/internal/channelz/logging.go:75
google.golang.org/grpc.(*addrConn).createTransport
	/home/jpkroehling/go/pkg/mod/google.golang.org/[email protected]/clientconn.go:1300
google.golang.org/grpc.(*addrConn).tryAllAddrs
	/home/jpkroehling/go/pkg/mod/google.golang.org/[email protected]/clientconn.go:1227
google.golang.org/grpc.(*addrConn).resetTransport
	/home/jpkroehling/go/pkg/mod/google.golang.org/[email protected]/clientconn.go:1142
2020-12-01T18:01:40.986+0100	INFO	grpclog/component.go:36	[core]Subchannel Connectivity change to TRANSIENT_FAILURE	{"component_kind": "exporter", "component_type": "jaeger", "component_name": "jaeger/2", "system": "grpc", "grpc_log": true}
2020-12-01T18:01:40.986+0100	INFO	grpclog/component.go:36	[core]Channel Connectivity change to TRANSIENT_FAILURE	{"component_kind": "exporter", "component_type": "jaeger", "component_name": "jaeger/2", "system": "grpc", "grpc_log": true}

Describe alternatives you've considered
While I think this is useful to be active for all profiles (dev, prod), some users might consider this too verbose. In such case, I'd be fine in replacing it only when the profile is set to dev (or log-level=debug).

[pavankrish123]

@jpkrohling now that #4009 is checked in. I am happy to work on this enhancement. Just as a confirmation do you envision this enhancement in this way?

service:
  telemetry:

    logs:
      level: "DEBUG" 
     development: true
     grpc_logs: true 

[jpkrohling]

I think I would include the gRPC logs as info, and without any entry in the configuration. If people need to customize it for some reason, we might want to wrap it behind a config option.

[pavankrish123]

Thank you @jpkrohling - Just as a confirmation

1. The idea still is to have grpc zap logger only in dev profile - correct? and that too without any configuration (that makes sense)

service:
  telemetry:
     development: true

2. What configuration of the grpc zap logger are we intending to expose? or shall we take it in a different PR when need arises?

3. do we have an intention to do the same for http logging as well?

[jpkrohling]

For 1, I think it could be made part of the production profile. As someone managing a production-quality instance, I would be interested in knowing when the connection between the collector and the backend Jaeger breaks and restores.

For 2, I would vote for a minimal solution for the moment and see what people really need.

For 3, not so sure. gRPC is somewhat different, as the client won't immediately fail if the server isn't available especially when the retries are enabled. As such, it's hard to tell what's the problem when things stop working. For HTTP, an error in the connection is usually caught right away and the client can decide to fail (and log) or retry itself.

[jpkrohling]

@pavankrish123, are you still interested in working on this one?

[pavankrish123]

@jpkrohling yes I am still interested. (Sorry was on a break). Will push out initial commit by this weekend.

[pavankrish123]

(comment copied from PR for the sake of completeness)

@jpkrohling - during my research with grpc logging, i found this settings that can be used to set and control grpc logs. Grpc by defaults sets its logging to error and logger output is set to stderr.

It also allows controlling these settings via environmental variables GRPC_GO_LOG_SEVERITY_LEVEL, GRPC_GO_LOG_VERBOSITY_LEVEL and GRPC_GO_LOG_FORMATTER

So if we do something like
$ GRPC_GO_LOG_SEVERITY_LEVEL=info ./otelcol_darwin_amd64 --config otelconfig.yaml

We get effectively the same detail of grpc messages without any code changes.

2021-11-12T20:02:23.318-0800	info	builder/exporters_builder.go:40	Exporter is starting...	{"kind": "exporter", "name": "logging"}
2021-11-12T20:02:23.318-0800	info	builder/exporters_builder.go:48	Exporter started.	{"kind": "exporter", "name": "logging"}
2021-11-12T20:02:23.318-0800	info	builder/exporters_builder.go:40	Exporter is starting...	{"kind": "exporter", "name": "otlp"}
2021/11/12 20:02:23 INFO: [core] original dial target is: "0.0.0.0:8889"
2021/11/12 20:02:23 INFO: [core] dial target "0.0.0.0:8889" parse failed: parse "0.0.0.0:8889": first path segment in URL cannot contain colon
2021/11/12 20:02:23 INFO: [core] fallback to scheme "passthrough"
2021/11/12 20:02:23 INFO: [core] parsed dial target is: {Scheme:passthrough Authority: Endpoint:0.0.0.0:8889 URL:{Scheme:passthrough Opaque: User: Host: Path:/0.0.0.0:8889 RawPath: ForceQuery:false RawQuery: Fragment: RawFragment:}}
2021/11/12 20:02:23 INFO: [core] Channel authority set to "0.0.0.0:8889"
2021/11/12 20:02:23 INFO: [core] ccResolverWrapper: sending update to cc: {[{0.0.0.0:8889  <nil> <nil> 0 <nil>}] <nil> <nil>}
2021/11/12 20:02:23 INFO: [core] ClientConn switching balancer to "pick_first"
2021/11/12 20:02:23 INFO: [core] Channel switches to new LB policy "pick_first"
2021-11-12T20:02:23.318-0800	info	builder/exporters_builder.go:48	Exporter started.	{"kind": "exporter", "name": "otlp"}
2021-11-12T20:02:23.318-0800	info	service/service.go:96	Starting processors...
2021-11-12T20:02:23.318-0800	info	builder/pipelines_builder.go:54	Pipeline is starting...	{"name": "pipeline", "name": "traces"}
2021/11/12 20:02:23 INFO: [core] Subchannel Connectivity change to CONNECTING
2021-11-12T20:02:23.318-0800	info	builder/pipelines_builder.go:65	Pipeline is started.	{"name": "pipeline", "name": "traces"}
2021/11/12 20:02:23 INFO: [core] Subchannel picks a new address "0.0.0.0:8889" to connect
2021-11-12T20:02:23.318-0800	info	service/service.go:101	Starting receivers...
2021/11/12 20:02:23 INFO: [core] Channel Connectivity change to CONNECTING
2021-11-12T20:02:23.318-0800	info	builder/receivers_builder.go:68	Receiver is starting...	{"kind": "receiver", "name": "otlp"}
2021-11-12T20:02:23.318-0800	info	otlpreceiver/otlp.go:68	Starting GRPC server on endpoint 0.0.0.0:4317	{"kind": "receiver", "name": "otlp"}
2021-11-12T20:02:23.319-0800	info	builder/receivers_builder.go:73	Receiver started.	{"kind": "receiver", "name": "otlp"}
2021-11-12T20:02:23.319-0800	info	service/telemetry.go:92	Setting up own telemetry...
2021-11-12T20:02:23.323-0800	info	service/telemetry.go:116	Serving Prometheus metrics	{"address": ":8888", "level": "basic", "service.instance.id": "f20d3995-e635-4f2a-9f2a-7767d0d38eac", "service.version": "v0.35.0-279-gb8544417"}
2021-11-12T20:02:23.323-0800	info	service/collector.go:235	Starting otelcol...	{"Version": "v0.35.0-279-gb8544417", "NumCPU": 12}
2021-11-12T20:02:23.323-0800	info	service/collector.go:131	Everything is ready. Begin running and processing data.
2021/11/12 20:02:24 WARNING: [core] grpc: addrConn.createTransport failed to connect to {0.0.0.0:8889 0.0.0.0:8889 <nil> <nil> 0 <nil>}. Err: connection error: desc = "transport: Error while dialing dial tcp 0.0.0.0:8889: connect: connection refused"
2021/11/12 20:02:24 INFO: [core] Subchannel Connectivity change to TRANSIENT_FAILURE
2021/11/12 20:02:24 INFO: [core] Channel Connectivity change to TRANSIENT_FAILURE
2021/11/12 20:02:25 INFO: [core] Subchannel Connectivity change to IDLE
2021/11/12 20:02:25 INFO: [core] Channel Connectivity change to IDLE

Do we still want these messages go through our collector logger? I wonder if we are getting any value by doing so especially because collector logger is also writing (and can only write to) to the same STDERR ? (and we expose basically same logging configuration on collector as well)

Let me know how you feel about using env variables to control grpc logging. Happy to discard this PR.

cc: @bogdandrutu @jpkrohling

[jpkrohling]

My personal opinion is that the collector shouldn't require knowledge about gRPC from the people running the collector. If they set the collector logging level to debug, I would expect to see the gRPC messages in the log, hopefully in a consistent format with the rest of the log entries.

We may want to take this discussion to the SIG meeting next week for a decision (I'm not able to join today's).

[pavankrish123]

@jpkrohling any leads on how to proceed - Thank you

[jpkrohling]

@pavankrish123, try to create a thread on Slack to discuss it. If we can't get a green light from a maintainer (@bogdandrutu?), let's discuss this tomorrow during the SIG meeting.

[jpkrohling]

I would have all the INFO statements from your previous comment as part of the prod profile. I don't think they are that verbose. If possible at all, one thing I would change is to omit the subchannel logging, having it only for the main channel.

[mx-psi]

I believe this is done, please reopen/comment if not