Cannot start a Clear Container on an Ubuntu VM using VMware Fusion

[pittma]

A lot of what I've experienced thus far aligns with the issue relates to #950.

This is a VM running in VMware Fusion with VT passthrough enabled:

I installed following the Ubuntu installation directions and nothing failed during installation. However, when I run:

$ sudo dockerd --add-runtime cor=/usr/bin/cc-oci-runtime --default-runtime=cor

and

$ sudo docker run -ti fedora bash

I see

ERRO[0008] containerd: start container                   error="containerd: container not started" id=8ffccf577048227ccf608706ab679f59c78bc566fc67ae0507a7125cce0d3768
ERRO[0008] Create container failed with error: containerd: container not started
ERRO[0008] Handler for POST /v1.30/containers/8ffccf577048227ccf608706ab679f59c78bc566fc67ae0507a7125cce0d3768/start returned error: containerd: container not started

and

docker: Error response from daemon: containerd: container not started.

respectively.

Thus far, I've been unable to track down any logs for cc-oci-runtime or the cc-proxy.

---

The hardware precheck succeeds:

dpitt@qemu-ubuntu:~$ ./check.sh container
Checking if host is capable of running Clear Linux* OS for Intel® Architecture in a container

SUCCESS: Intel CPU
SUCCESS: 64-bit CPU (lm)
SUCCESS: Streaming SIMD Extensions v4.1 (sse4_1)
SUCCESS: Virtualisation support (vmx)
SUCCESS: Kernel module kvm
SUCCESS: Kernel module kvm_intel
SUCCESS: Nested KVM support
SUCCESS: Unrestricted guest KVM support
SUCCESS: Kernel module vhost
SUCCESS: Kernel module vhost_net

While following along in #950, I found that the qemu command used to execute the Clear Container. Here's mine, altered slightly to reflect version and name changes:

$ sudo /usr/bin/qemu-lite-system-x86_64 \
    -name dan-test \
    -machine pc-lite,accel=kvm,kernel_irqchip,nvdimm \
    -object memory-backend-file,id=mem0,mem-path=/usr/share/clear-containers/clear-15550-containers.img,size=235929600 \
    -kernel /usr/share/clear-containers/vmlinux-4.9.35-62.container \
    -chardev stdio,id=stdio,mux=on \
    -device virtio-serial-pci \
    -device virtconsole,chardev=stdio \
    -mon chardev=stdio \
    -display none

Like in the aforementioned issue, this command hangs and qemu-lite pegs the CPU at 100%.

Thanks so much!

[jcvenegas]

Hi @danielscottt thanks for report the issue - some questions:

What runtime version are you using?:

cc-oci-runtime version

What docker version are you using ?:

docker info

In order to get the runtime logs please try the following:
Use cc-oci-runtime.sh when you add a runtime to docker:

 sudo dockerd --add-runtime cor=/usr/bin/cc-oci-runtime.sh --default-runtime=cor

And verify that following lines are not commented in /usr/bin/cc-oci-runtime.sh (https://github.com/01org/cc-oci-runtime/wiki/Debugging):

runtime_args="$runtime_args --global-log=\"$global_log\""
runtime_args="$runtime_args --debug"

For the proxy logs please enable debug logs in the proxy service adding -v 3 to the proxy command:

sudo sed -i 's,ExecStart=/usr/libexec/cc-proxy,ExecStart=/usr/libexec/cc-proxy -v 3 ,g' /usr/lib/systemd/system/cc-proxy.service
sudo systemctl daemon-reload
sudo systemctl restart cc-proxy

After that try to run a container:

sudo docker run -ti fedora bash

The runtime logs should be located in:

/run/cc-oci-runtime/cc-oci-runtime.log

To access to the proxy logs you can use journal:

journalctl -u cc-proxy.service

[pittma]

Hi @jcvenegas! Thanks so much for your reply.

I think we're on to something! TL;DR:

In the runtime's log:

2017-08-01T17:03:27.776244Z:1972:cc-oci-runtime:critical:/usr/bin/cc-oci-runtime: create: Unknown option --console-socket

---

Here's the logs and information you requested:

$ cc-oci-runtime version
cc-oci-runtime version: 2.2.3
spec version: 1.0.0-rc1
commit: 7f314dc3764e53f366676894994ed44340f4f836

And docker info:

$ sudo docker info
Containers: 13
 Running: 0
 Paused: 0
 Stopped: 13
Images: 2
Server Version: 17.06.0-ce
Storage Driver: aufs
 Root Dir: /var/lib/docker/aufs
 Backing Filesystem: extfs
 Dirs: 28
 Dirperm1 Supported: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
 Volume: local
 Network: bridge host macvlan null overlay
 Log: awslogs fluentd gcplogs gelf journald json-file logentries splunk syslog
Swarm: inactive
Runtimes: cor runc
Default Runtime: cor
Init Binary: docker-init
containerd version: cfb82a876ecc11b5ca0977d1733adbe58599088a
runc version: 2d41c047c83e09a6d61d464906feb2a2f3c52aa4
init version: 949e6fa
Security Options:
 apparmor
 seccomp
  Profile: default
Kernel Version: 4.4.0-62-generic
Operating System: Ubuntu 16.04.3 LTS
OSType: linux
Architecture: x86_64
CPUs: 2
Total Memory: 3.842GiB
Name: qemu-ubuntu
ID: LHOR:H7PC:4LPM:53LM:CU2A:TFJT:T5IX:UECZ:VN34:5BEC:QPBT:V4SB
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): true
 File Descriptors: 17
 Goroutines: 24
 System Time: 2017-08-01T08:56:44.348308372-07:00
 EventsListeners: 0
