Logging option to format sink as JSON

[pascalgn]

1. What would you like to have changed?

Currently, the sink logger just outputs plain text:

2019/11/08 16:34:34 [INFO][cache:0xc0000bb270] Started certificate maintenance routine

It would be nice if there was an option where this could be encapsulated in a simple JSON structure, like

{ "msg": "2019/11/08 16:34:34 [INFO][cache:0xc0000bb270] Started certificate maintenance routine" }

2. Why is this feature a useful, necessary, and/or important addition to this project?

Makes it easier to send the log to Elastic (and probably also similar logging tools)

3. What alternatives are there, or what are you doing in the meantime to work around the lack of this feature?

It's possible to manually configure log line patterns in Elastic, but it's more effort and not very easy / user-friendly to do

4. Please link to any relevant issues, pull requests, or other discussions.

--

[mholt]

We can customize only a few things about the sink logger, things which are exported here: https://golang.org/pkg/log/ -- so basically, the writer, and some "flags."

The best way to do this would be to make a log writer module that wraps its output in a JSON string. Depending on how this is implemented, it would have some cost in terms of performance. I bet it could be done without significant buffering and with using pools if necessary, though.

[pascalgn]

If possible, it would of course be nice if we could also extract the time and level information. However, I had a short look at the log module and I think the only option is log.SetOutput. That would mean there is no way to get these information directly, other than parsing the raw log line

[mholt]

Correct: since writers only get an array of bytes to work with, there has to be some parsing (hence the perf overhead).

I am also not 100% sure we can guarantee that each call to Write() correlates 1:1 with a log entry. From looking at the implementation of log.Output(), it appears that each log entry correlates 1:1 with calls to Write(), so that's convenient -- but the documentation does not explicitly guarantee this, I don't think (it just says that it will always end with a newline, but that doesn't mean that log entries can't have newlines in the middle of them too).

In any case, perhaps we can rest on the assumption that a single call to Write() consists of a single and complete log entry. If we assume that, then this problem is easier, since we can just parse out the timestamp.

Level information is definitely not structured -- there's absolutely no guarantee that the text within the [ ] after the timestamp will be the level. Perhaps it could be parsed and then compared against a list of known values, and then used as a level only if it matches a known level string.

Again, just adds performance overhead. But if that's OK, then I guess we can take a stab at it...

Want to give it a try?

[francislavoie]

@mholt I think this is essentially done?

https://caddyserver.com/docs/json/logging/logs/encoder/json/

[mholt]

@francislavoie No, unfortunately that's not the sink log. The sink is just an io.Writer and that's about all right now because of the reasons mentioned above. There's not much we can do without structured log messages.

[francislavoie]

I think this is largely resolved at this point. CertMagic now uses zap for logging, and #3668 should resolve the only other major source of non-zap logs.

Should we close @mholt?

[mholt]

That PR only formats http.Server logs as JSON; it doesn't change the whole standard lib's default logger to JSON. We can probably do that pretty easily following a similar pattern. Do we feel that is the right thing to do?

[mholt]

Mmm, guess we'll close this and see if we get any other requests/complaints about sink log formats.