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

Support non-colorized log output, logging refactor #420

Open
wants to merge 1 commit into
base: main
Choose a base branch
from

Conversation

dougluce
Copy link

Three things are happening here:

  1. An environment variable is added to allow for non-colorized text to be output. This is so /usr/sbin/daemon can direct stdout to syslog without escaped control sequences:

    Apr 15 14:48:52 orla syncv3[41839]: ^[[90m14:48:52^[[0m ^[[32mINF^[[0m Poller: accumulated data ^[[36mdevice [events,changed,left,account]=^[[0m[0,0,0,0] ^[[36mdevice_id=^[[0mQRZLYYCRTO ^[[36mrooms [timeline,state,typing,receipts,invites]=^[[0m[0,0,0,0,0] ^[[36muser_id=^[[0m@doug:yutz.horph.com

I would have preferred a command-line switch instead of the env var but am following the existing pattern.

  1. zerolog use is refactored. Since there really are no different types of log output and only minimal use of additional context, it makes sense to use zerolog's existing global logger. This simplifies things a bit both textually and cyclomatically and allows for central changes to the logger output based on the new env var.

  2. A go fmt ./... changed a few very minor things.

Pull Request Checklist

Copy link
Member

@kegsay kegsay left a comment

Choose a reason for hiding this comment

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

Overall this is a good improvement, thank you.

There is at least 1 case where we make a local logger with contextual fields which seems to have been lost here. Please can you ensure we use those local loggers rather than the global one.

Otherwise LGTM!

@@ -288,7 +289,7 @@ func (h *PollerMap) EnsurePolling(pid PollerID, accessToken, v2since string, isS

// replace the poller. If we don't need to wait, then we just want to nab to-device events initially.
// We don't do that on startup though as we cannot be sure that other pollers will not be using expired tokens.
poller = newPoller(pid, accessToken, h.v2Client, h, logger, !needToWait && !isStartup)
Copy link
Member

Choose a reason for hiding this comment

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

This logger has contextual information like the user ID and device ID which is now lost.

Copy link
Author

Choose a reason for hiding this comment

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

This was a conscious decision. In the implementation of newPoller() there are calls like this:

logger.Error().Str("user", p.userID).Str("device", p.deviceID).Msgf("%s. Traceback:\n%s", panicErr, debug.Stack())

where context is sent to the log output even though the logger already has that context. My worry is this happened because it wasn't clear that the logger already has that context or because it wasn't added in an earlier (and now-deleted) path or just to ensure the context is there in case one day it's handed a logger without it.

In any case, it makes more sense to me to add those values locally. There are several other logging calls in newPoller() that don't explicitly add user/device to output but it doesn't seem particularly useful to have it at those points. If that's not the case, my inclination would be to add those values locally instead of far up the call stack.

Going back to using the per-file local loggers would mean plumbing each of the dozen or so zerolog.New() call sites with the new environment variable logic.

I've rebased the PR on the current main branch to accommodate new code changes and removed the unused logger formal parameter. Please let me know if this works for you.

Copy link
Member

Choose a reason for hiding this comment

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

I would rather we double reported the user ID and device ID than risked not reporting the user ID / device ID at all. By having a poller-local logger instance we guarantee that those keys are always logged. We rely on these keys existing for debugging as we often search for these IDs when that user reports a problem.

I'm happy with the global logger usage everywhere else, but the poller really should be using the contextual one please.

Three things are happening here:

1) An environment variable is added to allow for non-colorized text to
be output. This is so /usr/sbin/daemon can direct stdout to syslog
without escaped control sequences:

    Apr 15 14:48:52 orla syncv3[41839]: ^[[90m14:48:52^[[0m ^[[32mINF^[[0m Poller: accumulated data ^[[36mdevice [events,changed,left,account]=^[[0m[0,0,0,0] ^[[36mdevice_id=^[[0mQRZLYYCRTO ^[[36mrooms [timeline,state,typing,receipts,invites]=^[[0m[0,0,0,0,0] ^[[36muser_id=^[[0m@doug:yutz.horph.com

I would have preferred a command-line switch instead of the env var
but am following the existing pattern.

2) zerolog use is refactored. Since there really are no different
types of log output and only minimal use of additional context, it
makes sense to use zerolog's existing global logger. This simplifies
things a bit both textually and cyclomatically and allows for central
changes to the logger output based on the new env var.

3) A `go fmt ./...` changed a few very minor things.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants