caddyhttp: Wrap http.Server logging with zap

[francislavoie]

Well this was way simpler than I expected... went way down the rabbithole in the wrong direction then realized all we needed was this one liner.

See https://pkg.go.dev/go.uber.org/zap?tab=doc#NewStdLog

Right now, this will log all errors from http.Server as INFO level, but we can easily change that by using NewStdLogAt instead to specify the level. Not sure what level you think we should use. Warn? Error?

This is how it looks before:

...
2020/08/20 04:10:27.647 INFO    serving initial configuration
2020/08/20 00:10:33 http: TLS handshake error from [::1]:65239: EOF
2020/08/20 04:11:32.551 INFO    shutting down   {"signal": "SIGINT"}
...

And after this change:

...
2020/08/20 04:32:52.059 INFO    serving initial configuration
2020/08/20 04:32:55.226 INFO    http    http: TLS handshake error from [::1]:49685: EOF
2020/08/20 04:33:48.299 INFO    shutting down   {"signal": "SIGINT"}
...

We may also want to make this change in other places like admin.go and the h3 server, i.e. where other http.Servers are created. This is the important one though.

[mholt]

Hey this is pretty neat!

Considering that the field is named ErrorLog we should probably log at ERROR level, although... most of the errors emitted by a server that don't cause it to totally shut down (which are returned instead) can be ignored as they are almost always client-caused and the server can do nothing about them anyway. What about DEBUG level?

[francislavoie]

Yeah I'm good with DEBUG level. I wanted to be conservative with it cause I wasn't sure where your opinion would lie.

Btw is it correct to do zap., i.e. use the global zap, or is there a way to grab the one off ctx or something... 🤔

I don't think I 100% understand the whole zap pipeline so I'm a bit shaky on that point.

Edit: Derp, I'm passing app.logger, so it's wrapping that. Do we want these errors to be under a namespace like http.server or something instead of http? 🤔

[francislavoie]

Changed to use debug, pulled the logger setup out of the loop, should be slightly more efficient when running multiple servers, and passing it to the server wrapped by the http3 server as well.

2020/08/20 18:36:22.495	INFO	tls	cleaned up storage units
2020/08/20 18:38:51.229	DEBUG	http	http: TLS handshake error from 127.0.0.1:40192: EOF
2020/08/20 18:38:58.666	DEBUG	http	http: TLS handshake error from 127.0.0.1:40200: EOF

Can also confirm the error is suppressed if the debug global option isn't on.

[mholt]

Good question about the namespace, I'm not sure... I wonder if we should specially namespace logs originating from the std lib, like, http.stdlib or something? Dunno if that's useful at all.

[francislavoie]

Yeah I don't mind that. I'm not sure how to do that though. How do we set it up with a different namespace? Do I need to make a new logger for that or something?

[mholt]

Easy :) Just serverLogger.Named("stdlib") will do!

[francislavoie]

Okay cool:

2020/08/20 20:07:12.332	DEBUG	http.stdlib	http: TLS handshake error from 127.0.0.1:42770: EOF

[mholt]

LGTM!

[francislavoie]

I feel like we might as well get this into v2.2 since it's such a simple fix.

[mholt]

Cool, might as well get this in then.