Registry: https://index.docker.io/v1/
Experimental: false
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false

WARNING: No swap limit support

Running the container:

$ sudo docker run -ti fedora bash
docker: Error response from daemon: json: cannot unmarshal number into Go value of type runtime.message.

dockerd's logs

ERRO[0141] containerd: start container                   error="json: cannot unmarshal number into Go value of type runtime.message" id=7b7269c406cece41e7cfcaea6bc9261f58d4f9d9048dbb74c2fe5d77a9eb9451
ERRO[0141] Create container failed with error: json: cannot unmarshal number into Go value of type runtime.message
ERRO[0141] Handler for POST /v1.30/containers/7b7269c406cece41e7cfcaea6bc9261f58d4f9d9048dbb74c2fe5d77a9eb9451/start returned error: json: cannot unmarshal number into Go value of type runtime.message
ERRO[0292] containerd: start container                   error="json: cannot unmarshal number into Go value of type runtime.message" id=e7bfc2ea0270a054d1e208216fac4d378b684117158cda10225b7b0fee818744
ERRO[0292] Create container failed with error: json: cannot unmarshal number into Go value of type runtime.message
ERRO[0292] Handler for POST /v1.30/containers/e7bfc2ea0270a054d1e208216fac4d378b684117158cda10225b7b0fee818744/start returned error: json: cannot unmarshal number into Go value of type runtime.message

cc-oci-runtime's logs

2017-08-01T17:03:27.776017Z:1972:cc-oci-runtime:debug:cc-oci-runtime 2.2.3  called as: /usr/bin/cc-oci-runtime create --bundle /var/run/docker/libcontainerd/e7bfc2ea0270a054d1e208216fac4d378b684117158cda10225b7b0fee818744 --console-socket /tmp/pty873238659/pty.sock --pid-file /run/docker/libcontainerd/containerd/e7bfc2ea0270a054d1e208216fac4d378b684117158cda10225b7b0fee818744/init/pid e7bfc2ea0270a054d1e208216fac4d378b684117158cda10225b7b0fee818744
2017-08-01T17:03:27.776244Z:1972:cc-oci-runtime:critical:/usr/bin/cc-oci-runtime: create: Unknown option --console-socket
2017-08-01T17:03:27.779491Z:1978:cc-oci-runtime:debug:cc-oci-runtime 2.2.3  called as: /usr/bin/cc-oci-runtime delete e7bfc2ea0270a054d1e208216fac4d378b684117158cda10225b7b0fee818744

2017-08-01T17:03:27.779541Z:1978:cc-oci-runtime:warning:state file does not exist for container e7bfc2ea0270a054d1e208216fac4d378b684117158cda10225b7b0fee818744

2017-08-01T17:03:27.805777Z:1983:cc-oci-runtime:debug:cc-oci-runtime 2.2.3  called as: /usr/bin/cc-oci-runtime delete e7bfc2ea0270a054d1e208216fac4d378b684117158cda10225b7b0fee818744

2017-08-01T17:03:27.805837Z:1983:cc-oci-runtime:warning:state file does not exist for container e7bfc2ea0270a054d1e208216fac4d378b684117158cda10225b7b0fee818744

cc-proxy's logs

Aug 01 09:00:44 qemu-ubuntu systemd[1]: Stopped Clear Containers Proxy.
Aug 01 09:00:44 qemu-ubuntu systemd[1]: Started Clear Containers Proxy.
Aug 01 09:00:44 qemu-ubuntu cc-proxy[1798]: I0801 09:00:44.555907    1798 proxy.go:381] proxy started

[jcvenegas]

@danielscottt, thanks for the quick response, seems you hit #1021 . Currently cc-oci-runtime is not compatible with docker 17.06, the last compatible version is 17.05. Could you try to use docker 17.05 by now.

[pittma]

Yes! I just downgraded to 17.03, as it was what was available:

$ apt-cache madison docker-ce
 docker-ce | 17.06.0~ce-0~ubuntu | https://download.docker.com/linux/ubuntu xenial/stable amd64 Packages
 docker-ce | 17.03.2~ce-0~ubuntu-xenial | https://download.docker.com/linux/ubuntu xenial/stable amd64 Packages
 docker-ce | 17.03.1~ce-0~ubuntu-xenial | https://download.docker.com/linux/ubuntu xenial/stable amd64 Packages
 docker-ce | 17.03.0~ce-0~ubuntu-xenial | https://download.docker.com/linux/ubuntu xenial/stable amd64 Packages

$ dockerd --version
Docker version 17.03.2-ce, build f5ec1e2

Now I'm seeing this from dockerd:

ERRO[0023] containerd: start container                   error=shim error: open pid: no such file or directory id=76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f
ERRO[0023] Create container failed with error: shim error: open pid: no such file or directory
ERRO[0023] Handler for POST /v1.27/containers/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/start returned error: shim error: open pid: no such file or directory

And the runtime reports this:

2017-08-01T17:00:56.394593Z:1862:cc-oci-runtime:debug:cc-oci-runtime 2.2.3  called as: /usr/bin/cc-oci-runtime create --bundle /var/run/docker/libcontainerd/7b7269c406cece41e7cfcaea6bc9261f58d4f9d9048dbb74c2fe5d77a9eb9451 --console-socket /tmp/pty664753388/pty.sock --pid-file /run/docker/libcontainerd/containerd/7b7269c406cece41e7cfcaea6bc9261f58d4f9d9048dbb74c2fe5d77a9eb9451/init/pid 7b7269c406cece41e7cfcaea6bc9261f58d4f9d9048dbb74c2fe5d77a9eb9451
2017-08-01T17:00:56.394784Z:1862:cc-oci-runtime:critical:/usr/bin/cc-oci-runtime: create: Unknown option --console-socket
2017-08-01T17:00:56.397671Z:1867:cc-oci-runtime:debug:cc-oci-runtime 2.2.3  called as: /usr/bin/cc-oci-runtime delete 7b7269c406cece41e7cfcaea6bc9261f58d4f9d9048dbb74c2fe5d77a9eb9451

