search

google / gvisor

Application Kernel for Containers
https://gvisor.dev
Apache License 2.0
15.85k stars 1.3k forks source link

ReactJS app hangs running with gVisor #121

Closed balopat closed 5 years ago

balopat commented 5 years ago

Same setup as in https://github.com/google/gvisor/issues/120 except this is a larger nodejs app, instead of nginx running in minikube + gvisor + containerd.

My pod is stuck "Terminating" 

NAMESPACE     NAME                                    READY     STATUS        RESTARTS   AGE
default       frontend-c9995db95-zgc44                1/1       Terminating   0          26m

kubelet logs: 

Dec 13 03:54:23 minikube kubelet[17178]: E1213 03:54:23.513392   17178 remote_runtime.go:229] StopContainer "0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0" from runtime service failed: rpc error: code = DeadlineExceeded desc = context deadline exceeded
Dec 13 03:54:23 minikube kubelet[17178]: E1213 03:54:23.514415   17178 kuberuntime_container.go:569] Container "containerd://0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0" termination failed with gracePeriod 30: rpc error: code = DeadlineExceeded desc = context deadline exceeded

containerd logs:

Dec 13 03:39:23 minikube containerd[19747]: time="2018-12-13T03:39:23.553166012Z" level=error msg="Stop container "0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0" timed out" error="wait container "0f
0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0" stop timeout"

the runsc process is still up and running:

ps ax | grep 0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0
 7090 ?        Sl     0:00 /usr/local/bin/runsc --root=/run/containerd/runsc/k8s.io --log=/run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0/log.json --log-format=json kill --all 0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0 9
25299 ?        Sl     0:00 gvisor-containerd-shim -namespace k8s.io -workdir /mnt/vda1/var/lib/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0 -address /run/containerd/containerd.sock -containerd-binary /usr/bin/containerd -runtime-root /run/containerd/runsc -debug
25326 ?        Sl     0:06 /usr/local/bin/runsc --root=/run/containerd/runsc/k8s.io --debug=false --log=/run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0/log.json --log-format=json --debug-log= --debug-log-format=text --file-access=exclusive --overlay=false --network=sandbox --log-packets=false --platform=ptrace --strace=false --strace-syscalls= --strace-log-size=1024 --watchdog-action=LogWarning --panic-signal=-1 gofer --bundle /run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0 --io-fds=3 --io-fds=4 --io-fds=5 --io-fds=6 --io-fds=7 --apply-caps=false

crictl inspect pod hangs too: 

crictl --runtime-endpoint unix:///run/containerd/containerd.sock inspectp 390c6c61b2f09
^C

if I kill the processes manually, the pod goes away (inside minikube):

ps ax | grep 0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0 | awk '{print $1 }' | sudo kill

the json logs don't contain anything interesting:

$ cat /run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0/log.json
{"msg":"***************************","level":"info","time":"2018-12-13T03:20:14.022981162Z"}
{"msg":"Args: [/usr/local/bin/runsc --root=/run/containerd/runsc/k8s.io --log=/run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0/log.json --log-format=json create --bundle /run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0 --pid-file /run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0/init.pid 0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0]","level":"info","time":"2018-12-13T03:20:14.023045957Z"}
{"msg":"Git Revision: 90e81b2e5c665b9fc149f97dcf15142c190260c6","level":"info","time":"2018-12-13T03:20:14.023062543Z"}
{"msg":"PID: 25308","level":"info","time":"2018-12-13T03:20:14.023068068Z"}
{"msg":"UID: 0, GID: 0","level":"info","time":"2018-12-13T03:20:14.023073766Z"}
{"msg":"Configuration:","level":"info","time":"2018-12-13T03:20:14.023077879Z"}
{"msg":"\t\tRootDir: /run/containerd/runsc/k8s.io","level":"info","time":"2018-12-13T03:20:14.023081821Z"}
{"msg":"\t\tPlatform: ptrace","level":"info","time":"2018-12-13T03:20:14.023085991Z"}
{"msg":"\t\tFileAccess: exclusive, overlay: false","level":"info","time":"2018-12-13T03:20:14.02309201Z"}
{"msg":"\t\tNetwork: sandbox, logging: false","level":"info","time":"2018-12-13T03:20:14.023097712Z"}
{"msg":"\t\tStrace: false, max size: 1024, syscalls: []","level":"info","time":"2018-12-13T03:20:14.023103762Z"}
{"msg":"***************************","level":"info","time":"2018-12-13T03:20:14.023108503Z"}
{"msg":"Exiting with status: 0","level":"info","time":"2018-12-13T03:20:14.025292596Z"}
{"msg":"***************************","level":"info","time":"2018-12-13T03:20:14.034959403Z"}
{"msg":"Args: [/usr/local/bin/runsc --root=/run/containerd/runsc/k8s.io --log=/run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0/log.json --log-format=json state 0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0]","level":"info","time":"2018-12-13T03:20:14.035027877Z"}
{"msg":"Git Revision: 90e81b2e5c665b9fc149f97dcf15142c190260c6","level":"info","time":"2018-12-13T03:20:14.035046676Z"}
{"msg":"PID: 25312","level":"info","time":"2018-12-13T03:20:14.035052114Z"}
{"msg":"UID: 0, GID: 0","level":"info","time":"2018-12-13T03:20:14.035057936Z"}
{"msg":"Configuration:","level":"info","time":"2018-12-13T03:20:14.035062094Z"}
{"msg":"\t\tRootDir: /run/containerd/runsc/k8s.io","level":"info","time":"2018-12-13T03:20:14.035066147Z"}
{"msg":"\t\tPlatform: ptrace","level":"info","time":"2018-12-13T03:20:14.035070435Z"}
{"msg":"\t\tFileAccess: exclusive, overlay: false","level":"info","time":"2018-12-13T03:20:14.035076728Z"}
{"msg":"\t\tNetwork: sandbox, logging: false","level":"info","time":"2018-12-13T03:20:14.035082655Z"}
{"msg":"\t\tStrace: false, max size: 1024, syscalls: []","level":"info","time":"2018-12-13T03:20:14.035088586Z"}
{"msg":"***************************","level":"info","time":"2018-12-13T03:20:14.03509348Z"}
{"msg":"Exiting with status: 0","level":"info","time":"2018-12-13T03:20:14.035737999Z"}
{"msg":"***************************","level":"info","time":"2018-12-13T03:20:14.040074261Z"}
{"msg":"Args: [/usr/local/bin/runsc --root=/run/containerd/runsc/k8s.io --log=/run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0/log.json --log-format=json start 0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0]","level":"info","time":"2018-12-13T03:20:14.040135511Z"}
{"msg":"Git Revision: 90e81b2e5c665b9fc149f97dcf15142c190260c6","level":"info","time":"2018-12-13T03:20:14.040151284Z"}
{"msg":"PID: 25317","level":"info","time":"2018-12-13T03:20:14.04015687Z"}
{"msg":"UID: 0, GID: 0","level":"info","time":"2018-12-13T03:20:14.040162572Z"}
{"msg":"Configuration:","level":"info","time":"2018-12-13T03:20:14.04016671Z"}
{"msg":"\t\tRootDir: /run/containerd/runsc/k8s.io","level":"info","time":"2018-12-13T03:20:14.04017078Z"}
{"msg":"\t\tPlatform: ptrace","level":"info","time":"2018-12-13T03:20:14.040178875Z"}
{"msg":"\t\tFileAccess: exclusive, overlay: false","level":"info","time":"2018-12-13T03:20:14.040184991Z"}
{"msg":"\t\tNetwork: sandbox, logging: false","level":"info","time":"2018-12-13T03:20:14.04019062Z"}
{"msg":"\t\tStrace: false, max size: 1024, syscalls: []","level":"info","time":"2018-12-13T03:20:14.040196297Z"}
{"msg":"***************************","level":"info","time":"2018-12-13T03:20:14.040200902Z"}
{"msg":"Mounting src: \"/mnt/vda1/var/lib/containerd/io.containerd.grpc.v1.cri/sandboxes/30e7f963992cf1b124483cd4fe39c339aa9a2de9e810b9a8764424ac1afae21a/resolv.conf\", dst: \"/run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0/rootfs/etc/resolv.conf\", flags: 0x45001","level":"info","time":"2018-12-13T03:20:14.044370518Z"}
{"msg":"Ignoring mount option \"rslave\"","level":"warning","time":"2018-12-13T03:20:14.050113267Z"}
{"msg":"Mounting src: \"/var/lib/kubelet/pods/f376413d-fe85-11e8-b7d4-36c8b3fdbcd9/volumes/kubernetes.io~secret/default-token-n6w76\", dst: \"/run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0/rootfs/run/secrets/kubernetes.io/serviceaccount\", flags: 0x5001","level":"info","time":"2018-12-13T03:20:14.05014831Z"}
{"msg":"Mounting src: \"/var/lib/kubelet/pods/f376413d-fe85-11e8-b7d4-36c8b3fdbcd9/etc-hosts\", dst: \"/run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0/rootfs/etc/hosts\", flags: 0x45001","level":"info","time":"2018-12-13T03:20:14.051074819Z"}
{"msg":"Mounting src: \"/var/lib/kubelet/pods/f376413d-fe85-11e8-b7d4-36c8b3fdbcd9/containers/frontend/e74ede4a\", dst: \"/run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0/rootfs/dev/termination-log\", flags: 0x45001","level":"info","time":"2018-12-13T03:20:14.051999643Z"}
{"msg":"Gofer started, PID: 25326","level":"info","time":"2018-12-13T03:20:14.190710008Z"}
{"msg":"***************************","level":"info","time":"2018-12-13T03:20:14.195785357Z"}
{"msg":"Args: [/usr/local/bin/runsc --root=/run/containerd/runsc/k8s.io --debug=false --log=/run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0/log.json --log-format=json --debug-log= --debug-log-format=text --file-access=exclusive --overlay=false --network=sandbox --log-packets=false --platform=ptrace --strace=false --strace-syscalls= --strace-log-size=1024 --watchdog-action=LogWarning --panic-signal=-1 gofer --bundle /run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0 --io-fds=3 --io-fds=4 --io-fds=5 --io-fds=6 --io-fds=7]","level":"info","time":"2018-12-13T03:20:14.195857729Z"}
{"msg":"Git Revision: 90e81b2e5c665b9fc149f97dcf15142c190260c6","level":"info","time":"2018-12-13T03:20:14.195881764Z"}
{"msg":"PID: 1","level":"info","time":"2018-12-13T03:20:14.195887524Z"}
{"msg":"UID: 0, GID: 0","level":"info","time":"2018-12-13T03:20:14.195893186Z"}
{"msg":"Configuration:","level":"info","time":"2018-12-13T03:20:14.195897394Z"}
{"msg":"\t\tRootDir: /run/containerd/runsc/k8s.io","level":"info","time":"2018-12-13T03:20:14.195901475Z"}
{"msg":"\t\tPlatform: ptrace","level":"info","time":"2018-12-13T03:20:14.195907954Z"}
{"msg":"\t\tFileAccess: exclusive, overlay: false","level":"info","time":"2018-12-13T03:20:14.195923008Z"}
{"msg":"\t\tNetwork: sandbox, logging: false","level":"info","time":"2018-12-13T03:20:14.195929203Z"}
{"msg":"\t\tStrace: false, max size: 1024, syscalls: []","level":"info","time":"2018-12-13T03:20:14.19593512Z"}
{"msg":"***************************","level":"info","time":"2018-12-13T03:20:14.195939975Z"}
{"msg":"Capabilities applied: { effective=\"chown, dac_override, dac_read_search, fowner, fsetid, sys_chroot\" permitted=\"chown, dac_override, dac_read_search, fowner, fsetid, sys_chroot\" inheritable=\"empty\" bounding=\"chown, dac_override, dac_read_search, fowner, fsetid, sys_chroot\" }","level":"info","time":"2018-12-13T03:20:14.196093369Z"}
{"msg":"Execve \"/usr/local/bin/runsc\" again, bye!","level":"info","time":"2018-12-13T03:20:14.196194485Z"}
{"msg":"***************************","level":"info","time":"2018-12-13T03:20:14.199854662Z"}
{"msg":"Args: [/usr/local/bin/runsc --root=/run/containerd/runsc/k8s.io --debug=false --log=/run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0/log.json --log-format=json --debug-log= --debug-log-format=text --file-access=exclusive --overlay=false --network=sandbox --log-packets=false --platform=ptrace --strace=false --strace-syscalls= --strace-log-size=1024 --watchdog-action=LogWarning --panic-signal=-1 gofer --bundle /run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0 --io-fds=3 --io-fds=4 --io-fds=5 --io-fds=6 --io-fds=7 --apply-caps=false]","level":"info","time":"2018-12-13T03:20:14.199945Z"}
{"msg":"Git Revision: 90e81b2e5c665b9fc149f97dcf15142c190260c6","level":"info","time":"2018-12-13T03:20:14.199967856Z"}
{"msg":"PID: 1","level":"info","time":"2018-12-13T03:20:14.199973919Z"}
{"msg":"UID: 0, GID: 0","level":"info","time":"2018-12-13T03:20:14.19998264Z"}
{"msg":"Configuration:","level":"info","time":"2018-12-13T03:20:14.199987964Z"}
{"msg":"\t\tRootDir: /run/containerd/runsc/k8s.io","level":"info","time":"2018-12-13T03:20:14.199992081Z"}
{"msg":"\t\tPlatform: ptrace","level":"info","time":"2018-12-13T03:20:14.199998957Z"}
{"msg":"\t\tFileAccess: exclusive, overlay: false","level":"info","time":"2018-12-13T03:20:14.200005443Z"}
{"msg":"\t\tNetwork: sandbox, logging: false","level":"info","time":"2018-12-13T03:20:14.200011504Z"}
{"msg":"\t\tStrace: false, max size: 1024, syscalls: []","level":"info","time":"2018-12-13T03:20:14.200022541Z"}
{"msg":"***************************","level":"info","time":"2018-12-13T03:20:14.200027327Z"}
{"msg":"Process chroot'd to \"/run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0/rootfs\"","level":"info","time":"2018-12-13T03:20:14.2004612Z"}
{"msg":"Serving \"/\" mapped to \"/run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0/rootfs\" on FD 3 (ro: false)","level":"info","time":"2018-12-13T03:20:14.200479026Z"}
{"msg":"Serving \"/etc/resolv.conf\" mapped on FD 4 (ro: false)","level":"info","time":"2018-12-13T03:20:14.200505289Z"}
{"msg":"Serving \"/run/secrets/kubernetes.io/serviceaccount\" mapped on FD 5 (ro: true)","level":"info","time":"2018-12-13T03:20:14.200512772Z"}
{"msg":"Serving \"/etc/hosts\" mapped on FD 6 (ro: false)","level":"info","time":"2018-12-13T03:20:14.200518766Z"}
{"msg":"Serving \"/dev/termination-log\" mapped on FD 7 (ro: false)","level":"info","time":"2018-12-13T03:20:14.200524005Z"}
{"msg":"Installing seccomp filters for 52 syscalls (kill=false)","level":"info","time":"2018-12-13T03:20:14.200531536Z"}
{"msg":"Seccomp filters installed.","level":"info","time":"2018-12-13T03:20:14.201149535Z"}
{"msg":"Exiting with status: 0","level":"info","time":"2018-12-13T03:20:14.243086826Z"}
{"msg":"***************************","level":"info","time":"2018-12-13T03:20:14.248629883Z"}
{"msg":"Args: [/usr/local/bin/runsc --root=/run/containerd/runsc/k8s.io --log=/run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0/log.json --log-format=json state 0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0]","level":"info","time":"2018-12-13T03:20:14.248694217Z"}
{"msg":"Git Revision: 90e81b2e5c665b9fc149f97dcf15142c190260c6","level":"info","time":"2018-12-13T03:20:14.248712746Z"}
{"msg":"PID: 25342","level":"info","time":"2018-12-13T03:20:14.248718248Z"}
{"msg":"UID: 0, GID: 0","level":"info","time":"2018-12-13T03:20:14.24872417Z"}
{"msg":"Configuration:","level":"info","time":"2018-12-13T03:20:14.248732934Z"}
{"msg":"\t\tRootDir: /run/containerd/runsc/k8s.io","level":"info","time":"2018-12-13T03:20:14.248737399Z"}
{"msg":"\t\tPlatform: ptrace","level":"info","time":"2018-12-13T03:20:14.248744176Z"}
{"msg":"\t\tFileAccess: exclusive, overlay: false","level":"info","time":"2018-12-13T03:20:14.248757884Z"}
{"msg":"\t\tNetwork: sandbox, logging: false","level":"info","time":"2018-12-13T03:20:14.248766275Z"}
{"msg":"\t\tStrace: false, max size: 1024, syscalls: []","level":"info","time":"2018-12-13T03:20:14.248772321Z"}
{"msg":"***************************","level":"info","time":"2018-12-13T03:20:14.2487772Z"}
{"msg":"***************************","level":"info","time":"2018-12-13T03:20:14.248770916Z"}
{"msg":"Args: [/usr/local/bin/runsc --root=/run/containerd/runsc/k8s.io --log=/run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0/log.json --log-format=json wait 0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0]","level":"info","time":"2018-12-13T03:20:14.248816752Z"}
{"msg":"Git Revision: 90e81b2e5c665b9fc149f97dcf15142c190260c6","level":"info","time":"2018-12-13T03:20:14.24888784Z"}
{"msg":"PID: 25340","level":"info","time":"2018-12-13T03:20:14.248893595Z"}
{"msg":"UID: 0, GID: 0","level":"info","time":"2018-12-13T03:20:14.248899374Z"}
{"msg":"Configuration:","level":"info","time":"2018-12-13T03:20:14.248903641Z"}
{"msg":"\t\tRootDir: /run/containerd/runsc/k8s.io","level":"info","time":"2018-12-13T03:20:14.248907681Z"}
{"msg":"\t\tPlatform: ptrace","level":"info","time":"2018-12-13T03:20:14.248912083Z"}
{"msg":"\t\tFileAccess: exclusive, overlay: false","level":"info","time":"2018-12-13T03:20:14.24891807Z"}
{"msg":"\t\tNetwork: sandbox, logging: false","level":"info","time":"2018-12-13T03:20:14.248923969Z"}
{"msg":"\t\tStrace: false, max size: 1024, syscalls: []","level":"info","time":"2018-12-13T03:20:14.24892959Z"}
{"msg":"***************************","level":"info","time":"2018-12-13T03:20:14.248934446Z"}
{"msg":"Exiting with status: 0","level":"info","time":"2018-12-13T03:20:14.250457398Z"}
{"msg":"***************************","level":"info","time":"2018-12-13T03:38:53.510944696Z"}
{"msg":"Args: [/usr/local/bin/runsc --root=/run/containerd/runsc/k8s.io --log=/run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0/log.json --log-format=json state 0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0]","level":"info","time":"2018-12-13T03:38:53.511024832Z"}
{"msg":"Git Revision: 90e81b2e5c665b9fc149f97dcf15142c190260c6","level":"info","time":"2018-12-13T03:38:53.511046461Z"}
{"msg":"PID: 7066","level":"info","time":"2018-12-13T03:38:53.511053021Z"}
{"msg":"UID: 0, GID: 0","level":"info","time":"2018-12-13T03:38:53.511059683Z"}
{"msg":"Configuration:","level":"info","time":"2018-12-13T03:38:53.511064705Z"}
{"msg":"\t\tRootDir: /run/containerd/runsc/k8s.io","level":"info","time":"2018-12-13T03:38:53.511069469Z"}
{"msg":"\t\tPlatform: ptrace","level":"info","time":"2018-12-13T03:38:53.511074493Z"}
{"msg":"\t\tFileAccess: exclusive, overlay: false","level":"info","time":"2018-12-13T03:38:53.511081565Z"}
{"msg":"\t\tNetwork: sandbox, logging: false","level":"info","time":"2018-12-13T03:38:53.511088183Z"}
{"msg":"\t\tStrace: false, max size: 1024, syscalls: []","level":"info","time":"2018-12-13T03:38:53.511094484Z"}
{"msg":"***************************","level":"info","time":"2018-12-13T03:38:53.511100035Z"}
{"msg":"Exiting with status: 0","level":"info","time":"2018-12-13T03:38:53.515003741Z"}
{"msg":"***************************","level":"info","time":"2018-12-13T03:38:53.52712763Z"}
{"msg":"Args: [/usr/local/bin/runsc --root=/run/containerd/runsc/k8s.io --log=/run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0/log.json --log-format=json state 0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0]","level":"info","time":"2018-12-13T03:38:53.527197098Z"}
{"msg":"Git Revision: 90e81b2e5c665b9fc149f97dcf15142c190260c6","level":"info","time":"2018-12-13T03:38:53.527218555Z"}
{"msg":"PID: 7071","level":"info","time":"2018-12-13T03:38:53.527225029Z"}
{"msg":"UID: 0, GID: 0","level":"info","time":"2018-12-13T03:38:53.527231572Z"}
{"msg":"Configuration:","level":"info","time":"2018-12-13T03:38:53.527236331Z"}
{"msg":"\t\tRootDir: /run/containerd/runsc/k8s.io","level":"info","time":"2018-12-13T03:38:53.52724099Z"}
{"msg":"\t\tPlatform: ptrace","level":"info","time":"2018-12-13T03:38:53.527246012Z"}
{"msg":"\t\tFileAccess: exclusive, overlay: false","level":"info","time":"2018-12-13T03:38:53.527252962Z"}
{"msg":"\t\tNetwork: sandbox, logging: false","level":"info","time":"2018-12-13T03:38:53.527259331Z"}
{"msg":"\t\tStrace: false, max size: 1024, syscalls: []","level":"info","time":"2018-12-13T03:38:53.527266007Z"}
{"msg":"***************************","level":"info","time":"2018-12-13T03:38:53.527271375Z"}
{"msg":"Exiting with status: 0","level":"info","time":"2018-12-13T03:38:53.54010829Z"}
{"msg":"***************************","level":"info","time":"2018-12-13T03:38:53.548179521Z"}
{"msg":"Args: [/usr/local/bin/runsc --root=/run/containerd/runsc/k8s.io --log=/run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0/log.json --log-format=json kill 0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0 15]","level":"info","time":"2018-12-13T03:38:53.54824929Z"}
{"msg":"Git Revision: 90e81b2e5c665b9fc149f97dcf15142c190260c6","level":"info","time":"2018-12-13T03:38:53.548284947Z"}
{"msg":"PID: 7079","level":"info","time":"2018-12-13T03:38:53.548293973Z"}
{"msg":"UID: 0, GID: 0","level":"info","time":"2018-12-13T03:38:53.548300827Z"}
{"msg":"Configuration:","level":"info","time":"2018-12-13T03:38:53.54830557Z"}
{"msg":"\t\tRootDir: /run/containerd/runsc/k8s.io","level":"info","time":"2018-12-13T03:38:53.548310333Z"}
{"msg":"\t\tPlatform: ptrace","level":"info","time":"2018-12-13T03:38:53.548315363Z"}
{"msg":"\t\tFileAccess: exclusive, overlay: false","level":"info","time":"2018-12-13T03:38:53.548389116Z"}
{"msg":"\t\tNetwork: sandbox, logging: false","level":"info","time":"2018-12-13T03:38:53.548396826Z"}
{"msg":"\t\tStrace: false, max size: 1024, syscalls: []","level":"info","time":"2018-12-13T03:38:53.548403767Z"}
{"msg":"***************************","level":"info","time":"2018-12-13T03:38:53.548422414Z"}
{"msg":"Exiting with status: 0","level":"info","time":"2018-12-13T03:38:53.551971224Z"}
{"msg":"Exiting with status: 0","level":"info","time":"2018-12-13T03:38:53.572114424Z"}
{"msg":"***************************","level":"info","time":"2018-12-13T03:38:53.577898657Z"}
{"msg":"Args: [/usr/local/bin/runsc --root=/run/containerd/runsc/k8s.io --log=/run/containerd/io.containerd.runtime.v1.linux/k8s.io/0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0/log.json --log-format=json kill --all 0f0a5c6d95efce5da17c6102a448e269b7cc775e43819e6eb0b4a3be95f202b0 9]","level":"info","time":"2018-12-13T03:38:53.577967961Z"}
{"msg":"Git Revision: 90e81b2e5c665b9fc149f97dcf15142c190260c6","level":"info","time":"2018-12-13T03:38:53.578019916Z"}
{"msg":"PID: 7090","level":"info","time":"2018-12-13T03:38:53.578026773Z"}
{"msg":"UID: 0, GID: 0","level":"info","time":"2018-12-13T03:38:53.578033344Z"}
{"msg":"Configuration:","level":"info","time":"2018-12-13T03:38:53.578038037Z"}
{"msg":"\t\tRootDir: /run/containerd/runsc/k8s.io","level":"info","time":"2018-12-13T03:38:53.578042646Z"}
{"msg":"\t\tPlatform: ptrace","level":"info","time":"2018-12-13T03:38:53.578047519Z"}
{"msg":"\t\tFileAccess: exclusive, overlay: false","level":"info","time":"2018-12-13T03:38:53.578054661Z"}
{"msg":"\t\tNetwork: sandbox, logging: false","level":"info","time":"2018-12-13T03:38:53.578070584Z"}
{"msg":"\t\tStrace: false, max size: 1024, syscalls: []","level":"info","time":"2018-12-13T03:38:53.578082162Z"}
{"msg":"***************************","level":"info","time":"2018-12-13T03:38:53.578088247Z"}
balopat commented 5 years ago

The sample project that I'm deploying is here: https://github.com/balopat/contribwall This has two services 1.) a go based one - that happily runs in runsc, and 2.) a reactjs frontend - that seems to have issues when ran in runsc - for example even though the app comes up and reports that it's listening on port 3000 - it can't accept connections for some reason, even from within the container curl localhost:3000 doesn't work. Maybe there is an unhandled syscall in the reactjs stack somewhere?

fvoznika commented 5 years ago

There are a few problems with inotify that this code is hitting:

  1. inotify is over reporting changes to directories, e.g. notify access to watchers that care about modify only. This causes the application to be constantly compiling changes.
  2. There is a deadlock in inotify code when epoll is watching directories and those directories are accessed. First stack is waiting on epoll, while the second one is reading directory contents. They take locks in opposite order and deadlock: 
    
goroutine 106 [semacquire, 3 minutes]:
sync.runtime_SemacquireMutex(0xc0001b000c, 0xc0007da900)
third_party/go/gc/src/runtime/sema.go:71 +0x3d
sync.(*Mutex).Lock(0xc0001b0008)
third_party/go/gc/src/sync/mutex.go:134 +0xff
google3/third_party/golang/gvisor/pkg/sentry/fs/fs.(*Inotify).Readiness(0xc0001b0000, 0x400019, 0xc000a90000)
third_party/golang/gvisor/pkg/sentry/fs/inotify.go:106 +0x41
google3/third_party/golang/gvisor/pkg/sentry/fs/fs.(*File).Readiness(0xc0005d8f30, 0x19, 0x0)
third_party/golang/gvisor/pkg/sentry/fs/file.go:180 +0x3e
google3/third_party/golang/gvisor/pkg/sentry/kernel/epoll/epoll.(*EventPoll).ReadEvents(0xc00076adc0, 0x400, 0xc0006cb050, 0x0, 0x7fc3bafe0780)
third_party/golang/gvisor/pkg/sentry/kernel/epoll/epoll.go:241 +0x14a
google3/third_party/golang/gvisor/pkg/sentry/syscalls/syscalls.WaitEpoll(0xc00070aa80, 0x3, 0x400, 0x2f, 0x0, 0x0, 0x0, 0x0, 0x0)
third_party/golang/gvisor/pkg/sentry/syscalls/epoll.go:139 +0xce
google3/third_party/golang/gvisor/pkg/sentry/syscalls/linux/linux.EpollWait(0xc00070aa80, 0x3, 0x7fc3bafdd750, 0x400, 0x2f, 0x0, 0x7fc3bafe0780, 0x0, 0x7fc3bafe0780, 0xc000000003, ...)
third_party/golang/gvisor/pkg/sentry/syscalls/linux/sys_epoll.go:140 +0x68
google3/third_party/golang/gvisor/pkg/sentry/kernel/kernel.(*Task).executeSyscall(0xc00070aa80, 0xe8, 0x3, 0x7fc3bafdd750, 0x400, 0x2f, 0x0, 0x7fc3bafe0780, 0x0, 0xc3ae00, ...)
third_party/golang/gvisor/pkg/sentry/kernel/task_syscall.go:165 +0x30a
google3/third_party/golang/gvisor/pkg/sentry/kernel/kernel.(*Task).doSyscallInvoke(0xc00070aa80, 0xe8, 0x3, 0x7fc3bafdd750, 0x400, 0x2f, 0x0, 0x7fc3bafe0780, 0x0, 0x7fc3bafe0780)
third_party/golang/gvisor/pkg/sentry/kernel/task_syscall.go:283 +0x69
google3/third_party/golang/gvisor/pkg/sentry/kernel/kernel.(*Task).doSyscallEnter(0xc00070aa80, 0xe8, 0x3, 0x7fc3bafdd750, 0x400, 0x2f, 0x0, 0x7fc3bafe0780, 0xd1ee60, 0xc00060fe58)
third_party/golang/gvisor/pkg/sentry/kernel/task_syscall.go:244 +0x99
google3/third_party/golang/gvisor/pkg/sentry/kernel/kernel.(*Task).doSyscall(0xc00070aa80, 0x2, 0xc00057c000)
third_party/golang/gvisor/pkg/sentry/kernel/task_syscall.go:219 +0x142
google3/third_party/golang/gvisor/pkg/sentry/kernel/kernel.(*runApp).execute(0x0, 0xc00070aa80, 0xd1ee60, 0x0)
third_party/golang/gvisor/pkg/sentry/kernel/task_run.go:215 +0xfda
google3/third_party/golang/gvisor/pkg/sentry/kernel/kernel.(*Task).run(0xc00070aa80, 0x12)
third_party/golang/gvisor/pkg/sentry/kernel/task_run.go:91 +0x149
created by google3/third_party/golang/gvisor/pkg/sentry/kernel/kernel.(*Task).Start
third_party/golang/gvisor/pkg/sentry/kernel/task_start.go:279 +0xfe

goroutine 3085 [semacquire, 3 minutes]: sync.runtime_SemacquireMutex(0xc00076ae0c, 0x408900) third_party/go/gc/src/runtime/sema.go:71 +0x3d sync.(Mutex).Lock(0xc00076ae08) third_party/go/gc/src/sync/mutex.go:134 +0xff google3/third_party/golang/gvisor/pkg/sentry/kernel/epoll/epoll.(readyCallback).Callback(0x136da70, 0xc000549220) third_party/golang/gvisor/pkg/sentry/kernel/epoll/epoll.go:290 +0x62 google3/third_party/golang/netstack/waiter/waiter.(Queue).Notify(0xc0001b0010, 0xd20001) third_party/golang/netstack/waiter/waiter.go:192 +0xa1 google3/third_party/golang/gvisor/pkg/sentry/fs/fs.(Inotify).queueEvent(0xc0001b0000, 0xc0004e6550) third_party/golang/gvisor/pkg/sentry/fs/inotify.go:229 +0xeb google3/third_party/golang/gvisor/pkg/sentry/fs/fs.(Watch).Notify(0xc000b173e0, 0x0, 0x0, 0x40000001) third_party/golang/gvisor/pkg/sentry/fs/inotify_watch.go:88 +0x8b google3/third_party/golang/gvisor/pkg/sentry/fs/fs.(Watches).Notify(0xc000480ff0, 0x0, 0x0, 0x40000001) third_party/golang/gvisor/pkg/sentry/fs/inode_inotify.go:131 +0x104 google3/third_party/golang/gvisor/pkg/sentry/fs/fs.(Dirent).InotifyEvent(0xc000d1f200, 0x40000001) third_party/golang/gvisor/pkg/sentry/fs/dirent.go:1358 +0xaf google3/third_party/golang/gvisor/pkg/sentry/syscalls/linux/linux.getdents(0xc000902000, 0xc00000000e, 0x7fc1100008f0, 0x8000, 0xc66df0, 0x0, 0x0, 0x0) third_party/golang/gvisor/pkg/sentry/syscalls/linux/sys_getdents.go:86 +0x2e0 google3/third_party/golang/gvisor/pkg/sentry/syscalls/linux/linux.Getdents(0xc000902000, 0xe, 0x7fc1100008f0, 0x8000, 0x0, 0x3, 0x7fc110000070, 0x3, 0x7fc110000070, 0xc000000003, ...) third_party/golang/gvisor/pkg/sentry/syscalls/linux/sys_getdents.go:43 +0xe3 google3/third_party/golang/gvisor/pkg/sentry/kernel/kernel.(Task).executeSyscall(0xc000902000, 0x4e, 0xe, 0x7fc1100008f0, 0x8000, 0x0, 0x3, 0x7fc110000070, 0xe, 0xc3ae00, ...) third_party/golang/gvisor/pkg/sentry/kernel/task_syscall.go:165 +0x30a google3/third_party/golang/gvisor/pkg/sentry/kernel/kernel.(Task).doSyscallInvoke(0xc000902000, 0x4e, 0xe, 0x7fc1100008f0, 0x8000, 0x0, 0x3, 0x7fc110000070, 0x3, 0x7fc110000070) third_party/golang/gvisor/pkg/sentry/kernel/task_syscall.go:283 +0x69 google3/third_party/golang/gvisor/pkg/sentry/kernel/kernel.(Task).doSyscallEnter(0xc000902000, 0x4e, 0xe, 0x7fc1100008f0, 0x8000, 0x0, 0x3, 0x7fc110000070, 0xd1ee60, 0xc0014f1e58) third_party/golang/gvisor/pkg/sentry/kernel/task_syscall.go:244 +0x99 google3/third_party/golang/gvisor/pkg/sentry/kernel/kernel.(Task).doSyscall(0xc000902000, 0x2, 0xc00057c000) third_party/golang/gvisor/pkg/sentry/kernel/task_syscall.go:219 +0x142 google3/third_party/golang/gvisor/pkg/sentry/kernel/kernel.(runApp).execute(0x0, 0xc000902000, 0xd1ee60, 0x0) third_party/golang/gvisor/pkg/sentry/kernel/task_run.go:215 +0xfda google3/third_party/golang/gvisor/pkg/sentry/kernel/kernel.(Task).run(0xc000902000, 0x19) third_party/golang/gvisor/pkg/sentry/kernel/task_run.go:91 +0x149 created by google3/third_party/golang/gvisor/pkg/sentry/kernel/kernel.(Task).Start third_party/golang/gvisor/pkg/sentry/kernel/task_start.go:279 +0xfe

fvoznika commented 5 years ago

BTW, the pod hung as "Terminating" problem also affects runc with gVisor disabled. containerd has fixed some issues with stuck termination in more recent builds, so it's likely fixed. If I'm able to repro again I'll report it to containerd.

fvoznika commented 5 years ago

It should be working now. I'll close once the deadlock fix is submitted.