Caddy access logs log client errors at `"level": "ERROR"`

1. The problem I’m having:

I’m using Caddy as a reverse proxy and have enabled access logs. It’s working correctly, but it logs client errors (e.g., HTTP 404 responses) with "level": "ERROR". That doesn’t seem right to me, as I’d prefer that errors caused by client misbehavior not to show up at the same severity level as, say, a message about Caddy being unable to parse its config file or connect to its storage.

Is there a way to configure Caddy to log HTTP client errors at another severity?

2. Error messages and/or full log output:

{
  "level":"INFO",
  "timestamp":"2024-02-12T21:12:06.294612446Z",
  "logger":"watcher",
  "msg":"config file changed; reloading",
  "config_file":"/config/caddyfile.json"
}
{
  "level":"INFO",
  "timestamp":"2024-02-12T21:12:06.296271855Z",
  "logger":"admin",
  "msg":"admin endpoint started",
  "address":"localhost:2019",
  "enforce_origin":false,
  "origins":["//localhost:2019","//[::1]:2019","//127.0.0.1:2019"]
}
{
  "level":"INFO",
  "timestamp":"2024-02-12T21:12:06.296485225Z",
  "logger":"admin",
  "msg":"stopped previous server",
  "address":"localhost:2019"
}
{
    "level": "ERROR",
    "timestamp": "2024-02-12T21:12:07.715988859Z",
    "logger": "http.log.access",
    "msg": "handled request",
    "request": {
        "remote_ip": "127.0.0.1",
        "remote_port": "33876",
        "client_ip": "127.0.0.1",
        "proto": "HTTP/1.1",
        "method": "GET",
        "host": "localhost:8080",
        "uri": "/",
        "headers": {
            "User-Agent": ["curl/8.2.1"],
            "Accept": ["*/*"]
        }
    },
    "bytes_read": 0,
    "user_id": "",
    "duration": 0.000592309,
    "size": 0,
    "status": 404,
    "resp_headers": {
        "Server": [
            "Caddy",
            "trillium/0.3.13"
        ],
        "Date": ["Mon, 12 Feb 2024 21:12:07 GMT"],
        "Content-Length": ["0"]
    }
}

3. Caddy version:

Caddy 2.7.6

4. How I installed and ran Caddy:

I build Caddy with this Dockerfile:

FROM caddy:2.7.6-builder-alpine AS builder

RUN xcaddy build \
    --with github.com/caddyserver/caddy/v2@v2.7.6 \
    --with github.com/pberkel/caddy-storage-redis@v1.1.0 \
    --with github.com/mholt/caddy-ratelimit@89a7fece9addf6881169642d0b8a18e79d58e179

FROM caddy:2.7.6-alpine

ARG GIT_REVISION=unknown
LABEL revision ${GIT_REVISION}
COPY --from=builder /usr/bin/caddy /usr/bin/caddy

a. System environment:

Running in Google Kubernetes Engine 1.27

b. Command:

caddy run --config /config/caddyfile.json --watch

c. Service/unit/compose file:

d. My complete Caddy config:

