3qTMfS3r

1[root@localhost hyperd]# hyperctl run -t ubuntu /bin/bash
2root@ubuntu-7378494712:/# df -h
3Filesystem      Size  Used Avail Use% Mounted on
4/dev/sda         10G  156M  9.9G   2% /
5devtmpfs         57M     0   57M   0% /dev
6tmpfs            59M     0   59M   0% /dev/shm
7rootfs           57M   15M   42M  26% /lib/modules/4.4.12-hyper
8share_dir       1.0M  4.0K 1020K   1% /etc/hosts
9root@ubuntu-7378494712:/# mount
10/dev/sda on / type xfs (rw,relatime,nouuid,attr2,inode64,logbsize=64k,sunit=128,swidth=128,noquota)
11proc on /proc type proc (rw,nosuid,nodev,noexec,relatime)
12sysfs on /sys type sysfs (rw,nosuid,nodev,noexec,relatime)
13devtmpfs on /dev type devtmpfs (rw,nosuid,relatime,size=57388k,nr_inodes=14347,mode=755)
14tmpfs on /dev/shm type tmpfs (rw,nosuid,nodev,relatime)
15devpts on /dev/pts type devpts (rw,nosuid,relatime,mode=620,ptmxmode=666)
16rootfs on /lib/modules/4.4.12-hyper type rootfs (rw,size=57380k,nr_inodes=14345)
17share_dir on /etc/hosts type 9p (rw,nodev,relatime,sync,dirsync,trans=virtio)
18root@ubuntu-7378494712:/#
19
20
21###########################
22[root@localhost hyperhq]# hyperd -v 3
23I0922 15:30:47.172377   12712 hyperd.go:106] The config file is
24I0922 15:30:47.173595   12712 daemon.go:141] The config: kernel=/var/lib/hyper/kernel, initrd=/var/lib/hyper/hyper-initrd.img
25I0922 15:30:47.173754   12712 daemon.go:143] The config: vbox image=
26I0922 15:30:47.173861   12712 daemon.go:146] The config: bridge=, ip=
27I0922 15:30:47.173921   12712 daemon.go:149] The config: bios=, cbfs=
28DEBU[0000] Using default logging driver none
29DEBU[0000] devicemapper: driver version is 4.34.0
30DEBU[0000] devmapper: Generated prefix: docker-253:0-1573769
31DEBU[0000] devmapper: Checking for existence of the pool docker-253:0-1573769-pool
32DEBU[0000] devmapper: poolDataMajMin=7:0 poolMetaMajMin=7:1
33
34DEBU[0000] devmapper: Major:Minor for device: /dev/loop0 is:7:0
35DEBU[0000] devmapper: Major:Minor for device: /dev/loop1 is:7:1
36DEBU[0000] devmapper: loadDeviceFilesOnStart()
37DEBU[0000] devmapper: Loading data for file /var/lib/hyper/devicemapper/metadata/59b902b72205af11560175bca929eb848a1aacf2f0b7b99f0dd6ceb7f4f57d15
38DEBU[0000] devmapper: Loading data for file /var/lib/hyper/devicemapper/metadata/831deeebf58f19fa49f3be37dc6ded131b5dfb8e552869ffc53694e9984b0131
39DEBU[0000] devmapper: Loading data for file /var/lib/hyper/devicemapper/metadata/a980b8a088852a01f42768b3906ada30b1ecad14c8ce765a4c9cb524a4eef2c8
40DEBU[0000] devmapper: Loading data for file /var/lib/hyper/devicemapper/metadata/b6b249718725ec9b3676a6003d4c29c37a0621d56dfb072790d0569c7fa4c08e
41DEBU[0000] devmapper: Loading data for file /var/lib/hyper/devicemapper/metadata/b6b249718725ec9b3676a6003d4c29c37a0621d56dfb072790d0569c7fa4c08e-init
42DEBU[0000] devmapper: Loading data for file /var/lib/hyper/devicemapper/metadata/base
43DEBU[0000] devmapper: Skipping file /var/lib/hyper/devicemapper/metadata/deviceset-metadata
44DEBU[0000] devmapper: Loading data for file /var/lib/hyper/devicemapper/metadata/e11ca2da1939fcc8b5148ed32315a0d63ad9aa28afb4bd6dda56fa4a045f0bd8
45DEBU[0000] devmapper: Loading data for file /var/lib/hyper/devicemapper/metadata/e139596f77e84ef2b9ac71cee2b5d29bb2e2a25b8de8032a8049893f68730f68
46DEBU[0000] devmapper: Loading data for file /var/lib/hyper/devicemapper/metadata/f3ea03622be802c772076a261c5d0230a6de98945b1c96e786fa2d6fb0accef4
47DEBU[0000] devmapper: Skipping file /var/lib/hyper/devicemapper/metadata/transaction-metadata
48DEBU[0000] devmapper: loadDeviceFilesOnStart() END
49DEBU[0000] devmapper: constructDeviceIDMap()
50DEBU[0000] devmapper: Added deviceId=9 to DeviceIdMap
51DEBU[0000] devmapper: Added deviceId=4 to DeviceIdMap
52DEBU[0000] devmapper: Added deviceId=5 to DeviceIdMap
53DEBU[0000] devmapper: Added deviceId=8 to DeviceIdMap
54DEBU[0000] devmapper: Added deviceId=6 to DeviceIdMap
55DEBU[0000] devmapper: Added deviceId=7 to DeviceIdMap
56DEBU[0000] devmapper: Added deviceId=1 to DeviceIdMap
57DEBU[0000] devmapper: Added deviceId=2 to DeviceIdMap
58DEBU[0000] devmapper: Added deviceId=3 to DeviceIdMap
59DEBU[0000] devmapper: constructDeviceIDMap() END
60WARN[0000] devmapper: Usage of loopback devices is strongly discouraged for production use. Please use `--storage-opt dm.thinpooldev` or use `man docker` to refer to dm.thinpooldev section.
61DEBU[0000] devmapper: activateDeviceIfNeeded()
62DEBU[0000] devmapper: UUID for device: /dev/mapper/docker-253:0-1573769-base is:a44e9b20-dacd-4ace-9d86-2cbef0cf7f73
63WARN[0000] devmapper: Base device already exists and has filesystem xfs on it. User specified filesystem  will be ignored.
64DEBU[0000] devmapper: deactivateDevice()
65DEBU[0000] devmapper: removeDevice START(docker-253:0-1573769-base)
66DEBU[0000] devmapper: removeDevice END(docker-253:0-1573769-base)
67DEBU[0000] devmapper: deactivateDevice END()
68INFO[0000] [graphdriver] using prior storage driver "devicemapper"
69DEBU[0000] Using graph driver devicemapper
70INFO[0000] Graph migration to content-addressability took 0.00 seconds
71DEBU[0000] Option DefaultDriver: bridge
72DEBU[0000] Option DefaultNetwork: bridge
73INFO[0000] Firewalld running: false
74DEBU[0000] Registering ipam driver: "default"
75DEBU[0000] Cleaning up old shm/mqueue mounts: start.
76DEBU[0000] Cleaning up old shm/mqueue mounts: done.
77DEBU[0000] Loaded container 1d7a3763c24d3f2a0b0eed89179a9753763e8c5a5523e43aa25a6ab2715ab85f
78I0922 15:30:47.368264   12712 server.go:70] Server created for HTTP on unix (/var/run/hyper.sock)
79Qemu Driver Loaded
80I0922 15:30:47.368670   12712 hyperd.go:193] The hypervisor's driver is qemu
81I0922 15:30:47.369389   12712 network_linux.go:263] bridge exist
82I0922 15:30:47.372729   12712 iptables_linux.go:140] /usr/sbin/iptables, [--wait -t nat -C POSTROUTING -s 192.168.123.1/24 ! -o hyper0 -j MASQUERADE]
83I0922 15:30:47.375385   12712 iptables_linux.go:140] /usr/sbin/iptables, [--wait -N HYPER]
84I0922 15:30:47.378046   12712 iptables_linux.go:140] /usr/sbin/iptables, [--wait -t filter -C FORWARD -o hyper0 -j HYPER]
85I0922 15:30:47.379733   12712 iptables_linux.go:140] /usr/sbin/iptables, [--wait -t filter -C FORWARD -i hyper0 -j ACCEPT]
86I0922 15:30:47.382319   12712 iptables_linux.go:140] /usr/sbin/iptables, [--wait -t filter -C FORWARD -o hyper0 -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT]
87I0922 15:30:47.386353   12712 iptables_linux.go:140] /usr/sbin/iptables, [--wait -t nat -N HYPER]
88I0922 15:30:47.387951   12712 iptables_linux.go:140] /usr/sbin/iptables, [--wait -t nat -C OUTPUT -m addrtype --dst-type LOCAL ! -d 127.0.0.1/8 -j HYPER]
89I0922 15:30:47.389648   12712 iptables_linux.go:140] /usr/sbin/iptables, [--wait -t nat -C PREROUTING -m addrtype --dst-type LOCAL -j HYPER]
90I0922 15:30:47.391727   12712 daemondb.go:220] got key from leveldb pod-container-pod-evSgAursPF
91I0922 15:30:47.391848   12712 daemondb.go:220] got key from leveldb pod-pod-evSgAursPF
92I0922 15:30:47.391884   12712 daemon.go:85] reloading pod pod-evSgAursPF with args {"id":"busybox-6199998260","hostname":"","containers":[{"name":"busybox-6199998260","image":"busybox","user":{"name":"","group":""},"command":[],"workdir":"/","entrypoint":[],"tty":true,"labels":null,"ports":null,"envs":null,"volumes":[{"path":"/etc/hosts","volume":"etchosts-volume","readOnly":false}],"files":[{"path":"/etc/resolv.conf","filename":"pod-evSgAursPF-resolvconf","perm":"0644","user":"","group":""}],"restartPolicy":"never"}],"resource":{"vcpu":1,"memory":128},"files":[{"name":"pod-evSgAursPF-resolvconf","encoding":"raw","uri":"file:///etc/resolv.conf","content":""}],"volumes":[{"name":"etchosts-volume","source":"/var/lib/hyper/hosts/pod-evSgAursPF/hosts","driver":"vfs","option":{"monitors":null,"user":"","keyring":"","bytespersec":0,"iops":0}}],"labels":{},"log":{"type":"json-file","config":{}},"tty":true,"type":"","RestartPolicy":""}
93I0922 15:30:47.392399   12712 run.go:40] podArgs: id:"busybox-6199998260" tty:true resource:<vcpu:1 memory:128 > log:<type:"json-file" > containers:<name:"busybox-6199998260" image:"busybox" workdir:"/" restartPolicy:"never" tty:true volumes:<path:"/etc/hosts" volume:"etchosts-volume" > files:<path:"/etc/resolv.conf" filename:"pod-evSgAursPF-resolvconf" perm:"0644" > user:<> > files:<name:"pod-evSgAursPF-resolvconf" encoding:"raw" uri:"file:///etc/resolv.conf" > volumes:<name:"etchosts-volume" source:"/var/lib/hyper/hosts/pod-evSgAursPF/hosts" driver:"vfs" option:<> >
94I0922 15:30:47.392780   12712 pod.go:905] Already has resolv.conf configured, bypass DNS insert
95I0922 15:30:47.392899   12712 daemondb.go:82] try get container list for pod pod-evSgAursPF
96I0922 15:30:47.393067   12712 pod.go:467] loaded containers for pod pod-evSgAursPF: [1d7a3763c24d3f2a0b0eed89179a9753763e8c5a5523e43aa25a6ab2715ab85f]
97I0922 15:30:47.393178   12712 pod.go:475] Loading container 1d7a3763c24d3f2a0b0eed89179a9753763e8c5a5523e43aa25a6ab2715ab85f of pod pod-evSgAursPF
98I0922 15:30:47.393318   12712 pod.go:487] Found exist container busybox-6199998260 (1d7a3763c24d3f2a0b0eed89179a9753763e8c5a5523e43aa25a6ab2715ab85f), pod: pod-evSgAursPF
99I0922 15:30:47.393540   12712 pod.go:520] do not need to create container busybox-6199998260 of pod pod-evSgAursPF[0]
100I0922 15:30:47.393818   12712 pod.go:597] container name busybox-6199998260, image busybox
101I0922 15:30:47.393894   12712 pod.go:624] container info config &{1d7a3763c24d   false false false map[]  false false false [PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin] 0xc82070ddc0 false busybox map[]  <nil> true  [] map[] }, Cmd [sh], Args []
102I0922 15:30:47.394089   12712 pod.go:648] Container Info is
103&{containerID:"1d7a3763c24d3f2a0b0eed89179a9753763e8c5a5523e43aa25a6ab2715ab85f" commands:"sh" env:<env:"PATH" value:"/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin" >  1474528533 b6b249718725ec9b3676a6003d4c29c37a0621d56dfb072790d0569c7fa4c08e   false}
104I0922 15:30:47.394420   12712 daemondb.go:91] try set container list for pod pod-evSgAursPF: [1d7a3763c24d3f2a0b0eed89179a9753763e8c5a5523e43aa25a6ab2715ab85f]
105I0922 15:30:47.394595   12712 daemon.go:109] no existing VM for pod pod-evSgAursPF: leveldb: not found
106I0922 15:30:47.394825   12712 daemon.go:119] 1 pod have been loaded
107I0922 15:30:47.394985   12712 daemon.go:121] container in pod pod-evSgAursPF status: [0xc820017e60]
108I0922 15:30:47.395104   12712 daemon.go:122] container in pod pod-evSgAursPF spec: [{busybox-6199998260 busybox {  []} [] / [] true map[] map[] [] [] [{/etc/hosts etchosts-volume false}] [{/etc/resolv.conf pod-evSgAursPF-resolvconf 0644  }] never}]
109I0922 15:30:47.395682   12712 server.go:199] Registering routers
110I0922 15:30:47.395720   12712 server.go:204] Registering GET, /container/info
111I0922 15:30:47.395787   12712 server.go:204] Registering GET, /container/logs
112I0922 15:30:47.395865   12712 server.go:204] Registering GET, /exitcode
113I0922 15:30:47.396143   12712 server.go:204] Registering POST, /container/create
114I0922 15:30:47.396209   12712 server.go:204] Registering POST, /container/rename
115I0922 15:30:47.396357   12712 server.go:204] Registering POST, /container/commit
116I0922 15:30:47.396484   12712 server.go:204] Registering POST, /container/stop
117I0922 15:30:47.396614   12712 server.go:204] Registering POST, /container/kill
118I0922 15:30:47.396736   12712 server.go:204] Registering POST, /exec/create
119I0922 15:30:47.396856   12712 server.go:204] Registering POST, /exec/start
120I0922 15:30:47.396969   12712 server.go:204] Registering POST, /attach
121I0922 15:30:47.397197   12712 server.go:204] Registering POST, /tty/resize
122I0922 15:30:47.397287   12712 server.go:204] Registering GET, /pod/info
123I0922 15:30:47.397446   12712 server.go:204] Registering GET, /pod/stats
124I0922 15:30:47.397593   12712 server.go:204] Registering GET, /list
125I0922 15:30:47.397653   12712 server.go:204] Registering POST, /pod/create
126I0922 15:30:47.397758   12712 hyperd.go:245] Hyper daemon: 0.6.2 0
127I0922 15:30:47.398025   12712 server.go:204] Registering POST, /pod/labels
128I0922 15:30:47.398135   12712 server.go:204] Registering POST, /pod/start
129I0922 15:30:47.398321   12712 server.go:204] Registering POST, /pod/stop
130I0922 15:30:47.398400   12712 server.go:204] Registering POST, /pod/kill
131I0922 15:30:47.398487   12712 server.go:204] Registering POST, /pod/pause
132I0922 15:30:47.398770   12712 server.go:204] Registering POST, /pod/unpause
133I0922 15:30:47.399011   12712 server.go:204] Registering POST, /vm/create
134I0922 15:30:47.399262   12712 server.go:204] Registering DELETE, /pod
135I0922 15:30:47.399417   12712 server.go:204] Registering DELETE, /vm
136I0922 15:30:47.399495   12712 server.go:204] Registering GET, /service/list
137I0922 15:30:47.399869   12712 server.go:204] Registering POST, /service/add
138I0922 15:30:47.400022   12712 server.go:204] Registering POST, /service/update
139I0922 15:30:47.400405   12712 server.go:204] Registering DELETE, /service
140I0922 15:30:47.400641   12712 server.go:204] Registering GET, /images/get
141I0922 15:30:47.400813   12712 server.go:204] Registering POST, /image/create
142I0922 15:30:47.401021   12712 server.go:204] Registering POST, /image/load
143I0922 15:30:47.401233   12712 server.go:204] Registering POST, /image/push
144I0922 15:30:47.401393   12712 server.go:204] Registering DELETE, /image
145I0922 15:30:47.401568   12712 server.go:204] Registering GET, /_ping
146I0922 15:30:47.401657   12712 server.go:204] Registering GET, /info
147I0922 15:30:47.401874   12712 server.go:204] Registering GET, /version
148I0922 15:30:47.402057   12712 server.go:204] Registering POST, /auth
149I0922 15:30:47.402256   12712 server.go:204] Registering POST, /image/build
150I0922 15:30:47.402397   12712 server.go:95] API listen on /var/run/hyper.sock
151I0922 15:30:52.350385   12712 server.go:152] Calling POST /v0.6.2/vm/create
152I0922 15:30:52.350440   12712 vm.go:192] The config: kernel=/var/lib/hyper/kernel, initrd=/var/lib/hyper/hyper-initrd.img
153I0922 15:30:52.351174   12712 qemu_amd64.go:44] kvm not exist change to no kvm mode
154I0922 15:30:52.351215   12712 qemu_process.go:131] cmdline arguments: -machine pc-i440fx-2.0,usb=off -cpu core2duo -kernel /var/lib/hyper/kernel -initrd /var/lib/hyper/hyper-initrd.img -append console=ttyS0 panic=1 no_timer_check -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-iZqpFsRQwq/qmp.sock,server,nowait -serial unix:/var/run/hyper/vm-iZqpFsRQwq/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-iZqpFsRQwq/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-iZqpFsRQwq/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-iZqpFsRQwq/share_dir,security_model=none -device virtio-9p-pci,fsdev=virtio9p,mount_tag=share_dir -daemonize -pidfile /var/run/hyper/vm-iZqpFsRQwq/pidfile -D /var/log/hyper/qemu/vm-iZqpFsRQwq.log
155I0922 15:30:52.351226   12712 qemu_process.go:132] qemu log file: /var/log/hyper/qemu/vm-iZqpFsRQwq.log
156I0922 15:30:52.352488   12712 server.go:152] Calling POST /v0.6.2/pod/create
157I0922 15:30:52.352535   12712 pod_routes.go:76] Args string is {"id":"ubuntu-7378494712","hostname":"","containers":[{"name":"ubuntu-7378494712","image":"ubuntu","user":{"name":"","group":""},"command":["/bin/bash"],"workdir":"/","entrypoint":[],"labels":null,"ports":[],"envs":[],"volumes":[],"files":[],"restartPolicy":"never"}],"resource":{"vcpu":1,"memory":128},"files":[],"volumes":[],"labels":{},"log":{"type":"","config":{}},"tty":true,"type":"","RestartPolicy":""}, autoremove false
158I0922 15:30:52.352709   12712 run.go:40] podArgs: id:"ubuntu-7378494712" tty:true resource:<vcpu:1 memory:128 > log:<> containers:<name:"ubuntu-7378494712" image:"ubuntu" workdir:"/" restartPolicy:"never" command:"/bin/bash" user:<> >
159I0922 15:30:52.353204   12712 daemondb.go:82] try get container list for pod pod-orbBigFyPD
160I0922 15:30:52.353241   12712 pod.go:467] loaded containers for pod pod-orbBigFyPD: []
161DEBU[0005] devmapper: AddDevice(hash=ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874-init basehash=f3ea03622be802c772076a261c5d0230a6de98945b1c96e786fa2d6fb0accef4)
162DEBU[0005] devmapper: registerDevice(10, ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874-init)
163DEBU[0005] devmapper: AddDevice(hash=ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874-init basehash=f3ea03622be802c772076a261c5d0230a6de98945b1c96e786fa2d6fb0accef4) END
164DEBU[0005] devmapper: activateDeviceIfNeeded(ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874-init)
165DEBU[0005] devmapper: UnmountDevice(hash=ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874-init)
166DEBU[0005] devmapper: Unmount(/var/lib/hyper/devicemapper/mnt/ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874-init)
167DEBU[0005] devmapper: Unmount done
168DEBU[0005] devmapper: deactivateDevice(ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874-init)
169DEBU[0005] devmapper: removeDevice START(docker-253:0-1573769-ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874-init)
170I0922 15:30:52.475008   12712 tty.go:155] tty socket connected
171I0922 15:30:52.475131   12712 tty.go:98] tty: trying to read 12 bytes
172I0922 15:30:52.475207   12712 qmp_handler.go:167] connected to /var/run/hyper/vm-iZqpFsRQwq/qmp.sock
173I0922 15:30:52.475253   12712 qmp_handler.go:177] begin qmp init...
174I0922 15:30:52.475408   12712 init_comm.go:142] Wating for init messages...
175I0922 15:30:52.475570   12712 init_comm.go:96] trying to read 8 bytes
176I0922 15:30:52.475518   12712 init_comm.go:53] connected to /var/run/hyper/vm-iZqpFsRQwq/console.sock
177I0922 15:30:52.475592   12712 init_comm.go:60] connected /var/run/hyper/vm-iZqpFsRQwq/console.sock as telnet mode.
178DEBU[0005] devmapper: removeDevice END(docker-253:0-1573769-ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874-init)
179DEBU[0005] devmapper: deactivateDevice END(ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874-init)
180DEBU[0005] devmapper: UnmountDevice(hash=ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874-init) END
181DEBU[0005] devmapper: AddDevice(hash=ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874 basehash=ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874-init)
182DEBU[0005] devmapper: registerDevice(11, ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874)
183DEBU[0005] devmapper: AddDevice(hash=ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874 basehash=ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874-init) END
184DEBU[0005] devmapper: activateDeviceIfNeeded(ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874)
185I0922 15:30:52.491600   12712 qmp_handler.go:186] got qmp welcome, now sending command qmp_capabilities
186I0922 15:30:52.491641   12712 qmp_handler.go:201] waiting for response
187I0922 15:30:52.492431   12712 qmp_handler.go:103] got a message {"return": {}}
188I0922 15:30:52.492453   12712 qmp_handler.go:210] got for response
189I0922 15:30:52.492467   12712 qmp_handler.go:213] QMP connection initialized
190I0922 15:30:52.492491   12712 qmp_handler.go:346] QMP initialzed, go into main QMP loop
191I0922 15:30:52.492501   12712 qmp_handler.go:137] Begin receive QMP message
192I0922 15:30:52.496847   12712 qemu_process.go:206] starting daemon with pid: 12776
193DEBU[0005] container mounted via layerStore: /var/lib/hyper/devicemapper/mnt/ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874/rootfs
194DEBU[0005] devmapper: UnmountDevice(hash=ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874)
195DEBU[0005] devmapper: Unmount(/var/lib/hyper/devicemapper/mnt/ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874)
196DEBU[0005] devmapper: Unmount done
197DEBU[0005] devmapper: deactivateDevice(ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874)
198DEBU[0005] devmapper: removeDevice START(docker-253:0-1573769-ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874)
199DEBU[0005] devmapper: removeDevice END(docker-253:0-1573769-ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874)
200DEBU[0005] devmapper: deactivateDevice END(ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874)
201DEBU[0005] devmapper: UnmountDevice(hash=ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874) END
202I0922 15:30:52.554105   12712 pod.go:557] create container aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673
203I0922 15:30:52.554146   12712 pod.go:597] container name ubuntu-7378494712, image ubuntu
204I0922 15:30:52.554213   12712 pod.go:624] container info config &{aa8826edab7f   false false false map[]  false false false [PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin] 0xc82087f320 false ubuntu map[]  <nil> true  [] map[] }, Cmd [/bin/bash], Args []
205I0922 15:30:52.554345   12712 pod.go:648] Container Info is
206&{containerID:"aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673" commands:"/bin/bash" env:<env:"PATH" value:"/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin" >  1474529452 ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874   true}
207I0922 15:30:52.554647   12712 daemondb.go:91] try set container list for pod pod-orbBigFyPD: [aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673]
208I0922 15:30:52.555162   12712 server.go:152] Calling GET /v0.6.2/pod/info
209I0922 15:30:52.556956   12712 server.go:152] Calling POST /v1.17/pod/start
210I0922 15:30:52.557274   12712 run.go:68] Run pod with tty attached
211I0922 15:30:52.557596   12712 run.go:76] pod:pod-orbBigFyPD, vm:vm-iZqpFsRQwq
212I0922 15:30:52.557875   12712 pod.go:320] lock pod pod-orbBigFyPD for operation start
213I0922 15:30:52.558106   12712 pod.go:323] successfully lock pod pod-orbBigFyPD for operation start
214I0922 15:30:52.558355   12712 vm.go:229] find vm:vm-iZqpFsRQwq
215I0922 15:30:52.558634   12712 pod.go:960] container ID: aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673, mountId ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874
216I0922 15:30:52.599180   12712 dm.go:95] The filesytem type is xfs
217I0922 15:30:52.629850   12712 volumes.go:29] trying to bind dir /var/lib/hyper/hosts/pod-orbBigFyPD/hosts to /var/run/hyper/vm-iZqpFsRQwq/share_dir/njznJfWEVL
218I0922 15:30:52.632645   12712 storage.go:79] dir /var/lib/hyper/hosts/pod-orbBigFyPD/hosts is bound to njznJfWEVL
219I0922 15:30:52.632679   12712 pod.go:1119] configuring log driver [json-file] for pod-orbBigFyPD
220I0922 15:30:52.632728   12712 pod.go:1147] configure container log to /var/run/hyper/Pods/pod-orbBigFyPD/aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673-json.log
221I0922 15:30:52.632769   12712 pod.go:1153] configured logger for pod-orbBigFyPD/aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673 (/ubuntu-7378494712)
222I0922 15:30:52.632812   12712 hypervisor.go:29] vm vm-iZqpFsRQwq: main event loop got message 34(GENERIC_OPERATION)
223I0922 15:30:52.632819   12712 vm_states.go:289] handle GenericOperation(Attach) on state(INIT)
224I0922 15:30:52.632843   12712 vm_states.go:229] attachment aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673 is pending
225I0922 15:30:52.632860   12712 hypervisor.go:29] vm vm-iZqpFsRQwq: main event loop got message 34(GENERIC_OPERATION)
226I0922 15:30:52.632863   12712 vm_states.go:289] handle GenericOperation(Attach) on state(INIT)
227I0922 15:30:52.632866   12712 vm_states.go:229] attachment aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673 is pending
228I0922 15:30:52.632870   12712 pod.go:1205] Attach to container aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673 before start pod
229I0922 15:30:52.632883   12712 hypervisor.go:29] vm vm-iZqpFsRQwq: main event loop got message 21(COMMAND_RUN_POD)
230I0922 15:30:52.632888   12712 vm_states.go:439] got spec, prepare devices
231I0922 15:30:52.632906   12712 context.go:292] #0 Container Info:
232I0922 15:30:52.633011   12712 vm.go:162] hyperHandlePodEvent pod pod-orbBigFyPD, vm vm-iZqpFsRQwq
233I0922 15:30:52.633064   12712 context.go:295]
234{
235...|    "Id": "aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673",
236...|    "User": "",
237...|    "MountId": "ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874",
238...|    "Rootfs": "/rootfs",
239...|    "Image": {
240...|        "name": "",
241...|        "source": "/dev/mapper/docker-253:0-1573769-ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874",
242...|        "driver": "",
243...|        "option": {
244...|            "monitors": null,
245...|            "user": "",
246...|            "keyring": "",
247...|            "bytespersec": 0,
248...|            "iops": 0
249...|        }
250...|    },
251...|    "Fstype": "xfs",
252...|    "Workdir": "",
253...|    "Entrypoint": null,
254...|    "Cmd": [
255...|        "/bin/bash"
256...|    ],
257...|    "Envs": {
258...|        "PATH": "/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"
259...|    },
260...|    "Initialize": true
261...|}
262I0922 15:30:52.633135   12712 devicemap.go:196] insert volume /dev/mapper/docker-253:0-1573769-ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874 source /dev/mapper/docker-253:0-1573769-ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874 fstype xfs
263I0922 15:30:52.633149   12712 devicemap.go:281] insert volume etchosts-volume to /etc/hosts on 0
264I0922 15:30:52.633388   12712 vm_states.go:67] initial vm spec: {
265        "hostname": "ubuntu-7378494712",
266        "containers": [
267            {
268                "id": "aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673",
269                "rootfs": "/rootfs",
270                "fstype": "xfs",
271                "image": "",
272                "fsmap": [
273                    {
274                        "source": "njznJfWEVL",
275                        "path": "/etc/hosts",
276                        "readOnly": false,
277                        "dockerVolume": false
278                    }
279                ],
280                "process": {
281                    "terminal": true,
282                    "stdio": 1,
283                    "args": [
284                        "/bin/bash"
285                    ],
286                    "envs": [
287                        {
288                            "env": "PATH",
289                            "value": "/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"
290                        }
291                    ],
292                    "workdir": "/"
293                },
294                "restartPolicy": "never",
295                "initialize": true
296            }
297        ],
298        "shareDir": "share_dir"
299    }
300I0922 15:30:52.633471   12712 context.go:224] found container aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673 at 0
301I0922 15:30:52.633480   12712 vm_states.go:75] attach pending client for aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673
302I0922 15:30:52.633487   12712 vm_states.go:247] Connecting tty for aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673 on session 1
303I0922 15:30:52.633493   12712 context.go:224] found container aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673 at 0
304I0922 15:30:52.633498   12712 vm_states.go:75] attach pending client for aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673
305I0922 15:30:52.633503   12712 vm_states.go:247] Connecting tty for aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673 on session 1
306I0922 15:30:52.633535   12712 context.go:260] VM vm-iZqpFsRQwq: state change from INIT to 'STARTING'
307I0922 15:30:52.633546   12712 qmp_handler.go:296] got new session
308I0922 15:30:52.633564   12712 qmp_handler.go:225] Begin process command session
309I0922 15:30:52.633584   12712 qmp_handler.go:243] sending command (1) {"execute":"human-monitor-command","arguments":{"command-line":"drive_add dummy file=/dev/mapper/docker-253:0-1573769-ba9e03dd15779eba57bf82a0cca79abcb4674c55dbb51bb1cfbb4499be316874,if=none,id=drive0,format=raw,cache=writeback"}}
310I0922 15:30:52.638098   12712 qmp_handler.go:103] got a message {"return": "OK\r\n"}
311I0922 15:30:52.638158   12712 qmp_handler.go:243] sending command (1) {"execute":"device_add","arguments":{"bus":"scsi0.0","drive":"drive0","driver":"scsi-hd","id":"scsi-disk0","scsi-id":"0"}}
312I0922 15:30:52.641146   12712 qmp_handler.go:103] got a message {"return": {}}
313I0922 15:30:52.641191   12712 qmp_handler.go:302] session finished, buffer size 1
314I0922 15:30:52.641199   12712 qmp_handler.go:305] success
315I0922 15:30:52.641206   12712 hypervisor.go:29] vm vm-iZqpFsRQwq: main event loop got message 9(EVENT_BLOCK_INSERTED)
316I0922 15:30:52.648622   12712 hypervisor.go:29] vm vm-iZqpFsRQwq: main event loop got message 12(EVENT_INTERFACE_ADD)
317I0922 15:30:52.648649   12712 qmp_wrapper_amd64.go:17] send net to qemu at 26
318I0922 15:30:52.648664   12712 qmp_handler.go:296] got new session
319I0922 15:30:52.648681   12712 qmp_handler.go:225] Begin process command session
320I0922 15:30:52.648699   12712 qmp_handler.go:238] send cmd with scm (24 bytes) (1) {"execute":"getfd","arguments":{"fdname":"fdeth0"}}
321I0922 15:30:52.652830   12712 qmp_handler.go:103] got a message {"return": {}}
322I0922 15:30:52.653078   12712 qmp_handler.go:243] sending command (1) {"execute":"netdev_add","arguments":{"fd":"fdeth0","id":"eth0","type":"tap"}}
323I0922 15:30:52.654996   12712 qmp_handler.go:103] got a message {"return": {}}
324I0922 15:30:52.655207   12712 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:a9:58:7b:9d","netdev":"eth0"}}
325I0922 15:30:52.659264   12712 qmp_handler.go:103] got a message {"return": {}}
326I0922 15:30:52.659482   12712 qmp_handler.go:302] session finished, buffer size 1
327I0922 15:30:52.659496   12712 qmp_handler.go:305] success
328I0922 15:30:52.659503   12712 hypervisor.go:29] vm vm-iZqpFsRQwq: main event loop got message 14(EVENT_INTERFACE_INSERTED)
329I0922 15:30:52.659514   12712 vm_states.go:466] device ready, could run pod.
330I0922 15:30:53.422723   12712 init_comm.go:68] [console] Initializing cgroup subsys cpuset
331I0922 15:30:53.422761   12712 init_comm.go:68] [console] Initializing cgroup subsys cpu
332I0922 15:30:53.422794   12712 init_comm.go:68] [console] Initializing cgroup subsys cpuacct
333I0922 15:30:53.423303   12712 init_comm.go:68] [console] Linux version 4.4.12-hyper (dev@hyper.sh) (gcc version 4.8.5 20150623 (Red Hat 4.8.5-4) (GCC) ) #1 SMP Tue Jun 7 19:29:06 UTC 2016
334I0922 15:30:53.423350   12712 init_comm.go:68] [console] Command line: console=ttyS0 panic=1 no_timer_check
335I0922 15:30:53.423637   12712 init_comm.go:68] [console] x86/fpu: Legacy x87 FPU detected.
336I0922 15:30:53.423667   12712 init_comm.go:68] [console] x86/fpu: Using 'lazy' FPU context switches.
337I0922 15:30:53.423696   12712 init_comm.go:68] [console] e820: BIOS-provided physical RAM map:
338I0922 15:30:53.423992   12712 init_comm.go:68] [console] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
339I0922 15:30:53.424236   12712 init_comm.go:68] [console] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
340I0922 15:30:53.424273   12712 init_comm.go:68] [console] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
341I0922 15:30:53.424488   12712 init_comm.go:68] [console] BIOS-e820: [mem 0x0000000000100000-0x0000000007ffdfff] usable
342I0922 15:30:53.424725   12712 init_comm.go:68] [console] BIOS-e820: [mem 0x0000000007ffe000-0x0000000007ffffff] reserved
343I0922 15:30:53.424789   12712 init_comm.go:68] [console] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
344I0922 15:30:53.425043   12712 init_comm.go:68] [console] NX (Execute Disable) protection: active
345I0922 15:30:53.425053   12712 init_comm.go:68] [console] SMBIOS 2.4 present.
346I0922 15:30:53.425342   12712 init_comm.go:68] [console] e820: last_pfn = 0x7ffe max_arch_pfn = 0x400000000
347I0922 15:30:53.425364   12712 init_comm.go:68] [console] x86/PAT: Configuration [0-7]: WB  WC  UC- UC  WB  WC  UC- WT
348I0922 15:30:53.425635   12712 init_comm.go:68] [console] found SMP MP-table at [mem 0x000f6b90-0x000f6b9f] mapped at [ffff8800000f6b90]
349I0922 15:30:53.425689   12712 init_comm.go:68] [console] RAMDISK: [mem 0x07b14000-0x07feffff]
350I0922 15:30:53.425936   12712 init_comm.go:68] [console] ACPI: Early table checksum verification disabled
351I0922 15:30:53.426154   12712 init_comm.go:68] [console] ACPI: RSDP 0x00000000000F6A10 000014 (v00 BOCHS )
352I0922 15:30:53.426417   12712 init_comm.go:68] [console] ACPI: RSDT 0x0000000007FFF6D8 00002C (v01 BOCHS  BXPCRSDT 00000001 BXPC 00000001)
353I0922 15:30:53.426651   12712 init_comm.go:68] [console] ACPI: FACP 0x0000000007FFF5EC 000074 (v01 BOCHS  BXPCFACP 00000001 BXPC 00000001)
354I0922 15:30:53.426713   12712 init_comm.go:68] [console] ACPI: DSDT 0x0000000007FFE040 0015AC (v01 BOCHS  BXPCDSDT 00000001 BXPC 00000001)
355I0922 15:30:53.426908   12712 init_comm.go:68] [console] ACPI: FACS 0x0000000007FFE000 000040
356I0922 15:30:53.427107   12712 init_comm.go:68] [console] ACPI: APIC 0x0000000007FFF660 000078 (v01 BOCHS  BXPCAPIC 00000001 BXPC 00000001)
357I0922 15:30:53.427307   12712 init_comm.go:68] [console] No NUMA configuration found
358I0922 15:30:53.427326   12712 init_comm.go:68] [console] Faking a node at [mem 0x0000000000000000-0x0000000007ffdfff]
359I0922 15:30:53.427517   12712 init_comm.go:68] [console] NODE_DATA(0) allocated [mem 0x07b02000-0x07b13fff]
360I0922 15:30:53.427539   12712 init_comm.go:68] [console] Zone ranges:
361I0922 15:30:53.427783   12712 init_comm.go:68] [console]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
362I0922 15:30:53.427975   12712 init_comm.go:68] [console]   DMA32    [mem 0x0000000001000000-0x0000000007ffdfff]
363I0922 15:30:53.427988   12712 init_comm.go:68] [console]   Normal   empty
364I0922 15:30:53.428680   12712 init_comm.go:68] [console] Movable zone start for each node
365I0922 15:30:53.428697   12712 init_comm.go:68] [console] Early memory node ranges
366I0922 15:30:53.428703   12712 init_comm.go:68] [console]   node   0: [mem 0x0000000000001000-0x000000000009efff]
367I0922 15:30:53.428708   12712 init_comm.go:68] [console]   node   0: [mem 0x0000000000100000-0x0000000007ffdfff]
368I0922 15:30:53.428713   12712 init_comm.go:68] [console] Initmem setup node 0 [mem 0x0000000000001000-0x0000000007ffdfff]
369I0922 15:30:53.428724   12712 init_comm.go:68] [console] ACPI: PM-Timer IO Port: 0x608
370I0922 15:30:53.429478   12712 init_comm.go:68] [console] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
371I0922 15:30:53.430382   12712 init_comm.go:68] [console] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
372I0922 15:30:53.431282   12712 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
373I0922 15:30:53.432832   12712 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
374I0922 15:30:53.432843   12712 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
375I0922 15:30:53.432848   12712 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
376I0922 15:30:53.432853   12712 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
377I0922 15:30:53.432859   12712 init_comm.go:68] [console] Using ACPI (MADT) for SMP configuration information
378I0922 15:30:53.432864   12712 init_comm.go:68] [console] smpboot: Allowing 1 CPUs, 0 hotplug CPUs
379I0922 15:30:53.432869   12712 init_comm.go:68] [console] e820: [mem 0x08000000-0xfffbffff] available for PCI devices
380I0922 15:30:53.432874   12712 init_comm.go:68] [console] Booting paravirtualized kernel on bare hardware
381I0922 15:30:53.432888   12712 init_comm.go:68] [console] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
382I0922 15:30:53.432893   12712 init_comm.go:68] [console] setup_percpu: NR_CPUS:8 nr_cpumask_bits:8 nr_cpu_ids:1 nr_node_ids:1
383I0922 15:30:53.432899   12712 init_comm.go:68] [console] PERCPU: Embedded 31 pages/cpu @ffff880007800000 s89624 r8192 d29160 u2097152
384I0922 15:30:53.432904   12712 init_comm.go:68] [console] Built 1 zonelists in Node order, mobility grouping on.  Total pages: 32135
385I0922 15:30:53.432909   12712 init_comm.go:68] [console] Policy zone: DMA32
386I0922 15:30:53.432914   12712 init_comm.go:68] [console] Kernel command line: console=ttyS0 panic=1 no_timer_check
387I0922 15:30:53.432919   12712 init_comm.go:68] [console] PID hash table entries: 512 (order: 0, 4096 bytes)
388I0922 15:30:53.432924   12712 init_comm.go:68] [console] Memory: 114760K/130672K available (4658K kernel code, 576K rwdata, 1472K rodata, 876K init, 756K bss, 15912K reserved, 0K cma-reserved)
389I0922 15:30:53.432931   12712 init_comm.go:68] [console] Hierarchical RCU implementation.
390I0922 15:30:53.432937   12712 init_comm.go:68] [console] 	Build-time adjustment of leaf fanout to 64.
391I0922 15:30:53.432944   12712 init_comm.go:68] [console] 	RCU restricting CPUs from NR_CPUS=8 to nr_cpu_ids=1.
392I0922 15:30:53.432950   12712 init_comm.go:68] [console] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=1
393I0922 15:30:53.432963   12712 init_comm.go:68] [console] NR_IRQS:4352 nr_irqs:256 16
394I0922 15:30:53.432972   12712 init_comm.go:68] [console] Console: colour *CGA 80x25
395I0922 15:30:53.432979   12712 init_comm.go:68] [console] console [ttyS0] enabled
396I0922 15:30:53.462532   12712 init_comm.go:68] [console] tsc: Fast TSC calibration failed
397I0922 15:30:53.497418   12712 qemu_process.go:74] qemu log: main-loop: WARNING: I/O thread spun for 1000 iterations
398I0922 15:30:53.536059   12712 init_comm.go:68] [console] tsc: Unable to calibrate against PIT
399I0922 15:30:53.536317   12712 init_comm.go:68] [console] tsc: using PMTIMER reference calibration
400I0922 15:30:53.536874   12712 init_comm.go:68] [console] tsc: Detected 2494.375 MHz processor
401I0922 15:30:53.539042   12712 init_comm.go:68] [console] Calibrating delay loop (skipped), value calculated using timer frequency.. 4988.75 BogoMIPS (lpj=2494375)
402I0922 15:30:53.539320   12712 init_comm.go:68] [console] pid_max: default: 32768 minimum: 301
403I0922 15:30:53.539998   12712 init_comm.go:68] [console] ACPI: Core revision 20150930
404I0922 15:30:53.566457   12712 init_comm.go:68] [console] ACPI: 1 ACPI AML tables successfully acquired and loaded
405I0922 15:30:53.569150   12712 init_comm.go:68] [console] Dentry cache hash table entries: 16384 (order: 5, 131072 bytes)
406I0922 15:30:53.570757   12712 init_comm.go:68] [console] Inode-cache hash table entries: 8192 (order: 4, 65536 bytes)
407I0922 15:30:53.571673   12712 init_comm.go:68] [console] Mount-cache hash table entries: 512 (order: 0, 4096 bytes)
408I0922 15:30:53.572492   12712 init_comm.go:68] [console] Mountpoint-cache hash table entries: 512 (order: 0, 4096 bytes)
409I0922 15:30:53.581538   12712 init_comm.go:68] [console] Initializing cgroup subsys io
410I0922 15:30:53.582347   12712 init_comm.go:68] [console] Initializing cgroup subsys memory
411I0922 15:30:53.583154   12712 init_comm.go:68] [console] Initializing cgroup subsys devices
412I0922 15:30:53.583655   12712 init_comm.go:68] [console] Initializing cgroup subsys freezer
413I0922 15:30:53.584266   12712 init_comm.go:68] [console] Initializing cgroup subsys net_cls
414I0922 15:30:53.584798   12712 init_comm.go:68] [console] Initializing cgroup subsys perf_event
415I0922 15:30:53.585293   12712 init_comm.go:68] [console] Initializing cgroup subsys net_prio
416I0922 15:30:53.585709   12712 init_comm.go:68] [console] Initializing cgroup subsys pids
417I0922 15:30:53.586471   12712 init_comm.go:68] [console] Initializing cgroup subsys debug
418I0922 15:30:53.588710   12712 init_comm.go:68] [console] process: using mwait in idle threads
419I0922 15:30:53.589414   12712 init_comm.go:68] [console] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0
420I0922 15:30:53.590004   12712 init_comm.go:68] [console] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0
421I0922 15:30:53.736454   12712 init_comm.go:68] [console] Freeing SMP alternatives memory: 20K (ffffffff8176b000 - ffffffff81770000)
422I0922 15:30:53.753170   12712 init_comm.go:68] [console] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
423I0922 15:30:53.856190   12712 init_comm.go:68] [console] smpboot: CPU0: Intel(R) Core(TM)2 Duo CPU     T7700  @ 2.40GHz (family: 0x6, model: 0xf, stepping: 0xb)
424I0922 15:30:53.858288   12712 init_comm.go:68] [console] Performance Events: unsupported p6 CPU model 15 no PMU driver, software events only.
425I0922 15:30:53.864263   12712 init_comm.go:68] [console] x86: Booted up 1 node, 1 CPUs
426I0922 15:30:53.865095   12712 init_comm.go:68] [console] smpboot: Total of 1 processors activated (4988.75 BogoMIPS)
427I0922 15:30:53.875137   12712 init_comm.go:68] [console] devtmpfs: initialized
428I0922 15:30:53.889983   12712 init_comm.go:68] [console] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
429I0922 15:30:53.896916   12712 init_comm.go:68] [console] NET: Registered protocol family 16
430I0922 15:30:53.899703   12712 init_comm.go:68] [console] cpuidle: using governor ladder
431I0922 15:30:53.900275   12712 init_comm.go:68] [console] cpuidle: using governor menu
432I0922 15:30:53.901416   12712 init_comm.go:68] [console] ACPI: bus type PCI registered
433I0922 15:30:53.902329   12712 init_comm.go:68] [console] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
434I0922 15:30:53.903412   12712 init_comm.go:68] [console] PCI: Using configuration type 1 for base access
435I0922 15:30:53.916925   12712 init_comm.go:68] [console] ACPI: Added _OSI(Module Device)
436I0922 15:30:53.917177   12712 init_comm.go:68] [console] ACPI: Added _OSI(Processor Device)
437I0922 15:30:53.917188   12712 init_comm.go:68] [console] ACPI: Added _OSI(3.0 _SCP Extensions)
438I0922 15:30:53.917197   12712 init_comm.go:68] [console] ACPI: Added _OSI(Processor Aggregator Device)
439I0922 15:30:53.938488   12712 init_comm.go:68] [console] ACPI: Interpreter enabled
440I0922 15:30:53.939450   12712 init_comm.go:68] [console] ACPI: (supports S0 S5)
441I0922 15:30:53.940045   12712 init_comm.go:68] [console] ACPI: Using IOAPIC for interrupt routing
442I0922 15:30:53.940753   12712 init_comm.go:68] [console] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
443I0922 15:30:53.978781   12712 init_comm.go:68] [console] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
444I0922 15:30:53.979404   12712 init_comm.go:68] [console] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI]
445I0922 15:30:53.980385   12712 init_comm.go:68] [console] acpi PNP0A03:00: _OSC failed (AE_NOT_FOUND); disabling ASPM
446I0922 15:30:53.984342   12712 init_comm.go:68] [console] acpiphp: Slot [2] registered
447I0922 15:30:53.985156   12712 init_comm.go:68] [console] acpiphp: Slot [3] registered
448I0922 15:30:53.985979   12712 init_comm.go:68] [console] acpiphp: Slot [4] registered
449I0922 15:30:53.986889   12712 init_comm.go:68] [console] acpiphp: Slot [5] registered
450I0922 15:30:53.987266   12712 init_comm.go:68] [console] acpiphp: Slot [6] registered
451I0922 15:30:53.987896   12712 init_comm.go:68] [console] acpiphp: Slot [7] registered
452I0922 15:30:53.988475   12712 init_comm.go:68] [console] acpiphp: Slot [8] registered
453I0922 15:30:53.989188   12712 init_comm.go:68] [console] acpiphp: Slot [9] registered
454I0922 15:30:53.989721   12712 init_comm.go:68] [console] acpiphp: Slot [10] registered
455I0922 15:30:53.990290   12712 init_comm.go:68] [console] acpiphp: Slot [11] registered
456I0922 15:30:53.990645   12712 init_comm.go:68] [console] acpiphp: Slot [12] registered
457I0922 15:30:53.991167   12712 init_comm.go:68] [console] acpiphp: Slot [13] registered
458I0922 15:30:53.991727   12712 init_comm.go:68] [console] acpiphp: Slot [14] registered
459I0922 15:30:53.992287   12712 init_comm.go:68] [console] acpiphp: Slot [15] registered
460I0922 15:30:53.992846   12712 init_comm.go:68] [console] acpiphp: Slot [16] registered
461I0922 15:30:53.993342   12712 init_comm.go:68] [console] acpiphp: Slot [17] registered
462I0922 15:30:53.993684   12712 init_comm.go:68] [console] acpiphp: Slot [18] registered
463I0922 15:30:53.994798   12712 init_comm.go:68] [console] acpiphp: Slot [19] registered
464I0922 15:30:53.995460   12712 init_comm.go:68] [console] acpiphp: Slot [20] registered
465I0922 15:30:53.996196   12712 init_comm.go:68] [console] acpiphp: Slot [21] registered
466I0922 15:30:53.996840   12712 init_comm.go:68] [console] acpiphp: Slot [22] registered
467I0922 15:30:53.997648   12712 init_comm.go:68] [console] acpiphp: Slot [23] registered
468I0922 15:30:53.998248   12712 init_comm.go:68] [console] acpiphp: Slot [24] registered
469I0922 15:30:53.998656   12712 init_comm.go:68] [console] acpiphp: Slot [25] registered
470I0922 15:30:53.999161   12712 init_comm.go:68] [console] acpiphp: Slot [26] registered
471I0922 15:30:53.999489   12712 init_comm.go:68] [console] acpiphp: Slot [27] registered
472I0922 15:30:54.000070   12712 init_comm.go:68] [console] acpiphp: Slot [28] registered
473I0922 15:30:54.000728   12712 init_comm.go:68] [console] acpiphp: Slot [29] registered
474I0922 15:30:54.001375   12712 init_comm.go:68] [console] acpiphp: Slot [30] registered
475I0922 15:30:54.002784   12712 init_comm.go:68] [console] acpiphp: Slot [31] registered
476I0922 15:30:54.003487   12712 init_comm.go:68] [console] PCI host bridge to bus 0000:00
477I0922 15:30:54.004191   12712 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7 window]
478I0922 15:30:54.004962   12712 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [io  0x0d00-0xffff window]
479I0922 15:30:54.005804   12712 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
480I0922 15:30:54.006560   12712 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [mem 0x08000000-0xfebfffff window]
481I0922 15:30:54.007225   12712 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [bus 00-ff]
482I0922 15:30:54.015957   12712 init_comm.go:68] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io  0x01f0-0x01f7]
483I0922 15:30:54.016903   12712 init_comm.go:68] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io  0x03f6]
484I0922 15:30:54.017685   12712 init_comm.go:68] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io  0x0170-0x0177]
485I0922 15:30:54.018327   12712 init_comm.go:68] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io  0x0376]
486I0922 15:30:54.020716   12712 init_comm.go:68] [console] pci 0000:00:01.3: quirk: [io  0x0600-0x063f] claimed by PIIX4 ACPI
487I0922 15:30:54.022344   12712 init_comm.go:68] [console] pci 0000:00:01.3: quirk: [io  0x0700-0x070f] claimed by PIIX4 SMB
488I0922 15:30:54.057048   12712 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11)
489I0922 15:30:54.059133   12712 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 *10 11)
490I0922 15:30:54.060521   12712 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 10 *11)
491I0922 15:30:54.062052   12712 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 10 *11)
492I0922 15:30:54.063020   12712 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKS] (IRQs *9)
493I0922 15:30:54.065913   12712 init_comm.go:68] [console] ACPI: Enabled 16 GPEs in block 00 to 0F
494I0922 15:30:54.070145   12712 init_comm.go:68] [console] vgaarb: loaded
495I0922 15:30:54.071269   12712 init_comm.go:68] [console] SCSI subsystem initialized
496I0922 15:30:54.072637   12712 init_comm.go:68] [console] PCI: Using ACPI for IRQ routing
497I0922 15:30:54.078448   12712 init_comm.go:68] [console] clocksource: Switched to clocksource refined-jiffies
498I0922 15:30:54.080539   12712 init_comm.go:68] [console] pnp: PnP ACPI init
499I0922 15:30:54.085648   12712 init_comm.go:68] [console] pnp: PnP ACPI: found 5 devices
500I0922 15:30:54.111774   12712 init_comm.go:68] [console] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
501I0922 15:30:54.112755   12712 init_comm.go:68] [console] clocksource: Switched to clocksource acpi_pm
502I0922 15:30:54.115624   12712 init_comm.go:68] [console] pci 0000:00:05.0: BAR 6: assigned [mem 0x08000000-0x0803ffff pref]
503I0922 15:30:54.116686   12712 init_comm.go:68] [console] pci 0000:00:05.0: BAR 1: assigned [mem 0x08040000-0x08040fff]
504I0922 15:30:54.117560   12712 init_comm.go:68] [console] pci 0000:00:05.0: BAR 0: assigned [io  0x1000-0x101f]
505I0922 15:30:54.118767   12712 init_comm.go:68] [console] NET: Registered protocol family 2
506I0922 15:30:54.123784   12712 init_comm.go:68] [console] TCP established hash table entries: 1024 (order: 1, 8192 bytes)
507I0922 15:30:54.124456   12712 init_comm.go:68] [console] TCP bind hash table entries: 1024 (order: 2, 16384 bytes)
508I0922 15:30:54.125178   12712 init_comm.go:68] [console] TCP: Hash tables configured (established 1024 bind 1024)
509I0922 15:30:54.126395   12712 init_comm.go:68] [console] UDP hash table entries: 256 (order: 1, 8192 bytes)
510I0922 15:30:54.127699   12712 init_comm.go:68] [console] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes)
511I0922 15:30:54.129536   12712 init_comm.go:68] [console] NET: Registered protocol family 1
512I0922 15:30:54.130567   12712 init_comm.go:68] [console] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
513I0922 15:30:54.131328   12712 init_comm.go:68] [console] pci 0000:00:01.0: PIIX3: Enabling Passive Release
514I0922 15:30:54.132322   12712 init_comm.go:68] [console] pci 0000:00:01.0: Activating ISA DMA hang workarounds
515I0922 15:30:54.136444   12712 init_comm.go:68] [console] Trying to unpack rootfs image as initramfs...
516I0922 15:30:54.498691   12712 init_comm.go:68] [console] Freeing initrd memory: 4976K (ffff880007b14000 - ffff880007ff0000)
517I0922 15:30:54.503535   12712 init_comm.go:68] [console] futex hash table entries: 256 (order: 2, 16384 bytes)
518I0922 15:30:54.509082   12712 init_comm.go:68] [console] SGI XFS with ACLs, security attributes, no debug enabled
519I0922 15:30:54.511163   12712 init_comm.go:68] [console] 9p: Installing v9fs 9p2000 file system support
520I0922 15:30:54.548610   12712 init_comm.go:68] [console] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 253)
521I0922 15:30:54.549537   12712 init_comm.go:68] [console] io scheduler noop registered
522I0922 15:30:54.550528   12712 init_comm.go:68] [console] io scheduler cfq registered (default)
523I0922 15:30:54.552210   12712 init_comm.go:68] [console] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
524I0922 15:30:54.553121   12712 init_comm.go:68] [console] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
525I0922 15:30:54.554632   12712 init_comm.go:68] [console] Warning: Processor Platform Limit event detected, but not handled.
526I0922 15:30:54.555080   12712 init_comm.go:68] [console] Consider compiling CPUfreq support into your kernel.
527I0922 15:30:54.845928   12712 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKB] enabled at IRQ 10
528I0922 15:30:54.847206   12712 init_comm.go:68] [console] virtio-pci 0000:00:02.0: virtio_pci: leaving for legacy driver
529I0922 15:30:55.144724   12712 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 11
530I0922 15:30:55.145345   12712 init_comm.go:68] [console] virtio-pci 0000:00:03.0: virtio_pci: leaving for legacy driver
531I0922 15:30:55.428450   12712 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 11
532I0922 15:30:55.429083   12712 init_comm.go:68] [console] virtio-pci 0000:00:04.0: virtio_pci: leaving for legacy driver
533I0922 15:30:55.430622   12712 init_comm.go:68] [console] virtio-pci 0000:00:05.0: enabling device (0000 -> 0003)
534I0922 15:30:55.717623   12712 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 10
535I0922 15:30:55.718936   12712 init_comm.go:68] [console] virtio-pci 0000:00:05.0: virtio_pci: leaving for legacy driver
536I0922 15:30:55.722297   12712 init_comm.go:68] [console] tsc: Refined TSC clocksource calibration: 2494.360 MHz
537I0922 15:30:55.722852   12712 init_comm.go:68] [console] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x23f46a15b30, max_idle_ns: 440795281732 ns
538I0922 15:30:55.724713   12712 init_comm.go:68] [console] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
539I0922 15:30:55.748924   12712 init_comm.go:68] [console] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
540I0922 15:30:55.796252   12712 init_comm.go:68] [console] brd: module loaded
541I0922 15:30:55.797702   12712 init_comm.go:68] [console] loop: module loaded
542I0922 15:30:55.800423   12712 init_comm.go:68] [console] scsi host0: Virtio SCSI HBA
543I0922 15:30:55.809865   12712 init_comm.go:68] [console] scsi 0:0:0:0: Direct-Access     QEMU     QEMU HARDDISK    2.0. PQ: 0 ANSI: 5
544I0922 15:30:55.972740   12712 init_comm.go:68] [console] sd 0:0:0:0: [sda] 20971520 512-byte logical blocks: (10.7 GB/10.0 GiB)
545I0922 15:30:55.974417   12712 init_comm.go:68] [console] sd 0:0:0:0: [sda] Write Protect is off
546I0922 15:30:55.976223   12712 init_comm.go:68] [console] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
547I0922 15:30:55.978596   12712 init_comm.go:68] [console] sd 0:0:0:0: Attached scsi generic sg0 type 0
548I0922 15:30:55.983778   12712 init_comm.go:68] [console] rtc_cmos 00:00: RTC can wake from S4
549I0922 15:30:55.992900   12712 init_comm.go:68] [console] sd 0:0:0:0: [sda] Attached SCSI disk
550I0922 15:30:55.994684   12712 init_comm.go:68] [console] rtc_cmos 00:00: rtc core: registered rtc_cmos as rtc0
551I0922 15:30:55.996396   12712 init_comm.go:68] [console] rtc_cmos 00:00: alarms up to one day, y3k, 114 bytes nvram
552I0922 15:30:55.998027   12712 init_comm.go:68] [console] Initializing XFRM netlink socket
553I0922 15:30:55.999187   12712 init_comm.go:68] [console] NET: Registered protocol family 10
554I0922 15:30:56.006848   12712 init_comm.go:68] [console] NET: Registered protocol family 17
555I0922 15:30:56.008647   12712 init_comm.go:68] [console] bridge: automatic filtering via arp/ip/ip6tables has been deprecated. Update your scripts to load br_netfilter if you need this.
556I0922 15:30:56.009515   12712 init_comm.go:68] [console] Bridge firewalling registered
557I0922 15:30:56.010560   12712 init_comm.go:68] [console] 9pnet: Installing 9P2000 support
558I0922 15:30:56.014191   12712 init_comm.go:68] [console] registered taskstats version 1
559I0922 15:30:56.018008   12712 init_comm.go:68] [console] rtc_cmos 00:00: setting system clock to 2016-09-22 07:30:55 UTC (1474529455)
560I0922 15:30:56.040704   12712 init_comm.go:68] [console] Freeing unused kernel memory: 876K (ffffffff81690000 - ffffffff8176b000)
561I0922 15:30:56.116134   12712 init_comm.go:68] [console] create directory /sys
562I0922 15:30:56.120667   12712 init_comm.go:68] [console] create directory /sbin
563I0922 15:30:56.123141   12712 init_comm.go:68] [console] create directory /proc
564I0922 15:30:56.130174   12712 init_comm.go:68] [console] uptime 2.48 0.21
565I0922 15:30:56.130750   12712 init_comm.go:68] [console]
566I0922 15:30:56.136061   12712 init_comm.go:68] [console] create directory /dev/pts
567I0922 15:30:56.150388   12712 init_comm.go:68] [console] open hyper channel /dev/vport0p1
568I0922 15:30:56.152124   12712 qmp_handler.go:103] got a message {"timestamp": {"seconds": 1474529456, "microseconds": 151969}, "event": "VSERPORT_CHANGE", "data": {"open": true, "id": "channel0"}}
569I0922 15:30:56.152216   12712 qmp_handler.go:107] got event: VSERPORT_CHANGE
570I0922 15:30:56.152398   12712 qmp_handler.go:323] got QMP event VSERPORT_CHANGE
571I0922 15:30:56.154081   12712 init_comm.go:68] [console] send ready message
572I0922 15:30:56.155299   12712 init_comm.go:68] [console] hyper send type 8, len 0
573I0922 15:30:56.156026   12712 init_comm.go:106] read 8/8 [length = 0]
574I0922 15:30:56.156055   12712 init_comm.go:110] data length is 8
575I0922 15:30:56.156064   12712 init_comm.go:152] Get init ready message
576I0922 15:30:56.156090   12712 init_comm.go:225] got cmd:1
577I0922 15:30:56.156092   12712 hypervisor.go:29] vm vm-iZqpFsRQwq: main event loop got message 5(EVENT_INIT_CONNECTED)
578I0922 15:30:56.156111   12712 vm_states.go:480] begin to wait vm commands
579I0922 15:30:56.156133   12712 vm.go:275] Get the response from VM, VM id is vm-iZqpFsRQwq!
580I0922 15:30:56.156144   12712 init_comm.go:96] trying to read 8 bytes
581I0922 15:30:56.156161   12712 init_comm.go:316] send command 1 to init, payload: '{"hostname":"ubuntu-7378494712","containers":[{"id":"aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673","rootfs":"/rootfs","fstype":"xfs","image":"sda","fsmap":[{"source":"njznJfWEVL","path":"/etc/hosts","readOnly":false,"dockerVolume":false}],"process":{"terminal":true,"stdio":1,"args":["/bin/bash"],"envs":[{"env":"PATH","value":"/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"}],"workdir":"/"},"restartPolicy":"never","initialize":true}],"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"}'.
582I0922 15:30:56.156193   12712 init_comm.go:329] write 512 to init, payload: '�{"hostname":"ubuntu-7378494712","containers":[{"id":"aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673","rootfs":"/rootfs","fstype":"xfs","image":"sda","fsmap":[{"source":"njznJfWEVL","path":"/etc/hosts","readOnly":false,"dockerVolume":false}],"process":{"terminal":true,"stdio":1,"args":["/bin/bash"],"envs":[{"env":"PATH","value":"/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"}],"workdir":"/"},"restartPolicy":"never","initialize":true}],"interfaces":[{"device":"eth0","i'.
583I0922 15:30:56.156204   12712 init_comm.go:334] message sent, set pong timer
584I0922 15:30:56.156210   12712 init_comm.go:225] got cmd:0
585I0922 15:30:56.156216   12712 init_comm.go:316] send command 0 to init, payload: 'null'.
586I0922 15:30:56.162717   12712 init_comm.go:68] [console] channel sh.hyper.channel.1, directory sh.hyper.channel.0
587I0922 15:30:56.163003   12712 init_comm.go:68] [console]
588I0922 15:30:56.165021   12712 init_comm.go:68] [console] open hyper channel /dev/vport0p2
589I0922 15:30:56.165576   12712 qmp_handler.go:103] got a message {"timestamp": {"seconds": 1474529456, "microseconds": 165467}, "event": "VSERPORT_CHANGE", "data": {"open": true, "id": "channel1"}}
590I0922 15:30:56.165637   12712 qmp_handler.go:107] got event: VSERPORT_CHANGE
591I0922 15:30:56.165842   12712 qmp_handler.go:323] got QMP event VSERPORT_CHANGE
592I0922 15:30:56.172782   12712 init_comm.go:68] [console] hyper_init_event hyper channel event 0x61c600, ops 0x61c3e0, fd 3
593I0922 15:30:56.174009   12712 init_comm.go:68] [console] hyper_add_event add event fd 3, 0x61c3e0
594I0922 15:30:56.175658   12712 init_comm.go:68] [console] hyper_init_event hyper ttyfd event 0x61c5c8, ops 0x61c3a0, fd 4
595I0922 15:30:56.176525   12712 init_comm.go:68] [console] hyper_add_event add event fd 4, 0x61c3a0
596I0922 15:30:56.177659   12712 init_comm.go:68] [console] hyper_loop epoll_wait 1
597I0922 15:30:56.178051   12712 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x61c600, fd 3. ops 0x61c3e0
598I0922 15:30:56.178827   12712 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x61c600, fd 3, 0x61c3e0
599I0922 15:30:56.179232   12712 init_comm.go:68] [console] hyper_event_read
600I0922 15:30:56.180011   12712 init_comm.go:68] [console] already read 8 bytes data
601I0922 15:30:56.180699   12712 init_comm.go:68] [console] hyper send type 14, len 4
602I0922 15:30:56.180979   12712 init_comm.go:106] read 8/8 [length = 0]
603I0922 15:30:56.181005   12712 init_comm.go:110] data length is 12
604I0922 15:30:56.181010   12712 init_comm.go:96] trying to read 4 bytes
605I0922 15:30:56.181304   12712 init_comm.go:106] read 12/12 [length = 12]
606I0922 15:30:56.181321   12712 init_comm.go:96] trying to read 8 bytes
607I0922 15:30:56.181332   12712 init_comm.go:225] got cmd:14
608I0922 15:30:56.181337   12712 init_comm.go:288] get command NEXT
609I0922 15:30:56.181342   12712 init_comm.go:291] send 512, receive 8
610I0922 15:30:56.182021   12712 init_comm.go:68] [console] get length 663
611I0922 15:30:56.182736   12712 init_comm.go:68] [console] read 504 bytes data, total data 512
612I0922 15:30:56.183199   12712 init_comm.go:68] [console] hyper send type 14, len 4
613I0922 15:30:56.183598   12712 init_comm.go:106] read 8/8 [length = 0]
614I0922 15:30:56.183610   12712 init_comm.go:110] data length is 12
615I0922 15:30:56.183613   12712 init_comm.go:96] trying to read 4 bytes
616I0922 15:30:56.183867   12712 init_comm.go:106] read 12/12 [length = 12]
617I0922 15:30:56.183880   12712 init_comm.go:96] trying to read 8 bytes
618I0922 15:30:56.183893   12712 init_comm.go:225] got cmd:14
619I0922 15:30:56.183898   12712 init_comm.go:288] get command NEXT
620I0922 15:30:56.183902   12712 init_comm.go:291] send 512, receive 512
621I0922 15:30:56.183910   12712 init_comm.go:329] write 163 to init, payload: 'pAddress":"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"}
622                                                                                                                                                                                                                                    null'.
623I0922 15:30:56.184784   12712 init_comm.go:68] [console] hyper_loop epoll_wait 1
624I0922 15:30:56.185736   12712 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x61c600, fd 3. ops 0x61c3e0
625I0922 15:30:56.186680   12712 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x61c600, fd 3, 0x61c3e0
626I0922 15:30:56.187178   12712 init_comm.go:68] [console] hyper_event_read
627I0922 15:30:56.187645   12712 init_comm.go:68] [console] get length 663
628I0922 15:30:56.188204   12712 init_comm.go:68] [console] read 151 bytes data, total data 663
629I0922 15:30:56.188788   12712 init_comm.go:68] [console] hyper send type 14, len 4
630I0922 15:30:56.188969   12712 init_comm.go:106] read 8/8 [length = 0]
631I0922 15:30:56.188979   12712 init_comm.go:110] data length is 12
632I0922 15:30:56.188982   12712 init_comm.go:96] trying to read 4 bytes
633I0922 15:30:56.189183   12712 init_comm.go:106] read 12/12 [length = 12]
634I0922 15:30:56.189202   12712 init_comm.go:96] trying to read 8 bytes
635I0922 15:30:56.189212   12712 init_comm.go:225] got cmd:14
636I0922 15:30:56.189216   12712 init_comm.go:288] get command NEXT
637I0922 15:30:56.189220   12712 init_comm.go:291] send 163, receive 151
638I0922 15:30:56.197543   12712 init_comm.go:68] [console] 0 0 0 1 0 0 2 97 7b 22 68 6f 73 74 6e 61 6d 65 22 3a 22 75 62 75 6e 74 75 2d 37 33 37 38 34 39 34 37 31 32 22 2c 22 63 6f 6e 74 61 69 6e 65 72 73 22 3a 5b 7b 22 69 64 22 3a 22 61 61 38 38 32 36 65 64 61 62 37 66 35 33 35 35 30 63 30 65 35 32 61 65 30 65 31 34 64 61 37 33 66 62 64 65 66 36 38 37 37 36 63 33 63 38 30 66 30 35 61 33 64 39 37 63 61 37 38 31 64 36 37 33 22 2c 22 72 6f 6f 74 66 73 22 3a 22 2f 72 6f 6f 74 66 73 22 2c 22 66 73 74 79 70 65 22 3a 22 78 66 73 22 2c 22 69 6d 61 67 65 22 3a 22 73 64 61 22 2c 22 66 73 6d 61 70 22 3a 5b 7b 22 73 6f 75 72 63 65 22 3a 22 6e 6a 7a 6e 4a 66 57 45 56 4c 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 62 61 73 68 22 5d 2c 22 65 6e 76 73 22 3a 5b 7b 22 65 6e 76 22 3a 22 50 41 54 48 22 2c 22 76 61 6c 75 65 22 3a 22 2f 75 73 72 2f 6c 6f 63 61 6c 2f 73 62 69 6e 3a 2f 75 73 72 2f 6c 6f 63 61 6c 2f 62 69 6e 3a 2f 75 73 72 2f 73 62 69 6e 3a 2f 75 73 72 2f 62 69 6e 3a 2f 73 62 69 6e 3a 2f 62 69 6e 22 7d 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 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
639I0922 15:30:56.198370   12712 init_comm.go:68] [console]  hyper_channel_handle, type 1, len 663
640I0922 15:30:56.202663   12712 init_comm.go:68] [console] call hyper_start_pod, json {"hostname":"ubuntu-7378494712","containers":[{"id":"aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673","rootfs":"/rootfs","fstype":"xfs","image":"sda","fsmap":[{"source":"njznJfWEVL","path":"/etc/hosts","readOnly":false,"dockerVolume":false}],"process":{"terminal":true,"stdio":1,"args":["/bin/bash"],"envs":[{"env":"PATH","value":"/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"}],"workdir":"/"},"restartPolicy":"never","initialize":true}],"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 655
641I0922 15:30:56.215217   12712 init_comm.go:68] [console] call hyper_start_pod, json {"hostname":"ubuntu-7378494712","containers":[{"id":"aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673","rootfs":"/rootfs","fstype":"xfs","image":"sda","fsmap":[{"source":"njznJfWEVL","path":"/etc/hosts","readOnly":false,"dockerVolume":false}],"process":{"terminal":true,"stdio":1,"args":["/bin/bash"],"envs":[{"env":"PATH","value":"/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"}],"workdir":"/"},"restartPolicy":"never","initialize":true}],"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 655
642I0922 15:30:56.222525   12712 init_comm.go:68] [console] jsmn parse successed, n is 67
643I0922 15:30:56.222886   12712 init_comm.go:68] [console] token 0, type is 1, size is 5
644I0922 15:30:56.223698   12712 init_comm.go:68] [console] token 1, type is 3, size is 1
645I0922 15:30:56.224573   12712 init_comm.go:68] [console] hostname is ubuntu-7378494712
646I0922 15:30:56.229152   12712 init_comm.go:68] [console] random: busybox urandom read with 25 bits of entropy available
647I0922 15:30:56.230162   12712 init_comm.go:68] [console] token 3, type is 3, size is 1
648I0922 15:30:56.230688   12712 init_comm.go:68] [console] container count 1
649I0922 15:30:56.231405   12712 init_comm.go:68] [console] next container 8
650I0922 15:30:56.231827   12712 init_comm.go:68] [console] 1 name id
651I0922 15:30:56.232951   12712 init_comm.go:68] [console] container id aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673
652I0922 15:30:56.236963   12712 init_comm.go:68] [console] 3 name rootfs
653I0922 15:30:56.242195   12712 init_comm.go:68] [console] container rootfs /rootfs
654I0922 15:30:56.242903   12712 init_comm.go:68] [console] 5 name fstype
655I0922 15:30:56.243103   12712 init_comm.go:68] [console] container fstype xfs
656I0922 15:30:56.243582   12712 init_comm.go:68] [console] 7 name image
657I0922 15:30:56.244002   12712 init_comm.go:68] [console] container image sda
658I0922 15:30:56.244453   12712 init_comm.go:68] [console] 9 name fsmap
659I0922 15:30:56.244809   12712 init_comm.go:68] [console] fsmap num 1
660I0922 15:30:56.245354   12712 init_comm.go:68] [console] maps 0 source njznJfWEVL
661I0922 15:30:56.245774   12712 init_comm.go:68] [console] maps 0 path /etc/hosts
662I0922 15:30:56.246180   12712 init_comm.go:68] [console] maps 0 readonly 0
663I0922 15:30:56.246657   12712 init_comm.go:68] [console] maps 0 docker volume 0
664I0922 15:30:56.246907   12712 init_comm.go:68] [console] 20 name process
665I0922 15:30:56.247480   12712 init_comm.go:68] [console] 1 name terminal
666I0922 15:30:56.251177   12712 init_comm.go:68] [console] container uses terminal
667I0922 15:30:56.251809   12712 init_comm.go:68] [console] 3 name stdio
668I0922 15:30:56.252649   12712 init_comm.go:68] [console] container seq 1
669I0922 15:30:56.253064   12712 init_comm.go:68] [console] 5 name args
670I0922 15:30:56.253893   12712 init_comm.go:68] [console] container init arg 0 /bin/bash
671I0922 15:30:56.254211   12712 init_comm.go:68] [console] 8 name envs
672I0922 15:30:56.255024   12712 init_comm.go:68] [console] envs num 1
673I0922 15:30:56.255951   12712 init_comm.go:68] [console] envs 0 env PATH
674I0922 15:30:56.257000   12712 init_comm.go:68] [console] envs 0 value /usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
675I0922 15:30:56.257463   12712 init_comm.go:68] [console] 15 name workdir
676I0922 15:30:56.257837   12712 init_comm.go:68] [console] container workdir /
677I0922 15:30:56.258729   12712 init_comm.go:68] [console] 38 name restartPolicy
678I0922 15:30:56.259582   12712 init_comm.go:68] [console] restart policy never
679I0922 15:30:56.260084   12712 init_comm.go:68] [console] 40 name initialize
680I0922 15:30:56.260662   12712 init_comm.go:68] [console] need to initialize container
681I0922 15:30:56.261572   12712 init_comm.go:68] [console] token 47, type is 3, size is 1
682I0922 15:30:56.261981   12712 init_comm.go:68] [console] network interfaces num 1
683I0922 15:30:56.263390   12712 init_comm.go:68] [console] net device is eth0
684I0922 15:30:56.263975   12712 init_comm.go:68] [console] net ipaddress is 192.168.123.2
685I0922 15:30:56.264603   12712 init_comm.go:68] [console] net mask is 255.255.255.0
686I0922 15:30:56.265200   12712 init_comm.go:68] [console] token 56, type is 3, size is 1
687I0922 15:30:56.265743   12712 init_comm.go:68] [console] network routes num 1
688I0922 15:30:56.266627   12712 init_comm.go:68] [console] route 0 dest is 0.0.0.0/0
689I0922 15:30:56.267129   12712 init_comm.go:68] [console] route 0 gateway is 192.168.123.1
690I0922 15:30:56.267892   12712 init_comm.go:68] [console] route 0 device is eth0
691I0922 15:30:56.268964   12712 init_comm.go:68] [console] token 65, type is 3, size is 1
692I0922 15:30:56.269603   12712 init_comm.go:68] [console] share tag is share_dir
693I0922 15:30:56.270100   12712 init_comm.go:68] [console] create directory /tmp
694I0922 15:30:56.271281   12712 init_comm.go:68] [console] create directory /tmp/hyper
695I0922 15:30:56.272885   12712 init_comm.go:68] [console] create directory /tmp/hyper/proc
696I0922 15:30:56.275081   12712 init_comm.go:68] [console] finish rescan
697I0922 15:30:56.277520   12712 init_comm.go:68] [console] net device eth0
698I0922 15:30:56.278502   12712 init_comm.go:68] [console] net device sys path is /sys/class/net/eth0/ifindex
699I0922 15:30:56.279160   12712 init_comm.go:68] [console] get ifindex 2
700I0922 15:30:56.280485   12712 init_comm.go:68] [console] interface get netamsk 24 255.255.255.0
701I0922 15:30:56.291100   12712 qmp_handler.go:103] got a message {"timestamp": {"seconds": 1474529456, "microseconds": 290948}, "event": "NIC_RX_FILTER_CHANGED", "data": {"name": "eth0", "path": "/machine/peripheral/eth0/virtio-backend"}}
702I0922 15:30:56.291139   12712 qmp_handler.go:107] got event: NIC_RX_FILTER_CHANGED
703I0922 15:30:56.291310   12712 qmp_handler.go:323] got QMP event NIC_RX_FILTER_CHANGED
704I0922 15:30:56.304769   12712 init_comm.go:68] [console] net device eth0
705I0922 15:30:56.305478   12712 init_comm.go:68] [console] net device sys path is /sys/class/net/eth0/ifindex
706I0922 15:30:56.305996   12712 init_comm.go:68] [console] get ifindex 2
707I0922 15:30:56.309419   12712 init_comm.go:68] [console] create directory /tmp/hyper/shared
708I0922 15:30:56.321487   12712 init_comm.go:68] [console] pod init pid 327
709I0922 15:30:56.326621   12712 init_comm.go:68] [console] hyper send type 8, len 0
710I0922 15:30:56.331045   12712 init_comm.go:68] [console] create directory /tmp/hyper/aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673
711I0922 15:30:56.332869   12712 init_comm.go:68] [console] create directory /tmp/hyper/aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673/devpts
712I0922 15:30:56.334055   12712 init_comm.go:68] [console] create directory /tmp/hyper/aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673/devpts/
713I0922 15:30:56.341137   12712 init_comm.go:68] [console] hyper send type 8, len 0
714I0922 15:30:56.345002   12712 init_comm.go:68] [console] create child process pid=329 in the sandbox
715I0922 15:30:56.348989   12712 init_comm.go:68] [console] path /sys/class/scsi_host/host0/scan
716I0922 15:30:56.487256   12712 init_comm.go:68] [console] finish scan scsi
717I0922 15:30:56.489065   12712 init_comm.go:68] [console] create directory /tmp/hyper/aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673/root
718I0922 15:30:56.490246   12712 init_comm.go:68] [console] create directory /tmp/hyper/aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673/root/
719I0922 15:30:56.491022   12712 init_comm.go:68] [console] container root directory /tmp/hyper/aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673/root/
720I0922 15:30:56.492286   12712 init_comm.go:68] [console] device /dev/sda
721I0922 15:30:56.508269   12712 init_comm.go:68] [console] XFS (sda): Mounting V5 Filesystem
722I0922 15:30:56.601196   12712 init_comm.go:68] [console] XFS (sda): Ending clean mount
723I0922 15:30:56.602254   12712 init_comm.go:68] [console] root directory for container is /tmp/hyper/aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673/root///rootfs, init task /bin/bash
724I0922 15:30:56.617502   12712 init_comm.go:68] [console] recreate file ./etc/hosts
725I0922 15:30:56.622186   12712 init_comm.go:68] [console] recreate file ./etc/hostname
726I0922 15:30:56.623792   12712 init_comm.go:68] [console] recreate symlink ./etc/mtab to /proc/mounts
727I0922 15:30:56.644945   12712 init_comm.go:68] [console] create directory ./lib/modules
728I0922 15:30:56.650163   12712 init_comm.go:68] [console] create directory ./dev/shm
729I0922 15:30:56.653341   12712 init_comm.go:68] [console] create directory .//lib/modules/4.4.12-hyper
730I0922 15:30:56.658734   12712 init_comm.go:68] [console] mount /tmp/hyper/shared/njznJfWEVL to .//etc/hosts
731I0922 15:30:56.665988   12712 init_comm.go:68] [console] no dns configured
732I0922 15:30:56.667824   12712 init_comm.go:68] [console] hyper send type 8, len 0
733I0922 15:30:56.679211   12712 init_comm.go:68] [console] get pty device for exec /tmp/hyper/aa8826edab7f53550c0e52ae0e14da73fbdef68776c3c80f05a3d97ca781d673/devpts//0
734I0922 15:30:56.680281   12712 init_comm.go:68] [console] hyper_setup_exec_tty pts event 0xd4c830, fd 6 7
735I0922 15:30:56.681117   12712 init_comm.go:68] [console] hyper_init_event container pts event 0xd4c830, ops 0x61c540, fd 6
736I0922 15:30:56.681626   12712 init_comm.go:68] [console] hyper_add_event add event fd 6, 0x61c540
737I0922 15:30:56.682482   12712 init_comm.go:68] [console] hyper_add_event add event fd 8, 0x61c500
738I0922 15:30:56.682995   12712 init_comm.go:68] [console] hyper_add_event add event fd 9, 0x61c4c0
739I0922 15:30:56.684229   12712 init_comm.go:68] [console] do_exec_cmd pid 594
740I0922 15:30:56.687045   12712 init_comm.go:68] [console] create child process pid=595 in the sandbox
741I0922 15:30:56.687541   12712 init_comm.go:68] [console] hyper send type 595, len 0
742I0922 15:30:56.688557   12712 init_comm.go:68] [console] hyper_run_process get ready message 595
743I0922 15:30:56.689595   12712 init_comm.go:68] [console] uptime 3.04 0.26
744I0922 15:30:56.689640   12712 init_comm.go:68] [console]
745I0922 15:30:56.690283   12712 init_comm.go:68] [console] hyper send type 9, len 0
746I0922 15:30:56.691937   12712 init_comm.go:106] read 8/8 [length = 0]
747I0922 15:30:56.691966   12712 init_comm.go:110] data length is 8
748I0922 15:30:56.691977   12712 init_comm.go:96] trying to read 8 bytes
749I0922 15:30:56.691988   12712 init_comm.go:225] got cmd:9
750I0922 15:30:56.692005   12712 init_comm.go:244] ack got, clear pong timer
751I0922 15:30:56.692019   12712 hypervisor.go:29] vm vm-iZqpFsRQwq: main event loop got message 31(COMMAND_ACK)
752I0922 15:30:56.692026   12712 vm_states.go:490] [starting] got init ack to &{1 859539954288 <nil> [] 859539411456}
753I0922 15:30:56.692301   12712 context.go:260] VM vm-iZqpFsRQwq: state change from STARTING to 'RUNNING'
754I0922 15:30:56.692314   12712 vm_states.go:506] pod start success
755I0922 15:30:56.692330   12712 vm.go:275] Get the response from VM, VM id is vm-iZqpFsRQwq!
756I0922 15:30:56.692437   12712 pod.go:1299] Add or Update the VM info for pod(pod-orbBigFyPD)
757I0922 15:30:56.692469   12712 pod.go:332] unlock pod pod-orbBigFyPD for operation start
758I0922 15:30:56.692475   12712 pod.go:335] successfully unlock pod pod-orbBigFyPD for operation start
759I0922 15:30:56.693998   12712 init_comm.go:68] [console] hyper_loop epoll_wait 2
760I0922 15:30:56.694864   12712 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x61c600, fd 3. ops 0x61c3e0
761I0922 15:30:56.698880   12712 init_comm.go:68] [console] hyper_dup_exec_tty
762I0922 15:30:56.701775   12712 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x61c600, fd 3, 0x61c3e0
763I0922 15:30:56.702154   12712 init_comm.go:68] [console] hyper_event_read
764I0922 15:30:56.703084   12712 init_comm.go:68] [console] already read 8 bytes data
765I0922 15:30:56.704091   12712 init_comm.go:68] [console] hyper send type 14, len 4
766I0922 15:30:56.711863   12712 init_comm.go:106] read 8/8 [length = 0]
767I0922 15:30:56.711901   12712 init_comm.go:110] data length is 12
768I0922 15:30:56.711906   12712 init_comm.go:96] trying to read 4 bytes
769I0922 15:30:56.712075   12712 init_comm.go:106] read 12/12 [length = 12]
770I0922 15:30:56.712091   12712 init_comm.go:96] trying to read 8 bytes
771I0922 15:30:56.712102   12712 init_comm.go:225] got cmd:14
772I0922 15:30:56.712108   12712 init_comm.go:288] get command NEXT
773I0922 15:30:56.712116   12712 init_comm.go:291] send 163, receive 159
774I0922 15:30:56.712768   12712 init_comm.go:68] [console] get length 12
775I0922 15:30:56.713002   12712 init_comm.go:68] [console] read 4 bytes data, total data 12
776I0922 15:30:56.713534   12712 init_comm.go:68] [console] hyper send type 14, len 4
777I0922 15:30:56.713643   12712 init_comm.go:106] read 8/8 [length = 0]
778I0922 15:30:56.713685   12712 init_comm.go:110] data length is 12
779I0922 15:30:56.713709   12712 init_comm.go:96] trying to read 4 bytes
780I0922 15:30:56.713844   12712 init_comm.go:106] read 12/12 [length = 12]
781I0922 15:30:56.713860   12712 init_comm.go:96] trying to read 8 bytes
782I0922 15:30:56.713880   12712 init_comm.go:225] got cmd:14
783I0922 15:30:56.713889   12712 init_comm.go:288] get command NEXT
784I0922 15:30:56.713895   12712 init_comm.go:291] send 163, receive 163
785I0922 15:30:56.714162   12712 init_comm.go:68] [console] 0 0 0 0 0 0 0 c 6e 75 6c 6c
786I0922 15:30:56.714674   12712 init_comm.go:68] [console]  hyper_channel_handle, type 0, len 12
787I0922 15:30:56.714855   12712 init_comm.go:68] [console] hyper send type 9, len 4
788I0922 15:30:56.714954   12712 init_comm.go:106] read 8/8 [length = 0]
789I0922 15:30:56.714963   12712 init_comm.go:110] data length is 12
790I0922 15:30:56.714966   12712 init_comm.go:96] trying to read 4 bytes
791I0922 15:30:56.714971   12712 init_comm.go:106] read 12/12 [length = 12]
792I0922 15:30:56.714975   12712 init_comm.go:96] trying to read 8 bytes
793I0922 15:30:56.714982   12712 init_comm.go:225] got cmd:9
794I0922 15:30:56.714990   12712 init_comm.go:198] hyperstart API version:4242, VM hyperstart API version: 4242
795I0922 15:30:56.715147   12712 init_comm.go:68] [console] hyper_handle_event get event 4, he 0xd4c830, fd 6. ops 0x61c540
796I0922 15:30:56.715638   12712 init_comm.go:68] [console] hyper_handle_event event EPOLLOUT, he 0xd4c830, fd 6, 0x61c540
797I0922 15:30:56.717124   12712 init_comm.go:68] [console] write_to_stdin, seq 1
798I0922 15:30:56.725219   12712 init_comm.go:68] [console] hyper_modify_event modify event fd 6, 0xd4c830, event 0
799I0922 15:30:56.730640   12712 init_comm.go:68] [console] clocksource: Switched to clocksource tsc
800I0922 15:30:56.739695   12712 init_comm.go:68] [console] pid 326 exit normally, status 0
801I0922 15:30:56.749151   12712 init_comm.go:68] [console] exec pid 595, pid 326
802I0922 15:30:56.750025   12712 init_comm.go:68] [console] can not find exec whose pid is 326
803I0922 15:30:56.752499   12712 init_comm.go:68] [console] pid 328 exit normally, status 0
804I0922 15:30:56.753543   12712 init_comm.go:68] [console] exec pid 595, pid 328
805I0922 15:30:56.755925   12712 init_comm.go:68] [console] can not find exec whose pid is 328
806I0922 15:30:56.760188   12712 init_comm.go:68] [console] pid 329 exit normally, status 0
807I0922 15:30:56.760896   12712 init_comm.go:68] [console] exec pid 595, pid 329
808I0922 15:30:56.761707   12712 init_comm.go:68] [console] can not find exec whose pid is 329
809I0922 15:30:56.763214   12712 init_comm.go:68] [console] pid 594 exit normally, status 0
810I0922 15:30:56.764794   12712 init_comm.go:68] [console] exec pid 595, pid 594
811I0922 15:30:56.765488   12712 init_comm.go:68] [console] can not find exec whose pid is 594
812I0922 15:30:56.770917   12712 init_comm.go:68] [console] hyper_loop epoll_wait -1
813I0922 15:30:57.045171   12712 init_comm.go:68] [console] random: nonblocking pool is initialized
814I0922 15:30:57.282707   12712 init_comm.go:68] [console] hyper_loop epoll_wait 2
815I0922 15:30:57.285902   12712 init_comm.go:68] [console] hyper_handle_event get event 1, he 0xd4c8a0, fd 9. ops 0x61c4c0
816I0922 15:30:57.287447   12712 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0xd4c8a0, fd 9, 0x61c4c0
817I0922 15:30:57.287893   12712 init_comm.go:68] [console] stderr_loop, seq 0
818I0922 15:30:57.289263   12712 init_comm.go:68] [console] pts_loop: read 56 data
819I0922 15:30:57.290206   12712 init_comm.go:68] [console] pts_loop: read -1 data
820I0922 15:30:57.291176   12712 init_comm.go:68] [console] hyper_modify_event modify event fd 4, 0x61c5c8, event 5
821I0922 15:30:57.292948   12712 init_comm.go:68] [console] hyper_handle_event get event 1, he 0xd4c868, fd 8. ops 0x61c500
822I0922 15:30:57.294639   12712 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0xd4c868, fd 8, 0x61c500
823I0922 15:30:57.295124   12712 init_comm.go:68] [console] stdout_loop, seq 1
824I0922 15:30:57.295785   12712 init_comm.go:68] [console] pts_loop: read -1 data
825I0922 15:30:57.296692   12712 init_comm.go:68] [console] hyper_loop epoll_wait 1
826I0922 15:30:57.297701   12712 init_comm.go:68] [console] hyper_handle_event get event 4, he 0x61c5c8, fd 4. ops 0x61c3a0
827I0922 15:30:57.298594   12712 init_comm.go:68] [console] hyper_handle_event event EPOLLOUT, he 0x61c5c8, fd 4, 0x61c3a0
828I0922 15:30:57.299135   12712 tty.go:108] tty: read 12/12 [length = 0]
829I0922 15:30:57.299147   12712 tty.go:112] data length is 68
830I0922 15:30:57.299151   12712 tty.go:98] tty: trying to read 56 bytes
831I0922 15:30:57.299157   12712 tty.go:108] tty: read 68/68 [length = 68]
832I0922 15:30:57.299198   12712 tty.go:98] tty: trying to read 12 bytes
833I0922 15:30:57.300924   12712 init_comm.go:68] [console] hyper_modify_event modify event fd 4, 0x61c5c8, event 1