Repository: caddyserver/caddy (language: go)

Issue:
Slow config reload when using shutdown_delay
We're currently using a `shutdown_delay` of 15 seconds to give our hardware load balancer warning of when caddy is about to go down for drains/maintenance etc as per https://caddyserver.com/docs/caddyfile/options#shutdown-delay - but this also seems to delay the config reload by the same amount. ~~During the shutdown period our load balancer marks the caddy servers offline (as it should) so we lose ingress to the swarm services until they come back online and pass the healthcheck again.~~

Should/can a reload ignore this delay?

![image](https://user-images.githubusercontent.com/88432183/221179979-5a941af9-8d72-4648-aa2f-a8454fb5dc0d.png)


Discussion / hints:
Note - opened originally in https://github.com/lucaslorentz/caddy-docker-proxy as that's what we're using and the logs are from, above. Advised to open here instead.
Yes, the config reload and the shutdown are interrelated. What changes does your config make during the reload? If it is stopping any server/listener (i.e. the socket is not used by the new config) then it will cause the config reload to be delayed by 15s in your case.
We're seeing it during any config update done by https://github.com/lucaslorentz/caddy-docker-proxy, even when just adding a single container to the upstream IPs - wouldn't expect that to stop a server/listener, but might be down to how caddy-docker-proxy handles the reload?

I have just double-checked and it's actually showing `200 OK` (which implies `http.shutting_down=false`) from the healthcheck endpoint during the 15 seconds so looks like the issue it just limited to the time taken to load in the the new config with new upstream IPs. Disregard the bit about the load balancers - sorry!
I don't really know how CDP works, sorry; but in vanilla Caddy, a shutdown delay simply delays the grace period and config change for that duration first.

>I have just double-checked and it's actually showing 200 OK (which implies http.shutting_down=false) from the healthcheck endpoint during the 15 seconds so looks like the issue it just limited to the time taken to load in the the new config with new upstream IPs.

The shutdown delay should only be enforced if a server is actually closing: https://github.com/caddyserver/caddy/blob/be53e432fcac0a9b9accbc36885304639e8ca70b/modules/caddyhttp/app.go#L496-L516

What is in your logs before, during, and after a reload? (Enable debug logging first.)
I have reproduced on docker compose, with 3x whoami containers - running with this CDP generated caddyfile/json:
```
caddy-test-caddy-controller-1     | 2023-02-27T15:58:52.978559207Z{"level":"info","ts":1677513532.9780087,"logger":"docker-proxy","msg":"New Caddyfile","caddyfile":"{\n\tdebug\n\tauto_https disable_certs\n\tgrace_period 1m\n\tshutdown_delay 15s\n}\nhttp://my-test-app.com {\n\treverse_proxy 172.26.0.2:80 172.26.0.5:80 172.26.0.6:80\n}\n"}
caddy-test-caddy-controller-1     | 2023-02-27T15:58:52.978668884Z{"level":"info","ts":1677513532.9782238,"logger":"docker-proxy","msg":"New Config JSON","json":"{\"logging\":{\"logs\":{\"default\":{\"level\":\"DEBUG\"}}},\"apps\":{\"http\":{\"grace_period\":60000000000,\"shutdown_delay\":15000000000,\"servers\":{\"srv0\":{\"listen\":[\":80\"],\"routes\":[{\"match\":[{\"host\":[\"my-test-app.com\"]}],\"handle\":[{\"handler\":\"subroute\",\"routes\":[{\"handle\":[{\"handler\":\"reverse_proxy\",\"upstreams\":[{\"dial\":\"172.26.0.2:80\"},{\"dial\":\"172.26.0.5:80\"},{\"dial\":\"172.26.0.6:80\"}]}]}]}],\"terminal\":true}],\"automatic_https\":{\"disable_certificates\":true}}}}}}"}
```
I then `docker stop` one of them to make it reevaluate the caddyfile/json - note that the other two containers are still up and the change in the caddyfile is just the removal of 1 upstream IP from the reverse proxy section:
```
caddy-test-whoami-2 exited with code 2
caddy-test-whoami-2 exited with code 0
caddy-test-caddy-controller-1     | 2023-02-27T15:59:28.512347912Z{"level":"info","ts":1677513568.5118773,"logger":"docker-proxy","msg":"New Caddyfile","caddyfile":"{\n\tdebug\n\tauto_https disable_certs\n\tgrace_period 1m\n\tshutdown_delay 15s\n}\nhttp://my-test-app.com {\n\treverse_proxy 172.26.0.2:80 172.26.0.6:80\n}\n"}
caddy-test-caddy-controller-1     | 2023-02-27T15:59:28.512405919Z{"level":"info","ts":1677513568.5121088,"logger":"docker-proxy","msg":"New Config JSON","json":"{\"logging\":{\"logs\":{\"default\":{\"level\":\"DEBUG\"}}},\"apps\":{\"http\":{\"grace_period\":60000000000,\"shutdown_delay\":15000000000,\"servers\":{\"srv0\":{\"listen\":[\":80\"],\"routes\":[{\"match\":[{\"host\":[\"my-test-app.com\"]}],\"handle\":[{\"handler\":\"subroute\",\"routes\":[{\"handle\":[{\"handler\":\"reverse_proxy\",\"upstreams\":[{\"dial\":\"172.26.0.2:80\"},{\"dial\":\"172.26.0.6:80\"}]}]}]}],\"terminal\":true}],\"automatic_https\":{\"disable_certificates\":true}}}}}}"}
caddy-test-caddy-controller-1     | 2023-02-27T15:59:28.512470711Z{"level":"info","ts":1677513568.5121634,"logger":"docker-proxy","msg":"Sending configuration to","server":"172.26.0.4"}
caddy-test-caddy-server-1         | 2023-02-27T15:59:28.514301153Z{"level":"info","ts":1677513568.5135128,"logger":"admin.api","msg":"received request","method":"POST","host":"172.26.0.4:2019","uri":"/load","remote_ip":"172.26.0.3","remote_port":"57160","headers":{"Accept-Encoding":["gzip"],"Content-Length":["469"],"Content-Type":["application/json"],"User-Agent":["Go-http-client/1.1"]}}
caddy-test-caddy-server-1         | 2023-02-27T15:59:28.514837836Z{"level":"info","ts":1677513568.514546,"logger":"admin","msg":"admin endpoint started","address":"172.26.0.4:2019","enforce_origin":false,"origins":["//172.26.0.4:2019"]}
caddy-test-caddy-server-1         | 2023-02-27T15:59:28.515001777Z{"level":"warn","ts":1677513568.5146751,"logger":"http","msg":"server is listening only on the HTTP port, so no automatic HTTPS will be applied to this server","server_name":"srv0","http_port":80}
caddy-test-caddy-server-1         | 2023-02-27T15:59:28.515135325Z{"level":"info","ts":1677513568.5148222,"logger":"tls.cache.maintenance","msg":"started background certificate maintenance","cache":"0xc0004277a0"}
caddy-test-caddy-server-1         | 2023-02-27T15:59:28.515180148Z{"level":"debug","ts":1677513568.5148494,"logger":"http","msg":"starting server loop","address":"[::]:80","tls":false,"http3":false}
caddy-test-caddy-server-1         | 2023-02-27T15:59:28.515197528Z{"level":"info","ts":1677513568.5148587,"logger":"http.log","msg":"server running","name":"srv0","protocols":["h1","h2","h3"]}
caddy-test-caddy-server-1         | 2023-02-27T15:59:28.515222919Z{"level":"debug","ts":1677513568.5148683,"logger":"http","msg":"listener closing and shutdown delay is configured","address":":80"}
caddy-test-caddy-server-1         | 2023-02-27T15:59:28.515254733Z{"level":"debug","ts":1677513568.5148714,"logger":"http","msg":"shutdown scheduled","delay_duration":15,"time":1677513583.5148654}
caddy-test-caddy-server-1         | 2023-02-27T15:59:38.516232477Z{"level":"error","ts":1677513578.5158157,"logger":"admin","msg":"stopping current admin endpoint","error":"shutting down admin server: context deadline exceeded"}
caddy-test-caddy-server-1         | 2023-02-27T15:59:43.516006492Z{"level":"debug","ts":1677513583.5156696,"logger":"http","msg":"servers shutting down; grace period initiated","duration":60}
caddy-test-caddy-server-1         | 2023-02-27T15:59:43.516037393Z{"level":"info","ts":1677513583.515803,"logger":"tls.cache.maintenance","msg":"stopped background certificate maintenance","cache":"0xc00040b880"}
caddy-test-caddy-server-1         | 2023-02-27T15:59:43.516126124Z{"level":"info","ts":1677513583.5159376,"msg":"autosaved config (load with --resume flag)","file":"/config/caddy/autosave.json"}
caddy-test-caddy-server-1         | 2023-02-27T15:59:43.516184078Z{"level":"info","ts":1677513583.5159612,"logger":"admin.api","msg":"load complete"}
caddy-test-caddy-controller-1     | 2023-02-27T15:59:43.516500246Z{"level":"info","ts":1677513583.5161676,"logger":"docker-proxy","msg":"Successfully configured","server":"172.26.0.4"}
```
Please share the `docker-compose.yml` you used
Hi, sure - the docker-compose.yml is:
```
version: '3.8'

services:
  whoami:
    image: containous/whoami
    scale: 3
    labels:
      caddy: http://my-test-app.com
      caddy.reverse_proxy: '{{upstreams 80}}'

  caddy-server:
    image: lucaslorentz/caddy-docker-proxy
    restart: unless-stopped
    environment:
      - CADDY_DOCKER_MODE=server
      - CADDY_CONTROLLER_NETWORK=172.0.0.0/8
    ports:
      - "80:80"
      - "443:443"
      - "443:443/udp"
    volumes:
      - caddy_data:/data
    labels:
        caddy_controlled_server:

  caddy-controller:
    image: lucaslorentz/caddy-docker-proxy
    restart: unless-stopped
    environment:
      - CADDY_DOCKER_MODE=controller
      - CADDY_DOCKER_CADDYFILE_PATH=/config/caddy/caddy_base.conf
      - CADDY_CONTROLLER_NETWORK=172.0.0.0/8
      - CADDY_DOCKER_POLLING_INTERVAL=5s
    volumes:
      - /var/run/docker.sock:/var/run/docker.sock:ro
      - /home/<my username>/caddy-test/caddy_base.conf:/config/caddy/caddy_base.conf

volumes:
  caddy_data: {}
```
the caddy_base.conf is:
```
{
        debug
        auto_https disable_certs
        grace_period 1m
        shutdown_delay 15s
}
```
I guess I don't really understand what the config is that's actually being loaded/unloaded though. I'd like to see a diff between them. Caddy thinks the server listening on `:80` is shutting down. Is there any way to get a diff of the configs? That's the only way I can think of to determine whether it's a bug or not.
@mholt it's there:

Before:
```
caddy-test-caddy-controller-1     | 2023-02-27T15:58:52.978668884Z{"level":"info","ts":1677513532.9782238,"logger":"docker-proxy","msg":"New Config JSON","json":"{\"logging\":{\"logs\":{\"default\":{\"level\":\"DEBUG\"}}},\"apps\":{\"http\":{\"grace_period\":60000000000,\"shutdown_delay\":15000000000,\"servers\":{\"srv0\":{\"listen\":[\":80\"],\"routes\":[{\"match\":[{\"host\":[\"my-test-app.com\"]}],\"handle\":[{\"handler\":\"subroute\",\"routes\":[{\"handle\":[{\"handler\":\"reverse_proxy\",\"upstreams\":[{\"dial\":\"172.26.0.2:80\"},{\"dial\":\"172.26.0.5:80\"},{\"dial\":\"172.26.0.6:80\"}]}]}]}],\"terminal\":true}],\"automatic_https\":{\"disable_certificates\":true}}}}}}"}
```

After:
```
caddy-test-caddy-controller-1     | 2023-02-27T15:59:28.512405919Z{"level":"info","ts":1677513568.5121088,"logger":"docker-proxy","msg":"New Config JSON","json":"{\"logging\":{\"logs\":{\"default\":{\"level\":\"DEBUG\"}}},\"apps\":{\"http\":{\"grace_period\":60000000000,\"shutdown_delay\":15000000000,\"servers\":{\"srv0\":{\"listen\":[\":80\"],\"routes\":[{\"match\":[{\"host\":[\"my-test-app.com\"]}],\"handle\":[{\"handler\":\"subroute\",\"routes\":[{\"handle\":[{\"handler\":\"reverse_proxy\",\"upstreams\":[{\"dial\":\"172.26.0.2:80\"},{\"dial\":\"172.26.0.6:80\"}]}]}]}],\"terminal\":true}],\"automatic_https\":{\"disable_certificates\":true}}}}}}"}
```
So that would be
```diff
diff --git a/prev.json b/new.json
index 3c253b35..e11cef50 100644
--- a/prev.json
+++ b/new.json
@@ -36,9 +36,6 @@
                             {
                               "dial": "172.26.0.2:80"
                             },
-                            {
-                              "dial": "172.26.0.5:80"
-                            },
                             {
                               "dial": "172.26.0.6:80"
                             }
```

But if I remember correctly, caddy-docker-proxy does some addtional stuff like hard-coding the admin api, so I believe this json nor this diff isn't actually that helpful
Oh... thanks @francislavoie. (I didn't expect it to be embedded as a single log-line. So I only briefly scanned the logs.)

Awesome, thank you @IndeedNotJames!

Indeed, from one config to another it looks like port 80 is staying open, not being closed.

However, I'm unable to reproduce this with vanilla Caddy (no CDP). The delay seems to work correctly. It might be helpful to have more information about how CDP works.
CDP just generates a new Caddyfile config from Docker labels and running containers, adapts it to JSON, then pushes the new config to Caddy's admin endpoint via `/load`. It's not doing anything fancy. I don't see how this issue could be unique to CDP.
Hmm. Then I'm not sure why I can't repro it... can anyone else reproduce it with vanilla Caddy?
Managed to reproduce the issue with vanilla Caddy.
It's specific to unix and [`/listen_unix.go`](https://github.com/caddyserver/caddy/blob/f6bab8ba85b231ea0930282e684c0040001059e6) 

Minimal repro Caddyfile:
```
{
	debug
	shutdown_delay 5s
}

localhost:80 {
	respond 1
}
```

The either changing the `respond` string or `caddy reload --force` will engage the `shutdown_delay` -- for a config reload.

As far as I can tell, this has been the case since its initial implementation and release in https://github.com/caddyserver/caddy/releases/tag/v2.6.0

All I essentially did was noticing
https://github.com/caddyserver/caddy/blob/f6bab8ba85b231ea0930282e684c0040001059e6/usagepool.go#L199-L210
always jumped straight to `return 0, false`.
I tried understanding as to why, stumbling in the dark, being completely unaware that [`/listen_unix.go`](https://github.com/caddyserver/caddy/blob/f6bab8ba85b231ea0930282e684c0040001059e6) existed :eyes: 

@francislavoie took it from there :)

Thanks to @IndeedNotJames for finding a way to reproduce it, which spun the wheels in my head and I realized it probably had to do with the recent listener rewrite which caused unix systems to not use the listener pool at all anymore, so that's no longer a reliable way to check for a shutdown.

I have a fix in https://github.com/caddyserver/caddy/pull/5405 which just uses a simple atomic ref counter.
Thank you for investigating, appreciate it! 

Fix patch:
diff --git a/go.mod b/go.mod
index 4a5dc86443a..1b6dbb92802 100644
--- a/go.mod
+++ b/go.mod
@@ -1,6 +1,6 @@
 module github.com/caddyserver/caddy/v2
 
-go 1.18
+go 1.19
 
 require (
 	github.com/BurntSushi/toml v1.2.1
diff --git a/listen.go b/listen.go
index 1ca16874446..e0d67c6ab1e 100644
--- a/listen.go
+++ b/listen.go
@@ -12,10 +12,7 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 
-// TODO: Go 1.19 introduced the "unix" build tag. We have to support Go 1.18 until Go 1.20 is released.
-// When Go 1.19 is our minimum, change this build tag to simply "!unix".
-// (see similar change needed in listen_unix.go)
-//go:build !(aix || android || darwin || dragonfly || freebsd || hurd || illumos || ios || linux || netbsd || openbsd || solaris)
+//go:build !unix
 
 package caddy
 
diff --git a/listen_unix.go b/listen_unix.go
index 7ea67452677..50d9a66dfed 100644
--- a/listen_unix.go
+++ b/listen_unix.go
@@ -12,10 +12,10 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 
-// TODO: Go 1.19 introduced the "unix" build tag. We have to support Go 1.18 until Go 1.20 is released.
-// When Go 1.19 is our minimum, remove this build tag, since "_unix" in the filename will do this.
-// (see also change needed in listen.go)
-//go:build aix || android || darwin || dragonfly || freebsd || hurd || illumos || ios || linux || netbsd || openbsd || solaris
+// Even though the filename ends in _unix.go, we still have to specify the
+// build constraint here, because the filename convention only works for
+// literal GOOS values, and "unix" is a shortcut unique to build tags.
+//go:build unix
 
 package caddy
 
@@ -98,7 +98,19 @@ func listenTCPOrUnix(ctx context.Context, lnKey string, network, address string,
 		}
 		return reusePort(network, address, c)
 	}
-	return config.Listen(ctx, network, address)
+
+	// even though SO_REUSEPORT lets us bind the socket multiple times,
+	// we still put it in the listenerPool so we can count how many
+	// configs are using this socket; necessary to ensure we can know
+	// whether to enforce shutdown delays, for example (see #5393).
+	ln, err := config.Listen(ctx, network, address)
+	if err == nil {
+		listenerPool.LoadOrStore(lnKey, nil)
+	}
+
+	// lightly wrap the listener so that when it is closed,
+	// we can decrement the usage pool counter
+	return deleteListener{ln, lnKey}, err
 }
 
 // reusePort sets SO_REUSEPORT. Ineffective for unix sockets.
@@ -116,3 +128,17 @@ func reusePort(network, address string, conn syscall.RawConn) error {
 		}
 	})
 }