{
    "admin": {
        "config": {
            "persist": false
        }
    },
    "apps": {
        "http": {
            "servers": {
                "metrics": {
                    "listen": [
                        ":9465"
                    ],
                    "metrics": {},
                    "routes": [
                        {
                            "handle": [
                                {
                                    "handler": "metrics"
                                }
                            ],
                            "match": [
                                {
                                    "path": [
                                        "/metrics"
                                    ]
                                }
                            ]
                        }
                    ]
                },
                "rate_limiter": {
                    "listen": [
                        ":80"
                    ],
                    "logs": {},
                    "metrics": {},
                    "routes": [
                        {
                            "handle": [
                                {
                                    "distributed": {
                                        "read_interval": "5s",
                                        "write_interval": "5s"
                                    },
                                    "handler": "rate_limit",
                                    "rate_limits": {
                                        "report-upload": {
                                            "key": "{http.regexp.report-upload.1}",
                                            "max_events": 375,
                                            "window": "15s"
                                        }
                                    }
                                },
                                {
                                    "handler": "reverse_proxy",
                                    "upstreams": [
                                        {
                                            "dial": ":8080"
                                        }
                                    ]
                                }
                            ],
                            "match": [
                                {
                                    "method": [
                                        "PUT"
                                    ],
                                    "path_regexp": {
                                        "name": "report-upload",
                                        "pattern": "/tasks/([0-9A-Za-z_-]{43})/reports"
                                    }
                                }
                            ]
                        },
                        {
                            "handle": [
                                {
                                    "distributed": {
                                        "read_interval": "5s",
                                        "write_interval": "5s"
                                    },
                                    "handler": "rate_limit",
                                    "rate_limits": {
                                        "aggregation-job": {
                                            "key": "{http.regexp.aggregation-job.1}",
                                            "max_events": 150,
                                            "window": "15s"
                                        }
                                    }
                                },
                                {
                                    "handler": "reverse_proxy",
                                    "upstreams": [
                                        {
                                            "dial": ":8080"
                                        }
                                    ]
                                }
                            ],
                            "match": [
                                {
                                    "method": [
                                        "PUT",
                                        "POST"
                                    ],
                                    "path_regexp": {
                                        "name": "aggregation-job",
                                        "pattern": "/tasks/([0-9A-Za-z_-]{43})/aggregation_jobs/[0-9A-Za-z_-]{22}"
                                    }
                                }
                            ]
                        },
                        {
                            "handle": [
                                {
                                    "distributed": {
                                        "read_interval": "5s",
                                        "write_interval": "5s"
                                    },
                                    "handler": "rate_limit",
                                    "rate_limits": {
                                        "collection-job": {
                                            "key": "{http.regexp.collection-job.1}",
                                            "max_events": 150,
                                            "window": "15s"
                                        }
                                    }
                                },
                                {
                                    "handler": "reverse_proxy",
                                    "upstreams": [
                                        {
                                            "dial": ":8080"
                                        }
                                    ]
                                }
                            ],
                            "match": [
                                {
                                    "method": [
                                        "PUT",
                                        "POST",
                                        "DELETE"
                                    ],
                                    "path_regexp": {
                                        "name": "collection-job",
                                        "pattern": "/tasks/([0-9A-Za-z_-]{43})/collection_jobs/[0-9A-Za-z_-]{22}"
                                    }
                                }
                            ]
                        },
                        {
                            "handle": [
                                {
                                    "distributed": {
                                        "read_interval": "5s",
                                        "write_interval": "5s"
                                    },
                                    "handler": "rate_limit",
                                    "rate_limits": {
                                        "aggregate-share": {
                                            "key": "{http.regexp.aggregate-share.1}",
                                            "max_events": 150,
                                            "window": "15s"
                                        }
                                    }
                                },
                                {
                                    "handler": "reverse_proxy",
                                    "upstreams": [
                                        {
                                            "dial": ":8080"
                                        }
                                    ]
                                }
                            ],
                            "match": [
                                {
                                    "method": [
                                        "POST"
                                    ],
                                    "path_regexp": {
                                        "name": "aggregate-share",
                                        "pattern": "/tasks/([0-9A-Za-z_-]{43})/aggregate_shares"
                                    }
                                }
                            ]
                        },
                        {
                            "handle": [
                                {
                                    "handler": "vars",
                                    "skip_log": true
                                },
                                {
                                    "handler": "static_response",
                                    "status_code": 200
                                }
                            ],
                            "match": [
                                {
                                    "method": [
                                        "GET"
                                    ],
                                    "path": [
                                        "/healthz"
                                    ]
                                }
                            ]
                        },
                        {
                            "handle": [
                                {
                                    "handler": "reverse_proxy",
                                    "upstreams": [
                                        {
                                            "dial": ":8080"
                                        }
                                    ]
                                }
                            ],
                            "match": [
                                {
                                    "path": [
                                        "/*"
                                    ]
                                }
                            ]
                        }
                    ]
                }
            }
        }
    },
    "logging": {
        "logs": {
            "default": {
                "encoder": {
                    "fields": {},
                    "format": "filter",
                    "wrap": {
                        "format": "json",
                        "level_format": "upper",
                        "time_format": "rfc3339_nano",
                        "time_key": "timestamp"
                    }
                },
                "include": [
                    "http.handlers.rate_limit",
                    "http.log.access"
                ],
                "level": "info",
                "sampling": {
                    "first": 10,
                    "thereafter": 100
                },
                "writer": {
                    "output": "stdout"
                }
            }
        }
    },
    "storage": {
        "host": [
            "redis.kind-ci-castor.svc"
        ],
        "key_prefix": "kind-ci-castor",
        "module": "redis",
        "port": [
            "6379"
        ],
        "tls_enabled": false,
        "tls_insecure": false,
        "tls_server_certs_pem": null
    }
}

5. Links to relevant resources:

1 Like

Not currently, no. But it’s probably something we can do.

You can (and probably should) write those to a separate file/stream from the rest of Caddy’s logs though (with include/exclude), so it shouldn’t interfere with other “more important” logs.

What severity would you have those written at?

1 Like

I’d be open to making a change like this. Should it just be INFO level like the others?

I strongly disagree to making a breaking change at this point.

My suggestion:

{
	servers {
		log_level 4xx INFO
		log_level 5xx ERROR
		log_level 502 INFO
	}
}

Would go besides Global options (Caddyfile) — Caddy Documentation essentially, server-wide config.

In JSON, it would be under servers > name > logs > level or something like that, mapping of status code to level.

Hm, I don’t view it as a breaking change (as discussed in slack) – especially considering the several other breaking changes we are making for 2.8 :upside_down_face:

I think people expect to only be alerted to 5xx errors, not 4xx. Arguably what we emit now is buggy.

FWIW I agree with @francislavoie that avoiding a breaking change is preferable, but I defer to the maintainers of Caddy. Defaulting to the current behavior but having a configuration option as Francis suggests would solve my problem.

And in aid of prioritization: this is a pretty minor issue for us. The fact that log entries are structured in JSON gives us plenty of ways to distinguish stuff we’re really worried about (like 500 Server Error) from 404s, and we have other metrics for request success and failure.

2 Likes

I still think 4xx should just be info-level :stuck_out_tongue_winking_eye:

I will advocate for this :+1:

I think if any change is made, 4xx should be WARN.

We do have evidence of users specifically wanting to parse out 403s, to rate limit/ban failed basicauth attempts. That’s what fail2ban is designed to do (although it doesn’t integrate too well with Caddy as-is).

So making that INFO would force users to plug into a way-too-noisy log stream when they know they only want this one status code.

1 Like

I wrote up an issue on the Caddy GitHub repo, referencing this discussion, so that we have some record of this work that won’t get auto-closed after a month. Thanks!

2 Likes

Thanks! Hopefully I’ll address it well before then :smile: