Add debug log if a request was not explicitly matched/handled

[francislavoie]

This was suggested by a user on the forums: https://caddy.community/t/v2-struggling-with-reverse-proxy-in-a-caddyfile/8352/10

It can be tricky to determine what's going on when Caddy returns an empty 200 response. A debug log that would mention that the request was not matched would be pretty handy to alert users that something wasn't configured correctly.

I took a quick look through the code and I'm not seeing an obvious way to do this because of the handler middleware chain. I think this might not be possible without having some state on the request context that gets set when a handler matches, then checked later in server.go's ServeHTTP().

I'm mainly opening this as a "would be nice if..." but if it's not viable, we can just close this.

[vbakke]

(I really dislike when people answer a post with 'I don't really know < insert the platform in quetsion >, but...'. If you don't know, be quiet. But, now I do it myself...)

I don't really know Go or your middleware, but... in NodeJS and the express middleware, you have a sort of catch-it-all route, that will be executed if no other routes match. To handle 404 in your own way.

Does your middleware have anything similar?

[mholt]

It's probably as simple as adding a log line in the emptyHandler:

caddy/modules/caddyhttp/caddyhttp.go

Line 79 in 1dc4ec2

var emptyHandler Handler = HandlerFunc(func(http.ResponseWriter, *http.Request) error { return nil })

[francislavoie]

I don't think that's enough because we use emptyHandler when a route is terminal:

caddy/modules/caddyhttp/routes.go

Line 223 in 1dc4ec2

nextCopy = emptyHandler

But I figure we could have 2 versions of empty handlers, one that logs and one that doesn't 🤔

I'll try it out I guess

[francislavoie]

Yeah, seems to work. See #3446

[mholt]

@francislavoie

I don't think that's enough because we use emptyHandler when a route is terminal:

An emptyHandler should never be reached if the request is handled, even if a route is terminal. I still think emptyHandler is the right way to do this.

emptyHandler is only the cap at the end of the middleware chain so that it will compile. If it is reached, nothing else happens -- no more middlewares will be invoked in that chain. It essentially means that the request is unhandled.

[mholt]

On second thought, I wonder if this feature would be better implemented with tracing.

The idea is that you can see all the handlers/middlewares that a request flows through -- that is already being planned (/cc @hairyhenderson) and would better fulfill this need than hacking a log into the empty handler.

[hairyhenderson]

I'm coming into this cold, so forgive me if I'm missing some obvious context...

If a request comes in that isn't otherwise handled, shouldn't that get a 404?

Regardless, it probably does makes sense to log this at debug/trace level. I'm not sure I follow why this would be exclusively tracked by the tracing support - I think it would be useful for users to be able to see logs as well to indicate the misconfiguration. If it's only reflected in tracing, that would require the user to have tracing enabled.

[mholt]

@hairyhenderson

If a request comes in that isn't otherwise handled, shouldn't that get a 404?

No, a request that is not configured to be handled is not a client error (or a server error). It is simply a no-op. A 404 is only appropriate where a handler decides that there is no resource at that URI and that the client made an erroneous request. It's also important to limit Caddy's implicit/hidden behaviors, especially where users want absolute control like with request handling.

I'm not sure I follow why this would be exclusively tracked by the tracing support

Tracing will show exactly which middleware handlers/functions are invoked during the cycle of a request.

If it's only reflected in tracing, that would require the user to have tracing enabled.

Same with debug logging. (All requests already show up in the access logs anyway.)

[hairyhenderson]

@mholt ok, makes sense, thanks for clarifying 😉

[vbakke]

(All requests already show up in the access logs anyway.)

It's not client requests that we need for debugging, though. We can see those in the browser.

What is difficult to pinpoint is 'what's happening inside Caddy', and 'what's happening between caddy and the backend'.

This is where Caddy could offer great insight.

Cheers,
Vegard

Log files are also a form of user interface

[mholt]

@vbakke

It's not client requests that we need for debugging, though.

Yes it is. A request comes in from a client. If it is not handled, you want to know that, right? The access logs will tell you that the default/empty response was used with a default status code and an empty body (size 0).

Caddy already logs requests to the backend as well.

The only thing that is needed is a debug log emitted from the emptyHandler. Or, as I more recently suggested, a tracing feature which is probably the correct way to do this, rather than the hacky way.

[francislavoie]

Ultimately I think this isn't really needed; most of the time, if the request went unhandled, the access logs will say that the status code is 0 (which gets turned into 200 by the Go stdlib when writing the response). So watching for that is a good way to tell if a request fell through all response writing handlers.