Skip to content

Race condition / bug in tasks exec #775

New issue
New issue
Open
Open
Race condition / bug in tasks exec#775
@pawelbeza

Description

@pawelbeza
pawelbeza
opened on Oct 30, 2023

Hey everyone,
I have an issue where the exec process hangs when I'm piping the input:
echo 123 | sudo firecracker-ctr --address /run/firecracker-containerd/containerd.sock tasks exec --exec-id test test cat

I experienced this issue for the first time when I was playing around with firecracker-containerd through API and it seems it's a broader issue. I've also double checked and latest version of containerd with runc doesn't have similar issues.

pprof

After running firecracker-ctr exec

sudo firecracker-ctr --address /run/firecracker-containerd/containerd.sock pprof --debug-socket /run/firecracker-containerd/debug.sock goroutines
goroutine 342 [running]:
runtime/pprof.writeGoroutineStacks({0x26ec740, 0xc0004d8620})
	/usr/lib/go-1.17/src/runtime/pprof/pprof.go:693 +0x70
runtime/pprof.writeGoroutine({0x26ec740, 0xc0004d8620}, 0xc00007ec00)
	/usr/lib/go-1.17/src/runtime/pprof/pprof.go:682 +0x2b
runtime/pprof.(*Profile).WriteTo(0x2317200, {0x26ec740, 0xc0004d8620}, 0xc)
	/usr/lib/go-1.17/src/runtime/pprof/pprof.go:331 +0x14b
net/http/pprof.handler.ServeHTTP({0xc0000f8a91, 0xc0001c0000}, {0x2711980, 0xc0004d8620}, 0xc0000f8a84)
	/usr/lib/go-1.17/src/net/http/pprof/pprof.go:253 +0x49a
net/http/pprof.Index({0x2711980, 0xc0004d8620}, 0xc000726200)
	/usr/lib/go-1.17/src/net/http/pprof/pprof.go:371 +0x12e
net/http.HandlerFunc.ServeHTTP(0x0, {0x2711980, 0xc0004d8620}, 0x0)
	/usr/lib/go-1.17/src/net/http/server.go:2047 +0x2f
net/http.(*ServeMux).ServeHTTP(0xc0000f8a9b, {0x2711980, 0xc0004d8620}, 0xc000726200)
	/usr/lib/go-1.17/src/net/http/server.go:2425 +0x149
net/http.serverHandler.ServeHTTP({0xc0006aeba0}, {0x2711980, 0xc0004d8620}, 0xc000726200)
	/usr/lib/go-1.17/src/net/http/server.go:2879 +0x43b
net/http.(*conn).serve(0xc0000e8d20, {0x2727360, 0xc0001c40f0})
	/usr/lib/go-1.17/src/net/http/server.go:1930 +0xb08
created by net/http.(*Server).Serve
	/usr/lib/go-1.17/src/net/http/server.go:3034 +0x4e8

goroutine 1 [chan receive, 7 minutes]:
github.com/containerd/containerd/cmd/containerd/command.App.func1(0xc0005ecc60)
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/cmd/containerd/command/main.go:279 +0x1395
github.com/urfave/cli.HandleAction({0x2172dc0, 0x2529bc8}, 0xc0000eee00)
	/home/pbeza/go/pkg/mod/github.com/urfave/cli@v1.22.2/app.go:523 +0xa8
github.com/urfave/cli.(*App).Run(0xc0000eee00, {0xc000112150, 0x3, 0x3})
	/home/pbeza/go/pkg/mod/github.com/urfave/cli@v1.22.2/app.go:285 +0x734
main.main()
	/home/pbeza/firecracker-containerd/firecracker-control/cmd/containerd/main.go:67 +0x37

goroutine 28 [chan receive]:
k8s.io/klog/v2.(*loggingT).flushDaemon(0x0)
	/home/pbeza/go/pkg/mod/k8s.io/klog/v2@v2.30.0/klog.go:1181 +0x6a
created by k8s.io/klog/v2.init.0
	/home/pbeza/go/pkg/mod/k8s.io/klog/v2@v2.30.0/klog.go:420 +0xfb

goroutine 15 [select, 3 minutes]:
github.com/docker/go-events.(*Broadcaster).run(0xc000640000)
	/home/pbeza/go/pkg/mod/github.com/docker/go-events@v0.0.0-20190806004212-e31b211e4f1c/broadcast.go:117 +0x195
created by github.com/docker/go-events.NewBroadcaster
	/home/pbeza/go/pkg/mod/github.com/docker/go-events@v0.0.0-20190806004212-e31b211e4f1c/broadcast.go:39 +0x1af

goroutine 13 [select, 7 minutes]:
github.com/containerd/containerd/cmd/containerd/command.handleSignals.func1()
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/cmd/containerd/command/main_unix.go:44 +0xf9
created by github.com/containerd/containerd/cmd/containerd/command.handleSignals
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/cmd/containerd/command/main_unix.go:41 +0xfe

goroutine 32 [syscall, 7 minutes]:
os/signal.signal_recv()
	/usr/lib/go-1.17/src/runtime/sigqueue.go:169 +0x98
os/signal.loop()
	/usr/lib/go-1.17/src/os/signal/signal_unix.go:24 +0x19
created by os/signal.Notify.func1.1
	/usr/lib/go-1.17/src/os/signal/signal.go:151 +0x2c

goroutine 274 [select, 3 minutes]:
github.com/containerd/ttrpc.(*serverConn).run(0xc000808d70, {0x27272f0, 0xc00012a000})
	/home/pbeza/go/pkg/mod/github.com/containerd/ttrpc@v1.1.2/server.go:432 +0x588
created by github.com/containerd/ttrpc.(*Server).Serve
	/home/pbeza/go/pkg/mod/github.com/containerd/ttrpc@v1.1.2/server.go:128 +0x275

goroutine 54 [select, 7 minutes]:
github.com/containerd/ttrpc.(*Client).run(0xc0007e4280)
	/home/pbeza/go/pkg/mod/github.com/containerd/ttrpc@v1.1.2/client.go:330 +0x21a
created by github.com/containerd/ttrpc.NewClient
	/home/pbeza/go/pkg/mod/github.com/containerd/ttrpc@v1.1.2/client.go:94 +0x1ef

