search

hyperhq / hyperd

HyperContainer Daemon
http://www.hypercontainer.io
Apache License 2.0
1.98k stars 194 forks source link

Build after https://github.com/hyperhq/hyperd/commit/4f070705f426ff1445d5d1131d4bc0521d449730 not working #292

Closed zenny closed 8 years ago

zenny commented 8 years ago

Hi, built after https://github.com/hyperhq/hyperd/commit/4f070705f426ff1445d5d1131d4bc0521d449730, but when trying to start a container, it gives the following error:

# hyperctl list
POD ID              POD Name                  VM name             Status
pod-qRllmlNPJP      alpine-caddy-9113191768                       pending
# hyperctl start pod-qRllmlNPJP
hyperctl ERROR: Error from daemon's response: VM vm-hOQaTeOHnX start failed with code 7: Start POD failed

Error log reads as follows:

# cat /var/log/hyper/hyperd.ERROR 
Log file created at: 2016/04/17 03:37:13
Running on machine: MACHINE-GA-970A-D3
Binary: Built with gc go1.6 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
E0417 03:37:13.805754   25883 pod.go:309] nosuchimagetag: No such image: xxtesaxx/idempiere:latest
E0417 03:37:13.807945   25883 server.go:170] Handler for POST /v0.5.0/pod/create returned error: No such image: xxtesaxx/idempiere:latest
E0417 03:38:20.872227   25883 vm_states.go:358] Shutting down because of an exception: Start POD failed
E0417 03:38:20.872250   25883 vm_states.go:635] Start POD failed
E0417 03:38:20.872306   25883 run.go:88] VM vm-WquYgVbuud start failed with code 7: Start POD failed
E0417 03:38:20.872333   25883 server.go:170] Handler for POST /v1.17/pod/start returned error: VM vm-WquYgVbuud start failed with code 7: Start POD failed
E0417 03:38:20.889684   25883 init_comm.go:75] read init data failed
E0417 03:38:20.889753   25883 tty.go:103] read tty data failed
E0417 03:39:47.908284   25883 vm_states.go:358] Shutting down because of an exception: Start POD failed
E0417 03:39:47.908356   25883 vm_states.go:635] Start POD failed
E0417 03:39:47.908523   25883 run.go:88] VM vm-cqGQXkwCXL start failed with code 7: Start POD failed
E0417 03:39:47.908561   25883 server.go:170] Handler for POST /v0.5.0/pod/start returned error: VM vm-cqGQXkwCXL start failed with code 7: Start POD failed
E0417 03:39:47.920351   25883 init_comm.go:75] read init data failed
E0417 03:39:47.920467   25883 tty.go:103] read tty data failed
E0417 03:51:05.096606   25883 pod.go:309] nosuchimagetag: No such image: zzrot/alpine-caddy:latest
E0417 03:51:05.097047   25883 server.go:170] Handler for POST /v0.5.0/pod/create returned error: No such image: zzrot/alpine-caddy:latest
E0417 03:51:20.501452   25883 vm_states.go:358] Shutting down because of an exception: Start POD failed
E0417 03:51:20.501520   25883 vm_states.go:635] Start POD failed
E0417 03:51:20.501700   25883 run.go:88] VM vm-YDSQHKoJCO start failed with code 7: Start POD failed
E0417 03:51:20.501833   25883 server.go:170] Handler for POST /v1.17/pod/start returned error: VM vm-YDSQHKoJCO start failed with code 7: Start POD failed
E0417 03:51:20.521791   25883 init_comm.go:75] read init data failed
E0417 03:51:20.521874   25883 tty.go:103] read tty data failed
E0417 03:51:54.676458   25883 vm_states.go:358] Shutting down because of an exception: Start POD failed
E0417 03:51:54.676523   25883 vm_states.go:635] Start POD failed
E0417 03:51:54.676727   25883 run.go:88] VM vm-hOQaTeOHnX start failed with code 7: Start POD failed
E0417 03:51:54.676767   25883 server.go:170] Handler for POST /v0.5.0/pod/start returned error: VM vm-hOQaTeOHnX start failed with code 7: Start POD failed
E0417 03:51:54.693691   25883 init_comm.go:75] read init data failed
E0417 03:51:54.693750   25883 tty.go:103] read tty data failed
gnawux commented 8 years ago

PR #282 is part of the fix for hyper build, before #282, the build is broken by previous commits (move to docker 1.10 new image id mechanism compatible).

And there are still problem to fix as I written in the comments. Before #289 close, the build won't work.

zenny commented 8 years ago

https://github.com/hyperhq/hyperd/issues/289 was closed, yet the problem persists as stated in https://github.com/hyperhq/hyperstart/pull/76#issuecomment-211780394

Log:


zenny@HYPER-MACHINE:[/mnt/tank/HYPERBUILD/hyperhq/src/github.com/hyperhq/hyperd]:$ sudo ./hyperctl list
[sudo] password for zenny: 
POD ID              POD Name            VM name             Status
pod-nGrWzvoRNi      alpine-0989527933                       pending

zenny@HYPER-MACHINE:[/mnt/tank/HYPERBUILD/hyperhq/src/github.com/hyperhq/hyperd]:$ sudo ./hyperctl start pod-nGrWzvoRNi
./hyperctl ERROR: Error from daemon's response: VM vm-bbuWmTciLc start failed with code 7: Start POD failed

zenny@HYPER-MACHINE:[/mnt/tank/HYPERBUILD/hyperhq/src/github.com/hyperhq/hyperd]:$ cat /var/log/hyper/hyperd.ERROR 
Log file created at: 2016/04/19 09:13:10
Running on machine: HYPER-MACHINE
Binary: Built with gc go1.6 for linux/amd64
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
E0419 09:13:10.126183   12946 vm_states.go:358] Shutting down because of an exception: Start POD failed
E0419 09:13:10.129314   12946 vm_states.go:635] Start POD failed
E0419 09:13:10.129363   12946 run.go:88] VM vm-bbuWmTciLc start failed with code 7: Start POD failed
E0419 09:13:10.129372   12946 server.go:170] Handler for POST /v0.5.0/pod/start returned error: VM vm-bbuWmTciLc start failed with code 7: Start POD failed
E0419 09:13:10.141460   12946 init_comm.go:75] read init data failed
E0419 09:13:10.141544   12946 tty.go:103] read tty data failed

zenny@HYPER-MACHINE:[/mnt/tank/HYPERBUILD/hyperhq/src/github.com/hyperhq/hyperd]:$ sudo ./hyperctl run -d busybox
[sudo] password for zenny: 
Using default tag: latest
latest: Pulling from library/busybox
385e281300cc: Pull complete 
a3ed95caeb02: Pull complete 
Digest: sha256:4a887a2326ec9e0fa90cce7b4764b0e627b5d6afcb81a3f73c85dc29cea00048
Status: Downloaded newer image for busybox:latest
POD id is pod-OZyNoqIJiX
./hyperctl ERROR: Error from daemon's response: VM vm-TcTOqfpdJk start failed with code 7: Start POD failed

zenny@HYPER-MACHINE:[/mnt/tank/HYPERBUILD/hyperhq/src/github.com/hyperhq/hyperd]:$ sudo ./hyperd --nondaemon --v=3 --config="/etc/hyper/config"
I0419 09:12:20.570689   12946 hyperd.go:108] The config file is /etc/hyper/config
I0419 09:12:20.648048   12946 daemon.go:137] The config: kernel=/mnt/tank/HYPER/kernel, initrd=/mnt/tank/HYPER/hyper-initrd.img
I0419 09:12:20.648120   12946 daemon.go:139] The config: vbox image=
I0419 09:12:20.648157   12946 daemon.go:142] The config: bridge=, ip=
I0419 09:12:20.648194   12946 daemon.go:145] The config: bios=/mnt/tank/HYPER/bios-qboot.bin, cbfs=/mnt/tank/HYPER/cbfs-qboot.rom
DEBU[0000] Using default logging driver none            
INFO[0000] [graphdriver] using prior tank driver "aufs" 
DEBU[0000] Using graph driver aufs                      
INFO[0001] Graph migration to content-addressability took 0.07 seconds 
DEBU[0001] Option DefaultDriver: bridge                 
DEBU[0001] Option DefaultNetwork: bridge                
WARN[0001] Running modprobe bridge br_netfilter failed with message: modprobe: WARNING: Module br_netfilter not found.
insmod /lib/modules/3.13.0-85-lowlatency/kernel/net/llc/llc.ko 
insmod /lib/modules/3.13.0-85-lowlatency/kernel/net/802/stp.ko 
insmod /lib/modules/3.13.0-85-lowlatency/kernel/net/bridge/bridge.ko 
, error: exit status 1 
INFO[0001] Firewalld running: false                     
DEBU[0001] Registering ipam driver: "default"           
DEBU[0001] Cleaning up old shm/mqueue mounts: start.    
DEBU[0001] Cleaning up old shm/mqueue mounts: done.     
INFO[0001] Loading containers: start.                   
DEBU[0001] Loaded container 16fedca36031c3778996e98f4978ac65e44ed79b1b68ad01cbcec265ae443e5d 
DEBU[0001] Loaded container 7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea 
DEBU[0001] Loaded container f14de5f26c178455eae3bedc68153f4e3292d83a42455e6692071fa4120b7d34 
INFO[0001] Loading containers: done.                    
I0419 09:12:21.839083   12946 server.go:70] Server created for HTTP on unix (/var/run/hyper.sock)
Qemu Driver Loaded
I0419 09:12:21.839193   12946 hyperd.go:195] The hypervisor's driver is 
I0419 09:12:21.839382   12946 network_linux.go:245] create bridge hyper0, ip 192.168.123.0/24
I0419 09:12:21.839886   12946 network_linux.go:366] Allocate IP Address 192.168.123.1 for bridge hyper0
I0419 09:12:21.839926   12946 network_linux.go:517] ifaddmsg length 8
I0419 09:12:21.843935   12946 iptables_linux.go:140] /sbin/iptables, [--wait -t nat -C POSTROUTING -s 192.168.123.1/24 ! -o hyper0 -j MASQUERADE]
I0419 09:12:21.915421   12946 iptables_linux.go:140] /sbin/iptables, [--wait -t nat -I POSTROUTING -s 192.168.123.1/24 ! -o hyper0 -j MASQUERADE]
I0419 09:12:21.922253   12946 iptables_linux.go:140] /sbin/iptables, [--wait -N HYPER]
I0419 09:12:21.927825   12946 iptables_linux.go:140] /sbin/iptables, [--wait -t filter -C FORWARD -o hyper0 -j HYPER]
I0419 09:12:21.948106   12946 iptables_linux.go:140] /sbin/iptables, [--wait -I FORWARD -o hyper0 -j HYPER]
I0419 09:12:21.952352   12946 iptables_linux.go:140] /sbin/iptables, [--wait -t filter -C FORWARD -i hyper0 -j ACCEPT]
I0419 09:12:21.959771   12946 iptables_linux.go:140] /sbin/iptables, [--wait -I FORWARD -i hyper0 -j ACCEPT]
I0419 09:12:21.963443   12946 iptables_linux.go:140] /sbin/iptables, [--wait -t filter -C FORWARD -o hyper0 -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT]
I0419 09:12:21.983308   12946 iptables_linux.go:140] /sbin/iptables, [--wait -I FORWARD -o hyper0 -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT]
I0419 09:12:21.992518   12946 network_linux.go:174] modprobe br_netfilter failed modprobe br_netfilter failed
I0419 09:12:21.992633   12946 iptables_linux.go:140] /sbin/iptables, [--wait -t nat -N HYPER]
I0419 09:12:21.996187   12946 iptables_linux.go:140] /sbin/iptables, [--wait -t nat -C OUTPUT -m addrtype --dst-type LOCAL ! -d 127.0.0.1/8 -j HYPER]
I0419 09:12:22.017007   12946 iptables_linux.go:140] /sbin/iptables, [--wait -t nat -I OUTPUT -m addrtype --dst-type LOCAL ! -d 127.0.0.1/8 -j HYPER]
I0419 09:12:22.021562   12946 iptables_linux.go:140] /sbin/iptables, [--wait -t nat -C PREROUTING -m addrtype --dst-type LOCAL -j HYPER]
I0419 09:12:22.028862   12946 iptables_linux.go:140] /sbin/iptables, [--wait -t nat -I PREROUTING -m addrtype --dst-type LOCAL -j HYPER]
I0419 09:12:22.048088   12946 daemondb.go:220] got key from leveldb pod-container-pod-hNxHwMrDbT
I0419 09:12:22.048183   12946 daemondb.go:220] got key from leveldb pod-container-pod-nGrWzvoRNi
I0419 09:12:22.048235   12946 daemondb.go:220] got key from leveldb pod-container-pod-qRllmlNPJP
I0419 09:12:22.048287   12946 daemondb.go:220] got key from leveldb pod-pod-nGrWzvoRNi
I0419 09:12:22.048378   12946 daemon.go:78] reloading pod pod-nGrWzvoRNi with args {"id":"alpine-0989527933","hostname":"","containers":[{"name":"alpine-0989527933","image":"alpine","command":["/bin/sh"],"workdir":"/","entrypoint":[],"ports":[],"envs":[],"volumes":[],"files":[],"restartPolicy":"never"}],"resource":{"vcpu":1,"memory":512},"files":[],"volumes":[],"labels":{},"log":{"type":"","config":{}},"tty":true,"type":"","RestartPolicy":""}
I0419 09:12:22.048671   12946 run.go:45] podArgs: {"id":"alpine-0989527933","hostname":"","containers":[{"name":"alpine-0989527933","image":"alpine","command":["/bin/sh"],"workdir":"/","entrypoint":[],"ports":[],"envs":[],"volumes":[],"files":[],"restartPolicy":"never"}],"resource":{"vcpu":1,"memory":512},"files":[],"volumes":[],"labels":{},"log":{"type":"","config":{}},"tty":true,"type":"","RestartPolicy":""}
I0419 09:12:22.049467   12946 daemondb.go:82] try get container list for pod pod-nGrWzvoRNi
I0419 09:12:22.049513   12946 pod.go:229] loaded containers for pod pod-nGrWzvoRNi: [7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea]
I0419 09:12:22.049581   12946 pod.go:248] Found exist container alpine-0989527933 (7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea), pod: pod-nGrWzvoRNi
I0419 09:12:22.049595   12946 pod.go:281] do not need to create container alpine-0989527933 of pod pod-nGrWzvoRNi[0]
I0419 09:12:22.049609   12946 pod.go:356] container name alpine-0989527933, image alpine
I0419 09:12:22.051137   12946 pod.go:373] container info config &{7383484ceb06   false false false map[]  false false false [] 0xc820fc9360 false alpine map[]  <nil> false  [] map[] }, Cmd [/bin/sh], Args []
I0419 09:12:22.051401   12946 pod.go:396] Container Info is 
&{7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea 7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea     [] [/bin/sh] map[] false}
I0419 09:12:22.051677   12946 daemondb.go:91] try set container list for pod pod-nGrWzvoRNi: [7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea]
I0419 09:12:22.051983   12946 daemon.go:96] no existing VM for pod pod-nGrWzvoRNi: leveldb: not found
I0419 09:12:22.052004   12946 daemon.go:106] 1 pod have been loaded
I0419 09:12:22.052020   12946 daemon.go:108] container in pod pod-nGrWzvoRNi status: [0xc82112e000]
I0419 09:12:22.052034   12946 daemon.go:109] container in pod pod-nGrWzvoRNi spec: [{alpine-0989527933 alpine [] / [] true map[] [] [] [{/etc/hosts etchosts-volume false}] [{/etc/resolv.conf pod-nGrWzvoRNi-resolvconf 0644  }] never}]
I0419 09:12:22.052639   12946 hyperd.go:234] Hyper daemon: 0.5.0 0
I0419 09:12:22.052657   12946 server.go:199] Registering routers
I0419 09:12:22.052772   12946 server.go:204] Registering GET, /container/info
I0419 09:12:22.059500   12946 server.go:204] Registering GET, /container/logs
I0419 09:12:22.059704   12946 server.go:204] Registering GET, /exitcode
I0419 09:12:22.059852   12946 server.go:204] Registering POST, /container/create
I0419 09:12:22.060025   12946 server.go:204] Registering POST, /container/rename
I0419 09:12:22.060185   12946 server.go:204] Registering POST, /container/commit
I0419 09:12:22.060345   12946 server.go:204] Registering POST, /container/kill
I0419 09:12:22.060503   12946 server.go:204] Registering POST, /exec
I0419 09:12:22.060637   12946 server.go:204] Registering POST, /attach
I0419 09:12:22.060767   12946 server.go:204] Registering POST, /tty/resize
I0419 09:12:22.060907   12946 server.go:204] Registering GET, /pod/info
I0419 09:12:22.061039   12946 server.go:204] Registering GET, /pod/stats
I0419 09:12:22.061175   12946 server.go:204] Registering GET, /list
I0419 09:12:22.061291   12946 server.go:204] Registering POST, /pod/create
I0419 09:12:22.061421   12946 server.go:204] Registering POST, /pod/labels
I0419 09:12:22.061560   12946 server.go:204] Registering POST, /pod/start
I0419 09:12:22.061703   12946 server.go:204] Registering POST, /pod/stop
I0419 09:12:22.061828   12946 server.go:204] Registering POST, /pod/kill
I0419 09:12:22.061974   12946 server.go:204] Registering POST, /pod/pause
I0419 09:12:22.062112   12946 server.go:204] Registering POST, /pod/unpause
I0419 09:12:22.062670   12946 server.go:204] Registering POST, /vm/create
I0419 09:12:22.062806   12946 server.go:204] Registering DELETE, /pod
I0419 09:12:22.062893   12946 server.go:204] Registering DELETE, /vm
I0419 09:12:22.062976   12946 server.go:204] Registering GET, /service/list
I0419 09:12:22.063089   12946 server.go:204] Registering POST, /service/add
I0419 09:12:22.063198   12946 server.go:204] Registering POST, /service/update
I0419 09:12:22.063316   12946 server.go:204] Registering DELETE, /service
I0419 09:12:22.063415   12946 server.go:204] Registering GET, /images/get
I0419 09:12:22.063521   12946 server.go:204] Registering POST, /image/create
I0419 09:12:22.063642   12946 server.go:204] Registering POST, /image/load
I0419 09:12:22.063747   12946 server.go:204] Registering POST, /image/push
I0419 09:12:22.063871   12946 server.go:204] Registering DELETE, /image
I0419 09:12:22.063967   12946 server.go:204] Registering GET, /_ping
I0419 09:12:22.064058   12946 server.go:204] Registering GET, /info
I0419 09:12:22.064150   12946 server.go:204] Registering GET, /version
I0419 09:12:22.064246   12946 server.go:204] Registering POST, /auth
I0419 09:12:22.064333   12946 server.go:204] Registering POST, /image/build
I0419 09:12:22.064470   12946 server.go:95] API listen on /var/run/hyper.sock
I0419 09:12:47.305783   12946 server.go:152] Calling GET /v0.5.0/list
I0419 09:12:47.305876   12946 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0419 09:13:09.305369   12946 server.go:152] Calling POST /v0.5.0/pod/start
I0419 09:13:09.305455   12946 run.go:78] pod:pod-nGrWzvoRNi, vm:
I0419 09:13:09.305478   12946 pod.go:71] lock pod for operation start
I0419 09:13:09.305490   12946 pod.go:74] successfully lock pod for operation start
I0419 09:13:09.305509   12946 vm.go:120] The config: kernel=/mnt/tank/HYPER/kernel, initrd=/mnt/tank/HYPER/hyper-initrd.img
I0419 09:13:09.305764   12946 pod.go:709] container ID: 7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea, mountId 7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea
I0419 09:13:09.306106   12946 qemu_process.go:63] cmdline arguments: -machine pc-i440fx-2.0,accel=kvm,usb=off -global kvm-pit.lost_tick_policy=discard -cpu host -drive if=pflash,file=/mnt/tank/HYPER/bios-qboot.bin,readonly=on -drive if=pflash,file=/mnt/tank/HYPER/cbfs-qboot.rom,readonly=on -realtime mlock=off -no-user-config -nodefaults -no-hpet -rtc base=utc,driftfix=slew -no-reboot -display none -boot strict=on -m 512 -smp 1 -qmp unix:/var/run/hyper/vm-bbuWmTciLc/qmp.sock,server,nowait -serial unix:/var/run/hyper/vm-bbuWmTciLc/console.sock,server,nowait -device virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x2 -device virtio-scsi-pci,id=scsi0,bus=pci.0,addr=0x3 -chardev socket,id=charch0,path=/var/run/hyper/vm-bbuWmTciLc/hyper.sock,server,nowait -device virtserialport,bus=virtio-serial0.0,nr=1,chardev=charch0,id=channel0,name=sh.hyper.channel.0 -chardev socket,id=charch1,path=/var/run/hyper/vm-bbuWmTciLc/tty.sock,server,nowait -device virtserialport,bus=virtio-serial0.0,nr=2,chardev=charch1,id=channel1,name=sh.hyper.channel.1 -fsdev local,id=virtio9p,path=/var/run/hyper/vm-bbuWmTciLc/share_dir,security_model=none -device virtio-9p-pci,fsdev=virtio9p,mount_tag=share_dir
I0419 09:13:09.309285   12946 qemu_process.go:74] starting daemon with pid: 13079
I0419 09:13:09.346809   12946 qmp_handler.go:167] connected to /var/run/hyper/vm-bbuWmTciLc/qmp.sock
I0419 09:13:09.346916   12946 qmp_handler.go:177] begin qmp init...
I0419 09:13:09.347062   12946 tty.go:157] tty socket connected
I0419 09:13:09.347116   12946 tty.go:100] tty: trying to read 12 bytes
I0419 09:13:09.347251   12946 init_comm.go:109] Wating for init messages...
I0419 09:13:09.347335   12946 init_comm.go:72] trying to read 8 bytes
I0419 09:13:09.387480   12946 init_comm.go:29] connected to /var/run/hyper/vm-bbuWmTciLc/console.sock
I0419 09:13:09.387613   12946 init_comm.go:36] connected /var/run/hyper/vm-bbuWmTciLc/console.sock as telnet mode.
I0419 09:13:09.391193   12946 volumes.go:28] trying to bind dir /mnt/tank/HYPER/hosts/pod-nGrWzvoRNi/hosts to /var/run/hyper/vm-bbuWmTciLc/share_dir/iVfeHKcqnR
I0419 09:13:09.391477   12946 tank.go:77] dir /mnt/tank/HYPER/hosts/pod-nGrWzvoRNi/hosts is bound to iVfeHKcqnR
I0419 09:13:09.391592   12946 pod.go:840] configuring log driver [json-file] for pod-nGrWzvoRNi
I0419 09:13:09.391642   12946 pod.go:859] configure container log to /var/run/hyper/Pods/pod-nGrWzvoRNi/7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea-json.log
I0419 09:13:09.391743   12946 pod.go:865] configured logger for pod-nGrWzvoRNi/7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea (/alpine-0989527933)
I0419 09:13:09.391928   12946 vm.go:180] hyperHandlePodEvent pod pod-nGrWzvoRNi, vm vm-bbuWmTciLc
I0419 09:13:09.391980   12946 hypervisor.go:29] main event loop got message 34(COMMAND_ATTACH)
I0419 09:13:09.392043   12946 vm_states.go:281] attachment log-fqj0xw00 is pending
I0419 09:13:09.392077   12946 hypervisor.go:29] main event loop got message 23(COMMAND_RUN_POD)
I0419 09:13:09.392112   12946 vm_states.go:556] got spec, prepare devices
I0419 09:13:09.392232   12946 context.go:244] #0 Container Info:
I0419 09:13:09.392514   12946 context.go:247] 
{
...|    "Id": "7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea",
...|    "MountId": "7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea",
...|    "Rootfs": "",
...|    "Image": "/7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea/rootfs",
...|    "Fstype": "dir",
...|    "Workdir": "",
...|    "Entrypoint": null,
...|    "Cmd": [
...|        "/bin/sh"
...|    ],
...|    "Envs": {},
...|    "Initialize": false
...|}
I0419 09:13:09.392654   12946 devicemap.go:235] insert volume etchosts-volume to /etc/hosts on 0
I0419 09:13:09.393396   12946 vm_states.go:72] initial vm spec: {
        "hostname": "alpine-0989527933",
        "containers": [
            {
                "id": "7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea",
                "rootfs": "",
                "image": "/7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea/rootfs",
                "fsmap": [
                    {
                        "source": "iVfeHKcqnR",
                        "path": "/etc/hosts",
                        "readOnly": false,
                        "dockerVolume": false
                    }
                ],
                "process": {
                    "terminal": true,
                    "stdio": 1,
                    "args": [
                        "/bin/sh"
                    ],
                    "workdir": "/"
                },
                "restartPolicy": "never",
                "initialize": false
            }
        ],
        "shareDir": "share_dir"
    }
I0419 09:13:09.393519   12946 context.go:176] found container 7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea at 0
I0419 09:13:09.393600   12946 vm_states.go:80] attach pending client log-fqj0xw00 for 7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea
I0419 09:13:09.393656   12946 vm_states.go:304] Connecting tty for 7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea on session 1
I0419 09:13:09.393735   12946 context.go:212] VM vm-bbuWmTciLc: state change from INIT to 'STARTING'
I0419 09:13:09.397881   12946 hypervisor.go:29] main event loop got message 13(EVENT_INTERFACE_ADD)
I0419 09:13:09.397980   12946 qmp_wrapper.go:90] send net to qemu at 20
I0419 09:13:09.398127   12946 qmp_handler.go:370] got new session during initializing
I0419 09:13:09.647189   12946 qmp_handler.go:186] got qmp welcome, now sending command qmp_capabilities
I0419 09:13:09.647406   12946 qmp_handler.go:201] waiting for response
I0419 09:13:09.647720   12946 qmp_handler.go:103] got a message {"return": {}}
I0419 09:13:09.647855   12946 qmp_handler.go:210] got for response
I0419 09:13:09.647905   12946 qmp_handler.go:213] QMP connection initialized
I0419 09:13:09.647982   12946 qmp_handler.go:346] QMP initialzed, go into main QMP loop
I0419 09:13:09.648095   12946 qmp_handler.go:137] Begin receive QMP message
I0419 09:13:09.648114   12946 qmp_handler.go:225] Begin process command session
I0419 09:13:09.648223   12946 qmp_handler.go:238] send cmd with scm (24 bytes) (1) {"execute":"getfd","arguments":{"fdname":"fdeth0"}}
I0419 09:13:09.649272   12946 qmp_handler.go:103] got a message {"return": {}}
I0419 09:13:09.649679   12946 qmp_handler.go:243] sending command (1) {"execute":"netdev_add","arguments":{"fd":"fdeth0","id":"eth0","type":"tap"}}
I0419 09:13:09.650757   12946 qmp_handler.go:103] got a message {"return": {}}
I0419 09:13:09.651080   12946 qmp_handler.go:243] sending command (1) {"execute":"device_add","arguments":{"addr":"0x5","bus":"pci.0","driver":"virtio-net-pci","id":"eth0","mac":"52:54:29:43:5a:30","netdev":"eth0"}}
I0419 09:13:09.677339   12946 qmp_handler.go:103] got a message {"return": {}}
I0419 09:13:09.677586   12946 qmp_handler.go:302] session finished, buffer size 1
I0419 09:13:09.677644   12946 qmp_handler.go:305] success 
I0419 09:13:09.677696   12946 hypervisor.go:29] main event loop got message 15(EVENT_INTERFACE_INSERTED)
I0419 09:13:09.677773   12946 vm_states.go:585] device ready, could run pod.
I0419 09:13:09.752428   12946 init_comm.go:44] [console] Initializing cgroup subsys cpu
I0419 09:13:09.753747   12946 init_comm.go:44] [console] Linux version 4.4.0-hyper+ (laijs@ubox) (gcc version 5.2.1 20151010 (Ubuntu 5.2.1-22ubuntu2) ) #0 SMP Mon Jan 25 01:10:46 CST 2016
I0419 09:13:09.754172   12946 init_comm.go:44] [console] Command line: console=ttyS0 panic=1 no_timer_check
I0419 09:13:09.754270   12946 init_comm.go:44] [console] 
I0419 09:13:09.754524   12946 init_comm.go:44] [console] x86/fpu: Legacy x87 FPU detected.
I0419 09:13:09.754808   12946 init_comm.go:44] [console] x86/fpu: Using 'lazy' FPU context switches.
I0419 09:13:09.755087   12946 init_comm.go:44] [console] e820: BIOS-provided physical RAM map:
I0419 09:13:09.755607   12946 init_comm.go:44] [console] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
I0419 09:13:09.756092   12946 init_comm.go:44] [console] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
I0419 09:13:09.756615   12946 init_comm.go:44] [console] BIOS-e820: [mem 0x00000000000d0000-0x00000000000effff] ACPI NVS
I0419 09:13:09.757139   12946 init_comm.go:44] [console] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
I0419 09:13:09.757650   12946 init_comm.go:44] [console] BIOS-e820: [mem 0x0000000000100000-0x000000001fffffff] usable
I0419 09:13:09.758164   12946 init_comm.go:44] [console] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved
I0419 09:13:09.758497   12946 init_comm.go:44] [console] NX (Execute Disable) protection: active
I0419 09:13:09.758739   12946 init_comm.go:44] [console] DMI not present or invalid.
I0419 09:13:09.758967   12946 init_comm.go:44] [console] Hypervisor detected: KVM
I0419 09:13:09.759397   12946 init_comm.go:44] [console] e820: last_pfn = 0x20000 max_arch_pfn = 0x400000000
I0419 09:13:09.759897   12946 init_comm.go:44] [console] x86/PAT: Configuration [0-7]: WB  WC  UC- UC  WB  WC  UC- WT  
I0419 09:13:09.760013   12946 init_comm.go:44] [console] MTRR: Disabled
I0419 09:13:09.760399   12946 init_comm.go:44] [console] CPU MTRRs all blank - virtualized system.
I0419 09:13:09.760714   12946 init_comm.go:44] [console] Using GB pages for direct mapping
I0419 09:13:09.761042   12946 init_comm.go:44] [console] RAMDISK: [mem 0x1ff10000-0x1fffffff]
I0419 09:13:09.761460   12946 init_comm.go:44] [console] ACPI: Early table checksum verification disabled
I0419 09:13:09.761917   12946 init_comm.go:44] [console] ACPI: RSDP 0x00000000000F2960 000014 (v00 BOCHS )
I0419 09:13:09.762593   12946 init_comm.go:44] [console] ACPI: RSDT 0x00000000000EFB95 000034 (v01 BOCHS  BXPCRSDT 00000001 BXPC 00000001)
I0419 09:13:09.763312   12946 init_comm.go:44] [console] ACPI: FACP 0x00000000000EF1C0 000074 (v01 BOCHS  BXPCFACP 00000001 BXPC 00000001)
I0419 09:13:09.764010   12946 init_comm.go:44] [console] ACPI: DSDT 0x00000000000EE040 001180 (v01 BOCHS  BXPCDSDT 00000001 BXPC 00000001)
I0419 09:13:09.764303   12946 init_comm.go:44] [console] ACPI: FACS 0x00000000000EE000 000040
I0419 09:13:09.765052   12946 init_comm.go:44] [console] ACPI: SSDT 0x00000000000EF234 0008E9 (v01 BOCHS  BXPCSSDT 00000001 BXPC 00000001)
I0419 09:13:09.765777   12946 init_comm.go:44] [console] ACPI: APIC 0x00000000000EFB1D 000078 (v01 BOCHS  BXPCAPIC 00000001 BXPC 00000001)
I0419 09:13:09.766416   12946 init_comm.go:44] [console] ACPI: RSDT 0x00000000000EFB95 000034 (v01 BOCHS  BXPCRSDT 00000001 BXPC 00000001)
I0419 09:13:09.766678   12946 init_comm.go:44] [console] No NUMA configuration found
I0419 09:13:09.767229   12946 init_comm.go:44] [console] Faking a node at [mem 0x0000000000000000-0x000000001fffffff]
I0419 09:13:09.767683   12946 init_comm.go:44] [console] NODE_DATA(0) allocated [mem 0x1fefe000-0x1ff0ffff]
I0419 09:13:09.768027   12946 init_comm.go:44] [console] kvm-clock: Using msrs 4b564d01 and 4b564d00
I0419 09:13:09.768497   12946 init_comm.go:44] [console] kvm-clock: cpu 0, msr 0:1fefd001, primary cpu clock
I0419 09:13:09.769454   12946 init_comm.go:44] [console] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
I0419 09:13:09.769581   12946 init_comm.go:44] [console] Zone ranges:
I0419 09:13:09.770082   12946 init_comm.go:44] [console]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
I0419 09:13:09.770589   12946 init_comm.go:44] [console]   DMA32    [mem 0x0000000001000000-0x000000001fffffff]
I0419 09:13:09.770767   12946 init_comm.go:44] [console]   Normal   empty
I0419 09:13:09.771070   12946 init_comm.go:44] [console] Movable zone start for each node
I0419 09:13:09.771323   12946 init_comm.go:44] [console] Early memory node ranges
I0419 09:13:09.771850   12946 init_comm.go:44] [console]   node   0: [mem 0x0000000000001000-0x000000000009efff]
I0419 09:13:09.772369   12946 init_comm.go:44] [console]   node   0: [mem 0x0000000000100000-0x000000001fffffff]
I0419 09:13:09.772986   12946 init_comm.go:44] [console] Initmem setup node 0 [mem 0x0000000000001000-0x000000001fffffff]
I0419 09:13:09.773272   12946 init_comm.go:44] [console] ACPI: PM-Timer IO Port: 0x608
I0419 09:13:09.773742   12946 init_comm.go:44] [console] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
I0419 09:13:09.774307   12946 init_comm.go:44] [console] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
I0419 09:13:09.774843   12946 init_comm.go:44] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
I0419 09:13:09.775397   12946 init_comm.go:44] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
I0419 09:13:09.775958   12946 init_comm.go:44] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
I0419 09:13:09.776521   12946 init_comm.go:44] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
I0419 09:13:09.777099   12946 init_comm.go:44] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
I0419 09:13:09.777571   12946 init_comm.go:44] [console] Using ACPI (MADT) for SMP configuration information
I0419 09:13:09.777951   12946 init_comm.go:44] [console] smpboot: Allowing 1 CPUs, 0 hotplug CPUs
I0419 09:13:09.778469   12946 init_comm.go:44] [console] e820: [mem 0x20000000-0xfeffbfff] available for PCI devices
I0419 09:13:09.778834   12946 init_comm.go:44] [console] Booting paravirtualized kernel on KVM
I0419 09:13:09.779767   12946 init_comm.go:44] [console] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
I0419 09:13:09.780389   12946 init_comm.go:44] [console] setup_percpu: NR_CPUS:8 nr_cpumask_bits:8 nr_cpu_ids:1 nr_node_ids:1
I0419 09:13:09.781082   12946 init_comm.go:44] [console] PERCPU: Embedded 31 pages/cpu @ffff88001fc00000 s89560 r8192 d29224 u2097152
I0419 09:13:09.781362   12946 init_comm.go:44] [console] KVM setup async PF for cpu 0
I0419 09:13:09.781692   12946 init_comm.go:44] [console] kvm-stealtime: cpu 0, msr 1fc0d480
I0419 09:13:09.782362   12946 init_comm.go:44] [console] Built 1 zonelists in Node order, mobility grouping on.  Total pages: 129161
I0419 09:13:09.782571   12946 init_comm.go:44] [console] Policy zone: DMA32
I0419 09:13:09.783106   12946 init_comm.go:44] [console] Kernel command line: console=ttyS0 panic=1 no_timer_check
I0419 09:13:09.783135   12946 init_comm.go:44] [console] 
I0419 09:13:09.783603   12946 init_comm.go:44] [console] PID hash table entries: 2048 (order: 2, 16384 bytes)
I0419 09:13:09.784816   12946 init_comm.go:44] [console] Memory: 507628K/523896K available (4225K kernel code, 452K rwdata, 1280K rodata, 860K init, 752K bss, 16268K reserved, 0K cma-reserved)
I0419 09:13:09.785127   12946 init_comm.go:44] [console] Hierarchical RCU implementation.
I0419 09:13:09.785551   12946 init_comm.go:44] [console]    Build-time adjustment of leaf fanout to 64.
I0419 09:13:09.786048   12946 init_comm.go:44] [console]    RCU restricting CPUs from NR_CPUS=8 to nr_cpu_ids=1.
I0419 09:13:09.786620   12946 init_comm.go:44] [console] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=1
I0419 09:13:09.786900   12946 init_comm.go:44] [console] NR_IRQS:4352 nr_irqs:256 16
I0419 09:13:09.787247   12946 init_comm.go:44] [console]    Offload RCU callbacks from all CPUs
I0419 09:13:09.787595   12946 init_comm.go:44] [console]    Offload RCU callbacks from CPUs: 0.
I0419 09:13:09.787842   12946 init_comm.go:44] [console] Console: colour *CGA 80x25
I0419 09:13:09.788081   12946 init_comm.go:44] [console] console [ttyS0] enabled
I0419 09:13:09.788451   12946 init_comm.go:44] [console] tsc: Detected 3422.964 MHz processor
I0419 09:13:09.789128   12946 init_comm.go:44] [console] Calibrating delay loop (skipped) preset value.. 6845.92 BogoMIPS (lpj=3422964)
I0419 09:13:09.789463   12946 init_comm.go:44] [console] pid_max: default: 32768 minimum: 301
I0419 09:13:09.789753   12946 init_comm.go:44] [console] ACPI: Core revision 20150930
I0419 09:13:09.791107   12946 init_comm.go:44] [console] ACPI: 2 ACPI AML tables successfully acquired and loaded
I0419 09:13:09.791731   12946 init_comm.go:44] [console] Dentry cache hash table entries: 65536 (order: 7, 524288 bytes)
I0419 09:13:09.792451   12946 init_comm.go:44] [console] Inode-cache hash table entries: 32768 (order: 6, 262144 bytes)
I0419 09:13:09.793043   12946 init_comm.go:44] [console] Mount-cache hash table entries: 1024 (order: 1, 8192 bytes)
I0419 09:13:09.793567   12946 init_comm.go:44] [console] Mountpoint-cache hash table entries: 1024 (order: 1, 8192 bytes)
I0419 09:13:09.794162   12946 init_comm.go:44] [console] Last level iTLB entries: 4KB 512, 2MB 16, 4MB 8
I0419 09:13:09.794685   12946 init_comm.go:44] [console] Last level dTLB entries: 4KB 512, 2MB 128, 4MB 64, 1GB 0
I0419 09:13:09.800677   12946 init_comm.go:44] [console] Freeing SMP alternatives memory: 20K (ffffffff816ac000 - ffffffff816b1000)
I0419 09:13:09.803964   12946 init_comm.go:44] [console] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
I0419 09:13:09.905929   12946 init_comm.go:44] [console] smpboot: CPU0: AMD Phenom(tm) II X4 965 Processor (family: 0x10, model: 0x4, stepping: 0x3)
I0419 09:13:09.906674   12946 init_comm.go:44] [console] Performance Events: Broken PMU hardware detected, using software events only.
I0419 09:13:09.907252   12946 init_comm.go:44] [console] Failed to access perfctr msr (MSR c0010001 is ffffffffffffffff)
I0419 09:13:09.907728   12946 init_comm.go:44] [console] x86: Booted up 1 node, 1 CPUs
I0419 09:13:09.908198   12946 init_comm.go:44] [console] smpboot: Total of 1 processors activated (6845.92 BogoMIPS)
I0419 09:13:09.908583   12946 init_comm.go:44] [console] devtmpfs: initialized
I0419 09:13:09.912846   12946 init_comm.go:44] [console] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
I0419 09:13:09.913277   12946 init_comm.go:44] [console] NET: Registered protocol family 16
I0419 09:13:09.913637   12946 init_comm.go:44] [console] cpuidle: using governor ladder
I0419 09:13:09.913900   12946 init_comm.go:44] [console] cpuidle: using governor menu
I0419 09:13:09.914528   12946 init_comm.go:44] [console] ACPI: bus type PCI registered
I0419 09:13:09.915032   12946 init_comm.go:44] [console] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
I0419 09:13:09.915470   12946 init_comm.go:44] [console] PCI: Using configuration type 1 for base access
I0419 09:13:09.915899   12946 init_comm.go:44] [console] PCI: Using configuration type 1 for extended access
I0419 09:13:09.916760   12946 init_comm.go:44] [console] ACPI: Added _OSI(Module Device)
I0419 09:13:09.917039   12946 init_comm.go:44] [console] ACPI: Added _OSI(Processor Device)
I0419 09:13:09.917353   12946 init_comm.go:44] [console] ACPI: Added _OSI(3.0 _SCP Extensions)
I0419 09:13:09.917797   12946 init_comm.go:44] [console] ACPI: Added _OSI(Processor Aggregator Device)
I0419 09:13:09.919373   12946 init_comm.go:44] [console] ACPI: Interpreter enabled
I0419 09:13:09.919645   12946 init_comm.go:44] [console] ACPI: (supports S0 S5)
I0419 09:13:09.919922   12946 init_comm.go:44] [console] ACPI: Using IOAPIC for interrupt routing
I0419 09:13:09.920747   12946 init_comm.go:44] [console] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
I0419 09:13:09.923656   12946 init_comm.go:44] [console] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
I0419 09:13:09.924330   12946 init_comm.go:44] [console] acpi PNP0A03:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments MSI]
I0419 09:13:09.924884   12946 init_comm.go:44] [console] acpi PNP0A03:00: _OSC failed (AE_NOT_FOUND); disabling ASPM
I0419 09:13:09.925269   12946 init_comm.go:44] [console] acpiphp: Slot [2] registered
I0419 09:13:09.925594   12946 init_comm.go:44] [console] acpiphp: Slot [3] registered
I0419 09:13:09.925796   12946 init_comm.go:44] [console] acpiphp: Slot [4] registered
I0419 09:13:09.926073   12946 init_comm.go:44] [console] acpiphp: Slot [5] registered
I0419 09:13:09.926332   12946 init_comm.go:44] [console] acpiphp: Slot [6] registered
I0419 09:13:09.926626   12946 init_comm.go:44] [console] acpiphp: Slot [7] registered
I0419 09:13:09.926901   12946 init_comm.go:44] [console] acpiphp: Slot [8] registered
I0419 09:13:09.927158   12946 init_comm.go:44] [console] acpiphp: Slot [9] registered
I0419 09:13:09.927439   12946 init_comm.go:44] [console] acpiphp: Slot [10] registered
I0419 09:13:09.927728   12946 init_comm.go:44] [console] acpiphp: Slot [11] registered
I0419 09:13:09.927991   12946 init_comm.go:44] [console] acpiphp: Slot [12] registered
I0419 09:13:09.928284   12946 init_comm.go:44] [console] acpiphp: Slot [13] registered
I0419 09:13:09.928575   12946 init_comm.go:44] [console] acpiphp: Slot [14] registered
I0419 09:13:09.928833   12946 init_comm.go:44] [console] acpiphp: Slot [15] registered
I0419 09:13:09.929134   12946 init_comm.go:44] [console] acpiphp: Slot [16] registered
I0419 09:13:09.929429   12946 init_comm.go:44] [console] acpiphp: Slot [17] registered
I0419 09:13:09.929734   12946 init_comm.go:44] [console] acpiphp: Slot [18] registered
I0419 09:13:09.930026   12946 init_comm.go:44] [console] acpiphp: Slot [19] registered
I0419 09:13:09.930315   12946 init_comm.go:44] [console] acpiphp: Slot [20] registered
I0419 09:13:09.930628   12946 init_comm.go:44] [console] acpiphp: Slot [21] registered
I0419 09:13:09.930925   12946 init_comm.go:44] [console] acpiphp: Slot [22] registered
I0419 09:13:09.931219   12946 init_comm.go:44] [console] acpiphp: Slot [23] registered
I0419 09:13:09.931523   12946 init_comm.go:44] [console] acpiphp: Slot [24] registered
I0419 09:13:09.931826   12946 init_comm.go:44] [console] acpiphp: Slot [25] registered
I0419 09:13:09.932133   12946 init_comm.go:44] [console] acpiphp: Slot [26] registered
I0419 09:13:09.932432   12946 init_comm.go:44] [console] acpiphp: Slot [27] registered
I0419 09:13:09.932732   12946 init_comm.go:44] [console] acpiphp: Slot [28] registered
I0419 09:13:09.933035   12946 init_comm.go:44] [console] acpiphp: Slot [29] registered
I0419 09:13:09.933347   12946 init_comm.go:44] [console] acpiphp: Slot [30] registered
I0419 09:13:09.933655   12946 init_comm.go:44] [console] acpiphp: Slot [31] registered
I0419 09:13:09.933956   12946 init_comm.go:44] [console] PCI host bridge to bus 0000:00
I0419 09:13:09.934527   12946 init_comm.go:44] [console] pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7 window]
I0419 09:13:09.935104   12946 init_comm.go:44] [console] pci_bus 0000:00: root bus resource [io  0x0d00-0xadff window]
I0419 09:13:09.935668   12946 init_comm.go:44] [console] pci_bus 0000:00: root bus resource [io  0xae0f-0xaeff window]
I0419 09:13:09.936222   12946 init_comm.go:44] [console] pci_bus 0000:00: root bus resource [io  0xaf20-0xafdf window]
I0419 09:13:09.936799   12946 init_comm.go:44] [console] pci_bus 0000:00: root bus resource [io  0xafe4-0xffff window]
I0419 09:13:09.937412   12946 init_comm.go:44] [console] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
I0419 09:13:09.938058   12946 init_comm.go:44] [console] pci_bus 0000:00: root bus resource [mem 0x20000000-0xfebfffff window]
I0419 09:13:09.938489   12946 init_comm.go:44] [console] pci_bus 0000:00: root bus resource [bus 00-ff]
I0419 09:13:09.939962   12946 init_comm.go:44] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io  0x01f0-0x01f7]
I0419 09:13:09.940506   12946 init_comm.go:44] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io  0x03f6]
I0419 09:13:09.941124   12946 init_comm.go:44] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io  0x0170-0x0177]
I0419 09:13:09.941678   12946 init_comm.go:44] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io  0x0376]
I0419 09:13:09.942595   12946 init_comm.go:44] [console] pci 0000:00:01.3: quirk: [io  0x0600-0x063f] claimed by PIIX4 ACPI
I0419 09:13:09.943194   12946 init_comm.go:44] [console] pci 0000:00:01.3: quirk: [io  0x0700-0x070f] claimed by PIIX4 SMB
I0419 09:13:09.945717   12946 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11)
I0419 09:13:09.946300   12946 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 *10 11)
I0419 09:13:09.946856   12946 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 10 *11)
I0419 09:13:09.947414   12946 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 10 *11)
I0419 09:13:09.947871   12946 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKS] (IRQs *9)
I0419 09:13:09.948552   12946 init_comm.go:44] [console] ACPI: Enabled 16 GPEs in block 00 to 0F
I0419 09:13:09.948797   12946 init_comm.go:44] [console] vgaarb: loaded
I0419 09:13:09.949109   12946 init_comm.go:44] [console] SCSI subsystem initialized
I0419 09:13:09.949445   12946 init_comm.go:44] [console] dmi: Firmware registration failed.
I0419 09:13:09.949756   12946 init_comm.go:44] [console] PCI: Using ACPI for IRQ routing
I0419 09:13:09.950382   12946 init_comm.go:44] [console] clocksource: Switched to clocksource kvm-clock
I0419 09:13:09.950653   12946 init_comm.go:44] [console] pnp: PnP ACPI init
I0419 09:13:09.951273   12946 init_comm.go:44] [console] pnp: PnP ACPI: found 5 devices
I0419 09:13:09.957625   12946 init_comm.go:44] [console] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
I0419 09:13:09.958255   12946 init_comm.go:44] [console] pci 0000:00:05.0: BAR 6: assigned [mem 0x20000000-0x2003ffff pref]
I0419 09:13:09.958803   12946 init_comm.go:44] [console] pci 0000:00:02.0: BAR 1: assigned [mem 0x20040000-0x20040fff]
I0419 09:13:09.959368   12946 init_comm.go:44] [console] pci 0000:00:03.0: BAR 1: assigned [mem 0x20041000-0x20041fff]
I0419 09:13:09.959900   12946 init_comm.go:44] [console] pci 0000:00:04.0: BAR 1: assigned [mem 0x20042000-0x20042fff]
I0419 09:13:09.960418   12946 init_comm.go:44] [console] pci 0000:00:05.0: BAR 1: assigned [mem 0x20043000-0x20043fff]
I0419 09:13:09.960901   12946 init_comm.go:44] [console] pci 0000:00:03.0: BAR 0: assigned [io  0x1000-0x103f]
I0419 09:13:09.961385   12946 init_comm.go:44] [console] pci 0000:00:04.0: BAR 0: assigned [io  0x1040-0x107f]
I0419 09:13:09.961855   12946 init_comm.go:44] [console] pci 0000:00:02.0: BAR 0: assigned [io  0x1080-0x109f]
I0419 09:13:09.962325   12946 init_comm.go:44] [console] pci 0000:00:05.0: BAR 0: assigned [io  0x10a0-0x10bf]
I0419 09:13:09.962791   12946 init_comm.go:44] [console] pci 0000:00:01.1: BAR 4: assigned [io  0x10c0-0x10cf]
I0419 09:13:09.963118   12946 init_comm.go:44] [console] NET: Registered protocol family 2
I0419 09:13:09.963732   12946 init_comm.go:44] [console] TCP established hash table entries: 4096 (order: 3, 32768 bytes)
I0419 09:13:09.964209   12946 init_comm.go:44] [console] TCP bind hash table entries: 4096 (order: 4, 65536 bytes)
I0419 09:13:09.964687   12946 init_comm.go:44] [console] TCP: Hash tables configured (established 4096 bind 4096)
I0419 09:13:09.965136   12946 init_comm.go:44] [console] UDP hash table entries: 256 (order: 1, 8192 bytes)
I0419 09:13:09.965601   12946 init_comm.go:44] [console] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes)
I0419 09:13:09.965928   12946 init_comm.go:44] [console] NET: Registered protocol family 1
I0419 09:13:09.966371   12946 init_comm.go:44] [console] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
I0419 09:13:09.966786   12946 init_comm.go:44] [console] pci 0000:00:01.0: PIIX3: Enabling Passive Release
I0419 09:13:09.967232   12946 init_comm.go:44] [console] pci 0000:00:01.0: Activating ISA DMA hang workarounds
I0419 09:13:09.967698   12946 init_comm.go:44] [console] Trying to unpack rootfs image as initramfs...
I0419 09:13:09.980494   12946 init_comm.go:44] [console] Freeing initrd memory: 960K (ffff88001ff10000 - ffff880020000000)
I0419 09:13:09.981125   12946 init_comm.go:44] [console] futex hash table entries: 256 (order: 2, 16384 bytes)
I0419 09:13:09.981875   12946 init_comm.go:44] [console] SGI XFS with ACLs, security attributes, no debug enabled
I0419 09:13:09.982328   12946 init_comm.go:44] [console] 9p: Installing v9fs 9p2000 file system support
I0419 09:13:09.983354   12946 init_comm.go:44] [console] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 254)
I0419 09:13:09.983653   12946 init_comm.go:44] [console] io scheduler noop registered
I0419 09:13:09.983998   12946 init_comm.go:44] [console] io scheduler cfq registered (default)
I0419 09:13:09.984486   12946 init_comm.go:44] [console] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
I0419 09:13:09.985059   12946 init_comm.go:44] [console] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
I0419 09:13:09.985732   12946 init_comm.go:44] [console] Warning: Processor Platform Limit event detected, but not handled.
I0419 09:13:09.986211   12946 init_comm.go:44] [console] Consider compiling CPUfreq support into your kernel.
I0419 09:13:09.987011   12946 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKB] enabled at IRQ 10
I0419 09:13:09.987522   12946 init_comm.go:44] [console] virtio-pci 0000:00:02.0: enabling device (0000 -> 0003)
I0419 09:13:09.988529   12946 init_comm.go:44] [console] virtio-pci 0000:00:02.0: virtio_pci: leaving for legacy driver
I0419 09:13:09.989560   12946 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 11
I0419 09:13:09.990084   12946 init_comm.go:44] [console] virtio-pci 0000:00:03.0: enabling device (0000 -> 0003)
I0419 09:13:09.991189   12946 init_comm.go:44] [console] virtio-pci 0000:00:03.0: virtio_pci: leaving for legacy driver
I0419 09:13:09.992233   12946 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 11
I0419 09:13:09.992762   12946 init_comm.go:44] [console] virtio-pci 0000:00:04.0: enabling device (0000 -> 0003)
I0419 09:13:09.994053   12946 init_comm.go:44] [console] virtio-pci 0000:00:04.0: virtio_pci: leaving for legacy driver
I0419 09:13:09.995270   12946 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 10
I0419 09:13:09.995811   12946 init_comm.go:44] [console] virtio-pci 0000:00:05.0: enabling device (0000 -> 0003)
I0419 09:13:09.997313   12946 init_comm.go:44] [console] virtio-pci 0000:00:05.0: virtio_pci: leaving for legacy driver
I0419 09:13:09.998520   12946 init_comm.go:44] [console] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
I0419 09:13:10.024831   12946 init_comm.go:44] [console] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
I0419 09:13:10.059118   12946 init_comm.go:44] [console] brd: module loaded
I0419 09:13:10.059332   12946 init_comm.go:44] [console] loop: module loaded
I0419 09:13:10.060672   12946 init_comm.go:44] [console] scsi host0: Virtio SCSI HBA
I0419 09:13:10.080969   12946 init_comm.go:44] [console] e1000: Intel(R) PRO/1000 Network Driver - version 7.3.21-k8-NAPI
I0419 09:13:10.081360   12946 init_comm.go:44] [console] e1000: Copyright (c) 1999-2006 Intel Corporation.
I0419 09:13:10.081757   12946 init_comm.go:44] [console] NET: Registered protocol family 10
I0419 09:13:10.082781   12946 init_comm.go:44] [console] NET: Registered protocol family 17
I0419 09:13:10.083112   12946 init_comm.go:44] [console] 9pnet: Installing 9P2000 support
I0419 09:13:10.084638   12946 init_comm.go:44] [console] registered taskstats version 1
I0419 09:13:10.086269   12946 init_comm.go:44] [console] Freeing unused kernel memory: 860K (ffffffff815d5000 - ffffffff816ac000)
I0419 09:13:10.087397   12946 init_comm.go:44] [console] create directory /dev
I0419 09:13:10.087608   12946 init_comm.go:44] [console] create directory /sys
I0419 09:13:10.087804   12946 init_comm.go:44] [console] create directory /proc
I0419 09:13:10.088031   12946 init_comm.go:44] [console] uptime 0.19 0.01
I0419 09:13:10.088158   12946 init_comm.go:44] [console] 
I0419 09:13:10.088379   12946 init_comm.go:44] [console] create directory /dev/pts
I0419 09:13:10.088606   12946 init_comm.go:44] [console] create directory /dev
I0419 09:13:10.088945   12946 init_comm.go:44] [console] open hyper channel /dev/vport0p1
I0419 09:13:10.089254   12946 init_comm.go:44] [console] send ready message
I0419 09:13:10.089475   12946 init_comm.go:44] [console] hyper send type 8, len 0
I0419 09:13:10.089621   12946 init_comm.go:82] read 8/8 [length = 0]
I0419 09:13:10.089680   12946 init_comm.go:86] data length is 8
I0419 09:13:10.089719   12946 init_comm.go:119] Get init ready message
I0419 09:13:10.089804   12946 hypervisor.go:29] main event loop got message 5(EVENT_INIT_CONNECTED)
I0419 09:13:10.089845   12946 vm_states.go:599] begin to wait vm commands
I0419 09:13:10.089842   12946 init_comm.go:163] got cmd:1
I0419 09:13:10.089889   12946 init_comm.go:72] trying to read 8 bytes
I0419 09:13:10.089893   12946 init_comm.go:244] send command 1 to init, payload: '{"hostname":"alpine-0989527933","containers":[{"id":"7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea","rootfs":"","image":"/7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea/rootfs","fsmap":[{"source":"iVfeHKcqnR","path":"/etc/hosts","readOnly":false,"dockerVolume":false}],"process":{"terminal":true,"stdio":1,"args":["/bin/sh"],"workdir":"/"},"restartPolicy":"never","initialize":false}],"interfaces":[{"device":"eth0","ipAddress":"192.168.123.2","netMask":"255.255.255.0"}],"routes":[{"dest":"0.0.0.0/0","gateway":"192.168.123.1","device":"eth0"}],"shareDir":"share_dir"}'.
I0419 09:13:10.090023   12946 init_comm.go:257] write 512 to init, payload: 'f{"hostname":"alpine-0989527933","containers":[{"id":"7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea","rootfs":"","image":"/7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea/rootfs","fsmap":[{"source":"iVfeHKcqnR","path":"/etc/hosts","readOnly":false,"dockerVolume":false}],"process":{"terminal":true,"stdio":1,"args":["/bin/sh"],"workdir":"/"},"restartPolicy":"never","initialize":false}],"interfaces":[{"device":"eth0","ipAddress":"192.168.123.2","netMask":"255.255.255.'.
I0419 09:13:10.089917   12946 vm.go:262] Get the response from VM, VM id is vm-bbuWmTciLc!
I0419 09:13:10.090141   12946 init_comm.go:262] message sent, set pong timer
I0419 09:13:10.090225   12946 init_comm.go:44] [console] channel sh.hyper.channel.1, directory sh.hyper.channel.0
I0419 09:13:10.090319   12946 init_comm.go:44] [console] 
I0419 09:13:10.090798   12946 init_comm.go:44] [console] open hyper channel /dev/vport0p2
I0419 09:13:10.091882   12946 init_comm.go:44] [console] hyper_init_event hyper channel event 0x613578, ops 0x613320, fd 4
I0419 09:13:10.092376   12946 init_comm.go:44] [console] hyper_add_event add event fd 4, 0x613320
I0419 09:13:10.093029   12946 init_comm.go:44] [console] hyper_init_event hyper ttyfd event 0x613540, ops 0x6132e0, fd 5
I0419 09:13:10.093554   12946 init_comm.go:44] [console] hyper_add_event add event fd 5, 0x6132e0
I0419 09:13:10.094246   12946 init_comm.go:44] [console] hyper_init_event hyper signal event 0x613508, ops 0x613360, fd 3
I0419 09:13:10.094770   12946 init_comm.go:44] [console] hyper_add_event add event fd 3, 0x613360
I0419 09:13:10.095112   12946 init_comm.go:44] [console] hyper_loop epoll_wait 1
I0419 09:13:10.095853   12946 init_comm.go:44] [console] hyper_handle_event get event 1, de 0x613578, fd 4. ops 0x613320
I0419 09:13:10.096499   12946 init_comm.go:44] [console] hyper_handle_event event EPOLLIN, de 0x613578, fd 4, 0x613320
I0419 09:13:10.096777   12946 init_comm.go:44] [console] hyper_event_read
I0419 09:13:10.097120   12946 init_comm.go:44] [console] already read 8 bytes data
I0419 09:13:10.097470   12946 init_comm.go:44] [console] hyper send type 14, len 4
I0419 09:13:10.097572   12946 init_comm.go:82] read 8/8 [length = 0]
I0419 09:13:10.097586   12946 init_comm.go:86] data length is 12
I0419 09:13:10.097593   12946 init_comm.go:72] trying to read 4 bytes
I0419 09:13:10.097603   12946 init_comm.go:82] read 12/12 [length = 12]
I0419 09:13:10.097617   12946 init_comm.go:72] trying to read 8 bytes
I0419 09:13:10.097626   12946 init_comm.go:163] got cmd:14
I0419 09:13:10.097635   12946 init_comm.go:231] get command NEXT
I0419 09:13:10.097648   12946 init_comm.go:234] send 512, receive 8
I0419 09:13:10.097781   12946 init_comm.go:44] [console] get length 614
I0419 09:13:10.098261   12946 init_comm.go:44] [console] read 504 bytes data, total data 512
I0419 09:13:10.098644   12946 init_comm.go:44] [console] hyper send type 14, len 4
I0419 09:13:10.098730   12946 init_comm.go:82] read 8/8 [length = 0]
I0419 09:13:10.098747   12946 init_comm.go:86] data length is 12
I0419 09:13:10.098758   12946 init_comm.go:72] trying to read 4 bytes
I0419 09:13:10.098773   12946 init_comm.go:82] read 12/12 [length = 12]
I0419 09:13:10.098790   12946 init_comm.go:72] trying to read 8 bytes
I0419 09:13:10.098808   12946 init_comm.go:163] got cmd:14
I0419 09:13:10.098821   12946 init_comm.go:231] get command NEXT
I0419 09:13:10.098832   12946 init_comm.go:234] send 512, receive 512
I0419 09:13:10.098853   12946 init_comm.go:257] write 102 to init, payload: '0"}],"routes":[{"dest":"0.0.0.0/0","gateway":"192.168.123.1","device":"eth0"}],"shareDir":"share_dir"}'.
I0419 09:13:10.099172   12946 init_comm.go:44] [console] hyper_loop epoll_wait 1
I0419 09:13:10.099597   12946 init_comm.go:44] [console] hyper_handle_event get event 1, de 0x613578, fd 4. ops 0x613320
I0419 09:13:10.099999   12946 init_comm.go:44] [console] hyper_handle_event event EPOLLIN, de 0x613578, fd 4, 0x613320
I0419 09:13:10.100162   12946 init_comm.go:44] [console] hyper_event_read
I0419 09:13:10.100304   12946 init_comm.go:44] [console] get length 614
I0419 09:13:10.100672   12946 init_comm.go:44] [console] read 102 bytes data, total data 614
I0419 09:13:10.100895   12946 init_comm.go:44] [console] hyper send type 14, len 4
I0419 09:13:10.100988   12946 init_comm.go:82] read 8/8 [length = 0]
I0419 09:13:10.101009   12946 init_comm.go:86] data length is 12
I0419 09:13:10.101021   12946 init_comm.go:72] trying to read 4 bytes
I0419 09:13:10.101035   12946 init_comm.go:82] read 12/12 [length = 12]
I0419 09:13:10.101059   12946 init_comm.go:72] trying to read 8 bytes
I0419 09:13:10.101074   12946 init_comm.go:163] got cmd:14
I0419 09:13:10.101087   12946 init_comm.go:231] get command NEXT
I0419 09:13:10.101099   12946 init_comm.go:234] send 102, receive 102
I0419 09:13:10.110793   12946 init_comm.go:44] [console] 0 0 0 1 0 0 2 66 7b 22 68 6f 73 74 6e 61 6d 65 22 3a 22 61 6c 70 69 6e 65 2d 30 39 38 39 35 32 37 39 33 33 22 2c 22 63 6f 6e 74 61 69 6e 65 72 73 22 3a 5b 7b 22 69 64 22 3a 22 37 33 38 33 34 38 34 63 65 62 30 36 34 33 65 62 33 39 37 38 37 64 33 31 36 33 38 64 66 34 63 38 37 66 38 31 65 32 38 32 30 38 63 61 63 32 63 31 33 31 63 62 63 35 63 39 37 61 33 32 64 61 65 61 22 2c 22 72 6f 6f 74 66 73 22 3a 22 22 2c 22 69 6d 61 67 65 22 3a 22 2f 37 33 38 33 34 38 34 63 65 62 30 36 34 33 65 62 33 39 37 38 37 64 33 31 36 33 38 64 66 34 63 38 37 66 38 31 65 32 38 32 30 38 63 61 63 32 63 31 33 31 63 62 63 35 63 39 37 61 33 32 64 61 65 61 2f 72 6f 6f 74 66 73 22 2c 22 66 73 6d 61 70 22 3a 5b 7b 22 73 6f 75 72 63 65 22 3a 22 69 56 66 65 48 4b 63 71 6e 52 22 2c 22 70 61 74 68 22 3a 22 2f 65 74 63 2f 68 6f 73 74 73 22 2c 22 72 65 61 64 4f 6e 6c 79 22 3a 66 61 6c 73 65 2c 22 64 6f 63 6b 65 72 56 6f 6c 75 6d 65 22 3a 66 61 6c 73 65 7d 5d 2c 22 70 72 6f 63 65 73 73 22 3a 7b 22 74 65 72 6d 69 6e 61 6c 22 3a 74 72 75 65 2c 22 73 74 64 69 6f 22 3a 31 2c 22 61 72 67 73 22 3a 5b 22 2f 62 69 6e 2f 73 68 22 5d 2c 22 77 6f 72 6b 64 69 72 22 3a 22 2f 22 7d 2c 22 72 65 73 74 61 72 74 50 6f 6c 69 63 79 22 3a 22 6e 65 76 65 72 22 2c 22 69 6e 69 74 69 61 6c 69 7a 65 22 3a 66 61 6c 73 65 7d 5d 2c 22 69 6e 74 65 72 66 61 63 65 73 22 3a 5b 7b 22 64 65 76 69 63 65 22 3a 22 65 74 68 30 22 2c 22 69 70 41 64 64 72 65 73 73 22 3a 22 31 39 32 2e 31 36 38 2e 31 32 33 2e 32 22 2c 22 6e 65 74 4d 61 73 6b 22 3a 22 32 35 35 2e 32 35 35 2e 32 35 35 2e 30 22 7d 5d 2c 22 72 6f 75 74 65 73 22 3a 5b 7b 22 64 65 73 74 22 3a 22 30 2e 30 2e 30 2e 30 2f 30 22 2c 22 67 61 74 65 77 61 79 22 3a 22 31 39 32 2e 31 36 38 2e 31 32 33 2e 31 22 2c 22 64 65 76 69 63 65 22 3a 22 65 74 68 30 22 7d 5d 2c 22 73 68 61 72 65 44 69 72 22 3a 22 73 68 61 72 65 5f 64 69 72 22 7d 
I0419 09:13:10.111087   12946 init_comm.go:44] [console]  hyper_channel_handle, type 1, len 614
I0419 09:13:10.111247   12946 init_comm.go:44] [console] online_cpu()
I0419 09:13:10.111440   12946 init_comm.go:44] [console] online_memory()
I0419 09:13:10.111664   12946 init_comm.go:44] [console] try to online memory1
I0419 09:13:10.111903   12946 init_comm.go:44] [console] online memory1 result: success
I0419 09:13:10.112130   12946 init_comm.go:44] [console] try to online memory2
I0419 09:13:10.112371   12946 init_comm.go:44] [console] online memory2 result: success
I0419 09:13:10.112602   12946 init_comm.go:44] [console] try to online memory3
I0419 09:13:10.112845   12946 init_comm.go:44] [console] online memory3 result: success
I0419 09:13:10.117136   12946 init_comm.go:44] [console] call hyper_start_pod, json {"hostname":"alpine-0989527933","containers":[{"id":"7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea","rootfs":"","image":"/7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea/rootfs","fsmap":[{"source":"iVfeHKcqnR","path":"/etc/hosts","readOnly":false,"dockerVolume":false}],"process":{"terminal":true,"stdio":1,"args":["/bin/sh"],"workdir":"/"},"restartPolicy":"never","initialize":false}],"interfaces":[{"device":"eth0","ipAddress":"192.168.123.2","netMask":"255.255.255.0"}],"routes":[{"dest":"0.0.0.0/0","gateway":"192.168.123.1","device":"eth0"}],"shareDir":"share_dir"}, len 606
I0419 09:13:10.120694   12946 init_comm.go:44] [console] call hyper_start_pod, json {"hostname":"alpine-0989527933","containers":[{"id":"7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea","rootfs":"","image":"/7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea/rootfs","fsmap":[{"source":"iVfeHKcqnR","path":"/etc/hosts","readOnly":false,"dockerVolume":false}],"process":{"terminal":true,"stdio":1,"args":["/bin/sh"],"workdir":"/"},"restartPolicy":"never","initialize":false}],"interfaces":[{"device":"eth0","ipAddress":"192.168.123.2","netMask":"255.255.255.0"}],"routes":[{"dest":"0.0.0.0/0","gateway":"192.168.123.1","device":"eth0"}],"shareDir":"share_dir"}, len 606
I0419 09:13:10.120964   12946 init_comm.go:44] [console] jsmn parse successed, n is 58
I0419 09:13:10.121204   12946 init_comm.go:44] [console] token 0, type is 1, size is 5
I0419 09:13:10.121459   12946 init_comm.go:44] [console] token 1, type is 3, size is 1
I0419 09:13:10.121712   12946 init_comm.go:44] [console] hostname is alpine-0989527933
I0419 09:13:10.121964   12946 init_comm.go:44] [console] token 3, type is 3, size is 1
I0419 09:13:10.122158   12946 init_comm.go:44] [console] container count 1
I0419 09:13:10.122326   12946 init_comm.go:44] [console] next container 7
I0419 09:13:10.122455   12946 init_comm.go:44] [console] 1 name id
I0419 09:13:10.122962   12946 init_comm.go:44] [console] container id 7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea
I0419 09:13:10.123119   12946 init_comm.go:44] [console] 3 name rootfs
I0419 09:13:10.123287   12946 init_comm.go:44] [console] container rootfs 
I0419 09:13:10.123428   12946 init_comm.go:44] [console] 5 name image
I0419 09:13:10.123995   12946 init_comm.go:44] [console] container image /7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea/rootfs
I0419 09:13:10.124138   12946 init_comm.go:44] [console] 7 name fsmap
I0419 09:13:10.124278   12946 init_comm.go:44] [console] fsmap num 1
I0419 09:13:10.124489   12946 init_comm.go:44] [console] maps 0 source iVfeHKcqnR
I0419 09:13:10.124695   12946 init_comm.go:44] [console] maps 0 path /etc/hosts
I0419 09:13:10.124914   12946 init_comm.go:44] [console] maps 0 readonly 0
I0419 09:13:10.125148   12946 init_comm.go:44] [console] in maps incorrect dockerVolume
I0419 09:13:10.125364   12946 init_comm.go:44] [console] parse pod json failed
I0419 09:13:10.125504   12946 init_comm.go:44] [console] uptime 0.23 0.01
I0419 09:13:10.125621   12946 init_comm.go:44] [console] 
I0419 09:13:10.125836   12946 init_comm.go:44] [console] hyper send type 10, len 0
I0419 09:13:10.125909   12946 init_comm.go:82] read 8/8 [length = 0]
I0419 09:13:10.125948   12946 init_comm.go:86] data length is 8
I0419 09:13:10.125987   12946 init_comm.go:72] trying to read 8 bytes
I0419 09:13:10.126026   12946 init_comm.go:163] got cmd:10
I0419 09:13:10.126083   12946 init_comm.go:186] ack got, clear pong timer
I0419 09:13:10.126122   12946 hypervisor.go:29] main event loop got message 44(ERROR_CMD_FAIL)
E0419 09:13:10.126183   12946 vm_states.go:358] Shutting down because of an exception: Start POD failed
I0419 09:13:10.129288   12946 context.go:212] VM vm-bbuWmTciLc: state change from STARTING to 'TERMINATING'
E0419 09:13:10.129314   12946 vm_states.go:635] Start POD failed
I0419 09:13:10.126363   12946 vm.go:262] Get the response from VM, VM id is vm-bbuWmTciLc!
I0419 09:13:10.129346   12946 pod.go:83] unlock pod for operation start
I0419 09:13:10.129355   12946 pod.go:86] successfully unlock pod for operation start
E0419 09:13:10.129363   12946 run.go:88] VM vm-bbuWmTciLc start failed with code 7: Start POD failed
E0419 09:13:10.129372   12946 server.go:170] Handler for POST /v0.5.0/pod/start returned error: VM vm-bbuWmTciLc start failed with code 7: Start POD failed
I0419 09:13:10.129447   12946 init_comm.go:163] got cmd:4
I0419 09:13:10.129458   12946 init_comm.go:244] send command 4 to init, payload: ''.
I0419 09:13:10.129474   12946 init_comm.go:257] write 8 to init, payload: ''.
I0419 09:13:10.129484   12946 init_comm.go:262] message sent, set pong timer
I0419 09:13:10.130240   12946 init_comm.go:44] [console] hyper_loop epoll_wait 1
I0419 09:13:10.130718   12946 init_comm.go:44] [console] hyper_handle_event get event 1, de 0x613578, fd 4. ops 0x613320
I0419 09:13:10.131232   12946 init_comm.go:44] [console] hyper_handle_event event EPOLLIN, de 0x613578, fd 4, 0x613320
I0419 09:13:10.131429   12946 init_comm.go:44] [console] hyper_event_read
I0419 09:13:10.131811   12946 init_comm.go:44] [console] already read 8 bytes data
I0419 09:13:10.132107   12946 init_comm.go:44] [console] hyper send type 14, len 4
I0419 09:13:10.132204   12946 init_comm.go:82] read 8/8 [length = 0]
I0419 09:13:10.132220   12946 init_comm.go:86] data length is 12
I0419 09:13:10.132232   12946 init_comm.go:72] trying to read 4 bytes
I0419 09:13:10.132246   12946 init_comm.go:82] read 12/12 [length = 12]
I0419 09:13:10.132290   12946 init_comm.go:72] trying to read 8 bytes
I0419 09:13:10.132305   12946 init_comm.go:163] got cmd:14
I0419 09:13:10.132317   12946 init_comm.go:231] get command NEXT
I0419 09:13:10.132327   12946 init_comm.go:234] send 8, receive 8
I0419 09:13:10.132347   12946 init_comm.go:44] [console] get length 8
I0419 09:13:10.132552   12946 init_comm.go:44] [console] 0 0 0 4 0 0 0 8 
I0419 09:13:10.132941   12946 init_comm.go:44] [console]  hyper_channel_handle, type 4, len 8
I0419 09:13:10.133216   12946 init_comm.go:44] [console] get DESTROYPOD message
I0419 09:13:10.133498   12946 init_comm.go:44] [console] hyper send type 9, len 0
I0419 09:13:10.133570   12946 init_comm.go:82] read 8/8 [length = 0]
I0419 09:13:10.133583   12946 init_comm.go:86] data length is 8
I0419 09:13:10.133599   12946 init_comm.go:72] trying to read 8 bytes
I0419 09:13:10.133613   12946 init_comm.go:163] got cmd:9
I0419 09:13:10.133627   12946 init_comm.go:167] got response of shutdown command, last round of command to init
I0419 09:13:10.133647   12946 init_comm.go:186] ack got, clear pong timer
I0419 09:13:10.133662   12946 hypervisor.go:29] main event loop got message 37(COMMAND_ACK)
I0419 09:13:10.133679   12946 vm_states.go:800] [Terminating] Got reply to &{4 [] <nil>}: ''
I0419 09:13:10.133709   12946 vm_states.go:802] POD destroyed 
I0419 09:13:10.133728   12946 qmp_handler.go:296] got new session
I0419 09:13:10.133755   12946 qmp_handler.go:225] Begin process command session
I0419 09:13:10.133781   12946 qmp_handler.go:243] sending command (1) {"execute":"quit"}
I0419 09:13:10.134353   12946 qmp_handler.go:103] got a message {"return": {}}
I0419 09:13:10.134433   12946 qmp_handler.go:103] got a message {"timestamp": {"seconds": 1461049990, "microseconds": 134330}, "event": "SHUTDOWN"}
I0419 09:13:10.134497   12946 qmp_handler.go:107] got event: SHUTDOWN
I0419 09:13:10.134512   12946 qmp_handler.go:152] Shutdown, quit QMP receiver
I0419 09:13:10.134527   12946 qmp_handler.go:323] got QMP event SHUTDOWN
I0419 09:13:10.134551   12946 qmp_handler.go:325] got QMP shutdown event, quit...
I0419 09:13:10.134564   12946 hypervisor.go:29] main event loop got message 1(EVENT_VM_EXIT)
I0419 09:13:10.134577   12946 vm_states.go:784] Got VM shutdown event while terminating, go to cleaning up
I0419 09:13:10.134587   12946 vm_states.go:34] VM has exit...
I0419 09:13:10.134606   12946 devicemap.go:419] need umount dir iVfeHKcqnR
I0419 09:13:10.134706   12946 devicemap.go:462] need unmount aufs /7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea/rootfs
I0419 09:13:10.134726   12946 devicemap.go:499] remove network card 0: 192.168.123.2
I0419 09:13:10.134743   12946 context.go:212] VM vm-bbuWmTciLc: state change from TERMINATING to 'DESTROYING'
I0419 09:13:10.135162   12946 pod.go:605] cleanup hosts for pod pod-nGrWzvoRNi failed, invalid argument
I0419 09:13:10.138323   12946 volume_linux.go:43] Ready to unmount the target : /var/run/hyper/vm-bbuWmTciLc/share_dir/7383484ceb0643eb39787d31638df4c87f81e28208cac2c131cbc5c97a32daea/rootfs
I0419 09:13:10.141402   12946 tty.go:441] Input byte chan closed, close the output string chan
I0419 09:13:10.141440   12946 init_comm.go:46] console output end
E0419 09:13:10.141460   12946 init_comm.go:75] read init data failed
I0419 09:13:10.141485   12946 hypervisor.go:29] main event loop got message 43(ERROR_INTERRUPTED)
I0419 09:13:10.141505   12946 vm_states.go:891] Connection interrupted while destroying
E0419 09:13:10.141544   12946 tty.go:103] read tty data failed
I0419 09:13:10.141575   12946 tty.go:164] tty socket closed, quit the reading goroutine EOF
I0419 09:13:10.141605   12946 tty.go:131] tty chan closed, quit sent goroutine
I0419 09:13:10.141620   12946 hypervisor.go:29] main event loop got message 43(ERROR_INTERRUPTED)
I0419 09:13:10.141650   12946 vm_states.go:891] Connection interrupted while destroying
I0419 09:13:10.156687   12946 hypervisor.go:29] main event loop got message 12(EVENT_BLOCK_EJECTED)
I0419 09:13:10.156726   12946 devicemap.go:396] volume etchosts-volume umounted
I0419 09:13:10.156743   12946 vm_states.go:456] Unplug block device return with true
I0419 09:13:10.156758   12946 hypervisor.go:29] main event loop got message 14(EVENT_INTERFACE_DELETE)
I0419 09:13:10.156774   12946 devicemap.go:387] interface 0 released
I0419 09:13:10.156789   12946 vm_states.go:453] Unplug interface return with true
I0419 09:13:10.165789   12946 hypervisor.go:29] main event loop got message 7(EVENT_CONTAINER_DELETE)
I0419 09:13:10.165828   12946 devicemap.go:369] container 0 umounted
I0419 09:13:10.165844   12946 vm_states.go:450] Unplug container return with true
I0419 09:13:10.165856   12946 context.go:199] no more device to release/remove/umount, quit
I0419 09:13:10.165901   12946 qemu_process.go:19] quit watch dog.
I0419 09:47:29.285124   12946 server.go:152] Calling POST /v0.5.0/vm/create
I0419 09:47:29.285333   12946 vm.go:120] The config: kernel=/mnt/tank/HYPER/kernel, initrd=/mnt/tank/HYPER/hyper-initrd.img
I0419 09:47:29.285967   12946 qemu_process.go:63] cmdline arguments: -machine pc-i440fx-2.0,accel=kvm,usb=off -global kvm-pit.lost_tick_policy=discard -cpu host -drive if=pflash,file=/mnt/tank/HYPER/bios-qboot.bin,readonly=on -drive if=pflash,file=/mnt/tank/HYPER/cbfs-qboot.rom,readonly=on -realtime mlock=off -no-user-config -nodefaults -no-hpet -rtc base=utc,driftfix=slew -no-reboot -display none -boot strict=on -m 128 -smp 1 -qmp unix:/var/run/hyper/vm-TcTOqfpdJk/qmp.sock,server,nowait -serial unix:/var/run/hyper/vm-TcTOqfpdJk/console.sock,server,nowait -device virtio-serial-pci,id=virtio-serial0,bus=pci.0,addr=0x2 -device virtio-scsi-pci,id=scsi0,bus=pci.0,addr=0x3 -chardev socket,id=charch0,path=/var/run/hyper/vm-TcTOqfpdJk/hyper.sock,server,nowait -device virtserialport,bus=virtio-serial0.0,nr=1,chardev=charch0,id=channel0,name=sh.hyper.channel.0 -chardev socket,id=charch1,path=/var/run/hyper/vm-TcTOqfpdJk/tty.sock,server,nowait -device virtserialport,bus=virtio-serial0.0,nr=2,chardev=charch1,id=channel1,name=sh.hyper.channel.1 -fsdev local,id=virtio9p,path=/var/run/hyper/vm-TcTOqfpdJk/share_dir,security_model=none -device virtio-9p-pci,fsdev=virtio9p,mount_tag=share_dir
I0419 09:47:29.286247   12946 server.go:152] Calling POST /v0.5.0/pod/create
I0419 09:47:29.286393   12946 pod_routes.go:76] Args string is {"id":"busybox-5112358495","hostname":"","containers":[{"name":"busybox-5112358495","image":"busybox","command":[],"workdir":"/","entrypoint":[],"ports":[],"envs":[],"volumes":[],"files":[],"restartPolicy":"never"}],"resource":{"vcpu":1,"memory":128},"files":[],"volumes":[],"labels":{},"log":{"type":"","config":{}},"tty":false,"type":"","RestartPolicy":""}, autoremove false
I0419 09:47:29.286494   12946 run.go:45] podArgs: {"id":"busybox-5112358495","hostname":"","containers":[{"name":"busybox-5112358495","image":"busybox","command":[],"workdir":"/","entrypoint":[],"ports":[],"envs":[],"volumes":[],"files":[],"restartPolicy":"never"}],"resource":{"vcpu":1,"memory":128},"files":[],"volumes":[],"labels":{},"log":{"type":"","config":{}},"tty":false,"type":"","RestartPolicy":""}
I0419 09:47:29.289009   12946 daemondb.go:82] try get container list for pod pod-XPJnIRsvhP
I0419 09:47:29.289108   12946 pod.go:229] loaded containers for pod pod-XPJnIRsvhP: []
E0419 09:47:29.289312   12946 pod.go:309] nosuchimagetag: No such image: busybox:latest
E0419 09:47:29.289339   12946 server.go:170] Handler for POST /v0.5.0/pod/create returned error: No such image: busybox:latest
I0419 09:47:29.290183   12946 qemu_process.go:74] starting daemon with pid: 13818
I0419 09:47:29.290355   12946 server.go:152] Calling POST /v0.5.0/image/create
DEBU[2108] Trying to pull busybox from https://registry-1.docker.io v2 
I0419 09:47:29.326299   12946 tty.go:157] tty socket connected
I0419 09:47:29.326390   12946 tty.go:100] tty: trying to read 12 bytes
I0419 09:47:29.326403   12946 qmp_handler.go:167] connected to /var/run/hyper/vm-TcTOqfpdJk/qmp.sock
I0419 09:47:29.326467   12946 qmp_handler.go:177] begin qmp init...
I0419 09:47:29.326429   12946 init_comm.go:29] connected to /var/run/hyper/vm-TcTOqfpdJk/console.sock
I0419 09:47:29.326503   12946 init_comm.go:36] connected /var/run/hyper/vm-TcTOqfpdJk/console.sock as telnet mode.
I0419 09:47:29.326314   12946 init_comm.go:109] Wating for init messages...
I0419 09:47:29.326544   12946 init_comm.go:72] trying to read 8 bytes
I0419 09:47:29.396018   12946 qmp_handler.go:186] got qmp welcome, now sending command qmp_capabilities
I0419 09:47:29.396082   12946 qmp_handler.go:201] waiting for response
I0419 09:47:29.396323   12946 qmp_handler.go:103] got a message {"return": {}}
I0419 09:47:29.396344   12946 qmp_handler.go:210] got for response
I0419 09:47:29.396354   12946 qmp_handler.go:213] QMP connection initialized
I0419 09:47:29.396384   12946 qmp_handler.go:346] QMP initialzed, go into main QMP loop
I0419 09:47:29.396408   12946 qmp_handler.go:137] Begin receive QMP message
I0419 09:47:29.475465   12946 init_comm.go:44] [console] Initializing cgroup subsys cpu
I0419 09:47:29.479392   12946 init_comm.go:44] [console] Linux version 4.4.0-hyper+ (laijs@ubox) (gcc version 5.2.1 20151010 (Ubuntu 5.2.1-22ubuntu2) ) #0 SMP Mon Jan 25 01:10:46 CST 2016
I0419 09:47:29.479841   12946 init_comm.go:44] [console] Command line: console=ttyS0 panic=1 no_timer_check
I0419 09:47:29.479947   12946 init_comm.go:44] [console] 
I0419 09:47:29.480199   12946 init_comm.go:44] [console] x86/fpu: Legacy x87 FPU detected.
I0419 09:47:29.480599   12946 init_comm.go:44] [console] x86/fpu: Using 'lazy' FPU context switches.
I0419 09:47:29.480961   12946 init_comm.go:44] [console] e820: BIOS-provided physical RAM map:
I0419 09:47:29.481524   12946 init_comm.go:44] [console] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
I0419 09:47:29.482110   12946 init_comm.go:44] [console] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
I0419 09:47:29.482715   12946 init_comm.go:44] [console] BIOS-e820: [mem 0x00000000000d0000-0x00000000000effff] ACPI NVS
I0419 09:47:29.483280   12946 init_comm.go:44] [console] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
I0419 09:47:29.483806   12946 init_comm.go:44] [console] BIOS-e820: [mem 0x0000000000100000-0x0000000007ffffff] usable
I0419 09:47:29.484302   12946 init_comm.go:44] [console] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved
I0419 09:47:29.484645   12946 init_comm.go:44] [console] NX (Execute Disable) protection: active
I0419 09:47:29.484899   12946 init_comm.go:44] [console] DMI not present or invalid.
I0419 09:47:29.485126   12946 init_comm.go:44] [console] Hypervisor detected: KVM
I0419 09:47:29.485573   12946 init_comm.go:44] [console] e820: last_pfn = 0x8000 max_arch_pfn = 0x400000000
I0419 09:47:29.486191   12946 init_comm.go:44] [console] x86/PAT: Configuration [0-7]: WB  WC  UC- UC  WB  WC  UC- WT  
I0419 09:47:29.486335   12946 init_comm.go:44] [console] MTRR: Disabled
I0419 09:47:29.486718   12946 init_comm.go:44] [console] CPU MTRRs all blank - virtualized system.
I0419 09:47:29.487032   12946 init_comm.go:44] [console] Using GB pages for direct mapping
I0419 09:47:29.487382   12946 init_comm.go:44] [console] RAMDISK: [mem 0x07f10000-0x07ffffff]
I0419 09:47:29.487826   12946 init_comm.go:44] [console] ACPI: Early table checksum verification disabled
I0419 09:47:29.488282   12946 init_comm.go:44] [console] ACPI: RSDP 0x00000000000F2960 000014 (v00 BOCHS )
I0419 09:47:29.489043   12946 init_comm.go:44] [console] ACPI: RSDT 0x00000000000EFB95 000034 (v01 BOCHS  BXPCRSDT 00000001 BXPC 00000001)
I0419 09:47:29.489790   12946 init_comm.go:44] [console] ACPI: FACP 0x00000000000EF1C0 000074 (v01 BOCHS  BXPCFACP 00000001 BXPC 00000001)
I0419 09:47:29.490546   12946 init_comm.go:44] [console] ACPI: DSDT 0x00000000000EE040 001180 (v01 BOCHS  BXPCDSDT 00000001 BXPC 00000001)
I0419 09:47:29.490895   12946 init_comm.go:44] [console] ACPI: FACS 0x00000000000EE000 000040
I0419 09:47:29.491672   12946 init_comm.go:44] [console] ACPI: SSDT 0x00000000000EF234 0008E9 (v01 BOCHS  BXPCSSDT 00000001 BXPC 00000001)
I0419 09:47:29.492413   12946 init_comm.go:44] [console] ACPI: APIC 0x00000000000EFB1D 000078 (v01 BOCHS  BXPCAPIC 00000001 BXPC 00000001)
I0419 09:47:29.493159   12946 init_comm.go:44] [console] ACPI: RSDT 0x00000000000EFB95 000034 (v01 BOCHS  BXPCRSDT 00000001 BXPC 00000001)
I0419 09:47:29.493412   12946 init_comm.go:44] [console] No NUMA configuration found
I0419 09:47:29.493971   12946 init_comm.go:44] [console] Faking a node at [mem 0x0000000000000000-0x0000000007ffffff]
I0419 09:47:29.494419   12946 init_comm.go:44] [console] NODE_DATA(0) allocated [mem 0x07efe000-0x07f0ffff]
I0419 09:47:29.494847   12946 init_comm.go:44] [console] kvm-clock: Using msrs 4b564d01 and 4b564d00
I0419 09:47:29.495312   12946 init_comm.go:44] [console] kvm-clock: cpu 0, msr 0:7efd001, primary cpu clock
I0419 09:47:29.496244   12946 init_comm.go:44] [console] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
I0419 09:47:29.496370   12946 init_comm.go:44] [console] Zone ranges:
I0419 09:47:29.496921   12946 init_comm.go:44] [console]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
I0419 09:47:29.497358   12946 init_comm.go:44] [console]   DMA32    [mem 0x0000000001000000-0x0000000007ffffff]
I0419 09:47:29.497513   12946 init_comm.go:44] [console]   Normal   empty
I0419 09:47:29.497827   12946 init_comm.go:44] [console] Movable zone start for each node
I0419 09:47:29.498059   12946 init_comm.go:44] [console] Early memory node ranges
I0419 09:47:29.498568   12946 init_comm.go:44] [console]   node   0: [mem 0x0000000000001000-0x000000000009efff]
I0419 09:47:29.499081   12946 init_comm.go:44] [console]   node   0: [mem 0x0000000000100000-0x0000000007ffffff]
I0419 09:47:29.499657   12946 init_comm.go:44] [console] Initmem setup node 0 [mem 0x0000000000001000-0x0000000007ffffff]
I0419 09:47:29.499932   12946 init_comm.go:44] [console] ACPI: PM-Timer IO Port: 0x608
I0419 09:47:29.500391   12946 init_comm.go:44] [console] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
I0419 09:47:29.500944   12946 init_comm.go:44] [console] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
I0419 09:47:29.501448   12946 init_comm.go:44] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
I0419 09:47:29.501988   12946 init_comm.go:44] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
I0419 09:47:29.502526   12946 init_comm.go:44] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
I0419 09:47:29.503097   12946 init_comm.go:44] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
I0419 09:47:29.503667   12946 init_comm.go:44] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
I0419 09:47:29.504149   12946 init_comm.go:44] [console] Using ACPI (MADT) for SMP configuration information
I0419 09:47:29.504525   12946 init_comm.go:44] [console] smpboot: Allowing 1 CPUs, 0 hotplug CPUs
I0419 09:47:29.505066   12946 init_comm.go:44] [console] e820: [mem 0x08000000-0xfeffbfff] available for PCI devices
I0419 09:47:29.505391   12946 init_comm.go:44] [console] Booting paravirtualized kernel on KVM
I0419 09:47:29.506329   12946 init_comm.go:44] [console] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
I0419 09:47:29.506938   12946 init_comm.go:44] [console] setup_percpu: NR_CPUS:8 nr_cpumask_bits:8 nr_cpu_ids:1 nr_node_ids:1
I0419 09:47:29.507633   12946 init_comm.go:44] [console] PERCPU: Embedded 31 pages/cpu @ffff880007c00000 s89560 r8192 d29224 u2097152
I0419 09:47:29.507886   12946 init_comm.go:44] [console] KVM setup async PF for cpu 0
I0419 09:47:29.508183   12946 init_comm.go:44] [console] kvm-stealtime: cpu 0, msr 7c0d480
I0419 09:47:29.508849   12946 init_comm.go:44] [console] Built 1 zonelists in Node order, mobility grouping on.  Total pages: 32201
I0419 09:47:29.509033   12946 init_comm.go:44] [console] Policy zone: DMA32
I0419 09:47:29.509564   12946 init_comm.go:44] [console] Kernel command line: console=ttyS0 panic=1 no_timer_check
I0419 09:47:29.509583   12946 init_comm.go:44] [console] 
I0419 09:47:29.510036   12946 init_comm.go:44] [console] PID hash table entries: 512 (order: 0, 4096 bytes)
I0419 09:47:29.511251   12946 init_comm.go:44] [console] Memory: 119800K/130680K available (4225K kernel code, 452K rwdata, 1280K rodata, 860K init, 752K bss, 10880K reserved, 0K cma-reserved)
I0419 09:47:29.511548   12946 init_comm.go:44] [console] Hierarchical RCU implementation.
I0419 09:47:29.511956   12946 init_comm.go:44] [console]    Build-time adjustment of leaf fanout to 64.
I0419 09:47:29.512447   12946 init_comm.go:44] [console]    RCU restricting CPUs from NR_CPUS=8 to nr_cpu_ids=1.
I0419 09:47:29.512996   12946 init_comm.go:44] [console] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=1
I0419 09:47:29.513267   12946 init_comm.go:44] [console] NR_IRQS:4352 nr_irqs:256 16
I0419 09:47:29.513608   12946 init_comm.go:44] [console]    Offload RCU callbacks from all CPUs
I0419 09:47:29.513939   12946 init_comm.go:44] [console]    Offload RCU callbacks from CPUs: 0.
I0419 09:47:29.514130   12946 init_comm.go:44] [console] Console: colour *CGA 80x25
I0419 09:47:29.514352   12946 init_comm.go:44] [console] console [ttyS0] enabled
I0419 09:47:29.514721   12946 init_comm.go:44] [console] tsc: Detected 3422.964 MHz processor
I0419 09:47:29.515452   12946 init_comm.go:44] [console] Calibrating delay loop (skipped) preset value.. 6845.92 BogoMIPS (lpj=3422964)
I0419 09:47:29.515784   12946 init_comm.go:44] [console] pid_max: default: 32768 minimum: 301
I0419 09:47:29.516009   12946 init_comm.go:44] [console] ACPI: Core revision 20150930
I0419 09:47:29.517357   12946 init_comm.go:44] [console] ACPI: 2 ACPI AML tables successfully acquired and loaded
I0419 09:47:29.517965   12946 init_comm.go:44] [console] Dentry cache hash table entries: 16384 (order: 5, 131072 bytes)
I0419 09:47:29.518576   12946 init_comm.go:44] [console] Inode-cache hash table entries: 8192 (order: 4, 65536 bytes)
I0419 09:47:29.519126   12946 init_comm.go:44] [console] Mount-cache hash table entries: 512 (order: 0, 4096 bytes)
I0419 09:47:29.519715   12946 init_comm.go:44] [console] Mountpoint-cache hash table entries: 512 (order: 0, 4096 bytes)
I0419 09:47:29.520387   12946 init_comm.go:44] [console] Last level iTLB entries: 4KB 512, 2MB 16, 4MB 8
I0419 09:47:29.520903   12946 init_comm.go:44] [console] Last level dTLB entries: 4KB 512, 2MB 128, 4MB 64, 1GB 0
I0419 09:47:29.526938   12946 init_comm.go:44] [console] Freeing SMP alternatives memory: 20K (ffffffff816ac000 - ffffffff816b1000)
I0419 09:47:29.530223   12946 init_comm.go:44] [console] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
I0419 09:47:29.632283   12946 init_comm.go:44] [console] smpboot: CPU0: AMD Phenom(tm) II X4 965 Processor (family: 0x10, model: 0x4, stepping: 0x3)
I0419 09:47:29.633007   12946 init_comm.go:44] [console] Performance Events: Broken PMU hardware detected, using software events only.
I0419 09:47:29.633468   12946 init_comm.go:44] [console] Failed to access perfctr msr (MSR c0010001 is ffffffffffffffff)
I0419 09:47:29.633867   12946 init_comm.go:44] [console] x86: Booted up 1 node, 1 CPUs
I0419 09:47:29.634352   12946 init_comm.go:44] [console] smpboot: Total of 1 processors activated (6845.92 BogoMIPS)
I0419 09:47:29.634739   12946 init_comm.go:44] [console] devtmpfs: initialized
I0419 09:47:29.638642   12946 init_comm.go:44] [console] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
I0419 09:47:29.639045   12946 init_comm.go:44] [console] NET: Registered protocol family 16
I0419 09:47:29.639370   12946 init_comm.go:44] [console] cpuidle: using governor ladder
I0419 09:47:29.639615   12946 init_comm.go:44] [console] cpuidle: using governor menu
I0419 09:47:29.640233   12946 init_comm.go:44] [console] ACPI: bus type PCI registered
I0419 09:47:29.640759   12946 init_comm.go:44] [console] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
I0419 09:47:29.641223   12946 init_comm.go:44] [console] PCI: Using configuration type 1 for base access
I0419 09:47:29.641707   12946 init_comm.go:44] [console] PCI: Using configuration type 1 for extended access
I0419 09:47:29.642586   12946 init_comm.go:44] [console] ACPI: Added _OSI(Module Device)
I0419 09:47:29.642848   12946 init_comm.go:44] [console] ACPI: Added _OSI(Processor Device)
I0419 09:47:29.643182   12946 init_comm.go:44] [console] ACPI: Added _OSI(3.0 _SCP Extensions)
I0419 09:47:29.643602   12946 init_comm.go:44] [console] ACPI: Added _OSI(Processor Aggregator Device)
I0419 09:47:29.645190   12946 init_comm.go:44] [console] ACPI: Interpreter enabled
I0419 09:47:29.645418   12946 init_comm.go:44] [console] ACPI: (supports S0 S5)
I0419 09:47:29.645795   12946 init_comm.go:44] [console] ACPI: Using IOAPIC for interrupt routing
I0419 09:47:29.646552   12946 init_comm.go:44] [console] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
I0419 09:47:29.648988   12946 init_comm.go:44] [console] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
I0419 09:47:29.649672   12946 init_comm.go:44] [console] acpi PNP0A03:00: _OSC: OS supports [ExtendedConfig ASPM ClockPM Segments MSI]
I0419 09:47:29.650218   12946 init_comm.go:44] [console] acpi PNP0A03:00: _OSC failed (AE_NOT_FOUND); disabling ASPM
I0419 09:47:29.650608   12946 init_comm.go:44] [console] acpiphp: Slot [2] registered
I0419 09:47:29.650897   12946 init_comm.go:44] [console] acpiphp: Slot [3] registered
I0419 09:47:29.651184   12946 init_comm.go:44] [console] acpiphp: Slot [4] registered
I0419 09:47:29.651481   12946 init_comm.go:44] [console] acpiphp: Slot [5] registered
I0419 09:47:29.651782   12946 init_comm.go:44] [console] acpiphp: Slot [6] registered
I0419 09:47:29.652068   12946 init_comm.go:44] [console] acpiphp: Slot [7] registered
I0419 09:47:29.652360   12946 init_comm.go:44] [console] acpiphp: Slot [8] registered
I0419 09:47:29.652653   12946 init_comm.go:44] [console] acpiphp: Slot [9] registered
I0419 09:47:29.652952   12946 init_comm.go:44] [console] acpiphp: Slot [10] registered
I0419 09:47:29.653251   12946 init_comm.go:44] [console] acpiphp: Slot [11] registered
I0419 09:47:29.653545   12946 init_comm.go:44] [console] acpiphp: Slot [12] registered
I0419 09:47:29.653836   12946 init_comm.go:44] [console] acpiphp: Slot [13] registered
I0419 09:47:29.654135   12946 init_comm.go:44] [console] acpiphp: Slot [14] registered
I0419 09:47:29.654427   12946 init_comm.go:44] [console] acpiphp: Slot [15] registered
I0419 09:47:29.654726   12946 init_comm.go:44] [console] acpiphp: Slot [16] registered
I0419 09:47:29.655021   12946 init_comm.go:44] [console] acpiphp: Slot [17] registered
I0419 09:47:29.655323   12946 init_comm.go:44] [console] acpiphp: Slot [18] registered
I0419 09:47:29.655638   12946 init_comm.go:44] [console] acpiphp: Slot [19] registered
I0419 09:47:29.655936   12946 init_comm.go:44] [console] acpiphp: Slot [20] registered
I0419 09:47:29.656227   12946 init_comm.go:44] [console] acpiphp: Slot [21] registered
I0419 09:47:29.656528   12946 init_comm.go:44] [console] acpiphp: Slot [22] registered
I0419 09:47:29.656829   12946 init_comm.go:44] [console] acpiphp: Slot [23] registered
I0419 09:47:29.657126   12946 init_comm.go:44] [console] acpiphp: Slot [24] registered
I0419 09:47:29.657415   12946 init_comm.go:44] [console] acpiphp: Slot [25] registered
I0419 09:47:29.657720   12946 init_comm.go:44] [console] acpiphp: Slot [26] registered
I0419 09:47:29.658009   12946 init_comm.go:44] [console] acpiphp: Slot [27] registered
I0419 09:47:29.658313   12946 init_comm.go:44] [console] acpiphp: Slot [28] registered
I0419 09:47:29.658618   12946 init_comm.go:44] [console] acpiphp: Slot [29] registered
I0419 09:47:29.658918   12946 init_comm.go:44] [console] acpiphp: Slot [30] registered
I0419 09:47:29.659212   12946 init_comm.go:44] [console] acpiphp: Slot [31] registered
I0419 09:47:29.659517   12946 init_comm.go:44] [console] PCI host bridge to bus 0000:00
I0419 09:47:29.660083   12946 init_comm.go:44] [console] pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7 window]
I0419 09:47:29.660654   12946 init_comm.go:44] [console] pci_bus 0000:00: root bus resource [io  0x0d00-0xadff window]
I0419 09:47:29.661209   12946 init_comm.go:44] [console] pci_bus 0000:00: root bus resource [io  0xae0f-0xaeff window]
I0419 09:47:29.661768   12946 init_comm.go:44] [console] pci_bus 0000:00: root bus resource [io  0xaf20-0xafdf window]
I0419 09:47:29.662293   12946 init_comm.go:44] [console] pci_bus 0000:00: root bus resource [io  0xafe4-0xffff window]
I0419 09:47:29.662873   12946 init_comm.go:44] [console] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
I0419 09:47:29.663469   12946 init_comm.go:44] [console] pci_bus 0000:00: root bus resource [mem 0x08000000-0xfebfffff window]
I0419 09:47:29.663837   12946 init_comm.go:44] [console] pci_bus 0000:00: root bus resource [bus 00-ff]
I0419 09:47:29.665191   12946 init_comm.go:44] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io  0x01f0-0x01f7]
I0419 09:47:29.665725   12946 init_comm.go:44] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io  0x03f6]
I0419 09:47:29.666296   12946 init_comm.go:44] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io  0x0170-0x0177]
I0419 09:47:29.666850   12946 init_comm.go:44] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io  0x0376]
I0419 09:47:29.667767   12946 init_comm.go:44] [console] pci 0000:00:01.3: quirk: [io  0x0600-0x063f] claimed by PIIX4 ACPI
I0419 09:47:29.668331   12946 init_comm.go:44] [console] pci 0000:00:01.3: quirk: [io  0x0700-0x070f] claimed by PIIX4 SMB
I0419 09:47:29.670367   12946 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11)
I0419 09:47:29.670916   12946 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 *10 11)
I0419 09:47:29.671464   12946 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 10 *11)
I0419 09:47:29.672024   12946 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 10 *11)
I0419 09:47:29.672488   12946 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKS] (IRQs *9)
I0419 09:47:29.673126   12946 init_comm.go:44] [console] ACPI: Enabled 16 GPEs in block 00 to 0F
I0419 09:47:29.673340   12946 init_comm.go:44] [console] vgaarb: loaded
I0419 09:47:29.673664   12946 init_comm.go:44] [console] SCSI subsystem initialized
I0419 09:47:29.673990   12946 init_comm.go:44] [console] dmi: Firmware registration failed.
I0419 09:47:29.674278   12946 init_comm.go:44] [console] PCI: Using ACPI for IRQ routing
I0419 09:47:29.674890   12946 init_comm.go:44] [console] clocksource: Switched to clocksource kvm-clock
I0419 09:47:29.675137   12946 init_comm.go:44] [console] pnp: PnP ACPI init
I0419 09:47:29.675778   12946 init_comm.go:44] [console] pnp: PnP ACPI: found 5 devices
I0419 09:47:29.682420   12946 init_comm.go:44] [console] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
I0419 09:47:29.682982   12946 init_comm.go:44] [console] pci 0000:00:02.0: BAR 1: assigned [mem 0x08000000-0x08000fff]
I0419 09:47:29.683615   12946 init_comm.go:44] [console] pci 0000:00:03.0: BAR 1: assigned [mem 0x08001000-0x08001fff]
I0419 09:47:29.684137   12946 init_comm.go:44] [console] pci 0000:00:04.0: BAR 1: assigned [mem 0x08002000-0x08002fff]
I0419 09:47:29.684652   12946 init_comm.go:44] [console] pci 0000:00:03.0: BAR 0: assigned [io  0x1000-0x103f]
I0419 09:47:29.685112   12946 init_comm.go:44] [console] pci 0000:00:04.0: BAR 0: assigned [io  0x1040-0x107f]
I0419 09:47:29.685580   12946 init_comm.go:44] [console] pci 0000:00:02.0: BAR 0: assigned [io  0x1080-0x109f]
I0419 09:47:29.686016   12946 init_comm.go:44] [console] pci 0000:00:01.1: BAR 4: assigned [io  0x10a0-0x10af]
I0419 09:47:29.686342   12946 init_comm.go:44] [console] NET: Registered protocol family 2
I0419 09:47:29.686951   12946 init_comm.go:44] [console] TCP established hash table entries: 1024 (order: 1, 8192 bytes)
I0419 09:47:29.687482   12946 init_comm.go:44] [console] TCP bind hash table entries: 1024 (order: 2, 16384 bytes)
I0419 09:47:29.687922   12946 init_comm.go:44] [console] TCP: Hash tables configured (established 1024 bind 1024)
I0419 09:47:29.688351   12946 init_comm.go:44] [console] UDP hash table entries: 256 (order: 1, 8192 bytes)
I0419 09:47:29.688823   12946 init_comm.go:44] [console] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes)
I0419 09:47:29.689187   12946 init_comm.go:44] [console] NET: Registered protocol family 1
I0419 09:47:29.689615   12946 init_comm.go:44] [console] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
I0419 09:47:29.690066   12946 init_comm.go:44] [console] pci 0000:00:01.0: PIIX3: Enabling Passive Release
I0419 09:47:29.690584   12946 init_comm.go:44] [console] pci 0000:00:01.0: Activating ISA DMA hang workarounds
I0419 09:47:29.691076   12946 init_comm.go:44] [console] Trying to unpack rootfs image as initramfs...
I0419 09:47:29.705316   12946 init_comm.go:44] [console] Freeing initrd memory: 960K (ffff880007f10000 - ffff880008000000)
I0419 09:47:29.706017   12946 init_comm.go:44] [console] futex hash table entries: 256 (order: 2, 16384 bytes)
I0419 09:47:29.706762   12946 init_comm.go:44] [console] SGI XFS with ACLs, security attributes, no debug enabled
I0419 09:47:29.707274   12946 init_comm.go:44] [console] 9p: Installing v9fs 9p2000 file system support
I0419 09:47:29.708337   12946 init_comm.go:44] [console] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 254)
I0419 09:47:29.708627   12946 init_comm.go:44] [console] io scheduler noop registered
I0419 09:47:29.708998   12946 init_comm.go:44] [console] io scheduler cfq registered (default)
I0419 09:47:29.709468   12946 init_comm.go:44] [console] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
I0419 09:47:29.710044   12946 init_comm.go:44] [console] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
I0419 09:47:29.710697   12946 init_comm.go:44] [console] Warning: Processor Platform Limit event detected, but not handled.
I0419 09:47:29.711148   12946 init_comm.go:44] [console] Consider compiling CPUfreq support into your kernel.
I0419 09:47:29.711897   12946 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKB] enabled at IRQ 10
I0419 09:47:29.712390   12946 init_comm.go:44] [console] virtio-pci 0000:00:02.0: enabling device (0000 -> 0003)
I0419 09:47:29.713324   12946 init_comm.go:44] [console] virtio-pci 0000:00:02.0: virtio_pci: leaving for legacy driver
I0419 09:47:29.714241   12946 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 11
I0419 09:47:29.714738   12946 init_comm.go:44] [console] virtio-pci 0000:00:03.0: enabling device (0000 -> 0003)
I0419 09:47:29.715814   12946 init_comm.go:44] [console] virtio-pci 0000:00:03.0: virtio_pci: leaving for legacy driver
I0419 09:47:29.716854   12946 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 11
I0419 09:47:29.717351   12946 init_comm.go:44] [console] virtio-pci 0000:00:04.0: enabling device (0000 -> 0003)
I0419 09:47:29.718620   12946 init_comm.go:44] [console] virtio-pci 0000:00:04.0: virtio_pci: leaving for legacy driver
I0419 09:47:29.719703   12946 init_comm.go:44] [console] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
I0419 09:47:29.743090   12946 init_comm.go:44] [console] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
I0419 09:47:29.771025   12946 init_comm.go:44] [console] brd: module loaded
I0419 09:47:29.771305   12946 init_comm.go:44] [console] loop: module loaded
I0419 09:47:29.772021   12946 init_comm.go:44] [console] scsi host0: Virtio SCSI HBA
I0419 09:47:29.805216   12946 init_comm.go:44] [console] e1000: Intel(R) PRO/1000 Network Driver - version 7.3.21-k8-NAPI
I0419 09:47:29.805246   12946 init_comm.go:44] [console] e1000: Copyright (c) 1999-2006 Intel Corporation.
I0419 09:47:29.805255   12946 init_comm.go:44] [console] NET: Registered protocol family 10
I0419 09:47:29.805263   12946 init_comm.go:44] [console] NET: Registered protocol family 17
I0419 09:47:29.805271   12946 init_comm.go:44] [console] 9pnet: Installing 9P2000 support
I0419 09:47:29.805278   12946 init_comm.go:44] [console] registered taskstats version 1
I0419 09:47:29.805790   12946 init_comm.go:44] [console] Freeing unused kernel memory: 860K (ffffffff815d5000 - ffffffff816ac000)
I0419 09:47:29.806894   12946 init_comm.go:44] [console] create directory /dev
I0419 09:47:29.807125   12946 init_comm.go:44] [console] create directory /sys
I0419 09:47:29.807381   12946 init_comm.go:44] [console] create directory /proc
I0419 09:47:29.807578   12946 init_comm.go:44] [console] uptime 0.19 0.01
I0419 09:47:29.807649   12946 init_comm.go:44] [console] 
I0419 09:47:29.807917   12946 init_comm.go:44] [console] create directory /dev/pts
I0419 09:47:29.808114   12946 init_comm.go:44] [console] create directory /dev
I0419 09:47:29.808449   12946 init_comm.go:44] [console] open hyper channel /dev/vport0p1
I0419 09:47:29.808883   12946 init_comm.go:44] [console] send ready message
I0419 09:47:29.809102   12946 init_comm.go:44] [console] hyper send type 8, len 0
I0419 09:47:29.809351   12946 init_comm.go:82] read 8/8 [length = 0]
I0419 09:47:29.809411   12946 init_comm.go:86] data length is 8
I0419 09:47:29.809448   12946 init_comm.go:119] Get init ready message
I0419 09:47:29.809579   12946 hypervisor.go:29] main event loop got message 5(EVENT_INIT_CONNECTED)
I0419 09:47:29.809602   12946 vm_states.go:529] begin to wait vm commands
I0419 09:47:29.809605   12946 init_comm.go:72] trying to read 8 bytes
I0419 09:47:29.809831   12946 init_comm.go:44] [console] channel sh.hyper.channel.1, directory sh.hyper.channel.0
I0419 09:47:29.809906   12946 init_comm.go:44] [console] 
I0419 09:47:29.810008   12946 init_comm.go:44] [console] open hyper channel /dev/vport0p2
I0419 09:47:29.810578   12946 init_comm.go:44] [console] hyper_init_event hyper channel event 0x613578, ops 0x613320, fd 4
I0419 09:47:29.810891   12946 init_comm.go:44] [console] hyper_add_event add event fd 4, 0x613320
I0419 09:47:29.811327   12946 init_comm.go:44] [console] hyper_init_event hyper ttyfd event 0x613540, ops 0x6132e0, fd 5
I0419 09:47:29.811655   12946 init_comm.go:44] [console] hyper_add_event add event fd 5, 0x6132e0
I0419 09:47:29.812102   12946 init_comm.go:44] [console] hyper_init_event hyper signal event 0x613508, ops 0x613360, fd 3
I0419 09:47:29.812379   12946 init_comm.go:44] [console] hyper_add_event add event fd 3, 0x613360
I0419 09:47:30.706081   12946 init_comm.go:44] [console] tsc: Refined TSC clocksource calibration: 3423.033 MHz
I0419 09:47:30.707036   12946 init_comm.go:44] [console] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x31574d6cac4, max_idle_ns: 440795369633 ns
DEBU[2110] Increasing token expiration to: 0 seconds    
DEBU[2111] Pulling ref from V2 registry: busybox:latest 
DEBU[2111] pulling blob "sha256:385e281300cc6d88bdd155e0931fbdfbb1801c2b0265340a40481ee2b733ae66" 
DEBU[2111] pulling blob "sha256:a3ed95caeb02ffe68cdd9fd84406680ae93d633cb16422d00e8a7c22955b46d4" 
DEBU[2111] Downloaded a3ed95caeb02 to tempfile /mnt/tank/HYPER/tmp/GetImageBlob044496314 
DEBU[2112] Downloaded 385e281300cc to tempfile /mnt/tank/HYPER/tmp/GetImageBlob824912849 
DEBU[2112] Applied tar sha256:1834950e52ce4d5a88a1bbd131c537f4d0e56d10ff0dd69e66be3b7dfa9df7e6 to 9305b0bc3c7251c6951f6753becb223e26dda490c7308aacf3307bc6475b82f5, size: 1112820 
DEBU[2112] Applied tar sha256:5f70bf18a086007016e948b04aed3b82103a36bea41755b6cddfaf10ace3c6ef to 0404b7906f00f8c1ce6afacbfe9dd4eae9ab961cc98671004303320a669a2fc1, size: 0 
I0419 09:47:33.428806   12946 server.go:152] Calling POST /v0.5.0/pod/create
I0419 09:47:33.428874   12946 pod_routes.go:76] Args string is {"id":"busybox-5112358495","hostname":"","containers":[{"name":"busybox-5112358495","image":"busybox","command":[],"workdir":"/","entrypoint":[],"ports":[],"envs":[],"volumes":[],"files":[],"restartPolicy":"never"}],"resource":{"vcpu":1,"memory":128},"files":[],"volumes":[],"labels":{},"log":{"type":"","config":{}},"tty":false,"type":"","RestartPolicy":""}, autoremove false
I0419 09:47:33.428910   12946 run.go:45] podArgs: {"id":"busybox-5112358495","hostname":"","containers":[{"name":"busybox-5112358495","image":"busybox","command":[],"workdir":"/","entrypoint":[],"ports":[],"envs":[],"volumes":[],"files":[],"restartPolicy":"never"}],"resource":{"vcpu":1,"memory":128},"files":[],"volumes":[],"labels":{},"log":{"type":"","config":{}},"tty":false,"type":"","RestartPolicy":""}
I0419 09:47:33.429367   12946 daemondb.go:82] try get container list for pod pod-OZyNoqIJiX
I0419 09:47:33.429412   12946 pod.go:229] loaded containers for pod pod-OZyNoqIJiX: []
DEBU[2112] container mounted via layerStore: /mnt/tank/HYPER/aufs/mnt/8772dfdfe88b2a962ae1cc4275632c87398778e329d4cdef59f9ad2f96d4af30 
I0419 09:47:33.466946   12946 pod.go:318] create container cd1b8f67f793383fb031caf6e61fcd2825d2d83805535653e5e8f5a53c95da58
I0419 09:47:33.466999   12946 pod.go:356] container name busybox-5112358495, image busybox
I0419 09:47:33.467049   12946 pod.go:373] container info config &{cd1b8f67f793   false false false map[]  false false false [] 0xc821bf16c0 false busybox map[]  <nil> true  [] map[] }, Cmd [sh], Args []
I0419 09:47:33.467092   12946 pod.go:396] Container Info is 
&{cd1b8f67f793383fb031caf6e61fcd2825d2d83805535653e5e8f5a53c95da58 8772dfdfe88b2a962ae1cc4275632c87398778e329d4cdef59f9ad2f96d4af30     [] [sh] map[] true}
I0419 09:47:33.467430   12946 daemondb.go:91] try set container list for pod pod-OZyNoqIJiX: [cd1b8f67f793383fb031caf6e61fcd2825d2d83805535653e5e8f5a53c95da58]
I0419 09:47:33.468835   12946 server.go:152] Calling POST /v0.5.0/pod/start
I0419 09:47:33.468959   12946 run.go:78] pod:pod-OZyNoqIJiX, vm:vm-TcTOqfpdJk
I0419 09:47:33.469010   12946 pod.go:71] lock pod for operation start
I0419 09:47:33.469053   12946 pod.go:74] successfully lock pod for operation start
I0419 09:47:33.469093   12946 vm.go:157] find vm:vm-TcTOqfpdJk
I0419 09:47:33.469187   12946 pod.go:709] container ID: cd1b8f67f793383fb031caf6e61fcd2825d2d83805535653e5e8f5a53c95da58, mountId 8772dfdfe88b2a962ae1cc4275632c87398778e329d4cdef59f9ad2f96d4af30
I0419 09:47:33.471049   12946 volumes.go:28] trying to bind dir /mnt/tank/HYPER/hosts/pod-OZyNoqIJiX/hosts to /var/run/hyper/vm-TcTOqfpdJk/share_dir/RWEhfAenSg
I0419 09:47:33.471273   12946 tank.go:77] dir /mnt/tank/HYPER/hosts/pod-OZyNoqIJiX/hosts is bound to RWEhfAenSg
I0419 09:47:33.471340   12946 pod.go:840] configuring log driver [json-file] for pod-OZyNoqIJiX
I0419 09:47:33.471388   12946 pod.go:859] configure container log to /var/run/hyper/Pods/pod-OZyNoqIJiX/cd1b8f67f793383fb031caf6e61fcd2825d2d83805535653e5e8f5a53c95da58-json.log
I0419 09:47:33.471477   12946 pod.go:865] configured logger for pod-OZyNoqIJiX/cd1b8f67f793383fb031caf6e61fcd2825d2d83805535653e5e8f5a53c95da58 (/busybox-5112358495)
I0419 09:47:33.471702   12946 vm.go:180] hyperHandlePodEvent pod pod-OZyNoqIJiX, vm vm-TcTOqfpdJk
I0419 09:47:33.471768   12946 hypervisor.go:29] main event loop got message 34(COMMAND_ATTACH)
I0419 09:47:33.471812   12946 vm_states.go:281] attachment log-aj2qdmnj is pending
I0419 09:47:33.471846   12946 hypervisor.go:29] main event loop got message 23(COMMAND_RUN_POD)
I0419 09:47:33.471881   12946 vm_states.go:556] got spec, prepare devices
I0419 09:47:33.471971   12946 context.go:244] #0 Container Info:
I0419 09:47:33.472106   12946 context.go:247] 
{
...|    "Id": "cd1b8f67f793383fb031caf6e61fcd2825d2d83805535653e5e8f5a53c95da58",
...|    "MountId": "8772dfdfe88b2a962ae1cc4275632c87398778e329d4cdef59f9ad2f96d4af30",
...|    "Rootfs": "",
...|    "Image": "/8772dfdfe88b2a962ae1cc4275632c87398778e329d4cdef59f9ad2f96d4af30/rootfs",
...|    "Fstype": "dir",
...|    "Workdir": "",
...|    "Entrypoint": null,
...|    "Cmd": [
...|        "sh"
...|    ],
...|    "Envs": {},
...|    "Initialize": true
...|}
I0419 09:47:33.472184   12946 devicemap.go:235] insert volume etchosts-volume to /etc/hosts on 0
I0419 09:47:33.472346   12946 vm_states.go:72] initial vm spec: {
        "hostname": "busybox-5112358495",
        "containers": [
            {
                "id": "cd1b8f67f793383fb031caf6e61fcd2825d2d83805535653e5e8f5a53c95da58",
                "rootfs": "",
                "image": "/8772dfdfe88b2a962ae1cc4275632c87398778e329d4cdef59f9ad2f96d4af30/rootfs",
                "fsmap": [
                    {
                        "source": "RWEhfAenSg",
                        "path": "/etc/hosts",
                        "readOnly": false,
                        "dockerVolume": false
                    }
                ],
                "process": {
                    "terminal": false,
                    "stdio": 1,
                    "stderr": 2,
                    "args": [
                        "sh"
                    ],
                    "workdir": "/"
                },
                "restartPolicy": "never",
                "initialize": true
            }
        ],
        "shareDir": "share_dir"
    }
I0419 09:47:33.472432   12946 context.go:176] found container cd1b8f67f793383fb031caf6e61fcd2825d2d83805535653e5e8f5a53c95da58 at 0
I0419 09:47:33.472475   12946 vm_states.go:80] attach pending client log-aj2qdmnj for cd1b8f67f793383fb031caf6e61fcd2825d2d83805535653e5e8f5a53c95da58
I0419 09:47:33.472514   12946 vm_states.go:304] Connecting tty for cd1b8f67f793383fb031caf6e61fcd2825d2d83805535653e5e8f5a53c95da58 on session 1
I0419 09:47:33.472618   12946 context.go:212] VM vm-TcTOqfpdJk: state change from INIT to 'STARTING'
I0419 09:47:33.475178   12946 hypervisor.go:29] main event loop got message 13(EVENT_INTERFACE_ADD)
I0419 09:47:33.475258   12946 qmp_wrapper.go:90] send net to qemu at 22
I0419 09:47:33.475346   12946 qmp_handler.go:296] got new session
I0419 09:47:33.475440   12946 qmp_handler.go:225] Begin process command session
I0419 09:47:33.475512   12946 qmp_handler.go:238] send cmd with scm (24 bytes) (1) {"execute":"getfd","arguments":{"fdname":"fdeth0"}}
I0419 09:47:33.477128   12946 qmp_handler.go:103] got a message {"return": {}}
I0419 09:47:33.477479   12946 qmp_handler.go:243] sending command (1) {"execute":"netdev_add","arguments":{"fd":"fdeth0","id":"eth0","type":"tap"}}
I0419 09:47:33.479921   12946 qmp_handler.go:103] got a message {"return": {}}
I0419 09:47:33.480094   12946 qmp_handler.go:243] sending command (1) {"execute":"device_add","arguments":{"addr":"0x5","bus":"pci.0","driver":"virtio-net-pci","id":"eth0","mac":"52:54:bf:6c:f5:31","netdev":"eth0"}}
I0419 09:47:33.487109   12946 qmp_handler.go:103] got a message {"return": {}}
I0419 09:47:33.487301   12946 qmp_handler.go:302] session finished, buffer size 1
I0419 09:47:33.487343   12946 qmp_handler.go:305] success 
I0419 09:47:33.487361   12946 hypervisor.go:29] main event loop got message 15(EVENT_INTERFACE_INSERTED)
I0419 09:47:33.487393   12946 vm_states.go:585] device ready, could run pod.
I0419 09:47:33.487468   12946 init_comm.go:163] got cmd:1
I0419 09:47:33.487487   12946 init_comm.go:244] send command 1 to init, payload: '{"hostname":"busybox-5112358495","containers":[{"id":"cd1b8f67f793383fb031caf6e61fcd2825d2d83805535653e5e8f5a53c95da58","rootfs":"","image":"/8772dfdfe88b2a962ae1cc4275632c87398778e329d4cdef59f9ad2f96d4af30/rootfs","fsmap":[{"source":"RWEhfAenSg","path":"/etc/hosts","readOnly":false,"dockerVolume":false}],"process":{"terminal":false,"stdio":1,"stderr":2,"args":["sh"],"workdir":"/"},"restartPolicy":"never","initialize":true}],"interfaces":[{"device":"eth0","ipAddress":"192.168.123.3","netMask":"255.255.255.0"}],"routes":[{"dest":"0.0.0.0/0","gateway":"192.168.123.1","device":"eth0"}],"shareDir":"share_dir"}'.
I0419 09:47:33.487525   12946 init_comm.go:257] write 512 to init, payload: 'm{"hostname":"busybox-5112358495","containers":[{"id":"cd1b8f67f793383fb031caf6e61fcd2825d2d83805535653e5e8f5a53c95da58","rootfs":"","image":"/8772dfdfe88b2a962ae1cc4275632c87398778e329d4cdef59f9ad2f96d4af30/rootfs","fsmap":[{"source":"RWEhfAenSg","path":"/etc/hosts","readOnly":false,"dockerVolume":false}],"process":{"terminal":false,"stdio":1,"stderr":2,"args":["sh"],"workdir":"/"},"restartPolicy":"never","initialize":true}],"interfaces":[{"device":"eth0","ipAddress":"192.168.123.3","netMask":"255.2'.
I0419 09:47:33.487585   12946 init_comm.go:262] message sent, set pong timer
I0419 09:47:33.488326   12946 init_comm.go:44] [console] hyper_loop epoll_wait 1
I0419 09:47:33.489069   12946 init_comm.go:44] [console] hyper_handle_event get event 1, de 0x613578, fd 4. ops 0x613320
I0419 09:47:33.489709   12946 init_comm.go:44] [console] hyper_handle_event event EPOLLIN, de 0x613578, fd 4, 0x613320
I0419 09:47:33.489970   12946 init_comm.go:44] [console] hyper_event_read
I0419 09:47:33.494687   12946 init_comm.go:82] read 8/8 [length = 0]
I0419 09:47:33.494715   12946 init_comm.go:86] data length is 12
I0419 09:47:33.494728   12946 init_comm.go:72] trying to read 4 bytes
I0419 09:47:33.494743   12946 init_comm.go:82] read 12/12 [length = 12]
I0419 09:47:33.494759   12946 init_comm.go:72] trying to read 8 bytes
I0419 09:47:33.494774   12946 init_comm.go:163] got cmd:14
I0419 09:47:33.494787   12946 init_comm.go:231] get command NEXT
I0419 09:47:33.494799   12946 init_comm.go:234] send 512, receive 8
I0419 09:47:33.494690   12946 init_comm.go:44] [console] already read 8 bytes data
I0419 09:47:33.494819   12946 init_comm.go:44] [console] hyper send type 14, len 4
I0419 09:47:33.494832   12946 init_comm.go:44] [console] get length 621
I0419 09:47:33.494843   12946 init_comm.go:44] [console] read 504 bytes data, total data 512
I0419 09:47:33.494858   12946 init_comm.go:44] [console] hyper send type 14, len 4
I0419 09:47:33.494870   12946 init_comm.go:44] [console] pci 0000:00:05.0: BAR 6: assigned [mem 0x08040000-0x0807ffff pref]
I0419 09:47:33.494882   12946 init_comm.go:44] [console] pci 0000:00:05.0: BAR 1: assigned [mem 0x08003000-0x08003fff]
I0419 09:47:33.494941   12946 init_comm.go:44] [console] pci 0000:00:05.0: BAR 0: assigned [io  0x10c0-0x10df]
I0419 09:47:33.496030   12946 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 10
I0419 09:47:33.496921   12946 init_comm.go:44] [console] virtio-pci 0000:00:05.0: enabling device (0000 -> 0003)
I0419 09:47:33.499226   12946 init_comm.go:44] [console] virtio-pci 0000:00:05.0: virtio_pci: leaving for legacy driver
I0419 09:47:33.500872   12946 init_comm.go:82] read 8/8 [length = 0]
I0419 09:47:33.500940   12946 init_comm.go:86] data length is 12
I0419 09:47:33.500971   12946 init_comm.go:72] trying to read 4 bytes
I0419 09:47:33.501018   12946 init_comm.go:82] read 12/12 [length = 12]
I0419 09:47:33.501076   12946 init_comm.go:72] trying to read 8 bytes
I0419 09:47:33.501123   12946 init_comm.go:163] got cmd:14
I0419 09:47:33.501165   12946 init_comm.go:231] get command NEXT
I0419 09:47:33.501201   12946 init_comm.go:234] send 512, receive 512
I0419 09:47:33.501264   12946 init_comm.go:257] write 109 to init, payload: '55.255.0"}],"routes":[{"dest":"0.0.0.0/0","gateway":"192.168.123.1","device":"eth0"}],"shareDir":"share_dir"}'.
I0419 09:47:33.501602   12946 init_comm.go:44] [console] hyper_loop epoll_wait 1
I0419 09:47:33.502069   12946 init_comm.go:44] [console] hyper_handle_event get event 1, de 0x613578, fd 4. ops 0x613320
I0419 09:47:33.502465   12946 init_comm.go:44] [console] hyper_handle_event event EPOLLIN, de 0x613578, fd 4, 0x613320
I0419 09:47:33.502674   12946 init_comm.go:44] [console] hyper_event_read
I0419 09:47:33.502823   12946 init_comm.go:44] [console] get length 621
I0419 09:47:33.503303   12946 init_comm.go:44] [console] read 109 bytes data, total data 621
I0419 09:47:33.503686   12946 init_comm.go:44] [console] hyper send type 14, len 4
I0419 09:47:33.503737   12946 init_comm.go:82] read 8/8 [length = 0]
I0419 09:47:33.503759   12946 init_comm.go:86] data length is 12
I0419 09:47:33.503768   12946 init_comm.go:72] trying to read 4 bytes
I0419 09:47:33.503820   12946 init_comm.go:82] read 12/12 [length = 12]
I0419 09:47:33.503877   12946 init_comm.go:72] trying to read 8 bytes
I0419 09:47:33.503975   12946 init_comm.go:163] got cmd:14
I0419 09:47:33.504016   12946 init_comm.go:231] get command NEXT
I0419 09:47:33.504057   12946 init_comm.go:234] send 109, receive 109
I0419 09:47:33.515784   12946 init_comm.go:44] [console] 0 0 0 1 0 0 2 6d 7b 22 68 6f 73 74 6e 61 6d 65 22 3a 22 62 75 73 79 62 6f 78 2d 35 31 31 32 33 35 38 34 39 35 22 2c 22 63 6f 6e 74 61 69 6e 65 72 73 22 3a 5b 7b 22 69 64 22 3a 22 63 64 31 62 38 66 36 37 66 37 39 33 33 38 33 66 62 30 33 31 63 61 66 36 65 36 31 66 63 64 32 38 32 35 64 32 64 38 33 38 30 35 35 33 35 36 35 33 65 35 65 38 66 35 61 35 33 63 39 35 64 61 35 38 22 2c 22 72 6f 6f 74 66 73 22 3a 22 22 2c 22 69 6d 61 67 65 22 3a 22 2f 38 37 37 32 64 66 64 66 65 38 38 62 32 61 39 36 32 61 65 31 63 63 34 32 37 35 36 33 32 63 38 37 33 39 38 37 37 38 65 33 32 39 64 34 63 64 65 66 35 39 66 39 61 64 32 66 39 36 64 34 61 66 33 30 2f 72 6f 6f 74 66 73 22 2c 22 66 73 6d 61 70 22 3a 5b 7b 22 73 6f 75 72 63 65 22 3a 22 52 57 45 68 66 41 65 6e 53 67 22 2c 22 70 61 74 68 22 3a 22 2f 65 74 63 2f 68 6f 73 74 73 22 2c 22 72 65 61 64 4f 6e 6c 79 22 3a 66 61 6c 73 65 2c 22 64 6f 63 6b 65 72 56 6f 6c 75 6d 65 22 3a 66 61 6c 73 65 7d 5d 2c 22 70 72 6f 63 65 73 73 22 3a 7b 22 74 65 72 6d 69 6e 61 6c 22 3a 66 61 6c 73 65 2c 22 73 74 64 69 6f 22 3a 31 2c 22 73 74 64 65 72 72 22 3a 32 2c 22 61 72 67 73 22 3a 5b 22 73 68 22 5d 2c 22 77 6f 72 6b 64 69 72 22 3a 22 2f 22 7d 2c 22 72 65 73 74 61 72 74 50 6f 6c 69 63 79 22 3a 22 6e 65 76 65 72 22 2c 22 69 6e 69 74 69 61 6c 69 7a 65 22 3a 74 72 75 65 7d 5d 2c 22 69 6e 74 65 72 66 61 63 65 73 22 3a 5b 7b 22 64 65 76 69 63 65 22 3a 22 65 74 68 30 22 2c 22 69 70 41 64 64 72 65 73 73 22 3a 22 31 39 32 2e 31 36 38 2e 31 32 33 2e 33 22 2c 22 6e 65 74 4d 61 73 6b 22 3a 22 32 35 35 2e 32 35 35 2e 32 35 35 2e 30 22 7d 5d 2c 22 72 6f 75 74 65 73 22 3a 5b 7b 22 64 65 73 74 22 3a 22 30 2e 30 2e 30 2e 30 2f 30 22 2c 22 67 61 74 65 77 61 79 22 3a 22 31 39 32 2e 31 36 38 2e 31 32 33 2e 31 22 2c 22 64 65 76 69 63 65 22 3a 22 65 74 68 30 22 7d 5d 2c 22 73 68 61 72 65 44 69 72 22 3a 22 73 68 61 72 65 5f 64 69 72 22 7d 
I0419 09:47:33.516114   12946 init_comm.go:44] [console]  hyper_channel_handle, type 1, len 621
I0419 09:47:33.516775   12946 init_comm.go:44] [console] online_cpu()
I0419 09:47:33.516953   12946 init_comm.go:44] [console] online_memory()
I0419 09:47:33.520754   12946 init_comm.go:44] [console] call hyper_start_pod, json {"hostname":"busybox-5112358495","containers":[{"id":"cd1b8f67f793383fb031caf6e61fcd2825d2d83805535653e5e8f5a53c95da58","rootfs":"","image":"/8772dfdfe88b2a962ae1cc4275632c87398778e329d4cdef59f9ad2f96d4af30/rootfs","fsmap":[{"source":"RWEhfAenSg","path":"/etc/hosts","readOnly":false,"dockerVolume":false}],"process":{"terminal":false,"stdio":1,"stderr":2,"args":["sh"],"workdir":"/"},"restartPolicy":"never","initialize":true}],"interfaces":[{"device":"eth0","ipAddress":"192.168.123.3","netMask":"255.255.255.0"}],"routes":[{"dest":"0.0.0.0/0","gateway":"192.168.123.1","device":"eth0"}],"shareDir":"share_dir"}, len 613
I0419 09:47:33.524338   12946 init_comm.go:44] [console] call hyper_start_pod, json {"hostname":"busybox-5112358495","containers":[{"id":"cd1b8f67f793383fb031caf6e61fcd2825d2d83805535653e5e8f5a53c95da58","rootfs":"","image":"/8772dfdfe88b2a962ae1cc4275632c87398778e329d4cdef59f9ad2f96d4af30/rootfs","fsmap":[{"source":"RWEhfAenSg","path":"/etc/hosts","readOnly":false,"dockerVolume":false}],"process":{"terminal":false,"stdio":1,"stderr":2,"args":["sh"],"workdir":"/"},"restartPolicy":"never","initialize":true}],"interfaces":[{"device":"eth0","ipAddress":"192.168.123.3","netMask":"255.255.255.0"}],"routes":[{"dest":"0.0.0.0/0","gateway":"192.168.123.1","device":"eth0"}],"shareDir":"share_dir"}, len 613
I0419 09:47:33.524636   12946 init_comm.go:44] [console] jsmn parse successed, n is 60
I0419 09:47:33.524803   12946 init_comm.go:44] [console] token 0, type is 1, size is 5
I0419 09:47:33.525029   12946 init_comm.go:44] [console] token 1, type is 3, size is 1
I0419 09:47:33.525265   12946 init_comm.go:44] [console] hostname is busybox-5112358495
I0419 09:47:33.525578   12946 init_comm.go:44] [console] token 3, type is 3, size is 1
I0419 09:47:33.525711   12946 init_comm.go:44] [console] container count 1
I0419 09:47:33.525902   12946 init_comm.go:44] [console] next container 7
I0419 09:47:33.526022   12946 init_comm.go:44] [console] 1 name id
I0419 09:47:33.526491   12946 init_comm.go:44] [console] container id cd1b8f67f793383fb031caf6e61fcd2825d2d83805535653e5e8f5a53c95da58
I0419 09:47:33.526681   12946 init_comm.go:44] [console] 3 name rootfs
I0419 09:47:33.526830   12946 init_comm.go:44] [console] container rootfs 
I0419 09:47:33.526993   12946 init_comm.go:44] [console] 5 name image
I0419 09:47:33.527549   12946 init_comm.go:44] [console] container image /8772dfdfe88b2a962ae1cc4275632c87398778e329d4cdef59f9ad2f96d4af30/rootfs
I0419 09:47:33.527691   12946 init_comm.go:44] [console] 7 name fsmap
I0419 09:47:33.527869   12946 init_comm.go:44] [console] fsmap num 1
I0419 09:47:33.528085   12946 init_comm.go:44] [console] maps 0 source RWEhfAenSg
I0419 09:47:33.528288   12946 init_comm.go:44] [console] maps 0 path /etc/hosts
I0419 09:47:33.528461   12946 init_comm.go:44] [console] maps 0 readonly 0
I0419 09:47:33.528681   12946 init_comm.go:44] [console] in maps incorrect dockerVolume
I0419 09:47:33.528875   12946 init_comm.go:44] [console] parse pod json failed
I0419 09:47:33.529050   12946 init_comm.go:44] [console] uptime 3.91 3.68
I0419 09:47:33.529126   12946 init_comm.go:44] [console] 
I0419 09:47:33.529350   12946 init_comm.go:44] [console] hyper send type 10, len 0
I0419 09:47:33.529439   12946 init_comm.go:82] read 8/8 [length = 0]
I0419 09:47:33.529461   12946 init_comm.go:86] data length is 8
I0419 09:47:33.529477   12946 init_comm.go:72] trying to read 8 bytes
I0419 09:47:33.529488   12946 init_comm.go:163] got cmd:10
I0419 09:47:33.529501   12946 init_comm.go:186] ack got, clear pong timer
I0419 09:47:33.529519   12946 hypervisor.go:29] main event loop got message 44(ERROR_CMD_FAIL)
E0419 09:47:33.529553   12946 vm_states.go:358] Shutting down because of an exception: Start POD failed
I0419 09:47:33.529578   12946 context.go:212] VM vm-TcTOqfpdJk: state change from STARTING to 'TERMINATING'
E0419 09:47:33.529606   12946 vm_states.go:635] Start POD failed
I0419 09:47:33.529609   12946 init_comm.go:163] got cmd:4
I0419 09:47:33.529635   12946 vm.go:262] Get the response from VM, VM id is vm-TcTOqfpdJk!
I0419 09:47:33.529682   12946 pod.go:83] unlock pod for operation start
I0419 09:47:33.529694   12946 pod.go:86] successfully unlock pod for operation start
E0419 09:47:33.529704   12946 run.go:88] VM vm-TcTOqfpdJk start failed with code 7: Start POD failed
E0419 09:47:33.529716   12946 server.go:170] Handler for POST /v0.5.0/pod/start returned error: VM vm-TcTOqfpdJk start failed with code 7: Start POD failed
I0419 09:47:33.529645   12946 init_comm.go:244] send command 4 to init, payload: ''.
I0419 09:47:33.529822   12946 init_comm.go:257] write 8 to init, payload: ''.
I0419 09:47:33.529841   12946 init_comm.go:262] message sent, set pong timer
I0419 09:47:33.530277   12946 server.go:152] Calling DELETE /v0.5.0/vm
I0419 09:47:33.530349   12946 hypervisor.go:29] main event loop got message 26(COMMAND_SHUTDOWN)
I0419 09:47:33.530383   12946 vm.go:81] Got response: 16: unexpected event during terminating
I0419 09:47:33.530410   12946 init_comm.go:44] [console] hyper_loop epoll_wait 1
I0419 09:47:33.530673   12946 init_comm.go:44] [console] hyper_handle_event get event 1, de 0x613578, fd 4. ops 0x613320
I0419 09:47:33.531063   12946 init_comm.go:44] [console] hyper_handle_event event EPOLLIN, de 0x613578, fd 4, 0x613320
I0419 09:47:33.531218   12946 init_comm.go:44] [console] hyper_event_read
I0419 09:47:33.531560   12946 init_comm.go:44] [console] already read 8 bytes data
I0419 09:47:33.531759   12946 init_comm.go:44] [console] hyper send type 14, len 4
I0419 09:47:33.531921   12946 init_comm.go:82] read 8/8 [length = 0]
I0419 09:47:33.531937   12946 init_comm.go:86] data length is 12
I0419 09:47:33.531948   12946 init_comm.go:72] trying to read 4 bytes
I0419 09:47:33.531962   12946 init_comm.go:82] read 12/12 [length = 12]
I0419 09:47:33.531980   12946 init_comm.go:72] trying to read 8 bytes
I0419 09:47:33.531995   12946 init_comm.go:163] got cmd:14
I0419 09:47:33.532008   12946 init_comm.go:231] get command NEXT
I0419 09:47:33.532025   12946 init_comm.go:234] send 8, receive 8
I0419 09:47:33.532007   12946 init_comm.go:44] [console] get length 8
I0419 09:47:33.532157   12946 init_comm.go:44] [console] 0 0 0 4 0 0 0 8 
I0419 09:47:33.532426   12946 init_comm.go:44] [console]  hyper_channel_handle, type 4, len 8
I0419 09:47:33.532639   12946 init_comm.go:44] [console] get DESTROYPOD message
I0419 09:47:33.532841   12946 init_comm.go:44] [console] hyper send type 9, len 0
I0419 09:47:33.532901   12946 init_comm.go:82] read 8/8 [length = 0]
I0419 09:47:33.532917   12946 init_comm.go:86] data length is 8
I0419 09:47:33.532935   12946 init_comm.go:72] trying to read 8 bytes
I0419 09:47:33.532950   12946 init_comm.go:163] got cmd:9
I0419 09:47:33.532965   12946 init_comm.go:167] got response of shutdown command, last round of command to init
I0419 09:47:33.532980   12946 init_comm.go:186] ack got, clear pong timer
I0419 09:47:33.532995   12946 hypervisor.go:29] main event loop got message 37(COMMAND_ACK)
I0419 09:47:33.533009   12946 vm_states.go:800] [Terminating] Got reply to &{4 [] <nil>}: ''
I0419 09:47:33.533082   12946 vm_states.go:802] POD destroyed 
I0419 09:47:33.533103   12946 qmp_handler.go:296] got new session
I0419 09:47:33.533134   12946 qmp_handler.go:225] Begin process command session
I0419 09:47:33.533159   12946 qmp_handler.go:243] sending command (1) {"execute":"quit"}
I0419 09:47:33.533787   12946 qmp_handler.go:103] got a message {"return": {}}
I0419 09:47:33.533884   12946 qmp_handler.go:103] got a message {"timestamp": {"seconds": 1461052053, "microseconds": 533777}, "event": "SHUTDOWN"}
I0419 09:47:33.533913   12946 qmp_handler.go:107] got event: SHUTDOWN
I0419 09:47:33.533928   12946 qmp_handler.go:152] Shutdown, quit QMP receiver
I0419 09:47:33.533944   12946 qmp_handler.go:323] got QMP event SHUTDOWN
I0419 09:47:33.533957   12946 qmp_handler.go:325] got QMP shutdown event, quit...
I0419 09:47:33.533969   12946 hypervisor.go:29] main event loop got message 1(EVENT_VM_EXIT)
I0419 09:47:33.533981   12946 vm_states.go:784] Got VM shutdown event while terminating, go to cleaning up
I0419 09:47:33.533993   12946 vm_states.go:34] VM has exit...
I0419 09:47:33.534009   12946 devicemap.go:419] need umount dir RWEhfAenSg
I0419 09:47:33.534094   12946 vm.go:81] Got response: 2: VM shut down
I0419 09:47:33.534119   12946 devicemap.go:462] need unmount aufs /8772dfdfe88b2a962ae1cc4275632c87398778e329d4cdef59f9ad2f96d4af30/rootfs
I0419 09:47:33.534139   12946 devicemap.go:499] remove network card 0: 192.168.123.3
I0419 09:47:33.534156   12946 context.go:212] VM vm-TcTOqfpdJk: state change from TERMINATING to 'DESTROYING'
E0419 09:47:33.541585   12946 init_comm.go:75] read init data failed
I0419 09:47:33.541624   12946 hypervisor.go:29] main event loop got message 43(ERROR_INTERRUPTED)
I0419 09:47:33.541763   12946 vm_states.go:891] Connection interrupted while destroying
E0419 09:47:33.541659   12946 tty.go:103] read tty data failed
I0419 09:47:33.541785   12946 tty.go:164] tty socket closed, quit the reading goroutine EOF
I0419 09:47:33.541810   12946 tty.go:131] tty chan closed, quit sent goroutine
I0419 09:47:33.541687   12946 tty.go:441] Input byte chan closed, close the output string chan
I0419 09:47:33.541835   12946 init_comm.go:46] console output end
I0419 09:47:33.541845   12946 hypervisor.go:29] main event loop got message 43(ERROR_INTERRUPTED)
I0419 09:47:33.541856   12946 vm_states.go:891] Connection interrupted while destroying
I0419 09:47:33.544821   12946 volume_linux.go:43] Ready to unmount the target : /var/run/hyper/vm-TcTOqfpdJk/share_dir/8772dfdfe88b2a962ae1cc4275632c87398778e329d4cdef59f9ad2f96d4af30/rootfs
I0419 09:47:33.550726   12946 hypervisor.go:29] main event loop got message 12(EVENT_BLOCK_EJECTED)
I0419 09:47:33.550762   12946 devicemap.go:396] volume etchosts-volume umounted
I0419 09:47:33.550774   12946 vm_states.go:456] Unplug block device return with true
I0419 09:47:33.550784   12946 hypervisor.go:29] main event loop got message 14(EVENT_INTERFACE_DELETE)
I0419 09:47:33.550792   12946 devicemap.go:387] interface 0 released
I0419 09:47:33.550803   12946 vm_states.go:453] Unplug interface return with true
I0419 09:47:33.557709   12946 hypervisor.go:29] main event loop got message 7(EVENT_CONTAINER_DELETE)
I0419 09:47:33.557743   12946 devicemap.go:369] container 0 umounted
I0419 09:47:33.557756   12946 vm_states.go:450] Unplug container return with true
I0419 09:47:33.557770   12946 context.go:199] no more device to release/remove/umount, quit
I0419 09:47:33.557809   12946 qemu_process.go:19] quit watch dog.
gao-feng commented 8 years ago

@zenny Is /mnt/tank/HYPER/hyper-initrd.img the new version of hyperstart initrd image?