search

intel / cc-oci-runtime

OCI (Open Containers Initiative) compatible runtime for Intel® Architecture
GNU General Public License v2.0
416 stars 59 forks source link

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

Open pittma opened 7 years ago

pittma commented 7 years ago

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: screen shot 2017-07-31 at 4 46 22 pm

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 commented 7 years ago

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 commented 7 years ago

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 commented 7 years ago

@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 commented 7 years ago

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\n*nat\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\n*filter\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 commented 7 years ago

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 commented 7 years ago

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 commented 7 years ago

This rang a bell - we've seen this before some time ago: https://github.com/01org/cc-oci-runtime/issues/666#issuecomment-284544889 @mcastelino @anthonyzxu did we ever come up with any more info on that (issues with msr access under vmware)

jcvenegas commented 7 years ago

@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?:

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 commented 7 years ago

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 commented 7 years ago

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

pittma commented 7 years ago 
# 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 commented 7 years ago

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

mcastelino commented 7 years ago

@danielscottt We should have these fixed in 3.0 once this PR merges

https://github.com/containers/virtcontainers/pull/343

This https://github.com/containers/virtcontainers/pull/343/commits/dd13e0b7e0a4957a6b8e982356e0cb4bc227e391#diff-82527fac73a6f9f5442c1db98ce1784aR589 fixes the PMU issue.

There were two issues, A kvm bug for which we have a workaround and the PMU issue.

I have verified this works on Workstation Pro 12 12.5.7 build-5813279

grahamwhaley commented 7 years ago

As a bit of an update, the root cause of the failure under VMware has been found over on CC3.x, and the fix is to turn off the pmu support on the qemu command line (I believe). See https://github.com/containers/virtcontainers/pull/343 for more details

grahamwhaley commented 7 years ago

(doh - thanks @mcastelino - beat me to it)