Skip to content
This repository has been archived by the owner on May 12, 2021. It is now read-only.

Kata fails to start #702

Closed
ghost opened this issue Sep 5, 2018 · 44 comments
Closed

Kata fails to start #702

ghost opened this issue Sep 5, 2018 · 44 comments
Assignees
Labels
high-priority Very urgent issue (resolve quickly)

Comments

@ghost
Copy link

ghost commented Sep 5, 2018

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 test

However, I got Failed to check if grpc server is working: rpc error: code = DeadlineExceeded desc = context deadline exceeded


Meta details

Running kata-collect-data.sh version 1.2.0 (commit 1820047c4e028314a2a19d1773d1aa26aa42e1f8-dirty) at 2018-09-05.15:29:54.876826586-0400.


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

kata-env

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

cannot find model field in file /proc/cpuinfo

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-system-s390x"
kernel = "/usr/share/kata-containers/vmlinuz.container"
initrd = "/usr/share/kata-containers/kata-containers-initrd.img"
#image = "/usr/share/kata-containers/kata-containers.img"
machine_type = "s390-ccw-virtio "

# 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

Image details

No image


Initrd details

No initrd


Logfiles

Runtime logs

Recent runtime problems found in system journal:

time="2018-09-05T14:56:28.027073996-04:00" level=error msg="#\t0x80039809\truntime.allocm+0x1a9\t\t\t/usr/local/go/src/runtime/proc.go:1516" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027073996-04:00" level=error msg="#\t0x80039809\truntime.allocm+0x1a9\t\t\t/usr/local/go/src/runtime/proc.go:1516" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027073996-04:00" level=error msg="#\t0x80039809\truntime.allocm+0x1a9\t\t\t/usr/local/go/src/runtime/proc.go:1516" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027073996-04:00" level=error msg="#\t0x80039809\truntime.allocm+0x1a9\t\t\t/usr/local/go/src/runtime/proc.go:1516" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027135241-04:00" level=error msg="#\t0x8003a0bf\truntime.newm+0x2f\t\t\t/usr/local/go/src/runtime/proc.go:1830" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027135241-04:00" level=error msg="#\t0x8003a0bf\truntime.newm+0x2f\t\t\t/usr/local/go/src/runtime/proc.go:1830" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027135241-04:00" level=error msg="#\t0x8003a0bf\truntime.newm+0x2f\t\t\t/usr/local/go/src/runtime/proc.go:1830" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027135241-04:00" level=error msg="#\t0x8003a0bf\truntime.newm+0x2f\t\t\t/usr/local/go/src/runtime/proc.go:1830" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027135241-04:00" level=error msg="#\t0x8003a0bf\truntime.newm+0x2f\t\t\t/usr/local/go/src/runtime/proc.go:1830" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027135241-04:00" level=error msg="#\t0x8003a0bf\truntime.newm+0x2f\t\t\t/usr/local/go/src/runtime/proc.go:1830" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027135241-04:00" level=error msg="#\t0x8003a0bf\truntime.newm+0x2f\t\t\t/usr/local/go/src/runtime/proc.go:1830" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027201984-04:00" level=error msg="#\t0x8003a3e9\truntime.startTemplateThread+0x59\t/usr/local/go/src/runtime/proc.go:1891" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027201984-04:00" level=error msg="#\t0x8003a3e9\truntime.startTemplateThread+0x59\t/usr/local/go/src/runtime/proc.go:1891" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027201984-04:00" level=error msg="#\t0x8003a3e9\truntime.startTemplateThread+0x59\t/usr/local/go/src/runtime/proc.go:1891" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027201984-04:00" level=error msg="#\t0x8003a3e9\truntime.startTemplateThread+0x59\t/usr/local/go/src/runtime/proc.go:1891" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027201984-04:00" level=error msg="#\t0x8003a3e9\truntime.startTemplateThread+0x59\t/usr/local/go/src/runtime/proc.go:1891" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027201984-04:00" level=error msg="#\t0x8003a3e9\truntime.startTemplateThread+0x59\t/usr/local/go/src/runtime/proc.go:1891" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027201984-04:00" level=error msg="#\t0x8003a3e9\truntime.startTemplateThread+0x59\t/usr/local/go/src/runtime/proc.go:1891" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.0272788-04:00" level=error msg="#\t0x800354fb\truntime.main+0x1bb\t\t\t/usr/local/go/src/runtime/proc.go:181" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.0272788-04:00" level=error msg="#\t0x800354fb\truntime.main+0x1bb\t\t\t/usr/local/go/src/runtime/proc.go:181" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.0272788-04:00" level=error msg="#\t0x800354fb\truntime.main+0x1bb\t\t\t/usr/local/go/src/runtime/proc.go:181" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.0272788-04:00" level=error msg="#\t0x800354fb\truntime.main+0x1bb\t\t\t/usr/local/go/src/runtime/proc.go:181" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.0272788-04:00" level=error msg="#\t0x800354fb\truntime.main+0x1bb\t\t\t/usr/local/go/src/runtime/proc.go:181" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.0272788-04:00" level=error msg="#\t0x800354fb\truntime.main+0x1bb\t\t\t/usr/local/go/src/runtime/proc.go:181" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.0272788-04:00" level=error msg="#\t0x800354fb\truntime.main+0x1bb\t\t\t/usr/local/go/src/runtime/proc.go:181" arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027363046-04:00" level=error arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027363046-04:00" level=error arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027363046-04:00" level=error arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027363046-04:00" level=error arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027363046-04:00" level=error arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027363046-04:00" level=error arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027363046-04:00" level=error arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027426045-04:00" level=error arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027426045-04:00" level=error arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027426045-04:00" level=error arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027426045-04:00" level=error arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027426045-04:00" level=error arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027426045-04:00" level=error arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.027426045-04:00" level=error arch=s390x container=1 name=kata-runtime pid=41263 sandbox=1 source=runtime
time="2018-09-05T14:56:28.030204632-04:00" level=error msg="Annotations[com.github.containers.virtcontainers.pkg.oci.container_type] not found, cannot determine the container type" arch=s390x container= name=kata-runtime pid=41263 sandbox=99999999-9999-9999-99999999999999999 source=virtcontainers subsystem=oci
time="2018-09-05T14:56:28.030204632-04:00" level=error msg="Annotations[com.github.containers.virtcontainers.pkg.oci.container_type] not found, cannot determine the container type" arch=s390x container= name=kata-runtime pid=41263 sandbox=99999999-9999-9999-99999999999999999 source=virtcontainers subsystem=oci
time="2018-09-05T14:56:28.030204632-04:00" level=error msg="Annotations[com.github.containers.virtcontainers.pkg.oci.container_type] not found, cannot determine the container type" arch=s390x container= name=kata-runtime pid=41263 sandbox=99999999-9999-9999-99999999999999999 source=virtcontainers subsystem=oci
time="2018-09-05T14:56:28.030204632-04:00" level=error msg="Annotations[com.github.containers.virtcontainers.pkg.oci.container_type] not found, cannot determine the container type" arch=s390x container= name=kata-runtime pid=41263 sandbox=99999999-9999-9999-99999999999999999 source=virtcontainers subsystem=oci
time="2018-09-05T14:56:28.030204632-04:00" level=error msg="Annotations[com.github.containers.virtcontainers.pkg.oci.container_type] not found, cannot determine the container type" arch=s390x container= name=kata-runtime pid=41263 sandbox=99999999-9999-9999-99999999999999999 source=virtcontainers subsystem=oci
time="2018-09-05T14:56:28.030204632-04:00" level=error msg="Annotations[com.github.containers.virtcontainers.pkg.oci.container_type] not found, cannot determine the container type" arch=s390x container= name=kata-runtime pid=41263 sandbox=99999999-9999-9999-99999999999999999 source=virtcontainers subsystem=oci
time="2018-09-05T14:56:28.030204632-04:00" level=error msg="Annotations[com.github.containers.virtcontainers.pkg.oci.container_type] not found, cannot determine the container type" arch=s390x container= name=kata-runtime pid=41263 sandbox=99999999-9999-9999-99999999999999999 source=virtcontainers subsystem=oci
time="2018-09-05T14:57:05.008232156-04:00" level=error msg="/usr/share/defaults/kata-containers/configuration.toml: EvalSymlinks: too many links" arch=s390x command=create name=kata-runtime pid=41954 source=runtime
time="2018-09-05T15:15:41.392836552-04:00" level=error msg="/usr/share/defaults/kata-containers/configuration.toml: EvalSymlinks: too many links" arch=s390x command=create name=kata-runtime pid=6207 source=runtime
time="2018-09-05T15:16:11.280441792-04:00" level=error msg="/usr/share/defaults/kata-containers/configuration.toml: EvalSymlinks: too many links" arch=s390x command=create name=kata-runtime pid=6266 source=runtime
time="2018-09-05T15:16:15.286036822-04:00" level=error msg="/usr/share/defaults/kata-containers/configuration.toml: EvalSymlinks: too many links" arch=s390x command=create name=kata-runtime pid=6319 source=runtime

Proxy logs

Recent proxy problems found in system journal:

time="2018-09-05T15:21:04.304446926-04:00" level=fatal msg="channel error" error="session shutdown" name=kata-proxy pid=6845 sandbox=test source=proxy
time="2018-09-05T15:21:04.306412868-04:00" level=fatal msg="failed to dial channel" channel=/run/vc/vm/test/kata.sock error="dial unix /run/vc/vm/test/kata.sock: connect: no such file or directory" name=kata-proxy pid=6927 sandbox=test source=proxy
time="2018-09-05T15:29:20.104046063-04:00" level=fatal msg="failed to dial channel" channel=/run/vc/vm/test/kata.sock error="dial unix /run/vc/vm/test/kata.sock: connect: no such file or directory" name=kata-proxy pid=7711 sandbox=test source=proxy

Shim logs

No recent shim problems found in system journal.


Container manager details

Have docker

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:34 2018
 OS/Arch:           linux/s390x
 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:34 2018
  OS/Arch:          linux/s390x
  Experimental:     false

Output of "docker info":

Containers: 3
 Running: 0
 Paused: 0
 Stopped: 3
Images: 18
Server Version: 18.06.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: runc
Init Binary: docker-init
containerd version: 468a545b9edcd5932818eb9de8e72413e616e86e
runc version: 69663f0bd4b60df09991c08812a60108003fa340
init version: fec3683
Security Options:
 apparmor
 seccomp
  Profile: default
Kernel Version: 4.15.0-33-generic
Operating System: Ubuntu 16.04.5 LTS
OSType: linux
Architecture: s390x
CPUs: 4
Total Memory: 15.51GiB
Name: lxkarta1
ID: MJF7:7SBK:MKRD:N4UV:2EMB:OYOR:HSTJ:GGUD:H7SS:GSAB:36K5:PNLY
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): true
 File Descriptors: 23
 Goroutines: 44
 System Time: 2018-09-05T15:29:55.668590841-04:00
 EventsListeners: 0
Registry: https://index.docker.io/v1/
Labels:
Experimental: false
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false

WARNING: No swap limit support

Output of "systemctl show docker":

Type=simple
Restart=on-failure
NotifyAccess=none
RestartUSec=100ms
TimeoutStartUSec=infinity
TimeoutStopUSec=1min 30s
RuntimeMaxUSec=infinity
WatchdogUSec=0
WatchdogTimestamp=Thu 2018-08-30 07:19:28 EDT
WatchdogTimestampMonotonic=6510414
FailureAction=none
PermissionsStartOnly=no
RootDirectoryStartOnly=no
RemainAfterExit=no
GuessMainPID=yes
MainPID=1314
ControlPID=0
FileDescriptorStoreMax=0
NFileDescriptorStore=0
StatusErrno=0
Result=success
ExecMainStartTimestamp=Thu 2018-08-30 07:19:28 EDT
ExecMainStartTimestampMonotonic=6510396
ExecMainExitTimestampMonotonic=0
ExecMainPID=1314
ExecMainCode=0
ExecMainStatus=0
ExecStart={ path=/usr/bin/dockerd ; argv[]=/usr/bin/dockerd -D --default-runtime runc --add-runtime kata-runtime=/usr/local/bin/kata-runtime ; ignore_errors=no ; start_time=[Thu 2018-08-30 07:19:28 EDT] ; stop_time=[n/a] ; pid=1314 ; 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=2280456192
CPUUsageNSec=1377781180720
TasksCurrent=45
Delegate=yes
CPUAccounting=no
CPUShares=18446744073709551615
StartupCPUShares=18446744073709551615
CPUQuotaPerSecUSec=infinity
BlockIOAccounting=no
BlockIOWeight=18446744073709551615
StartupBlockIOWeight=18446744073709551615
MemoryAccounting=no
MemoryLimit=18446744073709551615
DevicePolicy=auto
TasksAccounting=no
TasksMax=18446744073709551615
UMask=0022
LimitCPU=18446744073709551615
LimitCPUSoft=18446744073709551615
LimitFSIZE=18446744073709551615
LimitFSIZESoft=18446744073709551615
LimitDATA=18446744073709551615
LimitDATASoft=18446744073709551615
LimitSTACK=18446744073709551615
LimitSTACKSoft=8388608
LimitCORE=18446744073709551615
LimitCORESoft=18446744073709551615
LimitRSS=18446744073709551615
LimitRSSSoft=18446744073709551615
LimitNOFILE=1048576
LimitNOFILESoft=1048576
LimitAS=18446744073709551615
LimitASSoft=18446744073709551615
LimitNPROC=18446744073709551615
LimitNPROCSoft=18446744073709551615
LimitMEMLOCK=65536
LimitMEMLOCKSoft=65536
LimitLOCKS=18446744073709551615
LimitLOCKSSoft=18446744073709551615
LimitSIGPENDING=63445
LimitSIGPENDINGSoft=63445
LimitMSGQUEUE=819200
LimitMSGQUEUESoft=819200
LimitNICE=0
LimitNICESoft=0
LimitRTPRIO=0
LimitRTPRIOSoft=0
LimitRTTIME=18446744073709551615
LimitRTTIMESoft=18446744073709551615
OOMScoreAdjust=0
Nice=0
IOScheduling=0
CPUSchedulingPolicy=0
CPUSchedulingPriority=0
TimerSlackNSec=50000
CPUSchedulingResetOnFork=no
NonBlocking=no
StandardInput=null
StandardOutput=journal
StandardError=inherit
TTYReset=no
TTYVHangup=no
TTYVTDisallocate=no
SyslogPriority=30
SyslogLevelPrefix=yes
SyslogLevel=6
SyslogFacility=3
SecureBits=0
CapabilityBoundingSet=18446744073709551615
AmbientCapabilities=0
MountFlags=0
PrivateTmp=no
PrivateNetwork=no
PrivateDevices=no
ProtectHome=no
ProtectSystem=no
SameProcessGroup=no
UtmpMode=init
IgnoreSIGPIPE=yes
NoNewPrivileges=no
SystemCallErrorNumber=0
RuntimeDirectoryMode=0755
KillMode=process
KillSignal=15
SendSIGKILL=yes
SendSIGHUP=no
Id=docker.service
Names=docker.service
Requires=docker.socket system.slice sysinit.target
Wants=network-online.target
WantedBy=multi-user.target
ConsistsOf=docker.socket
Conflicts=shutdown.target
Before=shutdown.target multi-user.target
After=network-online.target firewalld.service sysinit.target basic.target system.slice docker.socket systemd-journald.socket
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
DropInPaths=/etc/systemd/system/docker.service.d/kata-containers.conf
UnitFileState=enabled
UnitFilePreset=enabled
StateChangeTimestamp=Thu 2018-08-30 07:19:28 EDT
StateChangeTimestampMonotonic=6510414
InactiveExitTimestamp=Thu 2018-08-30 07:19:28 EDT
InactiveExitTimestampMonotonic=6510414
ActiveEnterTimestamp=Thu 2018-08-30 07:19:28 EDT
ActiveEnterTimestampMonotonic=6510414
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
JobTimeoutAction=none
ConditionResult=yes
AssertResult=yes
ConditionTimestamp=Thu 2018-08-30 07:19:28 EDT
ConditionTimestampMonotonic=6509668
AssertTimestamp=Thu 2018-08-30 07:19:28 EDT
AssertTimestampMonotonic=6509668
Transient=no
StartLimitInterval=60000000
StartLimitBurst=3
StartLimitAction=none

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-)"":

ii  ipxe-qemu-256k-compat-efi-roms      1.0.0+git-20150424.a25a16d-0ubuntu2~cloud0  all          PXE boot firmware - Compat EFI ROM images for qemu
ii  qemu-block-extra:s390x              1:2.11+dfsg-1ubuntu7.4~cloud0               s390x        extra block backend modules for qemu-system and qemu-utils
ii  qemu-efi                            0~20160408.ffea0a2c-2                       all          UEFI firmware for virtual machines
ii  qemu-kvm                            1:2.11+dfsg-1ubuntu7.4~cloud0               s390x        QEMU Full virtualization on x86 hardware
ii  qemu-launcher                       1.7.4-1ubuntu2                              all          GTK+ front-end to QEMU computer emulator
ii  qemu-slof                           20151103+dfsg-1ubuntu1.1                    all          Slimline Open Firmware -- QEMU PowerPC version
ii  qemu-system                         1:2.11+dfsg-1ubuntu7.4~cloud0               s390x        QEMU full system emulation binaries
ii  qemu-system-arm                     1:2.11+dfsg-1ubuntu7.4~cloud0               s390x        QEMU full system emulation binaries (arm)
ii  qemu-system-common                  1:2.11+dfsg-1ubuntu7.4~cloud0               s390x        QEMU full system emulation binaries (common files)
ii  qemu-system-mips                    1:2.11+dfsg-1ubuntu7.4~cloud0               s390x        QEMU full system emulation binaries (mips)
ii  qemu-system-misc                    1:2.11+dfsg-1ubuntu7.4~cloud0               s390x        QEMU full system emulation binaries (miscellaneous)
ii  qemu-system-ppc                     1:2.11+dfsg-1ubuntu7.4~cloud0               s390x        QEMU full system emulation binaries (ppc)
ii  qemu-system-s390x                   1:2.11+dfsg-1ubuntu7.4~cloud0               s390x        QEMU full system emulation binaries (s390x)
ii  qemu-system-sparc                   1:2.11+dfsg-1ubuntu7.4~cloud0               s390x        QEMU full system emulation binaries (sparc)
ii  qemu-system-x86                     1:2.11+dfsg-1ubuntu7.4~cloud0               s390x        QEMU full system emulation binaries (x86)
ii  qemu-user                           1:2.11+dfsg-1ubuntu7.4~cloud0               s390x        QEMU user mode emulation binaries
ii  qemu-user-binfmt                    1:2.11+dfsg-1ubuntu7.4~cloud0               s390x        QEMU user mode binfmt registration for qemu-user
ii  qemu-utils                          1:2.11+dfsg-1ubuntu7.4~cloud0               s390x        QEMU utilities

No rpm


@jcvenegas
Copy link
Member

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
Copy link
Author

ghost commented Sep 5, 2018

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
Copy link
Member

See this several times, you can take a look at #516 #576 #626

@jodh-intel
Copy link
Contributor

Hi @ydjainopensource - A few things:

@fredbcode
Copy link

fredbcode commented Sep 21, 2018

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
Copy link
Contributor

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
Copy link
Contributor

If those affected could please:

  • enable full debug.
  • try to create a container.
  • run 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
Copy link
Contributor

There is a related mention over on kata-containers/tests#766 (comment) 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
Copy link
Member

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
Copy link
Contributor

Wait, if only we had agent tracing ...! 😄

@devimc
Copy link

devimc commented Sep 21, 2018

@fredbcode please try with vsocks

@fredbcode
Copy link

@devimc how ?

I will post debug monday

@fredbcode
Copy link

fredbcode commented Sep 24, 2018

@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
Copy link

fredbcode commented Sep 24, 2018

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

Meta details

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-env

Output 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"

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 = ""

# 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

Image details

---
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"

Initrd details

No initrd


Logfiles

Runtime logs

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=qemu

Proxy logs

Recent 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=agent

Shim logs

Recent 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=shim

Container manager details

Have docker

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:     false

Output 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 support

Output 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=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-)"":

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
Copy link
Contributor

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.log

@fredbcode
Copy link

@grahamwhaley
Copy link
Contributor

Thanks @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
Copy link

No problem, let me known if something is needed, I'm familiar with dev tools (but not at all with go language :))

@bergwolf
Copy link
Member

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 jodh-intel added the high-priority Very urgent issue (resolve quickly) label Sep 24, 2018
@jodh-intel
Copy link
Contributor

Yes, that first check call is very slow:

... but I still cannot recreate this issue.

@jodh-intel
Copy link
Contributor

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
Copy link

sboeuf commented Sep 24, 2018

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 is

The 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 ?

jcvenegas added a commit to jcvenegas/runtime that referenced this issue Sep 24, 2018
Today we use /dev/random as entropy source.
This is a blocking entropy source, when the
host is getting a low amount of entropy the
Kata VM startup takes longer because block
trying to get entropy from the source.

This change the entropy source to /dev/urandom
that is non-blocking .

Fixes: kata-containers#702

Signed-off-by: Jose Carlos Venegas Munoz <jose.carlos.venegas.munoz@intel.com>
@fredbcode
Copy link

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
Copy link
Contributor

@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 kata-containers/packaging#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 linuxkit/linuxkit#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
Copy link

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
Copy link
Contributor

great, thanks @fredbcode . I also confirm - I installed haveged on my headless Ubuntu NUC, and now I can run multiple container tests again...

@fredbcode
Copy link

@grahamwhaley with a stable value in /proc/sys/kernel/random/entropy_avail like me ?

@grahamwhaley
Copy link
Contributor

/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
Copy link

@grahamwhaley Yes I confirm it's stable because rng-tools (haveged) runs in background and generates permanently entropy

jcvenegas added a commit to jcvenegas/runtime that referenced this issue Sep 25, 2018
This adds a config option to choose the VM entropy
source.

Fixes: kata-containers#702

Signed-off-by: Jose Carlos Venegas Munoz <jose.carlos.venegas.munoz@intel.com>
@jcvenegas
Copy link
Member

@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
Copy link
Member

@grahamwhaley Actually my env is around 2.5 probably that is why I can not reproduce it.

@sboeuf
Copy link

sboeuf commented Sep 25, 2018

@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
Copy link
Member

@sboeuf I think haveged is a good recommendation anyway. About urandom it depends on the conclusion we get from the ML.

@sboeuf
Copy link

sboeuf commented Sep 25, 2018

@jcvenegas sure but if we go with /dev/urandom, we don't really need haveged.

@grahamwhaley
Copy link
Contributor

My gut tells me we:

  • go with urandom as the default
  • have the option to switch to random, 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.
    • this would also give distros the option to choose their default when package/shipping.

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
Copy link
Member

I am not sure if running haveged will ensure good entropy if there is (a) heavy load(s) using entropy.

@grahamwhaley
Copy link
Contributor

:-) 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 added a commit to jcvenegas/runtime that referenced this issue Sep 25, 2018
This adds a config option to choose the VM entropy
source.

Fixes: kata-containers#702

Signed-off-by: Jose Carlos Venegas Munoz <jose.carlos.venegas.munoz@intel.com>
jcvenegas added a commit to jcvenegas/runtime that referenced this issue Sep 25, 2018
This adds a config option to choose the VM entropy
source.

Fixes: kata-containers#702

Signed-off-by: Jose Carlos Venegas Munoz <jose.carlos.venegas.munoz@intel.com>
jcvenegas added a commit to jcvenegas/runtime that referenced this issue Sep 25, 2018
This adds a config option to choose the VM entropy
source.

Fixes: kata-containers#702

Signed-off-by: Jose Carlos Venegas Munoz <jose.carlos.venegas.munoz@intel.com>
@jcvenegas
Copy link
Member

jcvenegas commented Sep 25, 2018

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

vmlinuz-4.14.zip

jcvenegas added a commit to jcvenegas/runtime that referenced this issue Sep 25, 2018
This adds a config option to choose the VM entropy
source.

Fixes: kata-containers#702

Signed-off-by: Jose Carlos Venegas Munoz <jose.carlos.venegas.munoz@intel.com>
jcvenegas added a commit to jcvenegas/runtime that referenced this issue Sep 25, 2018
This adds a config option to choose the VM entropy
source.

Fixes: kata-containers#702

Signed-off-by: Jose Carlos Venegas Munoz <jose.carlos.venegas.munoz@intel.com>
@jcvenegas
Copy link
Member

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
Copy link
Contributor

@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
Copy link
Member

@grahamwhaley No, it is unnecessary now that we've decided to feed virtio-rng with host urandom.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
high-priority Very urgent issue (resolve quickly)
Projects
None yet
Development

No branches or pull requests

8 participants