goroutine 48 [select]:
github.com/containerd/containerd/gc/scheduler.(*gcScheduler).run(0xc00030e9c0, {0x27272b8, 0xc00015d000})
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/gc/scheduler/scheduler.go:268 +0x1a5
created by github.com/containerd/containerd/gc/scheduler.init.0.func1
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/gc/scheduler/scheduler.go:132 +0x37d

goroutine 123 [sleep]:
time.Sleep(0x2540be400)
	/usr/lib/go-1.17/src/runtime/time.go:193 +0x12e
github.com/containerd/containerd/runtime/restart/monitor.(*monitor).run(0xc0001011a0, 0xc00030f8c0)
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/runtime/restart/monitor/monitor.go:165 +0x3f
created by github.com/containerd/containerd/runtime/restart/monitor.init.0.func1
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/runtime/restart/monitor/monitor.go:86 +0x10f

goroutine 86 [IO wait]:
internal/poll.runtime_pollWait(0x7f370c6720f8, 0x72)
	/usr/lib/go-1.17/src/runtime/netpoll.go:303 +0x85
internal/poll.(*pollDesc).wait(0xc00004ba00, 0x203000, 0x0)
	/usr/lib/go-1.17/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
	/usr/lib/go-1.17/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Accept(0xc00004ba00)
	/usr/lib/go-1.17/src/internal/poll/fd_unix.go:402 +0x22c
net.(*netFD).accept(0xc00004ba00)
	/usr/lib/go-1.17/src/net/fd_unix.go:173 +0x35
net.(*UnixListener).accept(0xc00042aab8)
	/usr/lib/go-1.17/src/net/unixsock_posix.go:167 +0x1c
net.(*UnixListener).Accept(0xc00050d0e0)
	/usr/lib/go-1.17/src/net/unixsock.go:260 +0x3d
net/http.(*Server).Serve(0xc0001ca000, {0x27117a0, 0xc00050d0e0})
	/usr/lib/go-1.17/src/net/http/server.go:3002 +0x394
github.com/containerd/containerd/services/server.(*Server).ServeDebug(0x0, {0x27117a0, 0xc00050d0e0})
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/services/server/server.go:361 +0x165
github.com/containerd/containerd/cmd/containerd/command.serve.func1()
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/cmd/containerd/command/main.go:290 +0xbe
created by github.com/containerd/containerd/cmd/containerd/command.serve
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/cmd/containerd/command/main.go:288 +0x26f

goroutine 87 [IO wait, 7 minutes]:
internal/poll.runtime_pollWait(0x7f370c672008, 0x72)
	/usr/lib/go-1.17/src/runtime/netpoll.go:303 +0x85
internal/poll.(*pollDesc).wait(0xc0001bc100, 0x0, 0x0)
	/usr/lib/go-1.17/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
	/usr/lib/go-1.17/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Accept(0xc0001bc100)
	/usr/lib/go-1.17/src/internal/poll/fd_unix.go:402 +0x22c
net.(*netFD).accept(0xc0001bc100)
	/usr/lib/go-1.17/src/net/fd_unix.go:173 +0x35
net.(*UnixListener).accept(0xc0005f4b58)
	/usr/lib/go-1.17/src/net/unixsock_posix.go:167 +0x1c
net.(*UnixListener).Accept(0xc000820390)
	/usr/lib/go-1.17/src/net/unixsock.go:260 +0x3d
github.com/containerd/ttrpc.(*Server).Serve(0xc00003cae0, {0x27272f0, 0xc00012a000}, {0x27117a0, 0xc000820390})
	/home/pbeza/go/pkg/mod/github.com/containerd/ttrpc@v1.1.2/server.go:88 +0x142
github.com/containerd/containerd/services/server.(*Server).ServeTTRPC(0x0, {0x27117a0, 0xc000820390})
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/services/server/server.go:326 +0x3e
github.com/containerd/containerd/cmd/containerd/command.serve.func1()
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/cmd/containerd/command/main.go:290 +0xbe
created by github.com/containerd/containerd/cmd/containerd/command.serve
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/cmd/containerd/command/main.go:288 +0x26f

goroutine 88 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7f370c671f18, 0x72)
	/usr/lib/go-1.17/src/runtime/netpoll.go:303 +0x85
internal/poll.(*pollDesc).wait(0xc0001bcf00, 0x20, 0x0)
	/usr/lib/go-1.17/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
	/usr/lib/go-1.17/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Accept(0xc0001bcf00)
	/usr/lib/go-1.17/src/internal/poll/fd_unix.go:402 +0x22c
net.(*netFD).accept(0xc0001bcf00)
	/usr/lib/go-1.17/src/net/fd_unix.go:173 +0x35
net.(*UnixListener).accept(0xc00042bb40)
	/usr/lib/go-1.17/src/net/unixsock_posix.go:167 +0x1c
net.(*UnixListener).Accept(0xc000820450)
	/usr/lib/go-1.17/src/net/unixsock.go:260 +0x3d
google.golang.org/grpc.(*Server).Serve(0xc0000ee1c0, {0x27117a0, 0xc000820450})
	/home/pbeza/go/pkg/mod/google.golang.org/grpc@v1.38.1/server.go:786 +0x362
github.com/containerd/containerd/services/server.(*Server).ServeGRPC(0xc00063a0c0, {0x27117a0, 0xc000820450})
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/services/server/server.go:321 +0x6a
github.com/containerd/containerd/cmd/containerd/command.serve.func1()
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/cmd/containerd/command/main.go:290 +0xbe
created by github.com/containerd/containerd/cmd/containerd/command.serve
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/cmd/containerd/command/main.go:288 +0x26f

goroutine 338 [select, 3 minutes]:
github.com/containerd/ttrpc.(*Client).dispatch(0xc0007e4280, {0x2727360, 0xc0006aeb10}, 0xc000566900, 0xc0006b6380)
	/home/pbeza/go/pkg/mod/github.com/containerd/ttrpc@v1.1.2/client.go:163 +0x2cf
github.com/containerd/ttrpc.defaultClientInterceptor({0x2727360, 0xc0006aeb10}, 0x361ea58, 0xc0004aa100, 0xc000e77438, 0x40)
	/home/pbeza/go/pkg/mod/github.com/containerd/ttrpc@v1.1.2/interceptor.go:49 +0x26
github.com/containerd/ttrpc.(*Client).Call(0xc0007e4280, {0x2727360, 0xc0006aeb10}, {0x247e7d9, 0x0}, {0x2459171, 0xc000e774d0}, {0x23a9b60, 0xc0002b9880}, {0x23a9ca0, ...})
	/home/pbeza/go/pkg/mod/github.com/containerd/ttrpc@v1.1.2/client.go:132 +0x325
github.com/containerd/containerd/runtime/v2/task.(*taskClient).Wait(0xc000634110, {0x2727360, 0xc0006aeb10}, 0x22b4aa0)
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/runtime/v2/task/shim.pb.go:3689 +0x98
github.com/containerd/containerd/runtime/v2.(*process).Wait(0xc000625350, {0x2727360, 0xc0006aeb10})
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/runtime/v2/process.go:128 +0xca
github.com/containerd/containerd/services/tasks.(*local).Wait(0xc0006aeab0, {0x2727360, 0xc0006aeb10}, 0xc0002d7580, {0x2363d00, 0x23e61c0, 0xc000584c00})
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/services/tasks/local.go:634 +0xca
github.com/containerd/containerd/services/tasks.(*service).Wait(0x2727360, {0x2727360, 0xc0006aeb10}, 0x7)
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/services/tasks/service.go:133 +0x36
github.com/containerd/containerd/api/services/tasks/v1._Tasks_Wait_Handler.func1({0x2727360, 0xc0006aeb10}, {0x23a4f20, 0xc0002d7580})
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/api/services/tasks/v1/tasks.pb.go:1846 +0x7b
github.com/containerd/containerd/services/server.unaryNamespaceInterceptor({0x2727360, 0xc0006ae9c0}, {0x23a4f20, 0xc0002d7580}, 0x0, 0xc000625140)
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/services/server/namespace.go:31 +0x6b
github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1.1({0x2727360, 0xc0006ae9c0}, {0x23a4f20, 0xc0002d7580})
	/home/pbeza/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware@v1.3.0/chain.go:25 +0x3a
github.com/grpc-ecosystem/go-grpc-prometheus.(*ServerMetrics).UnaryServerInterceptor.func1({0x2727360, 0xc0006ae9c0}, {0x23a4f20, 0xc0002d7580}, 0x0, 0xc0007d0980)
	/home/pbeza/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-prometheus@v1.2.0/server_metrics.go:107 +0x87
github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1.1({0x2727360, 0xc0006ae9c0}, {0x23a4f20, 0xc0002d7580})
	/home/pbeza/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware@v1.3.0/chain.go:25 +0x3a
go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc.UnaryServerInterceptor.func1({0x2727360, 0xc0006ae750}, {0x23a4f20, 0xc0002d7580}, 0xc0007d0960, 0xc0007d09a0)
	/home/pbeza/go/pkg/mod/go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc@v0.28.0/interceptor.go:325 +0x63c
github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1.1({0x2727360, 0xc0006ae750}, {0x23a4f20, 0xc0002d7580})
	/home/pbeza/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware@v1.3.0/chain.go:25 +0x3a
github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1({0x2727360, 0xc0006ae750}, {0x23a4f20, 0xc0002d7580}, 0xc00042dbb8, 0x2211980)
	/home/pbeza/go/pkg/mod/github.com/grpc-ecosystem/go-grpc-middleware@v1.3.0/chain.go:34 +0xbf
github.com/containerd/containerd/api/services/tasks/v1._Tasks_Wait_Handler({0x23e61c0, 0xc000571c20}, {0x2727360, 0xc0006ae750}, 0xc000844c60, 0xc00003c3f0)
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/api/services/tasks/v1/tasks.pb.go:1848 +0x138
google.golang.org/grpc.(*Server).processUnaryRPC(0xc0000ee1c0, {0x2754438, 0xc0005e9500}, 0xc0005fb7a0, 0xc00050cf90, 0x3549a00, 0x0)
	/home/pbeza/go/pkg/mod/google.golang.org/grpc@v1.38.1/server.go:1286 +0xc8f
google.golang.org/grpc.(*Server).handleStream(0xc0000ee1c0, {0x2754438, 0xc0005e9500}, 0xc0005fb7a0, 0x0)
	/home/pbeza/go/pkg/mod/google.golang.org/grpc@v1.38.1/server.go:1609 +0xa2a
google.golang.org/grpc.(*Server).serveStreams.func1.2()
	/home/pbeza/go/pkg/mod/google.golang.org/grpc@v1.38.1/server.go:934 +0x98
created by google.golang.org/grpc.(*Server).serveStreams.func1
	/home/pbeza/go/pkg/mod/google.golang.org/grpc@v1.38.1/server.go:932 +0x294

goroutine 224 [IO wait, 7 minutes]:
internal/poll.runtime_pollWait(0x7f370c6716a8, 0x72)
	/usr/lib/go-1.17/src/runtime/netpoll.go:303 +0x85
internal/poll.(*pollDesc).wait(0xc000546c60, 0xc000fc4000, 0x1)
	/usr/lib/go-1.17/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
	/usr/lib/go-1.17/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc000546c60, {0xc000fc4000, 0x8000, 0x8000})
	/usr/lib/go-1.17/src/internal/poll/fd_unix.go:167 +0x25a
os.(*File).read(...)
	/usr/lib/go-1.17/src/os/file_posix.go:32
os.(*File).Read(0xc00031c4d8, {0xc000fc4000, 0xc00031c4c8, 0xc00063c720})
	/usr/lib/go-1.17/src/os/file.go:119 +0x5e
io.copyBuffer({0x26eb380, 0xc00031c4c8}, {0x26ec860, 0xc00031c4d8}, {0x0, 0x0, 0x0})
	/usr/lib/go-1.17/src/io/io.go:423 +0x1b2
io.Copy(...)
	/usr/lib/go-1.17/src/io/io.go:382
os/exec.(*Cmd).writerDescriptor.func1()
	/usr/lib/go-1.17/src/os/exec/exec.go:311 +0x3a
os/exec.(*Cmd).Start.func1(0xc00081e180)
	/usr/lib/go-1.17/src/os/exec/exec.go:444 +0x25
created by os/exec.(*Cmd).Start
	/usr/lib/go-1.17/src/os/exec/exec.go:443 +0x87b

goroutine 225 [syscall, 7 minutes]:
syscall.Syscall6(0xf7, 0x1, 0xca41, 0xc000429550, 0x1000004, 0x0, 0x0)
	/usr/lib/go-1.17/src/syscall/asm_linux_amd64.s:43 +0x5
os.(*Process).blockUntilWaitable(0xc0000f8f30)
	/usr/lib/go-1.17/src/os/wait_waitid.go:33 +0x9c
os.(*Process).wait(0xc0000f8f30)
	/usr/lib/go-1.17/src/os/exec_unix.go:23 +0x28
os.(*Process).Wait(...)
	/usr/lib/go-1.17/src/os/exec.go:132
os/exec.(*Cmd).Wait(0xc0005ed340)
	/usr/lib/go-1.17/src/os/exec/exec.go:510 +0x54
github.com/firecracker-microvm/firecracker-containerd/firecracker-control.(*local).newShim.func1()
	/home/pbeza/firecracker-containerd/firecracker-control/local.go:519 +0xa5
created by github.com/firecracker-microvm/firecracker-containerd/firecracker-control.(*local).newShim
	/home/pbeza/firecracker-containerd/firecracker-control/local.go:518 +0x104f

goroutine 223 [select, 7 minutes]:
io.(*pipe).Read(0xc000546ba0, {0xc0004d7000, 0x1000, 0xc000334401})
	/usr/lib/go-1.17/src/io/pipe.go:57 +0xb7
io.(*PipeReader).Read(0x30, {0xc0004d7000, 0x30, 0xc000301800})
	/usr/lib/go-1.17/src/io/pipe.go:134 +0x25
bufio.(*Scanner).Scan(0xc0005c3f28)
	/usr/lib/go-1.17/src/bufio/scan.go:215 +0x865
github.com/sirupsen/logrus.(*Entry).writerScanner(0xc0005c3fd0, 0xc00031c4c0, 0xc000585c60)
	/home/pbeza/go/pkg/mod/github.com/sirupsen/logrus@v1.8.1/writer.go:59 +0xa5
created by github.com/sirupsen/logrus.(*Entry).WriterLevel
	/home/pbeza/go/pkg/mod/github.com/sirupsen/logrus@v1.8.1/writer.go:51 +0x3d6

goroutine 301 [select, 3 minutes]:
google.golang.org/grpc/internal/transport.(*controlBuffer).get(0xc0000b14f0, 0x1)
	/home/pbeza/go/pkg/mod/google.golang.org/grpc@v1.38.1/internal/transport/controlbuf.go:407 +0x11b
google.golang.org/grpc/internal/transport.(*loopyWriter).run(0xc00058a9c0)
	/home/pbeza/go/pkg/mod/google.golang.org/grpc@v1.38.1/internal/transport/controlbuf.go:527 +0x85
google.golang.org/grpc/internal/transport.newHTTP2Server.func2()
	/home/pbeza/go/pkg/mod/google.golang.org/grpc@v1.38.1/internal/transport/http2_server.go:292 +0xc6
created by google.golang.org/grpc/internal/transport.newHTTP2Server
	/home/pbeza/go/pkg/mod/google.golang.org/grpc@v1.38.1/internal/transport/http2_server.go:289 +0x148f

goroutine 303 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7f370c671a68, 0x72)
	/usr/lib/go-1.17/src/runtime/netpoll.go:303 +0x85
internal/poll.(*pollDesc).wait(0xc000724400, 0xc0006b8000, 0x0)
	/usr/lib/go-1.17/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
	/usr/lib/go-1.17/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc000724400, {0xc0006b8000, 0x8000, 0x8000})
	/usr/lib/go-1.17/src/internal/poll/fd_unix.go:167 +0x25a
net.(*netFD).Read(0xc000724400, {0xc0006b8000, 0x60100000000, 0x8})
	/usr/lib/go-1.17/src/net/fd_posix.go:56 +0x29
net.(*conn).Read(0xc00031c2a8, {0xc0006b8000, 0xc0002631e0, 0x4})
	/usr/lib/go-1.17/src/net/net.go:183 +0x45
bufio.(*Reader).Read(0xc00058a900, {0xc00003ee40, 0x9, 0xc0002a9d28})
	/usr/lib/go-1.17/src/bufio/bufio.go:227 +0x1b4
io.ReadAtLeast({0x26e8520, 0xc00058a900}, {0xc00003ee40, 0x9, 0x9}, 0x9)
	/usr/lib/go-1.17/src/io/io.go:328 +0x9a
io.ReadFull(...)
	/usr/lib/go-1.17/src/io/io.go:347
golang.org/x/net/http2.readFrameHeader({0xc00003ee40, 0x9, 0xc0003342b8}, {0x26e8520, 0xc00058a900})
	/home/pbeza/go/pkg/mod/golang.org/x/net@v0.8.0/http2/frame.go:237 +0x6e
golang.org/x/net/http2.(*Framer).ReadFrame(0xc00003ee00)
	/home/pbeza/go/pkg/mod/golang.org/x/net@v0.8.0/http2/frame.go:498 +0x95
google.golang.org/grpc/internal/transport.(*http2Server).HandleStreams(0xc0005e9500, 0xc000f97710, 0xc000f977d0)
	/home/pbeza/go/pkg/mod/google.golang.org/grpc@v1.38.1/internal/transport/http2_server.go:473 +0xb2
google.golang.org/grpc.(*Server).serveStreams(0xc0000ee1c0, {0x2754438, 0xc0005e9500})
	/home/pbeza/go/pkg/mod/google.golang.org/grpc@v1.38.1/server.go:918 +0x142
google.golang.org/grpc.(*Server).handleRawConn.func1()
	/home/pbeza/go/pkg/mod/google.golang.org/grpc@v1.38.1/server.go:868 +0x46
created by google.golang.org/grpc.(*Server).handleRawConn
	/home/pbeza/go/pkg/mod/google.golang.org/grpc@v1.38.1/server.go:867 +0x472

goroutine 251 [IO wait, 7 minutes]:
internal/poll.runtime_pollWait(0x7f370c671d38, 0x72)
	/usr/lib/go-1.17/src/runtime/netpoll.go:303 +0x85
internal/poll.(*pollDesc).wait(0xc000844ae0, 0xc000fba000, 0x1)
	/usr/lib/go-1.17/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
	/usr/lib/go-1.17/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc000844ae0, {0xc000fba000, 0x8000, 0x8000})
	/usr/lib/go-1.17/src/internal/poll/fd_unix.go:167 +0x25a
os.(*File).read(...)
	/usr/lib/go-1.17/src/os/file_posix.go:32
os.(*File).Read(0xc0001dc1f8, {0xc000fba000, 0xc000700000, 0xc000fba000})
	/usr/lib/go-1.17/src/os/file.go:119 +0x5e
github.com/containerd/fifo.(*fifo).Read(0xc000844a80, {0xc000fba000, 0x8000, 0x8000})
	/home/pbeza/go/pkg/mod/github.com/containerd/fifo@v1.1.0/fifo.go:182 +0x113
io.copyBuffer({0x26ee880, 0xc000847890}, {0x7f370c42b378, 0xc000844a80}, {0x0, 0x0, 0x0})
	/usr/lib/go-1.17/src/io/io.go:423 +0x1b2
io.Copy(...)
	/usr/lib/go-1.17/src/io/io.go:382
os.genericReadFrom(0xc76915, {0x7f370c42b378, 0xc000844a80})
	/usr/lib/go-1.17/src/os/file.go:162 +0x5d
os.(*File).ReadFrom(0xc000126010, {0x7f370c42b378, 0xc000844a80})
	/usr/lib/go-1.17/src/os/file.go:156 +0x1b0
io.copyBuffer({0x26ec8a0, 0xc000126010}, {0x7f370c42b378, 0xc000844a80}, {0x0, 0x0, 0x0})
	/usr/lib/go-1.17/src/io/io.go:409 +0x14b
io.Copy(...)
	/usr/lib/go-1.17/src/io/io.go:382
github.com/containerd/containerd/runtime/v2.(*binary).Start.func3()
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/runtime/v2/binary.go:108 +0xdf
created by github.com/containerd/containerd/runtime/v2.(*binary).Start
	/home/pbeza/go/pkg/mod/github.com/containerd/containerd@v1.6.20/runtime/v2/binary.go:106 +0x50f

goroutine 302 [select, 3 minutes]:
google.golang.org/grpc/internal/transport.(*http2Server).keepalive(0xc0005e9500)
	/home/pbeza/go/pkg/mod/google.golang.org/grpc@v1.38.1/internal/transport/http2_server.go:993 +0x245
created by google.golang.org/grpc/internal/transport.newHTTP2Server
	/home/pbeza/go/pkg/mod/google.golang.org/grpc@v1.38.1/internal/transport/http2_server.go:300 +0x14d7

goroutine 56 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7f370c671b58, 0x72)
	/usr/lib/go-1.17/src/runtime/netpoll.go:303 +0x85
internal/poll.(*pollDesc).wait(0xc0007e4080, 0xc0007e7000, 0x0)
	/usr/lib/go-1.17/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
	/usr/lib/go-1.17/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc0007e4080, {0xc0007e7000, 0x1000, 0x1000})
	/usr/lib/go-1.17/src/internal/poll/fd_unix.go:167 +0x25a
net.(*netFD).Read(0xc0007e4080, {0xc0007e7000, 0x20e8f21, 0x7})
	/usr/lib/go-1.17/src/net/fd_posix.go:56 +0x29
net.(*conn).Read(0xc0006340b0, {0xc0007e7000, 0xfc0a70, 0xc0006314a0})
	/usr/lib/go-1.17/src/net/net.go:183 +0x45
bufio.(*Reader).Read(0xc0005661e0, {0xc0001b81a0, 0xa, 0xc000702b60})
	/usr/lib/go-1.17/src/bufio/bufio.go:227 +0x1b4
io.ReadAtLeast({0x26e8520, 0xc0005661e0}, {0xc0001b81a0, 0xa, 0xa}, 0xa)
	/usr/lib/go-1.17/src/io/io.go:328 +0x9a
io.ReadFull(...)
	/usr/lib/go-1.17/src/io/io.go:347
github.com/containerd/ttrpc.readMessageHeader({0xc0001b81a0, 0xa, 0x0}, {0x26e8520, 0xc0005661e0})
	/home/pbeza/go/pkg/mod/github.com/containerd/ttrpc@v1.1.2/channel.go:53 +0x55
github.com/containerd/ttrpc.(*channel).recv(0xc0001b8180)
	/home/pbeza/go/pkg/mod/github.com/containerd/ttrpc@v1.1.2/channel.go:101 +0x4d
github.com/containerd/ttrpc.(*Client).run.func2()
	/home/pbeza/go/pkg/mod/github.com/containerd/ttrpc@v1.1.2/client.go:294 +0xc6
created by github.com/containerd/ttrpc.(*Client).run
	/home/pbeza/go/pkg/mod/github.com/containerd/ttrpc@v1.1.2/client.go:286 +0x185

goroutine 55 [select, 3 minutes]:
github.com/containerd/ttrpc.(*Client).run.func1()
	/home/pbeza/go/pkg/mod/github.com/containerd/ttrpc@v1.1.2/client.go:265 +0xbe
created by github.com/containerd/ttrpc.(*Client).run
	/home/pbeza/go/pkg/mod/github.com/containerd/ttrpc@v1.1.2/client.go:262 +0x10f

goroutine 275 [IO wait, 3 minutes]:
internal/poll.runtime_pollWait(0x7f370c6714c8, 0x72)
	/usr/lib/go-1.17/src/runtime/netpoll.go:303 +0x85
internal/poll.(*pollDesc).wait(0xc000576000, 0xc000578000, 0x0)
	/usr/lib/go-1.17/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
	/usr/lib/go-1.17/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc000576000, {0xc000578000, 0x1000, 0x1000})
	/usr/lib/go-1.17/src/internal/poll/fd_unix.go:167 +0x25a
net.(*netFD).Read(0xc000576000, {0xc000578000, 0xcb72b1, 0xcd626e})
	/usr/lib/go-1.17/src/net/fd_posix.go:56 +0x29
net.(*conn).Read(0xc0001dc248, {0xc000578000, 0xcb5c13, 0x361e7c8})
	/usr/lib/go-1.17/src/net/net.go:183 +0x45
bufio.(*Reader).Read(0xc0008450e0, {0xc0003c78a0, 0xa, 0x0})
	/usr/lib/go-1.17/src/bufio/bufio.go:227 +0x1b4
io.ReadAtLeast({0x26e8520, 0xc0008450e0}, {0xc0003c78a0, 0xa, 0xa}, 0xa)
	/usr/lib/go-1.17/src/io/io.go:328 +0x9a
io.ReadFull(...)
	/usr/lib/go-1.17/src/io/io.go:347
github.com/containerd/ttrpc.readMessageHeader({0xc0003c78a0, 0xa, 0x10000c000e7e000}, {0x26e8520, 0xc0008450e0})
	/home/pbeza/go/pkg/mod/github.com/containerd/ttrpc@v1.1.2/channel.go:53 +0x55
github.com/containerd/ttrpc.(*channel).recv(0xc0003c7880)
	/home/pbeza/go/pkg/mod/github.com/containerd/ttrpc@v1.1.2/channel.go:101 +0x4d
github.com/containerd/ttrpc.(*serverConn).run.func1(0xc000845140)
	/home/pbeza/go/pkg/mod/github.com/containerd/ttrpc@v1.1.2/server.go:363 +0x165
created by github.com/containerd/ttrpc.(*serverConn).run
	/home/pbeza/go/pkg/mod/github.com/containerd/ttrpc@v1.1.2/server.go:333 +0x385

goroutine 343 [IO wait]:
internal/poll.runtime_pollWait(0x7f370c671978, 0x72)
	/usr/lib/go-1.17/src/runtime/netpoll.go:303 +0x85
internal/poll.(*pollDesc).wait(0xc000724100, 0xc0006aebb1, 0x0)
	/usr/lib/go-1.17/src/internal/poll/fd_poll_runtime.go:84 +0x32
internal/poll.(*pollDesc).waitRead(...)
	/usr/lib/go-1.17/src/internal/poll/fd_poll_runtime.go:89
internal/poll.(*FD).Read(0xc000724100, {0xc0006aebb1, 0x1, 0x1})
	/usr/lib/go-1.17/src/internal/poll/fd_unix.go:167 +0x25a
net.(*netFD).Read(0xc000724100, {0xc0006aebb1, 0x26ceb70, 0xc000f997d0})
	/usr/lib/go-1.17/src/net/fd_posix.go:56 +0x29
net.(*conn).Read(0xc000126078, {0xc0006aebb1, 0xc000101da0, 0x121eeb8})
	/usr/lib/go-1.17/src/net/net.go:183 +0x45
net/http.(*connReader).backgroundRead(0xc0006aeba0)
	/usr/lib/go-1.17/src/net/http/server.go:672 +0x3f
created by net/http.(*connReader).startBackgroundRead
	/usr/lib/go-1.17/src/net/http/server.go:668 +0xcf

Firecracker Logs

After running firecracker-ctr exec

DEBU[2023-10-30T20:04:19.345505116Z] state                                         exec_id= runtime=aws.firecracker task_id=test1
DEBU[2023-10-30T20:04:19.356212057Z] [  313.814828] agent[773]: time="2023-10-30T20:04:18Z" level=debug msg=state exec_id= name=State task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:04:19.358096967Z] making a new proxy                            exec_id= runtime=aws.firecracker task_id=test1
DEBU[2023-10-30T20:04:19.359098801Z] noop operation returning shim dir for JailPath  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55
DEBU[2023-10-30T20:04:19.359302712Z] skipping proxy io for unset stderr            ExecID= TaskID=test1 runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55
DEBU[2023-10-30T20:04:19.360913572Z] exec                                          exec_id=test1 runtime=aws.firecracker task_id=test1 vmID=dcec917f-be4e-4350-8a15-717faec64f55
DEBU[2023-10-30T20:04:19.360987461Z] noop operation returning shim dir for JailPath  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55
DEBU[2023-10-30T20:04:19.371021371Z] [  313.826470] agent[773]: time="2023-10-30T20:04:18Z" level=debug msg="state succeeded" bundle=/container/test1 exec_id= name=State pid=796 status=RUNNING task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:04:19.372645600Z] event forwarded                               ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-10-30T20:04:19.373053454Z] event forwarded                               ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded
DEBU[2023-10-30T20:04:19.383507783Z] [  313.841353] agent[773]: time="2023-10-30T20:04:18Z" level=debug msg="skipping proxy io for unset stderr" ExecID= TaskID=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:04:19.392762996Z] [  313.851040] agent[773]: time="2023-10-30T20:04:18Z" level=debug msg=exec exec_id=test1 name=Exec task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:04:19.404495174Z] [  313.860533] agent[773]: time="2023-10-30T20:04:18Z" level=debug msg="event published" ns=default topic=/tasks/exec-added type=containerd.events.TaskExecAdded  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:04:19.460932360Z] begin copying io                              ExecID= TaskID=test1 runtime=aws.firecracker stream=stdout vmID=dcec917f-be4e-4350-8a15-717faec64f55
DEBU[2023-10-30T20:04:19.460943460Z] begin copying io                              ExecID= TaskID=test1 runtime=aws.firecracker stream=stdin vmID=dcec917f-be4e-4350-8a15-717faec64f55
DEBU[2023-10-30T20:04:19.471169424Z] [  313.928906] agent[773]: time="2023-10-30T20:04:18Z" level=debug msg="begin copying io" ExecID= TaskID=test1 stream=stdout  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:04:19.471798028Z] begin copying io                              ExecID=test1 TaskID=test1 runtime=aws.firecracker stream=stderr vmID=dcec917f-be4e-4350-8a15-717faec64f55
DEBU[2023-10-30T20:04:19.471837181Z] begin copying io                              ExecID=test1 TaskID=test1 runtime=aws.firecracker stream=stdout vmID=dcec917f-be4e-4350-8a15-717faec64f55
DEBU[2023-10-30T20:04:19.471825710Z] begin copying io                              ExecID=test1 TaskID=test1 runtime=aws.firecracker stream=stdin vmID=dcec917f-be4e-4350-8a15-717faec64f55
DEBU[2023-10-30T20:04:19.471911138Z] copied 4                                      ExecID=test1 TaskID=test1 runtime=aws.firecracker stream=stdin vmID=dcec917f-be4e-4350-8a15-717faec64f55
DEBU[2023-10-30T20:04:19.471957841Z] end copying io                                ExecID=test1 TaskID=test1 runtime=aws.firecracker stream=stdin vmID=dcec917f-be4e-4350-8a15-717faec64f55
DEBU[2023-10-30T20:04:19.481590227Z] [  313.939654] agent[773]: time="2023-10-30T20:04:18Z" level=debug msg="begin copying io" ExecID= TaskID=test1 stream=stdin  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:04:19.484811201Z] state                                         exec_id=test1 runtime=aws.firecracker task_id=test1
DEBU[2023-10-30T20:04:19.484912403Z] state                                         exec_id=test1 runtime=aws.firecracker task_id=test1
DEBU[2023-10-30T20:04:19.486539537Z] task is no longer running                     exec_id=test1 runtime=aws.firecracker task_id=test1
DEBU[2023-10-30T20:04:19.486791920Z] wait                                          exec_id=test1 runtime=aws.firecracker task_id=test1
DEBU[2023-10-30T20:04:19.487545871Z] task is no longer running                     exec_id=test1 runtime=aws.firecracker task_id=test1
DEBU[2023-10-30T20:04:19.487805483Z] start                                         exec_id=test1 runtime=aws.firecracker task_id=test1
DEBU[2023-10-30T20:04:19.502656630Z] [  313.960328] agent[773]: time="2023-10-30T20:04:18Z" level=debug msg="begin copying io" ExecID=test1 TaskID=test1 stream=stderr  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:04:19.525559785Z] [  313.983057] agent[773]: time="2023-10-30T20:04:18Z" level=debug msg="begin copying io" ExecID=test1 TaskID=test1 stream=stdin  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:04:19.548114855Z] [  314.005718] agent[773]: time="2023-10-30T20:04:18Z" level=debug msg="begin copying io" ExecID=test1 TaskID=test1 stream=stdout  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:04:19.569497235Z] [  314.027317] agent[773]: time="2023-10-30T20:04:18Z" level=debug msg="exec succeeded" exec_id=test1 name=Exec task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:04:19.583394634Z] [  314.041206] agent[773]: time="2023-10-30T20:04:18Z" level=debug msg=wait exec_id=test1 name=Wait task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:04:19.587905401Z] event forwarded                               ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-10-30T20:04:19.588167491Z] state                                         exec_id=test1 runtime=aws.firecracker task_id=test1
DEBU[2023-10-30T20:04:19.588177488Z] event forwarded                               ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted
DEBU[2023-10-30T20:04:19.598663650Z] [  314.057123] agent[773]: time="2023-10-30T20:04:18Z" level=debug msg=state exec_id=test1 name=State task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:04:19.599882788Z] proxy is still alive                          exec_id=test1 runtime=aws.firecracker task_id=test1
DEBU[2023-10-30T20:04:19.612144815Z] [  314.067687] agent[773]: time="2023-10-30T20:04:18Z" level=debug msg="state succeeded" bundle=/container/test1 exec_id=test1 name=State pid=0 status=CREATED task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:04:19.621150981Z] [  314.079624] agent[773]: time="2023-10-30T20:04:18Z" level=debug msg=state exec_id=test1 name=State task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:04:19.632982995Z] [  314.088732] agent[773]: time="2023-10-30T20:04:18Z" level=debug msg="state succeeded" bundle=/container/test1 exec_id=test1 name=State pid=0 status=CREATED task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:04:19.642055142Z] [  314.100554] agent[773]: time="2023-10-30T20:04:18Z" level=debug msg=start exec_id=test1 name=Start task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:04:19.650905638Z] [  314.109535] agent[773]: time="2023-10-30T20:04:18Z" level=debug msg=wait exec_id=test1 name=Wait task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:04:19.661145916Z] [  314.118474] agent[773]: time="2023-10-30T20:04:19Z" level=debug msg="start succeeded" exec_id=test1 name=Start pid=819 task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:04:19.672381173Z] [  314.128716] agent[773]: time="2023-10-30T20:04:19Z" level=debug msg="event published" ns=default topic=/tasks/exec-started type=containerd.events.TaskExecStarted  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:04:19.681573184Z] [  314.139846] agent[773]: time="2023-10-30T20:04:19Z" level=debug msg="copied 4" ExecID=test1 TaskID=test1 stream=stdin  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:04:19.690770172Z] [  314.149031] agent[773]: time="2023-10-30T20:04:19Z" level=debug msg="end copying io" ExecID=test1 TaskID=test1 stream=stdin  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:04:19.699996979Z] [  314.158386] agent[773]: time="2023-10-30T20:04:19Z" level=debug msg=state exec_id=test1 name=State task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:04:19.711756083Z] [  314.167465] agent[773]: time="2023-10-30T20:04:19Z" level=debug msg="state succeeded" bundle=/container/test1 exec_id=test1 name=State pid=819 status=RUNNING task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:04:19.719483727Z] [  314.179470] systemd[1]: run-containerd-runc-default-test1-runc.EoeE9O.mount: Succeeded.  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout

After killing the firecracker-ctr exec process

