Caddyfile log directive not working when header_up Host set

[ziddey]

caddy 2.0.0 on ubuntu focal (20.04 lts)

demo Caddyfile:

:8080 {
    respond "OK"
}

domain.com {
    reverse_proxy /bad/* localhost:8080 {
        header_up Host {http.reverse_proxy.upstream.hostport}
    }

    reverse_proxy /good/* localhost:8080 {
        header_up Dummy {http.reverse_proxy.upstream.hostport}
    }

    log {
        output file /var/log/caddy/access.log
    }
}

In this example, requests to domain.com/good/ will log to /var/log/caddy/access.log as expected. However, domain.com/bad/ requests are not and are instead default logged:

journalctl -f -u caddy

caddy[215]: {"level":"info","ts":1592615674.2224905,"logger":"http.log.access","msg":"handled request",...

edit 20200706: changed from localhost to domain.com

[mholt]

Thanks for opening an issue! We'll look into this.

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! This will require some effort on your part -- please understand that we will be dedicating time to fix the bug you are reporting if you can just help us understand it and reproduce it easily.

This template will ask for some information you've already provided; that's OK, just fill it out the best you can. 👍 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 ___.

[ziddey]

The logger is determined here, using the request Host:

caddy/modules/caddyhttp/server.go

Lines 172 to 175 in 3af15c0

	logger := accLog
	if s.Logs != nil {
	logger = s.Logs.wrapLogger(logger, r.Host)
	}

When setting header_up Host for the reverse proxy, it must be overriding the original request's Host header, which causes the named logger to not be found and accLog to be used instead.

caddy/modules/caddyhttp/server.go

Lines 447 to 453 in 3af15c0

	// wrapLogger wraps logger in a logger named according to user preferences for the given host.
	func (slc ServerLogConfig) wrapLogger(logger *zap.Logger, host string) *zap.Logger {
	if loggerName := slc.getLoggerName(host); loggerName != "" {
	return logger.Named(loggerName)
	}
	return logger
	}

As a result, these requests end up getting logged by the default "logger":"http.log.access" instead of the appropriate "logger":"http.log.access.logX"

---

A temporary workaround would be to deploy another site to act as the intermediary. Here we can set header_up Host since we won't be enabling logging. The docs don't mention being able to set variables using Caddyfile, so I've set duplicate headers for x-forwarded-for and x-forwarded-proto to use in the reverse_proxy (since otherwise they'll be set again).

Note: the original x-forwarded headers become replaced inside the reverse_proxy block (much like host) which is why alternate headers need to be set first. As well, it appears the shorthand {header.*} doesn't work, so the full {http.request.header.*} is used instead.

# our fake upstream
:8080 {
    respond "OK"
}

localhost {
    reverse_proxy /bad/* localhost:79

    reverse_proxy /good/* localhost:8080 {
        header_up Dummy {http.reverse_proxy.upstream.hostport}
    }

    log {
        output file /var/log/caddy/access.log
    }
}

# intermediate
:79 {
    bind ::1
    request_header X-Forwarded-For-Orig {http.request.header.X-Forwarded-For}
    request_header X-Forwarded-Proto-Orig {http.request.header.X-Forwarded-Proto}
    reverse_proxy /bad/* localhost:8080 {
        header_up Host {http.reverse_proxy.upstream.hostport}
        header_up X-Forwarded-For {http.request.header.X-Forwarded-For-Orig}
        header_up X-Forwarded-Proto {http.request.header.X-Forwarded-Proto-Orig}
        header_up -X-Forwarded-For-Orig
        header_up -X-Forwarded-Proto-Orig
    }
}

This way, the original request host is maintained for localhost/bad/ and the named logger can be found and used accordingly.

---

The fix should occur in the reverseproxy section, ensuring that original request headers (specifically Host) are not overridden by header_up ones.

[mholt]

Thanks for the good instructions, but I'm not able to reproduce the problem. I used your Caddyfile verbatim, and this is my output log file:

2020/07/06 16:53:12.590	info	http.log.access.log0	handled request	{"request": {"method": "GET", "uri": "/good/", "proto": "HTTP/2.0", "remote_addr": "[::1]:53152", "host": "localhost", "headers": {"User-Agent": ["curl/7.64.1"], "Accept": ["*/*"]}, "tls": {"resumed": false, "version": 771, "ciphersuite": 49196, "proto": "h2", "proto_mutual": true, "server_name": "localhost"}}, "common_log": "::1 - - [06/Jul/2020:10:53:12 -0600] \"GET /good/ HTTP/2.0\" 200 2", "duration": 0.001236557, "size": 2, "status": 200, "resp_headers": {"Server": ["Caddy", "Caddy"], "Content-Length": ["2"], "Date": ["Mon, 06 Jul 2020 16:53:12 GMT"]}}
2020/07/06 16:53:22.238	info	http.log.access.log0	handled request	{"request": {"method": "GET", "uri": "/bad/", "proto": "HTTP/2.0", "remote_addr": "[::1]:53154", "host": "localhost", "headers": {"User-Agent": ["curl/7.64.1"], "Accept": ["*/*"]}, "tls": {"resumed": false, "version": 771, "ciphersuite": 49196, "proto": "h2", "proto_mutual": true, "server_name": "localhost"}}, "common_log": "::1 - - [06/Jul/2020:10:53:22 -0600] \"GET /bad/ HTTP/2.0\" 200 2", "duration": 0.000824753, "size": 2, "status": 200, "resp_headers": {"Server": ["Caddy", "Caddy"], "Date": ["Mon, 06 Jul 2020 16:53:22 GMT"], "Content-Length": ["2"]}}

