Inject entropy into kata container

[jcvenegas]

Description of problem

The entropy inside a kata container is too low

Expected result

Have a better entropy level. See the difference between runc and kata below.

Actual result

host
$ cat /proc/sys/kernel/random/entropy_avail
3089
runc
$ docker run --runtime runc -ti busybox cat /proc/sys/kernel/random/entropy_avail
3093
kata
$docker run --runtime kata-runtime -ti busybox cat /proc/sys/kernel/random/entropy_avail
7

---

We should consider add a VirtIORNG or a daemon to increase the entropy inside the container.

[jcvenegas]

I tested adding a virtio-rng-pci device.
update:
jcvenegas@18800fd

but I see the container boot hangs the last call by the kernel is calling virtio_rng_driver_init then I dont see any traces

level=info msg="time=\"2018-06-27T21:00:31.286175957Z\" level=debug msg=\"new request\" name=kata-agent pid=97 req=\"hostname:\\\"97b0e654fa2d\\\" storages:<driver:\\\"9p\\\" source:\\\"kataShared\\\" fstype:\\\"9p\\\" options:\\\"trans=virtio,version=9p2000.L\\\" options:\\\"nodev\\\" options:\\\"msize=8192\\\" mount_point:\\\"/run/kata-containers/shared/containers/\\\" > storages:<driver:\\\"ephemeral\\\" source:\\\"shm\\\" fstype:\\\"tmpfs\\\" options:\\\"noexec\\\" options:\\\"nosuid\\\" options:\\\"nodev\\\" options:\\\"mode=1777\\\" options:\\\"size=67108864\\\" mount_point:\\\"/run/kata-containers/sandbox/shm\\\" > \" request=/grpc.AgentService/CreateSandbox source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:00:31.294158507Z\" level=debug mount-destination=/run/kata-containers/shared/containers/ mount-flags=4 mount-fstype=9p mount-options=\"trans=virtio,version=9p2000.L,msize=8192\" mount-source=kataShared name=kata-agent pid=97 source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:00:31.299747104Z\" level=debug mount-destination=/run/kata-containers/sandbox/shm mount-flags=14 mount-fstype=tmpfs mount-options=\"mode=1777,size=67108864\" mount-source=shm name=kata-agent pid=97 source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:00:31.301868507Z\" level=debug msg=\"request end\" duration=15.364815ms name=kata-agent pid=97 request=/grpc.AgentService/CreateSandbox resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:00:31.336357522Z\" level=debug msg=\"new request\" name=kata-agent pid=97 req=\"container_id:\\\"97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1\\\" exec_id:\\\"97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1\\\" OCI:<Version:\\\"1.0.1\\\" Process:<Terminal:true User:<AdditionalGids:10 > Args:\\\"sh\\\" Env:\\\"PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin\\\" Env:\\\"HOSTNAME=97b0e654fa2d\\\" Env:\\\"TERM=xterm\\\" Env:\\\"HTTP_PROXY=http://proxy-chain.intel.com:911\\\" Env:\\\"http_proxy=http://proxy-chain.intel.com:911\\\" Env:\\\"HTTPS_PROXY=http://proxy-chain.intel.com:912\\\" Env:\\\"https_proxy=http://proxy-chain.intel.com:912\\\" Env:\\\"NO_PROXY=.intel.com,10.0.2.15,10.0.2.2,127.0.0.1,127.3.232.2,intel.com,kernel,localhost\\\" Env:\\\"no_proxy=.intel.com,10.0.2.15,10.0.2.2,127.0.0.1,127.3.232.2,intel.com,kernel,localhost\\\" Cwd:\\\"/\\\" Capabilities:<Bounding:\\\"CAP_CHOWN\\\" Bounding:\\\"CAP_DAC_OVERRIDE\\\" Bounding:\\\"CAP_FSETID\\\" Bounding:\\\"CAP_FOWNER\\\" Bounding:\\\"CAP_MKNOD\\\" Bounding:\\\"CAP_NET_RAW\\\" Bounding:\\\"CAP_SETGID\\\" Bounding:\\\"CAP_SETUID\\\" Bounding:\\\"CAP_SETFCAP\\\" Bounding:\\\"CAP_SETPCAP\\\" Bounding:\\\"CAP_NET_BIND_SERVICE\\\" Bounding:\\\"CAP_SYS_CHROOT\\\" Bounding:\\\"CAP_KILL\\\" Bounding:\\\"CAP_AUDIT_WRITE\\\" Effective:\\\"CAP_CHOWN\\\" Effective:\\\"CAP_DAC_OVERRIDE\\\" Effective:\\\"CAP_FSETID\\\" Effective:\\\"CAP_FOWNER\\\" Effective:\\\"CAP_MKNOD\\\" Effective:\\\"CAP_NET_RAW\\\" Effective:\\\"CAP_SETGID\\\" Effective:\\\"CAP_SETUID\\\" Effective:\\\"CAP_SETFCAP\\\" Effective:\\\"CAP_SETPCAP\\\" Effective:\\\"CAP_NET_BIND_SERVICE\\\" Effective:\\\"CAP_SYS_CHROOT\\\" Effective:\\\"CAP_KILL\\\" Effective:\\\"CAP_AUDIT_WRITE\\\" Inheritable:\\\"CAP_CHOWN\\\" Inheritable:\\\"CAP_DAC_OVERRIDE\\\" Inheritable:\\\"CAP_FSETID\\\" Inheritable:\\\"CAP_FOWNER\\\" Inheritable:\\\"CAP_MKNOD\\\" Inheritable:\\\"CAP_NET_RAW\\\" Inheritable:\\\"CAP_SETGID\\\" Inheritable:\\\"CAP_SETUID\\\" Inheritable:\\\"CAP_SETFCAP\\\" Inheritable:\\\"CAP_SETPCAP\\\" Inheritable:\\\"CAP_NET_BIND_SERVICE\\\" Inheritable:\\\"CAP_SYS_CHROOT\\\" Inheritable:\\\"CAP_KILL\\\" Inheritable:\\\"CAP_AUDIT_WRITE\\\" Permitted:\\\"CAP_CHOWN\\\" Permitted:\\\"CAP_DAC_OVERRIDE\\\" Permitted:\\\"CAP_FSETID\\\" Permitted:\\\"CAP_FOWNER\\\" Permitted:\\\"CAP_MKNOD\\\" Permitted:\\\"CAP_NET_RAW\\\" Permitted:\\\"CAP_SETGID\\\" Permitted:\\\"CAP_SETUID\\\" Permitted:\\\"CAP_SETFCAP\\\" Permitted:\\\"CAP_SETPCAP\\\" Permitted:\\\"CAP_NET_BIND_SERVICE\\\" Permitted:\\\"CAP_SYS_CHROOT\\\" Permitted:\\\"CAP_KILL\\\" Permitted:\\\"CAP_AUDIT_WRITE\\\" > ApparmorProfile:\\\"docker-default\\\" > Root:<Path:\\\"/run/kata-containers/shared/containers/97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1/rootfs\\\" > Hostname:\\\"97b0e654fa2d\\\" Mounts:<destination:\\\"/proc\\\" source:\\\"proc\\\" type:\\\"proc\\\" options:\\\"nosuid\\\" options:\\\"noexec\\\" options:\\\"nodev\\\" > Mounts:<destination:\\\"/dev\\\" source:\\\"tmpfs\\\" type:\\\"tmpfs\\\" options:\\\"nosuid\\\" options:\\\"strictatime\\\" options:\\\"mode=755\\\" options:\\\"size=65536k\\\" > Mounts:<destination:\\\"/dev/pts\\\" source:\\\"devpts\\\" type:\\\"devpts\\\" options:\\\"nosuid\\\" options:\\\"noexec\\\" options:\\\"newinstance\\\" options:\\\"ptmxmode=0666\\\" options:\\\"mode=0620\\\" options:\\\"gid=5\\\" > Mounts:<destination:\\\"/sys\\\" source:\\\"sysfs\\\" type:\\\"sysfs\\\" options:\\\"nosuid\\\" options:\\\"noexec\\\" options:\\\"nodev\\\" options:\\\"ro\\\" > Mounts:<destination:\\\"/sys/fs/cgroup\\\" source:\\\"cgroup\\\" type:\\\"cgroup\\\" options:\\\"ro\\\" options:\\\"nosuid\\\" options:\\\"noexec\\\" options:\\\"nodev\\\" > Mounts:<destination:\\\"/dev/mqueue\\\" source:\\\"mqueue\\\" type:\\\"mqueue\\\" options:\\\"nosuid\\\" options:\\\"noexec\\\" options:\\\"nodev\\\" > Mounts:<destination:\\\"/etc/resolv.conf\\\" source:\\\"/run/kata-containers/shared/containers/97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1-ddf55bd9a5f809c9-resolv.conf\\\" type:\\\"bind\\\" options:\\\"rbind\\\" options:\\\"rprivate\\\" > Mounts:<destination:\\\"/etc/hostname\\\" source:\\\"/run/kata-containers/shared/containers/97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1-a933d6bcb2b25a1e-hostname\\\" type:\\\"bind\\\" options:\\\"rbind\\\" options:\\\"rprivate\\\" > Mounts:<destination:\\\"/etc/hosts\\\" source:\\\"/run/kata-containers/shared/containers/97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1-b1f3b2788747cbc8-hosts\\\" type:\\\"bind\\\" options:\\\"rbind\\\" options:\\\"rprivate\\\" > Mounts:<destination:\\\"/dev/shm\\\" source:\\\"/run/kata-containers/sandbox/shm\\\" type:\\\"bind\\\" options:\\\"rbind\\\" > Linux:<Resources:<CPU:<> > CgroupsPath:\\\"/docker/97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1\\\" Namespaces:<Type:\\\"mount\\\" > Namespaces:<Type:\\\"uts\\\" > Namespaces:<Type:\\\"ipc\\\" > MaskedPaths:\\\"/proc/kcore\\\" MaskedPaths:\\\"/proc/keys\\\" MaskedPaths:\\\"/proc/latency_stats\\\" MaskedPaths:\\\"/proc/timer_list\\\" MaskedPaths:\\\"/proc/timer_stats\\\" MaskedPaths:\\\"/proc/sched_debug\\\" MaskedPaths:\\\"/proc/scsi\\\" MaskedPaths:\\\"/sys/firmware\\\" ReadonlyPaths:\\\"/proc/asound\\\" ReadonlyPaths:\\\"/proc/bus\\\" ReadonlyPaths:\\\"/proc/fs\\\" ReadonlyPaths:\\\"/proc/irq\\\" ReadonlyPaths:\\\"/proc/sys\\\" ReadonlyPaths:\\\"/proc/sysrq-trigger\\\" > > \" request=/grpc.AgentService/CreateContainer source=agent\n" name=kata-proxy pid=32493 source=agent
level=info msg="[    1.482721] pci 0000:00:02.0: PCI bridge to [bus 01]\n" name=kata-proxy pid=32493 source=agent
 level=info msg="[    1.483338] pci 0000:00:02.0:   bridge window [io  0xc000-0xcfff]\n" name=kata-proxy pid=32493 source=agent
 level=info msg="[    1.485374] pci 0000:00:02.0:   bridge window [mem 0xfe600000-0xfe7fffff]\n" name=kata-proxy pid=32493 source=agent
level=info msg="[    1.486781] pci 0000:00:02.0:   bridge window [mem 0xfea00000-0xfebfffff 64bit pref]\n" name=kata-proxy pid=32493 source=agent
level=info msg="time=\"2018-06-27T21:00:31.423813504Z\" level=debug msg=\"request end\" duration=86.829353ms name=kata-agent pid=97 request=/grpc.AgentService/CreateContainer resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:00:31.424470024Z\" level=info msg=\"ignoring unexpected signal\" name=kata-agent pid=97 signal=\"child exited\" source=agent\n" name=kata-proxy pid=32493 source=agent
level=info msg="time=\"2018-06-27T21:00:31.456476586Z\" level=debug msg=\"new request\" name=kata-agent pid=97 req=\"container_id:\\\"97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1\\\" exec_id:\\\"97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1\\\" \" request=/grpc.AgentService/TtyWinResize source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:00:31.460206943Z\" level=debug msg=\"request end\" duration=\"34.631µs\" name=kata-agent pid=97 request=/grpc.AgentService/TtyWinResize resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:00:31.469949625Z\" level=debug msg=\"new request\" name=kata-agent pid=97 req=\"container_id:\\\"97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1\\\" exec_id:\\\"97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1\\\" len:32768 \" request=/grpc.AgentService/ReadStdout source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:00:31.495934668Z\" level=debug msg=\"new request\" name=kata-agent pid=97 req=\"container_id:\\\"97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1\\\" \" request=/grpc.AgentService/StartContainer source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:00:31.513767669Z\" level=debug msg=\"request end\" duration=17.460131ms name=kata-agent pid=97 request=/grpc.AgentService/StartContainer resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:00:31.521995598Z\" level=debug msg=\"request end\" duration=51.737837ms name=kata-agent pid=97 request=/grpc.AgentService/ReadStdout resp=\"data:\\\"/ # \\\" \" source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:00:31.533373561Z\" level=debug msg=\"new request\" name=kata-agent pid=97 req=\"container_id:\\\"97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1\\\" exec_id:\\\"97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1\\\" len:32768 \" request=/grpc.AgentService/ReadStdout source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:00:31.571141166Z\" level=debug msg=\"new request\" name=kata-agent pid=97 req=\"container_id:\\\"97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1\\\" exec_id:\\\"97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1\\\" row:36 column:271 \" request=/grpc.AgentService/TtyWinResize source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:00:31.571476086Z\" level=debug msg=\"request end\" duration=\"80.797µs\" name=kata-agent pid=97 request=/grpc.AgentService/TtyWinResize resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:00:31.573362677Z\" level=debug msg=\"request end\" duration=38.862301ms name=kata-agent pid=97 request=/grpc.AgentService/ReadStdout resp=\"data:\\\"\\\\r/ # \\\\033[J\\\" \" source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:00:31.575795011Z\" level=debug msg=\"new request\" name=kata-agent pid=97 req=\"container_id:\\\"97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1\\\" exec_id:\\\"97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1\\\" len:32768 \" request=/grpc.AgentService/ReadStdout source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:01:05.23076555Z\" level=debug msg=\"new request\" name=kata-agent pid=97 req=\"container_id:\\\"97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1\\\" exec_id:\\\"97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1\\\" data:\\\"\\\\004\\\" \" request=/grpc.AgentService/WriteStdin source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:01:05.231339358Z\" level=debug msg=\"request end\" duration=\"235.586µs\" name=kata-agent pid=97 request=/grpc.AgentService/WriteStdin resp=\"len:1 \" source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:01:05.235330014Z\" level=debug msg=\"request end\" duration=33.658971553s error=\"read /dev/ptmx: input/output error\" name=kata-agent pid=97 request=/grpc.AgentService/ReadStdout resp= source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:01:05.236308013Z\" level=debug msg=\"process exited\" name=kata-agent pid=129 source=agent status=0\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:01:05.237651611Z\" level=info msg=\"ignoring unexpected signal\" name=kata-agent pid=97 signal=\"child exited\" source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:01:05.239190617Z\" level=debug msg=\"new request\" name=kata-agent pid=97 req=\"container_id:\\\"97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1\\\" exec_id:\\\"97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1\\\" \" request=/grpc.AgentService/WaitProcess source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:01:05.240958298Z\" level=debug msg=\"request end\" duration=1.447061ms name=kata-agent pid=97 request=/grpc.AgentService/WaitProcess resp= source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:01:05.262644449Z\" level=debug msg=\"new request\" name=kata-agent pid=97 req=\"container_id:\\\"97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1\\\" signal:9 \" request=/grpc.AgentService/SignalProcess source=agent\n" name=kata-proxy pid=32493 source=agent
level=info msg="time=\"2018-06-27T21:01:05.265775677Z\" level=info msg=\"discarding signal as container stopped\" containerID=97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1 name=kata-agent pid=97 sandbox=97b0e654fa2d signal=killed source=agent\n" name=kata-proxy pid=32493 source=agent
level=info msg="time=\"2018-06-27T21:01:05.266695077Z\" level=debug msg=\"request end\" duration=1.530976ms name=kata-agent pid=97 request=/grpc.AgentService/SignalProcess resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=32493 source=agent
level=info msg="time=\"2018-06-27T21:01:05.274775819Z\" level=debug msg=\"new request\" name=kata-agent pid=97 req=\"container_id:\\\"97b0e654fa2d24f339353150412414ea04d648a44553c5d02e7a5b4eebe721c1\\\" \" request=/grpc.AgentService/RemoveContainer source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:01:05.277389421Z\" level=debug msg=\"request end\" duration=2.139421ms name=kata-agent pid=97 request=/grpc.AgentService/RemoveContainer resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:01:05.417113619Z\" level=debug msg=\"new request\" name=kata-agent pid=97 req= request=/grpc.AgentService/DestroySandbox source=agent\n" name=kata-proxy pid=32493 source=agent
 level=info msg="time=\"2018-06-27T21:01:05.423141471Z\" level=debug msg=\"request end\" duration=5.823417ms name=kata-agent pid=97 request=/grpc.AgentService/DestroySandbox resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=32493 source=agent
 level=debug msg="shutting down" name=kata-proxy pid=32493 source=proxy
