"superfluous response.WriteHeader" and "wrote more than the declared Content-Length"

Open DeanMarkTaylor opened this issue 6 years ago • 1 comments

In Caddy 1.0.3 I've been seeing "superfluous response.WriteHeader" and "wrote more than the declared Content-Length" warnings / errors output in the logs.

I managed to track it down to when the http.cache plugin is used.

I've already noted this issue on the forum: https://caddy.community/t/caching-plugin-causing-superfluous-response-writeheader-and-wrote-more-than-the-declared-content-length/6262/

Steps to reproduce

The version I tested with was downloaded from here: https://caddyserver.com/download/windows/amd64?plugins=http.cache&license=personal&telemetry=off

Caddyfile

http://localhost {
	proxy / http://127.0.0.1
	cache
 	log stdout
}

http:// {
	status 418 /
	log stdout
}

Console output

λ caddy -log stdout
Activating privacy features... done.
2019/09/27 18:57:35 [INFO][cache:0xc000196230] Started certificate maintenance routine

Serving HTTP on port 80
http://localhost
http://

2019/09/27 18:57:35 [INFO] Serving http://localhost
2019/09/27 18:57:35 [INFO] Serving http://
127.0.0.1 - - [27/Sep/2019:18:57:38 +0100] "GET / HTTP/1.1" 418 17
2019/09/27 18:57:38 http: superfluous response.WriteHeader call from github.com/caddyserver/caddy/caddyhttp/httpserver.(*ResponseRecorder).WriteHeader (recorder.go:61)
2019/09/27 18:57:38 [Error] failed to write body:  http: wrote more than the declared Content-Length
::1 - - [27/Sep/2019:18:57:38 +0100] "GET / HTTP/1.1" 418 17
2019/09/27 18:58:23 [INFO] SIGINT: Shutting down
2019/09/27 18:58:23 [INFO][cache:0xc000196230] Stopped certificate maintenance routine

Removing the cache line from the Caddyfile results in the errors / warnings not displaying.

Additionally (1)

at times I've seen erroneous additional text at the bottom of responses, mostly during error responses. e.g.

503 Service Unavailable
503 Service Unavailable

Instead of just:

503 Service Unavailable

This has been seen in successful responses (200) too (at the bottom of HTML responses) - but not captured at the time.

Whilst this could be two bugs - it's likely related.

Additionally (2)

Had a crash on Caddy instance on Ubuntu receiving traffic.

This "out of memory" error seems to be "http.cache" related as the instance hasn't crashed until today - this crash is after having caching enabled for ~24-48 hours with a restart in the middle.

Crash Log: https://gist.github.com/DeanMarkTaylor/000b02b4fb4ff7ede8ac3afa6c766bfd

Sep 28 '19 21:09 DeanMarkTaylor

I managed to capture raw HTTP response (via Fiddler) where cache was enabled and disabled for a "503 Service Unavailable" error was occurring for the upstream proxy:

Caching plugin enabled

HTTP/1.1 503 Service Unavailable
Cache-Control: no-cache
Content-Type: text/html
Server: Caddy
X-Cache-Status: skip
Date: Thu, 03 Oct 2019 12:17:37 GMT
Content-Length: 336

<html>
  <head>
    <title>Server Maintenance</title>
  </head>
  <body style="font-family:Arial,Helvetica,sans-serif;">
        <h1>Server Maintenance</h1>
        <p>Dear Visitor.  This site is temporarily unavailable due to a system problem or planned maintenance.  Please bear with us.</p>
  </body>
</html>
503 Service Unavailable

Caching plugin disabled

HTTP/1.1 503 Service Unavailable
Cache-Control: no-cache
Content-Type: text/html
Date: Thu, 03 Oct 2019 12:19:41 GMT
Content-Length: 312

<html>
  <head>
    <title>Server Maintenance</title>
  </head>
  <body style="font-family:Arial,Helvetica,sans-serif;">
        <h1>Server Maintenance</h1>
        <p>Dear Visitor.  This site is temporarily unavailable due to a system problem or planned maintenance.  Please bear with us.</p>
  </body>
</html>

Cross posted here for reference: https://caddy.community/t/caching-plugin-causing-superfluous-response-writeheader-and-wrote-more-than-the-declared-content-length/6262/4?u=deanmarktaylor

Oct 03 '19 12:10 DeanMarkTaylor