Firecracker not working

[GabyCT]

It is not possible to run a container with firecracker

$ docker run -d --runtime $RUNTIME busybox sh -c "sleep 10"

This is leaving the container in created status, now running the kata-collect script, I have the following info

time="2019-03-15T00:34:53.649628404Z" level=info msg="No info could be fetched" arch=amd64 command=create container=f184497c8845243db9b48401e9e6eeaf840258fc95a19d22ed3902844149cdf1 error="open /run/vc/sbs/f184497c8845243db9b48401e9e6eeaf840258fc95a19d22ed3902844149cdf1/hypervisor.json: no such file or directory" function=init name=kata-runtime pid=7553 source=virtcontainers subsystem=firecracker
time="2019-03-15T00:34:53.649818703Z" level=warning msg="load sandbox devices failed" arch=amd64 command=create container=f184497c8845243db9b48401e9e6eeaf840258fc95a19d22ed3902844149cdf1 error="open /run/vc/sbs/f184497c8845243db9b48401e9e6eeaf840258fc95a19d22ed3902844149cdf1/devices.json: no such file or directory" name=kata-runtime pid=7553 sandbox=f184497c8845243db9b48401e9e6eeaf840258fc95a19d22ed3902844149cdf1 sandboxid=f184497c8845243db9b48401e9e6eeaf840258fc95a19d22ed3902844149cdf1 source=virtcontainers subsystem=sandbox
time="2019-03-15T00:35:08.792047253Z" level=error msg="Failed to check if grpc server is working: context deadline exceeded" arch=amd64 command=create container=f184497c8845243db9b48401e9e6eeaf840258fc95a19d22ed3902844149cdf1 name=kata-runtime pid=7553 source=runtime

[GabyCT]

Here it is the complete journal from kata-runtime

mar 15 03:06:00 testfc kata-runtime[94173]: time="2019-03-15T03:06:00.936569414Z" level=info msg="loaded configuration" arch=amd64 command=create file=/usr/share/defaults/kata-containers/configuration.toml format=TOML name=kata-runtime pid=94173 source=katautils
mar 15 03:06:00 testfc kata-runtime[94173]: time="2019-03-15T03:06:00.937940905Z" level=info msg="VSOCK supported, configure to not use proxy" arch=amd64 command=create name=kata-runtime pid=94173 source=katautils
mar 15 03:06:00 testfc kata-runtime[94173]: time="2019-03-15T03:06:00.938024005Z" level=info arch=amd64 arguments="\"create --bundle /var/run/docker/containerd/daemon/io.containerd.runtime.v1.linux/moby/4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b --pid-file /run/docker/containerd/daemon/io.containerd.runtime.v1.linux/moby/4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b/init.pid 4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b\"" command=create commit=8058fb07919786aee4c264d7c2d6fa5f99cb2a80-dirty name=kata-runtime pid=94173 source=runtime version=1.6.0-rc1
mar 15 03:06:00 testfc kata-runtime[94173]: time="2019-03-15T03:06:00.941339282Z" level=info msg="shm-size detected: 67108864" arch=amd64 command=create container=4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b name=kata-runtime pid=94173 source=virtcontainers subsystem=oci
mar 15 03:06:01 testfc kata-runtime[94173]: time="2019-03-15T03:06:01.434100286Z" level=info msg="No info could be fetched" arch=amd64 command=create container=4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b error="open /run/vc/sbs/4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b/hypervisor.json: no such file or directory" function=init name=kata-runtime pid=94173 source=virtcontainers subsystem=firecracker
mar 15 03:06:01 testfc kata-runtime[94173]: time="2019-03-15T03:06:01.434333485Z" level=warning msg="load sandbox devices failed" arch=amd64 command=create container=4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b error="open /run/vc/sbs/4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b/devices.json: no such file or directory" name=kata-runtime pid=94173 sandbox=4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b sandboxid=4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b source=virtcontainers subsystem=sandbox
mar 15 03:06:01 testfc kata-runtime[94173]: time="2019-03-15T03:06:01.434485484Z" level=info msg="FC not ready, queueing device" arch=amd64 command=create container=4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b name=kata-runtime pid=94173 source=virtcontainers subsystem=firecracker
mar 15 03:06:01 testfc kata-runtime[94173]: time="2019-03-15T03:06:01.437067666Z" level=info msg="Endpoints found after scan" arch=amd64 command=create container=4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b endpoints="[0xc00027a500]" name=kata-runtime pid=94173 source=virtcontainers subsystem=network
mar 15 03:06:01 testfc kata-runtime[94173]: time="2019-03-15T03:06:01.438478357Z" level=info msg="Attaching endpoint" arch=amd64 command=create container=4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b endpoint-type=virtual hotplug=false name=kata-runtime pid=94173 source=virtcontainers subsystem=network
mar 15 03:06:01 testfc kata-runtime[94173]: time="2019-03-15T03:06:01.453552356Z" level=info msg="FC not ready, queueing device" arch=amd64 command=create container=4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b name=kata-runtime pid=94173 source=virtcontainers subsystem=firecracker
mar 15 03:06:01 testfc kata-runtime[94173]: time="2019-03-15T03:06:01.45451695Z" level=info msg="Starting VM" arch=amd64 command=create container=4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b name=kata-runtime pid=94173 sandbox=4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b source=virtcontainers subsystem=sandbox
mar 15 03:06:01 testfc kata-runtime[94173]: time="2019-03-15T03:06:01.533445322Z" level=info msg="Adding device" arch=amd64 command=create container=4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b device-type-vsock="{2702230588 1024 0xc0000ae0d0}" name=kata-runtime pid=94173 source=virtcontainers subsystem=firecracker
mar 15 03:06:01 testfc kata-runtime[94173]: time="2019-03-15T03:06:01.544442848Z" level=info msg="Adding device" arch=amd64 command=create container=4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b device-type-endpoint="&{{{2f47ace8-9bf0-4105-af2e-af82bef255b4 br0_kata {tap0_kata 02:42:ac:11:00:02 []} [] []} {eth0 1e:d7:9e:6a:37:a4 []} 4} {{{47 1500 0 eth0 02:42:ac:11:00:02 up|broadcast|multicast 69699 48 0 <nil>  0xc000354588 0 <nil> ether <nil> up 0 0 0} veth} [172.17.0.2/16 eth0] [{Ifindex: 47 Dst: <nil> Src: <nil> Gw: 172.17.0.1 Flags: [] Table: 254} {Ifindex: 47 Dst: 172.17.0.0/16 Src: 172.17.0.2 Gw: <nil> Flags: [] Table: 254}] {[]  [] []}} virtual }" name=kata-runtime pid=94173 source=virtcontainers subsystem=firecracker
mar 15 03:06:01 testfc kata-runtime[94173]: time="2019-03-15T03:06:01.548193823Z" level=info msg="start firecracker virtual machine" arch=amd64 command=create container=4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b name=kata-runtime pid=94173 source=virtcontainers subsystem=firecracker
mar 15 03:06:01 testfc kata-runtime[94173]: time="2019-03-15T03:06:01.548284322Z" level=info msg="Starting VM" arch=amd64 command=create container=4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b name=kata-runtime pid=94173 source=virtcontainers subsystem=firecracker
mar 15 03:06:01 testfc kata-runtime[94173]: time="2019-03-15T03:06:01.675456572Z" level=info msg="VM started" arch=amd64 command=create container=4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b name=kata-runtime pid=94173 sandbox=4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b source=virtcontainers subsystem=sandbox
mar 15 03:06:01 testfc kata-runtime[94173]: time="2019-03-15T03:06:01.675805069Z" level=info msg="proxy started" arch=amd64 command=create container=4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b name=kata-runtime pid=94173 proxy-pid=0 proxy-url="vsock://2702230588:1024" sandbox=4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b source=virtcontainers subsystem=kata_agent
mar 15 03:06:01 testfc kata-runtime[94173]: time="2019-03-15T03:06:01.675925768Z" level=info msg="New client" arch=amd64 command=create container=4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b name=kata-runtime pid=94173 source=virtcontainers subsystem=kata_agent url="vsock://2702230588:1024"
mar 15 03:06:16 testfc kata-runtime[94173]: time="2019-03-15T03:06:16.676226125Z" level=info msg="Detaching endpoint" arch=amd64 command=create container=4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b endpoint-type=virtual hotunplug=false name=kata-runtime pid=94173 source=virtcontainers subsystem=network
mar 15 03:06:16 testfc kata-runtime[94173]: time="2019-03-15T03:06:16.729151171Z" level=info msg="Network namespace \"/var/run/netns/cni-c7e218d2-902d-01f1-cabf-00dda2cdd241\" deleted" arch=amd64 command=create container=4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b name=kata-runtime pid=94173 source=virtcontainers subsystem=network
mar 15 03:06:16 testfc kata-runtime[94173]: time="2019-03-15T03:06:16.749574134Z" level=info msg="cleanup agent" arch=amd64 command=create container=4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b name=kata-runtime path=/run/kata-containers/shared/sandboxes/4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b pid=94173 source=virtcontainers subsystem=kata_agent
mar 15 03:06:16 testfc kata-runtime[94173]: time="2019-03-15T03:06:16.75021203Z" level=error msg="Failed to check if grpc server is working: context deadline exceeded" arch=amd64 command=create container=4013aa179af16506dfb2177ab0fe20cd6fd07f9aca6d7e71d10ca8f498699b1b name=kata-runtime pid=94173 source=runtime

[jodh-intel]

Hi @GabyCT - have you compared your setup with the FC CI setup?

/cc @mcastelino, @amshinde.

[chavafg]

Could it be the host kernel issue? #1203 ?

[chavafg]

Or the recent osbuilder changes? kata-containers/osbuilder#236
/cc @devimc

I see also that the ARM CI started to fail with a similar issue.

10:10:45 Stderr: Failed to check if grpc server is working: rpc error: code = Unavailable desc = transport is closing

/cc @Pennyzct

[GabyCT]

@jodh-intel yes, the CI has been failing so I actually reproduce the errors locally and @chavafg I tried it yesterday with kernel images where vsocks are working and is not that

[GabyCT]

I tried it this commit in osbuilder cbe5642b9d018c100c87a1186def22d1907ce633 before kata-containers/osbuilder#236 and Firecracker is working properly. I am adding a CI for firecracker in osbuilder so this kind of errors does not happen again

[jodh-intel]

Thanks @GabyCT.

[amshinde]

Thanks @GabyCT for looking into this. @devimc Can you take a look why kata-containers/osbuilder#236 seems to be causing issues.

[Pennyzct]

Hi~ @GabyCT @jodh-intel @chavafg @devimc
With kata-containers/osbuilder#236, I'm afraid that ARM CI will break down.
Mar 18 10:51:59 entos-thunderx2-desktop kata-proxy[167232]: time="2019-03-18T10:51:59.986256824+08:00" level=info msg="VFS: Cannot open root device \"pmem0p1\" or unknown-block(0,0): error -6\n" name=kata-proxy pid=167232 sandbox=c0b8672c790501126fa3c523f9bd2ce3834806e6d94ce86eb5112028504f5f7c source=agent
I'm really quite unfamiliar with these techniques, so please correct me if i'm wrong.
The hacking solution in kata-containers/osbuilder#236 is based on these kernel features, NVDIMM_PFN and ZONE_DEVICE, etc. And ZONE_DEVICE is not fully supported on arm64. So I'm thinking maybe this pr is only designed for x86_64 only for now.

[GabyCT]

This is already fixed with kata-containers/osbuilder@d67aad8