Internal Logging

[MadVikingGod]

What is this?

This is an experiment to enable logging from the API and SDK.

It creates a simple user facing interface to set a logger, and then exposes that logr.Logger in the internal/debug package.

What is not included in this PR?

• Instrumenting some/most/all of the API, SDK, or exporters. I wanted to explore how simple of an interface I could make, and that can come in a later patch set.
• Guidelines on verbosity. I have included a simple blurb, but it is by no means fully flushed out.
• How to warn users that using this with a logger that exports to the otel log means messages might be lost if incorrectly setup.

How do you use it?

The simplest way is to run the NamedTracer example. This should output to stderr the only line that was instrumented in the project.

cd example/namedtracer
go run . >/dev/null

Closes #1068

[codecov]

Codecov Report

Merging #2343 (7e76cd8) into main (5ea9171) will decrease coverage by 0.0%.
The diff coverage is 50.0%.

@@           Coverage Diff           @@
##            main   #2343     +/-   ##
=======================================
- Coverage   74.2%   74.2%   -0.1%     
=======================================
  Files        173     175      +2     
  Lines      12174   12194     +20     
=======================================
+ Hits        9043    9057     +14     
- Misses      2894    2900      +6     
  Partials     237     237             

Impacted Files	Coverage Δ
internal_logging.go	0.0% <0.0%> (ø)
internal/global/internal_logging.go	50.0% <50.0%> (ø)
sdk/trace/batch_span_processor.go	84.4% <100.0%> (+1.1%)	⬆️
exporters/jaeger/jaeger.go	94.3% <0.0%> (+0.8%)	⬆️

[MadVikingGod]

So I was not aware of the otel.ErrorHandler when this was written. I'm working on a patch that will have these parts work in unison so we don't have to duplicate efforts in both systems. My first pass will have the default errorHandler be a function that calls the internal logger.Error, with a message of the err.Error()

[MadVikingGod]

Update

This now includes a rework of the error handeling. I'm not a fan of the scope creep, but I felt it necessary to have these interfaces work together as much as possible in unison. I simplified how the error handler is managed, and changed it's default to use the internal logger. I also made the default internal logger print Error messages to stderr, this perserves the behavior of the current errorHandler.

Conventions

When I first started on this because each logging implementation uses different levels internally (logrus uses 1 - -5, but glog, klog, and zap use 1 - 5 etc), I didn't know if there would be an easy convention we could set that would be easy to explain to users. To drive this I experimented with all of the loggers here, and found that MOST logr implementations use 0 as their default, and allow all Error messages. This makes setting a convention easy. To that extent what I set was three different levels Error, Info (lvl 1 off by default for most loggers), and debug (lvl 5 off on all loggers). I just need a bit of help writing the SetLogger documentation to explain how to see the different levels.

[pellared]

Suggested change

	To enable verbose logs configure the logger which will print V(1) logs. For debugging information configure to print V(5) logs. (#2343)
	To enable verbose logs, configure the logger which will print V(1) logs. For debugging information configure to print V(5) logs. (#2343)

[MadVikingGod]

So I think I might not be expressing my concerns about why we need to changethe error handling well enough. I made a quick demo of what the behavior is right now where we don't touch the error handler, here. Running it you will see:

######## Default Logger #######
2021/11/24 18:32:49 Error from error handler
2021/11/24 18:32:49 debug.go:47: "msg"="logging error" "error"="Error from interal logger"
######## Setting New Logger #######
2021/11/24 18:32:49 Error from error handler
ERRO[0000] logging error                                 error="Error from interal logger"
INFO[0000] Logging from Info    ```

I think that it is surprising to change SetLogger, and then some messages are still using a different logger.  Especially as an application developer because I would see all of these logs as emitted from otel.

If we were to link them you get two key results:
1. By default errors across our ecosystem will have a common formatted.
2. You don't have to set logging behavior in two places.  Yes, the error handler is more powerful in you can do things other than log, but that functionality is kept by changing the default.

[pellared]

So I think I might not be expressing my concerns about why we need to change the error handling well enough.

I see your concern. However, personally, I do not like that currently the default ErrorHandler is logging. As for me, the ErrorHandling logging concern could be addressed in a separate PR as a follow-up. I assume we are not planning a release in the following days.

Normally I would propose a PR that removes logging from the default error handler (that could be merged even before this PR). However, I do not time to work on that and participate in possible conversations 😞

EDIT: I created a draft PR in browser to express what I mean 😄 #2416

This would also be in line with my comment here: #2343 (comment)

[MrAlias]

Outside of the minor changelog suggestions this looks ready to merge.

I think this is a great launch point for our internal logging! Thanks for digging into this. 🚀

[pellared]

I created an issue #2417 and resolved most of my comments.

[jmacd]

I'm curious about the choice of V(1) and V(5). I take it the user shouldn't see OTel-SDK Info messages unless they're debugging, thus Info is V(1)?

[MadVikingGod]

Yeah, the idea was that V(1) is akin to a command line -v, the extra data that might be helpful.