In some rare occasions s6-overlay hangs at shutdown for undefined amount of time

[felipecrs]

From users perspective, this issue is very similar #557, the difference being that this happens very rarely now.

I use s6-overlay in my jenkins-agent image, to bring up a docker daemon inside the container as a sidecar service.

I had never observed such a problem when I was using v2 (which I recently upgraded felipecrs/docker-images#78), but after upgrading to v3, I started catching this problem.

My environment runs thousands of containers like this every day, and at the end of a working day I noticed 4 in "Termination" state (k8s) for a very long time (more than 50 minutes) with the container still running, and checking its logs, I can see:

medium-karrer001-lz2pq jnlp Nov 24, 2023 7:44:56 PM org.csanchez.jenkins.plugins.kubernetes.KubernetesSlave$SlaveDisconnector call
medium-karrer001-lz2pq jnlp INFO: Disabled agent engine reconnects.
medium-karrer001-lz2pq jnlp Nov 24, 2023 7:44:56 PM hudson.remoting.Launcher$CuiListener status
medium-karrer001-lz2pq jnlp INFO: Write side closed
medium-karrer001-lz2pq jnlp s6-rc: info: service legacy-services: stopping
medium-karrer001-lz2pq jnlp Received signal 15; terminating.
medium-karrer001-lz2pq jnlp time="2023-11-24T19:44:56.583376624Z" level=info msg="Processing signal 'terminated'"
medium-karrer001-lz2pq jnlp Nov 24, 2023 7:44:56 PM hudson.remoting.Launcher$CuiListener status
medium-karrer001-lz2pq jnlp INFO: Read side closed
medium-karrer001-lz2pq jnlp Nov 24, 2023 7:44:56 PM hudson.remoting.Launcher$CuiListener status
medium-karrer001-lz2pq jnlp INFO: Terminated
medium-karrer001-lz2pq jnlp Nov 24, 2023 7:44:56 PM hudson.remoting.Launcher$CuiListener status
medium-karrer001-lz2pq jnlp INFO: Read side closed
medium-karrer001-lz2pq jnlp time="2023-11-24T19:44:58.616127477Z" level=error msg="stream copy error: read /proc/self/fd/38: file already closed"
medium-karrer001-lz2pq jnlp time="2023-11-24T19:44:58.616138528Z" level=error msg="stream copy error: read /proc/self/fd/39: file already closed"
medium-karrer001-lz2pq jnlp time="2023-11-24T19:45:00.620677740Z" level=warning msg="error copying stdout" runtime=io.containerd.runc.v2
medium-karrer001-lz2pq jnlp time="2023-11-24T19:45:00.620870318Z" level=warning msg="error copying stderr" runtime=io.containerd.runc.v2
medium-karrer001-lz2pq jnlp time="2023-11-24T19:45:06.599597216Z" level=info msg="Container failed to exit within 10s of signal 15 - using the force" container=88f8afd0a0f49698fc87cbd40f6d2707829b8fdf0c97a2f1ad952f82e6e02a96
medium-karrer001-lz2pq jnlp time="2023-11-24T19:45:11.584523240Z" level=error msg="Force shutdown daemon"
medium-karrer001-lz2pq jnlp time="2023-11-24T19:45:11.584624658Z" level=info msg="Daemon shutdown complete"
medium-karrer001-lz2pq jnlp time="2023-11-24T19:45:11.584772233Z" level=info msg="stopping event stream following graceful shutdown" error="context canceled" module=libcontainerd namespace=plugins.moby
medium-karrer001-lz2pq jnlp time="2023-11-24T19:45:11.584804684Z" level=info msg="stopping healthcheck following graceful shutdown" module=libcontainerd
medium-karrer001-lz2pq jnlp time="2023-11-24T19:45:11.584819011Z" level=info msg="stopping event stream following graceful shutdown" error="context canceled" module=libcontainerd namespace=moby
medium-karrer001-lz2pq jnlp s6-svwait: fatal: timed out
medium-karrer001-lz2pq jnlp s6-rc: info: service legacy-services successfully stopped
medium-karrer001-lz2pq jnlp s6-rc: info: service legacy-cont-init: stopping
medium-karrer001-lz2pq jnlp s6-rc: info: service legacy-cont-init successfully stopped
medium-karrer001-lz2pq jnlp s6-rc: info: service fix-attrs: stopping
medium-karrer001-lz2pq jnlp s6-rc: info: service fix-attrs successfully stopped
medium-karrer001-lz2pq jnlp s6-rc: info: service s6rc-oneshot-runner: stopping
medium-karrer001-lz2pq jnlp s6-rc: info: service s6rc-oneshot-runner successfully stopped
medium-karrer001-lz2pq jnlp time="2023-11-24T19:45:11.615070940Z" level=info msg="Processing signal 'terminated'"

As you can see, looks like the docker daemon within the container did not exit in time (s6-svwait: fatal: timed out), and then I am not sure what else happened, but s6-overlay was supposed to wait for 15s and then force kill everything.

Again, note that this only happens rarely. I cannot reproduce the issue reliably, tried a lot, and I could not build an example repository too that can reproduce the problem.

These are my S6 envs:

ENV S6_BEHAVIOUR_IF_STAGE2_FAILS=2 \
    # Wait for services before running CMD \
    S6_CMD_WAIT_FOR_SERVICES=1 \
    # Give 15s for services to start \
    S6_CMD_WAIT_FOR_SERVICES_MAXTIME=15000 \
    # Give 15s for services to stop \
    S6_SERVICES_GRACETIME=15000 \
    # Honor container env on CMD \
    S6_KEEP_ENV=1

My only hope is that maybe some part of the code that was changed to fix #557 is not fully bullet proof and can be optimized to ensure this does not happen.

If it is not the case, and you think nothing can be done unless we can reproduce the issue reliably, feel free to close this issue.

For now, my only option is to downgrade back to v2, unfortunately.

[felipecrs]

PS: It may also be related to how stressed the machine is at the moment of shutdown.

[felipecrs]

I just caught a situation where docker daemon actually gracefully finishes within the SERVICES_GRACETIME, but container still hangs at shutdown so I believe the issue is not related to that.

small-karrer001-cx0qq jnlp INFO: Terminated
small-karrer001-cx0qq jnlp Nov 24, 2023 8:29:15 PM hudson.remoting.Launcher$CuiListener status
small-karrer001-cx0qq jnlp INFO: Performing onReconnect operation.
small-karrer001-cx0qq jnlp s6-rc: info: service legacy-services: stopping
small-karrer001-cx0qq jnlp Received signal 15; terminating.
small-karrer001-cx0qq jnlp time="2023-11-24T20:51:21.072402755Z" level=info msg="Processing signal 'terminated'"
small-karrer001-cx0qq jnlp time="2023-11-24T20:51:21.075793836Z" level=info msg="stopping event stream following graceful shutdown" error="<nil>" module=libcontainerd namespace=moby
small-karrer001-cx0qq jnlp time="2023-11-24T20:51:21.076441096Z" level=info msg="Daemon shutdown complete"
small-karrer001-cx0qq jnlp time="2023-11-24T20:51:21.076613767Z" level=info msg="stopping event stream following graceful shutdown" error="context canceled" module=libcontainerd namespace=plugins.moby
small-karrer001-cx0qq jnlp time="2023-11-24T20:51:21.076613006Z" level=info msg="stopping healthcheck following graceful shutdown" module=libcontainerd
small-karrer001-cx0qq jnlp s6-rc: info: service legacy-services successfully stopped
small-karrer001-cx0qq jnlp s6-rc: info: service legacy-cont-init: stopping
small-karrer001-cx0qq jnlp s6-rc: info: service legacy-cont-init successfully stopped
small-karrer001-cx0qq jnlp s6-rc: info: service fix-attrs: stopping
small-karrer001-cx0qq jnlp s6-rc: info: service fix-attrs successfully stopped
small-karrer001-cx0qq jnlp s6-rc: info: service s6rc-oneshot-runner: stopping
small-karrer001-cx0qq jnlp s6-rc: info: service s6rc-oneshot-runner successfully stopped

[skarnet]

This is disturbing, this suggests a race condition somewhere, that is rarely hit.

Indeed, if the problem is similar to the one in #557, this is entirely independent from graceful termination succeeding or not.

Did you observe that issue in s6-overlay v3.1.6.0 as well? or did it only start in v3.1.6.1 (where it was 100%) and continue in v3.1.6.2 (<0.4% of the time)?

[felipecrs]

Hey, @skarnet, thanks a lot for your response. I observed some cluster issues in my environment related to the volumes not being properly unmounted at pod finalization. Work is being done to fix that, and I am believing that it could be the cause of the problem and that nothing would be wrong with s6-overlay itself.

When that cluster issue gets resolved at my side, I will re-attempt to upgrade to v3, and monitor.

For now I will close this issue as there's nothing to be done from your side, and I will reopen if I face similar problems after upgrading again.

Again, thanks. Have a great weekend.