2017-08-01T17:00:56.397715Z:1867:cc-oci-runtime:warning:state file does not exist for container 7b7269c406cece41e7cfcaea6bc9261f58d4f9d9048dbb74c2fe5d77a9eb9451

2017-08-01T17:00:56.423123Z:1872:cc-oci-runtime:debug:cc-oci-runtime 2.2.3  called as: /usr/bin/cc-oci-runtime delete 7b7269c406cece41e7cfcaea6bc9261f58d4f9d9048dbb74c2fe5d77a9eb9451

2017-08-01T17:00:56.423181Z:1872:cc-oci-runtime:warning:state file does not exist for container 7b7269c406cece41e7cfcaea6bc9261f58d4f9d9048dbb74c2fe5d77a9eb9451

2017-08-01T17:03:27.776017Z:1972:cc-oci-runtime:debug:cc-oci-runtime 2.2.3  called as: /usr/bin/cc-oci-runtime create --bundle /var/run/docker/libcontainerd/e7bfc2ea0270a054d1e208216fac4d378b684117158cda10225b7b0fee818744 --console-socket /tmp/pty873238659/pty.sock --pid-file /run/docker/libcontainerd/containerd/e7bfc2ea0270a054d1e208216fac4d378b684117158cda10225b7b0fee818744/init/pid e7bfc2ea0270a054d1e208216fac4d378b684117158cda10225b7b0fee818744

2017-08-01T17:03:27.776244Z:1972:cc-oci-runtime:critical:/usr/bin/cc-oci-runtime: create: Unknown option --console-socket
2017-08-01T17:03:27.779491Z:1978:cc-oci-runtime:debug:cc-oci-runtime 2.2.3  called as: /usr/bin/cc-oci-runtime delete e7bfc2ea0270a054d1e208216fac4d378b684117158cda10225b7b0fee818744

2017-08-01T17:03:27.779541Z:1978:cc-oci-runtime:warning:state file does not exist for container e7bfc2ea0270a054d1e208216fac4d378b684117158cda10225b7b0fee818744

2017-08-01T17:03:27.805777Z:1983:cc-oci-runtime:debug:cc-oci-runtime 2.2.3  called as: /usr/bin/cc-oci-runtime delete e7bfc2ea0270a054d1e208216fac4d378b684117158cda10225b7b0fee818744

2017-08-01T17:03:27.805837Z:1983:cc-oci-runtime:warning:state file does not exist for container e7bfc2ea0270a054d1e208216fac4d378b684117158cda10225b7b0fee818744

2017-08-01T17:32:35.668351Z:2609:cc-oci-runtime:debug:cc-oci-runtime 2.2.3  called as: /usr/bin/cc-oci-runtime create --bundle /var/run/docker/libcontainerd/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f --console /dev/pts/3 --pid-file /run/docker/libcontainerd/containerd/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/init/pid 76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f

2017-08-01T17:32:35.668501Z:2609:cc-oci-runtime:debug:path '/var/run/docker/libcontainerd/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f' resolved to '/run/docker/libcontainerd/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f'

2017-08-01T17:32:35.668538Z:2609:cc-oci-runtime:debug:using config_file /run/docker/libcontainerd/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/config.json

2017-08-01T17:32:35.671738Z:2609:cc-oci-runtime:debug:path '/var/lib/docker/aufs/mnt/aaf6f482c6ebd88ef5a1cc827eb2e016346bd0a37909d9574736cf0480381162' resolved to '/var/lib/docker/aufs/mnt/aaf6f482c6ebd88ef5a1cc827eb2e016346bd0a37909d9574736cf0480381162'

2017-08-01T17:32:35.671821Z:2609:cc-oci-runtime:debug:Reading VM configuration from /usr/share/defaults/cc-oci-runtime/vm.json

2017-08-01T17:32:35.673556Z:2609:cc-oci-runtime:debug:path '/usr/bin/qemu-lite-system-x86_64' resolved to '/usr/bin/qemu-lite-system-x86_64'

2017-08-01T17:32:35.673914Z:2609:cc-oci-runtime:debug:path '/usr/share/clear-containers/clear-containers.img' resolved to '/usr/share/clear-containers/clear-16670-containers.img'

2017-08-01T17:32:35.673964Z:2609:cc-oci-runtime:debug:path '/usr/share/clear-containers/vmlinux.container' resolved to '/usr/share/clear-containers/vmlinux-4.9.35-62.container'

2017-08-01T17:32:35.674090Z:2609:cc-oci-runtime:debug:OCI spec versions: config=1.0.0-rc2-dev, runtime=1.0.0-rc1

2017-08-01T17:32:35.674133Z:2609:cc-oci-runtime:debug:creating directory /var/run/cc-oci-runtime/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f

2017-08-01T17:32:35.674189Z:2609:cc-oci-runtime:debug:Created rootfs bind mount object for container 76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f

2017-08-01T17:32:35.674220Z:2609:cc-oci-runtime:debug:Added rootfs bind mount for container 76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f

2017-08-01T17:32:35.674272Z:2609:cc-oci-runtime:debug:mounting /var/lib/docker/aufs/mnt/aaf6f482c6ebd88ef5a1cc827eb2e016346bd0a37909d9574736cf0480381162 of type bind onto /var/run/cc-oci-runtime/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/workload//76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/rootfs with options '' and flags 0x1000

2017-08-01T17:32:35.676190Z:2609:cc-oci-runtime:debug:setting up namespaces

2017-08-01T17:32:35.676409Z:2609:cc-oci-runtime:debug:created mount namespace

2017-08-01T17:32:35.677150Z:2609:cc-oci-runtime:debug:created network namespace

2017-08-01T17:32:35.677190Z:2609:cc-oci-runtime:debug:ignoring uts namespace request

2017-08-01T17:32:35.677217Z:2609:cc-oci-runtime:debug:ignoring pid namespace request

2017-08-01T17:32:35.677242Z:2609:cc-oci-runtime:debug:ignoring ipc namespace request

2017-08-01T17:32:35.677265Z:2609:cc-oci-runtime:debug:finished namespace setup

2017-08-01T17:32:35.677298Z:2609:cc-oci-runtime:debug:Mounting mount /var/run/cc-oci-runtime/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/workload/8a8e13259a7d1e15-resolv.conf for mnt_dir /etc/resolv.conf

2017-08-01T17:32:35.677338Z:2609:cc-oci-runtime:debug:mounting /var/lib/docker/containers/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/resolv.conf of type bind onto /var/run/cc-oci-runtime/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/workload/8a8e13259a7d1e15-resolv.conf with options '' and flags 0x45000

2017-08-01T17:32:35.678362Z:2609:cc-oci-runtime:debug:Mounting mount /var/run/cc-oci-runtime/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/workload/5ec48a4bc5474f3c-hostname for mnt_dir /etc/hostname

2017-08-01T17:32:35.678415Z:2609:cc-oci-runtime:debug:mounting /var/lib/docker/containers/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/hostname of type bind onto /var/run/cc-oci-runtime/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/workload/5ec48a4bc5474f3c-hostname with options '' and flags 0x45000

2017-08-01T17:32:35.679235Z:2609:cc-oci-runtime:debug:Mounting mount /var/run/cc-oci-runtime/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/workload/9c57b68ba72226b4-hosts for mnt_dir /etc/hosts

2017-08-01T17:32:35.679286Z:2609:cc-oci-runtime:debug:mounting /var/lib/docker/containers/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/hosts of type bind onto /var/run/cc-oci-runtime/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/workload/9c57b68ba72226b4-hosts with options '' and flags 0x45000

2017-08-01T17:32:35.680153Z:2609:cc-oci-runtime:debug:connecting to proxy cc-proxy

2017-08-01T17:32:35.683196Z:2609:cc-oci-runtime:debug:connected to proxy socket /var/run/cc-oci-runtime/proxy.sock

2017-08-01T17:32:35.683727Z:2609:cc-oci-runtime:debug:hypervisor child pid is 2616

2017-08-01T17:32:35.683803Z:2616:cc-oci-runtime:debug:disconnecting from proxy

2017-08-01T17:32:35.683961Z:2616:cc-oci-runtime:debug:reading hypervisor command-line length from pipe

2017-08-01T17:32:35.683976Z:2609:cc-oci-runtime:debug:shim process running with pid 2617

2017-08-01T17:32:35.684307Z:2617:cc-oci-runtime:debug:shim child waiting for proxy socket fd on fd 6

2017-08-01T17:32:35.684364Z:2609:cc-oci-runtime:debug:created state file /var/run/cc-oci-runtime/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/state.json

2017-08-01T17:32:35.731778Z:2609:cc-oci-runtime:debug:building hypervisor command-line

2017-08-01T17:32:35.732022Z:2609:cc-oci-runtime:debug:Discovering container interfaces

2017-08-01T17:32:35.732112Z:2609:cc-oci-runtime:debug:Interface := [lo]

2017-08-01T17:32:35.732156Z:2609:cc-oci-runtime:debug:Interface := [eth0]

2017-08-01T17:32:35.732193Z:2609:cc-oci-runtime:debug:Interface := [lo]

2017-08-01T17:32:35.732228Z:2609:cc-oci-runtime:debug:Interface := [eth0]

2017-08-01T17:32:35.732280Z:2609:cc-oci-runtime:debug:IP := [172.17.0.2]

2017-08-01T17:32:35.732325Z:2609:cc-oci-runtime:debug:IP := [255.255.0.0]

2017-08-01T17:32:35.732365Z:2609:cc-oci-runtime:debug:MTU for interface eth0: 1500
2017-08-01T17:32:35.732402Z:2609:cc-oci-runtime:debug:Interface := [lo]

2017-08-01T17:32:35.732438Z:2609:cc-oci-runtime:debug:Interface := [eth0]

2017-08-01T17:32:35.732475Z:2609:cc-oci-runtime:debug:IP := [fe80::42:acff:fe11:2]

2017-08-01T17:32:35.732510Z:2609:cc-oci-runtime:debug:netlink_get_default_gw

2017-08-01T17:32:35.732560Z:2609:cc-oci-runtime:debug:table=254

2017-08-01T17:32:35.732600Z:2609:cc-oci-runtime:debug:IP := [172.17.0.1]

2017-08-01T17:32:35.732634Z:2609:cc-oci-runtime:debug:gateway : 172.17.0.1

2017-08-01T17:32:35.732696Z:2609:cc-oci-runtime:debug:ifname=eth0

2017-08-01T17:32:35.732735Z:2609:cc-oci-runtime:debug:table=254

2017-08-01T17:32:35.732770Z:2609:cc-oci-runtime:debug:IP := [172.17.0.0]

2017-08-01T17:32:35.732803Z:2609:cc-oci-runtime:debug:destination : 172.17.0.0

2017-08-01T17:32:35.732841Z:2609:cc-oci-runtime:debug:ifname=eth0

2017-08-01T17:32:35.732877Z:2609:cc-oci-runtime:debug:table=255

2017-08-01T17:32:35.732910Z:2609:cc-oci-runtime:debug:table=255

2017-08-01T17:32:35.732942Z:2609:cc-oci-runtime:debug:table=255

2017-08-01T17:32:35.732974Z:2609:cc-oci-runtime:debug:table=255

2017-08-01T17:32:35.733006Z:2609:cc-oci-runtime:debug:table=255

2017-08-01T17:32:35.733038Z:2609:cc-oci-runtime:debug:table=255

2017-08-01T17:32:35.733070Z:2609:cc-oci-runtime:debug:table=255

2017-08-01T17:32:35.733105Z:2609:cc-oci-runtime:debug:[1] networks discovered

2017-08-01T17:32:35.733138Z:2609:cc-oci-runtime:debug:Running command : iptables-save

2017-08-01T17:32:35.734698Z:2609:cc-oci-runtime:debug:Running commands for dropping iptables

2017-08-01T17:32:35.734758Z:2609:cc-oci-runtime:debug:arg: '/bin/sh'

2017-08-01T17:32:35.734792Z:2609:cc-oci-runtime:debug:arg: '-c'

2017-08-01T17:32:35.734824Z:2609:cc-oci-runtime:debug:arg: 'iptables -P INPUT ACCEPT && iptables -P FORWARD ACCEPT && iptables -P OUTPUT ACCEPT && iptables -t nat -F && iptables -t mangle -F && iptables -F && iptables -X'

2017-08-01T17:32:35.744044Z:2609:cc-oci-runtime:debug:MTU set for interface ceth0 as 1500
2017-08-01T17:32:35.744142Z:2609:cc-oci-runtime:debug:netlink_link_add_bridge beth0

2017-08-01T17:32:35.744185Z:2609:cc-oci-runtime:debug:Turning off multicast snooping for bridge beth0

2017-08-01T17:32:35.744352Z:2609:cc-oci-runtime:debug:netlink_link_set_addr eth0

2017-08-01T17:32:35.744385Z:2609:cc-oci-runtime:debug:macaddr 02:00:ca:fe:00:00

2017-08-01T17:32:35.744495Z:2609:cc-oci-runtime:debug:netlink_link_set_master 2 3

2017-08-01T17:32:35.744626Z:2609:cc-oci-runtime:debug:netlink_link_set_master 8 3

2017-08-01T17:32:35.744777Z:2609:cc-oci-runtime:debug:netlink_link_enable[1] ceth0

2017-08-01T17:32:35.744834Z:2609:cc-oci-runtime:debug:netlink_link_enable[1] eth0

2017-08-01T17:32:35.744865Z:2609:cc-oci-runtime:debug:netlink_link_enable[1] beth0

2017-08-01T17:32:35.744955Z:2609:cc-oci-runtime:debug:network configuration complete

2017-08-01T17:32:35.745014Z:2609:cc-oci-runtime:debug:using /usr/share/defaults/cc-oci-runtime/hypervisor.args

2017-08-01T17:32:35.745867Z:2609:cc-oci-runtime:debug:guest agent ctl socket: /var/run/cc-oci-runtime/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/ga-ctl.sock

2017-08-01T17:32:35.745914Z:2609:cc-oci-runtime:debug:guest agent tty socket: /var/run/cc-oci-runtime/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/ga-tty.sock

2017-08-01T17:32:35.746016Z:2609:cc-oci-runtime:debug:checking child setup (blocking)

2017-08-01T17:32:35.746075Z:2616:cc-oci-runtime:debug:reading hypervisor command-line from pipe

2017-08-01T17:32:35.746165Z:2616:cc-oci-runtime:debug:running command:

2017-08-01T17:32:35.746213Z:2616:cc-oci-runtime:debug:arg: '/usr/bin/qemu-lite-system-x86_64'

2017-08-01T17:32:35.746251Z:2616:cc-oci-runtime:debug:arg: '-name'

2017-08-01T17:32:35.746288Z:2616:cc-oci-runtime:debug:arg: '4d6f07804182'

2017-08-01T17:32:35.746325Z:2616:cc-oci-runtime:debug:arg: '-machine'

2017-08-01T17:32:35.746352Z:2616:cc-oci-runtime:debug:arg: 'pc-lite,accel=kvm,kernel_irqchip,nvdimm'

2017-08-01T17:32:35.746378Z:2616:cc-oci-runtime:debug:arg: '-device'

2017-08-01T17:32:35.746410Z:2616:cc-oci-runtime:debug:arg: 'nvdimm,memdev=mem0,id=nv0'

2017-08-01T17:32:35.746436Z:2616:cc-oci-runtime:debug:arg: '-object'

2017-08-01T17:32:35.746466Z:2616:cc-oci-runtime:debug:arg: 'memory-backend-file,id=mem0,mem-path=/usr/share/clear-containers/clear-16670-containers.img,size=235929600'

2017-08-01T17:32:35.746493Z:2616:cc-oci-runtime:debug:arg: '-m'

2017-08-01T17:32:35.746518Z:2616:cc-oci-runtime:debug:arg: '2G,slots=2,maxmem=3G'

2017-08-01T17:32:35.746544Z:2616:cc-oci-runtime:debug:arg: '-kernel'

2017-08-01T17:32:35.746569Z:2616:cc-oci-runtime:debug:arg: '/usr/share/clear-containers/vmlinux-4.9.35-62.container'

2017-08-01T17:32:35.746595Z:2616:cc-oci-runtime:debug:arg: '-append'

2017-08-01T17:32:35.746626Z:2616:cc-oci-runtime:debug:arg: 'root=/dev/pmem0p1 rootflags=dax,data=ordered,errors=remount-ro rw rootfstype=ext4 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 panic=1 console=hvc0 console=hvc1 initcall_debug init=/usr/lib/systemd/systemd systemd.unit=cc-agent.target iommu=off quiet systemd.mask=systemd-networkd.service systemd.mask=systemd-networkd.socket systemd.show_status=false cryptomgr.notests net.ifnames=0 ip=::::::76e9f557a60a::off::'

2017-08-01T17:32:35.746680Z:2616:cc-oci-runtime:debug:arg: '-smp'

2017-08-01T17:32:35.746705Z:2616:cc-oci-runtime:debug:arg: '2,sockets=1,cores=2,threads=1'

2017-08-01T17:32:35.746730Z:2616:cc-oci-runtime:debug:arg: '-cpu'

2017-08-01T17:32:35.746755Z:2616:cc-oci-runtime:debug:arg: 'host'

2017-08-01T17:32:35.746778Z:2616:cc-oci-runtime:debug:arg: '-rtc'

2017-08-01T17:32:35.746802Z:2616:cc-oci-runtime:debug:arg: 'base=utc,driftfix=slew'

2017-08-01T17:32:35.746827Z:2616:cc-oci-runtime:debug:arg: '-no-user-config'

2017-08-01T17:32:35.746854Z:2616:cc-oci-runtime:debug:arg: '-nodefaults'

2017-08-01T17:32:35.746886Z:2616:cc-oci-runtime:debug:arg: '-global'

2017-08-01T17:32:35.746911Z:2616:cc-oci-runtime:debug:arg: 'kvm-pit.lost_tick_policy=discard'

2017-08-01T17:32:35.746936Z:2616:cc-oci-runtime:debug:arg: '-device'

2017-08-01T17:32:35.746960Z:2616:cc-oci-runtime:debug:arg: 'virtio-serial-pci,id=virtio-serial0'

2017-08-01T17:32:35.746985Z:2616:cc-oci-runtime:debug:arg: '-device'

2017-08-01T17:32:35.747009Z:2616:cc-oci-runtime:debug:arg: 'virtconsole,chardev=charconsole0,id=console0'

2017-08-01T17:32:35.747034Z:2616:cc-oci-runtime:debug:arg: '-chardev'

2017-08-01T17:32:35.747058Z:2616:cc-oci-runtime:debug:arg: 'socket,path=/var/run/cc-oci-runtime/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/console.sock,server,nowait,id=charconsole0,signal=off'

2017-08-01T17:32:35.747085Z:2616:cc-oci-runtime:debug:arg: '-chardev'

2017-08-01T17:32:35.747109Z:2616:cc-oci-runtime:debug:arg: 'socket,id=procsock,path=/var/run/cc-oci-runtime/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/process.sock,server,nowait'

2017-08-01T17:32:35.747135Z:2616:cc-oci-runtime:debug:arg: '-chardev'

2017-08-01T17:32:35.747159Z:2616:cc-oci-runtime:debug:arg: 'socket,id=charch0,path=/var/run/cc-oci-runtime/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/ga-ctl.sock,server,nowait'

2017-08-01T17:32:35.747185Z:2616:cc-oci-runtime:debug:arg: '-device'

2017-08-01T17:32:35.747209Z:2616:cc-oci-runtime:debug:arg: 'virtserialport,bus=virtio-serial0.0,nr=1,chardev=charch0,id=channel0,name=sh.hyper.channel.0'

2017-08-01T17:32:35.747237Z:2616:cc-oci-runtime:debug:arg: '-chardev'

2017-08-01T17:32:35.747263Z:2616:cc-oci-runtime:debug:arg: 'socket,id=charch1,path=/var/run/cc-oci-runtime/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/ga-tty.sock,server,nowait'

2017-08-01T17:32:35.747289Z:2616:cc-oci-runtime:debug:arg: '-device'

2017-08-01T17:32:35.747313Z:2616:cc-oci-runtime:debug:arg: 'virtserialport,bus=virtio-serial0.0,nr=2,chardev=charch1,id=channel1,name=sh.hyper.channel.1'

2017-08-01T17:32:35.747338Z:2616:cc-oci-runtime:debug:arg: '-uuid'

2017-08-01T17:32:35.747363Z:2616:cc-oci-runtime:debug:arg: '943691ee-266d-4d11-bbd3-4d6f07804182'

2017-08-01T17:32:35.747388Z:2616:cc-oci-runtime:debug:arg: '-qmp'

2017-08-01T17:32:35.747412Z:2616:cc-oci-runtime:debug:arg: 'unix:/var/run/cc-oci-runtime/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/hypervisor.sock,server,nowait'

2017-08-01T17:32:35.747438Z:2616:cc-oci-runtime:debug:arg: '-nographic'

2017-08-01T17:32:35.747462Z:2616:cc-oci-runtime:debug:arg: '-vga'

2017-08-01T17:32:35.747486Z:2616:cc-oci-runtime:debug:arg: 'none'

2017-08-01T17:32:35.747510Z:2616:cc-oci-runtime:debug:arg: '-netdev'

2017-08-01T17:32:35.747534Z:2616:cc-oci-runtime:debug:arg: 'tap,ifname=ceth0,script=no,downscript=no,id=ceth0,vhost=on'

2017-08-01T17:32:35.747559Z:2616:cc-oci-runtime:debug:arg: '-device'

2017-08-01T17:32:35.747584Z:2616:cc-oci-runtime:debug:arg: 'driver=virtio-net-pci,netdev=ceth0,mac=02:42:ac:11:00:02'

2017-08-01T17:32:35.747609Z:2616:cc-oci-runtime:debug:arg: '-device'

2017-08-01T17:32:35.747633Z:2616:cc-oci-runtime:debug:arg: 'virtio-9p-pci,fsdev=workload9p,mount_tag=rootfs'

2017-08-01T17:32:35.747658Z:2616:cc-oci-runtime:debug:arg: '-fsdev'

2017-08-01T17:32:35.747682Z:2616:cc-oci-runtime:debug:arg: 'local,id=workload9p,path=/var/run/cc-oci-runtime/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/workload,security_model=none'

2017-08-01T17:32:35.747871Z:2609:cc-oci-runtime:debug:child setup successful

2017-08-01T17:32:35.895441Z:2609:cc-oci-runtime:debug:CTL created event: 3

2017-08-01T17:32:35.895536Z:2609:cc-oci-runtime:debug:CTL created event: 1

2017-08-01T17:32:35.895603Z:2609:cc-oci-runtime:debug:communicating with proxy

2017-08-01T17:32:35.895646Z:2609:cc-oci-runtime:debug:sending message (length 447) to proxy socket

2017-08-01T17:32:35.895683Z:2609:cc-oci-runtime:debug:writing message data to proxy socket: {"id":"hello","data":{"containerId":"76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f","ctlSerial":"/var/run/cc-oci-runtime/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/ga-ctl.sock","ioSerial":"/var/run/cc-oci-runtime/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/ga-tty.sock","console":"/var/run/cc-oci-runtime/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/console.sock"}}

2017-08-01T17:32:36.725237Z:2609:cc-oci-runtime:debug:proxy msg length: 37

2017-08-01T17:32:36.725362Z:2609:cc-oci-runtime:debug:message read from proxy socket: {"success":true,"data":{"version":1}}

2017-08-01T17:32:36.725536Z:2609:cc-oci-runtime:debug:msg received: {"success":true,"data":{"version":1}}

2017-08-01T17:32:36.725789Z:2609:cc-oci-runtime:debug:communicating with proxy

2017-08-01T17:32:36.725865Z:2609:cc-oci-runtime:debug:sending message (length 795) to proxy socket

2017-08-01T17:32:36.725955Z:2609:cc-oci-runtime:debug:writing message data to proxy socket: {"id":"hyper","data":{"hyperName":"startpod","data":{"hostname":"76e9f557a60a","containers":[],"shareDir":"rootfs","interfaces":[{"macAddr":"02:42:ac:11:00:02","newDeviceName":"eth0","mtu":1500,"ipAddresses":[{"ipAddress":"172.17.0.2","netMask":"255.255.0.0"}]}],"routes":[{"dest":"default","gateway":"172.17.0.1","device":"eth0"},{"dest":"172.17.0.0","device":"eth0"}],"iptableRules":"# Generated by iptables-save v1.6.0 on Tue Aug  1 09:32:35 2017\nnat\n:PREROUTING ACCEPT [0:0]\n:INPUT ACCEPT [0:0]\n:OUTPUT ACCEPT [0:0]\n:POSTROUTING ACCEPT [0:0]\nCOMMIT\n# Completed on Tue Aug  1 09:32:35 2017\n# Generated by iptables-save v1.6.0 on Tue Aug  1 09:32:35 2017\nfilter\n:INPUT ACCEPT [0:0]\n:FORWARD ACCEPT [0:0]\n:OUTPUT ACCEPT [0:0]\nCOMMIT\n# Completed on Tue Aug  1 09:32:35 2017\n"}}}

2017-08-01T17:32:36.728639Z:2609:cc-oci-runtime:debug:proxy msg length: 181

2017-08-01T17:32:36.728737Z:2609:cc-oci-runtime:debug:message read from proxy socket: {"success":false,"error":"write unix @-\u003e/var/run/cc-oci-runtime/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/ga-ctl.sock: use of closed network connection"}

2017-08-01T17:32:36.729724Z:2609:cc-oci-runtime:critical:failed to run hyper cmd startpod: {"success":false,"error":"write unix @-\u003e/var/run/cc-oci-runtime/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/ga-ctl.sock: use of closed network connection"}

2017-08-01T17:32:36.729816Z:2609:cc-oci-runtime:critical:failed to run pod create

2017-08-01T17:32:36.729926Z:2617:cc-oci-runtime:critical:failed to read proxy socket fd

2017-08-01T17:32:36.739972Z:2653:cc-oci-runtime:debug:cc-oci-runtime 2.2.3  called as: /usr/bin/cc-oci-runtime delete 76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f

2017-08-01T17:32:36.744520Z:2653:cc-oci-runtime:critical:cannot delete container, it is not stopped

2017-08-01T17:32:36.744597Z:2653:cc-oci-runtime:critical:failed to stop container 76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f
2017-08-01T17:32:36.779130Z:2657:cc-oci-runtime:debug:cc-oci-runtime 2.2.3  called as: /usr/bin/cc-oci-runtime delete 76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f

2017-08-01T17:32:36.779550Z:2657:cc-oci-runtime:debug:unable to parse '/run/docker/libcontainerd/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/config.json'

2017-08-01T17:32:36.779580Z:2657:cc-oci-runtime:debug:Error parsing '/run/docker/libcontainerd/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/config.json': Failed to open file '/run/docker/libcontainerd/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/config.json': No such file or directory

---

It looks like the rub is in this line:

2017-08-01T17:32:36.729724Z:2609:cc-oci-runtime:critical:failed to run hyper cmd startpod: {"success":false,"error":"write unix @-\u003e/var/run/cc-oci-runtime/76e9f557a60a4d16151c594622c79f1e645ba0d1e143813c7325b2f661522e5f/ga-ctl.sock: use of closed network connection"}

[pittma]

I attempted to run the qemu command generated by the runtime, and am getting this error:

# source run.sh
qemu-lite-system-x86_64: /usr/src/packages/BUILD/target-i386/kvm.c:1777: kvm_put_msrs: Assertion `ret == cpu->kvm_msr_buf->nmsrs' failed.
Aborted (core dumped)

With a little Googling, I landed on this bug report on qemu, which states that VMware is likely disallowing the PMU MSR accesses, and previously this error was ignored. When using the suggested remedy of adding pmu=off to the -cpu flag, qemu again hangs and pegs the CPU at 100%.

That said, I think it's pretty likely that this issue resides in either VMware or qemu, or is just straight-up a limitation of my VMware-based environment ¯_(ツ)_/¯.

[pittma]

I'm going to close this for now and try and track down a physical host. Should the same issues arise, I'll reopen. Thanks for your help!

[grahamwhaley]

This rang a bell - we've seen this before some time ago: #666 (comment)
@mcastelino @anthonyzxu did we ever come up with any more info on that (issues with msr access under vmware)

[jcvenegas]

@danielscottt thank you!, looks like the VM is not working correctly,

After do docker run is there any reminding qemu process ? :

ps aux | qemu-lite

Can you provide more information about the guest that being used?:

• What is the amount of guest physical memory ?
• What is the CPU that is being visualized ?
• What is the Ubuntu version ?

cat /proc/cpuinfo

Also in order to have hypervisor logs , could you also do:

$ export logdir=/run/cc-oci-runtime
$ cat << EOT | sudo tee -a /etc/cc-oci-runtime/cc-oci-runtime.sh.cfg
--hypervisor-log-dir
$logdir
EOT

Then try to run again a container and see if there is something we could get from:

$cat /run/cc-oci-runtime/*hypervisor.std*

[pittma]

Hey, thanks for the responses! I'll reopen.

@grahamwhaley @mcastelino @anthonyzxu - I'd also love to know if there were any further developments!

@jcvenegas - Thanks! I'll start gathering this info now.

[jcvenegas]

@danielscottt sorry, I did not seen your comments before last my comment, sure let us know if you find something interesting

[pittma]

# cat /proc/cpuinfo
processor       : 0
vendor_id       : GenuineIntel
cpu family      : 6
model           : 70
model name      : Intel(R) Core(TM) i7-4980HQ CPU @ 2.80GHz
stepping        : 1
microcode       : 0xf
cpu MHz         : 2793.194
cache size      : 6144 KB
physical id     : 0
siblings        : 1
core id         : 0
cpu cores       : 1
apicid          : 0
initial apicid  : 0
fpu             : yes
fpu_exception   : yes
cpuid level     : 13
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts mmx fxsr sse sse2 ss syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts nopl xtopology tsc_reliable nonstop_tsc aperfmperf eagerfpu pni pclmulqdq vmx ssse3 fma cx16 pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand hypervisor lahf_lm abm epb tpr_shadow vnmi ept vpid fsgsbase tsc_adjust bmi1 avx2 smep bmi2 invpcid xsaveopt dtherm ida arat pln pts
bugs            :
bogomips        : 5586.38
clflush size    : 64
cache_alignment : 64
address sizes   : 42 bits physical, 48 bits virtual
power management:

processor       : 1
vendor_id       : GenuineIntel
cpu family      : 6
model           : 70
model name      : Intel(R) Core(TM) i7-4980HQ CPU @ 2.80GHz
stepping        : 1
microcode       : 0xf
cpu MHz         : 2793.194
cache size      : 6144 KB
physical id     : 2
siblings        : 1
core id         : 0
cpu cores       : 1
apicid          : 2
initial apicid  : 2
fpu             : yes
fpu_exception   : yes
cpuid level     : 13
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts mmx fxsr sse sse2 ss syscall nx pdpe1gb rdtscp lm constant_tsc arch_perfmon pebs bts nopl xtopology tsc_reliable nonstop_tsc aperfmperf eagerfpu pni pclmulqdq vmx ssse3 fma cx16 pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand hypervisor lahf_lm abm epb tpr_shadow vnmi ept vpid fsgsbase tsc_adjust bmi1 avx2 smep bmi2 invpcid xsaveopt dtherm ida arat pln pts
bugs            :
bogomips        : 5586.38
clflush size    : 64
cache_alignment : 64
address sizes   : 42 bits physical, 48 bits virtual
power management:

Guest memory is 4 GB:

# free -m
              total        used        free      shared  buff/cache   available
Mem:           3934         129        3228           6         576        3497
Swap:          4095           0        4095

Yep, the hypervisor's stderr file contains the same error:

# cat /run/cc-oci-runtime/b6d415b8822f2363f7580dd927525029e2cafe11a36746387520cf2ea1e2e74c-hypervisor.stderr
qemu-lite-system-x86_64: /usr/src/packages/BUILD/target-i386/kvm.c:1777: kvm_put_msrs: Assertion `ret == cpu->kvm_msr_buf->nmsrs' failed.

[jcvenegas]

Thanks for confirm, we will investigate more about it. In the in the meantime, I will add to our docs this limitation.