Http: multiple response.WriteHeader calls

[DeanMarkTaylor]

I’m seeing a bunch of http: multiple response.WriteHeader calls output in the logs.

I tried removing the cache config sections consisting of the following:

	cache {
		status_header X-Cache-Status
	}

And ran for over 24 hours without an occurrence of the log:

http: multiple response.WriteHeader calls

Put the config sections back in and saw an occurrence of the offending log entry after just 5 minutes and then several after that within 2-3 minutes.

Related thread in forum including further details: https://caddy.community/t/http-multiple-response-writeheader-calls/4667/1

[nicolasazrak]

I have two guesses here: the first one is that there is a concurrency issue in the cache code and the other one is that there is another plugin that is conflicting with the cache code. Are you using another plugin aside from the proxy one? It would be really useful if you had the cache status of the response that caused the problem or a stacktrace.

The problem is that caddy works as a chain of middlewares and anyone can keep a reference to the ResponseWriter and change the status. The cache already checks that to avoid having this problem (https://github.com/nicolasazrak/caddy-cache/blob/master/response.go#L62) but maybe a previous caller in the middleware chain is trying to add another header. I tried to reproduce the issue without luck, that's why I suspect there is something else.

[DeanMarkTaylor]

As indicated in the forum post the only other "setting" in use is "proxy". And for reference the only other plugin compiled in (but not used) is "expires".

If you can give me an indication as to how to compile a more verbose debug output I would give a go... ... currently I compile as follows:

docker run --rm -v $(pwd):/install -e PLUGINS=cache,expires,route53 -e VERSION=0.11.0 abiosoft/caddy:builder

(route53 has been added recently and "multiple response.WriteHeader calls" was seen before adding)

---

Edit: I'll continue to test other config change impacts - currently testing removal of use of status_header - I'll report back.

[DeanMarkTaylor]

I can confirm that removing status_header header has no impact - the problem still exists.

I.e. a config file in the following form with multiple "host" sections causes the issue.

example.co.uk,
www.example.co.uk {
	cache
	proxy / 185.xxx.xxx.xxx {
		transparent
	}
	tls [email protected]
}

example.org,
www.example.org {
	cache
	proxy / 185.xxx.xxx.xxx {
		transparent
	}
	tls [email protected]
}

http://example.net,
http://www.example.net,
example.com,
www.example.com {
	cache
	proxy / 91.xxx.xxx.xxx {
		transparent
	}
	tls [email protected]
}

I do I use tls { ask ... } in one of the config sections currently - however these offending log entries were seen before this was added.

As mentioned previously it would be great if you could give me an indication as to how to compile a more verbose debug output that would aid you.

[nicolasazrak]

I seems that it's not related to the configuration. For compiling it with a more verbose output it's a little bit harder. The problem is that this message comes from the go stdlib, otherwise I would be really easy to change it to show the stacktrace. Let me investigate a little bit, it seems the logger can be changed and that might help.

[DeanMarkTaylor]

I'm also having a different issue regarding stuck / stalled requests - which may / may not be related: https://caddy.community/t/requests-not-completing-stuck-possibly-cache-plugin-issue/4779?u=deanmarktaylor

[nicolasazrak]

This is likely to be a race condition. Can you compile it and run it with -race? I'm going to try to debug it using large files using a range header, maybe that path is problematic.

[naiba]

I'm also having a different issue regarding stuck / stalled requests - which may / may not be related: https://caddy.community/t/requests-not-completing-stuck-possibly-cache-plugin-issue/4779?u=deanmarktaylor

@DeanMarkTaylor I also found this problem, the reason is here. The reason why the request is not interrupted is that the channel is blocked here. If you want to experience the plugin after the merge, I can compile one for you.

and why not merge it? @nicolasazrak

[nicolasazrak]

@DeanMarkTaylor Thanks to the fix that @naiba proposed, I've understood why some request got stuck, it's because of slow readers where breaking the pub/sub mechanism. I've just published the fix. I hope it solves the problem.

[DeanMarkTaylor]

I've came back to testing this again, noted another issue - this might be directly related but reported as a separate bug here: https://github.com/nicolasazrak/caddy-cache/issues/52