Redirects (302) seem to be swallowed in 0.8.0

[julianrubisch]

I just upgraded an application to Kamal 2.2 (hence kamal-proxy 0.8.0) and observed some strange behavior concerning redirects:

After doing kamal proxy reboot, in both the kamal proxy as well as my application logs, I saw a 302 being rendered with the correct Location header.

In the browser, however, a 200 landed, but the Location header was preserved. I double and triple checked by moving between kamal 2.1.2 and kamal 2.2.0 and repeatedly doing kamal proxy reboot.

Additional context: it's an in-house app, hence no SSL. my kamal proxy config looks like this:

proxy:
  app_port: 3000
  ssl: false
  healthcheck:
    path: /health_check
    interval: 3
    timeout: 60
  forward_headers: true

[kevinmcconnell]

@julianrubisch I've been trying to reproduce this problem but so far I've been unable to. I consistently get the expected 302 from redirects after upgrading an app to Kamal 2.2.0/Kamal Proxy 0.8.0.

Are you able to reproduce this in a freshly deployed app, or is the behaviour specific to this particular app?

Also is there anything else in your setup that could be involved here, like additional proxies or load balancers? Do you see the problematic 200 response if you directly curl the request from Kamal Proxy?

[julianrubisch]

I will try to come up with an MVCE. (which is a bit hard to do as it comes to deployment tools)

It is weird, I admit as much.

Furthermore, it is because the environment is as bare bones as it can be (single in house server in a SMB, no load balancers, proxies or anything, CMD ["./bin/rails", "server"]) and the consistent difference between 2.1.2 and 2.2.0 that made me report this.

I think this should rule out configuration errors on my part as much as possible.

That said, I haven't tried curl ing yet, but I did try in different browsers

[julianrubisch]

curl + kamal-proxy logs with Kamal 2.2.0:

$ curl -i http://192.168.1.181/
HTTP/1.1 200 OK
Cache-Control: no-cache
Content-Type: text/html; charset=utf-8
Location: http://192.168.1.181/admin_users/sign_in
Set-Cookie: _my_app_session=def52b0930115bec025d10d5d3fb3279; path=/; httponly
X-Request-Id: 75f79f8c-d6b3-4eda-b2b1-e88d30ccc1b9
X-Runtime: 0.018681
Date: Wed, 09 Oct 2024 15:09:07 GMT
Transfer-Encoding: chunked

2024-10-09T15:09:07.476683071Z {"time":"2024-10-09T15:09:07.476396388Z","level":"INFO","msg":"http: superfluous response.WriteHeader call from github.com/basecamp/kamal-proxy/internal/server.(*loggerResponseWriter).WriteHeader (logging_middleware.go:132)"}
2024-10-09T15:09:07.476736743Z {"time":"2024-10-09T15:09:07.476554746Z","level":"INFO","msg":"Request","host":"192.168.1.181","port":80,"path":"/","request_id":"75f79f8c-d6b3-4eda-b2b1-e88d30ccc1b9","status":302,"service":"my-app-web-production","target":"12f001099b20:3000","duration":21913704,"method":"GET","req_content_length":0,"req_content_type":"","resp_content_length":0,"resp_content_type":"text/html; charset=utf-8","client_addr":"10.212.134.226","client_port":"64254","remote_addr":"10.212.134.226","user_agent":"curl/8.7.1","proto":"HTTP/1.1","scheme":"http","query":"","req_cache_control":"","req_last_modified":"","req_user_agent":"curl/8.7.1"}

curl + kamal-proxy logs with Kamal 2.1.2:

$ curl -i http://192.168.1.181/
HTTP/1.1 302 Found
Cache-Control: no-cache
Content-Type: text/html; charset=utf-8
Location: http://192.168.1.181/admin_users/sign_in
Set-Cookie: _my_app_session=5090b923d09fa8716191ccc526eda986; path=/; httponly
X-Request-Id: 3cecae0c-5d71-40ac-9ac2-d978cbcca777
X-Runtime: 0.019620
Date: Wed, 09 Oct 2024 15:13:36 GMT
Content-Length: 0

2024-10-09T15:13:36.332168919Z {"time":"2024-10-09T15:13:36.331913702Z","level":"INFO","msg":"Request","host":"192.168.1.181","port":80,"path":"/","request_id":"3cecae0c-5d71-40ac-9ac2-d978cbcca777","status":302,"service":"my-app-web-production","target":"12f001099b20:3000","duration":24478836,"method":"GET","req_content_length":0,"req_content_type":"","resp_content_length":0,"resp_content_type":"text/html; charset=utf-8","client_addr":"10.212.134.226","client_port":"65419","remote_addr":"10.212.134.226","user_agent":"curl/8.7.1","proto":"HTTP/1.1","scheme":"http","query":"","req_cache_control":"","req_last_modified":"","req_user_agent":"curl/8.7.1"}

what stands out is that the superfluous response.WriteHeader call info msg doesn't appear in the 2.1.2 logs. Does that give you something?

[kevinmcconnell]

Thanks, yes that's helpful! It does seem like something is flushing the headers too soon. I'll investigate this further and let you know what I find.

[jeppeliisberg]

Seeing the same here after upgrading from kamal 1.x - also a single server very basic setup. Let me know if I can contribute with any details.

[kevinmcconnell]

I have a fix for this now. Will publish a new release shortly. Thanks for reporting!

[julianrubisch]

Thanks for the fast turnaround!

[kevinmcconnell]

I've released 0.8.1 with the fix (the fix is in eaa84d3).

We'll get a corresponding Kamal release out now.

[kevinmcconnell]

Kamal PR: basecamp/kamal#1086

[kevinmcconnell]

@julianrubisch @jeppeliisberg a new Kamal release is now available with the fix (2.2.1). If you have a chance, could you let me know if that has resolved the problem for you? Thanks! 🙏

[julianrubisch]

looking good on my part 👏

[kevinmcconnell]

Great, thanks for confirming @julianrubisch!