"error handling handler error" with multiple handle in handle_errors

1. Caddy version (caddy version):

2.5.2

2. How I run Caddy:

a. System environment:

Docker + docker-compose

b. Command:

docker-compose up

c. Service/unit/compose file:

version: '3.8'

services:
  caddy:
    image: caddy:2.5.2
    ports:
      - "80:80"
      - "443:443"
      - "8383:8383"
    volumes:
      - ./Caddyfile:/etc/caddy/Caddyfile
      - ./.caddy/config/:/config/
      - ./.caddy/data/:/data/

d. My complete Caddyfile or JSON config:

{
    debug
}
:80 {
        handle_errors {
            @404-410 expression `{err.status_code} in [404, 410]`
            handle @404-410 {
                respond "It's a 404 or 410 error!"
            }

            @5xx expression `{err.status_code} >= 500 && {err.status_code} < 600`
            handle @5xx {
                respond "It's a 5xx error."
            }

            handle {
                respond "It's another error"
            }
        }

        route /404 {
            try_files not_exists.html =404
            file_server
        }
        route /500 {
            try_files not_exists.html =500
            file_server
        }
        route /418 {
            try_files not_exists.html =418
            file_server
        }
        respond "hello world"
}

3. The problem I’m having:

When I go the /404 path, I correctly enter the first error handler and receive the "It's a 404 or 410 error!" response data. But if I go to one of the other registered paths (/418 or /500) I receive no response data at all and looking at caddy log, we can see a error handling handler error logged error.

4. Error messages and/or full log output:

commands output

