Allow http.handlers to add field to log output

Handlers should be able to add field to server log output for debugging and extending functionality purpose.

Currently when a http.handler can only emit log using its own logger provisioned when creating an instance of the module. A module can attach some context information to the request handled.

Currently caddy tries to determine user_id from basicauth. However if it's not configured it will be empty and people maybe confused by its presence. (Commonly, most usage of caddy is just reverse proxy and file server.). Trying from the entry ServeHttp function is simply too much to maintain for every handler module that caddy is shipped with.

A recent pr will also add a new field to determine client_ip and it's also available as a variable.

Allow http.handlers to add custom fields to log can help generate logs that are easier to analyse.

Currently caddy tries to determine user_id from basicauth.

Not exclusively. Any module that implements the caddyauth.Authentication interface will implicitly have http.auth.user.id set. I think the caddy-security module makes use of that behaviour, or at least did at some point in the past, not sure if it changed away from it.

Also FWIW, the fastcgi transport pulls from it to set a CGI variable which has the user ID.

When we had a common_log field in the logs, it was also used to fill in one of the parts of the log line which was the user ID. We no longer have that now though, but it still gets handled by https://github.com/caddyserver/transform-encoder with {request>user_id}.

However if it's not configured it will be empty and people maybe confused by its presence.

I'd argue that it not being in the logs by default means it's less configurable that the property might exist if auth is used. Maybe a weak argument, but worth mentioning.

Another argument is that some log ingest tooling might not behave well if some fields are sometimes included and sometimes not, at the top level. It's the difference between undefined and null in some type systems.

Handlers should be able to add field to server log output for debugging

I'd argue that if the purpose is for debugging, then it should be logged as a debug level log from that module, with a separate logger name (i.e. the handler module's logger, instead of the access logs).

and extending functionality purpose.

This I think is a more compelling reason; it's true that allowing custom modules to manipulate access logging can open doors if there's certain properties of requests that should be pulled out into easier-access log fields.

A recent pr will also add a new field to determine client_ip and it's also available as a variable.

Yep -- adding a new field to the logs is one of the main reasons I'm acting slower on that PR, because I see adding a log field as a breaking change.

If we decide that having some log fields sometimes not exist is okay, then that makes that PR easier to merge because it would be less of a breaking change.

FYI @WeidiDeng I made a change in #5507 that allows handlers to add fields to the access logs.

May it be something like this to have ability to add extra fields to any log message?

    log reverse_proxy {
        output net <my_tcp_collector_host_and_port>
        include http.handlers.reverse_proxy
        level DEBUG
        format filter {
	        wrap json
	        fields {
		        my_custom_field {my_custom_handler.my_custom_field} add
	        }
        }
    }

What do you think?

The eventual plan is to allow adding fields to access logs. I need to figure out a good API for it though.

We can't do it in the log directive because that directive is not a handler, it just sets up logging configuration which is outside of the middleware routes (see the JSON config with caddy adapt --pretty). Thinking maybe a directive like extra_log <field> <value> but I'm not in love with that directive name.

You quoted a logger using http.handlers.reverse_proxy (not an access log), I have no plans right now for making that work. The problem is "when do you run that replacement", and there's no request in context when the encoder runs, it's not passed into the logging library's context. I don't know how that could work at all.

Technically this is already done because we have the ExtraLogFieldsCtxKey that plugins can use to add to the logs, but I'm adding an extra_log directive in https://github.com/caddyserver/caddy/pull/6066 to close this off fully.