level=info name=kata-proxy pid=2214 source=proxy version=1.0.0-4b80b0f6b4a527e58a63a49398b742e0db6199eb
level=info msg="[    0.243108] initcall hwrng_modinit+0x0/0x6e returned 0 after 1833 usecs\n" name=kata-proxy pid=2214 source=agent
level=info msg="[    0.243455] calling  mod_init+0x0/0x1cd @ 1\n" name=kata-proxy pid=2214 source=agent
level=info msg="[    0.243690] initcall mod_init+0x0/0x1cd returned -19 after 17 usecs\n" name=kata-proxy pid=2214 source=agent
level=info msg="[    0.244158] calling  virtio_rng_driver_init+0x0/0xc @ 1\n" name=kata-proxy pid=2214 source=agent

[sboeuf]

@jcvenegas make sure the syntax is correct as in the qemu doc: https://wiki.qemu.org/Features/VirtIORNG

[amshinde]

@jcvenegas So I tried this:

config.qemuParams = append(config.qemuParams, "-device")
config.qemuParams = append(config.qemuParams, "virtio-rng-pci")

This uses host /dev/random. This worked for me. With this:

sudo docker run -it --runtime=kata-runtime debian sh
# cat /proc/sys/kernel/random/entropy_avail
1040

I also tried with /dev/urandom as:

config.qemuParams = append(config.qemuParams, "-object")
config.qemuParams = append(config.qemuParams, "rng-random,filename=/dev/urandom,id=rng0")
config.qemuParams = append(config.qemuParams, "-device")
config.qemuParams = append(config.qemuParams, "virtio-rng-pci,rng=rng0"

With this the entropy is

sudo docker run -it --runtime=kata-runtime debian sh
# cat /proc/sys/kernel/random/entropy_avail
1065

[jcvenegas]

@amshinde interesting I will test again with an old kernel

[jcvenegas]

same result with an old kernel

[jcvenegas]

Created a "test" PR to verify is not my environment #451

[amshinde]

@jcvenegas I tested this with the newer kernel version on bare-metal 4.14..51. It works.
Maybe this has to do with your nested environment. The VM itself may not have enough entropy. This is just my guess though.

[sboeuf]

@amshinde @jcvenegas cool :)
One thing before we submit a PR for that, should we consider limiting the guest so that we don't end up draining the entire entropy from the host in case we have several VMs running. With something like:

-device virtio-rng-pci,max-bytes=1024,period=1000

[jcvenegas]

@sboeuf sure will add it.
@amshinde similar result in baremetal.
I see the proxy only show the following:

Jun 28 10:37:25 jcvenega-nuc.zpn.intel.com kata-proxy[21949]: time="2018-06-28T10:37:25.584553246-05:00" level=info name=kata-proxy pid=21949 source=proxy version=1.0.0-15459f4b4ac6f6a242445ff284fec14135bc0045
Jun 28 10:37:29 jcvenega-nuc.zpn.intel.com kata-proxy[21949]: time="2018-06-28T10:37:29.722010363-05:00" level=info msg="[    1.120107] tsc: Refined TSC clocksource calibration: 1895.607 MHz\n" name=kata-proxy pid=21949 source=agent
Jun 28 10:37:29 jcvenega-nuc.zpn.intel.com kata-proxy[21949]: time="2018-06-28T10:37:29.723750764-05:00" level=info msg="[    1.121788] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x36a5ec0fe57, max_idle_ns: 881590722870 ns\n" name=kata-proxy pid=21949 source=agent

and runtime:

Jun 28 10:37:25 jcvenega-nuc.zpn.intel.com kata-runtime[21904]: time="2018-06-28T10:37:25.555007981-05:00" level=info msg="{\"execute\":\"qmp_capabilities\"}" arch=amd64 name=kata-runtime pid=21904 source=virtcontainers subsystem=qmp
Jun 28 10:37:25 jcvenega-nuc.zpn.intel.com kata-runtime[21904]: time="2018-06-28T10:37:25.558280517-05:00" level=info msg="{\"return\": {}}" arch=amd64 name=kata-runtime pid=21904 source=virtcontainers subsystem=qmp
Jun 28 10:37:25 jcvenega-nuc.zpn.intel.com kata-runtime[21904]: time="2018-06-28T10:37:25.558520427-05:00" level=info msg="VM started" arch=amd64 name=kata-runtime pid=21904 sandbox-id=5806db38d3b2050722eb8373e44f99b30c87e0c1e6792043f82ac9a5d374e398 source=virtcontainers subsystem=sandbox
Jun 28 10:37:25 jcvenega-nuc.zpn.intel.com kata-runtime[21904]: time="2018-06-28T10:37:25.561526156-05:00" level=info msg="proxy started" arch=amd64 name=kata-runtime pid=21904 proxy-pid=21949 proxy-url="unix:///run/vc/sbs/5806db38d3b2050722eb8373e44f99b30c87e0c1e6792043f82ac9a5d374e398/proxy.sock" sandbox-id=5806db38d3b2050722eb8373e44f99b30c87e0c1e6792043f82ac9a5d374e398 source=virtcontainers subsystem=kata_agent

kata-collect-data output

Meta details

Running kata-collect-data.sh version 1.0.0 (commit 93775487c8c205a399fb4abb2a3940336098e380-dirty) at 2018-06-28.10:39:16.476561642-0500.

---

Runtime is /usr/local/bin/kata-runtime.

kata-env

Output of "/usr/local/bin/kata-runtime kata-env":

[Meta]
  Version = "1.0.12"

[Runtime]
  Debug = false
  [Runtime.Version]
    Semver = "1.0.0"
    Commit = "93775487c8c205a399fb4abb2a3940336098e380-dirty"
    OCI = "1.0.1"
  [Runtime.Config]
    Path = "/usr/share/defaults/kata-containers/configuration.toml"

[Hypervisor]
  MachineType = "pc"
  Version = "QEMU emulator version 2.11.0\nCopyright (c) 2003-2017 Fabrice Bellard and the QEMU Project developers"
  Path = "/usr/bin/qemu-lite-system-x86_64"
  BlockDeviceDriver = "virtio-scsi"
  Msize9p = 8192
  Debug = false

[Image]
  Path = "/usr/share/kata-containers/kata-containers-image_clearlinux_agent_a099747.img"

[Kernel]
  Path = "/usr/share/kata-containers/vmlinuz.container"
  Parameters = "agent.log=debug"

[Initrd]
  Path = ""

[Proxy]
  Type = "kataProxy"
  Version = "kata-proxy version 1.0.0-15459f4b4ac6f6a242445ff284fec14135bc0045"
  Path = "/usr//libexec/kata-containers/kata-proxy"
  Debug = true

[Shim]
  Type = "kataShim"
  Version = "kata-shim version 1.0.0-5296edac3823b31eecebd90ad0b3e7ad81d6e88a"
  Path = "/usr/libexec/kata-containers/kata-shim"
  Debug = true

[Agent]
  Type = "kata"

[Host]
  Kernel = "4.16.13-300.fc28.x86_64"
  Architecture = "amd64"
  VMContainerCapable = true
  [Host.Distro]
    Name = "Fedora"
    Version = "28"
  [Host.CPU]
    Vendor = "GenuineIntel"
    Model = "Intel(R) Core(TM) i5-4250U CPU @ 1.30GHz"

---

Runtime config files

Runtime default config files

/etc/kata-containers/configuration.toml
/usr/share/defaults/kata-containers/configuration.toml

Runtime config file contents

Config file /etc/kata-containers/configuration.toml not found
Output of "cat "/usr/share/defaults/kata-containers/configuration.toml"":

# Copyright (c) 2017-2018 Intel Corporation
#
# SPDX-License-Identifier: Apache-2.0
#

# XXX: WARNING: this file is auto-generated.
# XXX:
# XXX: Source file: "cli/config/configuration.toml.in"
# XXX: Project:
# XXX:   Name: Kata Containers
# XXX:   Type: kata

[hypervisor.qemu]
path = "/usr//bin/qemu-lite-system-x86_64"
kernel = "/usr//share/kata-containers/vmlinuz.container"
image = "/usr//share/kata-containers/kata-containers.img"
machine_type = "pc"

# Optional space-separated list of options to pass to the guest kernel.
# For example, use `kernel_params = "vsyscall=emulate"` if you are having
# trouble running pre-2.15 glibc.
#
# WARNING: - any parameter specified here will take priority over the default
# parameter value of the same name used to start the virtual machine.
# Do not set values here unless you understand the impact of doing so as you
# may stop the virtual machine from booting.
# To see the list of default parameters, enable hypervisor debug, create a
# container and look for 'default-kernel-parameters' log entries.
kernel_params = " agent.log=debug"

# Path to the firmware.
# If you want that qemu uses the default firmware leave this option empty
firmware = ""

# Machine accelerators
# comma-separated list of machine accelerators to pass to the hypervisor.
# For example, `machine_accelerators = "nosmm,nosmbus,nosata,nopit,static-prt,nofw"`
machine_accelerators=""

# Default number of vCPUs per SB/VM:
# unspecified or 0                --> will be set to 1
# < 0                             --> will be set to the actual number of physical cores
# > 0 <= number of physical cores --> will be set to the specified number
# > number of physical cores      --> will be set to the actual number of physical cores
default_vcpus = 1

# Default maximum number of vCPUs per SB/VM:
# unspecified or == 0             --> will be set to the actual number of physical cores or to the maximum number
#                                     of vCPUs supported by KVM if that number is exceeded
# > 0 <= number of physical cores --> will be set to the specified number
# > number of physical cores      --> will be set to the actual number of physical cores or to the maximum number
#                                     of vCPUs supported by KVM if that number is exceeded
# WARNING: Depending of the architecture, the maximum number of vCPUs supported by KVM is used when
# the actual number of physical cores is greater than it.
# WARNING: Be aware that this value impacts the virtual machine's memory footprint and CPU
# the hotplug functionality. For example, `default_maxvcpus = 240` specifies that until 240 vCPUs
# can be added to a SB/VM, but the memory footprint will be big. Another example, with
# `default_maxvcpus = 8` the memory footprint will be small, but 8 will be the maximum number of
# vCPUs supported by the SB/VM. In general, we recommend that you do not edit this variable,
# unless you know what are you doing.
default_maxvcpus = 0

# Bridges can be used to hot plug devices.
# Limitations:
# * Currently only pci bridges are supported
# * Until 30 devices per bridge can be hot plugged.
# * Until 5 PCI bridges can be cold plugged per VM.
#   This limitation could be a bug in qemu or in the kernel
# Default number of bridges per SB/VM:
# unspecified or 0   --> will be set to 1
# > 1 <= 5           --> will be set to the specified number
# > 5                --> will be set to 5
default_bridges = 1

# Default memory size in MiB for SB/VM.
# If unspecified then it will be set 2048 MiB.
#default_memory = 2048

# Disable block device from being used for a container's rootfs.
# In case of a storage driver like devicemapper where a container's 
# root file system is backed by a block device, the block device is passed
# directly to the hypervisor for performance reasons. 
# This flag prevents the block device from being passed to the hypervisor, 
# 9pfs is used instead to pass the rootfs.
disable_block_device_use = false

# Block storage driver to be used for the hypervisor in case the container
# rootfs is backed by a block device. This is either virtio-scsi or 
# virtio-blk.
block_device_driver = "virtio-scsi"

# Enable iothreads (data-plane) to be used. This causes IO to be
# handled in a separate IO thread. This is currently only implemented
# for SCSI.
#
enable_iothreads = false

# Enable pre allocation of VM RAM, default false
# Enabling this will result in lower container density
# as all of the memory will be allocated and locked
# This is useful when you want to reserve all the memory
# upfront or in the cases where you want memory latencies
# to be very predictable
# Default false
#enable_mem_prealloc = true

# Enable huge pages for VM RAM, default false
# Enabling this will result in the VM memory
# being allocated using huge pages.
# This is useful when you want to use vhost-user network
# stacks within the container. This will automatically 
# result in memory pre allocation
#enable_hugepages = true

# Enable swap of vm memory. Default false.
# The behaviour is undefined if mem_prealloc is also set to true
#enable_swap = true

# This option changes the default hypervisor and kernel parameters
# to enable debug output where available. This extra output is added
# to the proxy logs, but only when proxy debug is also enabled.
# 
# Default false
enable_debug = true

# Disable the customizations done in the runtime when it detects
# that it is running on top a VMM. This will result in the runtime
# behaving as it would when running on bare metal.
# 
#disable_nesting_checks = true

# This is the msize used for 9p shares. It is the number of bytes 
# used for 9p packet payload.
#msize_9p = 8192

[proxy.kata]
path = "/usr//libexec/kata-containers/kata-proxy"

# If enabled, proxy messages will be sent to the system log
# (default: disabled)
enable_debug = true

[shim.kata]
path = "/usr//libexec/kata-containers/kata-shim"

# If enabled, shim messages will be sent to the system log
# (default: disabled)
enable_debug = true

[agent.kata]
# There is no field for this section. The goal is only to be able to
# specify which type of agent the user wants to use.

[runtime]
# If enabled, the runtime will log additional debug messages to the
# system log
# (default: disabled)
enable_debug = true
#
# Internetworking model
# Determines how the VM should be connected to the
# the container network interface
# Options:
#
#   - bridged
#     Uses a linux bridge to interconnect the container interface to
#     the VM. Works for most cases except macvlan and ipvlan.
#
#   - macvtap
#     Used when the Container network interface can be bridged using
#     macvtap.
internetworking_model="macvtap"

---

Image details

---
osbuilder:
  url: "https://github.com/kata-containers/osbuilder"
  version: "unknown"
rootfs-creation-time: "2018-06-12T03:55:46.913416409+0000Z"
description: "osbuilder rootfs"
file-format-version: "0.0.2"
architecture: "x86_64"
base-distro:
  name: "Clear"
  version: "22950"
  packages:
    default:
      - "iptables-bin"
      - "libudev0-shim"
      - "systemd"
    extra:

agent:
  url: "https://github.com/kata-containers/agent"
  name: "kata-agent"
  version: "1.0.0-a099747be287d30d7f1efcd6ba2bda88fc4a0f15"
  agent-is-init-daemon: "no"

---

Initrd details

No initrd

---

Logfiles

Runtime logs

Recent runtime problems found in system journal:

time="2018-06-28T10:15:15.074905652-05:00" level=debug msg="Could not retrieve anything from storage" arch=amd64 name=kata-runtime pid=18048 source=virtcontainers subsystem=kata_agent
time="2018-06-28T10:15:15.305536841-05:00" level=debug arch=amd64 default-kernel-parameters="tsc=reliable no_timer_check rcupdate.rcu_expedited=1 i8042.direct=1 i8042.dumbkbd=1 i8042.nopnp=1 i8042.noaux=1 noreplace-smp reboot=k console=hvc0 console=hvc1 iommu=off cryptomgr.notests net.ifnames=0 pci=lastbus=0 root=/dev/pmem0p1 rootflags=dax,data=ordered,errors=remount-ro rw rootfstype=ext4 debug systemd.show_status=true systemd.log_level=debug" name=kata-runtime pid=18048 source=virtcontainers subsystem=qemu
time="2018-06-28T10:15:32.74437162-05:00" level=error msg="Container not ready, running or paused, impossible to signal the container" command=kill name=kata-runtime pid=18159 source=runtime
time="2018-06-28T10:15:32.831883688-05:00" level=error msg="Container f2f76b02c22627630b638af11320adb1511c3f2567ce6c2a28df83dc1ea10ee7 not ready, running or paused, cannot send a signal" command=kill name=kata-runtime pid=18190 source=runtime
time="2018-06-28T10:17:44.539854007-05:00" level=debug msg="Could not retrieve anything from storage" arch=amd64 name=kata-runtime pid=18709 source=virtcontainers subsystem=kata_agent
time="2018-06-28T10:17:44.734602783-05:00" level=debug arch=amd64 default-kernel-parameters="tsc=reliable no_timer_check rcupdate.rcu_expedited=1 i8042.direct=1 i8042.dumbkbd=1 i8042.nopnp=1 i8042.noaux=1 noreplace-smp reboot=k console=hvc0 console=hvc1 iommu=off cryptomgr.notests net.ifnames=0 pci=lastbus=0 root=/dev/pmem0p1 rootflags=dax,data=ordered,errors=remount-ro rw rootfstype=ext4 debug systemd.show_status=true systemd.log_level=debug" name=kata-runtime pid=18709 source=virtcontainers subsystem=qemu
time="2018-06-28T10:19:35.713136211-05:00" level=error msg="update interface request failed" arch=amd64 error="rpc error: code = Unavailable desc = transport is closing" interface-requested="device:\"eth0\" name:\"eth0\" IPAddresses:<address:\"172.17.0.2\" mask:\"16\" > mtu:1500 hwAddr:\"02:42:ac:11:00:02\" " name=kata-runtime pid=18709 resulting-interface="<nil>" source=virtcontainers subsystem=kata_agent
time="2018-06-28T10:19:35.714095163-05:00" level=error msg="rpc error: code = Unavailable desc = transport is closing" command=create name=kata-runtime pid=18709 source=runtime
time="2018-06-28T10:21:31.900853568-05:00" level=debug msg="Could not retrieve anything from storage" arch=amd64 name=kata-runtime pid=19674 source=virtcontainers subsystem=kata_agent
time="2018-06-28T10:21:32.070157886-05:00" level=debug arch=amd64 default-kernel-parameters="tsc=reliable no_timer_check rcupdate.rcu_expedited=1 i8042.direct=1 i8042.dumbkbd=1 i8042.nopnp=1 i8042.noaux=1 noreplace-smp reboot=k console=hvc0 console=hvc1 iommu=off cryptomgr.notests net.ifnames=0 pci=lastbus=0 root=/dev/pmem0p1 rootflags=dax,data=ordered,errors=remount-ro rw rootfstype=ext4 debug systemd.show_status=true systemd.log_level=debug" name=kata-runtime pid=19674 source=virtcontainers subsystem=qemu
time="2018-06-28T10:22:47.195633271-05:00" level=error msg="update interface request failed" arch=amd64 error="rpc error: code = Unavailable desc = transport is closing" interface-requested="device:\"eth0\" name:\"eth0\" IPAddresses:<address:\"172.17.0.2\" mask:\"16\" > mtu:1500 hwAddr:\"02:42:ac:11:00:02\" " name=kata-runtime pid=19674 resulting-interface="<nil>" source=virtcontainers subsystem=kata_agent
time="2018-06-28T10:22:47.196152023-05:00" level=error msg="rpc error: code = Unavailable desc = transport is closing" command=create name=kata-runtime pid=19674 source=runtime
time="2018-06-28T10:23:15.089836883-05:00" level=debug msg="Could not retrieve anything from storage" arch=amd64 name=kata-runtime pid=19790 source=virtcontainers subsystem=kata_agent
time="2018-06-28T10:23:15.271462122-05:00" level=debug arch=amd64 default-kernel-parameters="tsc=reliable no_timer_check rcupdate.rcu_expedited=1 i8042.direct=1 i8042.dumbkbd=1 i8042.nopnp=1 i8042.noaux=1 noreplace-smp reboot=k console=hvc0 console=hvc1 iommu=off cryptomgr.notests net.ifnames=0 pci=lastbus=0 root=/dev/pmem0p1 rootflags=dax,data=ordered,errors=remount-ro rw rootfstype=ext4 debug systemd.show_status=true systemd.log_level=debug" name=kata-runtime pid=19790 source=virtcontainers subsystem=qemu
time="2018-06-28T10:25:11.457806014-05:00" level=error msg="update interface request failed" arch=amd64 error="rpc error: code = Unavailable desc = transport is closing" interface-requested="device:\"eth0\" name:\"eth0\" IPAddresses:<address:\"172.17.0.2\" mask:\"16\" > mtu:1500 hwAddr:\"02:42:ac:11:00:02\" " name=kata-runtime pid=19790 resulting-interface="<nil>" source=virtcontainers subsystem=kata_agent
time="2018-06-28T10:25:11.458386531-05:00" level=error msg="rpc error: code = Unavailable desc = transport is closing" command=create name=kata-runtime pid=19790 source=runtime
time="2018-06-28T10:25:50.160772182-05:00" level=debug msg="Could not retrieve anything from storage" arch=amd64 name=kata-runtime pid=19959 source=virtcontainers subsystem=kata_agent
time="2018-06-28T10:25:50.3262247-05:00" level=debug arch=amd64 default-kernel-parameters="tsc=reliable no_timer_check rcupdate.rcu_expedited=1 i8042.direct=1 i8042.dumbkbd=1 i8042.nopnp=1 i8042.noaux=1 noreplace-smp reboot=k console=hvc0 console=hvc1 iommu=off cryptomgr.notests net.ifnames=0 pci=lastbus=0 root=/dev/pmem0p1 rootflags=dax,data=ordered,errors=remount-ro rw rootfstype=ext4 debug systemd.show_status=true systemd.log_level=debug" name=kata-runtime pid=19959 source=virtcontainers subsystem=qemu
time="2018-06-28T10:28:52.500068309-05:00" level=error msg="update interface request failed" arch=amd64 error="rpc error: code = Unavailable desc = transport is closing" interface-requested="device:\"eth0\" name:\"eth0\" IPAddresses:<address:\"172.17.0.2\" mask:\"16\" > mtu:1500 hwAddr:\"02:42:ac:11:00:02\" " name=kata-runtime pid=19959 resulting-interface="<nil>" source=virtcontainers subsystem=kata_agent
time="2018-06-28T10:28:52.500675842-05:00" level=error msg="rpc error: code = Unavailable desc = transport is closing" command=create name=kata-runtime pid=19959 source=runtime
time="2018-06-28T10:30:22.609788613-05:00" level=debug msg="Could not retrieve anything from storage" arch=amd64 name=kata-runtime pid=20132 source=virtcontainers subsystem=kata_agent
time="2018-06-28T10:30:22.818089348-05:00" level=debug arch=amd64 default-kernel-parameters="tsc=reliable no_timer_check rcupdate.rcu_expedited=1 i8042.direct=1 i8042.dumbkbd=1 i8042.nopnp=1 i8042.noaux=1 noreplace-smp reboot=k console=hvc0 console=hvc1 iommu=off cryptomgr.notests net.ifnames=0 pci=lastbus=0 root=/dev/pmem0p1 rootflags=dax,data=ordered,errors=remount-ro rw rootfstype=ext4 debug systemd.show_status=true systemd.log_level=debug" name=kata-runtime pid=20132 source=virtcontainers subsystem=qemu
time="2018-06-28T10:31:23.556867189-05:00" level=error msg="update interface request failed" arch=amd64 error="rpc error: code = Unavailable desc = transport is closing" interface-requested="device:\"eth0\" name:\"eth0\" IPAddresses:<address:\"172.17.0.2\" mask:\"16\" > mtu:1500 hwAddr:\"02:42:ac:11:00:02\" " name=kata-runtime pid=20132 resulting-interface="<nil>" source=virtcontainers subsystem=kata_agent
time="2018-06-28T10:31:23.557060272-05:00" level=error msg="rpc error: code = Unavailable desc = transport is closing" command=create name=kata-runtime pid=20132 source=runtime
time="2018-06-28T10:32:45.76577178-05:00" level=debug msg="Could not retrieve anything from storage" arch=amd64 name=kata-runtime pid=20625 source=virtcontainers subsystem=kata_agent
time="2018-06-28T10:32:45.949595564-05:00" level=debug arch=amd64 default-kernel-parameters="tsc=reliable no_timer_check rcupdate.rcu_expedited=1 i8042.direct=1 i8042.dumbkbd=1 i8042.nopnp=1 i8042.noaux=1 noreplace-smp reboot=k console=hvc0 console=hvc1 iommu=off cryptomgr.notests net.ifnames=0 pci=lastbus=0 root=/dev/pmem0p1 rootflags=dax,data=ordered,errors=remount-ro rw rootfstype=ext4 debug systemd.show_status=true systemd.log_level=debug" name=kata-runtime pid=20625 source=virtcontainers subsystem=qemu
time="2018-06-28T10:35:16.694604034-05:00" level=error msg="Container not ready, running or paused, impossible to signal the container" command=kill name=kata-runtime pid=20732 source=runtime
time="2018-06-28T10:35:16.83018716-05:00" level=error msg="Container 7fe6e14bd6e6e875bf0a7ffb3f95dea3132e886c309f4ba0d3674337bc226c4d not ready, running or paused, cannot send a signal" command=kill name=kata-runtime pid=20760 source=runtime
time="2018-06-28T10:37:25.274940018-05:00" level=debug msg="Could not retrieve anything from storage" arch=amd64 name=kata-runtime pid=21904 source=virtcontainers subsystem=kata_agent
time="2018-06-28T10:37:25.458426729-05:00" level=debug arch=amd64 default-kernel-parameters="tsc=reliable no_timer_check rcupdate.rcu_expedited=1 i8042.direct=1 i8042.dumbkbd=1 i8042.nopnp=1 i8042.noaux=1 noreplace-smp reboot=k console=hvc0 console=hvc1 iommu=off cryptomgr.notests net.ifnames=0 pci=lastbus=0 root=/dev/pmem0p1 rootflags=dax,data=ordered,errors=remount-ro rw rootfstype=ext4 debug systemd.show_status=true systemd.log_level=debug" name=kata-runtime pid=21904 source=virtcontainers subsystem=qemu

Proxy logs

Recent proxy problems found in system journal:

time="2018-06-28T10:15:18.211770894-05:00" level=info msg="[    0.979659] EXT4-fs (pmem0p1): DAX enabled. Warning: EXPERIMENTAL, use at your own risk\n" name=kata-proxy pid=18100 source=agent
time="2018-06-28T10:15:18.217278598-05:00" level=info msg="[    0.982115] EXT4-fs (pmem0p1): mounted filesystem with ordered data mode. Opts: dax,data=ordered,errors=remount-ro\n" name=kata-proxy pid=18100 source=agent
time="2018-06-28T10:15:18.368078525-05:00" level=info msg="[    1.135835] systemd[69]: tmp.mount: Failed to execute command: No such file or directory\n" name=kata-proxy pid=18100 source=agent
time="2018-06-28T10:15:18.394141489-05:00" level=info msg="[    1.161331] systemd-journald[72]: Failed to open configuration file '/etc/systemd/journald.conf': No such file or directory\n" name=kata-proxy pid=18100 source=agent
time="2018-06-28T10:15:18.43571356-05:00" level=info msg="[\x1b[0;1;31mFAILED\x1b[0m] Failed to mount Temporary Directory (/tmp).\n" name=kata-proxy pid=18100 source=agent
time="2018-06-28T10:15:18.441304449-05:00" level=info msg="[\x1b[0;1;33mDEPEND\x1b[0m] Dependency failed for Network Time Synchronization.\n" name=kata-proxy pid=18100 source=agent
time="2018-06-28T10:15:19.446462238-05:00" level=info msg="time=\"2018-06-28T15:15:19.312299452Z\" level=debug msg=\"request end\" duration=197.547423ms name=kata-agent pid=94 request=/grpc.AgentService/CreateSandbox resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=18100 source=agent
time="2018-06-28T10:15:19.642519954-05:00" level=info msg="time=\"2018-06-28T15:15:19.50836649Z\" level=debug msg=\"request end\" duration=129.031554ms name=kata-agent pid=94 request=/grpc.AgentService/CreateContainer resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=18100 source=agent
time="2018-06-28T10:15:19.644081559-05:00" level=info msg="time=\"2018-06-28T15:15:19.510011987Z\" level=info msg=\"ignoring unexpected signal\" name=kata-agent pid=94 signal=\"child exited\" source=agent\n" name=kata-proxy pid=18100 source=agent
time="2018-06-28T10:15:19.715680912-05:00" level=info msg="time=\"2018-06-28T15:15:19.581600599Z\" level=debug msg=\"request end\" duration=\"7.917µs\" name=kata-agent pid=94 request=/grpc.AgentService/TtyWinResize resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=18100 source=agent
time="2018-06-28T10:15:19.772101716-05:00" level=info msg="time=\"2018-06-28T15:15:19.638026704Z\" level=debug msg=\"request end\" duration=6.853667ms name=kata-agent pid=94 request=/grpc.AgentService/StartContainer resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=18100 source=agent
time="2018-06-28T10:15:19.832273035-05:00" level=info msg="time=\"2018-06-28T15:15:19.698164114Z\" level=debug msg=\"request end\" duration=\"529.576µs\" name=kata-agent pid=94 request=/grpc.AgentService/TtyWinResize resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=18100 source=agent
time="2018-06-28T10:15:26.940516119-05:00" level=info msg="time=\"2018-06-28T15:15:26.806079074Z\" level=debug msg=\"request end\" duration=\"19.666µs\" name=kata-agent pid=94 request=/grpc.AgentService/ReadStdout resp=\"data:\\\"sh: unmae: not found\\\\r\\\\n/ # \\\" \" source=agent\n" name=kata-proxy pid=18100 source=agent
time="2018-06-28T10:15:32.648088217-05:00" level=info msg="time=\"2018-06-28T15:15:32.513991309Z\" level=info msg=\"ignoring unexpected signal\" name=kata-agent pid=94 signal=\"child exited\" source=agent\n" name=kata-proxy pid=18100 source=agent
time="2018-06-28T10:15:32.656241861-05:00" level=info msg="time=\"2018-06-28T15:15:32.522134301Z\" level=debug msg=\"request end\" duration=\"20.069µs\" error=\"read /dev/ptmx: input/output error\" name=kata-agent pid=94 request=/grpc.AgentService/ReadStdout resp= source=agent\n" name=kata-proxy pid=18100 source=agent
time="2018-06-28T10:15:32.704866975-05:00" level=info msg="time=\"2018-06-28T15:15:32.570641039Z\" level=debug msg=\"request end\" duration=\"583.117µs\" name=kata-agent pid=94 request=/grpc.AgentService/SignalProcess resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=18100 source=agent
time="2018-06-28T10:15:32.708957935-05:00" level=info msg="time=\"2018-06-28T15:15:32.574861018Z\" level=debug msg=\"request end\" duration=\"800.931µs\" name=kata-agent pid=94 request=/grpc.AgentService/RemoveContainer resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=18100 source=agent
time="2018-06-28T10:15:32.868037165-05:00" level=info msg="time=\"2018-06-28T15:15:32.73391001Z\" level=debug msg=\"request end\" duration=5.194593ms name=kata-agent pid=94 request=/grpc.AgentService/DestroySandbox resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=18100 source=agent
time="2018-06-28T10:15:32.871415663-05:00" level=fatal msg="accept unix /run/vc/sbs/f2f76b02c22627630b638af11320adb1511c3f2567ce6c2a28df83dc1ea10ee7/proxy.sock: use of closed network connection" name=kata-proxy pid=18100 source=proxy
time="2018-06-28T10:32:49.560590767-05:00" level=info msg="[    0.772851] EXT4-fs (pmem0p1): DAX enabled. Warning: EXPERIMENTAL, use at your own risk\n" name=kata-proxy pid=20670 source=agent
time="2018-06-28T10:32:49.574196828-05:00" level=info msg="[    0.779708] EXT4-fs (pmem0p1): mounted filesystem with ordered data mode. Opts: dax,data=ordered,errors=remount-ro\n" name=kata-proxy pid=20670 source=agent
time="2018-06-28T10:32:49.741939579-05:00" level=info msg="[    0.955469] systemd[70]: tmp.mount: Failed to execute command: No such file or directory\n" name=kata-proxy pid=20670 source=agent
time="2018-06-28T10:32:49.778341398-05:00" level=info msg="[    0.991353] systemd-journald[73]: Failed to open configuration file '/etc/systemd/journald.conf': No such file or directory\n" name=kata-proxy pid=20670 source=agent
time="2018-06-28T10:32:49.79557347-05:00" level=info msg="[\x1b[0;1;31mFAILED\x1b[0m] Failed to mount Temporary Directory (/tmp).\n" name=kata-proxy pid=20670 source=agent
time="2018-06-28T10:32:49.798942768-05:00" level=info msg="[\x1b[0;1;33mDEPEND\x1b[0m] Dependency failed for Network Time Synchronization.\n" name=kata-proxy pid=20670 source=agent
time="2018-06-28T10:32:50.729408715-05:00" level=info msg="time=\"2018-06-28T15:32:50.619273198Z\" level=debug msg=\"request end\" duration=79.311029ms name=kata-agent pid=99 request=/grpc.AgentService/CreateSandbox resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=20670 source=agent
time="2018-06-28T10:32:51.134349568-05:00" level=info msg="time=\"2018-06-28T15:32:51.023741856Z\" level=debug msg=\"request end\" duration=327.398132ms name=kata-agent pid=99 request=/grpc.AgentService/CreateContainer resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=20670 source=agent
time="2018-06-28T10:32:51.135391777-05:00" level=info msg="time=\"2018-06-28T15:32:51.024258143Z\" level=info msg=\"ignoring unexpected signal\" name=kata-agent pid=99 signal=\"child exited\" source=agent\n" name=kata-proxy pid=20670 source=agent
time="2018-06-28T10:32:51.199461079-05:00" level=info msg="time=\"2018-06-28T15:32:51.08923335Z\" level=debug msg=\"request end\" duration=\"8.293µs\" name=kata-agent pid=99 request=/grpc.AgentService/TtyWinResize resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=20670 source=agent
time="2018-06-28T10:32:51.265513993-05:00" level=info msg="time=\"2018-06-28T15:32:51.15515233Z\" level=debug msg=\"request end\" duration=3.36621ms name=kata-agent pid=99 request=/grpc.AgentService/StartContainer resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=20670 source=agent
time="2018-06-28T10:32:51.328328221-05:00" level=info msg="time=\"2018-06-28T15:32:51.218168237Z\" level=debug msg=\"request end\" duration=\"899.272µs\" name=kata-agent pid=99 request=/grpc.AgentService/TtyWinResize resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=20670 source=agent
time="2018-06-28T10:33:03.976655671-05:00" level=info msg="time=\"2018-06-28T15:33:03.86648054Z\" level=debug msg=\"request end\" duration=\"46.467µs\" name=kata-agent pid=99 request=/grpc.AgentService/TtyWinResize resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=20670 source=agent
time="2018-06-28T10:33:05.073398949-05:00" level=info msg="time=\"2018-06-28T15:33:04.96322536Z\" level=debug msg=\"request end\" duration=\"56.209µs\" name=kata-agent pid=99 request=/grpc.AgentService/TtyWinResize resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=20670 source=agent
time="2018-06-28T10:35:16.582567485-05:00" level=info msg="time=\"2018-06-28T15:35:16.472346875Z\" level=debug msg=\"request end\" duration=2m11.505451364s error=\"read /dev/ptmx: input/output error\" name=kata-agent pid=99 request=/grpc.AgentService/ReadStdout resp= source=agent\n" name=kata-proxy pid=20670 source=agent
time="2018-06-28T10:35:16.591933458-05:00" level=info msg="time=\"2018-06-28T15:35:16.48178396Z\" level=info msg=\"ignoring unexpected signal\" name=kata-agent pid=99 signal=\"child exited\" source=agent\n" name=kata-proxy pid=20670 source=agent
time="2018-06-28T10:35:16.636730101-05:00" level=info msg="time=\"2018-06-28T15:35:16.526590145Z\" level=debug msg=\"request end\" duration=2.751868ms name=kata-agent pid=99 request=/grpc.AgentService/SignalProcess resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=20670 source=agent
time="2018-06-28T10:35:16.64232345-05:00" level=info msg="time=\"2018-06-28T15:35:16.530095096Z\" level=debug msg=\"request end\" duration=\"609.892µs\" name=kata-agent pid=99 request=/grpc.AgentService/RemoveContainer resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=20670 source=agent
time="2018-06-28T10:35:16.876332262-05:00" level=info msg="time=\"2018-06-28T15:35:16.765713167Z\" level=debug msg=\"request end\" duration=5.790204ms name=kata-agent pid=99 request=/grpc.AgentService/DestroySandbox resp=\"&Empty{}\" source=agent\n" name=kata-proxy pid=20670 source=agent
time="2018-06-28T10:35:16.879379076-05:00" level=fatal msg="accept unix /run/vc/sbs/7fe6e14bd6e6e875bf0a7ffb3f95dea3132e886c309f4ba0d3674337bc226c4d/proxy.sock: use of closed network connection" name=kata-proxy pid=20670 source=proxy

Shim logs

Recent shim problems found in system journal:

time="2018-06-28T10:15:32.657170553-05:00" level=info msg="copy stdout failed" container=f2f76b02c22627630b638af11320adb1511c3f2567ce6c2a28df83dc1ea10ee7 error="rpc error: code = Unknown desc = read /dev/ptmx: input/output error" exec-id=f2f76b02c22627630b638af11320adb1511c3f2567ce6c2a28df83dc1ea10ee7 name=kata-shim pid=1 source=shim
time="2018-06-28T10:35:16.583320324-05:00" level=info msg="copy stdout failed" container=7fe6e14bd6e6e875bf0a7ffb3f95dea3132e886c309f4ba0d3674337bc226c4d error="rpc error: code = Unknown desc = read /dev/ptmx: input/output error" exec-id=7fe6e14bd6e6e875bf0a7ffb3f95dea3132e886c309f4ba0d3674337bc226c4d name=kata-shim pid=1 source=shim

---

Container manager details

Have docker

Docker

Output of "docker version":

Client:
 Version:      18.03.1-ce
 API version:  1.37
 Go version:   go1.9.5
 Git commit:   9ee9f40
 Built:        Thu Apr 26 07:19:31 2018
 OS/Arch:      linux/amd64
 Experimental: false
 Orchestrator: swarm

Server:
 Engine:
  Version:      18.03.1-ce
  API version:  1.37 (minimum version 1.12)
  Go version:   go1.9.5
  Git commit:   9ee9f40
  Built:        Thu Apr 26 07:23:21 2018
  OS/Arch:      linux/amd64
  Experimental: false

Output of "docker info":

Containers: 8
 Running: 0
 Paused: 0
 Stopped: 8
Images: 1
Server Version: 18.03.1-ce
Storage Driver: overlay2
 Backing Filesystem: extfs
 Supports d_type: true
 Native Overlay Diff: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
 Volume: local
 Network: bridge host macvlan null overlay
 Log: awslogs fluentd gcplogs gelf journald json-file logentries splunk syslog
Swarm: inactive
Runtimes: runc kata-runtime
Default Runtime: kata-runtime
Init Binary: docker-init
containerd version: 773c489c9c1b21a6d78b5c538cd395416ec50f88
runc version: 93775487c8c205a399fb4abb2a3940336098e380-dirty (expected: 4fc53a81fb7c994640722ac585fa9ca548971871)
init version: 949e6fa
Security Options:
 seccomp
  Profile: default
Kernel Version: 4.16.13-300.fc28.x86_64
Operating System: Fedora 28 (Workstation Edition)
OSType: linux
Architecture: x86_64
CPUs: 4
Total Memory: 15.59GiB
Name: jcvenega-nuc.zpn.intel.com
ID: GHP7:C7Q7:66J3:TLLY:3YAZ:PZRK:7LSM:NYUX:ZVKX:AWT3:575R:4KBJ
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): true
 File Descriptors: 29
 Goroutines: 57
 System Time: 2018-06-28T10:39:17.208600069-05:00
 EventsListeners: 0
Registry: https://index.docker.io/v1/
Labels:
Experimental: false
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false

Output of "systemctl show docker":

Type=notify
Restart=on-failure
NotifyAccess=main
RestartUSec=100ms
TimeoutStartUSec=infinity
TimeoutStopUSec=1min 30s
RuntimeMaxUSec=infinity
WatchdogUSec=0
WatchdogTimestamp=Thu 2018-06-28 10:14:19 CDT
WatchdogTimestampMonotonic=1901887364153
PermissionsStartOnly=no
RootDirectoryStartOnly=no
RemainAfterExit=no
GuessMainPID=yes
MainPID=17679
ControlPID=0
FileDescriptorStoreMax=0
NFileDescriptorStore=0
StatusErrno=0
Result=success
UID=[not set]
GID=[not set]
NRestarts=0
ExecMainStartTimestamp=Thu 2018-06-28 10:14:17 CDT
ExecMainStartTimestampMonotonic=1901885900959
ExecMainExitTimestampMonotonic=0
ExecMainPID=17679
ExecMainCode=0
ExecMainStatus=0
ExecStart={ path=/usr/bin/dockerd ; argv[]=/usr/bin/dockerd -D --add-runtime kata-runtime=/usr/local/bin/kata-runtime --default-runtime=kata-runtime --storage-driver=overlay2 ; ignore_errors=no ; start_time=[Thu 2018-06-28 10:14:17 CDT] ; stop_time=[n/a] ; pid=17679 ; code=(null) ; status=0/0 }
ExecReload={ path=/bin/kill ; argv[]=/bin/kill -s HUP $MAINPID ; ignore_errors=no ; start_time=[n/a] ; stop_time=[n/a] ; pid=0 ; code=(null) ; status=0/0 }
Slice=system.slice
ControlGroup=/system.slice/docker.service
MemoryCurrent=263172096
CPUUsageNSec=[not set]
TasksCurrent=65
IPIngressBytes=18446744073709551615
IPIngressPackets=18446744073709551615
IPEgressBytes=18446744073709551615
IPEgressPackets=18446744073709551615
Delegate=yes
DelegateControllers=cpu cpuacct io blkio memory devices pids
CPUAccounting=no
CPUWeight=[not set]
StartupCPUWeight=[not set]
CPUShares=[not set]
StartupCPUShares=[not set]
CPUQuotaPerSecUSec=infinity
IOAccounting=no
IOWeight=[not set]
StartupIOWeight=[not set]
BlockIOAccounting=no
BlockIOWeight=[not set]
StartupBlockIOWeight=[not set]
MemoryAccounting=yes
MemoryLow=0
MemoryHigh=infinity
MemoryMax=infinity
MemorySwapMax=infinity
MemoryLimit=infinity
DevicePolicy=auto
TasksAccounting=yes
TasksMax=infinity
IPAccounting=no
UMask=0022
LimitCPU=infinity
LimitCPUSoft=infinity
LimitFSIZE=infinity
LimitFSIZESoft=infinity
LimitDATA=infinity
LimitDATASoft=infinity
LimitSTACK=infinity
LimitSTACKSoft=8388608
LimitCORE=infinity
LimitCORESoft=infinity
LimitRSS=infinity
LimitRSSSoft=infinity
LimitNOFILE=infinity
LimitNOFILESoft=infinity
LimitAS=infinity
LimitASSoft=infinity
LimitNPROC=infinity
LimitNPROCSoft=infinity
LimitMEMLOCK=16777216
LimitMEMLOCKSoft=16777216
LimitLOCKS=infinity
LimitLOCKSSoft=infinity
LimitSIGPENDING=62823
LimitSIGPENDINGSoft=62823
LimitMSGQUEUE=819200
LimitMSGQUEUESoft=819200
LimitNICE=0
LimitNICESoft=0
LimitRTPRIO=0
LimitRTPRIOSoft=0
LimitRTTIME=infinity
LimitRTTIMESoft=infinity
OOMScoreAdjust=0
Nice=0
IOSchedulingClass=0
IOSchedulingPriority=0
CPUSchedulingPolicy=0
CPUSchedulingPriority=0
TimerSlackNSec=50000
CPUSchedulingResetOnFork=no
NonBlocking=no
StandardInput=null
StandardInputData=
StandardOutput=journal
StandardError=inherit
TTYReset=no
TTYVHangup=no
TTYVTDisallocate=no
SyslogPriority=30
SyslogLevelPrefix=yes
SyslogLevel=6
SyslogFacility=3
LogLevelMax=-1
SecureBits=0
CapabilityBoundingSet=cap_chown cap_dac_override cap_dac_read_search cap_fowner cap_fsetid cap_kill cap_setgid cap_setuid cap_setpcap cap_linux_immutable cap_net_bind_service cap_net_broadcast cap_net_admin cap_net_raw cap_ipc_lock cap_ipc_owner cap_sys_module cap_sys_rawio cap_sys_chroot cap_sys_ptrace cap_sys_pacct cap_sys_admin cap_sys_boot cap_sys_nice cap_sys_resource cap_sys_time cap_sys_tty_config cap_mknod cap_lease cap_audit_write cap_audit_control cap_setfcap cap_mac_override cap_mac_admin cap_syslog cap_wake_alarm cap_block_suspend
AmbientCapabilities=
DynamicUser=no
RemoveIPC=no
MountFlags=
PrivateTmp=no
PrivateDevices=no
ProtectKernelTunables=no
ProtectKernelModules=no
ProtectControlGroups=no
PrivateNetwork=no
PrivateUsers=no
ProtectHome=no
ProtectSystem=no
SameProcessGroup=no
UtmpMode=init
IgnoreSIGPIPE=yes
NoNewPrivileges=no
SystemCallErrorNumber=0
LockPersonality=no
RuntimeDirectoryPreserve=no
RuntimeDirectoryMode=0755
StateDirectoryMode=0755
CacheDirectoryMode=0755
LogsDirectoryMode=0755
ConfigurationDirectoryMode=0755
MemoryDenyWriteExecute=no
RestrictRealtime=no
RestrictNamespaces=no
MountAPIVFS=no
KeyringMode=private
KillMode=process
KillSignal=15
SendSIGKILL=yes
SendSIGHUP=no
Id=docker.service
Names=docker.service
Requires=sysinit.target system.slice
Wants=network-online.target
WantedBy=multi-user.target
Conflicts=shutdown.target
Before=shutdown.target multi-user.target
After=systemd-journald.socket network-online.target firewalld.service system.slice sysinit.target basic.target
Documentation=https://docs.docker.com
Description=Docker Application Container Engine
LoadState=loaded
ActiveState=active
SubState=running
FragmentPath=/usr/lib/systemd/system/docker.service
DropInPaths=/etc/systemd/system/docker.service.d/kata-containers.conf
UnitFileState=enabled
UnitFilePreset=disabled
StateChangeTimestamp=Thu 2018-06-28 10:14:19 CDT
StateChangeTimestampMonotonic=1901887364155
InactiveExitTimestamp=Thu 2018-06-28 10:14:17 CDT
InactiveExitTimestampMonotonic=1901885901021
ActiveEnterTimestamp=Thu 2018-06-28 10:14:19 CDT
ActiveEnterTimestampMonotonic=1901887364155
ActiveExitTimestamp=Thu 2018-06-28 10:13:54 CDT
ActiveExitTimestampMonotonic=1901863061048
InactiveEnterTimestamp=Thu 2018-06-28 10:13:55 CDT
InactiveEnterTimestampMonotonic=1901864085578
CanStart=yes
CanStop=yes
CanReload=yes
CanIsolate=no
StopWhenUnneeded=no
RefuseManualStart=no
RefuseManualStop=no
AllowIsolate=no
DefaultDependencies=yes
OnFailureJobMode=replace
IgnoreOnIsolate=no
NeedDaemonReload=no
JobTimeoutUSec=infinity
JobRunningTimeoutUSec=infinity
JobTimeoutAction=none
ConditionResult=yes
AssertResult=yes
ConditionTimestamp=Thu 2018-06-28 10:14:17 CDT
ConditionTimestampMonotonic=1901885899246
AssertTimestamp=Thu 2018-06-28 10:14:17 CDT
AssertTimestampMonotonic=1901885899247
Transient=no
Perpetual=no
StartLimitIntervalUSec=1min
StartLimitBurst=3
StartLimitAction=none
FailureAction=none
SuccessAction=none
InvocationID=e9a9ed0046394bc08f5493ea6dd4387a
CollectMode=inactive

No kubectl

---

Packages

Have dpkg
Output of "dpkg -l|egrep "(cc-oci-runtimecc-runtimerunv|kata-proxy|kata-runtime|kata-shim|kata-containers-image|linux-container|qemu-)"":

Have rpm
Output of "rpm -qa|egrep "(cc-oci-runtimecc-runtimerunv|kata-proxy|kata-runtime|kata-shim|kata-containers-image|linux-container|qemu-)"":

qemu-common-2.11.1-2.fc28.x86_64
qemu-block-ssh-2.11.1-2.fc28.x86_64
qemu-block-dmg-2.11.1-2.fc28.x86_64
qemu-lite-2.11.0+git.6ba2bfbee9-43.1.x86_64
qemu-block-iscsi-2.11.1-2.fc28.x86_64
qemu-block-gluster-2.11.1-2.fc28.x86_64
qemu-lite-bin-2.11.0+git.6ba2bfbee9-43.1.x86_64
qemu-system-x86-core-2.11.1-2.fc28.x86_64
qemu-block-nfs-2.11.1-2.fc28.x86_64
ipxe-roms-qemu-20170710-3.git0600d3ae.fc28.noarch
qemu-lite-data-2.11.0+git.6ba2bfbee9-43.1.x86_64
qemu-block-curl-2.11.1-2.fc28.x86_64
libvirt-daemon-driver-qemu-4.1.0-2.fc28.x86_64
qemu-guest-agent-2.11.1-2.fc28.x86_64
qemu-system-x86-2.11.1-2.fc28.x86_64
qemu-block-rbd-2.11.1-2.fc28.x86_64
qemu-img-2.11.1-2.fc28.x86_64
kata-containers-image-1.0.0-29.1.x86_64
qemu-kvm-2.11.1-2.fc28.x86_64

---

[jcvenegas]

I was able to get a container working using qemu-vanilla probably something is missing in qemu-lite...

[jcvenegas]

ok , I just tested using an old qemu-lite version (2.7) and it works.

[jcvenegas]

@anthonyzxu ping

[anthonyzxu]

@jcvenegas
Ying Liu will take a look at this issue.

[liujing2]

I will take a look at this issue.