jcvenegas
commented
6 years ago I think would be good to get more kata-proxy logs here to see what happens with the VM boot.
journalctl -t kata-proxyClosed ghost closed 6 years ago
jcvenegas
commented
6 years ago I think would be good to get more kata-proxy logs here to see what happens with the VM boot.
journalctl -t kata-proxy
ghost
commented
6 years ago Unfortunately, I just see this
Sep 05 15:59:41 lxkarta1 kata-proxy[2740]: time="2018-09-05T15:59:41.726238101-04:00" level=fatal msg="failed to dial channel" channel=/run/vc/
Sep 05 16:01:41 lxkarta1 kata-proxy[2944]: time="2018-09-05T16:01:41.808379444-04:00" level=fatal msg="failed to dial channel" channel=/run/vc/
Sep 05 16:05:36 lxkarta1 kata-proxy[3708]: time="2018-09-05T16:05:36.811051744-04:00" level=fatal msg="failed to dial channel" channel=/run/vc/
Sep 05 16:10:03 lxkarta1 kata-proxy[4032]: time="2018-09-05T16:10:03.050223439-04:00" level=fatal msg="failed to dial channel" channel=/run/vc/
Sep 05 16:14:06 lxkarta1 kata-proxy[4623]: time="2018-09-05T16:14:06.492174987-04:00" level=fatal msg="failed to dial channel" channel=/run/vc/```
caoruidong
commented
6 years ago See this several times, you can take a look at #516 #576 https://github.com/kata-containers/runtime/issues/626
jodh-intel
commented
6 years ago Hi @ydjainopensource - A few things:
The output of kata-collect-data.sh isn't showing any details for your configured initrd. That 's a little odd - could it be a permissions issue? Either way, it suggests we might need to update https://github.com/kata-containers/runtime/blob/master/data/kata-collect-data.sh.in somehow.
genericGetCPUDetails() needs updating to resolve the cannot find model field in file /proc/cpuinfo error from kata-env.
You haven't enabled the all-important debug options to get more log output :)
https://github.com/kata-containers/documentation/blob/master/Developer-Guide.md#enable-full-debug
fredbcode
commented
6 years ago Same issue here with ubuntu 18.04, it's like a kind of timeout, sometimes it works, sometimes not
kata-runtime 1.3.0~rc1
docker run -d -ti --runtime kata-runtime my.registry/images/apache 68a8a0f1b26665b8f3cea92e9ec22b0e1fa4d8419fb77376ecd0bafd6e9d3856 docker: Error response from daemon: OCI runtime create failed: Failed to check if grpc server is working: rpc error: code = DeadlineExceeded desc = context deadline exceeded: unknown.
Right after:
docker run -d -ti --runtime kata-runtime my.registry/images/images/apache 54b8a667253de80cd713e9aa5699be26eb42ddc920d718b67854be276c43de49
grahamwhaley
commented
6 years ago Right - the DeadlineExceeded appears in the code base 3 times, all in the agent:
https://github.com/search?q=org%3Akata-containers+DeadlineExceeded&type=Code
/cc @sboeuf @devimc @bergwolf - input welcome here.
jodh-intel
commented
6 years ago If those affected could please:
sudo kata-collect-data.sh and paste output here (after checking it for sensitive info).The OP was running on a new architecture which hasn't landed in master yet (see #667). Hence, the more data points we can get, the easier it is going to be for us to fix ;)
grahamwhaley
commented
6 years ago There is a related mention over on https://github.com/kata-containers/tests/pull/766#issuecomment-423551314 from me. I was running parallel launches. Before I can paste more details here I need to re-create, as I think my docker/runtime install is a little bust at the moment (updated after I'd see the error).
jcvenegas
commented
6 years ago This makes me think the agent sometimes is taking longer to start to serve grpc calls. Agree would be helpful get kata-collect-data.sh info or when it fails collect the proxy logs and see the boot log.
jodh-intel
commented
6 years ago Wait, if only we had agent tracing ...! :smile:
devimc
commented
6 years ago @fredbcode please try with vsocks
fredbcode
commented
6 years ago @devimc how ?
I will post debug monday
devimc
commented
6 years ago fredbcode
commented
6 years ago @devimc not better, but when it works seems more faster than before
docker run -d -ti --name test1 --runtime kata-runtime app_apache 27944e17a8b888cf47b840920f25d6868c5aaefc26776a3126614f42697d4588 docker run -d -ti --name test2 --runtime kata-runtime app_apache f4dd677761e96aceea9989d6328af799451bfa62af3b0d44173c0daa531b3269 run -d -ti --name test3 --runtime kata-runtime app_apache 54fed571efb006623ffb2aa361e41da20c663917b686097e19b4d8940b263947 docker: Error response from daemon: OCI runtime create failed: Failed to check if grpc server is working: context deadline exceeded: unknown.
I will provide full debug logs
fredbcode
commented
6 years ago Fresh reboot, all images removed, without vsocks, ubuntu 18.04 fresh install: As you can see, it's a "random" problem test 3 ko but 4 ok
Test 1 OK docker run -d -ti --name test --runtime kata-runtime registry.test/images/nginx Unable to find image 'registry.test/images/nginx:latest' locally latest: Pulling from images/nginx 50513f4bae65: Pull complete 854cd4146cdf: Pull complete 3aa6df3c928d: Pull complete 3bcf156a92e8: Pull complete 10de78edcdec: Pull complete 1a7902332604: Pull complete 91da1c491187: Pull complete f6fe36c00817: Pull complete 37141a578bef: Pull complete 4886095a776d: Pull complete 56e5abc2fd85: Pull complete Digest: sha256:1653381caf2c825d755f9da158276df6759d97c51c6401e7cb9ae42ea73b2e7c Status: Downloaded newer image for registry.test/images/nginx:latest 2c4098b53fd95498752c35a478d39d3ad39b7836a183375a4485f130da228331
Test 2 Ok
docker run -d -ti --name test1 --runtime kata-runtime registry.test/images/nginx 7e89bf81fa37acd2ad17e036429df4f71689ccf5e31e4e1660a5b026653896d3
Test 3 Ko
docker run -d -ti --name test2 --runtime kata-runtime registry.test/images/nginx fb0de29f564b2f1bac243fe6bc12236cfa85e8fa9916abd3aa6e28c57f358b32 docker: Error response from daemon: OCI runtime create failed: Failed to check if grpc server is working: rpc error: code = DeadlineExceeded desc = context deadline exceeded: unknown.
Test 4 Ok
docker run -d -ti --name test3 --runtime kata-runtime registry.test/images/nginx a7c489bf0009eb6dc3f5fb9d17b84049bb9b0f06e4b7bae2a97b34c650811a98
Running kata-collect-data.sh version 1.3.0-rc1 (commit 22aedc4) at 2018-09-24.07:07:40.237805999+0000.
Runtime is /usr/bin/kata-runtime.
kata-envOutput of "/usr/bin/kata-runtime kata-env":
[Meta]
Version = "1.0.15"
[Runtime]
Debug = true
Path = "/usr/bin/kata-runtime"
[Runtime.Version]
Semver = "1.3.0-rc1"
Commit = "22aedc4"
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 = true
UseVSock = false
[Image]
Path = "/usr/share/kata-containers/kata-containers-image_clearlinux_1.3.0-rc1_agent_1ee972176ae.img"
[Kernel]
Path = "/usr/share/kata-containers/vmlinuz-4.14.67.11-137.container"
Parameters = ""
[Initrd]
Path = ""
[Proxy]
Type = "kataProxy"
Version = "kata-proxy version 1.3.0-rc1-981fef4"
Path = "/usr/libexec/kata-containers/kata-proxy"
Debug = true
[Shim]
Type = "kataShim"
Version = "kata-shim version 1.3.0-rc1-9b2891c"
Path = "/usr/libexec/kata-containers/kata-shim"
Debug = true
[Agent]
Type = "kata"
[Host]
Kernel = "4.15.0-34-generic"
Architecture = "amd64"
VMContainerCapable = true
SupportVSocks = false
[Host.Distro]
Name = "Ubuntu"
Version = "18.04"
[Host.CPU]
Vendor = "GenuineIntel"
Model = "Intel(R) Xeon(R) CPU E5-2609 v4 @ 1.70GHz"/etc/kata-containers/configuration.toml
/usr/share/defaults/kata-containers/configuration.tomlConfig 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 = ""
# 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
# If true and vsocks are supported, use vsocks to communicate directly
# with the agent and no proxy is started, otherwise use unix
# sockets and start a proxy to communicate with the agent.
# Default false
#use_vsock = true
# VFIO devices are hotplugged on a bridge by default.
# Enable hotplugging on root bus. This may be required for devices with
# a large PCI bar, as this is a current limitation with hotplugging on
# a bridge. This value is valid for "pc" machine type.
# Default false
#hotplug_vfio_on_root_bus = true
[factory]
# VM templating support. Once enabled, new VMs are created from template
# using vm cloning. They will share the same initial kernel, initramfs and
# agent memory by mapping it readonly. It helps speeding up new container
# creation and saves a lot of memory if there are many kata containers running
# on the same host.
#
# When disabled, new VMs are created from scratch.
#
# Default false
#enable_template = true
[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"
# If enabled, the runtime will create opentracing.io traces and spans.
# (See https://www.jaegertracing.io/docs/getting-started).
# (default: disabled)
#enable_tracing = true---
osbuilder:
url: "https://github.com/kata-containers/osbuilder"
version: "unknown"
rootfs-creation-time: "2018-09-13T22:26:12.472554196+0000Z"
description: "osbuilder rootfs"
file-format-version: "0.0.2"
architecture: "x86_64"
base-distro:
name: "Clear"
version: "25000"
packages:
default:
- "iptables-bin"
- "libudev0-shim"
- "systemd"
extra:
agent:
url: "https://github.com/kata-containers/agent"
name: "kata-agent"
version: "1.3.0-rc1-1ee972176ae437bcace0a37227818c506bb64ba9"
agent-is-init-daemon: "no"No initrd
Recent runtime problems found in system journal:
time="2018-09-24T06:44:12.680892011Z" level=debug arch=amd64 command=create container=de89365281abdd79a632c2b36adf200813f3226fa271adaddf670d4ba53daba5 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=4652 source=virtcontainers subsystem=qemu
time="2018-09-24T06:44:13.687205476Z" level=debug msg="Could not retrieve anything from storage" arch=amd64 command=create container=2f86d6ed7b2b38bf36abfc760252775535eba1f7b82d018e88ef1e520e435779 name=kata-runtime pid=4702 source=virtcontainers subsystem=kata_agent
time="2018-09-24T06:44:13.687307269Z" level=warning msg="fetch sandbox device failed" arch=amd64 command=create container=2f86d6ed7b2b38bf36abfc760252775535eba1f7b82d018e88ef1e520e435779 error="open /run/vc/sbs/2f86d6ed7b2b38bf36abfc760252775535eba1f7b82d018e88ef1e520e435779/devices.json: no such file or directory" name=kata-runtime pid=4702 sandbox=2f86d6ed7b2b38bf36abfc760252775535eba1f7b82d018e88ef1e520e435779 sandboxid=2f86d6ed7b2b38bf36abfc760252775535eba1f7b82d018e88ef1e520e435779 source=virtcontainers subsystem=sandbox
time="2018-09-24T06:44:13.690556476Z" level=debug arch=amd64 command=create container=2f86d6ed7b2b38bf36abfc760252775535eba1f7b82d018e88ef1e520e435779 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=4702 source=virtcontainers subsystem=qemu
time="2018-09-24T06:44:14.805481468Z" level=debug msg="Could not retrieve anything from storage" arch=amd64 command=create container=dcc8fd7c1abcadb1edb4de15428cf4cd0fc9ffb7f42eef98c1bbdbc3ac9cfe3f name=kata-runtime pid=4965 source=virtcontainers subsystem=kata_agent
time="2018-09-24T06:44:14.805577998Z" level=warning msg="fetch sandbox device failed" arch=amd64 command=create container=dcc8fd7c1abcadb1edb4de15428cf4cd0fc9ffb7f42eef98c1bbdbc3ac9cfe3f error="open /run/vc/sbs/dcc8fd7c1abcadb1edb4de15428cf4cd0fc9ffb7f42eef98c1bbdbc3ac9cfe3f/devices.json: no such file or directory" name=kata-runtime pid=4965 sandbox=dcc8fd7c1abcadb1edb4de15428cf4cd0fc9ffb7f42eef98c1bbdbc3ac9cfe3f sandboxid=dcc8fd7c1abcadb1edb4de15428cf4cd0fc9ffb7f42eef98c1bbdbc3ac9cfe3f source=virtcontainers subsystem=sandbox
time="2018-09-24T06:44:14.808745128Z" level=debug arch=amd64 command=create container=dcc8fd7c1abcadb1edb4de15428cf4cd0fc9ffb7f42eef98c1bbdbc3ac9cfe3f 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=4965 source=virtcontainers subsystem=qemu
time="2018-09-24T06:44:27.920837721Z" level=error msg="Failed to check if grpc server is working: context deadline exceeded" arch=amd64 command=create container=de89365281abdd79a632c2b36adf200813f3226fa271adaddf670d4ba53daba5 name=kata-runtime pid=4652 source=runtime
time="2018-09-24T06:47:01.085960002Z" level=error msg="Container 2f86d6ed7b2b38bf36abfc760252775535eba1f7b82d018e88ef1e520e435779 not ready, running or paused, cannot send a signal" arch=amd64 command=kill container=2f86d6ed7b2b38bf36abfc760252775535eba1f7b82d018e88ef1e520e435779 name=kata-runtime pid=5479 sandbox=2f86d6ed7b2b38bf36abfc760252775535eba1f7b82d018e88ef1e520e435779 source=runtime
time="2018-09-24T06:47:01.109476359Z" level=error msg="Container 62990ae0f153ffd7b0678a8a08ba6030c9d73748a4efb23767404f32deebb066 not ready, running or paused, cannot send a signal" arch=amd64 command=kill container=62990ae0f153ffd7b0678a8a08ba6030c9d73748a4efb23767404f32deebb066 name=kata-runtime pid=5489 sandbox=62990ae0f153ffd7b0678a8a08ba6030c9d73748a4efb23767404f32deebb066 source=runtime
time="2018-09-24T06:47:01.150488311Z" level=error msg="Container 2f86d6ed7b2b38bf36abfc760252775535eba1f7b82d018e88ef1e520e435779 not ready, running or paused, cannot send a signal" arch=amd64 command=kill container=2f86d6ed7b2b38bf36abfc760252775535eba1f7b82d018e88ef1e520e435779 name=kata-runtime pid=5523 sandbox=2f86d6ed7b2b38bf36abfc760252775535eba1f7b82d018e88ef1e520e435779 source=runtime
time="2018-09-24T06:47:01.171963441Z" level=error msg="Container 62990ae0f153ffd7b0678a8a08ba6030c9d73748a4efb23767404f32deebb066 not ready, running or paused, cannot send a signal" arch=amd64 command=kill container=62990ae0f153ffd7b0678a8a08ba6030c9d73748a4efb23767404f32deebb066 name=kata-runtime pid=5554 sandbox=62990ae0f153ffd7b0678a8a08ba6030c9d73748a4efb23767404f32deebb066 source=runtime
time="2018-09-24T06:47:11.143719309Z" level=error msg="Container dcc8fd7c1abcadb1edb4de15428cf4cd0fc9ffb7f42eef98c1bbdbc3ac9cfe3f not ready, running or paused, cannot send a signal" arch=amd64 command=kill container=dcc8fd7c1abcadb1edb4de15428cf4cd0fc9ffb7f42eef98c1bbdbc3ac9cfe3f name=kata-runtime pid=5629 sandbox=dcc8fd7c1abcadb1edb4de15428cf4cd0fc9ffb7f42eef98c1bbdbc3ac9cfe3f source=runtime
time="2018-09-24T06:47:11.211454843Z" level=error msg="Container dcc8fd7c1abcadb1edb4de15428cf4cd0fc9ffb7f42eef98c1bbdbc3ac9cfe3f not ready, running or paused, cannot send a signal" arch=amd64 command=kill container=dcc8fd7c1abcadb1edb4de15428cf4cd0fc9ffb7f42eef98c1bbdbc3ac9cfe3f name=kata-runtime pid=5663 sandbox=dcc8fd7c1abcadb1edb4de15428cf4cd0fc9ffb7f42eef98c1bbdbc3ac9cfe3f source=runtime
time="2018-09-24T06:47:11.213350994Z" level=error msg="Container 1060184190ac986a768f409ce3a0a6861c1fb3cdaba06e90df4f070663075b09 not ready, running or paused, cannot send a signal" arch=amd64 command=kill container=1060184190ac986a768f409ce3a0a6861c1fb3cdaba06e90df4f070663075b09 name=kata-runtime pid=5664 sandbox=1060184190ac986a768f409ce3a0a6861c1fb3cdaba06e90df4f070663075b09 source=runtime
time="2018-09-24T06:47:11.235923491Z" level=error msg="Container 501ad5e238b78dee18e7d003457b2a391e8389ee353c761abc2112bede8cee74 not ready, running or paused, cannot send a signal" arch=amd64 command=kill container=501ad5e238b78dee18e7d003457b2a391e8389ee353c761abc2112bede8cee74 name=kata-runtime pid=5686 sandbox=501ad5e238b78dee18e7d003457b2a391e8389ee353c761abc2112bede8cee74 source=runtime
time="2018-09-24T06:47:11.276808066Z" level=error msg="Container 1060184190ac986a768f409ce3a0a6861c1fb3cdaba06e90df4f070663075b09 not ready, running or paused, cannot send a signal" arch=amd64 command=kill container=1060184190ac986a768f409ce3a0a6861c1fb3cdaba06e90df4f070663075b09 name=kata-runtime pid=5730 sandbox=1060184190ac986a768f409ce3a0a6861c1fb3cdaba06e90df4f070663075b09 source=runtime
time="2018-09-24T06:47:11.299574911Z" level=error msg="Container 501ad5e238b78dee18e7d003457b2a391e8389ee353c761abc2112bede8cee74 not ready, running or paused, cannot send a signal" arch=amd64 command=kill container=501ad5e238b78dee18e7d003457b2a391e8389ee353c761abc2112bede8cee74 name=kata-runtime pid=5764 sandbox=501ad5e238b78dee18e7d003457b2a391e8389ee353c761abc2112bede8cee74 source=runtime
time="2018-09-24T06:48:12.533449065Z" level=debug msg="Could not retrieve anything from storage" arch=amd64 command=create container=9009bbf50ff4ceb5adec4532218669e9033676e0119836af36ee699bf75f3782 name=kata-runtime pid=5892 source=virtcontainers subsystem=kata_agent
time="2018-09-24T06:48:12.533542692Z" level=warning msg="fetch sandbox device failed" arch=amd64 command=create container=9009bbf50ff4ceb5adec4532218669e9033676e0119836af36ee699bf75f3782 error="open /run/vc/sbs/9009bbf50ff4ceb5adec4532218669e9033676e0119836af36ee699bf75f3782/devices.json: no such file or directory" name=kata-runtime pid=5892 sandbox=9009bbf50ff4ceb5adec4532218669e9033676e0119836af36ee699bf75f3782 sandboxid=9009bbf50ff4ceb5adec4532218669e9033676e0119836af36ee699bf75f3782 source=virtcontainers subsystem=sandbox
time="2018-09-24T06:48:12.536570913Z" level=debug arch=amd64 command=create container=9009bbf50ff4ceb5adec4532218669e9033676e0119836af36ee699bf75f3782 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=5892 source=virtcontainers subsystem=qemu
time="2018-09-24T06:49:29.189437696Z" level=debug msg="Could not retrieve anything from storage" arch=amd64 command=create container=27944e17a8b888cf47b840920f25d6868c5aaefc26776a3126614f42697d4588 name=kata-runtime pid=6131 source=virtcontainers subsystem=kata_agent
time="2018-09-24T06:49:29.189519192Z" level=warning msg="fetch sandbox device failed" arch=amd64 command=create container=27944e17a8b888cf47b840920f25d6868c5aaefc26776a3126614f42697d4588 error="open /run/vc/sbs/27944e17a8b888cf47b840920f25d6868c5aaefc26776a3126614f42697d4588/devices.json: no such file or directory" name=kata-runtime pid=6131 sandbox=27944e17a8b888cf47b840920f25d6868c5aaefc26776a3126614f42697d4588 sandboxid=27944e17a8b888cf47b840920f25d6868c5aaefc26776a3126614f42697d4588 source=virtcontainers subsystem=sandbox
time="2018-09-24T06:49:29.192601809Z" level=debug arch=amd64 command=create container=27944e17a8b888cf47b840920f25d6868c5aaefc26776a3126614f42697d4588 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=6131 source=virtcontainers subsystem=qemu
time="2018-09-24T06:49:42.797421508Z" level=debug msg="Could not retrieve anything from storage" arch=amd64 command=create container=f4dd677761e96aceea9989d6328af799451bfa62af3b0d44173c0daa531b3269 name=kata-runtime pid=6283 source=virtcontainers subsystem=kata_agent
time="2018-09-24T06:49:42.797518278Z" level=warning msg="fetch sandbox device failed" arch=amd64 command=create container=f4dd677761e96aceea9989d6328af799451bfa62af3b0d44173c0daa531b3269 error="open /run/vc/sbs/f4dd677761e96aceea9989d6328af799451bfa62af3b0d44173c0daa531b3269/devices.json: no such file or directory" name=kata-runtime pid=6283 sandbox=f4dd677761e96aceea9989d6328af799451bfa62af3b0d44173c0daa531b3269 sandboxid=f4dd677761e96aceea9989d6328af799451bfa62af3b0d44173c0daa531b3269 source=virtcontainers subsystem=sandbox
time="2018-09-24T06:49:42.800589575Z" level=debug arch=amd64 command=create container=f4dd677761e96aceea9989d6328af799451bfa62af3b0d44173c0daa531b3269 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=6283 source=virtcontainers subsystem=qemu
time="2018-09-24T06:49:58.701421917Z" level=debug msg="Could not retrieve anything from storage" arch=amd64 command=create container=54fed571efb006623ffb2aa361e41da20c663917b686097e19b4d8940b263947 name=kata-runtime pid=6424 source=virtcontainers subsystem=kata_agent
time="2018-09-24T06:49:58.70151386Z" level=warning msg="fetch sandbox device failed" arch=amd64 command=create container=54fed571efb006623ffb2aa361e41da20c663917b686097e19b4d8940b263947 error="open /run/vc/sbs/54fed571efb006623ffb2aa361e41da20c663917b686097e19b4d8940b263947/devices.json: no such file or directory" name=kata-runtime pid=6424 sandbox=54fed571efb006623ffb2aa361e41da20c663917b686097e19b4d8940b263947 sandboxid=54fed571efb006623ffb2aa361e41da20c663917b686097e19b4d8940b263947 source=virtcontainers subsystem=sandbox
time="2018-09-24T06:49:58.704658928Z" level=debug arch=amd64 command=create container=54fed571efb006623ffb2aa361e41da20c663917b686097e19b4d8940b263947 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=6424 source=virtcontainers subsystem=qemu
time="2018-09-24T06:50:13.904819978Z" level=error msg="Failed to check if grpc server is working: context deadline exceeded" arch=amd64 command=create container=54fed571efb006623ffb2aa361e41da20c663917b686097e19b4d8940b263947 name=kata-runtime pid=6424 source=runtime
time="2018-09-24T06:54:31.791355323Z" level=error msg="Container 9009bbf50ff4ceb5adec4532218669e9033676e0119836af36ee699bf75f3782 not ready, running or paused, cannot send a signal" arch=amd64 command=kill container=9009bbf50ff4ceb5adec4532218669e9033676e0119836af36ee699bf75f3782 name=kata-runtime pid=6645 sandbox=9009bbf50ff4ceb5adec4532218669e9033676e0119836af36ee699bf75f3782 source=runtime
time="2018-09-24T06:54:31.811833626Z" level=error msg="Container 27944e17a8b888cf47b840920f25d6868c5aaefc26776a3126614f42697d4588 not ready, running or paused, cannot send a signal" arch=amd64 command=kill container=27944e17a8b888cf47b840920f25d6868c5aaefc26776a3126614f42697d4588 name=kata-runtime pid=6657 sandbox=27944e17a8b888cf47b840920f25d6868c5aaefc26776a3126614f42697d4588 source=runtime
time="2018-09-24T06:54:31.853921266Z" level=error msg="Container f4dd677761e96aceea9989d6328af799451bfa62af3b0d44173c0daa531b3269 not ready, running or paused, cannot send a signal" arch=amd64 command=kill container=f4dd677761e96aceea9989d6328af799451bfa62af3b0d44173c0daa531b3269 name=kata-runtime pid=6692 sandbox=f4dd677761e96aceea9989d6328af799451bfa62af3b0d44173c0daa531b3269 source=runtime
time="2018-09-24T06:54:31.856587399Z" level=error msg="Container 9009bbf50ff4ceb5adec4532218669e9033676e0119836af36ee699bf75f3782 not ready, running or paused, cannot send a signal" arch=amd64 command=kill container=9009bbf50ff4ceb5adec4532218669e9033676e0119836af36ee699bf75f3782 name=kata-runtime pid=6707 sandbox=9009bbf50ff4ceb5adec4532218669e9033676e0119836af36ee699bf75f3782 source=runtime
time="2018-09-24T06:54:31.875760122Z" level=error msg="Container 27944e17a8b888cf47b840920f25d6868c5aaefc26776a3126614f42697d4588 not ready, running or paused, cannot send a signal" arch=amd64 command=kill container=27944e17a8b888cf47b840920f25d6868c5aaefc26776a3126614f42697d4588 name=kata-runtime pid=6726 sandbox=27944e17a8b888cf47b840920f25d6868c5aaefc26776a3126614f42697d4588 source=runtime
time="2018-09-24T06:54:31.92381823Z" level=error msg="Container f4dd677761e96aceea9989d6328af799451bfa62af3b0d44173c0daa531b3269 not ready, running or paused, cannot send a signal" arch=amd64 command=kill container=f4dd677761e96aceea9989d6328af799451bfa62af3b0d44173c0daa531b3269 name=kata-runtime pid=6770 sandbox=f4dd677761e96aceea9989d6328af799451bfa62af3b0d44173c0daa531b3269 source=runtime
time="2018-09-24T07:03:26.881113498Z" level=debug msg="Could not retrieve anything from storage" arch=amd64 command=create container=2c4098b53fd95498752c35a478d39d3ad39b7836a183375a4485f130da228331 name=kata-runtime pid=1863 source=virtcontainers subsystem=kata_agent
time="2018-09-24T07:03:26.881196576Z" level=warning msg="fetch sandbox device failed" arch=amd64 command=create container=2c4098b53fd95498752c35a478d39d3ad39b7836a183375a4485f130da228331 error="open /run/vc/sbs/2c4098b53fd95498752c35a478d39d3ad39b7836a183375a4485f130da228331/devices.json: no such file or directory" name=kata-runtime pid=1863 sandbox=2c4098b53fd95498752c35a478d39d3ad39b7836a183375a4485f130da228331 sandboxid=2c4098b53fd95498752c35a478d39d3ad39b7836a183375a4485f130da228331 source=virtcontainers subsystem=sandbox
time="2018-09-24T07:03:26.915605556Z" level=debug arch=amd64 command=create container=2c4098b53fd95498752c35a478d39d3ad39b7836a183375a4485f130da228331 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=1863 source=virtcontainers subsystem=qemu
time="2018-09-24T07:04:31.465253203Z" level=debug msg="Could not retrieve anything from storage" arch=amd64 command=create container=7e89bf81fa37acd2ad17e036429df4f71689ccf5e31e4e1660a5b026653896d3 name=kata-runtime pid=2127 source=virtcontainers subsystem=kata_agent
time="2018-09-24T07:04:31.465354861Z" level=warning msg="fetch sandbox device failed" arch=amd64 command=create container=7e89bf81fa37acd2ad17e036429df4f71689ccf5e31e4e1660a5b026653896d3 error="open /run/vc/sbs/7e89bf81fa37acd2ad17e036429df4f71689ccf5e31e4e1660a5b026653896d3/devices.json: no such file or directory" name=kata-runtime pid=2127 sandbox=7e89bf81fa37acd2ad17e036429df4f71689ccf5e31e4e1660a5b026653896d3 sandboxid=7e89bf81fa37acd2ad17e036429df4f71689ccf5e31e4e1660a5b026653896d3 source=virtcontainers subsystem=sandbox
time="2018-09-24T07:04:31.46866666Z" level=debug arch=amd64 command=create container=7e89bf81fa37acd2ad17e036429df4f71689ccf5e31e4e1660a5b026653896d3 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=2127 source=virtcontainers subsystem=qemu
time="2018-09-24T07:05:14.865140108Z" level=debug msg="Could not retrieve anything from storage" arch=amd64 command=create container=fb0de29f564b2f1bac243fe6bc12236cfa85e8fa9916abd3aa6e28c57f358b32 name=kata-runtime pid=2299 source=virtcontainers subsystem=kata_agent
time="2018-09-24T07:05:14.865233967Z" level=warning msg="fetch sandbox device failed" arch=amd64 command=create container=fb0de29f564b2f1bac243fe6bc12236cfa85e8fa9916abd3aa6e28c57f358b32 error="open /run/vc/sbs/fb0de29f564b2f1bac243fe6bc12236cfa85e8fa9916abd3aa6e28c57f358b32/devices.json: no such file or directory" name=kata-runtime pid=2299 sandbox=fb0de29f564b2f1bac243fe6bc12236cfa85e8fa9916abd3aa6e28c57f358b32 sandboxid=fb0de29f564b2f1bac243fe6bc12236cfa85e8fa9916abd3aa6e28c57f358b32 source=virtcontainers subsystem=sandbox
time="2018-09-24T07:05:14.868621159Z" level=debug arch=amd64 command=create container=fb0de29f564b2f1bac243fe6bc12236cfa85e8fa9916abd3aa6e28c57f358b32 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=2299 source=virtcontainers subsystem=qemu
time="2018-09-24T07:05:45.092593935Z" level=error msg="Failed to check if grpc server is working: rpc error: code = DeadlineExceeded desc = context deadline exceeded" arch=amd64 command=create container=fb0de29f564b2f1bac243fe6bc12236cfa85e8fa9916abd3aa6e28c57f358b32 name=kata-runtime pid=2299 source=runtime
time="2018-09-24T07:06:11.329160487Z" level=debug msg="Could not retrieve anything from storage" arch=amd64 command=create container=a7c489bf0009eb6dc3f5fb9d17b84049bb9b0f06e4b7bae2a97b34c650811a98 name=kata-runtime pid=2412 source=virtcontainers subsystem=kata_agent
time="2018-09-24T07:06:11.329256842Z" level=warning msg="fetch sandbox device failed" arch=amd64 command=create container=a7c489bf0009eb6dc3f5fb9d17b84049bb9b0f06e4b7bae2a97b34c650811a98 error="open /run/vc/sbs/a7c489bf0009eb6dc3f5fb9d17b84049bb9b0f06e4b7bae2a97b34c650811a98/devices.json: no such file or directory" name=kata-runtime pid=2412 sandbox=a7c489bf0009eb6dc3f5fb9d17b84049bb9b0f06e4b7bae2a97b34c650811a98 sandboxid=a7c489bf0009eb6dc3f5fb9d17b84049bb9b0f06e4b7bae2a97b34c650811a98 source=virtcontainers subsystem=sandbox
time="2018-09-24T07:06:11.332314841Z" level=debug arch=amd64 command=create container=a7c489bf0009eb6dc3f5fb9d17b84049bb9b0f06e4b7bae2a97b34c650811a98 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=2412 source=virtcontainers subsystem=qemuRecent proxy problems found in system journal:
time="2018-09-21T14:17:01.599299939Z" level=info msg="[ 22.837140] systemd[69]: tmp.mount: Failed to execute command: No such file or directory\n" name=kata-proxy pid=3703 sandbox=54b8a667253de80cd713e9aa5699be26eb42ddc920d718b67854be276c43de49 source=agent
time="2018-09-21T14:17:01.63349911Z" level=info msg="[ 22.871285] systemd-journald[80]: Failed to open configuration file '/etc/systemd/journald.conf': No such file or directory\n" name=kata-proxy pid=3703 sandbox=54b8a667253de80cd713e9aa5699be26eb42ddc920d718b67854be276c43de49 source=agent
time="2018-09-21T14:17:01.642228582Z" level=info msg="[\x1b[0;1;31mFAILED\x1b[0m] Failed to mount Temporary Directory (/tmp).\n" name=kata-proxy pid=3703 sandbox=54b8a667253de80cd713e9aa5699be26eb42ddc920d718b67854be276c43de49 source=agent
time="2018-09-21T14:17:01.643518371Z" level=info msg="[\x1b[0;1;33mDEPEND\x1b[0m] Dependency failed for Network Time Synchronization.\n" name=kata-proxy pid=3703 sandbox=54b8a667253de80cd713e9aa5699be26eb42ddc920d718b67854be276c43de49 source=agent
time="2018-09-21T14:17:02.042599946Z" level=info msg="time=\"2018-09-21T14:17:02.01771413Z\" level=info msg=\"ignoring unexpected signal\" name=kata-agent pid=112 sandbox=54b8a667253de80cd713e9aa5699be26eb42ddc920d718b67854be276c43de49 signal=\"child exited\" source=agent\n" name=kata-proxy pid=3703 sandbox=54b8a667253de80cd713e9aa5699be26eb42ddc920d718b67854be276c43de49 source=agent
time="2018-09-21T14:17:02.52129181Z" level=info msg="[ 23.759214] random: 7 urandom warning(s) missed due to ratelimiting\n" name=kata-proxy pid=3703 sandbox=54b8a667253de80cd713e9aa5699be26eb42ddc920d718b67854be276c43de49 source=agent
time="2018-09-21T14:19:31.320776775Z" level=info msg="[ 4.360811] EXT4-fs (pmem0p1): DAX enabled. Warning: EXPERIMENTAL, use at your own risk\n" name=kata-proxy pid=4002 sandbox=5c5bd9c5a57dc999255a7ad9d2a7ff7cab7a995efb239cda2ed9b462140d2a45 source=agent
time="2018-09-21T14:19:31.321519138Z" level=info msg="[ 4.361457] EXT4-fs (pmem0p1): mounted filesystem with ordered data mode. Opts: dax,data=ordered,errors=remount-ro\n" name=kata-proxy pid=4002 sandbox=5c5bd9c5a57dc999255a7ad9d2a7ff7cab7a995efb239cda2ed9b462140d2a45 source=agent
time="2018-09-21T14:19:31.36141069Z" level=info msg="[ 4.401342] systemd-gpt-auto-generator[68]: Failed to chase block device '/', ignoring: No such file or directory\n" name=kata-proxy pid=4002 sandbox=5c5bd9c5a57dc999255a7ad9d2a7ff7cab7a995efb239cda2ed9b462140d2a45 source=agent
time="2018-09-21T14:19:31.421607219Z" level=info msg="[ 4.461589] systemd[73]: tmp.mount: Failed to execute command: No such file or directory\n" name=kata-proxy pid=4002 sandbox=5c5bd9c5a57dc999255a7ad9d2a7ff7cab7a995efb239cda2ed9b462140d2a45 source=agent
time="2018-09-21T14:19:31.448559166Z" level=info msg="[ 4.488466] systemd-journald[80]: Failed to open configuration file '/etc/systemd/journald.conf': No such file or directory\n" name=kata-proxy pid=4002 sandbox=5c5bd9c5a57dc999255a7ad9d2a7ff7cab7a995efb239cda2ed9b462140d2a45 source=agent
time="2018-09-21T14:19:31.463031135Z" level=info msg="[\x1b[0;1;31mFAILED\x1b[0m] Failed to mount Temporary Directory (/tmp).\n" name=kata-proxy pid=4002 sandbox=5c5bd9c5a57dc999255a7ad9d2a7ff7cab7a995efb239cda2ed9b462140d2a45 source=agent
time="2018-09-21T14:19:31.47015376Z" level=info msg="[\x1b[0;1;33mDEPEND\x1b[0m] Dependency failed for Network Time Synchronization.\n" name=kata-proxy pid=4002 sandbox=5c5bd9c5a57dc999255a7ad9d2a7ff7cab7a995efb239cda2ed9b462140d2a45 source=agent
time="2018-09-21T14:19:31.828736502Z" level=info msg="time=\"2018-09-21T14:19:31.805849755Z\" level=info msg=\"ignoring unexpected signal\" name=kata-agent pid=104 sandbox=5c5bd9c5a57dc999255a7ad9d2a7ff7cab7a995efb239cda2ed9b462140d2a45 signal=\"child exited\" source=agent\n" name=kata-proxy pid=4002 sandbox=5c5bd9c5a57dc999255a7ad9d2a7ff7cab7a995efb239cda2ed9b462140d2a45 source=agent
time="2018-09-21T14:19:32.331539456Z" level=info msg="[ 5.371631] random: 7 urandom warning(s) missed due to ratelimiting\n" name=kata-proxy pid=4002 sandbox=5c5bd9c5a57dc999255a7ad9d2a7ff7cab7a995efb239cda2ed9b462140d2a45 source=agent
time="2018-09-21T14:45:40.614826526Z" level=info msg="time=\"2018-09-21T14:45:40.416652043Z\" level=info msg=\"ignoring unexpected signal\" name=kata-agent pid=112 sandbox=54b8a667253de80cd713e9aa5699be26eb42ddc920d718b67854be276c43de49 signal=\"child exited\" source=agent\n" name=kata-proxy pid=3703 sandbox=54b8a667253de80cd713e9aa5699be26eb42ddc920d718b67854be276c43de49 source=agent
time="2018-09-21T14:45:40.616147147Z" level=debug msg="Copy stream error" error="read unix /run/vc/sbs/54b8a667253de80cd713e9aa5699be26eb42ddc920d718b67854be276c43de49/proxy.sock->@: read: connection reset by peer" name=kata-proxy pid=3703 sandbox=54b8a667253de80cd713e9aa5699be26eb42ddc920d718b67854be276c43de49 source=proxy
time="2018-09-21T14:45:40.63701319Z" level=info msg="time=\"2018-09-21T14:45:40.423365835Z\" level=info msg=\"ignoring unexpected signal\" name=kata-agent pid=107 sandbox=72a16a08cabc382b0b4c08e26b3b8577793c87ffb1014af79a6b250842d4e15b signal=\"child exited\" source=agent\n" name=kata-proxy pid=3384 sandbox=72a16a08cabc382b0b4c08e26b3b8577793c87ffb1014af79a6b250842d4e15b source=agent
time="2018-09-21T14:45:40.638421254Z" level=debug msg="Copy stream error" error="read unix /run/vc/sbs/72a16a08cabc382b0b4c08e26b3b8577793c87ffb1014af79a6b250842d4e15b/proxy.sock->@: read: connection reset by peer" name=kata-proxy pid=3384 sandbox=72a16a08cabc382b0b4c08e26b3b8577793c87ffb1014af79a6b250842d4e15b source=proxy
time="2018-09-21T14:45:40.66193199Z" level=info msg="time=\"2018-09-21T14:45:40.475752662Z\" level=info msg=\"ignoring unexpected signal\" name=kata-agent pid=104 sandbox=5c5bd9c5a57dc999255a7ad9d2a7ff7cab7a995efb239cda2ed9b462140d2a45 signal=\"child exited\" source=agent\n" name=kata-proxy pid=4002 sandbox=5c5bd9c5a57dc999255a7ad9d2a7ff7cab7a995efb239cda2ed9b462140d2a45 source=agent
time="2018-09-21T14:45:40.663161652Z" level=debug msg="Copy stream error" error="read unix /run/vc/sbs/5c5bd9c5a57dc999255a7ad9d2a7ff7cab7a995efb239cda2ed9b462140d2a45/proxy.sock->@: read: connection reset by peer" name=kata-proxy pid=4002 sandbox=5c5bd9c5a57dc999255a7ad9d2a7ff7cab7a995efb239cda2ed9b462140d2a45 source=proxy
time="2018-09-21T14:45:40.828933911Z" level=fatal msg="failed to handle exit signal" error="close unix @->/run/vc/vm/54b8a667253de80cd713e9aa5699be26eb42ddc920d718b67854be276c43de49/kata.sock: use of closed network connection" name=kata-proxy pid=3703 sandbox=54b8a667253de80cd713e9aa5699be26eb42ddc920d718b67854be276c43de49 source=proxy
time="2018-09-21T14:45:40.901268738Z" level=fatal msg="failed to handle exit signal" error="close unix @->/run/vc/vm/5c5bd9c5a57dc999255a7ad9d2a7ff7cab7a995efb239cda2ed9b462140d2a45/kata.sock: use of closed network connection" name=kata-proxy pid=4002 sandbox=5c5bd9c5a57dc999255a7ad9d2a7ff7cab7a995efb239cda2ed9b462140d2a45 source=proxy
time="2018-09-21T14:45:40.905499648Z" level=fatal msg="failed to handle exit signal" error="close unix @->/run/vc/vm/72a16a08cabc382b0b4c08e26b3b8577793c87ffb1014af79a6b250842d4e15b/kata.sock: use of closed network connection" name=kata-proxy pid=3384 sandbox=72a16a08cabc382b0b4c08e26b3b8577793c87ffb1014af79a6b250842d4e15b source=proxy
time="2018-09-24T07:03:28.307042984Z" level=info msg="[ 0.406127] EXT4-fs (pmem0p1): DAX enabled. Warning: EXPERIMENTAL, use at your own risk\n" name=kata-proxy pid=1927 sandbox=2c4098b53fd95498752c35a478d39d3ad39b7836a183375a4485f130da228331 source=agent
time="2018-09-24T07:03:28.312470256Z" level=info msg="[ 0.411474] EXT4-fs (pmem0p1): mounted filesystem with ordered data mode. Opts: dax,data=ordered,errors=remount-ro\n" name=kata-proxy pid=1927 sandbox=2c4098b53fd95498752c35a478d39d3ad39b7836a183375a4485f130da228331 source=agent
time="2018-09-24T07:03:28.653759897Z" level=info msg="[ 0.752713] systemd-gpt-auto-generator[68]: Failed to chase block device '/', ignoring: No such file or directory\n" name=kata-proxy pid=1927 sandbox=2c4098b53fd95498752c35a478d39d3ad39b7836a183375a4485f130da228331 source=agent
time="2018-09-24T07:03:28.730893074Z" level=info msg="[ 0.829907] systemd[69]: tmp.mount: Failed to execute command: No such file or directory\n" name=kata-proxy pid=1927 sandbox=2c4098b53fd95498752c35a478d39d3ad39b7836a183375a4485f130da228331 source=agent
time="2018-09-24T07:03:28.791453231Z" level=info msg="[ 0.890395] systemd-journald[78]: Failed to open configuration file '/etc/systemd/journald.conf': No such file or directory\n" name=kata-proxy pid=1927 sandbox=2c4098b53fd95498752c35a478d39d3ad39b7836a183375a4485f130da228331 source=agent
time="2018-09-24T07:03:28.793011695Z" level=info msg="[\x1b[0;1;31mFAILED\x1b[0m] Failed to mount Temporary Directory (/tmp).\n" name=kata-proxy pid=1927 sandbox=2c4098b53fd95498752c35a478d39d3ad39b7836a183375a4485f130da228331 source=agent
time="2018-09-24T07:03:28.797670117Z" level=info msg="[\x1b[0;1;33mDEPEND\x1b[0m] Dependency failed for Network Time Synchronization.\n" name=kata-proxy pid=1927 sandbox=2c4098b53fd95498752c35a478d39d3ad39b7836a183375a4485f130da228331 source=agent
time="2018-09-24T07:03:29.409550524Z" level=info msg="time=\"2018-09-24T07:03:29.381676307Z\" level=info msg=\"ignoring unexpected signal\" name=kata-agent pid=116 sandbox=2c4098b53fd95498752c35a478d39d3ad39b7836a183375a4485f130da228331 signal=\"child exited\" source=agent\n" name=kata-proxy pid=1927 sandbox=2c4098b53fd95498752c35a478d39d3ad39b7836a183375a4485f130da228331 source=agent
time="2018-09-24T07:04:36.381714004Z" level=info msg="[ 4.380684] EXT4-fs (pmem0p1): DAX enabled. Warning: EXPERIMENTAL, use at your own risk\n" name=kata-proxy pid=2173 sandbox=7e89bf81fa37acd2ad17e036429df4f71689ccf5e31e4e1660a5b026653896d3 source=agent
time="2018-09-24T07:04:36.382439484Z" level=info msg="[ 4.381302] EXT4-fs (pmem0p1): mounted filesystem with ordered data mode. Opts: dax,data=ordered,errors=remount-ro\n" name=kata-proxy pid=2173 sandbox=7e89bf81fa37acd2ad17e036429df4f71689ccf5e31e4e1660a5b026653896d3 source=agent
time="2018-09-24T07:04:36.427279954Z" level=info msg="[ 4.426144] systemd-gpt-auto-generator[68]: Failed to chase block device '/', ignoring: No such file or directory\n" name=kata-proxy pid=2173 sandbox=7e89bf81fa37acd2ad17e036429df4f71689ccf5e31e4e1660a5b026653896d3 source=agent
time="2018-09-24T07:04:36.47247461Z" level=info msg="[ 4.471324] systemd-journald[71]: Failed to open configuration file '/etc/systemd/journald.conf': No such file or directory\n" name=kata-proxy pid=2173 sandbox=7e89bf81fa37acd2ad17e036429df4f71689ccf5e31e4e1660a5b026653896d3 source=agent
time="2018-09-24T07:04:36.473505173Z" level=info msg="[ 4.472426] systemd[70]: tmp.mount: Failed to execute command: No such file or directory\n" name=kata-proxy pid=2173 sandbox=7e89bf81fa37acd2ad17e036429df4f71689ccf5e31e4e1660a5b026653896d3 source=agent
time="2018-09-24T07:04:36.510565757Z" level=info msg="[\x1b[0;1;31mFAILED\x1b[0m] Failed to mount Temporary Directory (/tmp).\n" name=kata-proxy pid=2173 sandbox=7e89bf81fa37acd2ad17e036429df4f71689ccf5e31e4e1660a5b026653896d3 source=agent
time="2018-09-24T07:04:36.51104268Z" level=info msg="[\x1b[0;1;33mDEPEND\x1b[0m] Dependency failed for Network Time Synchronization.\n" name=kata-proxy pid=2173 sandbox=7e89bf81fa37acd2ad17e036429df4f71689ccf5e31e4e1660a5b026653896d3 source=agent
time="2018-09-24T07:04:36.893075043Z" level=info msg="time=\"2018-09-24T07:04:36.869069148Z\" level=info msg=\"ignoring unexpected signal\" name=kata-agent pid=106 sandbox=7e89bf81fa37acd2ad17e036429df4f71689ccf5e31e4e1660a5b026653896d3 signal=\"child exited\" source=agent\n" name=kata-proxy pid=2173 sandbox=7e89bf81fa37acd2ad17e036429df4f71689ccf5e31e4e1660a5b026653896d3 source=agent
time="2018-09-24T07:05:46.655977024Z" level=info msg="[ 74.652292] random: 7 urandom warning(s) missed due to ratelimiting\n" name=kata-proxy pid=2173 sandbox=7e89bf81fa37acd2ad17e036429df4f71689ccf5e31e4e1660a5b026653896d3 source=agent
time="2018-09-24T07:06:32.301144206Z" level=info msg="[ 20.430523] EXT4-fs (pmem0p1): DAX enabled. Warning: EXPERIMENTAL, use at your own risk\n" name=kata-proxy pid=2457 sandbox=a7c489bf0009eb6dc3f5fb9d17b84049bb9b0f06e4b7bae2a97b34c650811a98 source=agent
time="2018-09-24T07:06:32.301858858Z" level=info msg="[ 20.431178] EXT4-fs (pmem0p1): mounted filesystem with ordered data mode. Opts: dax,data=ordered,errors=remount-ro\n" name=kata-proxy pid=2457 sandbox=a7c489bf0009eb6dc3f5fb9d17b84049bb9b0f06e4b7bae2a97b34c650811a98 source=agent
time="2018-09-24T07:06:32.346739586Z" level=info msg="[ 20.476121] systemd-gpt-auto-generator[68]: Failed to chase block device '/', ignoring: No such file or directory\n" name=kata-proxy pid=2457 sandbox=a7c489bf0009eb6dc3f5fb9d17b84049bb9b0f06e4b7bae2a97b34c650811a98 source=agent
time="2018-09-24T07:06:32.388397711Z" level=info msg="[ 20.517760] systemd-journald[70]: Failed to open configuration file '/etc/systemd/journald.conf': No such file or directory\n" name=kata-proxy pid=2457 sandbox=a7c489bf0009eb6dc3f5fb9d17b84049bb9b0f06e4b7bae2a97b34c650811a98 source=agent
time="2018-09-24T07:06:32.415729032Z" level=info msg="[ 20.545144] systemd[76]: tmp.mount: Failed to execute command: No such file or directory\n" name=kata-proxy pid=2457 sandbox=a7c489bf0009eb6dc3f5fb9d17b84049bb9b0f06e4b7bae2a97b34c650811a98 source=agent
time="2018-09-24T07:06:32.444183746Z" level=info msg="[\x1b[0;1;31mFAILED\x1b[0m] Failed to mount Temporary Directory (/tmp).\n" name=kata-proxy pid=2457 sandbox=a7c489bf0009eb6dc3f5fb9d17b84049bb9b0f06e4b7bae2a97b34c650811a98 source=agent
time="2018-09-24T07:06:32.445792927Z" level=info msg="[\x1b[0;1;33mDEPEND\x1b[0m] Dependency failed for Network Time Synchronization.\n" name=kata-proxy pid=2457 sandbox=a7c489bf0009eb6dc3f5fb9d17b84049bb9b0f06e4b7bae2a97b34c650811a98 source=agent
time="2018-09-24T07:06:32.835624026Z" level=info msg="time=\"2018-09-24T07:06:32.806889206Z\" level=info msg=\"ignoring unexpected signal\" name=kata-agent pid=106 sandbox=a7c489bf0009eb6dc3f5fb9d17b84049bb9b0f06e4b7bae2a97b34c650811a98 signal=\"child exited\" source=agent\n" name=kata-proxy pid=2457 sandbox=a7c489bf0009eb6dc3f5fb9d17b84049bb9b0f06e4b7bae2a97b34c650811a98 source=agent
time="2018-09-24T07:07:38.528074615Z" level=info msg="[ 86.655174] random: 7 urandom warning(s) missed due to ratelimiting\n" name=kata-proxy pid=2457 sandbox=a7c489bf0009eb6dc3f5fb9d17b84049bb9b0f06e4b7bae2a97b34c650811a98 source=agentRecent shim problems found in system journal:
time="2018-09-21T12:02:51.537034417Z" level=info msg="copy stdout failed" container=222d3564894a8bb8f695ff258e8a44e935198adc394abb463d80e0b8922140f0 error="rpc error: code = Unknown desc = EOF" exec-id=222d3564894a8bb8f695ff258e8a44e935198adc394abb463d80e0b8922140f0 name=kata-shim pid=1 source=shim
time="2018-09-21T12:02:51.537061616Z" level=info msg="copy stderr failed" container=222d3564894a8bb8f695ff258e8a44e935198adc394abb463d80e0b8922140f0 error="rpc error: code = Unknown desc = EOF" exec-id=222d3564894a8bb8f695ff258e8a44e935198adc394abb463d80e0b8922140f0 name=kata-shim pid=1 source=shim
time="2018-09-21T12:05:45.078068234Z" level=info msg="copy stdout failed" container=699be9820c3573706f383202ff28ae782b064b5e7be1e8d2caa1fe65a4d57bc0 error="rpc error: code = Unknown desc = EOF" exec-id=699be9820c3573706f383202ff28ae782b064b5e7be1e8d2caa1fe65a4d57bc0 name=kata-shim pid=1 source=shim
time="2018-09-21T12:05:45.078125461Z" level=info msg="copy stderr failed" container=699be9820c3573706f383202ff28ae782b064b5e7be1e8d2caa1fe65a4d57bc0 error="rpc error: code = Unknown desc = EOF" exec-id=699be9820c3573706f383202ff28ae782b064b5e7be1e8d2caa1fe65a4d57bc0 name=kata-shim pid=1 source=shim
time="2018-09-21T12:05:45.103831766Z" level=info msg="copy stdout failed" container=273c7f59b45fa5e6337c97fdfcc49f781f43aa58b3dfff7a639bc35a66781052 error="rpc error: code = Unknown desc = EOF" exec-id=273c7f59b45fa5e6337c97fdfcc49f781f43aa58b3dfff7a639bc35a66781052 name=kata-shim pid=1 source=shim
time="2018-09-21T12:05:45.103900477Z" level=info msg="copy stderr failed" container=273c7f59b45fa5e6337c97fdfcc49f781f43aa58b3dfff7a639bc35a66781052 error="rpc error: code = Unknown desc = EOF" exec-id=273c7f59b45fa5e6337c97fdfcc49f781f43aa58b3dfff7a639bc35a66781052 name=kata-shim pid=1 source=shim
time="2018-09-21T12:14:12.819078341Z" level=info msg="copy stdout failed" container=699be9820c3573706f383202ff28ae782b064b5e7be1e8d2caa1fe65a4d57bc0 error="rpc error: code = Unknown desc = EOF" exec-id=699be9820c3573706f383202ff28ae782b064b5e7be1e8d2caa1fe65a4d57bc0 name=kata-shim pid=1 source=shim
time="2018-09-21T12:14:12.819163555Z" level=info msg="copy stderr failed" container=699be9820c3573706f383202ff28ae782b064b5e7be1e8d2caa1fe65a4d57bc0 error="rpc error: code = Unknown desc = EOF" exec-id=699be9820c3573706f383202ff28ae782b064b5e7be1e8d2caa1fe65a4d57bc0 name=kata-shim pid=1 source=shim
time="2018-09-21T13:33:56.184507929Z" level=info msg="copy stdout failed" container=dd7f4eb03a6740116c60fcce025e5eb0a7f9b7855c53f93447bd2575019fa11a error="rpc error: code = Unknown desc = read /dev/ptmx: input/output error" exec-id=dd7f4eb03a6740116c60fcce025e5eb0a7f9b7855c53f93447bd2575019fa11a name=kata-shim pid=1 source=shim
time="2018-09-21T13:36:25.307068616Z" level=info msg="copy stdout failed" container=016843a7700a221c36991295f347331ab7126ada7f7f72223edf52026faa9a34 error="rpc error: code = Unknown desc = read /dev/ptmx: input/output error" exec-id=016843a7700a221c36991295f347331ab7126ada7f7f72223edf52026faa9a34 name=kata-shim pid=1 source=shim
time="2018-09-21T13:36:31.891353676Z" level=info msg="copy stdout failed" container=01ca48ba7413f6c7a3c1f99ab810749166ec23b7fca0cc2230f77b84ca51925a error="rpc error: code = Unknown desc = read /dev/ptmx: input/output error" exec-id=01ca48ba7413f6c7a3c1f99ab810749166ec23b7fca0cc2230f77b84ca51925a name=kata-shim pid=1 source=shim
time="2018-09-21T13:36:36.219300422Z" level=info msg="copy stdout failed" container=f97f4dbf4a1b12cd2e5330eeef3ae1b118b4ec6312a45d70ec6d74931e71930d error="rpc error: code = Unknown desc = read /dev/ptmx: input/output error" exec-id=f97f4dbf4a1b12cd2e5330eeef3ae1b118b4ec6312a45d70ec6d74931e71930d name=kata-shim pid=1 source=shim
time="2018-09-21T13:36:43.79285939Z" level=info msg="copy stdout failed" container=15e412980c3bc37d96f780ce575179e575650dd74a9f3def7dad482071bb07a3 error="rpc error: code = Unknown desc = read /dev/ptmx: input/output error" exec-id=15e412980c3bc37d96f780ce575179e575650dd74a9f3def7dad482071bb07a3 name=kata-shim pid=1 source=shim
time="2018-09-21T13:38:03.243046366Z" level=info msg="copy stdout failed" container=f50b58d4a13ccfaa616b37995730e39dd41e85d76b2e4e84ad748617c4d9a91c error="rpc error: code = Unknown desc = read /dev/ptmx: input/output error" exec-id=f50b58d4a13ccfaa616b37995730e39dd41e85d76b2e4e84ad748617c4d9a91c name=kata-shim pid=1 source=shim
time="2018-09-21T13:38:10.563360248Z" level=info msg="copy stdout failed" container=9586b01c759fce4027ddf58bfbfda5aa313673b44c3bcbe5f5979e9b0fc6dd4d error="rpc error: code = Unknown desc = read /dev/ptmx: input/output error" exec-id=9586b01c759fce4027ddf58bfbfda5aa313673b44c3bcbe5f5979e9b0fc6dd4d name=kata-shim pid=1 source=shim
time="2018-09-21T13:49:51.020526364Z" level=info msg="copy stdout failed" container=78b7a6f5e257282cb626cb383c70a49d8ab4622840bac2dcaab3bb1cb90b35f3 error="rpc error: code = Unknown desc = read /dev/ptmx: input/output error" exec-id=78b7a6f5e257282cb626cb383c70a49d8ab4622840bac2dcaab3bb1cb90b35f3 name=kata-shim pid=1 source=shim
time="2018-09-21T13:58:05.880961414Z" level=info msg="copy stdout failed" container=9c90803805e1378f7ae7cf3a02bc858475c347c7e19f0aa0882b1e3fc59f7df5 error="rpc error: code = Unknown desc = read /dev/ptmx: input/output error" exec-id=9c90803805e1378f7ae7cf3a02bc858475c347c7e19f0aa0882b1e3fc59f7df5 name=kata-shim pid=1 source=shim
time="2018-09-21T13:58:39.881542862Z" level=info msg="copy stderr failed" container=29e30fcbb57b53a95578cce61a33b60cab90d358752c4a2e7bce6fcc1adddd9f error="rpc error: code = Unavailable desc = transport is closing" exec-id=29e30fcbb57b53a95578cce61a33b60cab90d358752c4a2e7bce6fcc1adddd9f name=kata-shim pid=1 source=shim
time="2018-09-21T13:58:39.881650188Z" level=info msg="copy stdout failed" container=29e30fcbb57b53a95578cce61a33b60cab90d358752c4a2e7bce6fcc1adddd9f error="rpc error: code = Unavailable desc = transport is closing" exec-id=29e30fcbb57b53a95578cce61a33b60cab90d358752c4a2e7bce6fcc1adddd9f name=kata-shim pid=1 source=shim
time="2018-09-21T13:58:39.882015166Z" level=error msg="failed waiting for process" container=29e30fcbb57b53a95578cce61a33b60cab90d358752c4a2e7bce6fcc1adddd9f error="rpc error: code = Unavailable desc = all SubConns are in TransientFailure" exec-id=29e30fcbb57b53a95578cce61a33b60cab90d358752c4a2e7bce6fcc1adddd9f name=kata-shim pid=1 source=shim
time="2018-09-21T13:58:39.882015947Z" level=info msg="copy stderr failed" container=4c0919a3d27c801bfdc02c17cdaa76051e1696da8311e564b35d98549f21baf7 error="rpc error: code = Unavailable desc = transport is closing" exec-id=4c0919a3d27c801bfdc02c17cdaa76051e1696da8311e564b35d98549f21baf7 name=kata-shim pid=1 source=shim
time="2018-09-21T13:58:39.882462768Z" level=info msg="copy stdout failed" container=4c0919a3d27c801bfdc02c17cdaa76051e1696da8311e564b35d98549f21baf7 error="rpc error: code = Unavailable desc = transport is closing" exec-id=4c0919a3d27c801bfdc02c17cdaa76051e1696da8311e564b35d98549f21baf7 name=kata-shim pid=1 source=shim
time="2018-09-21T13:58:39.882597151Z" level=error msg="failed waiting for process" container=4c0919a3d27c801bfdc02c17cdaa76051e1696da8311e564b35d98549f21baf7 error="rpc error: code = Unavailable desc = all SubConns are in TransientFailure" exec-id=4c0919a3d27c801bfdc02c17cdaa76051e1696da8311e564b35d98549f21baf7 name=kata-shim pid=1 source=shim
time="2018-09-21T13:58:39.883143672Z" level=info msg="copy stderr failed" container=9eccc32b73a40dc37008c2cd684f57c756175284180ea8e7c108708ab666281d error="rpc error: code = Unavailable desc = transport is closing" exec-id=9eccc32b73a40dc37008c2cd684f57c756175284180ea8e7c108708ab666281d name=kata-shim pid=1 source=shim
time="2018-09-21T13:58:39.883178329Z" level=info msg="copy stdout failed" container=9eccc32b73a40dc37008c2cd684f57c756175284180ea8e7c108708ab666281d error="rpc error: code = Unavailable desc = transport is closing" exec-id=9eccc32b73a40dc37008c2cd684f57c756175284180ea8e7c108708ab666281d name=kata-shim pid=1 source=shim
time="2018-09-21T13:58:39.883421962Z" level=error msg="failed waiting for process" container=9eccc32b73a40dc37008c2cd684f57c756175284180ea8e7c108708ab666281d error="rpc error: code = Unavailable desc = all SubConns are in TransientFailure" exec-id=9eccc32b73a40dc37008c2cd684f57c756175284180ea8e7c108708ab666281d name=kata-shim pid=1 source=shim
time="2018-09-21T14:08:57.463750652Z" level=info msg="copy stdout failed" container=a622aef5eeac182b63939a415e9290cbfa6fe2dc631f68ffa974d8b32193b59b error="rpc error: code = Unknown desc = read /dev/ptmx: input/output error" exec-id=a622aef5eeac182b63939a415e9290cbfa6fe2dc631f68ffa974d8b32193b59b name=kata-shim pid=1 source=shim
time="2018-09-21T14:09:38.399521213Z" level=info msg="copy stderr failed" container=4c0919a3d27c801bfdc02c17cdaa76051e1696da8311e564b35d98549f21baf7 error="rpc error: code = Unknown desc = EOF" exec-id=4c0919a3d27c801bfdc02c17cdaa76051e1696da8311e564b35d98549f21baf7 name=kata-shim pid=1 source=shim
time="2018-09-21T14:09:38.401246278Z" level=info msg="copy stdout failed" container=4c0919a3d27c801bfdc02c17cdaa76051e1696da8311e564b35d98549f21baf7 error="rpc error: code = Unknown desc = EOF" exec-id=4c0919a3d27c801bfdc02c17cdaa76051e1696da8311e564b35d98549f21baf7 name=kata-shim pid=1 source=shim
time="2018-09-21T14:10:46.629596078Z" level=info msg="copy stdout failed" container=35ed3dfb1e9a5f0a40b3d649e2cf7593b05bf665967a55d9a4c60f6e1dab3e70 error="rpc error: code = Unknown desc = read /dev/ptmx: input/output error" exec-id=35ed3dfb1e9a5f0a40b3d649e2cf7593b05bf665967a55d9a4c60f6e1dab3e70 name=kata-shim pid=1 source=shim
time="2018-09-21T14:11:09.574097911Z" level=info msg="copy stdout failed" container=59f3200ad54d1c6f3a5644057e38ccc281c6e89bc11949b6f573d99caed00737 error="rpc error: code = Unknown desc = read /dev/ptmx: input/output error" exec-id=59f3200ad54d1c6f3a5644057e38ccc281c6e89bc11949b6f573d99caed00737 name=kata-shim pid=1 source=shim
time="2018-09-21T14:11:33.315677908Z" level=info msg="copy stdout failed" container=16bcaceb53ca07a41be02ed6cba5c5f73edccad2f058f9fa09f6470718a927bb error="rpc error: code = Unknown desc = read /dev/ptmx: input/output error" exec-id=16bcaceb53ca07a41be02ed6cba5c5f73edccad2f058f9fa09f6470718a927bb name=kata-shim pid=1 source=shim
time="2018-09-21T14:12:52.069849967Z" level=info msg="copy stdout failed" container=83bb101db3dbbba71c6e4def4fd09a81bb425ca39a8fdac01040ac6c2f8df509 error="rpc error: code = Unknown desc = read /dev/ptmx: input/output error" exec-id=83bb101db3dbbba71c6e4def4fd09a81bb425ca39a8fdac01040ac6c2f8df509 name=kata-shim pid=1 source=shim
time="2018-09-21T14:13:57.2853292Z" level=info msg="copy stdout failed" container=f354ad3d564b215fc629c4159a82f986f25b4457c3416aada93f777fbf5699aa error="rpc error: code = Unknown desc = read /dev/ptmx: input/output error" exec-id=f354ad3d564b215fc629c4159a82f986f25b4457c3416aada93f777fbf5699aa name=kata-shim pid=1 source=shim
time="2018-09-21T14:45:40.60474234Z" level=info msg="copy stdout failed" container=54b8a667253de80cd713e9aa5699be26eb42ddc920d718b67854be276c43de49 error="rpc error: code = Unknown desc = read /dev/ptmx: input/output error" exec-id=54b8a667253de80cd713e9aa5699be26eb42ddc920d718b67854be276c43de49 name=kata-shim pid=1 source=shim
time="2018-09-21T14:45:40.627162902Z" level=info msg="copy stdout failed" container=72a16a08cabc382b0b4c08e26b3b8577793c87ffb1014af79a6b250842d4e15b error="rpc error: code = Unknown desc = read /dev/ptmx: input/output error" exec-id=72a16a08cabc382b0b4c08e26b3b8577793c87ffb1014af79a6b250842d4e15b name=kata-shim pid=1 source=shim
time="2018-09-21T14:45:40.652345496Z" level=info msg="copy stdout failed" container=5c5bd9c5a57dc999255a7ad9d2a7ff7cab7a995efb239cda2ed9b462140d2a45 error="rpc error: code = Unknown desc = read /dev/ptmx: input/output error" exec-id=5c5bd9c5a57dc999255a7ad9d2a7ff7cab7a995efb239cda2ed9b462140d2a45 name=kata-shim pid=1 source=shim
time="2018-09-24T06:47:00.783591666Z" level=info msg="copy stderr failed" container=2f86d6ed7b2b38bf36abfc760252775535eba1f7b82d018e88ef1e520e435779 error="rpc error: code = Unknown desc = EOF" exec-id=2f86d6ed7b2b38bf36abfc760252775535eba1f7b82d018e88ef1e520e435779 name=kata-shim pid=1 source=shim
time="2018-09-24T06:47:00.78361505Z" level=info msg="copy stdout failed" container=2f86d6ed7b2b38bf36abfc760252775535eba1f7b82d018e88ef1e520e435779 error="rpc error: code = Unknown desc = EOF" exec-id=2f86d6ed7b2b38bf36abfc760252775535eba1f7b82d018e88ef1e520e435779 name=kata-shim pid=1 source=shim
time="2018-09-24T06:47:00.808180605Z" level=info msg="copy stderr failed" container=62990ae0f153ffd7b0678a8a08ba6030c9d73748a4efb23767404f32deebb066 error="rpc error: code = Unknown desc = EOF" exec-id=62990ae0f153ffd7b0678a8a08ba6030c9d73748a4efb23767404f32deebb066 name=kata-shim pid=1 source=shim
time="2018-09-24T06:47:00.808225604Z" level=info msg="copy stdout failed" container=62990ae0f153ffd7b0678a8a08ba6030c9d73748a4efb23767404f32deebb066 error="rpc error: code = Unknown desc = EOF" exec-id=62990ae0f153ffd7b0678a8a08ba6030c9d73748a4efb23767404f32deebb066 name=kata-shim pid=1 source=shim
time="2018-09-24T06:47:10.783199063Z" level=info msg="copy stderr failed" container=dcc8fd7c1abcadb1edb4de15428cf4cd0fc9ffb7f42eef98c1bbdbc3ac9cfe3f error="rpc error: code = Unknown desc = EOF" exec-id=dcc8fd7c1abcadb1edb4de15428cf4cd0fc9ffb7f42eef98c1bbdbc3ac9cfe3f name=kata-shim pid=1 source=shim
time="2018-09-24T06:47:10.78537479Z" level=info msg="copy stderr failed" container=501ad5e238b78dee18e7d003457b2a391e8389ee353c761abc2112bede8cee74 error="rpc error: code = Unknown desc = EOF" exec-id=501ad5e238b78dee18e7d003457b2a391e8389ee353c761abc2112bede8cee74 name=kata-shim pid=1 source=shim
time="2018-09-24T06:47:10.786567999Z" level=info msg="copy stdout failed" container=dcc8fd7c1abcadb1edb4de15428cf4cd0fc9ffb7f42eef98c1bbdbc3ac9cfe3f error="rpc error: code = Unknown desc = EOF" exec-id=dcc8fd7c1abcadb1edb4de15428cf4cd0fc9ffb7f42eef98c1bbdbc3ac9cfe3f name=kata-shim pid=1 source=shim
time="2018-09-24T06:47:10.790398757Z" level=info msg="copy stdout failed" container=501ad5e238b78dee18e7d003457b2a391e8389ee353c761abc2112bede8cee74 error="rpc error: code = Unknown desc = EOF" exec-id=501ad5e238b78dee18e7d003457b2a391e8389ee353c761abc2112bede8cee74 name=kata-shim pid=1 source=shim
time="2018-09-24T06:47:10.807478808Z" level=info msg="copy stderr failed" container=1060184190ac986a768f409ce3a0a6861c1fb3cdaba06e90df4f070663075b09 error="rpc error: code = Unknown desc = EOF" exec-id=1060184190ac986a768f409ce3a0a6861c1fb3cdaba06e90df4f070663075b09 name=kata-shim pid=1 source=shim
time="2018-09-24T06:47:10.807562816Z" level=info msg="copy stdout failed" container=1060184190ac986a768f409ce3a0a6861c1fb3cdaba06e90df4f070663075b09 error="rpc error: code = Unknown desc = EOF" exec-id=1060184190ac986a768f409ce3a0a6861c1fb3cdaba06e90df4f070663075b09 name=kata-shim pid=1 source=shim
time="2018-09-24T06:54:31.474293984Z" level=info msg="copy stdout failed" container=9009bbf50ff4ceb5adec4532218669e9033676e0119836af36ee699bf75f3782 error="rpc error: code = Unknown desc = read /dev/ptmx: input/output error" exec-id=9009bbf50ff4ceb5adec4532218669e9033676e0119836af36ee699bf75f3782 name=kata-shim pid=1 source=shim
time="2018-09-24T06:54:31.474426224Z" level=info msg="copy stdout failed" container=f4dd677761e96aceea9989d6328af799451bfa62af3b0d44173c0daa531b3269 error="rpc error: code = Unknown desc = read /dev/ptmx: input/output error" exec-id=f4dd677761e96aceea9989d6328af799451bfa62af3b0d44173c0daa531b3269 name=kata-shim pid=1 source=shim
time="2018-09-24T06:54:31.493621235Z" level=info msg="copy stdout failed" container=27944e17a8b888cf47b840920f25d6868c5aaefc26776a3126614f42697d4588 error="rpc error: code = Unknown desc = read /dev/ptmx: input/output error" exec-id=27944e17a8b888cf47b840920f25d6868c5aaefc26776a3126614f42697d4588 name=kata-shim pid=1 source=shimHave docker
Output of "docker version":
Client:
Version: 18.06.1-ce
API version: 1.38
Go version: go1.10.3
Git commit: e68fc7a
Built: Tue Aug 21 17:24:51 2018
OS/Arch: linux/amd64
Experimental: false
Server:
Engine:
Version: 18.06.1-ce
API version: 1.38 (minimum version 1.12)
Go version: go1.10.3
Git commit: e68fc7a
Built: Tue Aug 21 17:23:15 2018
OS/Arch: linux/amd64
Experimental: falseOutput of "docker info":
Containers: 4
Running: 3
Paused: 0
Stopped: 1
Images: 1
Server Version: 18.06.1-ce
Storage Driver: overlay2
Backing Filesystem: extfs
Supports d_type: true
Native Overlay Diff: true
Logging Driver: syslog
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: kata-runtime runc
Default Runtime: kata-runtime
Init Binary: docker-init
containerd version: 468a545b9edcd5932818eb9de8e72413e616e86e
runc version: 22aedc4 (expected: 69663f0bd4b60df09991c08812a60108003fa340)
init version: fec3683
Security Options:
apparmor
seccomp
Profile: default
Kernel Version: 4.15.0-34-generic
Operating System: Ubuntu 18.04.1 LTS
OSType: linux
Architecture: x86_64
CPUs: 16
Total Memory: 62.82GiB
Name: RNS-SV-KATA-001
ID: UWGY:MJA5:6VGJ:YAQY:X6F3:QRQL:JEE3:HWYM:23HC:MJHV:XSJR:J4UQ
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://index.docker.io/v1/
Labels:
Experimental: false
Insecure Registries:
127.0.0.0/8
Live Restore Enabled: false
WARNING: No swap limit supportOutput of "systemctl show docker":
Type=notify
Restart=on-failure
NotifyAccess=main
RestartUSec=100ms
TimeoutStartUSec=infinity
TimeoutStopUSec=1min 30s
RuntimeMaxUSec=infinity
WatchdogUSec=0
WatchdogTimestamp=Mon 2018-09-24 06:57:40 UTC
WatchdogTimestampMonotonic=19884200
PermissionsStartOnly=no
RootDirectoryStartOnly=no
RemainAfterExit=no
GuessMainPID=yes
MainPID=1113
ControlPID=0
FileDescriptorStoreMax=0
NFileDescriptorStore=0
StatusErrno=0
Result=success
UID=[not set]
GID=[not set]
NRestarts=0
ExecMainStartTimestamp=Mon 2018-09-24 06:57:35 UTC
ExecMainStartTimestampMonotonic=15553050
ExecMainExitTimestampMonotonic=0
ExecMainPID=1113
ExecMainCode=0
ExecMainStatus=0
ExecStart={ path=/usr/bin/dockerd ; argv[]=/usr/bin/dockerd -H fd:// ; ignore_errors=no ; start_time=[Mon 2018-09-24 06:57:35 UTC] ; stop_time=[n/a] ; pid=1113 ; 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=[not set]
CPUUsageNSec=[not set]
TasksCurrent=173
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=no
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=1048576
LimitNOFILESoft=1048576
LimitAS=infinity
LimitASSoft=infinity
LimitNPROC=infinity
LimitNPROCSoft=infinity
LimitMEMLOCK=16777216
LimitMEMLOCKSoft=16777216
LimitLOCKS=infinity
LimitLOCKSSoft=infinity
LimitSIGPENDING=257088
LimitSIGPENDINGSoft=257088
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=system.slice sysinit.target docker.socket
Wants=network-online.target
WantedBy=multi-user.target
ConsistsOf=docker.socket
Conflicts=shutdown.target
Before=multi-user.target shutdown.target
After=firewalld.service basic.target network-online.target system.slice systemd-journald.socket docker.socket sysinit.target
TriggeredBy=docker.socket
Documentation=https://docs.docker.com
Description=Docker Application Container Engine
LoadState=loaded
ActiveState=active
SubState=running
FragmentPath=/lib/systemd/system/docker.service
UnitFileState=enabled
UnitFilePreset=enabled
StateChangeTimestamp=Mon 2018-09-24 06:57:40 UTC
StateChangeTimestampMonotonic=19884204
InactiveExitTimestamp=Mon 2018-09-24 06:57:35 UTC
InactiveExitTimestampMonotonic=15553179
ActiveEnterTimestamp=Mon 2018-09-24 06:57:40 UTC
ActiveEnterTimestampMonotonic=19884204
ActiveExitTimestampMonotonic=0
InactiveEnterTimestampMonotonic=0
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=Mon 2018-09-24 06:57:35 UTC
ConditionTimestampMonotonic=15551726
AssertTimestamp=Mon 2018-09-24 06:57:35 UTC
AssertTimestampMonotonic=15551727
Transient=no
Perpetual=no
StartLimitIntervalUSec=1min
StartLimitBurst=3
StartLimitAction=none
FailureAction=none
SuccessAction=none
InvocationID=cda732e27422467599f27d77cebb21ff
CollectMode=inactiveNo kubectl
Have dpkg
Output of "dpkg -l|egrep "(cc-oci-runtimecc-runtimerunv|kata-proxy|kata-runtime|kata-shim|kata-containers-image|linux-container|qemu-)"":
ii kata-containers-image 1.3.0~rc1-34 amd64 Kata containers image
ii kata-linux-container 4.14.67.11-137 amd64 linux kernel optimised for container-like workloads.
ii kata-proxy 1.3.0~rc1+git.981fef4-34 amd64
ii kata-runtime 1.3.0~rc1+git.22aedc4-49 amd64
ii kata-shim 1.3.0~rc1+git.9b2891c-35 amd64
ii qemu-lite 2.11.0+git.f886228056-50 amd64 linux kernel optimised for container-like workloads.
ii qemu-vanilla 2.11.2+git.a39e0b3e82-44 amd64 linux kernel optimised for container-like workloads.No rpm
jodh-intel
commented
6 years ago Hi @fredbcode - thanks for posting this. Please could you attach the full proxy log:
$ sudo journalctl -q -o cat -a -t kata-proxy > ./proxy.log && gzip -9 ./proxy.logThanks @fredbcode - attaching that file here to the thread (for posterity ;-) ) If that is not OK with you then let me know and I'll drop it again. proxy.log.gz
fredbcode
commented
6 years ago No problem, let me known if something is needed, I'm familiar with dev tools (but not at all with go language :))
bergwolf
commented
6 years ago One kind of timeout I've hit is when memory preallocation is enabled and run kata on a slow machine that can cost some time to allocate the required memory. Then the very first check grpc fails on the 30 second timeout. I don't think that is the case here but just FYI.
jodh-intel
commented
6 years ago Yes, that first check call is very slow:
... but I still cannot recreate this issue.
jodh-intel
commented
6 years ago Hi @fredbcode - would you be able to create a clean set of logs basically following the simple instructions here?:
I think we only need the proxy + runtime logs. If you could clear the systemd journal first, that would be helpful so we only get a minimal set of logs from docker run.
It would also be very useful to know if you have ever seen this on a single run (first docker run)?
We really need a reliable way to recreate this to allow us to debug. If we can't do this, we could create a special version of kata-containers.img with lots of debug added to the agent running inside that which you could try running with to give us further information (however, I'm hoping we can avoid that approach at this stage).
The error message suggests that either the gRPC layer isn't ready yet (VM or agent not ready). Note that the agend hasn't died as we don't see any crashes in the proxy log.
@fredbcode - you mention you are seeing this with version 1.3.0~rc1 - did you ever see it with an older version of Kata do you remember?
One other thing you can try is to update the kernel_params entry below [hypervisor.qemu] in the configuration.toml file so that it becomes:
[hypervisor.qemu]
kernel_params = "agent.log=debug systemd.journald.forward_to_console=1 systemd.log_level=debug systemd.log_target=console"
sboeuf
commented
6 years ago I have spent some time on this issue this morning and I have been able to reproduce it very easily.
$ docker run --rm -d -ti --runtime kata-runtime fedora bash
3d66c99ea21eddb5046a1e1636adbe35148091594471e16c64f23b55c4eb40a6
$ docker run --rm -d -ti --runtime kata-runtime fedora bash
docker: Error response from daemon: OCI runtime create failed: Failed to check if grpc server is working: rpc error: code = Unavailable desc = transport is closing: unknown.Mostly, it happened on the second or third container run.
Because the first container is detached, it's still running in the background, and it's still consuming the entropy of the host, as you can see here:
$ cat /proc/sys/kernel/random/entropy_avail
3844
$ docker run --rm -d -ti --runtime kata-runtime fedora bash
b0ed37de68328fc59f1b8fa644ff5f0ac184d4782231b737e17b7199debebe74
$ cat /proc/sys/kernel/random/entropy_avail
833
$ docker run --rm -d -ti --runtime kata-runtime fedora bash
b0ed37de68328fc59f1b8fa644ff5f0ac184d4782231b737e17b7199debebe74
$ cat /proc/sys/kernel/random/entropy_avail
53
$ docker run --rm -d -ti --runtime kata-runtime fedora bash
docker: Error response from daemon: OCI runtime create failed: Failed to check if grpc server isThe problem comes from the fact that those containers are actually consuming a large amount of the host entropy, leaving almost nothing to the next ones.
I'm not sure if this is something related to one of our recent PR in the agent, because I don't think we were hitting this issue when the virtio-rng device was added to the VM, right @jcvenegas ?
fredbcode
commented
6 years ago @jodh-intel OK, I will make tests today Like sboeuf it happened at least on the second container run, for now never at first.
Yes the issue was present with "your" previous ubuntu package (I mean from your mirror) but sorry I forgot the version number
It's odd that you can reproduce, perhaps this issue is related with OS ? @sboeuf are you using Ubuntu 18.04 ?
bergwolf
commented
6 years ago @fredbcode It seems to be related to the random number generation speed on your machine. It would be great if you can verify if https://github.com/kata-containers/runtime/pull/781 fixes it.
fredbcode
commented
6 years ago Yes, but I'm using a test machine without internet, but if somehow can share with me a package (or at least just the binaries for 18.04) that would help a lot.
grahamwhaley
commented
6 years ago @sboeuf @jon et. al. I'm fairly sure we didn't used to suffer this random number stall/hangup/timeout. For our own sanity, I think it would be good if we can nail down what changed and when to make it happen. I'm fairly sure what changed changed for good reason, and we can't undo that - but, I'd like to make sure we understand statements like over on https://github.com/kata-containers/packaging/issues/193 where a non-upgrading qemu is cited as a potential candidate.
I had a memory there was a kernel related upgrade item not long ago when we first saw these random number hang up issues on our CI (@jcvenegas @chavafg for any reference...). I had a quick dig, and came up with https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux.git/commit/?h=v4.14.40&id=6e513bc20ca63f594632eca4e1968791240b8f18, referenced from https://github.com/linuxkit/linuxkit/issues/3032 . I think that is our first item in the list. Then we need to figure if a golang version update (as referred to my @mcastelino ) played a part in the mix, along with any changes in our agent and any qemu version bumps.
fredbcode
commented
6 years ago I confirm entropy impact, I generated a lot of them and now kata works better (better because I have an another bug now that I will report after, related or not I don't know -)
cat /proc/sys/kernel/random/entropy_avail 3094 docker run -d -ti --name test1 --runtime kata-runtime registry.test/images/nginx 12231b53e5efdfcb8efb98d9c731926289b510f57d832fb7b12c6d388e1efee7 docker run -d -ti --name test2 --runtime kata-runtime registry.test/images/nginx 9aeb66b118e7f79d015bf0df0c48c68a01bae45bbec07155b06f5347e5954b55 cat /proc/sys/kernel/random/entropy_avail 3082 docker run -d -ti --name test3 --runtime kata-runtime registry.test/images/nginx 31e7a9316dac3939c56983328c4794849142440c42abb4f689d45ba95de1fcdc cat /proc/sys/kernel/random/entropy_avail 3093 docker run -d -ti --name test4 --runtime kata-runtime registry.test/images/nginx 6648cc891b56af55446d8f659baaf069f1c99c15e8ec07c5fd91231818e6ad51 cat /proc/sys/kernel/random/entropy_avail 3092 docker run -d -ti --name test5 --runtime kata-runtime registry.test/images/nginx 109b3d3607c37eca971034aea6a7600a1d2c4d17d9c4c33bbd6bdef991422d51 docker run -d -ti --name test6 --runtime kata-runtime registry.test/images/nginx 6b79e15b49b34f53102c0efb2719fe1cf08a9ff193a1540dd2cc005aa2732aa1 docker run -d -ti --name test7 --runtime kata-runtime registry.test/images/nginx bc0ae230bb52279b32d73861a779fcf926ba1c685efa760bbbf4f8e0aa30aa8a
as you can see the value is stable and gprc error is gone
grahamwhaley
commented
6 years ago great, thanks @fredbcode . I also confirm - I installed haveged on my headless Ubuntu NUC, and now I can run multiple container tests again...
fredbcode
commented
6 years ago @grahamwhaley with a stable value in /proc/sys/kernel/random/entropy_avail like me ?
grahamwhaley
commented
6 years ago /me goes to hack script.... @fredbcode it would seem so. I didn't check my entropy before, but now I have between about 1k and 2.5k available before each container launch, and get no grpc timeout errors.
fredbcode
commented
6 years ago @grahamwhaley Yes I confirm it's stable because rng-tools (haveged) runs in background and generates permanently entropy
jcvenegas
commented
6 years ago @grahamwhaley so one suggestion to add a part of our docs make is a recommendation to have a daemon haveged to help the kernel to collect entropy quickly. The other is if we left urandom as default or document for users that are out of entropy.
jcvenegas
commented
6 years ago @grahamwhaley Actually my env is around 2.5 probably that is why I can not reproduce it.
sboeuf
commented
6 years ago @grahamwhaley so what would be the best approach here?
Either we force the user to have haveged on his host in order to generate more entropy, or we switch to /dev/urandom. Things are still unclear to me.
That being said, there's one point where I totally agree with you, we should understand why this issue happened at some point, since I don't think we had it before.
jcvenegas
commented
6 years ago @sboeuf I think haveged is a good recommendation anyway. About urandom it depends on the conclusion we get from the ML.
sboeuf
commented
6 years ago @jcvenegas sure but if we go with /dev/urandom, we don't really need haveged.
grahamwhaley
commented
6 years ago My gut tells me we:
urandom as the defaultrandom, and document that then the user may run out of entropy on the host, and might need to look at additional tools like haveged to supplement this.
My only concern there is if passing urandom to qemu makes the entropy of /dev/random inside the guest less 'good'. Does anybody know?
But, we need to do some more research first on VM state-of-the-art recommendations, and see if/what turns up on the mailing list. I think we have some members of the kata community who have experience in this area (scaling out VMs) who can probably contribute or know some others who can.
jcvenegas
commented
6 years ago I am not sure if running haveged will ensure good entropy if there is (a) heavy load(s) using entropy.
grahamwhaley
commented
6 years ago :-) well, technically we don't have to 'fix' the lack of entropy, we just have to document where and why it happens, and note that a fix will be needed if you are a heavy entropy user :-) We can of course point to some tools, like haveged, that may help - but, end users who are heavy entropy users may already have their own favorite solution.
jcvenegas
commented
6 years ago from @bergwolf in the ML.
I wonder if Ted's patch [1] can help us on the guest side. It relies on CPU to initialize the guest's CRNG, which (IMO) is the main reason we read a lot from virtio-rng for every new guest
@sboeuf @grahamwhaley here is a kernel with the patch let me know if solve the issue. http://lkml.iu.edu/hypermail/linux/kernel/1807.2/02498.html
jcvenegas
commented
6 years ago based in the feedback from the ML we are moving to dev/urandom as VM source of entropy. See: http://lists.katacontainers.io/pipermail/kata-dev/2018-September/000439.html
grahamwhaley
commented
6 years ago @jcvenegas I'm presuming you don't need us to test that patched kernel any more? I was curious though - if that was a host or guest kernel?
bergwolf
commented
6 years ago @grahamwhaley No, it is unnecessary now that we've decided to feed virtio-rng with host urandom.
Description of problem
I was trying to port runtime to Z. It passes all the unit tests as of now. I used the following command to run
kata-runtime --log /dev/stdout create -b ../osbuilder/ubuntu_rootfs testHowever, I got
Failed to check if grpc server is working: rpc error: code = DeadlineExceeded desc = context deadline exceededMeta details
Running
kata-collect-data.shversion1.2.0 (commit 1820047c4e028314a2a19d1773d1aa26aa42e1f8-dirty)at2018-09-05.15:29:54.876826586-0400.Runtime is
/usr/local/bin/kata-runtime.kata-envOutput of "
/usr/local/bin/kata-runtime kata-env":Runtime config files
Runtime default config files
Runtime config file contents
Config file
/etc/kata-containers/configuration.tomlnot found Output of "cat "/usr/share/defaults/kata-containers/configuration.toml"":Image details
No image
Initrd details
No initrd
Logfiles
Runtime logs
Recent runtime problems found in system journal:
Proxy logs
Recent proxy problems found in system journal:
Shim logs
No recent shim problems found in system journal.
Container manager details
Have
dockerDocker
Output of "
docker version":Output of "
docker info":Output of "
systemctl show docker":No
kubectlPackages
Have
dpkgOutput of "dpkg -l|egrep "(cc-oci-runtimecc-runtimerunv|kata-proxy|kata-runtime|kata-shim|kata-containers-image|linux-container|qemu-)"":No
rpm