Repository: moby/moby (language: go)

Issue:
dockerd doesn't kill healthcheck processes after timeout
**Description**

dockerd already has logic to gracefully stop healthcheck processes after timeout ([/daemon/exec.go#L277-L291](https://github.com/moby/moby/blob/v20.10.17/daemon/exec.go#L277-L291)).

But it seems completely broken because of using canceled context in `daemon.containerd.SignalProcess()` call ([/daemon/exec.go#L279](https://github.com/moby/moby/blob/v20.10.17/daemon/exec.go#L279)). `SignalProcess()` just returns `context canceled` error and does nothing.

**Steps to reproduce the issue:**

1. Create `Dockerfile`:
    ```
    FROM ubuntu:22.04

    HEALTHCHECK --interval=5s --timeout=5s \
       CMD ["sleep", "3600"]

    CMD ["sleep", "infinity"]
    ```
2. Build image:
    ```
    docker build --tag=healthcheck-test .
    ```
3. Start container:
    ```
    docker run -d --rm --name=healthcheck-test healthcheck-test
    ```
4. Wait some health intervals:
    ```
    sleep 30
    ```
5. Check processes in the container:
    ```
    docker exec healthcheck-test ps axuf
    ```

* Cleanup:
    ```
    docker rm --force healthcheck-test # remove container
    docker rmi healthcheck-test # remove image
    ```

**Describe the results you received:**

More then one `sleep 3600` processes:

```
$ docker build --tag=healthcheck-test .
Sending build context to Docker daemon  2.048kB
Step 1/3 : FROM ubuntu:22.04
 ---> 27941809078c
Step 2/3 : HEALTHCHECK --interval=5s --timeout=5s    CMD ["sleep", "3600"]
 ---> Running in 248a9dcfaa6f
Removing intermediate container 248a9dcfaa6f
 ---> 16d09d0a1b09
Step 3/3 : CMD ["sleep", "infinity"]
 ---> Running in 55ef832b3170
Removing intermediate container 55ef832b3170
 ---> 7e8b71425a0a
Successfully built 7e8b71425a0a
Successfully tagged healthcheck-test:latest
$ docker run -d --rm --name=healthcheck-test healthcheck-test
41e8e2eb21d0bdd485e647c6ec1273474b19ba616d284d48d53ea607edd96841
$ sleep 30
$ docker exec healthcheck-test ps axuf
USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root          25  0.0  0.0   7060  1664 ?        Rs   12:01   0:00 ps axuf
root          19  0.2  0.0   2788  1036 ?        Ss   12:01   0:00 sleep 3600
root          13  0.0  0.0   2788  1036 ?        Ss   12:00   0:00 sleep 3600
root           7  0.0  0.0   2788  1056 ?        Ss   12:00   0:00 sleep 3600
root           1  0.0  0.0   2788  1108 ?        Ss   12:00   0:00 sleep infinity
```

**Describe the results you expected:**

Zero or one `sleep 3600` process:

```
$ docker exec healthcheck-test ps axuf
USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root          25  0.0  0.0   7060  1664 ?        Rs   12:01   0:00 ps axuf
root          19  0.2  0.0   2788  1036 ?        Ss   12:01   0:00 sleep 3600
root           1  0.0  0.0   2788  1108 ?        Ss   12:00   0:00 sleep infinity
```

**Additional information you deem important (e.g. issue happens only occasionally):**

N/A

**Output of `docker version`:**

```
Client: Docker Engine - Community
 Version:           20.10.17
 API version:       1.41
 Go version:        go1.17.11
 Git commit:        100c701
 Built:             Mon Jun  6 23:02:57 2022
 OS/Arch:           linux/amd64
 Context:           default
 Experimental:      true

Server: Docker Engine - Community
 Engine:
  Version:          20.10.17
  API version:      1.41 (minimum version 1.12)
  Go version:       go1.17.11
  Git commit:       a89b842
  Built:            Mon Jun  6 23:01:03 2022
  OS/Arch:          linux/amd64
  Experimental:     false
 containerd:
  Version:          1.6.6
  GitCommit:        10c12954828e7c7c9b6e0ea9b0c02b01407d3ae1
 runc:
  Version:          1.1.2
  GitCommit:        v1.1.2-0-ga916309
 docker-init:
  Version:          0.19.0
  GitCommit:        de40ad0
```

**Output of `docker info`:**

```
Client:
 Context:    default
 Debug Mode: false
 Plugins:
  app: Docker App (Docker Inc., v0.9.1-beta3)
  buildx: Docker Buildx (Docker Inc., v0.8.2-docker)
  scan: Docker Scan (Docker Inc., v0.17.0)

Server:
 Containers: 10
  Running: 1
  Paused: 0
  Stopped: 9
 Images: 119
 Server Version: 20.10.17
 Storage Driver: overlay2
  Backing Filesystem: extfs
  Supports d_type: true
  Native Overlay Diff: true
  userxattr: false
 Logging Driver: json-file
 Cgroup Driver: cgroupfs
 Cgroup Version: 1
 Plugins:
  Volume: local
  Network: bridge host ipvlan macvlan null overlay
  Log: awslogs fluentd gcplogs gelf journald json-file local logentries splunk syslog
 Swarm: inactive
 Runtimes: io.containerd.runc.v2 io.containerd.runtime.v1.linux runc
 Default Runtime: runc
 Init Binary: docker-init
 containerd version: 10c12954828e7c7c9b6e0ea9b0c02b01407d3ae1
 runc version: v1.1.2-0-ga916309
 init version: de40ad0
 Security Options:
  apparmor
  seccomp
   Profile: default
 Kernel Version: 5.13.0-51-generic
 Operating System: Ubuntu 20.04.4 LTS
 OSType: linux
 Architecture: x86_64
 CPUs: 8
 Total Memory: 15.34GiB
 Name: uk-ubnt-61
 ID: BXVR:65LG:FDYH:IX7Q:U2LT:LQI6:P5B5:ZFEG:EIMS:WPWM:D3ND:RN4H
 Docker Root Dir: /var/lib/docker
 Debug Mode: true
  File Descriptors: 90
  Goroutines: 74
  System Time: 2022-06-22T15:03:06.064800737+03:00
  EventsListeners: 0
 Username: 2gis
 Registry: https://index.docker.io/v1/
 Labels:
 Experimental: false
 Insecure Registries:
  docker-hub.2gis.ru:5444
  127.0.0.0/8
 Registry Mirrors:
  https://docker-registry-proxy.2gis.io/
 Live Restore Enabled: false

```

**Additional environment details (AWS, VirtualBox, physical, etc.):**

N/A


Discussion / hints:
Thanks for reporting this issue with detailed diagnostic, I'll investigate today
Hello, @ndeloof! Many thanks for your help! I tried the patch (but I cherry-picked it on v20.10.17 actually) and it works well for `TERM`. But it looks like `KILL` part still broken (sorry I didn't test earlier :disappointed:).

I think `// TERM signal worked` part called immediately because `attachErr` is not empty (because of "context canceled" :smiling_face_with_tear:). But I'm not sure.

---

**Steps to reproduce**:

I didn't find simple test app that ignores `TERM`, so:

1. Create `no-sigterm.c` with content:
    ```
    #include <signal.h>
    #include <unistd.h>

    int main(void) {
        signal(SIGTERM, SIG_IGN);

        sleep(3600); // 1 hour

        return 0;
    }
    ```
2. Build it:
    ```
    gcc -o no-sigterm no-sigterm.c
    ```
3. Create `Dockerfile` (I increased interval to cover all timeouts, so only one healtcheck process should be alive at the same time):
    ```
    FROM ubuntu:22.04

    COPY /no-sigterm /usr/local/bin/

    HEALTHCHECK --interval=30s --timeout=5s \
       CMD ["no-sigterm"]

    CMD ["sleep", "infinity"]
    ```
4. Build container and run it:
    ```
    docker build --tag=healthcheck-test .
    docker run -d --rm --name=healthcheck-test healthcheck-test
    ```
5. Wait some health intervals:
    ```
    sleep 120
    ```
6. Check processes in the container:
    ```
    docker exec healthcheck-test ps axuf
    ```

**Describe the results you received:**

```
USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root          31  0.0  0.0   7060  1440 ?        Rs   14:22   0:00 ps axuf
root          25  0.0  0.0   2640   852 ?        Ss   14:21   0:00 no-sigterm
root          13  0.0  0.0   2640   844 ?        Ss   14:21   0:00 no-sigterm
root           7  0.0  0.0   2640   856 ?        Ss   14:20   0:00 no-sigterm
root           1  0.0  0.0   2788   972 ?        Ss   14:20   0:00 sleep infinity
```

**Describe the results you expected:**

```
USER         PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND
root          31  0.0  0.0   7060  1440 ?        Rs   14:22   0:00 ps axuf
root          25  0.0  0.0   2640   852 ?        Ss   14:21   0:00 no-sigterm
root           1  0.0  0.0   2788   972 ?        Ss   14:20   0:00 sleep infinity
```


Fix patch:
diff --git a/daemon/exec.go b/daemon/exec.go
index 08687760a720b..4675ee4557129 100644
--- a/daemon/exec.go
+++ b/daemon/exec.go
@@ -23,9 +23,6 @@ import (
 	"github.com/sirupsen/logrus"
 )
 
-// Seconds to wait after sending TERM before trying KILL
-const termProcessTimeout = 10 * time.Second
-
 func (daemon *Daemon) registerExecCommand(container *container.Container, config *exec.Config) {
 	// Storing execs in container in order to kill them gracefully whenever the container is stopped or removed.
 	container.ExecCommands.Add(config.ID, config)
@@ -272,7 +269,10 @@ func (daemon *Daemon) ContainerExecStart(ctx context.Context, name string, optio
 		CloseStdin: true,
 	}
 	ec.StreamConfig.AttachStreams(&attachConfig)
-	attachErr := ec.StreamConfig.CopyStreams(ctx, &attachConfig)
+	// using context.Background() so that attachErr does not race ctx.Done().
+	copyCtx, cancel := context.WithCancel(context.Background())
+	defer cancel()
+	attachErr := ec.StreamConfig.CopyStreams(copyCtx, &attachConfig)
 
 	// Synchronize with libcontainerd event loop
 	ec.Lock()
@@ -292,18 +292,15 @@ func (daemon *Daemon) ContainerExecStart(ctx context.Context, name string, optio
 
 	select {
 	case <-ctx.Done():
-		logrus.Debugf("Sending TERM signal to process %v in container %v", name, c.ID)
-		daemon.containerd.SignalProcess(ctx, c.ID, name, signal.SignalMap["TERM"])
-
-		timeout := time.NewTimer(termProcessTimeout)
-		defer timeout.Stop()
-
-		select {
-		case <-timeout.C:
-			logrus.Infof("Container %v, process %v failed to exit within %v of signal TERM - using the force", c.ID, name, termProcessTimeout)
-			daemon.containerd.SignalProcess(ctx, c.ID, name, signal.SignalMap["KILL"])
-		case <-attachErr:
-			// TERM signal worked
+		log := logrus.
+			WithField("container", c.ID).
+			WithField("exec", name)
+		log.Debug("Sending KILL signal to container process")
+		sigCtx, cancelFunc := context.WithTimeout(context.Background(), 30*time.Second)
+		defer cancelFunc()
+		err := daemon.containerd.SignalProcess(sigCtx, c.ID, name, signal.SignalMap["KILL"])
+		if err != nil {
+			log.WithError(err).Error("Could not send KILL signal to container process")
 		}
 		return ctx.Err()
 	case err := <-attachErr:
diff --git a/daemon/health.go b/daemon/health.go
index 335f91e0ecb58..5f5779526bb6b 100644
--- a/daemon/health.go
+++ b/daemon/health.go
@@ -133,8 +133,8 @@ func (p *cmdProbe) run(ctx context.Context, d *Daemon, cntr *container.Container
 	case <-tm.C:
 		cancelProbe()
 		logrus.WithContext(ctx).Debugf("Health check for container %s taking too long", cntr.ID)
-		// Wait for probe to exit (it might take a while to respond to the TERM
-		// signal and we don't want dying probes to pile up).
+		// Wait for probe to exit (it might take some time to call containerd to kill
+		// the process and we don't want dying probes to pile up).
 		<-execErr
 		return &types.HealthcheckResult{
 			ExitCode: -1,


Test patch:
diff --git a/integration/container/health_test.go b/integration/container/health_test.go
index ad0245c6a80d4..c55e9e9180049 100644
--- a/integration/container/health_test.go
+++ b/integration/container/health_test.go
@@ -2,6 +2,7 @@ package container // import "github.com/docker/docker/integration/container"
 
 import (
 	"context"
+	"fmt"
 	"testing"
 	"time"
 
@@ -93,6 +94,42 @@ while true; do sleep 1; done
 	poll.WaitOn(t, pollForHealthStatus(ctxPoll, client, id, "healthy"), poll.WithDelay(100*time.Millisecond))
 }
 
+// TestHealthCheckProcessKilled verifies that health-checks exec get killed on time-out.
+func TestHealthCheckProcessKilled(t *testing.T) {
+	skip.If(t, testEnv.RuntimeIsWindowsContainerd(), "FIXME: Broken on Windows + containerd combination")
+	defer setupTest(t)()
+	ctx := context.Background()
+	apiClient := testEnv.APIClient()
+
+	cID := container.Run(ctx, t, apiClient, func(c *container.TestContainerConfig) {
+		c.Config.Healthcheck = &containertypes.HealthConfig{
+			Test:     []string{"CMD", "sh", "-c", "sleep 60"},
+			Interval: 100 * time.Millisecond,
+			Timeout:  50 * time.Millisecond,
+			Retries:  1,
+		}
+	})
+	poll.WaitOn(t, pollForHealthCheckLog(ctx, apiClient, cID, "Health check exceeded timeout (50ms)"))
+}
+
+func pollForHealthCheckLog(ctx context.Context, client client.APIClient, containerID string, expected string) func(log poll.LogT) poll.Result {
+	return func(log poll.LogT) poll.Result {
+		inspect, err := client.ContainerInspect(ctx, containerID)
+		if err != nil {
+			return poll.Error(err)
+		}
+		healthChecksTotal := len(inspect.State.Health.Log)
+		if healthChecksTotal > 0 {
+			output := inspect.State.Health.Log[healthChecksTotal-1].Output
+			if output == expected {
+				return poll.Success()
+			}
+			return poll.Error(fmt.Errorf("expected %q, got %q", expected, output))
+		}
+		return poll.Continue("waiting for container healthcheck logs")
+	}
+}
+
 func pollForHealthStatus(ctx context.Context, client client.APIClient, containerID string, healthStatus string) func(log poll.LogT) poll.Result {
 	return func(log poll.LogT) poll.Result {
 		inspect, err := client.ContainerInspect(ctx, containerID)