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

Kata-runtime getting stuck, causing CRI-O to hang #396

Closed
jamiehannaford opened this issue Jun 13, 2018 · 18 comments
Closed

Kata-runtime getting stuck, causing CRI-O to hang #396

jamiehannaford opened this issue Jun 13, 2018 · 18 comments

Comments

@jamiehannaford
Copy link

Description of problem

CRI-O fails to boot sometimes when using Kata.

Expected result

After running systemctl restart crio, I expected CRI-O to restart, but it's currently stuck in the initialization procedure and doesn't seem to bind to its sock file. This causes Kubelet to hang too, since it needs crio.sock to launch its server.

Actual result

Looking at the CRI-O logs, it's able to run kata-runtime state <id>:

Jun 13 12:09:01 k8s-jamie-terraform-4c6ef93f-default-pool-mv3n systemd[1]: Stopping OCI-based implementation of Kubernetes Container Runtime Interface...
Jun 13 12:09:01 k8s-jamie-terraform-4c6ef93f-default-pool-mv3n systemd[1]: Stopped OCI-based implementation of Kubernetes Container Runtime Interface.
Jun 13 12:09:01 k8s-jamie-terraform-4c6ef93f-default-pool-mv3n systemd[1]: Started OCI-based implementation of Kubernetes Container Runtime Interface.
Jun 13 12:09:01 k8s-jamie-terraform-4c6ef93f-default-pool-mv3n crio[23222]: time="2018-06-13 time="2018-06-13 12:09:01.559676555Z" level=debug msg="[graphdriver] trying provided driver "overlay""
time="2018-06-13 12:09:01.559820868Z" level=debug msg="overlay: override_kernelcheck=true"
time="2018-06-13 12:09:01.598789333Z" level=debug msg="overlay test mount with multiple lowers succeeded"
time="2018-06-13 12:09:01.645248033Z" level=debug msg="backingFs=extfs, projectQuotaSupported=false, useNativeDiff=true"
time="2018-06-13 12:09:01.647089066Z" level=warning msg="hooks path: "/usr/share/containers/oci/hooks.d" does not exist"
time="2018-06-13 12:09:01.647129086Z" level=warning msg="hooks path: "/etc/containers/oci/hooks.d" does not exist"
time="2018-06-13 12:09:01.647140964Z" level=debug msg="hooks map[]"
time="2018-06-13 12:09:01.647508237Z" level=info msg="CNI network k8s-pod-network (type=calico) is used from /etc/cni/net.d/10-calico.conf"
time="2018-06-13 12:09:01.647761471Z" level=info msg="CNI network k8s-pod-network (type=calico) is used from /etc/cni/net.d/10-calico.conf"
time="2018-06-13 12:09:01.656032315Z" level=debug msg="seccomp status: true"
time="2018-06-13 12:09:01.656947908Z" level=debug msg="Golang's threads limit set to 108090"
time="2018-06-13T12:09:01.677849423Z" level=debug msg="loaded configuration" command=state format=TOML name=kata-runtime pid=23282 source=runtime
time="2018-06-13T12:09:01.677996154Z" level=info arguments="\"state bbb17ab9dea375b90a6a566aa7a33c6fc1a07c497f5f7f80e970c0eb54271b83\"" command=state commit= name=kata-runtime pid=23282 source=runtime version=1.0.0
time="2018-06-13T12:09:01.6792827Z" level=warning msg="shortening QMP socket name" arch=amd64 name=kata-runtime new-name=mon-49a922e1-1051-46a5-a887-a4 original-name=mon-49a922e1-1051-46a5-a887-a454ad285a73 pid=23282 source=virtcontainers subsystem=qemu
time="2018-06-13T12:09:01.67933361Z" level=warning msg="shortening QMP socket name" arch=amd64 name=kata-runtime new-name=ctl-49a922e1-1051-46a5-a887-a4 original-name=ctl-49a922e1-1051-46a5-a887-a454ad285a73 pid=23282 source=virtcontainers subsystem=qemu
time="2018-06-13T12:09:01.680125824Z" level=info msg="Virtual endpoint unmarshalled [{{a8dfda68-2438-4c17-bea5-9bfe8c203b56 br0 {eth0 02:00:ca:fe:00:00 [192.168.2.120/32 eth0]} {tap0 56:a8:f4:b4:a0:8f []} 2 [0xc4201ea150 0xc4201ea160 0xc4201ea168 0xc4201ea170 0xc4201ea178 0xc4201ea180 0xc4201ea188 0xc4201ea190] [0xc4201ea198 0xc4201ea1a0 0xc4201ea1a8 0xc4201ea1b0 0xc4201ea1b8 0xc4201ea1c0 0xc4201ea1c8 0xc4201ea1d0]} {{{4 1500 0 eth0 56:a8:f4:b4:a0:8f up|broadcast|multicast 69699 787 0 <nil>  0xc4202840c0 0 0xc4201d3700 ether <nil> up 0 0 0} veth} [192.168.2.120/32 eth0 fe80::54a8:f4ff:feb4:a08f/64] [{Ifindex: 4 Dst: <nil> Src: <nil> Gw: 169.254.1.1 Flags: [] Table: 254} {Ifindex: 4 Dst: 169.254.1.1/32 Src: <nil> Gw: <nil> Flags: [] Table: 254} {Ifindex: 4 Dst: fe80::/64 Src: <nil> Gw: <nil> Flags: [] Table: 254}] {[]  [] []}} false virtual}]" arch=amd64 name=kata-runtime pid=23282 source=virtcontainers
time="2018-06-13T12:09:01.690835052Z" level=debug msg="loaded configuration" command=state format=TOML name=kata-runtime pid=23291 source=runtime
time="2018-06-13T12:09:01.690991288Z" level=info arguments="\"state 7bb1f49c7822695612fd77c0e71053374a0db950700ea7e8db2f6db0f99c92c7\"" command=state commit= name=kata-runtime pid=23291 source=runtime version=1.0.0
time="2018-06-13T12:09:01.69250342Z" level=warning msg="shortening QMP socket name" arch=amd64 name=kata-runtime new-name=mon-8006a0b6-712d-4f85-9509-30 original-name=mon-8006a0b6-712d-4f85-9509-30641b617856 pid=23291 source=virtcontainers subsystem=qemu
time="2018-06-13T12:09:01.692645451Z" level=warning msg="shortening QMP socket name" arch=amd64 name=kata-runtime new-name=ctl-8006a0b6-712d-4f85-9509-30 original-name=ctl-8006a0b6-712d-4f85-9509-30641b617856 pid=23291 source=virtcontainers subsystem=qemu
time="2018-06-13T12:09:01.693450042Z" level=info msg="Virtual endpoint unmarshalled [{{9443e046-c3a8-48bf-8556-4ea29762dc68 br0 {eth0 02:00:ca:fe:00:00 [192.168.2.122/32 eth0]} {tap0 76:4d:7f:50:d9:be []} 2 [0xc42000e1b8 0xc42000e1c8 0xc42000e1d0 0xc42000e1d8 0xc42000e1e0 0xc42000e1e8 0xc42000e1f0 0xc42000e1f8] [0xc42000e200 0xc42000e208 0xc42000e210 0xc42000e218 0xc42000e220 0xc42000e228 0xc42000e230 0xc42000e238]} {{{4 1500 0 eth0 76:4d:7f:50:d9:be up|broadcast|multicast 69699 789 0 <nil>  0xc4201a6180 0 0xc4200a5fa0 ether <nil> up 0 0 0} veth} [192.168.2.122/32 eth0 fe80::744d:7fff:fe50:d9be/64] [{Ifindex: 4 Dst: <nil> Src: <nil> Gw: 169.254.1.1 Flags: [] Table: 254} {Ifindex: 4 Dst: 169.254.1.1/32 Src: <nil> Gw: <nil> Flags: [] Table: 254} {Ifindex: 4 Dst: fe80::/64 Src: <nil> Gw: <nil> Flags: [] Table: 254}] {[]  [] []}} false virtual}]" arch=amd64 name=kata-runtime pid=23291 source=virtcontainers
time="2018-06-13T12:09:01.702430649Z" level=debug msg="loaded configuration" command=state format=TOML name=kata-runtime pid=23299 source=runtime
time="2018-06-13T12:09:01.702589641Z" level=info arguments="\"state bf7ebe755c33277f6c2bfe65a55abe958f22a88cb49d94451bde61512070b65e\"" command=state commit= name=kata-runtime pid=23299 source=runtime version=1.0.0

This also corresponds to kata-runtime logs:

time="2018-06-13T12:09:01.677849423Z" level=debug msg="loaded configuration" command=state format=TOML name=kata-runtime pid=23282 source=runtime
time="2018-06-13T12:09:01.677996154Z" level=info arguments="\"state bbb17ab9dea375b90a6a566aa7a33c6fc1a07c497f5f7f80e970c0eb54271b83\"" command=state commit= name=kata-runtime pid=23282 source=runtime version=1.0.0
time="2018-06-13T12:09:01.6792827Z" level=warning msg="shortening QMP socket name" arch=amd64 name=kata-runtime new-name=mon-49a922e1-1051-46a5-a887-a4 original-name=mon-49a922e1-1051-46a5-a887-a454ad285a73 pid=23282 source=virtcontainers subsystem=qemu
time="2018-06-13T12:09:01.67933361Z" level=warning msg="shortening QMP socket name" arch=amd64 name=kata-runtime new-name=ctl-49a922e1-1051-46a5-a887-a4 original-name=ctl-49a922e1-1051-46a5-a887-a454ad285a73 pid=23282 source=virtcontainers subsystem=qemu
time="2018-06-13T12:09:01.680125824Z" level=info msg="Virtual endpoint unmarshalled [{{a8dfda68-2438-4c17-bea5-9bfe8c203b56 br0 {eth0 02:00:ca:fe:00:00 [192.168.2.120/32 eth0]} {tap0 56:a8:f4:b4:a0:8f []} 2 [0xc4201ea150 0xc4201ea160 0xc4201ea168 0xc4201ea170 0xc4201ea178 0xc4201ea180 0xc4201ea188 0xc4201ea190] [0xc4201ea198 0xc4201ea1a0 0xc4201ea1a8 0xc4201ea1b0 0xc4201ea1b8 0xc4201ea1c0 0xc4201ea1c8 0xc4201ea1d0]} {{{4 1500 0 eth0 56:a8:f4:b4:a0:8f up|broadcast|multicast 69699 787 0 <nil>  0xc4202840c0 0 0xc4201d3700 ether <nil> up 0 0 0} veth} [192.168.2.120/32 eth0 fe80::54a8:f4ff:feb4:a08f/64] [{Ifindex: 4 Dst: <nil> Src: <nil> Gw: 169.254.1.1 Flags: [] Table: 254} {Ifindex: 4 Dst: 169.254.1.1/32 Src: <nil> Gw: <nil> Flags: [] Table: 254} {Ifindex: 4 Dst: fe80::/64 Src: <nil> Gw: <nil> Flags: [] Table: 254}] {[]  [] []}} false virtual}]" arch=amd64 name=kata-runtime pid=23282 source=virtcontainers
time="2018-06-13T12:09:01.690835052Z" level=debug msg="loaded configuration" command=state format=TOML name=kata-runtime pid=23291 source=runtime
time="2018-06-13T12:09:01.690991288Z" level=info arguments="\"state 7bb1f49c7822695612fd77c0e71053374a0db950700ea7e8db2f6db0f99c92c7\"" command=state commit= name=kata-runtime pid=23291 source=runtime version=1.0.0
time="2018-06-13T12:09:01.69250342Z" level=warning msg="shortening QMP socket name" arch=amd64 name=kata-runtime new-name=mon-8006a0b6-712d-4f85-9509-30 original-name=mon-8006a0b6-712d-4f85-9509-30641b617856 pid=23291 source=virtcontainers subsystem=qemu
time="2018-06-13T12:09:01.692645451Z" level=warning msg="shortening QMP socket name" arch=amd64 name=kata-runtime new-name=ctl-8006a0b6-712d-4f85-9509-30 original-name=ctl-8006a0b6-712d-4f85-9509-30641b617856 pid=23291 source=virtcontainers subsystem=qemu
time="2018-06-13T12:09:01.693450042Z" level=info msg="Virtual endpoint unmarshalled [{{9443e046-c3a8-48bf-8556-4ea29762dc68 br0 {eth0 02:00:ca:fe:00:00 [192.168.2.122/32 eth0]} {tap0 76:4d:7f:50:d9:be []} 2 [0xc42000e1b8 0xc42000e1c8 0xc42000e1d0 0xc42000e1d8 0xc42000e1e0 0xc42000e1e8 0xc42000e1f0 0xc42000e1f8] [0xc42000e200 0xc42000e208 0xc42000e210 0xc42000e218 0xc42000e220 0xc42000e228 0xc42000e230 0xc42000e238]} {{{4 1500 0 eth0 76:4d:7f:50:d9:be up|broadcast|multicast 69699 789 0 <nil>  0xc4201a6180 0 0xc4200a5fa0 ether <nil> up 0 0 0} veth} [192.168.2.122/32 eth0 fe80::744d:7fff:fe50:d9be/64] [{Ifindex: 4 Dst: <nil> Src: <nil> Gw: 169.254.1.1 Flags: [] Table: 254} {Ifindex: 4 Dst: 169.254.1.1/32 Src: <nil> Gw: <nil> Flags: [] Table: 254} {Ifindex: 4 Dst: fe80::/64 Src: <nil> Gw: <nil> Flags: [] Table: 254}] {[]  [] []}} false virtual}]" arch=amd64 name=kata-runtime pid=23291 source=virtcontainers
time="2018-06-13T12:09:01.702430649Z" level=debug msg="loaded configuration" command=state format=TOML name=kata-runtime pid=23299 source=runtime
time="2018-06-13T12:09:01.702589641Z" level=info arguments="\"state bf7ebe755c33277f6c2bfe65a55abe958f22a88cb49d94451bde61512070b65e\"" command=state commit= name=kata-runtime pid=23299 source=runtime version=1.0.0

