Caddy: Site access log outputs to default log despite not being enabled, if on same port as a site that has it enabled

[aPinat]

Caddy version: v2.0.0-rc.3

Without any log directives in any site blocks, no access logging is being output anywhere as expected.
As soon as a single log directive inside a single site block, like the one below, is added Caddy starts to output all access logs (for every site block, not only where the directive as added in) to stderr in addition to also outputting the site specific access log to access.log (in this case).

log {
  output file access.log
}

I haven't found any way to again disable the access log for the other site blocks. Placing the discard output module inside the other site blocks, as below, also doesn't stop stderr being spammed with the access log.

log {
  output discard
}

Also limiting the log level for stderr doesn't seam to help...

log {
  output stderr
  level ERROR
}

I would like to be able to only enable access logging for a single site block, while having all other site blocks behave like with no logging directive was enabled anywhere. It would also be nice if Caddy only outputs to the output module specified and not redundantly in stderr as well.

[mholt]

You can always ignore extra logs that you don't want.

However, a lot of people seem confused by this, so I opened this PR: https://github.com/caddyserver/caddy/pull/3301 - can you try that out? Does it solve the problem for you?

Duplicate of #3294.

[aPinat]

Ah, I see...
So by ignoring you mean filtering them externally again to only see the log entries without access logs? Since I read TLS errors from the default log, it's hard to find those, when a lot of small requests are also in the same log without programmatically filtering them.

Also, for me it was so confusing, because when no logging directive is set anywhere, no access logging is done and the default output of course also shows nothing, but once a single one is set then the default log also shows it for all other sites, even though I actually only want the log for that single site.
Generally I am fine with the duplication, if it would only output the access log of the single site I wanted it from.

So, I've read a little more into the other issues, and I can just exclude the access log from the default logger through the JSON config, but there is no way to do it in the Caddyfile, right?

As for your PR, I haven't come around to install and build Go yet, but looking at the code, that looks good and would be the solution I'd prefer!

[mholt]

@aPinat You can download the build artifact from that PR, no need to compile from source.

So, I've read a little more into the other issues, and I can just exclude the access log from the default logger through the JSON config, but there is no way to do it in the Caddyfile, right?

That's what the PR does, if I understand you right. Can you try it out and let me know?

but once a single one is set then the default log also shows it for all other sites, even though I actually only want the log for that single site.

Can you provide more information so I can reproduce the issue? It's not immediately clear to me what is going on, so I'll need your help to understand it better.

Ideally, we need to be able to reproduce the bug _in the most minimal way possible_. This allows us to write regression tests to verify the fix is working. If we can't reproduce it, then you'll have to test our changes for us until it's fixed -- and then we can't add test cases, either.

I've attached a template below that will help make this easier and faster! It will ask for some information you've already provided; that's OK, just fill it out the best you can. :+1:

I've also included some helpful tips below the template. Feel free to let me know if you have any questions!

Thank you again for your report, we look forward to resolving it!

Template

## 1. Environment

### 1a. Operating system and version

paste here


1b. Caddy version (run caddy version or paste commit SHA)

paste here


1c. Go version (if building Caddy from source; run go version)

paste here


2. Description

2a. What happens (briefly explain what is wrong)

2b. Why it's a bug (if it's not obvious)

2c. Log output

paste terminal output or logs here


2d. Workaround(s)

2e. Relevant links

3. Tutorial (minimal steps to reproduce the bug)

Helpful tips

1. Environment: Please fill out your OS and Caddy versions, even if you don't think they are relevant. (They are _always_ relevant.) If you built Caddy from source, provide the commit SHA and specify your exact Go version.

2. Description: Describe at a high level what the bug is. What happens? Why is it a bug? Not all bugs are obvious, so convince readers that it's actually a bug.

   • 2c) Log output: Paste terminal output and/or complete logs in a code block. DO NOT REDACT INFORMATION except for credentials.
   • 2d) Workaround: What are you doing to work around the problem in the meantime? This can help others who encounter the same problem, until we implement a fix.
   • 2e) Relevant links: Please link to any related issues, pull requests, docs, and/or discussion. This can add crucial context to your report.

3. Tutorial: What are the _minimum required specific steps_ someone needs to take in order to experience the same bug? Your goal here is to make sure that anyone else can have the same experience with the bug as you do. You are writing a tutorial, so make sure to carry it out yourself before posting it. Please:

   • Start with an empty config. Add _only_ the lines/parameters that are _absolutely required_ to reproduce the bug.
   • Do not run Caddy inside containers.
   • Run Caddy manually in your terminal; do not use systemd or other init systems.
   • If making HTTP requests, avoid web browsers. Use a simpler HTTP client instead, like curl.
   • Do not redact any information from your config (except credentials). Domain names are public knowledge and often necessary for quick resolution of an issue!
   • Note that ignoring this advice may result in delays, or even in your issue being closed. 😞 Only actionable issues are kept open, and if there is not enough information or clarity to reproduce the bug, then the report is not actionable.

Example of a tutorial:

Create a config file:

{ ... }

Open terminal and run Caddy:

$ caddy ...

Make an HTTP request:

$ curl ...

Notice that the result is ___ but it should be ___.

[aPinat]

So, I've tried the build from your PR, and while it does remove the duplicated log from the console output as expected, the logs for different sites still show up as well, as I will report below.
After a couple hours of testing I have finally been able to narrow down the issue to be compact and easily reproducible:

1. Environment

1a. Operating system and version

Tested and reproduced on Windows 10 Version 2004 Build 19041.208
Initially occurred on Windows Server 2019 Version 1809 Build 17763.1192