+
+// deleteListener is a type that simply deletes itself
+// from the listenerPool when it closes. It is used
+// solely for the purpose of reference counting (i.e.
+// counting how many configs are using a given socket).
+type deleteListener struct {
+	net.Listener
+	lnKey string
+}
+
+func (dl deleteListener) Close() error {
+	_, _ = listenerPool.Delete(dl.lnKey)
+	return dl.Listener.Close()
+}
diff --git a/modules/caddyhttp/app.go b/modules/caddyhttp/app.go
index 36a4011b30c..670185a135c 100644
--- a/modules/caddyhttp/app.go
+++ b/modules/caddyhttp/app.go
@@ -517,7 +517,7 @@ func (app *App) Stop() error {
 
 	// honor scheduled/delayed shutdown time
 	if delay {
-		app.logger.Debug("shutdown scheduled",
+		app.logger.Info("shutdown scheduled",
 			zap.Duration("delay_duration", time.Duration(app.ShutdownDelay)),
 			zap.Time("time", scheduledTime))
 		time.Sleep(time.Duration(app.ShutdownDelay))
@@ -528,9 +528,9 @@ func (app *App) Stop() error {
 		var cancel context.CancelFunc
 		ctx, cancel = context.WithTimeout(ctx, time.Duration(app.GracePeriod))
 		defer cancel()
-		app.logger.Debug("servers shutting down; grace period initiated", zap.Duration("duration", time.Duration(app.GracePeriod)))
+		app.logger.Info("servers shutting down; grace period initiated", zap.Duration("duration", time.Duration(app.GracePeriod)))
 	} else {
-		app.logger.Debug("servers shutting down with eternal grace period")
+		app.logger.Info("servers shutting down with eternal grace period")
 	}
 
 	// goroutines aren't guaranteed to be scheduled right away,


Test patch: