Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Race condition / bug in tasks exec #775

Open
pawelbeza opened this issue Oct 30, 2023 · 1 comment
Open

Race condition / bug in tasks exec #775

pawelbeza opened this issue Oct 30, 2023 · 1 comment

Comments

@pawelbeza
Copy link

pawelbeza commented Oct 30, 2023 •
edited
Loading

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/[email protected]/cmd/containerd/command/main.go:279 +0x1395
github.com/urfave/cli.HandleAction({0x2172dc0, 0x2529bc8}, 0xc0000eee00)
	/home/pbeza/go/pkg/mod/github.com/urfave/[email protected]/app.go:523 +0xa8
github.com/urfave/cli.(*App).Run(0xc0000eee00, {0xc000112150, 0x3, 0x3})
	/home/pbeza/go/pkg/mod/github.com/urfave/[email protected]/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/[email protected]/klog.go:1181 +0x6a
created by k8s.io/klog/v2.init.0
	/home/pbeza/go/pkg/mod/k8s.io/klog/[email protected]/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/[email protected]/broadcast.go:117 +0x195
created by github.com/docker/go-events.NewBroadcaster
	/home/pbeza/go/pkg/mod/github.com/docker/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/server.go:432 +0x588
created by github.com/containerd/ttrpc.(*Server).Serve
	/home/pbeza/go/pkg/mod/github.com/containerd/[email protected]/server.go:128 +0x275

goroutine 54 [select, 7 minutes]:
github.com/containerd/ttrpc.(*Client).run(0xc0007e4280)
	/home/pbeza/go/pkg/mod/github.com/containerd/[email protected]/client.go:330 +0x21a
created by github.com/containerd/ttrpc.NewClient
	/home/pbeza/go/pkg/mod/github.com/containerd/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/services/server/server.go:361 +0x165
github.com/containerd/containerd/cmd/containerd/command.serve.func1()
	/home/pbeza/go/pkg/mod/github.com/containerd/[email protected]/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/[email protected]/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/[email protected]/server.go:88 +0x142
github.com/containerd/containerd/services/server.(*Server).ServeTTRPC(0x0, {0x27117a0, 0xc000820390})
	/home/pbeza/go/pkg/mod/github.com/containerd/[email protected]/services/server/server.go:326 +0x3e
github.com/containerd/containerd/cmd/containerd/command.serve.func1()
	/home/pbeza/go/pkg/mod/github.com/containerd/[email protected]/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/[email protected]/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/[email protected]/server.go:786 +0x362
github.com/containerd/containerd/services/server.(*Server).ServeGRPC(0xc00063a0c0, {0x27117a0, 0xc000820450})
	/home/pbeza/go/pkg/mod/github.com/containerd/[email protected]/services/server/server.go:321 +0x6a
github.com/containerd/containerd/cmd/containerd/command.serve.func1()
	/home/pbeza/go/pkg/mod/github.com/containerd/[email protected]/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/[email protected]/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/[email protected]/client.go:163 +0x2cf
github.com/containerd/ttrpc.defaultClientInterceptor({0x2727360, 0xc0006aeb10}, 0x361ea58, 0xc0004aa100, 0xc000e77438, 0x40)
	/home/pbeza/go/pkg/mod/github.com/containerd/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/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/[email protected]/server.go:1286 +0xc8f
google.golang.org/grpc.(*Server).handleStream(0xc0000ee1c0, {0x2754438, 0xc0005e9500}, 0xc0005fb7a0, 0x0)
	/home/pbeza/go/pkg/mod/google.golang.org/[email protected]/server.go:1609 +0xa2a
google.golang.org/grpc.(*Server).serveStreams.func1.2()
	/home/pbeza/go/pkg/mod/google.golang.org/[email protected]/server.go:934 +0x98
created by google.golang.org/grpc.(*Server).serveStreams.func1
	/home/pbeza/go/pkg/mod/google.golang.org/[email protected]/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/[email protected]/writer.go:59 +0xa5
created by github.com/sirupsen/logrus.(*Entry).WriterLevel
	/home/pbeza/go/pkg/mod/github.com/sirupsen/[email protected]/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/[email protected]/internal/transport/controlbuf.go:407 +0x11b
google.golang.org/grpc/internal/transport.(*loopyWriter).run(0xc00058a9c0)
	/home/pbeza/go/pkg/mod/google.golang.org/[email protected]/internal/transport/controlbuf.go:527 +0x85
google.golang.org/grpc/internal/transport.newHTTP2Server.func2()
	/home/pbeza/go/pkg/mod/google.golang.org/[email protected]/internal/transport/http2_server.go:292 +0xc6
created by google.golang.org/grpc/internal/transport.newHTTP2Server
	/home/pbeza/go/pkg/mod/google.golang.org/[email protected]/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/[email protected]/http2/frame.go:237 +0x6e
golang.org/x/net/http2.(*Framer).ReadFrame(0xc00003ee00)
	/home/pbeza/go/pkg/mod/golang.org/x/[email protected]/http2/frame.go:498 +0x95
google.golang.org/grpc/internal/transport.(*http2Server).HandleStreams(0xc0005e9500, 0xc000f97710, 0xc000f977d0)
	/home/pbeza/go/pkg/mod/google.golang.org/[email protected]/internal/transport/http2_server.go:473 +0xb2
google.golang.org/grpc.(*Server).serveStreams(0xc0000ee1c0, {0x2754438, 0xc0005e9500})
	/home/pbeza/go/pkg/mod/google.golang.org/[email protected]/server.go:918 +0x142
google.golang.org/grpc.(*Server).handleRawConn.func1()
	/home/pbeza/go/pkg/mod/google.golang.org/[email protected]/server.go:868 +0x46
created by google.golang.org/grpc.(*Server).handleRawConn
	/home/pbeza/go/pkg/mod/google.golang.org/[email protected]/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/[email protected]/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/[email protected]/runtime/v2/binary.go:108 +0xdf
created by github.com/containerd/containerd/runtime/v2.(*binary).Start
	/home/pbeza/go/pkg/mod/github.com/containerd/[email protected]/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/[email protected]/internal/transport/http2_server.go:993 +0x245
created by google.golang.org/grpc/internal/transport.newHTTP2Server
	/home/pbeza/go/pkg/mod/google.golang.org/[email protected]/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/[email protected]/channel.go:53 +0x55
github.com/containerd/ttrpc.(*channel).recv(0xc0001b8180)
	/home/pbeza/go/pkg/mod/github.com/containerd/[email protected]/channel.go:101 +0x4d
github.com/containerd/ttrpc.(*Client).run.func2()
	/home/pbeza/go/pkg/mod/github.com/containerd/[email protected]/client.go:294 +0xc6
created by github.com/containerd/ttrpc.(*Client).run
	/home/pbeza/go/pkg/mod/github.com/containerd/[email protected]/client.go:286 +0x185

goroutine 55 [select, 3 minutes]:
github.com/containerd/ttrpc.(*Client).run.func1()
	/home/pbeza/go/pkg/mod/github.com/containerd/[email protected]/client.go:265 +0xbe
created by github.com/containerd/ttrpc.(*Client).run
	/home/pbeza/go/pkg/mod/github.com/containerd/[email protected]/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/[email protected]/channel.go:53 +0x55
github.com/containerd/ttrpc.(*channel).recv(0xc0003c7880)
	/home/pbeza/go/pkg/mod/github.com/containerd/[email protected]/channel.go:101 +0x4d
github.com/containerd/ttrpc.(*serverConn).run.func1(0xc000845140)
	/home/pbeza/go/pkg/mod/github.com/containerd/[email protected]/server.go:363 +0x165
created by github.com/containerd/ttrpc.(*serverConn).run
	/home/pbeza/go/pkg/mod/github.com/containerd/[email protected]/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.
@Simezekiel097
Copy link

I need a Guardian

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@pawelbeza @Simezekiel097