% curl -v http://localhost/404
*   Trying 127.0.0.1:80...
* Connected to localhost (127.0.0.1) port 80 (#0)
> GET /404 HTTP/1.1
> Host: localhost
> User-Agent: curl/7.79.1
> Accept: */*
>
* Mark bundle as not supporting multiuse
< HTTP/1.1 404 Not Found
< Server: Caddy
< Date: Wed, 27 Jul 2022 18:39:42 GMT
< Content-Length: 24
<
* Connection #0 to host localhost left intact
It's a 404 or 410 error!%

% curl -v http://localhost/500
*   Trying 127.0.0.1:80...
* Connected to localhost (127.0.0.1) port 80 (#0)
> GET /500 HTTP/1.1
> Host: localhost
> User-Agent: curl/7.79.1
> Accept: */*
>
* Mark bundle as not supporting multiuse
< HTTP/1.1 500 Internal Server Error
< Server: Caddy
< Date: Wed, 27 Jul 2022 18:39:49 GMT
< Content-Length: 0
<
* Connection #0 to host localhost left intact

% curl -v http://localhost/418
*   Trying 127.0.0.1:80...
* Connected to localhost (127.0.0.1) port 80 (#0)
> GET /418 HTTP/1.1
> Host: localhost
> User-Agent: curl/7.79.1
> Accept: */*
>
* Mark bundle as not supporting multiuse
< HTTP/1.1 418 I'm a teapot
< Server: Caddy
< Date: Wed, 27 Jul 2022 18:39:52 GMT
< Content-Length: 0
<
* Connection #0 to host localhost left intact

logs


{"level":"info","ts":1658948420.6560957,"msg":"using provided configuration","config_file":"/etc/caddy/Caddyfile","config_adapter":"caddyfile"}
{"level":"warn","ts":1658948420.6566408,"msg":"Caddyfile input is not formatted; run the 'caddy fmt' command to fix inconsistencies","adapter":"caddyfile","file":"/etc/caddy/Caddyfile","line":2}
{"level":"info","ts":1658948420.6570919,"logger":"admin","msg":"admin endpoint started","address":"tcp/localhost:2019","enforce_origin":false,"origins":["//localhost:2019","//[::1]:2019","//127.0.0.1:2019"]}
{"level":"warn","ts":1658948420.6571612,"logger":"http","msg":"server is listening only on the HTTP port, so no automatic HTTPS will be applied to this server","server_name":"srv0","http_port":80}
{"level":"info","ts":1658948420.657233,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0x40003a7f10"}
{"level":"info","ts":1658948420.6600542,"logger":"tls","msg":"cleaning storage unit","description":"FileStorage:/data/caddy"}
{"level":"debug","ts":1658948420.6600566,"logger":"http","msg":"starting server loop","address":"[::]:80","http3":false,"tls":false}
{"level":"info","ts":1658948420.6603255,"logger":"tls","msg":"finished cleaning storage units"}
{"level":"info","ts":1658948420.660852,"msg":"autosaved config (load with --resume flag)","file":"/config/caddy/autosave.json"}
{"level":"info","ts":1658948420.660863,"msg":"serving initial configuration"}
{"level":"debug","ts":1658948429.3529906,"logger":"http.log.error","msg":"404","request":{"remote_ip":"172.18.0.1","remote_port":"63362","proto":"HTTP/1.1","method":"GET","host":"localhost","uri":"/404","headers":{"Accept":["*/*"],"User-Agent":["curl/7.79.1"]}},"duration":0.000290208,"status":404,"err_id":"zgu7a19h6","err_trace":"fileserver.parseErrorCode (matcher.go:407)"}
{"level":"error","ts":1658948432.0278478,"logger":"http.log.error","msg":"error handling handler error","request":{"remote_ip":"172.18.0.1","remote_port":"63364","proto":"HTTP/1.1","method":"GET","host":"localhost","uri":"/500","headers":{"User-Agent":["curl/7.79.1"],"Accept":["*/*"]}},"duration":0.000121375,"error":"{id=79bgxgqnm} fileserver.parseErrorCode (matcher.go:407): HTTP 500: 500","first_error":{"msg":"500","status":500,"err_id":"79bgxgqnm","err_trace":"fileserver.parseErrorCode (matcher.go:407)"}}
{"level":"error","ts":1658948433.787707,"logger":"http.log.error","msg":"error handling handler error","request":{"remote_ip":"172.18.0.1","remote_port":"63366","proto":"HTTP/1.1","method":"GET","host":"localhost","uri":"/418","headers":{"User-Agent":["curl/7.79.1"],"Accept":["*/*"]}},"duration":0.000395583,"error":"{id=6u69bmwzp} fileserver.parseErrorCode (matcher.go:407): HTTP 418: 418","first_error":{"msg":"418","status":418,"err_id":"6u69bmwzp","err_trace":"fileserver.parseErrorCode (matcher.go:407)"}}

5. What I already tried:

I simplified my code as much as possible to isolate the problem. For the handle_errors directive, I used the one given as an example in the documentation.
I also tried to remove the @5xx hendler part to simplify it even more, but as soon as I have more than one handle block, I get an error after the first one no matter what.
At this point I suppose that either the docs about handle_errors syntax are not up-to-date, or I stumbled upon a caddy bug :sweat_smile:

6. Links to relevant resources:

1 Like

Oof, you found a really subtle bug!

Didn’t take me long at all to figure it out, but I kinda impressed myself with realizing what it is so quickly, because it’s pretty nuanced!

So the problem is that try_files =404 under the hood puts the error in the request’s context (little bag of data attached to request) because matchers don’t have a way to directly return errors (they can only return a boolean). We then look at the context to see if the matcher produced an error (only if the matcher return false), and then return that error which bubbles up to the top-level route handler. Then, since there was an error, the handle_errors routes are invoked. Turns out, we never clear the matcher error from the request context, so on the first matcher inside the error routes, the same error will be returned again, but only if the matcher returns false (if it returns true it doesn’t look if there’s an error).

This explains the behaviour you were seeing, because only the first handle in your error routes would work, anything else would be “an error during error handling”. Comment out the first handle, and you’ll notice the /500 works but not anything else.

Super simple one-liner fix, just need to clear the error from the request’s context immediately after the matcher.

Thanks for spotting this! Just happens that nobody tried the try_files =404 into handle_errors with matchers in error routes yet, I guess. So many combinations of configuration, we just hadn’t done that for some reason.

2 Likes

Wow, didn’t expect a solution this quickly!
Thanks a lot, I will wait for your PR to be merged :champagne:

1 Like