Using these commands:

$ curl -v "https://localhost/good/"
$ curl -v "https://localhost/bad/"

(To clarify, the reverse proxy doesn't (shouldn't) override the original r.Host value. If it does, that is probably a bug, but I am not seeing evidence of it here.)

[ziddey]

Ah, it looks like caddy doesn't treat localhost as an actual hostname? In my setup, I have a fqdn with https, but I've just tested that http works as well for this issue (seems localhost is the exception).

Updated Caddyfile:

:8080 {
    respond "OK"
}

http://bad.bad.com {
    reverse_proxy /bad/* localhost:8080 {
        header_up Host {http.reverse_proxy.upstream.hostport}
    }

    reverse_proxy /good/* localhost:8080 {
        header_up Dummy {http.reverse_proxy.upstream.hostport}
    }

    log {
        output file /var/log/caddy/access.log
    }
}

Now it gets interesting. In the case of bad.bad.com, we need to specify to host header to curl: -H 'host: bad.bad.com', or with :80 at the end.

curl localhost/bad/ -H 'host: bad.bad.com' -v

2020/07/06 21:07:31.995 INFO http.log.access handled request {"request": {"method": "GET", "uri": "/bad/", "proto": "HTTP/1.1", "remote_addr": "[::1]:42726", "host": "bad.bad.com", "headers": {"User-Agent": ["curl/7.68.0"], "Accept": ["*/*"]}}, "common_log": "::1 - - [06/Jul/2020:21:07:31 +0000] \"GET /bad/ HTTP/1.1\" 200 0", "duration": 0.000459092, "size": 0, "status": 200, "resp_headers": {"Date": ["Mon, 06 Jul 2020 21:07:31 GMT"], "Content-Length": ["0"], "Server": ["Caddy", "Caddy"]}}

As well, other hosts seem to still match this block (in the case of http). These requests also get logged to the main http.log.access: (note: this is not the original issue but is potentially related)

curl localhost/good/ -v

2020/07/06 21:16:38.489 INFO http.log.access handled request {"request": {"method": "GET", "uri": "/good/", "proto": "HTTP/1.1", "remote_addr": "[::1]:43042", "host": "localhost", "headers": {"User-Agent": ["curl/7.68.0"], "Accept": ["*/*"]}}, "common_log": "::1 - - [06/Jul/2020:21:16:38 +0000] \"GET /good/ HTTP/1.1\" 0 0", "duration": 0.000003857, "size": 0, "status": 0, "resp_headers": {"Server": ["Caddy"]}}

edit: also, have updated caddy since first post: v2.1.1 h1:X9k1+ehZPYYrSqBvf/ocUgdLSRIuiNiMo7CvyGUQKeA=

[mholt]

The actual domain names are very important, so that's why we ask that users don't redact, alter, or change their configs (except credentials) when posting them.

This morning was my scheduled time on this issue; I'll have another chance to look at this next time, probably in a week or two. Someone else can look at it before then if they want (or you can!).

[mholt]

Thanks for the info -- as I said, the hostnames do matter so that's why we ask people to never change them when they post reports or ask for help. Finally had some time to look at this again and I think you're right as to the cause, so that made things a bit easier.