Buildkitd logs "failed to kill process in container id <cid>: buildkit-runc did not terminate successfully: container not running" for hours

Hello! 👋

Problem

We are seeing the buildkitd logs full of the following lines:

level=debug msg="sending sigkill to process in container 7l2ykurlf4pziiza5pnf97raw"
level=error msg="failed to kill process in container id 7l2ykurlf4pziiza5pnf97raw: buildkit-runc did not terminate successfully: exit status 1: container not running\n"

The container id is always the same. These lines are repeated for many hours, sometimes days. The frequency is about 1000/minute (~15/s). We are seeing the buildkitd healthcheck fail, and it's not clear if the cause is these errors or if the errors are simply making it more difficult to determine the underlying cause.

A pod restart clears out the problem for a bit, but it generally happens again within a few hours.

Seems like the logs come from:

buildkit/executor/runcexecutor/executor.go

Lines 526 to 529 in f84cfe3

    
           bklog.G(ctx).Debugf("sending sigkill to process in container %s", k.id) 
        
           defer func() { 
        
           	if err != nil { 
        
           		bklog.G(ctx).Errorf("failed to kill process in container id %s: %+v", k.id, err)

Before the log spam starts I don't see anything particularlly interesting in the logs

debug time="2023-12-12T08:38:23Z" level=debug msg="removed snapshot" key=buildkit/10364/nekk455whng4seiauy6yz3w4k-view snapshotter=overlayfs
debug time="2023-12-12T08:38:23Z" level=debug msg="content garbage collected" d=29.017431ms
debug time="2023-12-12T08:38:23Z" level=debug msg="snapshot garbage collected" d=415.90514ms snapshotter=overlayfs
debug time="2023-12-12T08:38:23Z" level=debug msg="gc cleaned up 2099235886 bytes"
debug time="2023-12-12T08:39:20Z" level=debug msg="session finished: <nil>" spanID=e936167880750bc7 traceID=ec6a365de81b3b59b41ae2dc13e6e08c
debug time="2023-12-12T08:39:20Z" level=debug msg="sending sigkill to process in container 7l2ykurlf4pziiza5pnf97raw"

Details

Version: buildkit:v0.12.3-rootless (we also saw this problem with 0.11.0 before upgrade)

We run 4 buildkitd runner with --oci-worker-no-process-sandbox. All of these seem to manifest this behaviour at one time or another (not necessarily at the same time).

Any ideas about how to fix this? Thank you!

@coryb

👋

@coryb Can you take a look? I've seen some of these logs myself but not in a loop as it is described here. I've also not been able to understand what exact case causes this. Even if there is some weird condition that stops from killing container cleanly, going to loop when the process is already gone should be avoided.

--oci-worker-no-process-sandbox

This might be related as it does change the parent-child structure for subprocess.

Looking at this for loop

buildkit/executor/runcexecutor/executor.go

Lines 615 to 637 in 438f472

    
           for { 
        
           	select { 
        
           	case <-ctx.Done(): 
        
           		killCtx, timeout := context.WithTimeout(context.Background(), 7*time.Second) 
        
           		if err := p.killer.Kill(killCtx); err != nil { 
        
           			select { 
        
           			case <-killCtx.Done(): 
        
           				timeout() 
        
           				cancel() 
        
           				return 
        
           			default: 
        
           			} 
        
           		} 
        
           		timeout() 
        
           		select { 
        
           		case <-time.After(50 * time.Millisecond): 
        
           		case <-p.ended: 
        
           			return 
        
           		} 
        
           	case <-p.ended: 
        
           		return 
        
           	} 
        
           }

We know that killer.Kill on line 619 is returning before the timeout with an error (the one we see in the logs). In the select on 620 that would mean it goes into the default case and does not cancel or return. Assuming p.ended on 631 is also not yet closed, that select on 629 would exit from the time.After(50ms) case and also not return, and the loop would continue. I think this is roughly the frequency of logging we are seeing, and likely what's happening.

p.ended I guess is closed by procHandle.Release, which is deferred from the caller . If I'm reading this right the caller is supposed to be cancelled by the cancel() on 623, but in this flow it seems like it would be skipped. I'm not sure if there are other possible ways this context would be cancelled.

I don't understand exactly the scenario that leads to this, but I believe this could explain the behaviour. Maybe before going into the select on 620 we could inspect the error and cancel and return if the error indicates the container is already killed?

I can also try to capture a goroutine stack dump if that would help.

we could inspect the error and cancel and return if the error indicates the container is already killed?

I think this makes sense. Looks like the actual error is coming from runc directly (via runc kill) so we do need either some string matching or some follow-up runc command to check that it doesn't see the container anymore.

We do need to make sure that the container is actually cleaned up and this isn't some issue where runc kill does not work well with the oci-worker-no-process-sandbox flag.

Thank you for confirming! This hasn't been a huge problem just yet, but I will be doing more work with our buildkit runners soon. I may come back to this and attempt a fix if it's getting in the way of the work I am doing.

Confirmed still occurring in v0.14.1-rootless.

We are seeing this behavior occur when the buildctl client is terminated in the middle of a RUN stanza in a build.

In addition to generating massive amounts of error messages, the buildkitd server can no longer terminate gracefully immediately. Instead it waits a few minutes before finally exiting with this message:

....
time="2024-06-24T19:02:15Z" level=error msg="failed to kill process in container id 8ila2y0gzo081gpwj1b6ble0q: buildkit-runc did not terminate successfully: exit status 1: container not running\n"
time="2024-06-24T19:02:15Z" level=error msg="failed to kill process in container id 8ila2y0gzo081gpwj1b6ble0q: buildkit-runc did not terminate successfully: exit status 1: container not running\n"
time="2024-06-24T19:02:16Z" level=error msg="/moby.buildkit.v1.Control/Solve returned error: rpc error: code = Canceled desc = context canceled"
buildkitd: got 1 SIGTERM/SIGINTs, forcing shutdown
github.com/moby/buildkit/util/appcontext.Context.func1.1
    /src/util/appcontext/appcontext.go:38
runtime.goexit
    /usr/local/go/src/runtime/asm_arm64.s:1197
[rootlesskit:child ] error: command [buildkitd --addr tcp://0.0.0.0:1234 --addr unix:///run/user/1000/buildkit/buildkitd.sock --oci-worker-no-process-sandbox] exited: exit status 1
[rootlesskit:parent] error: child exited: exit status 1
Stream closed EOF for buildkit/buildkit-arm64-0 (buildkitd)

Interestingly, it does resolve itself eventually, sometimes in as short as 30 seconds but other times continues for many minutes.

It does not appear to have any functional impact. The buildkitd daemon is still able to accept new builds even when this is occurring.

Looked into it more but still quite confusing what case this is.

Pretty clear it comes from this loop/sleep https://github.com/moby/buildkit/blob/v0.14.1/executor/runcexecutor/executor.go#L618-L633 , but this is only possible if p.ended has not been closed. Otherwise, you could get one or two such logs but not get stuck there. p.ended is closed in defer https://github.com/moby/buildkit/blob/v0.14.1/executor/runcexecutor/executor_linux.go#L61 . So it looks like something is blocked in this function and this goroutine is not returning.

There is no stacktrace but possible candidates where the goroutine is stuck is errgroup.Wait in https://github.com/moby/buildkit/blob/v0.14.1/executor/runcexecutor/executor_linux.go#L65-L78 or the runc.Run(). The errgroup does not seem possible, for RUN handleSignals path is skipped and WaitForStart has own early return on cancellation.

That leaves runc.Run. Looking at library, I thought that maybe it hangs in https://github.com/containerd/go-runc/blob/main/runc.go#L341 channel send because the receiver side has already returned. But that doesn't seem possible because the channel is buffered https://github.com/moby/buildkit/blob/v0.14.1/executor/runcexecutor/executor_linux.go#L71 . I fixed another case #5106 when looking at this, that could have caused process cancellation to be skipped if it appeared before the process was started, but this should not affect this case in here. I also thought that maybe the stdout/stderr streams are blocked after cancellation and runc.Run can not return but does not look like this is possible.

Then last remaining part is actual runc bug where runc run process keeps running and doesn't return while runc kill anwers "no such container running". That is possible in a small window but should not remain in error state repeatedly.

So, although we could fix the log issue with some detection of specific error, it is not clear if the runc process has actually returned, and if it has not then fixing the log would just hide the error and also avoid sending further kill commands. It should also mean that the build request is still hanging while the repeated runc kill commands are being attempted.

When I run this command:

docker buildx build --sbom=true --platform=linux/amd64 --output type=local,dest=./out docker/gotenberg

For this Dockerfile:

FROM gotenberg/gotenberg:8

# https://gotenberg.dev/docs/configuration#fonts
USER root

COPY ./fonts/*.ttf /usr/local/share/fonts/

USER gotenberg

I get the following output with error:

[+] Building 52.4s (12/12) FINISHED                                                                                                                                                             docker:desktop-linux
 => [internal] load build definition from Dockerfile                                                                                                                                                            0.0s
 => => transferring dockerfile: 223B                                                                                                                                                                            0.0s
 => resolve image config for docker-image://docker.io/docker/buildkit-syft-scanner:stable-1                                                                                                                     1.4s
 => [auth] docker/buildkit-syft-scanner:pull token for registry-1.docker.io                                                                                                                                     0.0s
 => [internal] load metadata for docker.io/gotenberg/gotenberg:8                                                                                                                                                0.9s
 => [auth] gotenberg/gotenberg:pull token for registry-1.docker.io                                                                                                                                              0.0s
 => [internal] load .dockerignore                                                                                                                                                                               0.0s
 => => transferring context: 2B                                                                                                                                                                                 0.0s
 => [internal] load build context                                                                                                                                                                               0.0s
 => => transferring context: 263B                                                                                                                                                                               0.0s
 => docker-image://docker.io/docker/buildkit-syft-scanner:stable-1                                                                                                                                              0.2s
 => => resolve docker.io/docker/buildkit-syft-scanner:stable-1                                                                                                                                                  0.2s
 => [1/2] FROM docker.io/gotenberg/gotenberg:8@sha256:8ccd9b57b537a92bba778a49a0c7a8367c61927170e632840fe8a056c4702d9f                                                                                          0.0s
 => => resolve docker.io/gotenberg/gotenberg:8@sha256:8ccd9b57b537a92bba778a49a0c7a8367c61927170e632840fe8a056c4702d9f                                                                                          0.0s
 => CACHED [2/2] COPY ./fonts/*.ttf /usr/local/share/fonts/                                                                                                                                                     0.0s
 => CACHED [linux/amd64] generating sbom using docker.io/docker/buildkit-syft-scanner:stable-1                                                                                                                  0.0s
 => CANCELED exporting to client directory                                                                                                                                                                     49.8s
 => => copying files 1.54GB                                                                                                                                                                                    46.7s
ERROR: failed to solve: error from receiver: context canceled

$ docker info                                                                                                                                                  
Client:
 Version:    28.1.1
 Context:    desktop-linux
 Debug Mode: false
 Plugins:
  ai: Docker AI Agent - Ask Gordon (Docker Inc.)
    Version:  v1.1.7
    Path:     /Users/nikbr/.docker/cli-plugins/docker-ai
  buildx: Docker Buildx (Docker Inc.)
    Version:  v0.23.0-desktop.1
    Path:     /Users/nikbr/.docker/cli-plugins/docker-buildx
  cloud: Docker Cloud (Docker Inc.)
    Version:  v0.3.0
    Path:     /Users/nikbr/.docker/cli-plugins/docker-cloud
  compose: Docker Compose (Docker Inc.)
    Version:  v2.36.0-desktop.1
    Path:     /Users/nikbr/.docker/cli-plugins/docker-compose
  debug: Get a shell into any image or container (Docker Inc.)
    Version:  0.0.38
    Path:     /Users/nikbr/.docker/cli-plugins/docker-debug
  desktop: Docker Desktop commands (Docker Inc.)
    Version:  v0.1.8
    Path:     /Users/nikbr/.docker/cli-plugins/docker-desktop
  dev: Docker Dev Environments (Docker Inc.)
    Version:  v0.1.2
    Path:     /Users/nikbr/.docker/cli-plugins/docker-dev
  extension: Manages Docker extensions (Docker Inc.)
    Version:  v0.2.27
    Path:     /Users/nikbr/.docker/cli-plugins/docker-extension
  init: Creates Docker-related starter files for your project (Docker Inc.)
    Version:  v1.4.0
    Path:     /Users/nikbr/.docker/cli-plugins/docker-init
  mcp: Docker MCP Plugin (Docker Inc.)
    Version:  dev
    Path:     /Users/nikbr/.docker/cli-plugins/docker-mcp
  model: Docker Model Runner (Docker Inc.)
    Version:  v0.1.23
    Path:     /Users/nikbr/.docker/cli-plugins/docker-model
  sbom: View the packaged-based Software Bill Of Materials (SBOM) for an image (Anchore Inc.)
    Version:  0.6.0
    Path:     /Users/nikbr/.docker/cli-plugins/docker-sbom
  scout: Docker Scout (Docker Inc.)
    Version:  v1.18.0
    Path:     /Users/nikbr/.docker/cli-plugins/docker-scout

@glightfoot

@glightfoot if this is occurring consistently for you, can you run kill -QUIT on the dockerd process or buildkit process where the build is happening and send over the stack trace it prints? I believe the stack trace will probably end up in the log but it may also end up in another location. If you're using docker desktop, I think the process might be a little more involved and I can probably guide you through it after testing it myself.

Go programs will print the stack trace of the goroutines when they are killed with that signal which is really useful for finding deadlocks.

I suspect this is occurring due to a deadlock that's happening somewhere in this area. It's possible it's earlier than that (somewhere else in callWithIO) but that specific function is a very likely area.

@jsternberg

@jsternberg unfortunately we don't have any indication when it's happening on the client, and run out buildkits centrally for all our users, so we have no clean way of generating that stacktrace on the client side. If you mean on the buildkit process itself, I can try to find one where its happening and generate one when I notice it again. Thanks for looking into it!

Yea the buildkit process is where I'm looking. I'm also looking at the test case in your PR and I suspect the underlying problem might have something to do with runtime.LockOSThread() and possibly Start or Wait. I saw in the test case in your PR that you identified things as being locked waiting for Wait. Can you confirm that it is getting stuck in Wait? That'll help me narrow down a bit what the underlying cause might be.

@glightfoot

@glightfoot also what options do you run buildkit with? Are you using rootless and/or --oci-process-no-sandbox like the original issue creator was or in a different configuration?

Looking into this more, I'm becoming more convinced the bug is in runc itself somewhere. Our current logging doesn't cover the case where the first kill signal gets sent successfully but runc fails to exit so I imagine there's a possibility that it sends kill to runc, the state somehow gets cleaned up but runc never returns or returns very slowly, and then subsequent kill requests return that the container doesn't exist anymore.

We run the rootless version with worker.oci.noProcessSandbox: true in the config. Yeah when I looked into it it also seemed like a bug in runc, but don't know the codebase well enough to be sure

Here is a stack trace from one of the nodes running on the latest buildkit (v0.30.0) that has spewed about 100 of these in the last hour

buildkit-stacktrace.txt

Thanks. That was really helpful. Do you know how many cores there are on the machine that created this? Or if you've overwritten GOMAXPROCS whatever that value is.

It's running on an m7i.8xlarge (32 vCPU) with no overrides for GOMAXPROCS

Since you are running this with no process sandbox, I assume that you can see the hanging runc processes in the host pid namespace. If you use ps -e to see all processes, can you see any runc processes? If so, can you also try using kill -QUIT on them? I don't know where they'd print whatever they're going to print but maybe we'll be able to see something.

I don't see any hung runc processes - just a few buildkit-runc that spawn and finish over a few seconds to minutes. Although, I might have just been too late in getting to the node

I think that's the issue - runc exits and buildkit still thinks it's running and tries to kill something that isn't there

@glightfoot

@glightfoot when buildkit prints the container it failed to kill, such as in this log message from another person:

failed to kill process in container id 8ila2y0gzo081gpwj1b6ble0q

Is the id there the same for longer than 5 minutes? Or does the container id change over time? I'm wondering if there's no deadlock here. It's just runc takes a little while to shut down and we aren't patient or coerce enough with logging. As with the current iteration, we'll spam the log every 50 ms with an unnecessary "could not kill container" over and over again until runc exits properly even if it's currently in the process of exiting.

In case my guess from the previous comment is correct, I refactored how the runc executor logs this event to either make it more clear what's happening (if this is what's happening) or to at least give us some more information in #6779.

Under no-process-sandbox runc kill only reaches init and surviving subprocesses can hold the container open - #7087 kills the process group instead, should prob. fix it.

Navigation Menu

Buildkitd logs "failed to kill process in container id <cid>: buildkit-runc did not terminate successfully: container not running" for hours #4483

Problem

Details

16 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

	bklog.G(ctx).Debugf("sending sigkill to process in container %s", k.id)
	defer func() {
	if err != nil {
	bklog.G(ctx).Errorf("failed to kill process in container id %s: %+v", k.id, err)

	for {
	select {
	case <-ctx.Done():
	killCtx, timeout := context.WithTimeout(context.Background(), 7*time.Second)
	if err := p.killer.Kill(killCtx); err != nil {
	select {
	case <-killCtx.Done():
	timeout()
	cancel()
	return
	default:
	}
	}
	timeout()
	select {
	case <-time.After(50 * time.Millisecond):
	case <-p.ended:
	return
	}
	case <-p.ended:
	return
	}
	}

Buildkitd logs "failed to kill process in container id <cid>: buildkit-runc did not terminate successfully: container not running" for hours #4483

Description

Problem

Details

Activity

tonistiigi commented on Dec 14, 2023

dnephin commented on Dec 14, 2023

tonistiigi commented on Dec 14, 2023

dnephin commented on Jan 13, 2024

fullykubed commented on Jun 24, 2024

fullykubed commented on Jun 24, 2024

tonistiigi commented on Jul 1, 2024

16 remaining items

NiklasBr commented on May 22, 2025

jsternberg commented on May 14, 2026

glightfoot commented on May 14, 2026

jsternberg commented on May 14, 2026

jsternberg commented on May 14, 2026

glightfoot commented on May 14, 2026

glightfoot commented on May 14, 2026

jsternberg commented on May 14, 2026

glightfoot commented on May 14, 2026

jsternberg commented on May 14, 2026

glightfoot commented on May 14, 2026

glightfoot commented on May 14, 2026

jsternberg commented on May 15, 2026

jsternberg commented on May 15, 2026

dany74q commented on Aug 27, 2026

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions