logging: Implement log_append handler

[francislavoie]

Closes #5336

This adds a new handler log_append which adds an extra field to the access logs on the way back up the request chain (after most other handlers have run, including after handler errors).

The value may be a placeholder (if the value is surrounded by {}) or a vars key (will do a map lookup to see if it exists) or a constant string.

log_append [<matcher>] <key> <value>

Worth noting, zap doesn't validate that log fields don't overlap with existing ones when adding, so it's possible to have two log fields with the same name in the logs. For example, you might do log_append status not-an-int or whatever and you'd end up with "status": 200, "status": "not-an-int" in the logs. We could validate that the key is not one of the ones we have built-in, but I'm not sure if that's worth the effort?

[steffenbusch]

Wow, I will love this feature

[mholt]

Thanks for this!

Maybe bikeshedding, but what about append_log? Or log_append? or log_field?

[francislavoie]

Could do log_add.

But we have skip_log right now. Maybe we should rename that too, to log_skip if we want consistency. (Deprecate old name in Caddyfile, add new name with both working for the time being)

[isaced]

Love this feature, which is used to add information similar to UserId/ProjectId to the logs without returning it to the client. 👍

https://caddy.community/t/logging-a-response-header-field-in-caddy-reverse-proxy-without-returning-to-client/22758

[francislavoie]

We changed our mind again to log_append. Should be good to go now.

[mholt]

As for

We could validate that the key is not one of the ones we have built-in, but I'm not sure if that's worth the effort?

Probably not worth the effort. Different deserializers will handle it differently anyway.

[francislavoie]

And it would probably harm performance to do that for little benefit if done at runtime. Unless we check it at provision time or something and warn if they used a "reserved" log key. Can be added later tho.

[mholt]

Thanks for working on this! :)

[steffenbusch]

I have just built Caddy from the master branch in my personal testing environment to make some experiments with all the new features since 2.7.6. (I can't wait for 2.8.0 - you're doing a great job).

I was already aware that certain directives such as basicauth and skip_log were deprecated due to renaming, but I was also expecting that deprecation does not mean that existing Caddyfile configurations will not work and cause Errors.

For basicauth no breaking behavior was observed, just the WARN logs that it has been renamed.
But skip_log occurrences will cause this error that the skip_log directive is not an ordered HTTP handler:

$ ./caddy_master validate --config ../Caddyfile
2024/03/07 18:04:12.432 INFO    using config from file  {"file": "../Caddyfile"}
2024/03/07 18:04:12.437 WARN    config.adapter.caddyfile        the 'basicauth' directive is deprecated, please use 'basic_auth' instead!
2024/03/07 18:04:12.438 WARN    config.adapter.caddyfile        the 'skip_log' directive is deprecated, please use 'log_skip' instead!
2024/03/07 18:04:12.438 WARN    config.adapter.caddyfile        the 'skip_log' directive is deprecated, please use 'log_skip' instead!
Error: adapting config using caddyfile: directive 'skip_log' is not an ordered HTTP handler, so it cannot be used here - try placing within a route block or using the order global option

Shall I open a separate issue for this?

[francislavoie]

Oh oops, you're right, I should've left the old directive names in the directive order. If you want to make a quick PR to fix it, it would save me a few minutes 😅 just needs a // TODO comment next to it about the deprecation.

[steffenbusch]

I am going to try to make this PR to fix it.