1b. Caddy version (run caddy version or paste commit SHA)

v2.0.0-rc.3 h1:z2H/QnaRscip6aZJxwTbghu3zhC88Vo8l/K57WUce4Q=

2. Description

2a. What happens (briefly explain what is wrong)

Adding the log directive to a single site block also enables access logging for all other sites (it seams the sites need to be on the same port though)

2b. Why it's a bug (if it's not obvious)

It should not be logging other sites running on the same server/port if not specified in the config.

2c. Log output

Console output:

{"level":"info","ts":1587934097.2151284,"msg":"using adjacent Caddyfile"}
{"level":"info","ts":1587934097.2301326,"logger":"admin","msg":"admin endpoint started","address":"tcp/localhost:2019","enforce_origin":false,"origins":["127.0.0.1:2019","localhost:2019","[::1]:2019"]}
{"level":"info","ts":1587934097.2301326,"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}
2020/04/26 22:48:17 [INFO][cache:0xc00038fa40] Started certificate maintenance routine
{"level":"info","ts":1587934097.2331324,"logger":"tls","msg":"cleaned up storage units"}
{"level":"info","ts":1587934097.2361343,"msg":"autosaved config","file":"C:\\Users\\apina\\AppData\\Roaming\\Caddy\\autosave.json"}
{"level":"info","ts":1587934097.2361343,"msg":"serving initial configuration"}
{"level":"info","ts":1587934110.7292602,"logger":"http.log.access","msg":"handled request","request":{"method":"GET","uri":"/","proto":"HTTP/1.1","remote_addr":"[::1]:4241","host":"localhost","headers":{"User-Agent":["curl/7.55.1"],"Accept":["*/*"]}},"common_log":"::1 - - [26/Apr/2020:22:48:30 +0200] \"GET / HTTP/1.1\" 0 0","latency":0,"size":0,"status":0,"resp_headers":{"Server":["Caddy"]}}
{"level":"info","ts":1587934152.4946542,"logger":"http.log.access.log0","msg":"handled request","request":{"method":"GET","uri":"/","proto":"HTTP/1.1","remote_addr":"127.0.0.1:4261","host":"auth.localhost","headers":{"User-Agent":["curl/7.55.1"],"Accept":["*/*"]}},"common_log":"127.0.0.1 - - [26/Apr/2020:22:49:12 +0200] \"GET / HTTP/1.1\" 0 0","latency":0,"size":0,"status":0,"resp_headers":{"Server":["Caddy"]}}
{"level":"info","ts":1587934157.001663,"msg":"shutting down","signal":"SIGINT"}
2020/04/26 22:49:17 [INFO][cache:0xc00038fa40] Stopped certificate maintenance routine
{"level":"info","ts":1587934157.001663,"msg":"shutdown done","signal":"SIGINT"}

auth.log

{"level":"info","ts":1587934152.4946542,"logger":"http.log.access.log0","msg":"handled request","request":{"method":"GET","uri":"/","proto":"HTTP/1.1","remote_addr":"127.0.0.1:4261","host":"auth.localhost","headers":{"User-Agent":["curl/7.55.1"],"Accept":["*/*"]}},"common_log":"127.0.0.1 - - [26/Apr/2020:22:49:12 +0200] \"GET / HTTP/1.1\" 0 0","latency":0,"size":0,"status":0,"resp_headers":{"Server":["Caddy"]}}

2d. Workaround(s)

Running the site, that is being logged, on another port makes the other sites disappear from the log again. For example exchange auth.localhost in with localhost:8080 in the tutorial below and the issue does not appear.

3. Tutorial (minimal steps to reproduce the bug)

Create Caddyfile:

http://localhost {

}

http://auth.localhost {
    log {
        output file auth.log
    }
}

Make sure both resolve to 127.0.0.1, ex. add this to hosts file:

127.0.0.1 localhost
127.0.0.1 auth.localhost

Open terminal and run Caddy:

> caddy run

Make requests to localhost and auth.localhost

> curl localhost
> curl auth.localhost

Observe the result in console output and auth.log as posted above.
Find that the request to localhost is also being logged by the logger http.log.access to console output, despite not specified and unwanted in Caddyfile. Request to auth.localhost is correctly logged to both console and auth.log.
Running the build from #3301 correctly does not log requests from auth.localhost to console output and only to auth.log, but requests to localhost are still being logged to console, so same issue remains.
This also happens with different domains (so issue is not limited to subdomains), ex. exchange auth.localhost with local and test again with same results.

[mholt]

@aPinat Thanks, that's super helpful! I will look at it this week.

[mholt]

@aPinat I spent most of the morning and afternoon today working on a fix for your issue, and generally improving access logging overall. Please try the latest in #3301 if you would, and confirm for me that it resolves all issues for you! Thank you!

[aPinat]

@mholt Hey! Thanks for resolving this so quickly!
I've just tested the latest build of that PR and it seams to be working mostly for me, except for one thing: if the site address contains an asterisk like *.localhost in place of auth.localhost using the example above requests matching that block are still being logged incorrectly.

[mholt]

Thanks for trying it out. I haven't implemented support for wildcards. It's already really complicated...

Honestly, if you need that, my recommendation is to just use the default log and ignore the lines you don't want.

[aPinat]

No, that's fine, just wanted to point that out since it's related or is part of this and I noticed it.

Thanks!

[mholt]

Alrighty, cool then. I appreciate you trying it out and being thorough! If this is something that's really needed, we can look into adding it later.