DEBU[2023-10-30T20:07:21.117332515Z] state                                         exec_id=test1 runtime=aws.firecracker task_id=test1
DEBU[2023-10-30T20:07:21.128202220Z] [  495.570355] agent[773]: time="2023-10-30T20:07:20Z" level=debug msg=state exec_id=test1 name=State task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:07:21.130698854Z] proxy is still alive                          exec_id=test1 runtime=aws.firecracker task_id=test1
DEBU[2023-10-30T20:07:21.131090229Z] kill                                          exec_id=test1 runtime=aws.firecracker task_id=test1
DEBU[2023-10-30T20:07:21.133096138Z] event forwarded                               ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-10-30T20:07:21.133409222Z] event forwarded                               ns=default topic=/tasks/exit type=containerd.events.TaskExit
DEBU[2023-10-30T20:07:21.134078472Z] copied 0                                      ExecID=test1 TaskID=test1 runtime=aws.firecracker stream=stderr vmID=dcec917f-be4e-4350-8a15-717faec64f55
DEBU[2023-10-30T20:07:21.134182390Z] end copying io                                ExecID=test1 TaskID=test1 runtime=aws.firecracker stream=stderr vmID=dcec917f-be4e-4350-8a15-717faec64f55
DEBU[2023-10-30T20:07:21.134554915Z] copied 4                                      ExecID=test1 TaskID=test1 runtime=aws.firecracker stream=stdout vmID=dcec917f-be4e-4350-8a15-717faec64f55
DEBU[2023-10-30T20:07:21.134601306Z] end copying io                                ExecID=test1 TaskID=test1 runtime=aws.firecracker stream=stdout vmID=dcec917f-be4e-4350-8a15-717faec64f55
DEBU[2023-10-30T20:07:21.134633655Z] closed proxy                                  ExecID=test1 TaskID=test1 runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55
ERRO[2023-10-30T20:07:21.134701948Z] error closing io stream                       ExecID=test1 TaskID=test1 error="1 error occurred:\n\t* close unix @->firecracker.vsock: use of closed network connection\n\n" runtime=aws.firecracker stream=stdin vmID=dcec917f-be4e-4350-8a15-717faec64f55
INFO[2023-10-30T20:07:21.136001180Z] exited                                        ExecID=test1 TaskID=test1 exit_status=130 exited_at="2023-10-30 20:07:20.56021865 +0000 UTC" runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55
DEBU[2023-10-30T20:07:21.138078976Z] state                                         exec_id=test1 runtime=aws.firecracker task_id=test1
DEBU[2023-10-30T20:07:21.147989935Z] [  495.587042] agent[773]: time="2023-10-30T20:07:20Z" level=debug msg="state succeeded" bundle=/container/test1 exec_id=test1 name=State pid=819 status=RUNNING task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:07:21.149359080Z] task is no longer running                     exec_id=test1 runtime=aws.firecracker task_id=test1
DEBU[2023-10-30T20:07:21.149614671Z] state                                         exec_id=test1 runtime=aws.firecracker task_id=test1
DEBU[2023-10-30T20:07:21.150330928Z] task is no longer running                     exec_id=test1 runtime=aws.firecracker task_id=test1
DEBU[2023-10-30T20:07:21.151173798Z] state                                         exec_id=test1 runtime=aws.firecracker task_id=test1
DEBU[2023-10-30T20:07:21.159190463Z] [  495.601306] agent[773]: time="2023-10-30T20:07:20Z" level=debug msg=kill exec_id=test1 name=Kill task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:07:21.160071533Z] task is no longer running                     exec_id=test1 runtime=aws.firecracker task_id=test1
DEBU[2023-10-30T20:07:21.160307936Z] delete                                        exec_id=test1 runtime=aws.firecracker task_id=test1
DEBU[2023-10-30T20:07:21.169539496Z] [  495.610992] agent[773]: time="2023-10-30T20:07:20Z" level=debug msg="kill succeeded" exec_id=test1 name=Kill task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:07:21.181176890Z] [  495.621624] agent[773]: time="2023-10-30T20:07:20Z" level=debug msg="event published" ns=default topic=/tasks/exit type=containerd.events.TaskExit  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:07:21.191372318Z] [  495.632462] agent[773]: time="2023-10-30T20:07:20Z" level=debug msg="wait succeeded" exec_id=test1 exit_status=130 name=Wait task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:07:21.201695542Z] [  495.642583] agent[773]: time="2023-10-30T20:07:20Z" level=debug msg="wait succeeded" exec_id=test1 exit_status=130 name=Wait task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:07:21.214210378Z] [  495.652964] agent[773]: time="2023-10-30T20:07:20Z" level=info msg=exited ExecID=test1 TaskID=test1 exit_status=130 exited_at="2023-10-30 20:07:20.56021865 +0000 UTC m=+491.736380188"  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:07:21.223603351Z] [  495.665594] agent[773]: time="2023-10-30T20:07:20Z" level=debug msg="copied 0" ExecID=test1 TaskID=test1 stream=stderr  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:07:21.233209512Z] [  495.674814] agent[773]: time="2023-10-30T20:07:20Z" level=debug msg="end copying io" ExecID=test1 TaskID=test1 stream=stderr  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:07:21.242476539Z] [  495.684546] agent[773]: time="2023-10-30T20:07:20Z" level=debug msg="copied 4" ExecID=test1 TaskID=test1 stream=stdout  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:07:21.252097618Z] [  495.693688] agent[773]: time="2023-10-30T20:07:20Z" level=debug msg="end copying io" ExecID=test1 TaskID=test1 stream=stdout  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:07:21.260989820Z] [  495.703328] agent[773]: time="2023-10-30T20:07:20Z" level=debug msg="closed proxy" ExecID=test1 TaskID=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:07:21.270059344Z] [  495.712314] agent[773]: time="2023-10-30T20:07:20Z" level=debug msg=state exec_id=test1 name=State task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:07:21.281969935Z] [  495.721281] agent[773]: time="2023-10-30T20:07:20Z" level=debug msg="state succeeded" bundle=/container/test1 exec_id=test1 name=State pid=819 status=STOPPED task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:07:21.290905421Z] [  495.733167] agent[773]: time="2023-10-30T20:07:20Z" level=debug msg=state exec_id=test1 name=State task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:07:21.302762749Z] [  495.742115] agent[773]: time="2023-10-30T20:07:20Z" level=debug msg="state succeeded" bundle=/container/test1 exec_id=test1 name=State pid=819 status=STOPPED task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:07:21.311762572Z] [  495.753983] agent[773]: time="2023-10-30T20:07:20Z" level=debug msg=state exec_id=test1 name=State task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:07:21.323883572Z] [  495.763115] agent[773]: time="2023-10-30T20:07:20Z" level=debug msg="state succeeded" bundle=/container/test1 exec_id=test1 name=State pid=819 status=STOPPED task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:07:21.333049333Z] [  495.775112] agent[773]: time="2023-10-30T20:07:20Z" level=debug msg=delete exec_id=test1 name=Delete task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout
DEBU[2023-10-30T20:07:21.343799712Z] [  495.784334] agent[773]: time="2023-10-30T20:07:20Z" level=debug msg="delete succeeded" exec_id=test1 exit_status=130 name=Delete pid=819 task_id=test1  jailer=noop runtime=aws.firecracker vmID=dcec917f-be4e-4350-8a15-717faec64f55 vmm_stream=stdout

Steps to reproduce

  1. Follow https://github.com/koyeb/firecracker-containerd-internal/blob/master/docs/quickstart.md to setup machine
sudo firecracker-ctr --address /run/firecracker-containerd/containerd.sock \
     image pull \
     --snapshotter devmapper \
     docker.io/library/debian:latest 

sudo firecracker-ctr --address /run/firecracker-containerd/containerd.sock \
     run \
     --snapshotter devmapper \
     --runtime aws.firecracker \
     --rm --tty --net-host \
     docker.io/library/debian:latest \
     test

echo 123 | sudo firecracker-ctr --address /run/firecracker-containerd/containerd.sock tasks exec --exec-id test test cat
5. Process will echo "123" and hang

Note
I tried to make it as easy to reproduce as possible but in general we're experiencing the same issue on the broader scale internally.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions