Context logging #39
Context logging #39
Conversation
| @@ -196,6 +200,8 @@ func main() { | |||
| w.Write([]byte(`{"version":"` + version + `"}`)) | |||
| }) | |||
|
|
|||
| rand.Seed(time.Now().UnixNano()) | |||
There was a problem hiding this comment.
Is it possible to make this configurable for testing purposes?
Also, is it possible to get a separately-seeded/used sequence, so that this will only be used for the trace-ids?
(If you need cryptographic strength here, this isn't a good enough seed, and also not a good enough package...but it doesn't look like you need it)
(looks like you can create your own source/random object... just can't be easily used concurrently)
There was a problem hiding this comment.
main.go is the "reference" nanoMDM implementation afaik. Any other implementer who uses the NanoMDM library could do this in a separate way, so I don't think this is an issue.
There was a problem hiding this comment.
It's a testability consideration, not anything else.
There was a problem hiding this comment.
(As far as I can tell, the only security implication of UUIDs is preventing collisions. So ... any seeding is "good enough", and use of a cryptographic PRNG is unnecessary. There's no harm if someone can guess a UUID.
So I'm just asking for "creation of unit test" purposes: if you can control the PRNG seed, you can get repeatable sequences out which makes testing easier.
If this isn't where anyone would actually test this, then ... yeah. Nevermind/drop)
| func Logger(ctx context.Context, logger log.Logger) log.Logger { | ||
| if ctx == nil { | ||
| return logger | ||
| } |
There was a problem hiding this comment.
...
Do you have benchmarks for how long it takes (on average) to log a line? This seems expensive for logging, and I'm wondering if this can be precalculated
| } | ||
| var acc []interface{} | ||
| ctxFuncs.RLock() | ||
| for _, f := range ctxFuncs.funcs { |
There was a problem hiding this comment.
Similarly in the annals of "premature optimization", is it possible to avoid doing this if the message won't actually be logged because the current log level is too high for the message? (or am I totally missing how this is implemented?)
|
@kilpatds re: log levels: I'm not sure if I'm reading you right, but there are only two log levels: Info and Debug. Wether those are logged or how is a detail left to the logger implementation and this nanomdm/log/stdlogfmt/stdlog.go Line 43 in 6eb91ef For more details/philosophy on the simplistic logging "levels" see https://pkg.go.dev/github.com/jessepeterson/go-log#section-documentation and https://dave.cheney.net/2015/11/05/lets-talk-about-logging. Hope that helps. :) |
|
'''The log package should support fine grained control to enable or disable debug, and only debug, statements at the package or possibly even finer scope.''' A pattern I've seen far too often around logging is something like where it's a shame to generate 2k of text output just to throw it away because you don't actually log because debug logs aren't on. So ... that loop that provides context: if those functions are expensive, it's a shame to waste them on debug log lines that aren't actually enabled? Or again, am I totally missing the boat? |
|
@kilpatds I think I see what you're saying now. Yeah so the general pattern we follow is that we unconditionally call Regarding computing the logger context stuff each invocation/being expensive: yes, I see that concern too and it's semi-addressed in two ways: one is that for some cases (Info logging) we only generated when we're going to log. The other cases, I'm just not really concerned about now. In summary: yes, good points, I hear you, but not a concern and/or pre-mature optimization at this point. IMO, at least. :) |
Adds a simple
ctxlogpackage which permits associating multipleCtxKVFuncs with a context. Then, when it's time to log, these are ran using the request context to pull out logging key-value pairs and create a new logger.The end result is something like this for a typical NanoMDM push request.
Before:
After:
Note the
trace_idvalue which tracks each log's request from its origin. Note also thatidandtypein theservice=nanomdmlayer is also a context value rather than explicitly logged now.