However it doesn't get much further than that. I can't seem to list any containers, kata-runtime list command just hangs. I can't run any crictl command (they all just hang).


kata-collect-data.sh output here: https://gist.github.com/jamiehannaford/43a323ab0866d9db393c85536c41a366

@jamiehannaford
Copy link
Author

Interestingly, looking at the logs when the list command is sent, the runtime seems to be handling it:

time="2018-06-13T12:32:41.644537664Z" level=info msg="loaded configuration" command=list file=/usr/share/defaults/kata-containers/configuration.toml format=TOML name=kata-runtime pid=24765 source=runtime
time="2018-06-13T12:32:41.644752505Z" level=info arguments="\"list\"" command=list commit=ca9f7abba96e5c4db734673b9e7d870076d715e2 name=kata-runtime pid=24765 source=runtime version=1.0.0
time="2018-06-13T12:32:41.646454965Z" level=warning msg="shortening QMP socket name" arch=amd64 name=kata-runtime new-name=mon-984cabb8-459e-4747-a112-4d original-name=mon-984cabb8-459e-4747-a112-4d744258a731 pid=24765 source=virtcontainers subsystem=qemu
time="2018-06-13T12:32:41.646507688Z" level=warning msg="shortening QMP socket name" arch=amd64 name=kata-runtime new-name=ctl-984cabb8-459e-4747-a112-4d original-name=ctl-984cabb8-459e-4747-a112-4d744258a731 pid=24765 source=virtcontainers subsystem=qemu
time="2018-06-13T12:32:41.647304579Z" level=info msg="Virtual endpoint unmarshalled [{{773b64af-5634-40bc-8f45-d81818f7ca26 br0 {eth0 02:00:ca:fe:00:00 [192.168.2.99/32 eth0]} {tap0 d6:b4:e7:56:10:1b []} 2 [0xc4201aa0c8 0xc4201aa0d0 0xc4201aa0d8 0xc4201aa0e0 0xc4201aa0e8 0xc4201aa0f0 0xc4201aa0f8 0xc4201aa100] [0xc4201aa108 0xc4201aa110 0xc4201aa118 0xc4201aa120 0xc4201aa128 0xc4201aa130 0xc4201aa138 0xc4201aa140]} {{{4 1500 0 eth0 d6:b4:e7:56:10:1b up|broadcast|multicast 69699 763 0 <nil>  0xc42018c480 0 0xc42024c1a0 ether <nil> up 0 0 0} veth} [192.168.2.99/32 eth0 fe80::d4b4:e7ff:fe56:101b/64] [{Ifindex: 4 Dst: <nil> Src: <nil> Gw: 169.254.1.1 Flags: [] Table: 254} {Ifindex: 4 Dst: 169.254.1.1/32 Src: <nil> Gw: <nil> Flags: [] Table: 254} {Ifindex: 4 Dst: fe80::/64 Src: <nil> Gw: <nil> Flags: [] Table: 254}] {[]  [] []}} false virtual}]" arch=amd64 name=kata-runtime pid=24765 source=virtcontainers

I'm not sure why the CLI is hanging...

@jodh-intel
Copy link
Contributor

Hi @jamiehannaford - these logs don't appear to be from the from same build - note the commit= entry which should show commit=$commit. Are you building as described in https://github.com/kata-containers/documentation/blob/master/Developer-Guide.md#build-and-install-the-kata-containers-runtime?

@jodh-intel
Copy link
Contributor

Again, it would be helpful if you could re-run with full debug enabled as you're only seeing some of the messages:

@jamiehannaford
Copy link
Author

@jodh-intel I originally installed using apt-get install (as documented here). The binary path which is set in /etc/crio/crio.conf is /usr/bin/kata-runtime.

I only cloned this repo and ran make && sudo -E PATH=$PATH make install so I could build kata-collect-data.sh, so that probably explains the different commits.

Both /usr/bin/kata-runtime (apt-get) and /usr/local/bin/kata-runtime (make build) both hang when I run list command. Do you think they're interfering with eachother? If so, what might be causing that?

@jamiehannaford
Copy link
Author

I think I have turned on full debug:

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"
initrd = "/usr/share/kata-containers/kata-containers-initrd.img"
#image = "/usr/share/kata-containers/kata-containers.img"
machine_type = "pc"

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

Is that incorrect?

@jodh-intel
Copy link
Contributor

Yes - there should be four enable_debug=true entries.

@jamiehannaford
Copy link
Author

@jodh-intel Looking at the TOML file I just pasted, there are 4: [hypervisor.qemu], [proxy.kata], [shim.kata], [runtime]. Which one am I missing?

Also, I think kata-runtime is hanging when retrieving state for a particular container:

root@k8s-jamie-terraform-4c6ef93f-default-pool-mv3n:~/runtime# kata-runtime state bf7ebe755c33277f6c2bfe65a55abe958f22a88cb49d94451bde61512070b65e
^C

root@k8s-jamie-terraform-4c6ef93f-default-pool-mv3n:~/runtime# journalctl -e -o cat -t kata-runtime
time="2018-06-13T13:17:39.006518861Z" level=warning msg="shortening QMP socket name" arch=amd64 name=kata-runtime new-name=mon-8006a0b6-712d-4f85-9509-30 original-name=mon-8006a0b6-712d-4f85-9509-30641b617856 pid=27667 source=virtcontainers subsystem=qemu
time="2018-06-13T13:17:39.006581101Z" level=warning msg="shortening QMP socket name" arch=amd64 name=kata-runtime new-name=ctl-8006a0b6-712d-4f85-9509-30 original-name=ctl-8006a0b6-712d-4f85-9509-30641b617856 pid=27667 source=virtcontainers subsystem=qemu
time="2018-06-13T13:17:39.007550754Z" level=info msg="Virtual endpoint unmarshalled [{{9443e046-c3a8-48bf-8556-4ea29762dc68 br0 {eth0 02:00:ca:fe:00:00 [192.168.2.122/32 eth0]} {tap0 76:4d:7f:50:d9:be []} 2 [0xc42000e168 0xc42000e170 0xc42000e178 0xc42000e180 0xc42000e188 0xc420
time="2018-06-13T13:17:51.067343795Z" level=info msg="loaded configuration" command=state file=/usr/share/defaults/kata-containers/configuration.toml format=TOML name=kata-runtime pid=27680 source=runtime
time="2018-06-13T13:17:51.067502303Z" level=info arguments="\"state bf7ebe755c33277f6c2bfe65a55abe958f22a88cb49d94451bde61512070b65e\"" command=state commit=ca9f7abba96e5c4db734673b9e7d870076d715e2 name=kata-runtime pid=27680 source=runtime version=1.0.0

Any other container ID works. Some questions:

  1. What might cause the CLI to hang? Maybe the proxy or shim misbehaving?
  2. If a container component is hanging, is there any way for it to fail quickly when booting up CRI-O etc?

@jamiehannaford
Copy link
Author

It seems the qemu-lite process for that container isn't running. Here's what a healthy container looks like:

root@k8s-jamie-terraform-4c6ef93f-default-pool-mv3n:~/runtime# ps aux | grep bbb17ab9dea375b90a6a566aa7a33c6fc1a07c497f5f7f80e970c0eb54271b83
root      4110  0.0  0.0  85952  1908 ?        Ssl  Jun12   0:00 /usr/local/libexec/crio/conmon -c bbb17ab9dea375b90a6a566aa7a33c6fc1a07c497f5f7f80e970c0eb54271b83 -u bbb17ab9dea375b90a6a566aa7a33c6fc1a07c497f5f7f80e970c0eb54271b83 -r /usr/bin/kata-runtime -b /var/run/containers/storage/overlay-containers/bbb17ab9dea375b90a6a566aa7a33c6fc1a07c497f5f7f80e970c0eb54271b83/userdata -p /var/run/containers/storage/overlay-containers/bbb17ab9dea375b90a6a566aa7a33c6fc1a07c497f5f7f80e970c0eb54271b83/userdata/pidfile -l /var/log/pods/818c5608-6e61-11e8-97ac-42010a8e000a/bbb17ab9dea375b90a6a566aa7a33c6fc1a07c497f5f7f80e970c0eb54271b83.log --exit-dir /var/run/crio/exits --socket-dir-path /var/run/crio
root      4138  0.0  0.9 2751976 145292 ?      Sl   Jun12   1:10 /usr/bin/qemu-lite-system-x86_64 -name sandbox-bbb17ab9dea375b90a6a566aa7a33c6fc1a07c497f5f7f80e970c0eb54271b83 -uuid 49a922e1-1051-46a5-a887-a454ad285a73 -machine pc,accel=kvm,kernel_irqchip,nvdimm -cpu host,pmu=off -qmp unix:/run/vc/sbs/bbb17ab9dea375b90a6a566aa7a33c6fc1a07c497f5f7f80e970c0eb54271b83/mon-49a922e1-1051-46a5-a887-a4,server,nowait -qmp unix:/run/vc/sbs/bbb17ab9dea375b90a6a566aa7a33c6fc1a07c497f5f7f80e970c0eb54271b83/ctl-49a922e1-1051-46a5-a887-a4,server,nowait -m 2048M,slots=2,maxmem=16056M -device pci-bridge,bus=pci.0,id=pci-bridge-0,chassis_nr=1,shpc=on,addr=2 -device virtio-serial-pci,disable-modern=true,id=serial0 -device virtconsole,chardev=charconsole0,id=console0 -chardev socket,id=charconsole0,path=/run/vc/sbs/bbb17ab9dea375b90a6a566aa7a33c6fc1a07c497f5f7f80e970c0eb54271b83/console.sock,server,nowait -device virtio-scsi-pci,id=scsi0,disable-modern=true -device virtserialport,chardev=charch0,id=channel0,name=agent.channel.0 -chardev socket,id=charch0,path=/run/vc/sbs/bbb17ab9dea375b90a6a566aa7a33c6fc1a07c497f5f7f80e970c0eb54271b83/kata.sock,server,nowait -device virtio-9p-pci,disable-modern=true,fsdev=extra-9p-kataShared,mount_tag=kataShared -fsdev local,id=extra-9p-kataShared,path=/run/kata-containers/shared/sandboxes/bbb17ab9dea375b90a6a566aa7a33c6fc1a07c497f5f7f80e970c0eb54271b83,security_model=none -netdev tap,id=network-0,vhost=on,vhostfds=3:4:5:6:7:8:9:10,fds=11:12:13:14:15:16:17:18 -device driver=virtio-net-pci,netdev=network-0,mac=56:a8:f4:b4:a0:8f,disable-modern=true,mq=on,vectors=18 -rtc base=utc,driftfix=slew -global kvm-pit.lost_tick_policy=discard -vga none -no-user-config -nodefaults -nographic -daemonize -kernel /usr/share/kata-containers/vmlinuz-4.14.22.1-130.container -initrd /usr/share/kata-containers/kata-containers-initrd_alpine_agent_a099747.initrd -append 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 debug panic=1 initcall_debug nr_cpus=4 ip=::::::bbb17ab9dea375b90a6a566aa7a33c6fc1a07c497f5f7f80e970c0eb54271b83::off:: agent.log=debug -smp 1,cores=1,threads=1,sockets=1,maxcpus=4
root      4152  0.0  0.0 500584  3020 ?        Sl   Jun12   0:01 /usr/libexec/kata-containers/kata-proxy -listen-socket unix:///run/vc/sbs/bbb17ab9dea375b90a6a566aa7a33c6fc1a07c497f5f7f80e970c0eb54271b83/proxy.sock -mux-socket /run/vc/sbs/bbb17ab9dea375b90a6a566aa7a33c6fc1a07c497f5f7f80e970c0eb54271b83/kata.sock -log debug -agent-logs-socket /run/vc/sbs/bbb17ab9dea375b90a6a566aa7a33c6fc1a07c497f5f7f80e970c0eb54271b83/console.sock
root      4174  0.0  0.0 348668  8848 ?        Sl   Jun12   0:00 /usr/libexec/kata-containers/kata-shim -agent unix:///run/vc/sbs/bbb17ab9dea375b90a6a566aa7a33c6fc1a07c497f5f7f80e970c0eb54271b83/proxy.sock -container bbb17ab9dea375b90a6a566aa7a33c6fc1a07c497f5f7f80e970c0eb54271b83 -exec-id bbb17ab9dea375b90a6a566aa7a33c6fc1a07c497f5f7f80e970c0eb54271b83 -log debug
root      4236  0.0  0.0 331412  8904 ?        Sl   Jun12   0:00 /usr/libexec/kata-containers/kata-shim -agent unix:///run/vc/sbs/bbb17ab9dea375b90a6a566aa7a33c6fc1a07c497f5f7f80e970c0eb54271b83/proxy.sock -container f6feffdd51a01a834d1125c4ce577d9ee6acaece1c5186c89d5460180ddcf27b -exec-id f6feffdd51a01a834d1125c4ce577d9ee6acaece1c5186c89d5460180ddcf27b -log debug
root     28295  0.0  0.0  13076  2428 pts/0    S+   13:29   0:00 grep --color=auto bbb17ab9dea375b90a6a566aa7a33c6fc1a07c497f5f7f80e970c0eb54271b83

Here's the faulty container causing things to hang:

root@k8s-jamie-terraform-4c6ef93f-default-pool-mv3n:~/runtime# ps aux | grep bf7ebe755c33277f6c2bfe65a55abe958f22a88cb49d94451bde61512070b65e
root      6583  0.0  0.0  85952  1800 ?        Ssl  Jun12   0:00 /usr/local/libexec/crio/conmon -c bf7ebe755c33277f6c2bfe65a55abe958f22a88cb49d94451bde61512070b65e -u bf7ebe755c33277f6c2bfe65a55abe958f22a88cb49d94451bde61512070b65e -r /usr/bin/kata-runtime -b /var/run/containers/storage/overlay-containers/bf7ebe755c33277f6c2bfe65a55abe958f22a88cb49d94451bde61512070b65e/userdata -p /var/run/containers/storage/overlay-containers/bf7ebe755c33277f6c2bfe65a55abe958f22a88cb49d94451bde61512070b65e/userdata/pidfile -l /var/log/pods/6bb5c248-6e62-11e8-97ac-42010a8e000a/bf7ebe755c33277f6c2bfe65a55abe958f22a88cb49d94451bde61512070b65e.log --exit-dir /var/run/crio/exits --socket-dir-path /var/run/crio
root      6632  0.0  0.0 359616  4512 ?        Sl   Jun12   0:00 /usr/libexec/kata-containers/kata-proxy -listen-socket unix:///run/vc/sbs/bf7ebe755c33277f6c2bfe65a55abe958f22a88cb49d94451bde61512070b65e/proxy.sock -mux-socket /run/vc/sbs/bf7ebe755c33277f6c2bfe65a55abe958f22a88cb49d94451bde61512070b65e/kata.sock -log debug -agent-logs-socket /run/vc/sbs/bf7ebe755c33277f6c2bfe65a55abe958f22a88cb49d94451bde61512070b65e/console.sock
root      6814  0.0  0.0 373256  8756 ?        Sl   Jun12   0:00 /usr/libexec/kata-containers/kata-shim -agent unix:///run/vc/sbs/bf7ebe755c33277f6c2bfe65a55abe958f22a88cb49d94451bde61512070b65e/proxy.sock -container bf7ebe755c33277f6c2bfe65a55abe958f22a88cb49d94451bde61512070b65e -exec-id bf7ebe755c33277f6c2bfe65a55abe958f22a88cb49d94451bde61512070b65e -log debug
root     23299  0.0  0.0 211092 10116 ?        Sl   12:09   0:00 /usr/bin/kata-runtime state bf7ebe755c33277f6c2bfe65a55abe958f22a88cb49d94451bde61512070b65e
root     28346  0.0  0.0  13076  2484 pts/0    S+   13:30   0:00 grep --color=auto bf7ebe755c33277f6c2bfe65a55abe958f22a88cb49d94451bde61512070b65e

Is there anything which reaps the proxy, shim and conmon process? Because without that, I assume CRI-O will just keep on requesting its state and wait forever

@jodh-intel
Copy link
Contributor

Yes, I said there are four debug options and you have listed four ;)

ping @egernst, @sboeuf - we need your k8s/crio expertise over here! ;)

@jamiehannaford
Copy link
Author

Yes, I said there are four debug options and you have listed four ;)

Ah sorry! I asked if it was incorrect and you said Yes 😛

So it seems like this is happening: the qemu-lite process got killed for whatever reason, but all the other kata- processes and conmon are still running. So when CRI-O runs kata-runtime state, it just hangs.

@jamiehannaford
Copy link
Author

Rebooting the instance fixed the issue. But I'd rather not have to do this every time a Kata container gets stuck 😄 So any tips here would be super appreciated

@jodh-intel
Copy link
Contributor

That certainly should not be necessary. I think we were still waiting to see your debug logs though (paste in the output of sudo kata-collect-data.sh after reviewing)?

@jamiehannaford
Copy link
Author

@jodh-intel I'm a bit confused. If you look at the TOML file, it has enable_debug=true in the [runtime] section. However when I run kata-runtime env-check it says Debug = false

@jodh-intel
Copy link
Contributor

The runtime can look for its configuration file in multiple locations - see https://github.com/kata-containers/runtime/#configuration. I suspect you're looking at the "wrong" config file.

Note also that the output of kata-env shows the path to the config file the runtime has selected.

@jamiehannaford
Copy link
Author

The config file which is referenced in kata-env has debug set to true it seems:

root@k8s-jamie-terraform-4c6ef93f-default-pool-mv3n:~# /usr/bin/kata-runtime kata-env
[Meta]
  Version = "1.0.12"

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

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

[Image]
  Path = ""

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

[Initrd]
  Path = "/usr/share/kata-containers/kata-containers-initrd_alpine_agent_a099747.initrd"

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

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

[Agent]
  Type = "kata"

[Host]
  Kernel = "4.13.0-1019-gcp"
  Architecture = "amd64"
  VMContainerCapable = true
  [Host.Distro]
    Name = "Ubuntu"
    Version = "16.04"
  [Host.CPU]
    Vendor = "GenuineIntel"
    Model = "Intel(R) Xeon(R) CPU @ 2.30GHz"
root@k8s-jamie-terraform-4c6ef93f-default-pool-mv3n:~# 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"
initrd = "/usr/share/kata-containers/kata-containers-initrd.img"
#image = "/usr/share/kata-containers/kata-containers.img"
machine_type = "pc"

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

@sboeuf
Copy link

sboeuf commented Jun 13, 2018

Hey @jamiehannaford, we have to figure out some proper rollback for cases like this where things does not end up as expected.
In the meantime, if you don't want to reboot, you can apply this quick sequence of commands to restart your cluster, making sure you're not leaving old stuff behind.
https://gist.github.com/sboeuf/d84acfbaf2bccd528098d73a3b891cd1#file-run-k8s-cri-o-L7-L37

@jamiehannaford
Copy link
Author

@sboeuf Unfortunately restarting the cluster represents way more of a disruption than just rebooting a node. Would something like this work:

if $(ps aux | grep -q /usr/bin/qemu-lite-system-x86_64 -name sandbox-<id> ); then
   // vm is okay
else
   // kill processes
   // delete the following dirs:
   //    /var/lib/containers/storage/overlay/<id>
   //    /run/kata-containers/shared/sandboxes/<id>
   //    /run/containers/storage/overlay-containers/<id>
   //    /var/lib/cni/networks/<id>
   // umount /run/netns/cni-<id>
   // restart crio
fi

Or it safer to just reboot? I could automate detection (is kubelet/CRIO alive, is kata-runtime responsive, are the processes okay) and rebooting into some kind of controller, but I'd prefer to fix this at root cause if possible.

How difficult would it be for kata-runtime to detect this kind of situation? Wondering if I could submit something in a PR.

zklei pushed a commit to zklei/runtime that referenced this issue Jun 13, 2019
Since the Yamux's keepalive has been disabled both
on the server and the client side, and this brings
a weird issue where the communication between the
proxy and the agent hangs. The same issue has been
fixed in kata proxy by:
"kata-containers/proxy#91".

This commit just cherry-pick that patch here to
fix the same issue on kata builtin proxy.

Fixes: kata-containers#396

Signed-off-by: fupan <lifupan@gmail.com>
@chavafg
Copy link
Contributor

chavafg commented Jul 17, 2019

Hi @jamiehannaford, is this still an issue for you? Or can we close it? We have been tested newest versions of cri-o and seems to work fine with kata-runtime.

lifupan pushed a commit to lifupan/kata-runtime that referenced this issue Aug 5, 2020
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants