Caddy will not gracefully stop when SSH is proxied #258

Monviech · 2024-10-25T09:56:55Z

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 [email protected] -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.

The text was updated successfully, but these errors were encountered:

mholt · 2024-10-25T18:40:49Z

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.

mholt · 2024-10-25T18:43:09Z

Are there any logs when you send a signal to Caddy? I guess stop sends SIGTERM I think?

Monviech · 2024-10-25T18:51:13Z

Its using the admin interface to tell caddy to stop.

https://github.com/opnsense/ports/blob/0a04fb51826bb9102ee3c9b9704138837ae4444d/www/caddy-custom/files/caddy.in#L148

So its sending the stop/restart/reload directly to the socket where Caddy listens on the Admin Endpoint.

Monviech · 2024-10-25T19:23:29Z

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}
���```

vnxme · 2024-10-25T20:24:41Z

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 http app that won't stop.

Update 3:

Inside the http app, the following lines hang for a listener_wrapper connection:
- https://github.com/caddyserver/caddy/blob/eaaa2e5872ef9e845a50c6aade36676c0ecfe2e2/modules/caddyhttp/app.go#L744
- https://github.com/caddyserver/caddy/blob/eaaa2e5872ef9e845a50c6aade36676c0ecfe2e2/modules/caddyhttp/app.go#L691
Inside net/http.Server.Shutdown(), it is srv.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.listenerGroup is 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.

Monviech · 2024-10-26T09:18:19Z

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.

opnsense/plugins#4261

WeidiDeng · 2024-10-28T03:20:12Z

@Monviech Can you try this pr?

Monviech · 2024-10-28T06:01:51Z

@WeidiDeng

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

WeidiDeng · 2024-10-28T06:12:02Z

@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.

Monviech · 2024-10-28T06:25:17Z

@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 · 2024-10-28T07:48:51Z

@Monviech Now, try it again.

Monviech · 2024-10-28T09:21:54Z

@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!! 👋"}

vnxme · 2024-10-28T14:27:23Z

Confirm Caddy stops successfully and closes HTTP connections with #261. Thank you, @WeidiDeng!

WeidiDeng mentioned this issue Oct 28, 2024

stop the loop when listener is closed #261

Merged

mholt closed this as completed in #261 Nov 4, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Caddy will not gracefully stop when SSH is proxied #258

Caddy will not gracefully stop when SSH is proxied #258

Monviech commented Oct 25, 2024

mholt commented Oct 25, 2024

mholt commented Oct 25, 2024

Monviech commented Oct 25, 2024 •

edited

Loading

Monviech commented Oct 25, 2024

vnxme commented Oct 25, 2024 •

edited

Loading

Monviech commented Oct 26, 2024 •

edited

Loading

WeidiDeng commented Oct 28, 2024

Monviech commented Oct 28, 2024

WeidiDeng commented Oct 28, 2024

Monviech commented Oct 28, 2024

WeidiDeng commented Oct 28, 2024

Monviech commented Oct 28, 2024

vnxme commented Oct 28, 2024

Caddy will not gracefully stop when SSH is proxied #258

Caddy will not gracefully stop when SSH is proxied #258

Comments

Monviech commented Oct 25, 2024

mholt commented Oct 25, 2024

mholt commented Oct 25, 2024

Monviech commented Oct 25, 2024 • edited Loading

Monviech commented Oct 25, 2024

vnxme commented Oct 25, 2024 • edited Loading

Monviech commented Oct 26, 2024 • edited Loading

WeidiDeng commented Oct 28, 2024

Monviech commented Oct 28, 2024

WeidiDeng commented Oct 28, 2024

Monviech commented Oct 28, 2024

WeidiDeng commented Oct 28, 2024

Monviech commented Oct 28, 2024

vnxme commented Oct 28, 2024

Monviech commented Oct 25, 2024 •

edited

Loading

vnxme commented Oct 25, 2024 •

edited

Loading

Monviech commented Oct 26, 2024 •

edited

Loading