Caddy will not gracefully stop when SSH is proxied
Closed this issue · 13 comments
Caddy will hang indefinitely on stop with this setup:
https://docs.opnsense.org/manual/how-tos/caddy.html#ssh-multiplexing-on-https-port
User report:
https://forum.opnsense.org/index.php?topic=38714.msg217113#msg217113
My own minimal test case to reproduce it (on FreeBSD 14.1):
caddy-l4 version used: bdee6a6
{
http_port 8080
https_port 8443
servers {
listener_wrappers {
layer4 {
@f9088005-43c9-404d-af09-41fae900ed03 ssh
route @f9088005-43c9-404d-af09-41fae900ed03 {
proxy tcp/127.0.0.1:22 {
}
}
route
}
tls
}
}
grace_period 10s
}
:8080 {
}
:8443 {
}
Open SSH connection: ssh root@172.16.1.109 -p 8443
Try to stop caddy: service caddy stop
Caddy will hang indefinitely or until the SSH connection is disconnected. The grace_period will not kill this context for layer4 proxy.
Expected behavior:
Any Layer 4 proxy will adhere to the grace_period on SIGTERM and disconnect all connections so caddy can stop.
One thing to note, unless it's in the layer4 config block, the rest of the config applies to HTTP servers.
But I'll try to find out why it's not closing connections.
Are there any logs when you send a signal to Caddy? I guess stop sends SIGTERM I think?
Its using the admin interface to tell caddy to stop.
So its sending the stop/restart/reload directly to the socket where Caddy listens on the Admin Endpoint.
Here's the logfiles. It will hang indefinitely after
2024-10-25T19:20:06 | Informational | caddy | "info","ts":"2024-10-25T19:20:06Z","logger":"http","msg":"servers shutting down; grace period initiated","duration":10}
Full log from initial reload till stop while SSH is active:
2024-10-25T19:20:06 Informational caddy "info","ts":"2024-10-25T19:20:06Z","logger":"http","msg":"servers shutting down; grace period initiated","duration":10}
2024-10-25T19:20:06 Warning caddy "warn","ts":"2024-10-25T19:20:06Z","logger":"admin.api","msg":"exiting; byeee!! 👋"}
2024-10-25T19:20:06 Informational caddy "info","ts":"2024-10-25T19:20:06Z","logger":"admin.api","msg":"received request","method":"POST","host":"127.0.0.1","uri":"/stop","remote_ip":"","remote_port":"","headers":{"Accept-Encoding":["gzip"],"Content-Length":["0"],"User-Agent":["Go-http-client/1.1"]}}
2024-10-25T19:19:58 Debug caddy "debug","ts":"2024-10-25T19:19:58Z","logger":"layer4.handlers.proxy","msg":"dial upstream","remote":"172.16.1.105:59791","upstream":"127.0.0.1:22"}
2024-10-25T19:19:58 Debug caddy "debug","ts":"2024-10-25T19:19:58Z","logger":"caddy.listeners.layer4","msg":"matching","remote":"172.16.1.105:59791","matcher":"layer4.matchers.ssh","matched":true}
2024-10-25T19:19:58 Debug caddy "debug","ts":"2024-10-25T19:19:58Z","logger":"caddy.listeners.layer4","msg":"prefetched","remote":"172.16.1.105:59791","bytes":21}
2024-10-25T19:19:58 Error caddy "debug","ts":"2024-10-25T19:19:58Z","logger":"caddy.listeners.layer4","msg":"matching","remote":"172.16.1.105:59791","error":"consumed all prefetched bytes","matcher":"layer4.matchers.ssh","matched":false}
2024-10-25T19:19:29 Informational caddy "info","ts":"2024-10-25T19:19:29Z","logger":"admin","msg":"stopped previous server","address":"unix//var/run/caddy/caddy.sock"}
2024-10-25T19:19:29 Informational caddy "info","ts":"2024-10-25T19:19:29Z","logger":"admin.api","msg":"load complete"}
2024-10-25T19:19:29 Informational caddy "info","ts":"2024-10-25T19:19:29Z","msg":"autosaved config (load with --resume flag)","file":"/var/db/caddy/config/caddy/autosave.json"}
2024-10-25T19:19:29 Informational caddy "info","ts":"2024-10-25T19:19:29Z","logger":"http","msg":"servers shutting down; grace period initiated","duration":10}
2024-10-25T19:19:29 Informational caddy "info","ts":"2024-10-25T19:19:29Z","logger":"http.log","msg":"server running","name":"srv1","protocols":["h1","h2"]}
2024-10-25T19:19:29 Debug caddy "debug","ts":"2024-10-25T19:19:29Z","logger":"http","msg":"starting server loop","address":"[::]:8443","tls":true,"http3":false}
2024-10-25T19:19:29 Informational caddy "info","ts":"2024-10-25T19:19:29Z","logger":"http.log","msg":"server running","name":"srv0","protocols":["h1","h2"]}
2024-10-25T19:19:29 Debug caddy "debug","ts":"2024-10-25T19:19:29Z","logger":"http","msg":"starting server loop","address":"[::]:8080","tls":false,"http3":false}
2024-10-25T19:19:29 Debug caddy "debug","ts":"2024-10-25T19:19:29Z","logger":"http.auto_https","msg":"adjusted config","tls":{"automation":{"policies":[{}]}},"http":{"http_port":8080,"https_port":8443,"grace_period":10000000000,"servers":{"srv0":{"listen":[":8080"],"listener_wrappers":[{"routes":[{"handle":[{"handler":"proxy","upstreams":[{"dial":["tcp/127.0.0.1:22"]}]}],"match":[{"ssh":{}}]},{}],"wrapper":"layer4"},{"wrapper":"tls"}],"routes":[{}],"automatic_https":{"disable":true},"protocols":["h1","h2"]},"srv1":{"listen":[":8443"],"listener_wrappers":[{"routes":[{"handle":[{"handler":"proxy","upstreams":[{"dial":["tcp/127.0.0.1:22"]}]}],"match":[{"ssh":{}}]},{}],"wrapper":"layer4"},{"wrapper":"tls"}],"tls_connection_policies":[{}],"automatic_https":{},"protocols":["h1","h2"]}}}}
2024-10-25T19:19:29 Informational caddy "info","ts":"2024-10-25T19:19:29Z","logger":"http.auto_https","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv1"}
2024-10-25T19:19:29 Informational caddy "info","ts":"2024-10-25T19:19:29Z","logger":"http.auto_https","msg":"server is listening only on the HTTPS port but has no TLS connection policies; adding one to enable TLS","server_name":"srv1","https_port":8443}
2024-10-25T19:19:29 Warning caddy "warn","ts":"2024-10-25T19:19:29Z","logger":"http.auto_https","msg":"server is listening only on the HTTP port, so no automatic HTTPS will be applied to this server","server_name":"srv0","http_port":8080}
2024-10-25T19:19:29 Informational caddy "info","ts":"2024-10-25T19:19:29Z","logger":"admin","msg":"admin endpoint started","address":"unix//var/run/caddy/caddy.sock","enforce_origin":false,"origins":["","//127.0.0.1","//::1"]}
2024-10-25T19:19:29 Informational caddy "info","ts":"2024-10-25T19:19:29Z","logger":"admin.api","msg":"received request","method":"POST","host":"127.0.0.1","uri":"/load","remote_ip":"","remote_port":"","headers":{"Accept-Encoding":["gzip"],"Cache-Control":["must-revalidate"],"Content-Length":["1069"],"Content-Type":["application/json"],"User-Agent":["Go-http-client/1.1"]}}
2024-10-25T19:19:29 Informational caddy "info","ts":"2024-10-25T19:19:29Z","logger":"tls.cache.maintenance","msg":"stopped background certificate maintenance","cache":"0x87081e000"}
2024-10-25T19:19:29 Informational caddy "info","ts":"2024-10-25T19:19:29Z","logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0x87081e000"}
2024-10-25T19:19:29 Debug caddy "debug","ts":"2024-10-25T19:19:29Z","logger":"http.auto_https","msg":"adjusted config","tls":{"automation":{"policies":[{}]}},"http":{"http_port":8080,"https_port":8443,"grace_period":10000000000,"servers":{"srv0":{"listen":[":8080"],"listener_wrappers":[{"routes":[{"handle":[{"handler":"proxy","upstreams":[{"dial":["tcp/127.0.0.1:22"]}]}],"match":[{"ssh":{}}]},{}],"wrapper":"layer4"},{"wrapper":"tls"}],"routes":[{}],"automatic_https":{"disable":true},"protocols":["h1","h2"]},"srv1":{"listen":[":8443"],"listener_wrappers":[{"routes":[{"handle":[{"handler":"proxy","upstreams":[{"dial":["tcp/127.0.0.1:22"]}]}],"match":[{"ssh":{}}]},{}],"wrapper":"layer4"},{"wrapper":"tls"}],"tls_connection_policies":[{}],"automatic_https":{},"protocols":["h1","h2"]}}}}
2024-10-25T19:19:29 Informational caddy "info","ts":"2024-10-25T19:19:29Z","logger":"http.auto_https","msg":"enabling automatic HTTP->HTTPS redirects","server_name":"srv1"}
2024-10-25T19:19:29 Informational caddy "info","ts":"2024-10-25T19:19:29Z","logger":"http.auto_https","msg":"server is listening only on the HTTPS port but has no TLS connection policies; adding one to enable TLS","server_name":"srv1","https_port":8443}
2024-10-25T19:19:29 Warning caddy "warn","ts":"2024-10-25T19:19:29Z","logger":"http.auto_https","msg":"server is listening only on the HTTP port, so no automatic HTTPS will be applied to this server","server_name":"srv0","http_port":8080}
���```
I can confirm the issue on Windows, both if I send a POST to 127.0.0.1:2019/stop and when I press a stop button in my IDE (i.e. SIGINT) - Caddy won't stop, an SSH connection keeps working. However, it seems to be applicable to listener_wrappers only - direct layer4 connections are terminated as intended. See updates below.
My sample config:
{
grace_period 10s
layer4 {
:8022 {
route {
proxy tcp/another.machine:22
}
}
:8028 {
route {
proxy tcp/another.machine:80
}
}
}
servers {
listener_wrappers {
layer4 {
@test-ssh ssh
route @test-ssh {
proxy tcp/another.machine:22
}
@test-http http
route @test-http {
proxy tcp/another.machine:80
}
}
tls
}
}
}
:80 {
respond "OK"
}
Update 1:
- Both direct layer4 connections and listener_wrappers seem to be affected. The issue won't reproduce for the former ones every time though.
- I can also confirm Caddy won't stop while proxying not only SSH, but also HTTP connections (continuous data exchange is required, so it's not enough to open a static web page).
- What is more, when a POST request is sent, Caddy prints "byeee" in the log, than a grace period message appears, 10 seconds pass and nothing happens, with the POST request still waiting for a response. So it's possible to cancel it and issue the second stop request - Caddy prints "byeee" again, but won't stop either.
- After one/two POST requests, when I press a stop button in the IDE, Caddy acknowledges it has received a SIGINT, but won't terminate again. I have to press the stop button twice to make it finally stop.
Update 2:
-
When a POST request is received, the following lines hang for a listener_wrapper connection:
-
On the last line it is the
httpapp that won't stop.
Update 3:
-
Inside the
httpapp, the following lines hang for a listener_wrapper connection: -
Inside
net/http.Server.Shutdown(), it issrv.listenerGroup.Wait()that hangs. -
A few lines before that https://github.com/caddyserver/caddy/blob/eaaa2e5872ef9e845a50c6aade36676c0ecfe2e2/listen.go#L181 is called, and it is written there that it actually doesn't close the underlying listener. I suppose it is done on purpose.
-
There is only one place in the code where
srv.listenerGroupis released -net/http.Server.trackListener(), but the code doesn't get to this place when there is an active listener_wrapper connection.
Update 4:
- I've also checked the prior revisions of caddy-l4 up to ec5408a and the issue persists.
That it will not stop with continous http traffic is also something I have user reports from, but mostly from the caddy ntml plugin and exchange servers. I dont know if its an related issue.
It has been around that time I noticed stop/reload inconsistencies while using the layer4 module too.
I've built with
github.com/mholt/caddy-l4=github.com/WeidiDeng/caddy-l4@20ad8720564575a91e9c8c39c163a5e443660deb
The open SSH connection gets closed now and caddy stops. But it seems caddy stops due to a panic, and not gracefully. Here are what I have in the logs:
Successfully started Caddy (pid=46178) - Caddy is running in the background
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x30 pc=0x7e173d]
goroutine 44 [running]:
net/http.(*conn).serve(0xac0008a0480, {0x2ca17c8, 0xac000390600})
net/http/server.go:1938 +0x3d
created by net/http.(*Server).Serve in goroutine 50
net/http/server.go:3360 +0x485
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x30 pc=0x7e173d]
goroutine 48 [running]:
net/http.(*conn).serve(0xac0008a06c0, {0x2ca17c8, 0xac0003907e0})
net/http/server.go:1938 +0x3d
created by net/http.(*Server).Serve in goroutine 50
net/http/server.go:3360 +0x485
{"level":"info","ts":1730095147.4331343,"msg":"using config from file","file":"/usr/local/etc/caddy/Caddyfile"}
{"level":"warn","ts":1730095147.433274,"msg":"No files matching import glob pattern","pattern":"/usr/local/etc/caddy/caddy.d/*.layer4listener"}
{"level":"warn","ts":1730095147.4333072,"msg":"No files matching import glob pattern","pattern":"/usr/local/etc/caddy/caddy.d/*.layer4global"}
{"level":"warn","ts":1730095147.433338,"msg":"No files matching import glob pattern","pattern":"/usr/local/etc/caddy/caddy.d/*.global"}
{"level":"warn","ts":1730095147.4333642,"msg":"No files matching import glob pattern","pattern":"/usr/local/etc/caddy/caddy.d/*.conf"}
{"level":"info","ts":1730095147.4347057,"msg":"adapted config to JSON","adapter":"caddyfile"}
{"level":"info","ts":1730095147.435025,"msg":"redirected default logger","from":"stderr","to":"unixgram//var/run/caddy/log.sock"}
Successfully started Caddy (pid=64202) - Caddy is running in the background
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x30 pc=0x7e173d]
goroutine 69 [running]:
net/http.(*conn).serve(0x8709fc090, {0x2ca17c8, 0x8700c68d0})
net/http/server.go:1938 +0x3d
created by net/http.(*Server).Serve in goroutine 49
net/http/server.go:3360 +0x485
@Monviech I pushed a new commit, test if now it's fixed. You may need to clean the go mod cache, or clone that branch locally to ensure latest commits.
@WeidiDeng I've built with the new commit and deleted cache and tried it out. Now Caddy is hanging again at this:
2024-10-28T06:22:01 | Informational | caddy | "info","ts":"2024-10-28T06:22:01Z","logger":"http","msg":"servers shutting down; grace period initiated","duration":10}
and the ssh connection stays open.
When I manually close the SSH connection caddy will stop.
@WeidiDeng Caddy stopped gracefully and closed the ssh connection. No errors in the logs.
2024-10-28T09:20:38 | Informational | caddy | "info","ts":"2024-10-28T09:20:38Z","logger":"admin.api","msg":"shutdown complete","exit_code":0} |
2024-10-28T09:20:38 | Informational | caddy | "info","ts":"2024-10-28T09:20:38Z","logger":"admin","msg":"stopped previous server","address":"unix//var/run/caddy/caddy.sock"} |
2024-10-28T09:20:38 | Informational | caddy | "info","ts":"2024-10-28T09:20:38Z","logger":"http","msg":"servers shutting down; grace period initiated","duration":10} |
2024-10-28T09:20:38 | Warning | caddy | "warn","ts":"2024-10-28T09:20:38Z","logger":"admin.api","msg":"exiting; byeee!! 👋"}
Confirm Caddy stops successfully and closes HTTP connections with #261. Thank you, @WeidiDeng!