Add client-side logging with swift-log #514
Conversation
Motivation: Logging is a hugely valuable tool for debugging, we currently have no logging whatsoever. Modifications: - Add swift-log as a dependency - Add (some) logging to the client Result: - More visibility into what the lifecycle of the application
|
This looks really great @glbrntt! Thank you |
MrMage
left a comment
MrMage
left a comment
There was a problem hiding this comment.
Sorry, I am not very familiar with swift-log. Some overall questions:
- How can users change the "output target" of the logger, e.g. if logs should be written to a specific file? I've noticed some
internalLoggers in the library; therefore users could not change theirhandlerproperty. Also, having to update the handler of like 10 different logger instances would be cumbersome. - How can users change the log level?
- Have you ensured that all logger uses provide as much context as possible? E.g.
BaseClientCalltakes in aLoggerinstance without adding extra "this log message was produced somewhere inside BaseClientCall" metadata. - Could you provide an example of the log output for a typical run?
| self.status = self.responseHandler.statusPromise.futureResult | ||
|
|
||
| self.streamPromise.futureResult.whenFailure { error in | ||
| self.logger.error("failed to create http/2 stream: \(error)") |
There was a problem hiding this comment.
Should the error parameter be part of the metadata? (I'm unfamiliar with best practices here.)
There was a problem hiding this comment.
Good question, I'm not super familiar with best practices here either!
From the docs:
Logging metadata is metadata that can be attached to loggers to add information that is crucial when debugging a problem
It seems like it could be either: I suppose adding it to metadata would make it easier for handlers to extract the description of the actual Error the message is related to which could be useful for e.g. emitting metrics.
@weissi do you have any insight here on when to when use metadata vs. include it in the log message? Things like identity (request Id, connection Id) seem obvious since they're useful for separating out instances. Things like errors are less clear.
var newLogger = existingLogger
newLogger.logLevel = .errorThe configure logging backend may or may not specify some more global policy around the log level.
I'll leave those for George |
To expand on @weissi's answer: the application user should be able to do this when configuring the We can also provide a way to make it easier for users to configure logging on a subsystem-basis (i.e. client call, client connection) so that they can tune the loggers they're interested in. The gRPC core lib gives you some control over this with environment variables. We can provide methods to parse whatever environment variables we decide on and for checking whether a logger is recognised as a gRPC-Swift logger should make this fairly straightforward for users.
The file, function and line are all captured when you write a log message (see here). Of course whether that is emitted depends on the handler. Thinking about it a little more it's probably worth having a UUID on the client connection since there could be many within a single application. I'll add that.
When I update the PR I'll post debug logs from e.g. a single unary call. In the meantime tou can see output in the build logs from the default log handler (level is info): https://travis-ci.org/grpc/grpc-swift/jobs/559374655 |
Thanks, that answers my question!
As long as the user can e.g. drop log messages below the "warning" level in their handler or global config, I think we should be fine for now. We could look into what is needed in terms of more fine-grained control later on, but I guess even then filtering by label could be sufficient.
Stupid me, that makes total sense!
I think that's a good idea.
Thanks, looking forward to the example log. In the meantime, the CI job has lines like |
|
To summarize: No objections from my side, just waiting for UUIDs to get added and CI to turn green. I would also appreciate a second review from @weissi or someone else who is familiar with Swift-log best practices. |
I think attaching errors into metadata as you mentioned is probably the best way to deal with this, it's then more obvious that the value in the metadata is just the
Travis killed it because of too many log lines, should be fine when disabling / changing the level to error. |
Sounds good, should we do that in the tests, then? Should probably avoid increasing test runtimes too much, too? |
|
@MrMage forgot to post some logs yesterday, this is from a unary call: |
|
LGTM. @weissi, would you mind reviewing as well? |
3 participants
Motivation:
Logging is a hugely valuable tool for debugging, we currently
have no logging whatsoever.
Modifications:
Result: