search

kata-containers / runtime

Kata Containers version 1.x runtime (for version 2.x see https://github.com/kata-containers/kata-containers).
https://katacontainers.io/
Apache License 2.0
2.1k stars 374 forks source link

kata container fail to start when vm boot time become longer #979

Closed telala closed 3 years ago

telala commented 6 years ago

Description of problem

I changed the kernel for the vm when starting the kata container. And the vm's boot time is longer than before. I got the following error messages when starting a kata container: docker: Error response from daemon: oci runtime error: Failed to check if grpc server is working: rpc error: code = Unavailable desc = transport is closing.

I think the reason is the kata-agent start slowly because the vm start slow and triggered some timeout. But I can not find the exact timeout.

Expected result

Actual result

(replace this text with the output of the kata-collect-data.sh script, after you have reviewed its content to ensure it does not contain any private information).

jodh-intel commented 6 years ago

Hi @telala - thanks for reporting.

Please could do the following:

grahamwhaley commented 6 years ago

also @telala - some details about which kernel version and what changes/config you used might help. I would not expect a kernel boot to be so slow to make the grpc/agent timeout - it might be that you have some feature that kata needs not enabled in your kernel also.

telala commented 6 years ago

@grahamwhaley I only add the ftrace and muma support in the kernel. the kernel version is 4.14.68. I add some gpus to the kata container when I add 2 gpus kata container can boot succeed. But when I add 4 gpus the kata container fail to boot and give the above messages. The initialization of gpu is time consuming because it have to allocate 32GB bar for each gpu which is time consuming.

@jodh-intel following is the output of kata-collect-data.sh: [root@**** /data1/kata/kvm4.0_host_daemon]# kata-collect-data.sh

Meta details

Running kata-collect-data.sh version 1.3.0 (commit 57a1ead6b57da2337d00fd0b65ed89cafc25cf10) at 2018-12-05.18:35:28.040517470+0800.

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

kata-env

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

[Meta]
  Version = "1.0.19"

[Runtime]
  Debug = true
  DisableNewNetNs = true
  Path = "/usr/local/bin/kata-runtime"
  [Runtime.Version]
    Semver = "1.3.0"
    Commit = "57a1ead6b57da2337d00fd0b65ed89cafc25cf10-dirty"
    OCI = "1.0.1-dev"
  [Runtime.Config]
    Path = "/usr/share/defaults/kata-containers/configuration.toml"

[Hypervisor]
  MachineType = "pc"
  Version = "QEMU emulator version 3.0.0 (-dirty)\nCopyright (c) 2003-2017 Fabrice Bellard and the QEMU Project developers"
  Path = "/usr/local/bin/qemu-system-x86_64"
  BlockDeviceDriver = "virtio-scsi"
  EntropySource = "/dev/urandom"
  Msize9p = 8192
  MemorySlots = 10
  Debug = true
  UseVSock = false

[Image]
  Path = "/data1/kata/kata-img/kata-containers.img"

[Kernel]
  Path = "/data1/kata/kata-img/vmlinuz.container"
  Parameters = "agent.log=debug initcall_debug"

[Initrd]
  Path = ""

[Proxy]
  Type = "kataProxy"
  Version = "kata-proxy version 1.3.1-d364b2e"
  Path = "/usr/libexec/kata-containers/kata-proxy"
  Debug = true

[Shim]
  Type = "kataShim"
  Version = "kata-shim version 1.3.1-58f757d"
  Path = "/usr/libexec/kata-containers/kata-shim"
  Debug = true

[Agent]
  Type = "kata"

[Host]
  Kernel = "4.14.68-1-linux_runv_nosign_test1-0005"
  Architecture = "amd64"
  VMContainerCapable = false
  SupportVSocks = false
  [Host.Distro]
    Name = "linux"
    Version = "2.2"
  [Host.CPU]
    Vendor = "GenuineIntel"
    Model = "Intel(R) Xeon(R) CPU E5-2680 v4 @ 2.40GHz"

[Netmon]
  Version = "kata-netmon version 1.3.0"
  Path = "/usr/libexec/kata-containers/kata-netmon"
  Debug = true
  Enable = false

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/local/bin/qemu-system-x86_64"
kernel = "/data1/kata/kata-img/vmlinuz.container"
#initrd = "/usr/share/kata-containers/kata-containers-initrd.img"
image = "/data1/kata/kata-img/kata-containers.img"
machine_type = "pc"

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

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

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

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

# 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 = 65536
#
# Default memory slots per SB/VM.
# If unspecified then it will be set 10.
# This is will determine the times that memory will be hotadded to sandbox/VM.
#memory_slots = 10

# 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

# If host doesn't support vhost_net, set to true. Thus we won't create vhost fds for nics.
# Default false
#disable_vhost_net = true
#
# Default entropy source.
# The path to a host source of entropy (including a real hardware RNG)
# /dev/urandom and /dev/random are two main options.
# Be aware that /dev/random is a blocking source of entropy.  If the host
# runs out of entropy, the VMs boot time will increase leading to get startup
# timeouts.
# The source of entropy /dev/urandom is non-blocking and provides a
# generally acceptable source of entropy. It should work well for pretty much
# all practical purposes.
#entropy_source= "/dev/urandom"

# Path to OCI hook binaries in the *guest rootfs*.
# This does not affect host-side hooks which must instead be added to
# the OCI spec passed to the runtime.
#
# You can create a rootfs with hooks by customizing the osbuilder scripts:
# https://github.com/kata-containers/osbuilder
#
# Hooks must be stored in a subdirectory of guest_hook_path according to their
# hook type, i.e. "guest_hook_path/{prestart,postart,poststop}".
# The agent will scan these directories for executable files and add them, in
# lexicographical order, to the lifecycle of the guest container.
# Hooks are executed in the runtime namespace of the guest. See the official documentation:
# https://github.com/opencontainers/runtime-spec/blob/v1.0.1/config.md#posix-platform-hooks
# Warnings will be logged if any error is encountered will scanning for hooks,
# but it will not abort container execution.
#guest_hook_path = "/usr/share/oci/hooks"

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

[netmon]
# If enabled, the network monitoring process gets started when the
# sandbox is created. This allows for the detection of some additional
# network being added to the existing network namespace, after the
# sandbox has been created.
# (default: disabled)
#enable_netmon = true

# Specify the path to the netmon binary.
path = "/usr/libexec/kata-containers/kata-netmon"

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

[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.
#
#   - none
#     Used when customize network. Only creates a tap device. No veth pair.
#
#   - tcfilter
#     Uses tc filter rules to redirect traffic from the network interface
#     provided by plugin to a tap interface connected to the VM.
#
internetworking_model="none"

# If enabled, the runtime will create opentracing.io traces and spans.
# (See https://www.jaegertracing.io/docs/getting-started).
# (default: disabled)
#enable_tracing = true

# If enabled, the runtime will not create a network namespace for shim and hypervisor processes.
# This option may have some potential impacts to your host. It should only be used when you know what you're doing.
# `disable_new_netns` conflicts with `enable_netmon`
# `disable_new_netns` conflicts with `internetworking_model=bridged` and `internetworking_model=macvtap`. It works only
# with `internetworking_model=none`. The tap device will be in the host network namespace and can connect to a bridge
# (like OVS) directly.
# If you are using docker, `disable_new_netns` only works with `docker run --net=none`
# (default: false)
disable_new_netns = true

KSM throttler

version

Output of "/usr/lib/systemd/system/kata-ksm-throttler.service --version":

/usr/local/bin/kata-collect-data.sh: line 168: /usr/lib/systemd/system/kata-ksm-throttler.service: Permission denied

Output of "/usr/libexec/kata-ksm-throttler/kata-ksm-throttler --version":

kata-ksm-throttler version 1.3.0-6e903fb

systemd service

Image details

unknown

Initrd details

No initrd

Logfiles

Runtime logs

Recent runtime problems found in system journal:

time="2018-12-05T17:19:27.450985437+08:00" level=debug msg="Could not retrieve anything from storage" arch=amd64 command=create container=4eebb7ddd06968f99bd3e969b3ef5317ee50cf1737dbeb415f66c4ccebfcd972 name=kata-runtime pid=13214 source=virtcontainers subsystem=kata_agent
time="2018-12-05T17:19:27.45376105+08:00" level=warning msg="fetch sandbox device failed" arch=amd64 command=create container=4eebb7ddd06968f99bd3e969b3ef5317ee50cf1737dbeb415f66c4ccebfcd972 error="open /run/vc/sbs/4eebb7ddd06968f99bd3e969b3ef5317ee50cf1737dbeb415f66c4ccebfcd972/devices.json: no such file or directory" name=kata-runtime pid=13214 sandbox=4eebb7ddd06968f99bd3e969b3ef5317ee50cf1737dbeb415f66c4ccebfcd972 sandboxid=4eebb7ddd06968f99bd3e969b3ef5317ee50cf1737dbeb415f66c4ccebfcd972 source=virtcontainers subsystem=sandbox
time="2018-12-05T17:20:24.590961931+08:00" level=error msg="Container not ready, running or paused, impossible to signal the container" arch=amd64 command=kill container=4eebb7ddd06968f99bd3e969b3ef5317ee50cf1737dbeb415f66c4ccebfcd972 name=kata-runtime pid=13772 sandbox=4eebb7ddd06968f99bd3e969b3ef5317ee50cf1737dbeb415f66c4ccebfcd972 source=runtime
time="2018-12-05T17:20:24.634178982+08:00" level=error msg="Container ID (4eebb7ddd06968f99bd3e969b3ef5317ee50cf1737dbeb415f66c4ccebfcd972) does not exist" arch=amd64 command=delete container=4eebb7ddd06968f99bd3e969b3ef5317ee50cf1737dbeb415f66c4ccebfcd972 name=kata-runtime pid=13812 source=runtime
time="2018-12-05T17:21:45.803021126+08:00" level=debug msg="Could not retrieve anything from storage" arch=amd64 command=create container=a646047a129d9b48ff1bc2fa78076351a4622aef70384d2d0f2db6404d76e9c9 name=kata-runtime pid=14263 source=virtcontainers subsystem=kata_agent
time="2018-12-05T17:21:45.805732306+08:00" level=warning msg="fetch sandbox device failed" arch=amd64 command=create container=a646047a129d9b48ff1bc2fa78076351a4622aef70384d2d0f2db6404d76e9c9 error="open /run/vc/sbs/a646047a129d9b48ff1bc2fa78076351a4622aef70384d2d0f2db6404d76e9c9/devices.json: no such file or directory" name=kata-runtime pid=14263 sandbox=a646047a129d9b48ff1bc2fa78076351a4622aef70384d2d0f2db6404d76e9c9 sandboxid=a646047a129d9b48ff1bc2fa78076351a4622aef70384d2d0f2db6404d76e9c9 source=virtcontainers subsystem=sandbox
time="2018-12-05T17:28:11.966196074+08:00" level=error msg="Container not ready, running or paused, impossible to signal the container" arch=amd64 command=kill container=a646047a129d9b48ff1bc2fa78076351a4622aef70384d2d0f2db6404d76e9c9 name=kata-runtime pid=17431 sandbox=a646047a129d9b48ff1bc2fa78076351a4622aef70384d2d0f2db6404d76e9c9 source=runtime
time="2018-12-05T17:28:12.006334934+08:00" level=error msg="Container ID (a646047a129d9b48ff1bc2fa78076351a4622aef70384d2d0f2db6404d76e9c9) does not exist" arch=amd64 command=delete container=a646047a129d9b48ff1bc2fa78076351a4622aef70384d2d0f2db6404d76e9c9 name=kata-runtime pid=17464 source=runtime
time="2018-12-05T17:30:25.339975547+08:00" level=debug msg="Could not retrieve anything from storage" arch=amd64 command=create container=f2472dd91ee92205261433f63e4c50096e6e0372dfa32566f96f19c8542cc923 name=kata-runtime pid=18382 source=virtcontainers subsystem=kata_agent
time="2018-12-05T17:30:25.342729027+08:00" level=warning msg="fetch sandbox device failed" arch=amd64 command=create container=f2472dd91ee92205261433f63e4c50096e6e0372dfa32566f96f19c8542cc923 error="open /run/vc/sbs/f2472dd91ee92205261433f63e4c50096e6e0372dfa32566f96f19c8542cc923/devices.json: no such file or directory" name=kata-runtime pid=18382 sandbox=f2472dd91ee92205261433f63e4c50096e6e0372dfa32566f96f19c8542cc923 sandboxid=f2472dd91ee92205261433f63e4c50096e6e0372dfa32566f96f19c8542cc923 source=virtcontainers subsystem=sandbox
time="2018-12-05T17:32:04.219064375+08:00" level=error msg="Container not ready, running or paused, impossible to signal the container" arch=amd64 command=kill container=f2472dd91ee92205261433f63e4c50096e6e0372dfa32566f96f19c8542cc923 name=kata-runtime pid=19299 sandbox=f2472dd91ee92205261433f63e4c50096e6e0372dfa32566f96f19c8542cc923 source=runtime
time="2018-12-05T17:32:04.258911696+08:00" level=error msg="Container ID (f2472dd91ee92205261433f63e4c50096e6e0372dfa32566f96f19c8542cc923) does not exist" arch=amd64 command=delete container=f2472dd91ee92205261433f63e4c50096e6e0372dfa32566f96f19c8542cc923 name=kata-runtime pid=19347 source=runtime
time="2018-12-05T17:34:12.160014328+08:00" level=debug msg="Could not retrieve anything from storage" arch=amd64 command=create container=21425d0d4c9cb63d0a542bc3fcb9ceef824b74f7014f0f0048833573e874c9d5 name=kata-runtime pid=20352 source=virtcontainers subsystem=kata_agent
time="2018-12-05T17:34:12.162762458+08:00" level=warning msg="fetch sandbox device failed" arch=amd64 command=create container=21425d0d4c9cb63d0a542bc3fcb9ceef824b74f7014f0f0048833573e874c9d5 error="open /run/vc/sbs/21425d0d4c9cb63d0a542bc3fcb9ceef824b74f7014f0f0048833573e874c9d5/devices.json: no such file or directory" name=kata-runtime pid=20352 sandbox=21425d0d4c9cb63d0a542bc3fcb9ceef824b74f7014f0f0048833573e874c9d5 sandboxid=21425d0d4c9cb63d0a542bc3fcb9ceef824b74f7014f0f0048833573e874c9d5 source=virtcontainers subsystem=sandbox
time="2018-12-05T17:56:21.219926674+08:00" level=error msg="rpc error: code = Unavailable desc = transport is closing" arch=amd64 command=exec container=21425d0d4c9cb63d0a542bc3fcb9ceef824b74f7014f0f0048833573e874c9d5 name=kata-runtime pid=31531 sandbox=21425d0d4c9cb63d0a542bc3fcb9ceef824b74f7014f0f0048833573e874c9d5 source=runtime
time="2018-12-05T17:58:20.197298951+08:00" level=error msg="Container still running, should be stopped" arch=amd64 command=delete container=21425d0d4c9cb63d0a542bc3fcb9ceef824b74f7014f0f0048833573e874c9d5 name=kata-runtime pid=32060 sandbox=21425d0d4c9cb63d0a542bc3fcb9ceef824b74f7014f0f0048833573e874c9d5 source=runtime
time="2018-12-05T17:58:29.575840467+08:00" level=debug msg="Could not retrieve anything from storage" arch=amd64 command=create container=8ac551a1283e9e868ef0fd32f5d18ae2dbeec3b0ecd0fddb0f0f84b776ca880f name=kata-runtime pid=32645 source=virtcontainers subsystem=kata_agent
time="2018-12-05T17:58:29.580110741+08:00" level=warning msg="fetch sandbox device failed" arch=amd64 command=create container=8ac551a1283e9e868ef0fd32f5d18ae2dbeec3b0ecd0fddb0f0f84b776ca880f error="open /run/vc/sbs/8ac551a1283e9e868ef0fd32f5d18ae2dbeec3b0ecd0fddb0f0f84b776ca880f/devices.json: no such file or directory" name=kata-runtime pid=32645 sandbox=8ac551a1283e9e868ef0fd32f5d18ae2dbeec3b0ecd0fddb0f0f84b776ca880f sandboxid=8ac551a1283e9e868ef0fd32f5d18ae2dbeec3b0ecd0fddb0f0f84b776ca880f source=virtcontainers subsystem=sandbox
time="2018-12-05T17:58:29.593453728+08:00" level=error msg="Unable to launch /usr/local/bin/qemu-system-x86_64: exit status 1" arch=amd64 command=create container=8ac551a1283e9e868ef0fd32f5d18ae2dbeec3b0ecd0fddb0f0f84b776ca880f name=kata-runtime pid=32645 source=virtcontainers subsystem=qmp
time="2018-12-05T17:58:29.593527073+08:00" level=error msg="chenxg:kvm ioctl to set gpu plugin notifier fd:40\n2018.12.05 17:58:29 chenxg:kvm set plugin notifier succeed\nchenxg:kvm ioctl to set gpu unplug notifier fd:41\nchenxg:kvm set unplug notifier succeed\nqemu-system-x86_64: Could not set up host forwarding rule 'tcp::10022-:22'\n" arch=amd64 command=create container=8ac551a1283e9e868ef0fd32f5d18ae2dbeec3b0ecd0fddb0f0f84b776ca880f name=kata-runtime pid=32645 source=virtcontainers subsystem=qmp
time="2018-12-05T17:58:29.593662372+08:00" level=error msg="chenxg:kvm ioctl to set gpu plugin notifier fd:40\n2018.12.05 17:58:29 chenxg:kvm set plugin notifier succeed\nchenxg:kvm ioctl to set gpu unplug notifier fd:41\nchenxg:kvm set unplug notifier succeed\nqemu-system-x86_64: Could not set up host forwarding rule 'tcp::10022-:22'\n" arch=amd64 command=create container=8ac551a1283e9e868ef0fd32f5d18ae2dbeec3b0ecd0fddb0f0f84b776ca880f name=kata-runtime pid=32645 source=runtime
time="2018-12-05T17:58:29.604559572+08:00" level=error msg="Container ID (8ac551a1283e9e868ef0fd32f5d18ae2dbeec3b0ecd0fddb0f0f84b776ca880f) does not exist" arch=amd64 command=delete container=8ac551a1283e9e868ef0fd32f5d18ae2dbeec3b0ecd0fddb0f0f84b776ca880f name=kata-runtime pid=32664 source=runtime
time="2018-12-05T17:58:29.635452822+08:00" level=error msg="Container ID (8ac551a1283e9e868ef0fd32f5d18ae2dbeec3b0ecd0fddb0f0f84b776ca880f) does not exist" arch=amd64 command=delete container=8ac551a1283e9e868ef0fd32f5d18ae2dbeec3b0ecd0fddb0f0f84b776ca880f name=kata-runtime pid=32673 source=runtime
time="2018-12-05T17:59:28.859495301+08:00" level=debug msg="Could not retrieve anything from storage" arch=amd64 command=create container=d44de99f23ddc17448079edaf6bdbf666a8a2017684c94ce28a5f2dfd8050b68 name=kata-runtime pid=33020 source=virtcontainers subsystem=kata_agent
time="2018-12-05T17:59:28.862306063+08:00" level=warning msg="fetch sandbox device failed" arch=amd64 command=create container=d44de99f23ddc17448079edaf6bdbf666a8a2017684c94ce28a5f2dfd8050b68 error="open /run/vc/sbs/d44de99f23ddc17448079edaf6bdbf666a8a2017684c94ce28a5f2dfd8050b68/devices.json: no such file or directory" name=kata-runtime pid=33020 sandbox=d44de99f23ddc17448079edaf6bdbf666a8a2017684c94ce28a5f2dfd8050b68 sandboxid=d44de99f23ddc17448079edaf6bdbf666a8a2017684c94ce28a5f2dfd8050b68 source=virtcontainers subsystem=sandbox
time="2018-12-05T18:04:12.038830567+08:00" level=error msg="rpc error: code = Internal desc = Could not run process: container_linux.go:348: starting container process caused \"exec: \\\"exec\\\": executable file not found in $PATH\"" arch=amd64 command=exec container=d44de99f23ddc17448079edaf6bdbf666a8a2017684c94ce28a5f2dfd8050b68 name=kata-runtime pid=37866 sandbox=d44de99f23ddc17448079edaf6bdbf666a8a2017684c94ce28a5f2dfd8050b68 source=runtime
time="2018-12-05T18:06:14.870823228+08:00" level=error msg="Container not ready, running or paused, impossible to signal the container" arch=amd64 command=kill container=d44de99f23ddc17448079edaf6bdbf666a8a2017684c94ce28a5f2dfd8050b68 name=kata-runtime pid=40057 sandbox=d44de99f23ddc17448079edaf6bdbf666a8a2017684c94ce28a5f2dfd8050b68 source=runtime
time="2018-12-05T18:06:14.911476321+08:00" level=error msg="Container ID (d44de99f23ddc17448079edaf6bdbf666a8a2017684c94ce28a5f2dfd8050b68) does not exist" arch=amd64 command=delete container=d44de99f23ddc17448079edaf6bdbf666a8a2017684c94ce28a5f2dfd8050b68 name=kata-runtime pid=40096 source=runtime
time="2018-12-05T18:07:16.642607035+08:00" level=debug msg="Could not retrieve anything from storage" arch=amd64 command=create container=4cee43ca9d53ad0c634f02295457dc306fcc10739631309ad64e558cad70afb9 name=kata-runtime pid=40651 source=virtcontainers subsystem=kata_agent
time="2018-12-05T18:07:16.645315949+08:00" level=warning msg="fetch sandbox device failed" arch=amd64 command=create container=4cee43ca9d53ad0c634f02295457dc306fcc10739631309ad64e558cad70afb9 error="open /run/vc/sbs/4cee43ca9d53ad0c634f02295457dc306fcc10739631309ad64e558cad70afb9/devices.json: no such file or directory" name=kata-runtime pid=40651 sandbox=4cee43ca9d53ad0c634f02295457dc306fcc10739631309ad64e558cad70afb9 sandboxid=4cee43ca9d53ad0c634f02295457dc306fcc10739631309ad64e558cad70afb9 source=virtcontainers subsystem=sandbox
time="2018-12-05T18:08:03.799187833+08:00" level=error msg="Failed to check if grpc server is working: rpc error: code = Unavailable desc = transport is closing" arch=amd64 command=create container=4cee43ca9d53ad0c634f02295457dc306fcc10739631309ad64e558cad70afb9 name=kata-runtime pid=40651 source=runtime
time="2018-12-05T18:08:03.809192557+08:00" level=error msg="Container ID (4cee43ca9d53ad0c634f02295457dc306fcc10739631309ad64e558cad70afb9) does not exist" arch=amd64 command=delete container=4cee43ca9d53ad0c634f02295457dc306fcc10739631309ad64e558cad70afb9 name=kata-runtime pid=41144 source=runtime
time="2018-12-05T18:08:03.849078654+08:00" level=error msg="Container ID (4cee43ca9d53ad0c634f02295457dc306fcc10739631309ad64e558cad70afb9) does not exist" arch=amd64 command=delete container=4cee43ca9d53ad0c634f02295457dc306fcc10739631309ad64e558cad70afb9 name=kata-runtime pid=41153 source=runtime
time="2018-12-05T18:21:00.258684961+08:00" level=debug msg="Could not retrieve anything from storage" arch=amd64 command=create container=b9685b5836f219a819ad568d45bdf533e2acbb3fc58b662384c55635670316aa name=kata-runtime pid=47457 source=virtcontainers subsystem=kata_agent
time="2018-12-05T18:21:00.261457161+08:00" level=warning msg="fetch sandbox device failed" arch=amd64 command=create container=b9685b5836f219a819ad568d45bdf533e2acbb3fc58b662384c55635670316aa error="open /run/vc/sbs/b9685b5836f219a819ad568d45bdf533e2acbb3fc58b662384c55635670316aa/devices.json: no such file or directory" name=kata-runtime pid=47457 sandbox=b9685b5836f219a819ad568d45bdf533e2acbb3fc58b662384c55635670316aa sandboxid=b9685b5836f219a819ad568d45bdf533e2acbb3fc58b662384c55635670316aa source=virtcontainers subsystem=sandbox
time="2018-12-05T18:21:00.26960943+08:00" level=error msg="Unable to launch /usr/local/bin/qemu-system-x86_64: exit status 1" arch=amd64 command=create container=b9685b5836f219a819ad568d45bdf533e2acbb3fc58b662384c55635670316aa name=kata-runtime pid=47457 source=virtcontainers subsystem=qmp
time="2018-12-05T18:21:00.269664142+08:00" level=error msg="qemu-system-x86_64: -smp sockets=2,cores=14,thread=2: Invalid parameter 'thread'\n" arch=amd64 command=create container=b9685b5836f219a819ad568d45bdf533e2acbb3fc58b662384c55635670316aa name=kata-runtime pid=47457 source=virtcontainers subsystem=qmp
time="2018-12-05T18:21:00.269708194+08:00" level=error msg="qemu-system-x86_64: -smp sockets=2,cores=14,thread=2: Invalid parameter 'thread'\n" arch=amd64 command=create container=b9685b5836f219a819ad568d45bdf533e2acbb3fc58b662384c55635670316aa name=kata-runtime pid=47457 source=runtime
time="2018-12-05T18:21:00.279189106+08:00" level=error msg="Container ID (b9685b5836f219a819ad568d45bdf533e2acbb3fc58b662384c55635670316aa) does not exist" arch=amd64 command=delete container=b9685b5836f219a819ad568d45bdf533e2acbb3fc58b662384c55635670316aa name=kata-runtime pid=47468 source=runtime
time="2018-12-05T18:21:00.304946151+08:00" level=error msg="Container ID (b9685b5836f219a819ad568d45bdf533e2acbb3fc58b662384c55635670316aa) does not exist" arch=amd64 command=delete container=b9685b5836f219a819ad568d45bdf533e2acbb3fc58b662384c55635670316aa name=kata-runtime pid=47476 source=runtime
time="2018-12-05T18:22:31.994094979+08:00" level=debug msg="Could not retrieve anything from storage" arch=amd64 command=create container=cf1aed4f9b5465bc504615418888e464eca4bddde614bca39fc0c4c610390458 name=kata-runtime pid=48855 source=virtcontainers subsystem=kata_agent
time="2018-12-05T18:22:31.996859659+08:00" level=warning msg="fetch sandbox device failed" arch=amd64 command=create container=cf1aed4f9b5465bc504615418888e464eca4bddde614bca39fc0c4c610390458 error="open /run/vc/sbs/cf1aed4f9b5465bc504615418888e464eca4bddde614bca39fc0c4c610390458/devices.json: no such file or directory" name=kata-runtime pid=48855 sandbox=cf1aed4f9b5465bc504615418888e464eca4bddde614bca39fc0c4c610390458 sandboxid=cf1aed4f9b5465bc504615418888e464eca4bddde614bca39fc0c4c610390458 source=virtcontainers subsystem=sandbox
time="2018-12-05T18:27:37.267243402+08:00" level=error msg="Container not ready, running or paused, impossible to signal the container" arch=amd64 command=kill container=cf1aed4f9b5465bc504615418888e464eca4bddde614bca39fc0c4c610390458 name=kata-runtime pid=53176 sandbox=cf1aed4f9b5465bc504615418888e464eca4bddde614bca39fc0c4c610390458 source=runtime
time="2018-12-05T18:27:37.308677523+08:00" level=error msg="Container ID (cf1aed4f9b5465bc504615418888e464eca4bddde614bca39fc0c4c610390458) does not exist" arch=amd64 command=delete container=cf1aed4f9b5465bc504615418888e464eca4bddde614bca39fc0c4c610390458 name=kata-runtime pid=53215 source=runtime
time="2018-12-05T18:34:08.423855564+08:00" level=debug msg="Could not retrieve anything from storage" arch=amd64 command=create container=2420299c94d9a4d3208ca531af9d590da7e9f0fe3784a9bcf70e2d12a0975399 name=kata-runtime pid=618 source=virtcontainers subsystem=kata_agent
time="2018-12-05T18:34:08.426640591+08:00" level=warning msg="fetch sandbox device failed" arch=amd64 command=create container=2420299c94d9a4d3208ca531af9d590da7e9f0fe3784a9bcf70e2d12a0975399 error="open /run/vc/sbs/2420299c94d9a4d3208ca531af9d590da7e9f0fe3784a9bcf70e2d12a0975399/devices.json: no such file or directory" name=kata-runtime pid=618 sandbox=2420299c94d9a4d3208ca531af9d590da7e9f0fe3784a9bcf70e2d12a0975399 sandboxid=2420299c94d9a4d3208ca531af9d590da7e9f0fe3784a9bcf70e2d12a0975399 source=virtcontainers subsystem=sandbox
time="2018-12-05T18:34:08.426808901+08:00" level=debug arch=amd64 command=create container=2420299c94d9a4d3208ca531af9d590da7e9f0fe3784a9bcf70e2d12a0975399 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=618 source=virtcontainers subsystem=qemu
time="2018-12-05T18:34:55.671420688+08:00" level=error msg="Failed to check if grpc server is working: rpc error: code = Unavailable desc = transport is closing" arch=amd64 command=create container=2420299c94d9a4d3208ca531af9d590da7e9f0fe3784a9bcf70e2d12a0975399 name=kata-runtime pid=618 source=runtime
time="2018-12-05T18:34:55.682468269+08:00" level=error msg="Container ID (2420299c94d9a4d3208ca531af9d590da7e9f0fe3784a9bcf70e2d12a0975399) does not exist" arch=amd64 command=delete container=2420299c94d9a4d3208ca531af9d590da7e9f0fe3784a9bcf70e2d12a0975399 name=kata-runtime pid=941 source=runtime
time="2018-12-05T18:34:55.713950931+08:00" level=error msg="Container ID (2420299c94d9a4d3208ca531af9d590da7e9f0fe3784a9bcf70e2d12a0975399) does not exist" arch=amd64 command=delete container=2420299c94d9a4d3208ca531af9d590da7e9f0fe3784a9bcf70e2d12a0975399 name=kata-runtime pid=949 source=runtime

Proxy logs

Recent proxy problems found in system journal:

time="2018-12-05T11:05:49.359980114+08:00" level=fatal msg="failed to handle exit signal" error="close unix @->/run/vc/vm/58fbedd4b9b1bf97db8617bd80c6986841a61778bab74b7a99ff5deb651943cc/kata.sock: use of closed network connection" name=kata-proxy pid=7337 sandbox=58fbedd4b9b1bf97db8617bd80c6986841a61778bab74b7a99ff5deb651943cc source=proxy
time="2018-12-05T11:15:23.895874914+08:00" level=fatal msg="failed to handle exit signal" error="close unix @->/run/vc/vm/480912080f3d3e89d6f0890b9d01f0321b972d652e89c4fb409c63f2c7a1ae9c/kata.sock: use of closed network connection" name=kata-proxy pid=11093 sandbox=480912080f3d3e89d6f0890b9d01f0321b972d652e89c4fb409c63f2c7a1ae9c source=proxy
time="2018-12-05T11:19:46.788208701+08:00" level=fatal msg="failed to handle exit signal" error="close unix @->/run/vc/vm/87d71d86ac8b542ced23c0fde9b9df0e8f08d53035d762a394de09b8233f5ada/kata.sock: use of closed network connection" name=kata-proxy pid=13023 sandbox=87d71d86ac8b542ced23c0fde9b9df0e8f08d53035d762a394de09b8233f5ada source=proxy
time="2018-12-05T11:22:46.545672007+08:00" level=fatal msg="failed to handle exit signal" error="close unix @->/run/vc/vm/f8689b7ab2fcb459511edc4a0046d7325eac02c26c58c6c047c4af0ba47de002/kata.sock: use of closed network connection" name=kata-proxy pid=14522 sandbox=f8689b7ab2fcb459511edc4a0046d7325eac02c26c58c6c047c4af0ba47de002 source=proxy
time="2018-12-05T14:20:48.646115004+08:00" level=fatal msg="failed to handle exit signal" error="close unix @->/run/vc/vm/142963ddae8596bd266706e5722689df1a817cececc71836db4915f645c6e91a/kata.sock: use of closed network connection" name=kata-proxy pid=31341 sandbox=142963ddae8596bd266706e5722689df1a817cececc71836db4915f645c6e91a source=proxy
time="2018-12-05T14:30:19.224241056+08:00" level=fatal msg="failed to handle exit signal" error="close unix @->/run/vc/vm/a19bb83067c8e87f85ab64f2597a199690b1e7a31b3fa0759470603fb46ef3f2/kata.sock: use of closed network connection" name=kata-proxy pid=37032 sandbox=a19bb83067c8e87f85ab64f2597a199690b1e7a31b3fa0759470603fb46ef3f2 source=proxy
time="2018-12-05T14:32:03.496912154+08:00" level=fatal msg="failed to handle exit signal" error="close unix @->/run/vc/vm/f635dd0eeba4f4efe3b4a3938a1285e1d062ceac968813a162b1fc58dc115f24/kata.sock: use of closed network connection" name=kata-proxy pid=38280 sandbox=f635dd0eeba4f4efe3b4a3938a1285e1d062ceac968813a162b1fc58dc115f24 source=proxy
time="2018-12-05T14:42:13.611413294+08:00" level=fatal msg="failed to handle exit signal" error="close unix @->/run/vc/vm/5e77256ec65d7da6cde5d6d5899235043858d32fdaa2a0b545fea8bbe009b272/kata.sock: use of closed network connection" name=kata-proxy pid=39401 sandbox=5e77256ec65d7da6cde5d6d5899235043858d32fdaa2a0b545fea8bbe009b272 source=proxy
time="2018-12-05T14:54:30.233516026+08:00" level=fatal msg="failed to handle exit signal" error="close unix @->/run/vc/vm/79cbf42fe6284b2698c4e21588dd419ed9a18c01cb07e61a2ddcd7f32383bb45/kata.sock: use of closed network connection" name=kata-proxy pid=47910 sandbox=79cbf42fe6284b2698c4e21588dd419ed9a18c01cb07e61a2ddcd7f32383bb45 source=proxy
time="2018-12-05T15:06:04.472016826+08:00" level=fatal msg="failed to handle exit signal" error="close unix @->/run/vc/vm/91ef2f25ad29c59511c05876f6f4a03f7f0c9a9d91ed879c4d7a9c6120022d92/kata.sock: use of closed network connection" name=kata-proxy pid=50351 sandbox=91ef2f25ad29c59511c05876f6f4a03f7f0c9a9d91ed879c4d7a9c6120022d92 source=proxy
time="2018-12-05T15:16:41.008404726+08:00" level=fatal msg="channel error" error="accept unix /run/vc/sbs/71faf757320600cc495bc9bad463785d286855fd3b328c519a0202e6675fa68d/proxy.sock: use of closed network connection" name=kata-proxy pid=550 sandbox=71faf757320600cc495bc9bad463785d286855fd3b328c519a0202e6675fa68d source=proxy
time="2018-12-05T15:42:25.408904577+08:00" level=fatal msg="failed to handle exit signal" error="close unix @->/run/vc/vm/0817ab2d857dd4fecb08f5e38b7180d5b2db60462317139a2109962eef51dc39/kata.sock: use of closed network connection" name=kata-proxy pid=13145 sandbox=0817ab2d857dd4fecb08f5e38b7180d5b2db60462317139a2109962eef51dc39 source=proxy
time="2018-12-05T15:59:40.981403258+08:00" level=fatal msg="failed to handle exit signal" error="close unix @->/run/vc/vm/afc40c5765ecf36397d40350c2e139dff87a743e72f9f394c0497f61cdcf4048/kata.sock: use of closed network connection" name=kata-proxy pid=14922 sandbox=afc40c5765ecf36397d40350c2e139dff87a743e72f9f394c0497f61cdcf4048 source=proxy
time="2018-12-05T16:05:05.111178089+08:00" level=fatal msg="channel error" error="accept unix /run/vc/sbs/da01a3eea34155ff42dd61835691ed1e676400186c920004088d63cb29755f57/proxy.sock: use of closed network connection" name=kata-proxy pid=24018 sandbox=da01a3eea34155ff42dd61835691ed1e676400186c920004088d63cb29755f57 source=proxy
time="2018-12-05T16:16:47.374152621+08:00" level=fatal msg="failed to handle exit signal" error="close unix @->/run/vc/vm/a00cc3b0098efa479dc248540ccffad9e2d7bfe8423218fa7e03a54d18ecc604/kata.sock: use of closed network connection" name=kata-proxy pid=26946 sandbox=a00cc3b0098efa479dc248540ccffad9e2d7bfe8423218fa7e03a54d18ecc604 source=proxy
time="2018-12-05T16:16:47.374273752+08:00" level=warning msg="2018/12/05 16:16:47 [ERR] yamux: Failed to write header: write unix @->/run/vc/vm/a00cc3b0098efa479dc248540ccffad9e2d7bfe8423218fa7e03a54d18ecc604/kata.sock: use of closed network connection\n" component=yamux name=kata-proxy pid=26946 sandbox=a00cc3b0098efa479dc248540ccffad9e2d7bfe8423218fa7e03a54d18ecc604 source=proxy
time="2018-12-05T16:21:39.348157784+08:00" level=fatal msg="channel error" error="accept unix /run/vc/sbs/8966aa7ff7e7edbaf21a30e55a546b5b889b4e2133b1c5d5280b6fe492686002/proxy.sock: use of closed network connection" name=kata-proxy pid=32017 sandbox=8966aa7ff7e7edbaf21a30e55a546b5b889b4e2133b1c5d5280b6fe492686002 source=proxy
time="2018-12-05T16:43:34.150197904+08:00" level=fatal msg="failed to handle exit signal" error="close unix @->/run/vc/vm/9db4c186fbdf2fbb36f3d8241c36ec4ecaa90882e4efb1ee5c3833c6a311e494/kata.sock: use of closed network connection" name=kata-proxy pid=41236 sandbox=9db4c186fbdf2fbb36f3d8241c36ec4ecaa90882e4efb1ee5c3833c6a311e494 source=proxy
time="2018-12-05T17:12:59.305584087+08:00" level=fatal msg="failed to handle exit signal" error="close unix @->/run/vc/vm/e7fb8381d2f86e47d9af166fc513c3f4880c912eff50a523eb1912d9c2deffd2/kata.sock: use of closed network connection" name=kata-proxy pid=45046 sandbox=e7fb8381d2f86e47d9af166fc513c3f4880c912eff50a523eb1912d9c2deffd2 source=proxy
time="2018-12-05T17:17:58.596881303+08:00" level=fatal msg="channel error" error="accept unix /run/vc/sbs/0dea95ca7cf22bcaa5a4b84f1493c6cb799b73ea6007f0425dde081d929f7816/proxy.sock: use of closed network connection" name=kata-proxy pid=12085 sandbox=0dea95ca7cf22bcaa5a4b84f1493c6cb799b73ea6007f0425dde081d929f7816 source=proxy
time="2018-12-05T17:20:24.610680652+08:00" level=fatal msg="channel error" error="accept unix /run/vc/sbs/4eebb7ddd06968f99bd3e969b3ef5317ee50cf1737dbeb415f66c4ccebfcd972/proxy.sock: use of closed network connection" name=kata-proxy pid=13360 sandbox=4eebb7ddd06968f99bd3e969b3ef5317ee50cf1737dbeb415f66c4ccebfcd972 source=proxy
time="2018-12-05T17:28:11.985421143+08:00" level=fatal msg="failed to handle exit signal" error="close unix @->/run/vc/vm/a646047a129d9b48ff1bc2fa78076351a4622aef70384d2d0f2db6404d76e9c9/kata.sock: use of closed network connection" name=kata-proxy pid=14626 sandbox=a646047a129d9b48ff1bc2fa78076351a4622aef70384d2d0f2db6404d76e9c9 source=proxy
time="2018-12-05T17:32:04.238493569+08:00" level=fatal msg="channel error" error="accept unix /run/vc/sbs/f2472dd91ee92205261433f63e4c50096e6e0372dfa32566f96f19c8542cc923/proxy.sock: use of closed network connection" name=kata-proxy pid=18535 sandbox=f2472dd91ee92205261433f63e4c50096e6e0372dfa32566f96f19c8542cc923 source=proxy
time="2018-12-05T18:06:14.890348011+08:00" level=fatal msg="failed to handle exit signal" error="close unix @->/run/vc/vm/d44de99f23ddc17448079edaf6bdbf666a8a2017684c94ce28a5f2dfd8050b68/kata.sock: use of closed network connection" name=kata-proxy pid=33185 sandbox=d44de99f23ddc17448079edaf6bdbf666a8a2017684c94ce28a5f2dfd8050b68 source=proxy
time="2018-12-05T18:08:03.79682059+08:00" level=fatal msg="channel error" error="accept unix /run/vc/sbs/4cee43ca9d53ad0c634f02295457dc306fcc10739631309ad64e558cad70afb9/proxy.sock: use of closed network connection" name=kata-proxy pid=40832 sandbox=4cee43ca9d53ad0c634f02295457dc306fcc10739631309ad64e558cad70afb9 source=proxy
time="2018-12-05T18:27:37.287436567+08:00" level=fatal msg="failed to handle exit signal" error="close unix @->/run/vc/vm/cf1aed4f9b5465bc504615418888e464eca4bddde614bca39fc0c4c610390458/kata.sock: use of closed network connection" name=kata-proxy pid=49024 sandbox=cf1aed4f9b5465bc504615418888e464eca4bddde614bca39fc0c4c610390458 source=proxy
time="2018-12-05T18:34:54.175945498+08:00" level=info msg="[   14.349995] EXT4-fs (pmem0p1): DAX enabled. Warning: EXPERIMENTAL, use at your own risk\n" name=kata-proxy pid=832 sandbox=2420299c94d9a4d3208ca531af9d590da7e9f0fe3784a9bcf70e2d12a0975399 source=agent
time="2018-12-05T18:34:54.176625805+08:00" level=info msg="[   14.350646] EXT4-fs (pmem0p1): mounted filesystem with ordered data mode. Opts: dax,data=ordered,errors=remount-ro\n" name=kata-proxy pid=832 sandbox=2420299c94d9a4d3208ca531af9d590da7e9f0fe3784a9bcf70e2d12a0975399 source=agent
time="2018-12-05T18:34:54.235082022+08:00" level=info msg="         Starting Mark the need to relabel after reboot...\n" name=kata-proxy pid=832 sandbox=2420299c94d9a4d3208ca531af9d590da7e9f0fe3784a9bcf70e2d12a0975399 source=agent
time="2018-12-05T18:34:54.236424354+08:00" level=info msg="[\x1b[32m  OK  \x1b[0m] Started Mark the need to relabel after reboot.\n" name=kata-proxy pid=832 sandbox=2420299c94d9a4d3208ca531af9d590da7e9f0fe3784a9bcf70e2d12a0975399 source=agent
time="2018-12-05T18:34:55.668792958+08:00" level=debug msg="Copy stream error" error="stream closed" name=kata-proxy pid=832 sandbox=2420299c94d9a4d3208ca531af9d590da7e9f0fe3784a9bcf70e2d12a0975399 source=proxy

Shim logs

No recent shim problems found in system journal.

Throttler logs

No recent throttler problems found in system journal.

Container manager details

Have docker

Docker

Output of "docker version":

Client:
 Version:      17.09.0-ce
 API version:  1.32
 Go version:   go1.8.3
 Git commit:   afdb6d4
 Built:        Tue Sep 26 22:41:23 2017
 OS/Arch:      linux/amd64

Server:
 Version:      17.09.0-ce
 API version:  1.32 (minimum version 1.12)
 Go version:   go1.8.3
 Git commit:   afdb6d4
 Built:        Tue Sep 26 22:42:49 2017
 OS/Arch:      linux/amd64
 Experimental: false

Output of "docker info":

Containers: 101
 Running: 0
 Paused: 0
 Stopped: 101
Images: 225
Server Version: 17.09.0-ce
Storage Driver: overlay
 Backing Filesystem: xfs
 Supports d_type: true
Logging Driver: journald
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: runv docker-runc kata-runtime nvidia runc runsc
Default Runtime: runc
Init Binary: docker-init
containerd version: 06b9cb35161009dcb7123345749fef02f7cea8e0
runc version: 3f2f8b84a77f73d38244dd690525642a72156c64
init version: 949e6fa
Security Options:
 seccomp
  Profile: default
Kernel Version: 4.14.68-1-linux_runv_nosign_test1-0005
Operating System: linux 2.2 (Final)
OSType: linux
Architecture: x86_64
CPUs: 56
Total Memory: 251.6GiB
Name: ****
ID: 44PA:H43M:LKHI:ABYI:35J2:PZAZ:APA2:L55U:TW7Q:NITF:ZHJN:7E5Z
Docker Root Dir: /data1/docker
Debug Mode (client): false
Debug Mode (server): true
 File Descriptors: 14
 Goroutines: 26
 System Time: 2018-12-05T18:35:35.738180846+08:00
 EventsListeners: 0
Registry: https://index.docker.io/v1/
Labels:
 ip=****
Experimental: false
Insecure Registries:
 10.0.0.0/8
 ****/10
 127.0.0.0/8
Registry Mirrors:
 http://****:5000/
Live Restore Enabled: false

Output of "systemctl show docker":

Type=notify
Restart=on-failure
NotifyAccess=main
RestartUSec=100ms
TimeoutStartUSec=0
TimeoutStopUSec=5s
WatchdogUSec=0
WatchdogTimestamp=Wed 2018-12-05 11:00:57 CST
WatchdogTimestampMonotonic=37574519
StartLimitInterval=60000000
StartLimitBurst=3
StartLimitAction=none
FailureAction=none
PermissionsStartOnly=no
RootDirectoryStartOnly=no
RemainAfterExit=no
GuessMainPID=yes
MainPID=4327
ControlPID=0
FileDescriptorStoreMax=0
StatusErrno=0
Result=success
ExecMainStartTimestamp=Wed 2018-12-05 11:00:54 CST
ExecMainStartTimestampMonotonic=35454237
ExecMainExitTimestampMonotonic=0
ExecMainPID=4327
ExecMainCode=0
ExecMainStatus=0
ExecStart={ path=/usr/bin/dockerd ; argv[]=/usr/bin/dockerd ; ignore_errors=no ; start_time=[Wed 2018-12-05 11:00:54 CST] ; stop_time=[n/a] ; pid=4327 ; 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=128191614976
TasksCurrent=254
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
LimitFSIZE=18446744073709551615
LimitDATA=18446744073709551615
LimitSTACK=18446744073709551615
LimitCORE=18446744073709551615
LimitRSS=18446744073709551615
LimitNOFILE=18446744073709551615
LimitAS=18446744073709551615
LimitNPROC=18446744073709551615
LimitMEMLOCK=65536
LimitLOCKS=18446744073709551615
LimitSIGPENDING=1030215
LimitMSGQUEUE=819200
LimitNICE=0
LimitRTPRIO=0
LimitRTTIME=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
SecureBits=0
CapabilityBoundingSet=18446744073709551615
AmbientCapabilities=0
MountFlags=0
PrivateTmp=no
PrivateNetwork=no
PrivateDevices=no
ProtectHome=no
ProtectSystem=no
SameProcessGroup=no
IgnoreSIGPIPE=yes
NoNewPrivileges=no
SystemCallErrorNumber=0
RuntimeDirectoryMode=0755
KillMode=process
KillSignal=15
SendSIGKILL=yes
SendSIGHUP=no
Id=docker.service
Names=docker.service
Requires=basic.target
Wants=network-online.target system.slice
RequiredBy=kubelet.service
WantedBy=multi-user.target
Conflicts=shutdown.target
Before=multi-user.target kubelet.service shutdown.target
After=firewalld.service basic.target network-online.target systemd-journald.socket system.slice
Documentation=https://docs.docker.com
Description=Docker Application Container Engine
LoadState=loaded
ActiveState=active
SubState=running
FragmentPath=/usr/lib/systemd/system/docker.service
UnitFileState=enabled
UnitFilePreset=disabled
InactiveExitTimestamp=Wed 2018-12-05 11:00:54 CST
InactiveExitTimestampMonotonic=35454264
ActiveEnterTimestamp=Wed 2018-12-05 11:00:57 CST
ActiveEnterTimestampMonotonic=37574556
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
IgnoreOnSnapshot=no
NeedDaemonReload=no
JobTimeoutUSec=0
JobTimeoutAction=none
ConditionResult=yes
AssertResult=yes
ConditionTimestamp=Wed 2018-12-05 11:00:54 CST
ConditionTimestampMonotonic=35453466
AssertTimestamp=Wed 2018-12-05 11:00:54 CST
AssertTimestampMonotonic=35453467
Transient=no

Have kubectl

Kubernetes

Output of "kubectl version":

Client Version: version.Info{Major:"1", Minor:"9", GitVersion:"v1.9.2", GitCommit:"5fa2db2bd46ac79e5e00a4e6ed24191080aa463b", GitTreeState:"clean", BuildDate:"2018-01-18T10:09:24Z", GoVersion:"go1.9.2", Compiler:"gc", Platform:"linux/amd64"}
The connection to the server localhost:8080 was refused - did you specify the right host or port?

Output of "kubectl config view":

apiVersion: v1
clusters: []
contexts: []
current-context: ""
kind: Config
preferences: {}
users: []

Output of "systemctl show kubelet":

Type=simple
Restart=on-failure
NotifyAccess=none
RestartUSec=5s
TimeoutStartUSec=1min 30s
TimeoutStopUSec=5s
WatchdogUSec=0
WatchdogTimestampMonotonic=0
StartLimitInterval=10000000
StartLimitBurst=5
StartLimitAction=none
FailureAction=none
PermissionsStartOnly=no
RootDirectoryStartOnly=no
RemainAfterExit=no
GuessMainPID=yes
MainPID=0
ControlPID=0
FileDescriptorStoreMax=0
StatusErrno=0
Result=exit-code
ExecMainStartTimestamp=Wed 2018-12-05 18:35:32 CST
ExecMainStartTimestampMonotonic=27313291715
ExecMainExitTimestamp=Wed 2018-12-05 18:35:32 CST
ExecMainExitTimestampMonotonic=27313293641
ExecMainPID=1268
ExecMainCode=1
ExecMainStatus=203
ExecStart={ path=/usr/local/bin/kubelet ; argv[]=/usr/local/bin/kubelet --address=**** --hostname-override=**** --pod-infra-container-image=****:5000/library/pause-amd64:3.0 --bootstrap-kubeconfig=/etc/kubernetes/bootstrap.kubeconfig --kubeconfig=/etc/kubernetes/kubelet.kubeconfig --cert-dir=/etc/kubernetes/ssl --cluster-dns=192.168.0.2 --cluster-domain=cluster.local. --hairpin-mode promiscuous-bridge --allow-privileged=true --serialize-image-pulls=false --logtostderr=true --v=2 --cgroup-driver=cgroupfs --fail-swap-on=false --feature-gates=Accelerators=true,DevicePlugins=true,CPUManager=true --minimum-image-ttl-duration=43800h --logtostderr=false --log-dir=/data/log/k8s --image-gc-low-threshold=100 --network-plugin=cni --cni-conf-dir=/etc/cni/net.d --cni-bin-dir=/opt/cni/bin --cpu-manager-policy=nvidia --kube-reserved=cpu=2 --image-gc-high-threshold=100 ; ignore_errors=no ; start_time=[Wed 2018-12-05 18:35:32 CST] ; stop_time=[Wed 2018-12-05 18:35:32 CST] ; pid=1268 ; code=exited ; status=203 }
Slice=system.slice
MemoryCurrent=18446744073709551615
TasksCurrent=18446744073709551615
Delegate=no
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
LimitFSIZE=18446744073709551615
LimitDATA=18446744073709551615
LimitSTACK=18446744073709551615
LimitCORE=18446744073709551615
LimitRSS=18446744073709551615
LimitNOFILE=4096
LimitAS=18446744073709551615
LimitNPROC=1030215
LimitMEMLOCK=65536
LimitLOCKS=18446744073709551615
LimitSIGPENDING=1030215
LimitMSGQUEUE=819200
LimitNICE=0
LimitRTPRIO=0
LimitRTTIME=18446744073709551615
WorkingDirectory=/var/lib/kubelet
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
SecureBits=0
CapabilityBoundingSet=18446744073709551615
AmbientCapabilities=0
MountFlags=0
PrivateTmp=no
PrivateNetwork=no
PrivateDevices=no
ProtectHome=no
ProtectSystem=no
SameProcessGroup=no
IgnoreSIGPIPE=yes
NoNewPrivileges=no
SystemCallErrorNumber=0
RuntimeDirectoryMode=0755
KillMode=control-group
KillSignal=15
SendSIGKILL=yes
SendSIGHUP=no
Id=kubelet.service
Names=kubelet.service
Requires=docker.service basic.target -.mount
Wants=system.slice
Conflicts=shutdown.target
Before=shutdown.target
After=systemd-journald.socket basic.target docker.service -.mount system.slice
RequiresMountsFor=/var/lib/kubelet
Documentation=https://kubernetes.io/docs/home/
Description=kubernetes Kubelet
LoadState=loaded
ActiveState=activating
SubState=auto-restart
FragmentPath=/etc/systemd/system/kubelet.service
UnitFileState=disabled
UnitFilePreset=disabled
InactiveExitTimestamp=Wed 2018-12-05 18:35:32 CST
InactiveExitTimestampMonotonic=27313294295
ActiveEnterTimestamp=Wed 2018-12-05 18:35:32 CST
ActiveEnterTimestampMonotonic=27313291761
ActiveExitTimestamp=Wed 2018-12-05 18:35:32 CST
ActiveExitTimestampMonotonic=27313293785
InactiveEnterTimestamp=Wed 2018-12-05 18:35:32 CST
InactiveEnterTimestampMonotonic=27313293785
CanStart=yes
CanStop=yes
CanReload=no
CanIsolate=no
StopWhenUnneeded=no
RefuseManualStart=no
RefuseManualStop=no
AllowIsolate=no
DefaultDependencies=yes
OnFailureJobMode=replace
IgnoreOnIsolate=no
IgnoreOnSnapshot=no
NeedDaemonReload=no
JobTimeoutUSec=0
JobTimeoutAction=none
ConditionResult=yes
AssertResult=yes
ConditionTimestamp=Wed 2018-12-05 18:35:32 CST
ConditionTimestampMonotonic=27313290708
AssertTimestamp=Wed 2018-12-05 18:35:32 CST
AssertTimestampMonotonic=27313290708
Transient=no

No crio

Packages

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

kata-shim-bin-1.3.1+git.58f757d-3.1.x86_64
kata-linux-container-debug-4.14.67.16-4.1.x86_64
qemu-vanilla-data-2.11.2+git.0982a56a55-5.1.x86_64
kata-proxy-bin-1.3.1+git.d364b2e-3.1.x86_64
qemu-lite-data-2.11.0+git.f886228056-5.1.x86_64
qemu-lite-bin-2.11.0+git.f886228056-5.1.x86_64
kata-ksm-throttler-1.3.1.git+6e903fb-3.1.x86_64
kata-containers-image-1.3.1-3.1.x86_64
qemu-3.0-1.tl2.x86_64
qemu-vanilla-2.11.2+git.0982a56a55-5.1.x86_64
kata-shim-1.3.1+git.58f757d-3.1.x86_64
kata-linux-container-4.14.67.16-4.1.x86_64
qemu-vanilla-bin-2.11.2+git.0982a56a55-5.1.x86_64
kata-proxy-1.3.1+git.d364b2e-3.1.x86_64
qemu-lite-2.11.0+git.f886228056-5.1.x86_64
kata-runtime-1.3.1+git.258eae0-3.1.x86_64
devimc commented 6 years ago

@telala could you please try changing default_vcpus to 1 ?

telala commented 6 years ago

@grahamwhaley is there a way to enlarge the grpc/agent time before timeout.

jodh-intel commented 6 years ago

@telala - not currently, unless you want to change the timeout manually and then rebuild the runtime.

But as @grahamwhaley was saying, if your system is taking > 30 seconds to boot a container with your custom kernel, there is something very wrong.

Speaking of which, it appears you are running a custom host kernel too. Could you maybe try with your custom guest kernel on a stock host kernel and see if that has any effect?