Healthcheck logging seems to not work sometimes

[apostasie]

Description

Healthcheck seemingly fails to capture the output of commands it runs (one time out of two or three on slow environments - one time in 30 or 40 on my local lima).

Since this is a new feature, suggesting we hold on v2.1.3 a little bit until we fix this. (<- tag @AkihiroSuda)

Steps to reproduce the issue

Here is an example of a log entry with nothing in it (while there should be).

        +============================================================================================================+
        | 🏗       | "TestContainerHealthCheckAdvance/Health_check_uses_container_environment_variables": setup       |
        +============================================================================================================+
        
    container_health_check_test.go:331: 
        
        +------------------------------------------------------------------------------------------------------------+
        | ➡️      | ⚙️ /usr/local/bin/nerdctl run -d --name testcontainerhealthcheckadvance-health-check-uses-contai |
        |         | ner-environ-285e8021 --env MYVAR=test-value --health-cmd echo $MYVAR --health-interval 1s --heal |
        |         | th-timeout 1s ghcr.io/stargz-containers/alpine:3.13-org sleep 3600                               |
        +------------------------------------------------------------------------------------------------------------+
        |         | 🟢 f6c5e3bbcb7a9b31abffed58dcc67366b58865cefe2b1b546f44b012572fc2e7                              |
        +------------------------------------------------------------------------------------------------------------+
        | 🌱      | HOME=/root                                                                                       |
        |         | PATH=/usr/local/go/bin:/usr/local/go/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin |
        |         | :/bin                                                                                            |
        |         | DOCKER_CONFIG=/tmp/TestContainerHealthCheckAdvanceHealth_check_uses_container_environment_variab |
        |         | les1890087731/003                                                                                |
        |         | NERDCTL_TOML=/tmp/TestContainerHealthCheckAdvanceHealth_check_uses_container_environment_variabl |
        |         | es1890087731/003/nerdctl.toml                                                                    |
        +------------------------------------------------------------------------------------------------------------+
        | ⏰      | <1s (limit: 3m0s)                                                                                |
        +------------------------------------------------------------------------------------------------------------+
        | 📁      | /tmp/TestContainerHealthCheckAdvanceHealth_check_uses_container_environment_variables1890087731/ |
        |         | 002                                                                                              |
        +------------------------------------------------------------------------------------------------------------+
        
    container_health_check_test.go:337: 
        
        +------------------------------------------------------------------------------------------------------------+
        | ➡️      | ⚙️ /usr/local/bin/nerdctl container inspect testcontainerhealthcheckadvance-health-check-uses-co |
        |         | ntainer-environ-285e8021                                                                         |
        +------------------------------------------------------------------------------------------------------------+
        |         | Actual content is 173 lines long and has been abbreviated to 50
         |
        |         |                                                                                                  |
        |         | 🟢 [                                                                                             |
        |         |     {                                                                                            |
        |         |         "Id": "f6c5e3bbcb7a9b31abffed58dcc67366b58865cefe2b1b546f44b012572fc2e7",                |
        |         |         "Created": "2025-06-26T03:43:36.566037659Z",                                             |
        |         |         "Path": "sleep",                                                                         |
        |         |         "Args": [                                                                                |
        |         |             "3600"                                                                               |
        |         |         ],                                                                                       |
        |         |         "State": {                                                                               |
        |         |             "Status": "running",                                                                 |
        |         |             "Running": true,                                                                     |
        |         |             "Paused": false,                                                                     |
        |         | ... 123 lines are being ignored...                                                               |
        |         | 000000000,\"Timeout\":1000000000}",                                                              |
        |         |                 "nerdctl/host-config": "{\"BlkioWeight\":0,\"CidFile\":\"\",\"Devices\":null}",  |
        |         |                 "nerdctl/hostname": "f6c5e3bbcb7a",                                              |
        |         |                 "nerdctl/ipc": "{\"mode\":\"private\"}",                                         |
        |         |                 "nerdctl/log-config": "{\"driver\":\"json-file\",\"address\":\"/run/containerd/c |
        |         | ontainerd.sock\"}",                                                                              |
        |         |                 "nerdctl/log-uri": "binary:///usr/local/bin/nerdctl?_NERDCTL_INTERNAL_LOGGING=%2 |
        |         | Fvar%2Flib%2Fnerdctl%2F1935db59",                                                                |
        |         |                 "nerdctl/name": "testcontainerhealthcheckadvance-health-check-uses-container-env |
        |         | iron-285e8021",                                                                                  |
        |         |                 "nerdctl/namespace": "nerdctl-test",                                             |
        |         |                 "nerdctl/networks": "[\"bridge\"]",                                              |
        |         |                 "nerdctl/platform": "linux/amd64",                                               |
        |         |                 "nerdctl/state-dir": "/var/lib/nerdctl/1935db59/containers/nerdctl-test/f6c5e3bb |
        |         | cb7a9b31abffed58dcc67366b58865cefe2b1b546f44b012572fc2e7"                                        |
        |         |             }                                                                                    |
        |         |         },                                                                                       |
        |         |         "NetworkSettings": {                                                                     |
        |         |             "Ports": {},                                                                         |
        |         |             "GlobalIPv6Address": "",                                                             |
        |         |             "GlobalIPv6PrefixLen": 0,                                                            |
        |         |             "IPAddress": "10.4.0.92",                                                            |
        |         |             "IPPrefixLen": 24,                                                                   |
        |         |             "MacAddress": "d2:27:31:7b:40:73",                                                   |
        |         |             "Networks": {                                                                        |
        |         |                 "unknown-eth0": {                                                                |
        |         |                     "IPAddress": "10.4.0.92",                                                    |
        |         |                     "IPPrefixLen": 24,                                                           |
        |         |                     "GlobalIPv6Address": "",                                                     |
        |         |                     "GlobalIPv6PrefixLen": 0,                                                    |
        |         |                     "MacAddress": "d2:27:31:7b:40:73"                                            |
        |         |                 }                                                                                |
        |         |             }                                                                                    |
        |         |         }                                                                                        |
        |         |     }                                                                                            |
        |         | ]                                                                                                |
        |         |                                                                                                  |
        +------------------------------------------------------------------------------------------------------------+
        | 🌱      | HOME=/root                                                                                       |
        |         | PATH=/usr/local/go/bin:/usr/local/go/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin |
        |         | :/bin                                                                                            |
        |         | DOCKER_CONFIG=/tmp/TestContainerHealthCheckAdvanceHealth_check_uses_container_environment_variab |
        |         | les1890087731/003                                                                                |
        |         | NERDCTL_TOML=/tmp/TestContainerHealthCheckAdvanceHealth_check_uses_container_environment_variabl |
        |         | es1890087731/003/nerdctl.toml                                                                    |
        +------------------------------------------------------------------------------------------------------------+
        | ⏰      | <1s (limit: 3m0s)                                                                                |
        +------------------------------------------------------------------------------------------------------------+
        | 📁      | /tmp/TestContainerHealthCheckAdvanceHealth_check_uses_container_environment_variables1890087731/ |
        |         | 002                                                                                              |
        +------------------------------------------------------------------------------------------------------------+

        
    container_health_check_test.go:603: 
        
        +============================================================================================================+
        | 🚀      | "TestContainerHealthCheckAdvance/Health_check_uses_container_environment_variables": starting te |
        |         | st!                                                                                              |
        +============================================================================================================+
        | ⏳      | /tmp/TestContainerHealthCheckAdvanceHealth_check_uses_container_environment_variables1890087731/ |
        |         | 001/c59fef3d                                                                                     |
        +============================================================================================================+
        |         |                                                                                                  |
        +============================================================================================================+
        | config  | {                                                                                                |
        |         |   "Namespace": "nerdctl-test",                                                                   |
        |         |   "PrivateMode": ""                                                                              |
        |         | }                                                                                                |
        +============================================================================================================+
        | labels  | {}                                                                                               |
        +============================================================================================================+
        
    container_health_check_test.go:603: 
        
        +------------------------------------------------------------------------------------------------------------+
        | ➡️      | ⚙️ /usr/local/bin/nerdctl container healthcheck testcontainerhealthcheckadvance-health-check-use |
        |         | s-container-environ-285e8021                                                                     |
        +------------------------------------------------------------------------------------------------------------+
        | 🌱      | HOME=/root                                                                                       |
        |         | PATH=/usr/local/go/bin:/usr/local/go/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin |
        |         | :/bin                                                                                            |
        |         | NERDCTL_TOML=/tmp/TestContainerHealthCheckAdvanceHealth_check_uses_container_environment_variabl |
        |         | es1890087731/003/nerdctl.toml                                                                    |
        |         | DOCKER_CONFIG=/tmp/TestContainerHealthCheckAdvanceHealth_check_uses_container_environment_variab |
        |         | les1890087731/003                                                                                |
        +------------------------------------------------------------------------------------------------------------+
        | ⏰      | <1s (limit: 3m0s)                                                                                |
        +------------------------------------------------------------------------------------------------------------+
        | 📁      | /tmp/TestContainerHealthCheckAdvanceHealth_check_uses_container_environment_variables1890087731/ |
        |         | 002                                                                                              |
        +------------------------------------------------------------------------------------------------------------+
        
    container_health_check_test.go:349: 
        
        +------------------------------------------------------------------------------------------------------------+
        | ➡️      | ⚙️ /usr/local/bin/nerdctl container inspect testcontainerhealthcheckadvance-health-check-uses-co |
        |         | ntainer-environ-285e8021                                                                         |
        +------------------------------------------------------------------------------------------------------------+
        |         | Actual content is 186 lines long and has been abbreviated to 50
         |
        |         |                                                                                                  |
        |         | 🟢 [                                                                                             |
        |         |     {                                                                                            |
        |         |         "Id": "f6c5e3bbcb7a9b31abffed58dcc67366b58865cefe2b1b546f44b012572fc2e7",                |
        |         |         "Created": "2025-06-26T03:43:36.566037659Z",                                             |
        |         |         "Path": "sleep",                                                                         |
        |         |         "Args": [                                                                                |
        |         |             "3600"                                                                               |
        |         |         ],                                                                                       |
        |         |         "State": {                                                                               |
        |         |             "Status": "running",                                                                 |
        |         |             "Running": true,                                                                     |
        |         |             "Paused": false,                                                                     |
        |         | ... 136 lines are being ignored...                                                               |
        |         |                 "nerdctl/healthstate": "{\"Status\":\"healthy\",\"FailingStreak\":0}",           |
        |         |                 "nerdctl/host-config": "{\"BlkioWeight\":0,\"CidFile\":\"\",\"Devices\":null}",  |
        |         |                 "nerdctl/hostname": "f6c5e3bbcb7a",                                              |
        |         |                 "nerdctl/ipc": "{\"mode\":\"private\"}",                                         |
        |         |                 "nerdctl/log-config": "{\"driver\":\"json-file\",\"address\":\"/run/containerd/c |
        |         | ontainerd.sock\"}",                                                                              |
        |         |                 "nerdctl/log-uri": "binary:///usr/local/bin/nerdctl?_NERDCTL_INTERNAL_LOGGING=%2 |
        |         | Fvar%2Flib%2Fnerdctl%2F1935db59",                                                                |
        |         |                 "nerdctl/name": "testcontainerhealthcheckadvance-health-check-uses-container-env |
        |         | iron-285e8021",                                                                                  |
        |         |                 "nerdctl/namespace": "nerdctl-test",                                             |
        |         |                 "nerdctl/networks": "[\"bridge\"]",                                              |
        |         |                 "nerdctl/platform": "linux/amd64",                                               |
        |         |                 "nerdctl/state-dir": "/var/lib/nerdctl/1935db59/containers/nerdctl-test/f6c5e3bb |
        |         | cb7a9b31abffed58dcc67366b58865cefe2b1b546f44b012572fc2e7"                                        |
        |         |             }                                                                                    |
        |         |         },                                                                                       |
        |         |         "NetworkSettings": {                                                                     |
        |         |             "Ports": {},                                                                         |
        |         |             "GlobalIPv6Address": "",                                                             |
        |         |             "GlobalIPv6PrefixLen": 0,                                                            |
        |         |             "IPAddress": "10.4.0.92",                                                            |
        |         |             "IPPrefixLen": 24,                                                                   |
        |         |             "MacAddress": "d2:27:31:7b:40:73",                                                   |
        |         |             "Networks": {                                                                        |
        |         |                 "unknown-eth0": {                                                                |
        |         |                     "IPAddress": "10.4.0.92",                                                    |
        |         |                     "IPPrefixLen": 24,                                                           |
        |         |                     "GlobalIPv6Address": "",                                                     |
        |         |                     "GlobalIPv6PrefixLen": 0,                                                    |
        |         |                     "MacAddress": "d2:27:31:7b:40:73"                                            |
        |         |                 }                                                                                |
        |         |             }                                                                                    |
        |         |         }                                                                                        |
        |         |     }                                                                                            |
        |         | ]                                                                                                |
        |         |                                                                                                  |
        +------------------------------------------------------------------------------------------------------------+
        | 🌱      | HOME=/root                                                                                       |
        |         | PATH=/usr/local/go/bin:/usr/local/go/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin |
        |         | :/bin                                                                                            |
        |         | DOCKER_CONFIG=/tmp/TestContainerHealthCheckAdvanceHealth_check_uses_container_environment_variab |
        |         | les1890087731/003                                                                                |
        |         | NERDCTL_TOML=/tmp/TestContainerHealthCheckAdvanceHealth_check_uses_container_environment_variabl |
        |         | es1890087731/003/nerdctl.toml                                                                    |
        +------------------------------------------------------------------------------------------------------------+
        | ⏰      | <1s (limit: 3m0s)                                                                                |
        +------------------------------------------------------------------------------------------------------------+
        | 📁      | /tmp/TestContainerHealthCheckAdvanceHealth_check_uses_container_environment_variables1890087731/ |
        |         | 002                                                                                              |
        +------------------------------------------------------------------------------------------------------------+
        
    container_health_check_test.go:352: {
          "Status": "healthy",
          "FailingStreak": 0,
          "Log": [
            {
              "Start": "2025-06-26T03:43:38.039774087Z",
              "End": "2025-06-26T03:43:38.117066808Z",
              "ExitCode": 0,
              "Output": ""
            }
          ]
        }
    container_health_check_test.go:356: assertion failed: expression is false: strings.Contains(h.Log[0].Output, "test"): expected health log output to contain 'test'
    container_health_check_test.go:603:        

Describe the results you received and expected

Work

What version of nerdctl are you using?

main

Are you using a variant of nerdctl? (e.g., Rancher Desktop)

None

Host information

No response

[apostasie]

@ningmingxiao, as our "resident-expert-in-horrible-containerd-bugs" :-)

wdyt?

Do you think we have a problem with cio? (that would explain a number of other failures) (eg: the output of a task appears empty while it should not)

nerdctl/pkg/healthcheck/executor.go

Lines 67 to 115 in 90e0caa

	func probeHealthCheck(ctx context.Context, task containerd.Task, hc *Healthcheck, processSpec *specs.Process) (*HealthcheckResult, error) {
	execID := "health-check-" + idgen.TruncateID(idgen.GenerateID())
	outputBuf := NewResizableBuffer(MaxOutputLen)
	process, err := task.Exec(ctx, execID, processSpec, cio.NewCreator(
	cio.WithStreams(nil, outputBuf, outputBuf),
	))
	if err != nil {
	log.G(ctx).Debugf("failed to exec health check: %v", err)
	return nil, fmt.Errorf("exec error: %w", err)
	}
	if err := process.Start(ctx); err != nil {
	log.G(ctx).Debugf("failed to start health check: %v", err)
	return nil, fmt.Errorf("start error: %w", err)
	}
	exitStatusC, err := process.Wait(ctx)
	if err != nil {
	return nil, fmt.Errorf("failed to wait for health check: %w", err)
	}
	select {
	case <-time.After(hc.Timeout):
	_ = process.Kill(ctx, syscall.SIGKILL)
	go func() { <-exitStatusC }()
	msg := fmt.Sprintf("Health check exceeded timeout (%v)", hc.Timeout)
	if out := outputBuf.String(); len(out) > 0 {
	msg = fmt.Sprintf("Health check exceeded timeout (%v): %s", hc.Timeout, out)
	}
	log.G(ctx).Debugf("health check timed out: %s", msg)
	return &HealthcheckResult{
	ExitCode: -1,
	Output: msg,
	End: time.Now(),
	}, nil
	case exitStatus := <-exitStatusC:
	code, _, _ := exitStatus.Result()
	return &HealthcheckResult{
	ExitCode: int(code),
	Output: outputBuf.String(),
	End: time.Now(),
	}, nil
	}
	}

[ningmingxiao]

nerdctl  run --network=none -d --name=test007 --env MYVAR=test-value --health-cmd="ls /tmp00000000" --health-interval=1s --health-timeout=1s busybox:1.28 sleep 1000

❯ nerdctl  ps
CONTAINER ID    IMAGE                             COMMAND         CREATED           STATUS    PORTS    NAMES
3b717dca8172    docker.io/library/busybox:1.28    "sleep 1000"    40 seconds ago    Up                 test007

I find healcheck doesn't work . @apostasie

❯ nerdctl  version
WARN[0000] unable to determine buildctl version          error="exec: \"buildctl\": executable file not found in $PATH"
Client:
 Version:       v0.11.1-4857-g90e0caaf.m
 OS/Arch:       linux/amd64
 Git commit:    90e0caaf46d277d4effb5c2a9aace069af814309.m
 buildctl:
  Version:

[ningmingxiao]

I should run another command "nerdctl container healthcheck 3b71"

[ningmingxiao]

can you reproduce it @apostasie
I run health check many times I can't reproduce.

./nerdctl  container healthcheck b8c887d224ef|nerdctl inspect b8c |grep -i Output
                        "Output": "test-value\n"
                        "Output": "test-value\n"
                        "Output": "test-value\n"
                        "Output": "test-value\n"
                        "Output": "test-value\n"

[ningmingxiao]

I know why, if add some sleep before it will happen, I'll try to fix it latter.

	var wg = &sync.WaitGroup{}
	if fifos.Stdout != "" {
		wg.Add(1)
		go func() {
			p := bufPool.Get().(*[]byte)
			defer bufPool.Put(p)
			time.Sleep(time.Second * 1)
			io.CopyBuffer(ioset.Stdout, pipes.Stdout, *p)
			pipes.Stdout.Close()
			wg.Done()
		}()
	}

nerdctl healthchek exited too quickly. we should wait all log is writed.

[ningmingxiao]

#4383 may fix