caddyserver / caddy

Fast and extensible multi-platform HTTP/1-2-3 web server with automatic HTTPS
https://caddyserver.com
Apache License 2.0
55.79k stars 3.93k forks source link

logs.skip_hosts is ignored #6248

Closed Winand closed 2 months ago

Winand commented 3 months ago

Caddy 2.7.6 in Docker. Port forwarding: 80(host) -> 80(caddy), 2999(host) -> 443(caddy)

I have several domain names in Caddyfile, only one of them has log enabled.

domain1.com {
  ...
}
domain2.com {
  log
  ...
}
domain3.com {
  ...
}

In caddy adapt output I see that domain 1 and 3 are added to skip_hosts:

                    "logs": {
                        "logger_names": {
                            "domain2.com": ""
                        },
                        "skip_hosts": [
                            "domain1.com",
                            "domain3.com"
                        ]
                    },

But access log records for all three domains appear in docker logs caddy. Is it the expected behaviour? Of course I can add skip_log to domains 1 and 3 but why skip_hosts does not disable logs?

francislavoie commented 3 months ago

We've made significant changes to logging since 2.7.6. Please try with the master branch.

Winand commented 3 months ago

First I've built caddy using xcaddy build master Then I've built docker image with modified Dockerfile

...
COPY ./caddy /usr/bin/caddy
RUN setcap cap_net_bind_service=+ep /usr/bin/caddy; \
    chmod +x /usr/bin/caddy; \
    caddy version
...

With this newly built image I have no access log in docker logs caddy output at all with just a log directive in domain2 section. Here's logging part of adapt output:

                    "logs": {
                        "logger_names": {
                            "domain2.com": [
                                ""
                            ]
                        },
                        "skip_hosts": [
                            "domain3.com",
                            "domain1.com"
                        ]
                    },

BUT it works as expected with

  log {
    output stderr
  }

which adds logging section in adapt output:

                    "logs": {
                        "logger_names": {
                            "domain2.com": [
                                "log0"
                            ]
                        },
                        "skip_hosts": [
                            "domain3.com",
                            "domain1.com"
                        ]
                    },
....
    "logging": {
        "logs": {
            "default": {
                "exclude": [
                    "http.log.access.log0"
                ]
            },
            "log0": {
                "include": [
                    "http.log.access.log0"
                ],
                "writer": {
                    "output": "stderr"
                }
            }
        }
    }
francislavoie commented 3 months ago

Interesting, okay I can replicate this. Investigating...

francislavoie commented 3 months ago

I think I have a fix in https://github.com/caddyserver/caddy/pull/6251, can you give it a shot? You can build with xcaddy build fix-default-logger or xcaddy build 732653f

Winand commented 3 months ago

Now it's the same as in v2.7.6. There're access log records for all three domains in stderr, though log directive is only in the 2nd one

domain1.com {
  handle /metrics {
    reverse_proxy node_exporter:9100
  }
}

domain2.com {
  log
  reverse_proxy * firezone:13000
}

domain3.com {
........
}

Here's my Dockerfile to build Caddy.

francislavoie commented 3 months ago

That's not the behaviour I see. If you redact your domains, I can't know with certainty that we're trying the same thing.

Winand commented 3 months ago

Ok, I've made a minimal reproducible example: docker-compose.yml

services:
  caddy:
    image: winand/caddy:2.7.6-default-logger-3
    container_name: caddy
    volumes:
      - ./caddy-data:/data/caddy
      - ./Caddyfile:/etc/caddy/Caddyfile
    ports:
      - "80:80"
      - "2053:443"
    restart: unless-stopped

networks:
  default:
    name: caddy-network

Caddyfile:

domain1.localhost {
  respond "Hello World. I'm domain 1"
}

domain2.localhost {
  log
  respond "Hello World. I'm domain 2"
}

Do requests:

curl -k https://domain2.localhost:2053
curl -k https://domain1.localhost:2053

Docker container logs:

...
{"level":"info","ts":1713546040.6438966,"logger":"http.log.access","msg":"handled request","request":{"remote_ip":"172.18.0.1","remote_port":"52714","client_ip":"172.18.0.1","proto":"HTTP/2.0","method":"GET","host":"domain2.localhost:2053","uri":"/","headers":{"User-Agent":["curl/7.61.1"],"Accept":["*/*"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"domain2.localhost"}},"bytes_read":0,"user_id":"","duration":0.000129289,"size":25,"status":200,"resp_headers":{"Server":["Caddy"],"Alt-Svc":["h3=\":443\"; ma=2592000"],"Content-Type":["text/plain; charset=utf-8"]}}
{"level":"info","ts":1713546054.7794793,"logger":"http.log.access","msg":"handled request","request":{"remote_ip":"172.18.0.1","remote_port":"44428","client_ip":"172.18.0.1","proto":"HTTP/2.0","method":"GET","host":"domain1.localhost:2053","uri":"/","headers":{"User-Agent":["curl/7.61.1"],"Accept":["*/*"]},"tls":{"resumed":false,"version":772,"cipher_suite":4865,"proto":"h2","server_name":"domain1.localhost"}},"bytes_read":0,"user_id":"","duration":0.000028357,"size":25,"status":200,"resp_headers":{"Server":["Caddy"],"Alt-Svc":["h3=\":443\"; ma=2592000"],"Content-Type":["text/plain; charset=utf-8"]}}

I assumed that only domain2.localhost:2053 should be logged.

Winand commented 3 months ago

Update. ✅If I change port to standard - "443:443" in docker compose logging works as expected. ❌If I set https_port 2053 in Caddyfile and - "2053:2053" in docker compose the problem persists

francislavoie commented 3 months ago

Ah right so the problem is with the port being included in the Host. I thought I also fixed that in my PR. I'll take another look. You're sure you used my branch for this last test? (You can run caddy version to make sure)

Winand commented 3 months ago

You're sure you used my branch for this last test? (You can run caddy version to make sure)

[~]$ docker exec caddy caddy version v2.7.6-0.20240419023528-732653fcf0ab h1:cIIuO6xno7uoRS23Bh+ptm3zf2N5UChz0ukcYBD3Dl0=

Built using this Dockerfile with command docker buildx build --build-arg="CADDY_VERSION=fix-default-logger" .

francislavoie commented 3 months ago

Okay, I figured it out, I missed a spot when dropping the port when checking logger config. Updated https://github.com/caddyserver/caddy/pull/6251, you can try building from commit ae03e14 (same branch, but Go tooling sometimes doesn't refresh the build if you use the same branch name so you can just use the commit hash instead)

Winand commented 3 months ago

I run xcaddy in Dockerfile build stage, so each time it's a fresh build for Go tooling.

✅The problem is resolved in version v2.7.6-0.20240421110859-6ef4c4dfcd0f