search

hyperhq / runv

Hypervisor-based Runtime for OCI
Apache License 2.0
827 stars 129 forks source link

kvmtool bug #534

Open SergeyOvsienko opened 6 years ago

SergeyOvsienko commented 6 years ago

Hi All!

runv version 0.8.1, commit: v0.8.1-61-g773c40b
Docker version 17.05.0-ce, build 89658be

Runv hase been started as

sudo ./runv --debug --driver kvmtool --kernel /opt/hyperstart/build/kernel --initrd /opt/hyperstart/build/hyper-initrd.img containerd
I0724 14:19:55.725148   24171 driverloader_linux.go:60] Driver "kvmtool" loaded
I0724 14:19:55.726186   24171 containerd.go:179] containerd daemon started successfully.
I0724 14:19:55.726201   24171 containerd.go:216] containerd: grpc api on /run/runv-containerd/containerd.sock

Dockerd

sudo dockerd -D -s devicemapper -l debug --containerd=/run/runv-containerd/containerd.sock --add-runtime runv=runv --default-runtime runv

After i am start busybox container

sudo docker  run -ti busybox
Unable to find image 'busybox:latest' locally
latest: Pulling from library/busybox
9e87eff13613: Pull complete 
Digest: sha256:2605a2c4875ce5eb27a9f7403263190cd1af31e48a2044d400320548356251c4
Status: Downloaded newer image for busybox:latest
docker: Error response from daemon: json: cannot unmarshal array into Go struct field Process.capabilities of type specs.LinuxCapabilities.

In RunV log

I0724 14:21:55.870186   24171 server.go:41] gRPC handle CreateContainer

In dockerd log

DEBU[0029] Calling POST /v1.29/containers/create        
DEBU[0029] form data: {"AttachStderr":true,"AttachStdin":true,"AttachStdout":true,"Cmd":null,"Domainname":"","Entrypoint":null,"Env":[],"HostConfig":{"AutoRemove":false,"Binds":null,"BlkioDeviceReadBps":null,"BlkioDeviceReadIOps":null,"BlkioDeviceWriteBps":null,"BlkioDeviceWriteIOps":null,"BlkioWeight":0,"BlkioWeightDevice":null,"CapAdd":null,"CapDrop":null,"Cgroup":"","CgroupParent":"","ConsoleSize":[0,0],"ContainerIDFile":"","CpuCount":0,"CpuPercent":0,"CpuPeriod":0,"CpuQuota":0,"CpuRealtimePeriod":0,"CpuRealtimeRuntime":0,"CpuShares":0,"CpusetCpus":"","CpusetMems":"","DeviceCgroupRules":null,"Devices":[],"DiskQuota":0,"Dns":[],"DnsOptions":[],"DnsSearch":[],"ExtraHosts":null,"GroupAdd":null,"IOMaximumBandwidth":0,"IOMaximumIOps":0,"IpcMode":"","Isolation":"","KernelMemory":0,"Links":null,"LogConfig":{"Config":{},"Type":""},"Memory":0,"MemoryReservation":0,"MemorySwap":0,"MemorySwappiness":-1,"NanoCpus":0,"NetworkMode":"default","OomKillDisable":false,"OomScoreAdj":0,"PidMode":"","PidsLimit":0,"PortBindings":{},"Privileged":false,"PublishAllPorts":false,"ReadonlyRootfs":false,"RestartPolicy":{"MaximumRetryCount":0,"Name":"no"},"SecurityOpt":null,"ShmSize":0,"UTSMode":"","Ulimits":null,"UsernsMode":"","VolumeDriver":"","VolumesFrom":null},"Hostname":"","Image":"busybox","Labels":{},"NetworkingConfig":{"EndpointsConfig":{}},"OnBuild":null,"OpenStdin":true,"StdinOnce":true,"Tty":true,"User":"","Volumes":{},"WorkingDir":""} 
DEBU[0029] Calling GET /v1.29/info                      
DEBU[0029] Calling POST /v1.29/images/create?fromImage=busybox&tag=latest 
DEBU[0029] Trying to pull busybox from https://registry-1.docker.io v2 
DEBU[0031] Pulling ref from V2 registry: busybox:latest 
DEBU[0031] pulling blob "sha256:9e87eff13613eed2f67b0188f8604d1bbdd3a7f5d6a4f565e8923817db65d6e5" 
DEBU[0032] Downloaded 9e87eff13613 to tempfile /var/lib/docker/tmp/GetImageBlob097780392 
DEBU[0032] devmapper: AddDevice START(hash=fd304673a72f98c4ae78c28999c1eec555aadfecd6ea7165a696f563a2394188 basehash=) 
DEBU[0032] devmapper: Failed to read /var/lib/docker/devicemapper/metadata/fd304673a72f98c4ae78c28999c1eec555aadfecd6ea7165a696f563a2394188 with err: open /var/lib/docker/devicemapper/metadata/fd304673a72f98c4ae78c28999c1eec555aadfecd6ea7165a696f563a2394188: no such file or directory 
DEBU[0032] devmapper: registerDevice(2, fd304673a72f98c4ae78c28999c1eec555aadfecd6ea7165a696f563a2394188) 
DEBU[0032] devmapper: AddDevice END(hash=fd304673a72f98c4ae78c28999c1eec555aadfecd6ea7165a696f563a2394188 basehash=) 
DEBU[0032] devmapper: activateDeviceIfNeeded(fd304673a72f98c4ae78c28999c1eec555aadfecd6ea7165a696f563a2394188) 
DEBU[0032] Start untar layer                            
DEBU[0032] Untar time: 0.073797027s                     
DEBU[0032] devmapper: UnmountDevice START(hash=fd304673a72f98c4ae78c28999c1eec555aadfecd6ea7165a696f563a2394188) 
DEBU[0032] devmapper: Unmount(/var/lib/docker/devicemapper/mnt/fd304673a72f98c4ae78c28999c1eec555aadfecd6ea7165a696f563a2394188) 
DEBU[0032] devmapper: Unmount done                      
DEBU[0032] devmapper: deactivateDevice START(fd304673a72f98c4ae78c28999c1eec555aadfecd6ea7165a696f563a2394188) 
DEBU[0032] devmapper: removeDevice START(docker-8:1-7087740-fd304673a72f98c4ae78c28999c1eec555aadfecd6ea7165a696f563a2394188) 
DEBU[0032] devmapper: removeDevice END(docker-8:1-7087740-fd304673a72f98c4ae78c28999c1eec555aadfecd6ea7165a696f563a2394188) 
DEBU[0032] devmapper: deactivateDevice END(fd304673a72f98c4ae78c28999c1eec555aadfecd6ea7165a696f563a2394188) 
DEBU[0032] devmapper: UnmountDevice END(hash=fd304673a72f98c4ae78c28999c1eec555aadfecd6ea7165a696f563a2394188) 
DEBU[0032] Applied tar sha256:08c2295a7fa5c220b0f60c994362d290429ad92f6e0235509db91582809442f3 to fd304673a72f98c4ae78c28999c1eec555aadfecd6ea7165a696f563a2394188, size: 1129193 
DEBU[0032] Calling POST /v1.29/containers/create        
DEBU[0032] form data: {"AttachStderr":true,"AttachStdin":true,"AttachStdout":true,"Cmd":null,"Domainname":"","Entrypoint":null,"Env":[],"HostConfig":{"AutoRemove":false,"Binds":null,"BlkioDeviceReadBps":null,"BlkioDeviceReadIOps":null,"BlkioDeviceWriteBps":null,"BlkioDeviceWriteIOps":null,"BlkioWeight":0,"BlkioWeightDevice":null,"CapAdd":null,"CapDrop":null,"Cgroup":"","CgroupParent":"","ConsoleSize":[0,0],"ContainerIDFile":"","CpuCount":0,"CpuPercent":0,"CpuPeriod":0,"CpuQuota":0,"CpuRealtimePeriod":0,"CpuRealtimeRuntime":0,"CpuShares":0,"CpusetCpus":"","CpusetMems":"","DeviceCgroupRules":null,"Devices":[],"DiskQuota":0,"Dns":[],"DnsOptions":[],"DnsSearch":[],"ExtraHosts":null,"GroupAdd":null,"IOMaximumBandwidth":0,"IOMaximumIOps":0,"IpcMode":"","Isolation":"","KernelMemory":0,"Links":null,"LogConfig":{"Config":{},"Type":""},"Memory":0,"MemoryReservation":0,"MemorySwap":0,"MemorySwappiness":-1,"NanoCpus":0,"NetworkMode":"default","OomKillDisable":false,"OomScoreAdj":0,"PidMode":"","PidsLimit":0,"PortBindings":{},"Privileged":false,"PublishAllPorts":false,"ReadonlyRootfs":false,"RestartPolicy":{"MaximumRetryCount":0,"Name":"no"},"SecurityOpt":null,"ShmSize":0,"UTSMode":"","Ulimits":null,"UsernsMode":"","VolumeDriver":"","VolumesFrom":null},"Hostname":"","Image":"busybox","Labels":{},"NetworkingConfig":{"EndpointsConfig":{}},"OnBuild":null,"OpenStdin":true,"StdinOnce":true,"Tty":true,"User":"","Volumes":{},"WorkingDir":""} 
DEBU[0032] devmapper: AddDevice START(hash=a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f-init basehash=fd304673a72f98c4ae78c28999c1eec555aadfecd6ea7165a696f563a2394188) 
DEBU[0032] devmapper: Failed to read /var/lib/docker/devicemapper/metadata/a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f-init with err: open /var/lib/docker/devicemapper/metadata/a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f-init: no such file or directory 
DEBU[0032] devmapper: registerDevice(3, a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f-init) 
DEBU[0032] devmapper: AddDevice END(hash=a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f-init basehash=fd304673a72f98c4ae78c28999c1eec555aadfecd6ea7165a696f563a2394188) 
DEBU[0032] devmapper: activateDeviceIfNeeded(a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f-init) 
DEBU[0032] devmapper: UnmountDevice START(hash=a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f-init) 
DEBU[0032] devmapper: Unmount(/var/lib/docker/devicemapper/mnt/a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f-init) 
DEBU[0032] devmapper: Unmount done                      
DEBU[0032] devmapper: deactivateDevice START(a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f-init) 
DEBU[0032] devmapper: removeDevice START(docker-8:1-7087740-a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f-init) 
DEBU[0032] devmapper: removeDevice END(docker-8:1-7087740-a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f-init) 
DEBU[0032] devmapper: deactivateDevice END(a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f-init) 
DEBU[0032] devmapper: UnmountDevice END(hash=a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f-init) 
DEBU[0032] devmapper: AddDevice START(hash=a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f basehash=a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f-init) 
DEBU[0032] devmapper: Failed to read /var/lib/docker/devicemapper/metadata/a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f with err: open /var/lib/docker/devicemapper/metadata/a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f: no such file or directory 
DEBU[0032] devmapper: registerDevice(4, a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f) 
DEBU[0032] devmapper: AddDevice END(hash=a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f basehash=a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f-init) 
DEBU[0032] devmapper: activateDeviceIfNeeded(a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f) 
DEBU[0032] container mounted via layerStore: /var/lib/docker/devicemapper/mnt/a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f/rootfs 
DEBU[0032] devmapper: UnmountDevice START(hash=a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f) 
DEBU[0032] devmapper: Unmount(/var/lib/docker/devicemapper/mnt/a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f) 
DEBU[0032] devmapper: Unmount done                      
DEBU[0032] devmapper: deactivateDevice START(a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f) 
DEBU[0032] devmapper: removeDevice START(docker-8:1-7087740-a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f) 
DEBU[0032] devmapper: removeDevice END(docker-8:1-7087740-a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f) 
DEBU[0032] devmapper: deactivateDevice END(a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f) 
DEBU[0032] devmapper: UnmountDevice END(hash=a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f) 
DEBU[0032] Calling POST /v1.29/containers/1133902ccd286779a72245102b2f0d3824f8e8a0d156d635b7d81a9840bb4e47/attach?stderr=1&stdin=1&stdout=1&stream=1 
DEBU[0032] attach: stdin: begin                         
DEBU[0032] attach: stdout: begin                        
DEBU[0032] attach: stderr: begin                        
DEBU[0032] Calling GET /v1.29/events?filters=%7B%22container%22%3A%7B%221133902ccd286779a72245102b2f0d3824f8e8a0d156d635b7d81a9840bb4e47%22%3Atrue%7D%2C%22type%22%3A%7B%22container%22%3Atrue%7D%7D 
DEBU[0032] Calling POST /v1.29/containers/1133902ccd286779a72245102b2f0d3824f8e8a0d156d635b7d81a9840bb4e47/start 
DEBU[0032] devmapper: activateDeviceIfNeeded(a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f) 
DEBU[0032] container mounted via layerStore: /var/lib/docker/devicemapper/mnt/a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f/rootfs 
DEBU[0032] Assigning addresses for endpoint loving_brahmagupta's interface on network bridge 
DEBU[0032] RequestAddress(LocalDefault/172.17.0.0/16, <nil>, map[]) 
DEBU[0032] Assigning addresses for endpoint loving_brahmagupta's interface on network bridge 
DEBU[0032] Programming external connectivity on endpoint loving_brahmagupta (1b416c0f1567d82af0eb877da881ac23a36a69abf09a43dab1d9145f36454727) 
ERRO[0032] Create container failed with error: json: cannot unmarshal array into Go struct field Process.capabilities of type specs.LinuxCapabilities 
ERRO[0032] stream copy error: reading from a closed fifo
github.com/docker/docker/vendor/github.com/tonistiigi/fifo.(*fifo).Read
    /usr/src/docker/.gopath/src/github.com/docker/docker/vendor/github.com/tonistiigi/fifo/fifo.go:142
bufio.(*Reader).fill
    /usr/local/go/src/bufio/bufio.go:97
bufio.(*Reader).WriteTo
    /usr/local/go/src/bufio/bufio.go:472
io.copyBuffer
    /usr/local/go/src/io/io.go:380
io.Copy
    /usr/local/go/src/io/io.go:360
github.com/docker/docker/pkg/pools.Copy
    /usr/src/docker/.gopath/src/github.com/docker/docker/pkg/pools/pools.go:60
github.com/docker/docker/container/stream.(*Config).CopyToPipe.func1.1
    /usr/src/docker/.gopath/src/github.com/docker/docker/container/stream/streams.go:121
runtime.goexit
    /usr/local/go/src/runtime/asm_amd64.s:2086 
DEBU[0032] attach: stdout: end                          
DEBU[0032] attach: stderr: end                          
DEBU[0032] attach: stdin: end                           
DEBU[0032] Closing buffered stdin pipe                  
DEBU[0032] Revoking external connectivity on endpoint loving_brahmagupta (1b416c0f1567d82af0eb877da881ac23a36a69abf09a43dab1d9145f36454727) 
DEBU[0032] DeleteConntrackEntries purged ipv4:0, ipv6:0 
DEBU[0032] Releasing addresses for endpoint loving_brahmagupta's interface on network bridge 
DEBU[0032] ReleaseAddress(LocalDefault/172.17.0.0/16, 172.17.0.2) 
DEBU[0032] devmapper: UnmountDevice START(hash=a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f) 
DEBU[0032] devmapper: Unmount(/var/lib/docker/devicemapper/mnt/a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f) 
DEBU[0032] devmapper: Unmount done                      
DEBU[0032] devmapper: deactivateDevice START(a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f) 
DEBU[0032] devmapper: removeDevice START(docker-8:1-7087740-a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f) 
DEBU[0032] devmapper: removeDevice END(docker-8:1-7087740-a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f) 
DEBU[0032] devmapper: deactivateDevice END(a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f) 
DEBU[0032] devmapper: UnmountDevice END(hash=a874f3b8603a4edf784a867942210ffef05d681a08f0600f682a59d65885b57f) 
ERRO[0032] Handler for POST /v1.29/containers/1133902ccd286779a72245102b2f0d3824f8e8a0d156d635b7d81a9840bb4e47/start returned error: json: cannot unmarshal array into Go struct field Process.capabilities of type specs.LinuxCapabilities
gao-feng commented 6 years ago

@SergeyOvsienko

Wow, so quickly:-) Thanks for your try!

docker: Error response from daemon: json: cannot unmarshal array into Go struct field Process.capabilities of type specs.LinuxCapabilities.

This problem is not related to kvmtool or other hypervisor, it is caused by the old oci config and new oci spec. you should update your oci container config, simply remove Process.capabilities is fine since runv doesn't care about this field. the below is my process config

        "process": {
                "terminal": true,
                "user": {},
                "args": [
                        "sh"
                ],
                "env": [
                        "PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin",
                        "TERM=xterm"
                ],
                "cwd": "/",
                "rlimits": [
                        {
                                "type": "RLIMIT_NOFILE",
                                "hard": 1024,
                                "soft": 1024
                        }
                ],
                "noNewPrivileges": true
        },
SergeyOvsienko commented 6 years ago

Thanks for quick answer. I am update docker for Docker version 17.06.0-ce, build 02c1d87 and clear /var/lib/docker directory.

dpkg -l|grep kvmtool
ii  kvmtool                                               0.20151104-1                                   amd64        Native Linux KVM TOOL

After this i am run sudo docker run -ti busybox

I0724 17:42:10.209946    2163 server.go:41] gRPC handle CreateContainer
I0724 17:42:10.211748    2163 hyperpod.go:456] Using kernel: ; Initrd: ; vCPU: 1; Memory 128
I0724 17:42:10.220949    2163 lkvm.go:222] SB[vm-mgXyNufJtB] find /dev/pts/12 /dev/pts/13
I0724 17:42:11.221103    2163 lkvm.go:222] SB[vm-mgXyNufJtB] find /dev/pts/12 /dev/pts/13 /dev/pts/14
I0724 17:42:11.221189    2163 vm.go:765] VM[vm-mgXyNufJtB] GetVm succeeded
I0724 17:42:11.221196    2163 hyperpod.go:468] Creating VM with default kernel config
I0724 17:42:11.221237    2163 lkvm.go:248] lkvm output:
I0724 17:42:11.221283    2163 hypervisor.go:41] SB[vm-mgXyNufJtB] watch hyperstart
I0724 17:42:11.221289    2163 hypervisor.go:44] SB[vm-mgXyNufJtB] issue VERSION request for keep-alive test
I0724 17:42:11.222700    2163 vm_console.go:56] SB[vm-mgXyNufJtB] fail to enable vmLogd: dial unix /var/run/vmlogd.sock: connect: no such file or directory
I0724 17:42:11.242161    2163 json.go:171] SB[vm-mgXyNufJtB] Wating for init messages...
I0724 17:42:11.242263    2163 json.go:446] SB[vm-mgXyNufJtB] stream socket connected
I0724 17:42:11.242806    2163 vm_console.go:68] SB[vm-mgXyNufJtB] connected to /var/run/hyper/vm-mgXyNufJtB/console.sock
I0724 17:42:11.242834    2163 vm_console.go:75] SB[vm-mgXyNufJtB] connected /var/run/hyper/vm-mgXyNufJtB/console.sock as telnet mode.
I0724 17:42:11.242990    2163 vm_console.go:91] SB[vm-mgXyNufJtB] [CNL] omit the first 128 line of console logs
I0724 17:42:11.243003    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Policy zone: DMA32
I0724 17:42:11.243008    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL]
I0724 17:42:11.243014    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Kernel command line: noapic noacpi pci=conf1 reboot=k panic=1 i8042.direct=1 i8042.dumbkbd=1 i8042.nopnp=1 console=ttyS0 earlyprintk=serial i8042.noaux=1 rw rootflags=trans=virtio,version=9p2000.L,cache=loose rootfstype=9p console=ttyS0 hyper_use_serial
I0724 17:42:11.243019    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL]
I0724 17:42:11.243028    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] PID hash table entries: 512 (order: 0, 4096 bytes)
I0724 17:42:11.243032    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL]
I0724 17:42:11.243038    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Memory: 110856K/130680K available (5140K kernel code, 604K rwdata, 1528K rodata, 992K init, 640K bss, 19824K reserved, 0K cma-reserved)
I0724 17:42:11.243047    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL]
I0724 17:42:11.243051    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Hierarchical RCU implementation.
I0724 17:42:11.243056    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL]
I0724 17:42:11.243060    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL]     Build-time adjustment of leaf fanout to 64.
I0724 17:42:11.243065    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL]
I0724 17:42:11.243069    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL]     RCU restricting CPUs from NR_CPUS=8 to nr_cpu_ids=2.
I0724 17:42:11.243073    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=2
I0724 17:42:11.243078    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] NR_IRQS:4352 nr_irqs:440 16
I0724 17:42:11.243082    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Console: colour *CGA 80x25
I0724 17:42:11.243086    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] console [ttyS0] enabled
I0724 17:42:11.243090    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] console [ttyS0] enabled
I0724 17:42:11.243095    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] bootconsole [earlyser0] disabled
I0724 17:42:11.243099    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] bootconsole [earlyser0] disabled
I0724 17:42:11.243103    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] tsc: Detected 3192.672 MHz processor
I0724 17:42:11.243107    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] tsc: Marking TSC unstable due to TSCs unsynchronized
I0724 17:42:11.243112    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Calibrating delay loop (skipped) preset value.. 6385.34 BogoMIPS (lpj=3192672)
I0724 17:42:11.243117    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] pid_max: default: 32768 minimum: 301
I0724 17:42:11.243122    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Dentry cache hash table entries: 16384 (order: 5, 131072 bytes)
I0724 17:42:11.243126    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Inode-cache hash table entries: 8192 (order: 4, 65536 bytes)
I0724 17:42:11.243130    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Mount-cache hash table entries: 512 (order: 0, 4096 bytes)
I0724 17:42:11.243135    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Mountpoint-cache hash table entries: 512 (order: 0, 4096 bytes)
I0724 17:42:11.243140    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0
I0724 17:42:11.243144    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0
I0724 17:42:11.243148    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] smpboot: Max logical packages: 2
I0724 17:42:11.243152    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] smpboot: CPU 0 Converting physical 4 to logical package 0
I0724 17:42:11.243157    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] smpboot: CPU0: LKVMLKVMLKVM 06/3c (family: 0x6, model: 0x3c, stepping: 0x3)
I0724 17:42:11.243161    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Performance Events: no PMU driver, software events only.
I0724 17:42:11.243166    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] KVM setup paravirtual spinlock
I0724 17:42:11.243170    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] x86: Booted up 1 node, 1 CPUs
I0724 17:42:11.243252    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] smpboot: Total of 1 processors activated (6385.34 BogoMIPS)
I0724 17:42:11.243258    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] devtmpfs: initialized
I0724 17:42:11.243262    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] x86/mm: Memory block size: 128MB
I0724 17:42:11.243267    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
I0724 17:42:11.243271    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] futex hash table entries: 512 (order: 3, 32768 bytes)
I0724 17:42:11.243276    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] NET: Registered protocol family 16
I0724 17:42:11.243280    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] cpuidle: using governor ladder
I0724 17:42:11.243284    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] cpuidle: using governor menu
I0724 17:42:11.243289    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] PCI: Using configuration type 1 for base access
I0724 17:42:11.243293    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] ACPI: Interpreter disabled.
I0724 17:42:11.243297    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] vgaarb: loaded
I0724 17:42:11.243302    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] SCSI subsystem initialized
I0724 17:42:11.243306    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] dmi: Firmware registration failed.
I0724 17:42:11.243310    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] PCI: Probing PCI hardware
I0724 17:42:11.243315    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] PCI host bridge to bus 0000:00
I0724 17:42:11.243319    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] pci_bus 0000:00: root bus resource [io  0x0000-0xffff]
I0724 17:42:11.243323    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] pci_bus 0000:00: root bus resource [mem 0x00000000-0x7fffffffff]
I0724 17:42:11.243328    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] pci_bus 0000:00: No busn resource found for root bus, will use [bus 00-ff]
I0724 17:42:11.243332    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] clocksource: Switched to clocksource kvm-clock
I0724 17:42:11.243336    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] pnp: PnP ACPI: disabled
I0724 17:42:11.243340    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] NET: Registered protocol family 2
I0724 17:42:11.243345    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] TCP established hash table entries: 1024 (order: 1, 8192 bytes)
I0724 17:42:11.243350    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] TCP bind hash table entries: 1024 (order: 2, 16384 bytes)
I0724 17:42:11.243355    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] TCP: Hash tables configured (established 1024 bind 1024)
I0724 17:42:11.243359    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] UDP hash table entries: 256 (order: 1, 8192 bytes)
I0724 17:42:11.243367    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes)
I0724 17:42:11.243372    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] NET: Registered protocol family 1
I0724 17:42:11.243376    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Trying to unpack rootfs image as initramfs...
I0724 17:42:11.243380    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Freeing initrd memory: 6840K (ffff880007900000 - ffff880007fae000)
I0724 17:42:11.243385    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] platform rtc_cmos: registered platform RTC device (no PNP device found)
I0724 17:42:11.243389    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x2e053f72b27, max_idle_ns: 440795293829 ns
I0724 17:42:11.243394    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] workingset: timestamp_bits=37 max_order=15 bucket_order=0
I0724 17:42:11.243398    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] SGI XFS with ACLs, security attributes, no debug enabled
I0724 17:42:11.243402    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] 9p: Installing v9fs 9p2000 file system support
I0724 17:42:11.243406    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 253)
I0724 17:42:11.243411    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] io scheduler noop registered
I0724 17:42:11.243415    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] io scheduler cfq registered (default)
I0724 17:42:11.243419    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
I0724 17:42:11.243424    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
I0724 17:42:11.243428    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] virtio-pci 0000:00:00.0: virtio_pci: leaving for legacy driver
I0724 17:42:11.243433    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] virtio-pci 0000:00:01.0: virtio_pci: leaving for legacy driver
I0724 17:42:11.243437    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] virtio-pci 0000:00:02.0: virtio_pci: leaving for legacy driver
I0724 17:42:11.243453    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
I0724 17:42:11.243458    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] serial8250: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a U6_16550A
I0724 17:42:11.243462    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] serial8250: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a U6_16550A
I0724 17:42:11.243466    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] serial8250: ttyS2 at I/O 0x3e8 (irq = 4, base_baud = 115200) is a U6_16550A
I0724 17:42:11.243481    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] brd: module loaded
I0724 17:42:11.243485    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] loop: module loaded
I0724 17:42:11.243490    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] rtc_cmos rtc_cmos: rtc core: registered rtc_cmos as rtc0
I0724 17:42:11.243494    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] rtc_cmos rtc_cmos: only 24-hr supported
I0724 17:42:11.243498    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Initializing XFRM netlink socket
I0724 17:42:11.243502    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] NET: Registered protocol family 10
I0724 17:42:11.243507    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] NET: Registered protocol family 17
I0724 17:42:11.243511    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Bridge firewalling registered
I0724 17:42:11.243515    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] 9pnet: Installing 9P2000 support
I0724 17:42:11.243520    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] registered taskstats version 1
I0724 17:42:11.243525    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] hctosys: unable to open rtc device (rtc0)
I0724 17:42:11.243529    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Freeing unused kernel memory: 992K (ffffffff81899000 - ffffffff81991000)
I0724 17:42:11.243533    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Write protecting the kernel read-only data: 8192k
I0724 17:42:11.243538    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Freeing unused kernel memory: 988K (ffff880001509000 - ffff880001600000)
I0724 17:42:11.243542    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Freeing unused kernel memory: 520K (ffff88000177e000 - ffff880001800000)
I0724 17:42:11.243547    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL]
I0724 17:42:11.243551    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] <**********************************************************************
I0724 17:42:11.243555    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] < Hyperstart Version: 0.8.1, commit: v0.8.1-2-gfaef420
I0724 17:42:11.243559    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] <**********************************************************************
I0724 17:42:11.243564    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] uptime 0.29 0.01
I0724 17:42:11.243568    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL]
I0724 17:42:11.243573    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] create directory /dev/pts
I0724 17:42:11.243577    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] probe /sys/bus/pci/devices//0000:00:00.0
I0724 17:42:11.243581    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] found vendor: 1af4 ID: 9
I0724 17:42:11.243585    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] probe /sys/bus/pci/devices//0000:00:02.0
I0724 17:42:11.243589    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] found vendor: 1af4 ID: 1
I0724 17:42:11.243595    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] random: fast init done
I0724 17:42:11.243599    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] probe /sys/bus/pci/devices//0000:00:01.0
I0724 17:42:11.243603    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] found vendor: 1af4 ID: 9
I0724 17:42:11.243607    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] cannot find vsock device
I0724 17:42:11.243612    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] fail to setup hyper control serial port
I0724 17:42:11.243616    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00000000
I0724 17:42:11.243620    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL]
I0724 17:42:11.243624    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] CPU: 0 PID: 1 Comm: init Not tainted 4.9.23-hyper #1
I0724 17:42:11.243629    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL]  0000000000000000 ffffffff812b1000 ffff8800068af300 ffffc9000003beb8
I0724 17:42:11.243659    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL]  ffffffff810dadfd 0000000000000010 ffffc9000003bec8 ffffc9000003be68
I0724 17:42:11.243666    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL]  ffff8800076176a0 0000000000000000 ffff8800068bb9d0 0000000000000000
I0724 17:42:11.243670    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Call Trace:
I0724 17:42:11.243675    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL]  [<ffffffff812b1000>] ? dump_stack+0x5c/0x7c
I0724 17:42:11.243679    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL]  [<ffffffff810dadfd>] ? panic+0xd6/0x208
I0724 17:42:11.243685    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL]  [<ffffffff81056b96>] ? do_exit+0xa66/0xa70
I0724 17:42:11.243689    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL]  [<ffffffff81056c04>] ? do_group_exit+0x34/0xa0
I0724 17:42:11.243693    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL]  [<ffffffff81056c7b>] ? SyS_exit_group+0xb/0x10
I0724 17:42:11.243697    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL]  [<ffffffff8150133b>] ? entry_SYSCALL_64_fastpath+0x1e/0xad
I0724 17:42:11.243702    2163 vm_console.go:96] SB[vm-mgXyNufJtB] [CNL] Kernel Offset: disabled
I0724 17:42:19.966256    2163 lkvm.go:325] read failed: read /dev/pts/14: input/output error
I0724 17:42:19.966304    2163 lkvm.go:331] REACH the END of io copy
I0724 17:42:19.966256    2163 lkvm.go:325] read failed: read /dev/pts/13: input/output error
I0724 17:42:19.966339    2163 lkvm.go:331] REACH the END of io copy
I0724 17:42:19.966272    2163 lkvm.go:325] read failed: read /dev/pts/12: input/output error
I0724 17:42:19.966347    2163 lkvm.go:331] REACH the END of io copy
I0724 17:42:19.966283    2163 lkvm.go:251] read lkvm output failed: read /dev/ptmx: input/output error
I0724 17:42:19.966372    2163 lkvm.go:277] close socket to pty
I0724 17:42:19.966394    2163 vm_console.go:113] Input byte chan closed, close the output string chan
I0724 17:42:19.966406    2163 vm_console.go:98] SB[vm-mgXyNufJtB] console output end
E0724 17:43:11.221511    2163 hypervisor.go:37] SB[vm-mgXyNufJtB] watch hyperstart timeout
I0724 17:43:11.222546    2163 json.go:93] SB[vm-mgXyNufJtB] close jsonBasedHyperstart
E0724 17:43:11.222596    2163 json.go:601] SB[vm-mgXyNufJtB] get hyperstart API version error: hyperstart closed
W0724 17:43:11.222619    2163 hypervisor.go:47] SB[vm-mgXyNufJtB] keep-alive test end with error: hyperstart closed
E0724 17:43:11.222651    2163 vm_states.go:226] SB[vm-mgXyNufJtB] Start POD failed: hyperstart closed
I0724 17:43:11.222695    2163 vm_states.go:249] SB[vm-mgXyNufJtB] poweroff vm based on command: vm.Kill()
I0724 17:43:11.222713    2163 lkvm.go:380] SB[vm-mgXyNufJtB] shutdown
I0724 17:43:11.222758    2163 hypervisor.go:23] SB[vm-mgXyNufJtB] main event loop got message 13(ERROR_INIT_FAIL)
E0724 17:43:11.222795    2163 vm_states.go:289] SB[vm-mgXyNufJtB] watch hyperstart timeout
E0724 17:43:11.222816    2163 vm_states.go:246] SB[vm-mgXyNufJtB] Shutting down because of an exception: %!(EXTRA string=connection to vm broken)
I0724 17:43:11.222832    2163 vm_states.go:249] SB[vm-mgXyNufJtB] poweroff vm based on command: connection to vm broken
I0724 17:43:11.222847    2163 lkvm.go:380] SB[vm-mgXyNufJtB] shutdown
I0724 17:43:11.226325    2163 json.go:426] SB[vm-mgXyNufJtB] tty chan closed, quit sent goroutine
E0724 17:43:11.226488    2163 json.go:401] read tty data failed
E0724 17:43:11.226539    2163 json.go:458] SB[vm-mgXyNufJtB] tty socket closed, quit the reading goroutine: read unix @->/var/run/hyper/vm-mgXyNufJtB/tty.sock: use of closed network connection
I0724 17:43:11.226780    2163 lkvm.go:321] read end of file
I0724 17:43:11.226841    2163 lkvm.go:331] REACH the END of io copy
I0724 17:43:11.226970    2163 lkvm.go:277] close socket to pty
E0724 17:43:11.239174    2163 hyperpod.go:500] StartPod fail, response: &api.ResultBase{Id:"vm-mgXyNufJtB", Success:false, ResultMessage:"got failed event when wait init message"}
I0724 17:43:11.239244    2163 supervisor.go:231] createHyperPod() returns
I0724 17:43:11.239259    2163 supervisor.go:155] reap container 7a0a7306dfa16e77eeda2ec3ae9ed5264a8cf252323d254bbb98d25b4946f779 processId init
I0724 17:43:11.240194    2163 context.go:197] SB[vm-mgXyNufJtB] VmContext Close()
I0724 17:43:11.240267    2163 hypervisor.go:31] SB[vm-mgXyNufJtB] main event loop exiting

What am I doing wrong?

SergeyOvsienko commented 6 years ago 
sudo lsmod |grep -i vhost_vsock
vhost_vsock            16384  0
vmw_vsock_virtio_transport_common    28672  1 vhost_vsock
vsock                  36864  2 vhost_vsock,vmw_vsock_virtio_transport_common
vhost                  45056  1 vhost_vsock
sergey@sergey-All-Series:~$ uname -a
Linux sergey-All-Series 4.8.0-58-generic #63~16.04.1-Ubuntu SMP Mon Jun 26 18:08:51 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
SergeyOvsienko commented 6 years ago

I am update hyperstart

hyperstart  0.8.1
    prefix:     /usr/local

    with-vbox:  no
    with-aarch64:   no
    with-kmodules:  yes

    vsock-support:  yes

    compiler:          gcc
    cflags:            -g -O2
    suid cflags:
    ldflags:
    suid ldflags:
    systemd unit path: /lib/systemd/system

Work fine. I think it's worth adding to the documentation about kernel 4.8+ and hyperstart 0.8.1

SergeyOvsienko commented 6 years ago

After destroy vm

root      5058  0.0  0.0  60216  3940 pts/10   S+   18:09   0:00  |                   \_ sudo ./runv --debug --driver kvmtool --kernel /opt/hyperstart/build/kernel --initrd /opt/hyperstart/build/hyper-i
root      5059  0.6  0.2 1115344 33508 pts/10  Sl+  18:09   0:12  |                       \_ ./runv --debug --driver kvmtool --kernel /opt/hyperstart/build/kernel --initrd /opt/hyperstart/build/hyper-in
root      5314  0.0  0.0      0     0 pts/10   Z+   18:10   0:00  |                           \_ [runv] <defunct>
root      5687  0.0  0.0      0     0 pts/10   Z+   18:11   0:00  |                           \_ [runv] <defunct>

Growing number of zombies