peUwZTvb

1[root@fedora24 hyper]# hyperd --v=5
2I0919 07:48:23.537105   20402 hyperd.go:106] The config file is 
3I0919 07:48:23.538048   20402 daemon.go:141] The config: kernel=/var/lib/hyper/kernel, initrd=/var/lib/hyper/hyper-initrd.img
4I0919 07:48:23.538068   20402 daemon.go:143] The config: vbox image=
5I0919 07:48:23.538084   20402 daemon.go:146] The config: bridge=, ip=
6I0919 07:48:23.538099   20402 daemon.go:149] The config: bios=, cbfs=
7DEBU[0000] Using default logging driver none            
8DEBU[0000] devicemapper: driver version is 4.34.0       
9DEBU[0000] devmapper: Generated prefix: docker-253:0-398548 
10DEBU[0000] devmapper: Checking for existence of the pool docker-253:0-398548-pool 
11DEBU[0000] devmapper: poolDataMajMin=7:0 poolMetaMajMin=7:1
12 
13DEBU[0000] devmapper: Major:Minor for device: /dev/loop0 is:7:0 
14DEBU[0000] devmapper: Major:Minor for device: /dev/loop1 is:7:1 
15DEBU[0000] devmapper: loadDeviceFilesOnStart()          
16DEBU[0000] devmapper: Loading data for file /var/lib/hyper/devicemapper/metadata/a30b73d2eda5421a430b11abb7250b749dd0133b801097899615d41e9701fec1 
17DEBU[0000] devmapper: Loading data for file /var/lib/hyper/devicemapper/metadata/a30b73d2eda5421a430b11abb7250b749dd0133b801097899615d41e9701fec1-init 
18DEBU[0000] devmapper: Loading data for file /var/lib/hyper/devicemapper/metadata/ba8214d42946e9de4da576bdc457667db09b745cb20e4e9635b0341b7c85ec40 
19DEBU[0000] devmapper: Loading data for file /var/lib/hyper/devicemapper/metadata/ba8214d42946e9de4da576bdc457667db09b745cb20e4e9635b0341b7c85ec40-init 
20DEBU[0000] devmapper: Loading data for file /var/lib/hyper/devicemapper/metadata/base 
21DEBU[0000] devmapper: Skipping file /var/lib/hyper/devicemapper/metadata/deviceset-metadata 
22DEBU[0000] devmapper: Loading data for file /var/lib/hyper/devicemapper/metadata/e57535c83466fa3d485307db5c098d1f1d9a7419caaf8bfd80f9827979a70625 
23DEBU[0000] devmapper: Loading data for file /var/lib/hyper/devicemapper/metadata/e8f8ff8d3acc8688fce00ea892ef4fc2f982aa802f8e6f39fa9438058b84c86d 
24DEBU[0000] devmapper: Skipping file /var/lib/hyper/devicemapper/metadata/transaction-metadata 
25DEBU[0000] devmapper: loadDeviceFilesOnStart() END      
26DEBU[0000] devmapper: constructDeviceIDMap()            
27DEBU[0000] devmapper: Added deviceId=3 to DeviceIdMap   
28DEBU[0000] devmapper: Added deviceId=1 to DeviceIdMap   
29DEBU[0000] devmapper: Added deviceId=7 to DeviceIdMap   
30DEBU[0000] devmapper: Added deviceId=2 to DeviceIdMap   
31DEBU[0000] devmapper: Added deviceId=11 to DeviceIdMap  
32DEBU[0000] devmapper: Added deviceId=10 to DeviceIdMap  
33DEBU[0000] devmapper: Added deviceId=4 to DeviceIdMap   
34DEBU[0000] devmapper: constructDeviceIDMap() END        
35WARN[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. 
36DEBU[0000] devmapper: activateDeviceIfNeeded()          
37DEBU[0000] devmapper: UUID for device: /dev/mapper/docker-253:0-398548-base is:b8b69fbb-a0c7-4d6c-94c6-bc9643b7dd99 
38WARN[0000] devmapper: Base device already exists and has filesystem xfs on it. User specified filesystem  will be ignored. 
39DEBU[0000] devmapper: deactivateDevice()                
40DEBU[0000] devmapper: removeDevice START(docker-253:0-398548-base) 
41DEBU[0000] devmapper: removeDevice END(docker-253:0-398548-base) 
42DEBU[0000] devmapper: deactivateDevice END()            
43INFO[0000] [graphdriver] using prior storage driver "devicemapper" 
44DEBU[0000] Using graph driver devicemapper              
45INFO[0000] Graph migration to content-addressability took 0.00 seconds 
46DEBU[0000] Option DefaultDriver: bridge                 
47DEBU[0000] Option DefaultNetwork: bridge                
48INFO[0000] Firewalld running: false                     
49DEBU[0000] Registering ipam driver: "default"           
50DEBU[0000] Cleaning up old shm/mqueue mounts: start.    
51DEBU[0000] Cleaning up old shm/mqueue mounts: done.     
52DEBU[0000] Loaded container 88de61dcbf7c921e7af440dbcf8be3125e9910c1549a956b2b04351b27df9832 
53DEBU[0000] Loaded container e129c9b952aaaf137ad1dffe0094f7749c213b3cb63afb1d215c29838a645826 
54I0919 07:48:24.261184   20402 server.go:70] Server created for HTTP on unix (/var/run/hyper.sock)
55Qemu Driver Loaded
56I0919 07:48:24.261661   20402 hyperd.go:193] The hypervisor's driver is qemu
57I0919 07:48:24.263041   20402 network_linux.go:263] bridge exist
58I0919 07:48:24.271238   20402 iptables_linux.go:140] /sbin/iptables, [--wait -t nat -C POSTROUTING -s 192.168.123.1/24 ! -o hyper0 -j MASQUERADE]
59I0919 07:48:24.276994   20402 iptables_linux.go:140] /sbin/iptables, [--wait -N HYPER]
60I0919 07:48:24.284452   20402 iptables_linux.go:140] /sbin/iptables, [--wait -t filter -C FORWARD -o hyper0 -j HYPER]
61I0919 07:48:24.290062   20402 iptables_linux.go:140] /sbin/iptables, [--wait -t filter -C FORWARD -i hyper0 -j ACCEPT]
62I0919 07:48:24.296377   20402 iptables_linux.go:140] /sbin/iptables, [--wait -t filter -C FORWARD -o hyper0 -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT]
63I0919 07:48:24.306415   20402 iptables_linux.go:140] /sbin/iptables, [--wait -t nat -N HYPER]
64I0919 07:48:24.310720   20402 iptables_linux.go:140] /sbin/iptables, [--wait -t nat -C OUTPUT -m addrtype --dst-type LOCAL ! -d 127.0.0.1/8 -j HYPER]
65I0919 07:48:24.314565   20402 iptables_linux.go:140] /sbin/iptables, [--wait -t nat -C PREROUTING -m addrtype --dst-type LOCAL -j HYPER]
66I0919 07:48:24.319242   20402 daemondb.go:220] got key from leveldb pod-container-pod-feMwpKISGX
67I0919 07:48:24.319322   20402 daemondb.go:220] got key from leveldb pod-container-pod-nLJWtxCRoh
68I0919 07:48:24.319383   20402 daemondb.go:220] got key from leveldb pod-pod-feMwpKISGX
69I0919 07:48:24.319447   20402 daemondb.go:220] got key from leveldb pod-pod-nLJWtxCRoh
70I0919 07:48:24.319505   20402 daemon.go:85] reloading pod pod-feMwpKISGX with args {"id":"fedora-6178177928","hostname":"","containers":[{"name":"fedora-6178177928","image":"fedora","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-feMwpKISGX-resolvconf","perm":"0644","user":"","group":""}],"restartPolicy":"never"}],"resource":{"vcpu":1,"memory":128},"files":[{"name":"pod-feMwpKISGX-resolvconf","encoding":"raw","uri":"file:///etc/resolv.conf","content":""}],"volumes":[{"name":"etchosts-volume","source":"/var/lib/hyper/hosts/pod-feMwpKISGX/hosts","driver":"vfs","option":{"monitors":null,"user":"","keyring":"","bytespersec":0,"iops":0}}],"labels":{},"log":{"type":"json-file","config":{}},"tty":true,"type":"","RestartPolicy":""}
71I0919 07:48:24.320666   20402 run.go:40] podArgs: id:"fedora-6178177928" tty:true resource:<vcpu:1 memory:128 > log:<type:"json-file" > containers:<name:"fedora-6178177928" image:"fedora" workdir:"/" restartPolicy:"never" tty:true volumes:<path:"/etc/hosts" volume:"etchosts-volume" > files:<path:"/etc/resolv.conf" filename:"pod-feMwpKISGX-resolvconf" perm:"0644" > user:<> > files:<name:"pod-feMwpKISGX-resolvconf" encoding:"raw" uri:"file:///etc/resolv.conf" > volumes:<name:"etchosts-volume" source:"/var/lib/hyper/hosts/pod-feMwpKISGX/hosts" driver:"vfs" option:<> > 
72I0919 07:48:24.321083   20402 pod.go:905] Already has resolv.conf configured, bypass DNS insert
73I0919 07:48:24.321112   20402 daemondb.go:82] try get container list for pod pod-feMwpKISGX
74I0919 07:48:24.321178   20402 pod.go:467] loaded containers for pod pod-feMwpKISGX: [88de61dcbf7c921e7af440dbcf8be3125e9910c1549a956b2b04351b27df9832]
75I0919 07:48:24.321201   20402 pod.go:475] Loading container 88de61dcbf7c921e7af440dbcf8be3125e9910c1549a956b2b04351b27df9832 of pod pod-feMwpKISGX
76I0919 07:48:24.321266   20402 pod.go:487] Found exist container fedora-6178177928 (88de61dcbf7c921e7af440dbcf8be3125e9910c1549a956b2b04351b27df9832), pod: pod-feMwpKISGX
77I0919 07:48:24.321284   20402 pod.go:520] do not need to create container fedora-6178177928 of pod pod-feMwpKISGX[0]
78I0919 07:48:24.321300   20402 pod.go:597] container name fedora-6178177928, image fedora
79I0919 07:48:24.321374   20402 pod.go:624] container info config &{88de61dcbf7c   false false false map[]  false false false [PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin] 0xc8205f16c0 false fedora map[]  <nil> true  [] map[] }, Cmd [/bin/bash], Args []
80I0919 07:48:24.321434   20402 pod.go:648] Container Info is 
81&{containerID:"88de61dcbf7c921e7af440dbcf8be3125e9910c1549a956b2b04351b27df9832" commands:"/bin/bash" env:<env:"PATH" value:"/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin" >  1474242318 ba8214d42946e9de4da576bdc457667db09b745cb20e4e9635b0341b7c85ec40   false}
82I0919 07:48:24.321669   20402 daemondb.go:91] try set container list for pod pod-feMwpKISGX: [88de61dcbf7c921e7af440dbcf8be3125e9910c1549a956b2b04351b27df9832]
83I0919 07:48:24.321788   20402 daemon.go:109] no existing VM for pod pod-feMwpKISGX: leveldb: not found
84I0919 07:48:24.321823   20402 daemon.go:85] reloading pod pod-nLJWtxCRoh with args {"id":"fedora-9735126198","hostname":"","containers":[{"name":"fedora-9735126198","image":"fedora","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-nLJWtxCRoh-resolvconf","perm":"0644","user":"","group":""}],"restartPolicy":"never"}],"resource":{"vcpu":1,"memory":128},"files":[{"name":"pod-nLJWtxCRoh-resolvconf","encoding":"raw","uri":"file:///etc/resolv.conf","content":""}],"volumes":[{"name":"etchosts-volume","source":"/var/lib/hyper/hosts/pod-nLJWtxCRoh/hosts","driver":"vfs","option":{"monitors":null,"user":"","keyring":"","bytespersec":0,"iops":0}}],"labels":{},"log":{"type":"json-file","config":{}},"tty":true,"type":"","RestartPolicy":""}
85I0919 07:48:24.322065   20402 run.go:40] podArgs: id:"fedora-9735126198" tty:true resource:<vcpu:1 memory:128 > log:<type:"json-file" > containers:<name:"fedora-9735126198" image:"fedora" workdir:"/" restartPolicy:"never" tty:true volumes:<path:"/etc/hosts" volume:"etchosts-volume" > files:<path:"/etc/resolv.conf" filename:"pod-nLJWtxCRoh-resolvconf" perm:"0644" > user:<> > files:<name:"pod-nLJWtxCRoh-resolvconf" encoding:"raw" uri:"file:///etc/resolv.conf" > volumes:<name:"etchosts-volume" source:"/var/lib/hyper/hosts/pod-nLJWtxCRoh/hosts" driver:"vfs" option:<> > 
86I0919 07:48:24.322172   20402 pod.go:905] Already has resolv.conf configured, bypass DNS insert
87I0919 07:48:24.322192   20402 daemondb.go:82] try get container list for pod pod-nLJWtxCRoh
88I0919 07:48:24.322235   20402 pod.go:467] loaded containers for pod pod-nLJWtxCRoh: [e129c9b952aaaf137ad1dffe0094f7749c213b3cb63afb1d215c29838a645826]
89I0919 07:48:24.322254   20402 pod.go:475] Loading container e129c9b952aaaf137ad1dffe0094f7749c213b3cb63afb1d215c29838a645826 of pod pod-nLJWtxCRoh
90I0919 07:48:24.322297   20402 pod.go:487] Found exist container fedora-9735126198 (e129c9b952aaaf137ad1dffe0094f7749c213b3cb63afb1d215c29838a645826), pod: pod-nLJWtxCRoh
91I0919 07:48:24.322312   20402 pod.go:520] do not need to create container fedora-9735126198 of pod pod-nLJWtxCRoh[0]
92I0919 07:48:24.322327   20402 pod.go:597] container name fedora-9735126198, image fedora
93I0919 07:48:24.322383   20402 pod.go:624] container info config &{e129c9b952aa   false false false map[]  false false false [PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin] 0xc8205f1e40 false fedora map[]  <nil> true  [] map[] }, Cmd [/bin/bash], Args []
94I0919 07:48:24.322429   20402 pod.go:648] Container Info is 
95&{containerID:"e129c9b952aaaf137ad1dffe0094f7749c213b3cb63afb1d215c29838a645826" commands:"/bin/bash" env:<env:"PATH" value:"/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin" >  1474209751 a30b73d2eda5421a430b11abb7250b749dd0133b801097899615d41e9701fec1   false}
96I0919 07:48:24.322525   20402 daemondb.go:91] try set container list for pod pod-nLJWtxCRoh: [e129c9b952aaaf137ad1dffe0094f7749c213b3cb63afb1d215c29838a645826]
97I0919 07:48:24.322642   20402 daemon.go:109] no existing VM for pod pod-nLJWtxCRoh: leveldb: not found
98I0919 07:48:24.322659   20402 daemon.go:119] 2 pod have been loaded
99I0919 07:48:24.322674   20402 daemon.go:121] container in pod pod-feMwpKISGX status: [0xc8201a5200]
100I0919 07:48:24.322690   20402 daemon.go:122] container in pod pod-feMwpKISGX spec: [{fedora-6178177928 fedora {  []} [] / [] true map[] map[] [] [] [{/etc/hosts etchosts-volume false}] [{/etc/resolv.conf pod-feMwpKISGX-resolvconf 0644  }] never}]
101I0919 07:48:24.322745   20402 daemon.go:121] container in pod pod-nLJWtxCRoh status: [0xc8201a53b0]
102I0919 07:48:24.322759   20402 daemon.go:122] container in pod pod-nLJWtxCRoh spec: [{fedora-9735126198 fedora {  []} [] / [] true map[] map[] [] [] [{/etc/hosts etchosts-volume false}] [{/etc/resolv.conf pod-nLJWtxCRoh-resolvconf 0644  }] never}]
103I0919 07:48:24.322967   20402 hyperd.go:245] Hyper daemon: 0.6.2 0
104I0919 07:48:24.323538   20402 server.go:199] Registering routers
105I0919 07:48:24.323560   20402 server.go:204] Registering GET, /container/info
106I0919 07:48:24.323724   20402 server.go:204] Registering GET, /container/logs
107I0919 07:48:24.323900   20402 server.go:204] Registering GET, /exitcode
108I0919 07:48:24.324036   20402 server.go:204] Registering POST, /container/create
109I0919 07:48:24.324187   20402 server.go:204] Registering POST, /container/rename
110I0919 07:48:24.324339   20402 server.go:204] Registering POST, /container/commit
111I0919 07:48:24.324486   20402 server.go:204] Registering POST, /container/stop
112I0919 07:48:24.324618   20402 server.go:204] Registering POST, /container/kill
113I0919 07:48:24.324743   20402 server.go:204] Registering POST, /exec/create
114I0919 07:48:24.324894   20402 server.go:204] Registering POST, /exec/start
115I0919 07:48:24.325029   20402 server.go:204] Registering POST, /attach
116I0919 07:48:24.325148   20402 server.go:204] Registering POST, /tty/resize
117I0919 07:48:24.325273   20402 server.go:204] Registering GET, /pod/info
118I0919 07:48:24.325404   20402 server.go:204] Registering GET, /pod/stats
119I0919 07:48:24.325528   20402 server.go:204] Registering GET, /list
120I0919 07:48:24.325641   20402 server.go:204] Registering POST, /pod/create
121I0919 07:48:24.325767   20402 server.go:204] Registering POST, /pod/labels
122I0919 07:48:24.325916   20402 server.go:204] Registering POST, /pod/start
123I0919 07:48:24.326047   20402 server.go:204] Registering POST, /pod/stop
124I0919 07:48:24.326228   20402 server.go:204] Registering POST, /pod/kill
125I0919 07:48:24.326441   20402 server.go:204] Registering POST, /pod/pause
126I0919 07:48:24.326676   20402 server.go:204] Registering POST, /pod/unpause
127I0919 07:48:24.326913   20402 server.go:204] Registering POST, /vm/create
128I0919 07:48:24.327143   20402 server.go:204] Registering DELETE, /pod
129I0919 07:48:24.327320   20402 server.go:204] Registering DELETE, /vm
130I0919 07:48:24.327436   20402 server.go:204] Registering GET, /service/list
131I0919 07:48:24.327610   20402 server.go:204] Registering POST, /service/add
132I0919 07:48:24.327837   20402 server.go:204] Registering POST, /service/update
133I0919 07:48:24.327972   20402 server.go:204] Registering DELETE, /service
134I0919 07:48:24.328128   20402 server.go:204] Registering GET, /images/get
135I0919 07:48:24.328277   20402 server.go:204] Registering POST, /image/create
136I0919 07:48:24.328427   20402 server.go:204] Registering POST, /image/load
137I0919 07:48:24.328567   20402 server.go:204] Registering POST, /image/push
138I0919 07:48:24.328714   20402 server.go:204] Registering DELETE, /image
139I0919 07:48:24.328860   20402 server.go:204] Registering GET, /_ping
140I0919 07:48:24.328972   20402 server.go:204] Registering GET, /info
141I0919 07:48:24.329080   20402 server.go:204] Registering GET, /version
142I0919 07:48:24.329196   20402 server.go:204] Registering POST, /auth
143I0919 07:48:24.329302   20402 server.go:204] Registering POST, /image/build
144I0919 07:48:24.329466   20402 server.go:95] API listen on /var/run/hyper.sock
145I0919 07:48:34.959601   20402 server.go:152] Calling POST /v0.6.2/vm/create
146I0919 07:48:34.959683   20402 vm.go:192] The config: kernel=/var/lib/hyper/kernel, initrd=/var/lib/hyper/hyper-initrd.img
147I0919 07:48:34.960802   20402 qemu_process.go:130] cmdline arguments: -machine pc-i440fx-2.0,accel=kvm,usb=off -global kvm-pit.lost_tick_policy=discard -cpu host -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-TrYQBzUgOJ/qmp.sock,server,nowait -serial unix:/var/run/hyper/vm-TrYQBzUgOJ/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-TrYQBzUgOJ/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-TrYQBzUgOJ/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-TrYQBzUgOJ/share_dir,security_model=none -device virtio-9p-pci,fsdev=virtio9p,mount_tag=share_dir
148I0919 07:48:34.960830   20402 server.go:152] Calling POST /v0.6.2/pod/create
149I0919 07:48:34.962251   20402 pod_routes.go:76] Args string is {"id":"fedora-0672306655","hostname":"","containers":[{"name":"fedora-0672306655","image":"fedora","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
150I0919 07:48:34.962713   20402 run.go:40] podArgs: id:"fedora-0672306655" tty:true resource:<vcpu:1 memory:128 > log:<> containers:<name:"fedora-0672306655" image:"fedora" workdir:"/" restartPolicy:"never" command:"/bin/bash" user:<> > 
151I0919 07:48:34.963476   20402 daemondb.go:82] try get container list for pod pod-vSsESEduXU
152I0919 07:48:34.963634   20402 pod.go:467] loaded containers for pod pod-vSsESEduXU: []
153DEBU[0011] devmapper: AddDevice(hash=69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920-init basehash=e57535c83466fa3d485307db5c098d1f1d9a7419caaf8bfd80f9827979a70625) 
154I0919 07:48:35.083258   20402 init_comm.go:53] connected to /var/run/hyper/vm-TrYQBzUgOJ/console.sock
155I0919 07:48:35.083299   20402 init_comm.go:60] connected /var/run/hyper/vm-TrYQBzUgOJ/console.sock as telnet mode.
156I0919 07:48:35.083308   20402 init_comm.go:142] Wating for init messages...
157I0919 07:48:35.083456   20402 init_comm.go:96] trying to read 8 bytes
158I0919 07:48:35.083272   20402 tty.go:146] tty socket connected
159I0919 07:48:35.083493   20402 tty.go:89] tty: trying to read 12 bytes
160I0919 07:48:35.083392   20402 qmp_handler.go:167] connected to /var/run/hyper/vm-TrYQBzUgOJ/qmp.sock
161I0919 07:48:35.083528   20402 qmp_handler.go:177] begin qmp init...
162DEBU[0011] devmapper: registerDevice(5, 69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920-init) 
163I0919 07:48:35.126515   20402 qmp_handler.go:186] got qmp welcome, now sending command qmp_capabilities
164I0919 07:48:35.126618   20402 qmp_handler.go:201] waiting for response
165I0919 07:48:35.130277   20402 qemu_process.go:204] starting daemon with pid: 20451
166I0919 07:48:35.130669   20402 qmp_handler.go:103] got a message {"return": {}}
167I0919 07:48:35.130738   20402 qmp_handler.go:210] got for response
168I0919 07:48:35.130763   20402 qmp_handler.go:213] QMP connection initialized
169I0919 07:48:35.130807   20402 qmp_handler.go:346] QMP initialzed, go into main QMP loop
170I0919 07:48:35.130855   20402 qmp_handler.go:137] Begin receive QMP message
171DEBU[0011] devmapper: AddDevice(hash=69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920-init basehash=e57535c83466fa3d485307db5c098d1f1d9a7419caaf8bfd80f9827979a70625) END 
172DEBU[0011] devmapper: activateDeviceIfNeeded(69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920-init) 
173DEBU[0011] devmapper: UnmountDevice(hash=69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920-init) 
174DEBU[0011] devmapper: Unmount(/var/lib/hyper/devicemapper/mnt/69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920-init) 
175DEBU[0012] devmapper: Unmount done                      
176DEBU[0012] devmapper: deactivateDevice(69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920-init) 
177DEBU[0012] devmapper: removeDevice START(docker-253:0-398548-69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920-init) 
178DEBU[0012] devmapper: removeDevice END(docker-253:0-398548-69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920-init) 
179DEBU[0012] devmapper: deactivateDevice END(69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920-init) 
180DEBU[0012] devmapper: UnmountDevice(hash=69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920-init) END 
181DEBU[0012] devmapper: AddDevice(hash=69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920 basehash=69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920-init) 
182DEBU[0012] devmapper: registerDevice(6, 69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920) 
183DEBU[0012] devmapper: AddDevice(hash=69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920 basehash=69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920-init) END 
184DEBU[0012] devmapper: activateDeviceIfNeeded(69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920) 
185DEBU[0012] container mounted via layerStore: /var/lib/hyper/devicemapper/mnt/69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920/rootfs 
186DEBU[0012] devmapper: UnmountDevice(hash=69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920) 
187DEBU[0012] devmapper: Unmount(/var/lib/hyper/devicemapper/mnt/69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920) 
188DEBU[0013] devmapper: Unmount done                      
189DEBU[0013] devmapper: deactivateDevice(69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920) 
190DEBU[0013] devmapper: removeDevice START(docker-253:0-398548-69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920) 
191DEBU[0013] devmapper: removeDevice END(docker-253:0-398548-69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920) 
192DEBU[0013] devmapper: deactivateDevice END(69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920) 
193DEBU[0013] devmapper: UnmountDevice(hash=69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920) END 
194I0919 07:48:36.706657   20402 pod.go:557] create container 05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b
195I0919 07:48:36.706764   20402 pod.go:597] container name fedora-0672306655, image fedora
196I0919 07:48:36.706909   20402 pod.go:624] container info config &{05b2767fa8a9   false false false map[]  false false false [PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin] 0xc8207d13c0 false fedora map[]  <nil> true  [] map[] }, Cmd [/bin/bash], Args []
197I0919 07:48:36.707099   20402 pod.go:648] Container Info is 
198&{containerID:"05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b" commands:"/bin/bash" env:<env:"PATH" value:"/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin" >  1474242514 69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920   true}
199I0919 07:48:36.707865   20402 daemondb.go:91] try set container list for pod pod-vSsESEduXU: [05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b]
200I0919 07:48:36.708702   20402 server.go:152] Calling GET /v0.6.2/pod/info
201I0919 07:48:36.710708   20402 server.go:152] Calling POST /v1.17/pod/start
202I0919 07:48:36.710837   20402 run.go:68] Run pod with tty attached
203I0919 07:48:36.710858   20402 run.go:76] pod:pod-vSsESEduXU, vm:vm-TrYQBzUgOJ
204I0919 07:48:36.710876   20402 pod.go:320] lock pod pod-vSsESEduXU for operation start
205I0919 07:48:36.710890   20402 pod.go:323] successfully lock pod pod-vSsESEduXU for operation start
206I0919 07:48:36.710906   20402 vm.go:229] find vm:vm-TrYQBzUgOJ
207I0919 07:48:36.710953   20402 pod.go:960] container ID: 05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b, mountId 69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920
208I0919 07:48:36.743138   20402 init_comm.go:68] [console] Initializing cgroup subsys cpuset
209I0919 07:48:36.743252   20402 init_comm.go:68] [console] Initializing cgroup subsys cpu
210I0919 07:48:36.743552   20402 init_comm.go:68] [console] Initializing cgroup subsys cpuacct
211I0919 07:48:36.745586   20402 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
212I0919 07:48:36.746909   20402 init_comm.go:68] [console] Command line: console=ttyS0 panic=1 no_timer_check
213I0919 07:48:36.750771   20402 init_comm.go:68] [console] x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256
214I0919 07:48:36.750938   20402 init_comm.go:68] [console] x86/fpu: Supporting XSAVE feature 0x01: 'x87 floating point registers'
215I0919 07:48:36.751330   20402 init_comm.go:68] [console] x86/fpu: Supporting XSAVE feature 0x02: 'SSE registers'
216I0919 07:48:36.753456   20402 init_comm.go:68] [console] x86/fpu: Supporting XSAVE feature 0x04: 'AVX registers'
217I0919 07:48:36.754997   20402 init_comm.go:68] [console] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format.
218I0919 07:48:36.756396   20402 init_comm.go:68] [console] x86/fpu: Using 'eager' FPU context switches.
219I0919 07:48:36.757929   20402 init_comm.go:68] [console] e820: BIOS-provided physical RAM map:
220I0919 07:48:36.758878   20402 init_comm.go:68] [console] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
221I0919 07:48:36.760514   20402 init_comm.go:68] [console] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
222I0919 07:48:36.761505   20402 init_comm.go:68] [console] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
223I0919 07:48:36.762468   20402 init_comm.go:68] [console] BIOS-e820: [mem 0x0000000000100000-0x0000000007ffdfff] usable
224I0919 07:48:36.764040   20402 init_comm.go:68] [console] BIOS-e820: [mem 0x0000000007ffe000-0x0000000007ffffff] reserved
225I0919 07:48:36.764950   20402 init_comm.go:68] [console] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved
226I0919 07:48:36.767022   20402 init_comm.go:68] [console] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
227I0919 07:48:36.767897   20402 init_comm.go:68] [console] NX (Execute Disable) protection: active
228I0919 07:48:36.768362   20402 init_comm.go:68] [console] SMBIOS 2.4 present.
229I0919 07:48:36.768942   20402 init_comm.go:68] [console] Hypervisor detected: KVM
230I0919 07:48:36.770281   20402 init_comm.go:68] [console] e820: last_pfn = 0x7ffe max_arch_pfn = 0x400000000
231I0919 07:48:36.770632   20402 dm.go:95] The filesytem type is xfs
232I0919 07:48:36.772062   20402 init_comm.go:68] [console] x86/PAT: Configuration [0-7]: WB  WC  UC- UC  WB  WC  UC- WT  
233I0919 07:48:36.774133   20402 init_comm.go:68] [console] found SMP MP-table at [mem 0x000f6b90-0x000f6b9f] mapped at [ffff8800000f6b90]
234I0919 07:48:36.775020   20402 init_comm.go:68] [console] RAMDISK: [mem 0x07b13000-0x07feffff]
235I0919 07:48:36.776658   20402 init_comm.go:68] [console] ACPI: Early table checksum verification disabled
236I0919 07:48:36.778100   20402 init_comm.go:68] [console] ACPI: RSDP 0x00000000000F6A10 000014 (v00 BOCHS )
237I0919 07:48:36.780341   20402 init_comm.go:68] [console] ACPI: RSDT 0x0000000007FFF6D8 00002C (v01 BOCHS  BXPCRSDT 00000001 BXPC 00000001)
238I0919 07:48:36.784406   20402 init_comm.go:68] [console] ACPI: FACP 0x0000000007FFF5EC 000074 (v01 BOCHS  BXPCFACP 00000001 BXPC 00000001)
239I0919 07:48:36.784437   20402 init_comm.go:68] [console] ACPI: DSDT 0x0000000007FFE040 0015AC (v01 BOCHS  BXPCDSDT 00000001 BXPC 00000001)
240I0919 07:48:36.784844   20402 init_comm.go:68] [console] ACPI: FACS 0x0000000007FFE000 000040
241I0919 07:48:36.786806   20402 init_comm.go:68] [console] ACPI: APIC 0x0000000007FFF660 000078 (v01 BOCHS  BXPCAPIC 00000001 BXPC 00000001)
242I0919 07:48:36.787509   20402 init_comm.go:68] [console] No NUMA configuration found
243I0919 07:48:36.790045   20402 init_comm.go:68] [console] Faking a node at [mem 0x0000000000000000-0x0000000007ffdfff]
244I0919 07:48:36.790092   20402 init_comm.go:68] [console] NODE_DATA(0) allocated [mem 0x07b01000-0x07b12fff]
245I0919 07:48:36.790119   20402 init_comm.go:68] [console] kvm-clock: Using msrs 4b564d01 and 4b564d00
246I0919 07:48:36.791314   20402 init_comm.go:68] [console] kvm-clock: cpu 0, msr 0:7ffd001, primary cpu clock
247I0919 07:48:36.792557   20402 init_comm.go:68] [console] kvm-clock: using sched offset of 1598169905 cycles
248I0919 07:48:36.795414   20402 init_comm.go:68] [console] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
249I0919 07:48:36.795455   20402 init_comm.go:68] [console] Zone ranges:
250I0919 07:48:36.797710   20402 init_comm.go:68] [console]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
251I0919 07:48:36.799152   20402 init_comm.go:68] [console]   DMA32    [mem 0x0000000001000000-0x0000000007ffdfff]
252I0919 07:48:36.799644   20402 init_comm.go:68] [console]   Normal   empty
253I0919 07:48:36.800752   20402 init_comm.go:68] [console] Movable zone start for each node
254I0919 07:48:36.801565   20402 init_comm.go:68] [console] Early memory node ranges
255I0919 07:48:36.802947   20402 init_comm.go:68] [console]   node   0: [mem 0x0000000000001000-0x000000000009efff]
256I0919 07:48:36.804012   20402 init_comm.go:68] [console]   node   0: [mem 0x0000000000100000-0x0000000007ffdfff]
257I0919 07:48:36.805924   20402 init_comm.go:68] [console] Initmem setup node 0 [mem 0x0000000000001000-0x0000000007ffdfff]
258I0919 07:48:36.805947   20402 init_comm.go:68] [console] ACPI: PM-Timer IO Port: 0x608
259I0919 07:48:36.806110   20402 init_comm.go:68] [console] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
260I0919 07:48:36.807031   20402 init_comm.go:68] [console] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
261I0919 07:48:36.808391   20402 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
262I0919 07:48:36.809860   20402 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
263I0919 07:48:36.811937   20402 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
264I0919 07:48:36.812143   20402 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
265I0919 07:48:36.813710   20402 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
266I0919 07:48:36.815023   20402 init_comm.go:68] [console] Using ACPI (MADT) for SMP configuration information
267I0919 07:48:36.816064   20402 init_comm.go:68] [console] smpboot: Allowing 1 CPUs, 0 hotplug CPUs
268I0919 07:48:36.817546   20402 init_comm.go:68] [console] e820: [mem 0x08000000-0xfeffbfff] available for PCI devices
269I0919 07:48:36.818300   20402 init_comm.go:68] [console] Booting paravirtualized kernel on KVM
270I0919 07:48:36.821977   20402 init_comm.go:68] [console] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
271I0919 07:48:36.821996   20402 init_comm.go:68] [console] setup_percpu: NR_CPUS:8 nr_cpumask_bits:8 nr_cpu_ids:1 nr_node_ids:1
272I0919 07:48:36.822005   20402 init_comm.go:68] [console] PERCPU: Embedded 31 pages/cpu @ffff880007800000 s89624 r8192 d29160 u2097152
273I0919 07:48:36.822229   20402 init_comm.go:68] [console] KVM setup async PF for cpu 0
274I0919 07:48:36.822648   20402 init_comm.go:68] [console] kvm-stealtime: cpu 0, msr 780d480
275I0919 07:48:36.824504   20402 init_comm.go:68] [console] Built 1 zonelists in Node order, mobility grouping on.  Total pages: 32135
276I0919 07:48:36.825006   20402 init_comm.go:68] [console] Policy zone: DMA32
277I0919 07:48:36.825854   20402 init_comm.go:68] [console] Kernel command line: console=ttyS0 panic=1 no_timer_check
278I0919 07:48:36.827104   20402 init_comm.go:68] [console] PID hash table entries: 512 (order: 0, 4096 bytes)
279I0919 07:48:36.830386   20402 init_comm.go:68] [console] Memory: 114752K/130672K available (4658K kernel code, 576K rwdata, 1472K rodata, 876K init, 756K bss, 15920K reserved, 0K cma-reserved)
280I0919 07:48:36.831218   20402 init_comm.go:68] [console] Hierarchical RCU implementation.
281I0919 07:48:36.832330   20402 init_comm.go:68] [console] 	Build-time adjustment of leaf fanout to 64.
282I0919 07:48:36.833652   20402 init_comm.go:68] [console] 	RCU restricting CPUs from NR_CPUS=8 to nr_cpu_ids=1.
283I0919 07:48:36.835146   20402 init_comm.go:68] [console] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=1
284I0919 07:48:36.835857   20402 init_comm.go:68] [console] NR_IRQS:4352 nr_irqs:256 16
285I0919 07:48:36.836540   20402 init_comm.go:68] [console] Console: colour *CGA 80x25
286I0919 07:48:36.837175   20402 init_comm.go:68] [console] console [ttyS0] enabled
287I0919 07:48:36.837822   20402 init_comm.go:68] [console] tsc: Detected 2093.204 MHz processor
288I0919 07:48:36.839726   20402 init_comm.go:68] [console] Calibrating delay loop (skipped) preset value.. 4186.40 BogoMIPS (lpj=2093204)
289I0919 07:48:36.840307   20402 init_comm.go:68] [console] pid_max: default: 32768 minimum: 301
290I0919 07:48:36.841043   20402 init_comm.go:68] [console] ACPI: Core revision 20150930
291I0919 07:48:36.843121   20402 init_comm.go:68] [console] ACPI: 1 ACPI AML tables successfully acquired and loaded
292I0919 07:48:36.844707   20402 init_comm.go:68] [console] Dentry cache hash table entries: 16384 (order: 5, 131072 bytes)
293I0919 07:48:36.846253   20402 init_comm.go:68] [console] Inode-cache hash table entries: 8192 (order: 4, 65536 bytes)
294I0919 07:48:36.847753   20402 init_comm.go:68] [console] Mount-cache hash table entries: 512 (order: 0, 4096 bytes)
295I0919 07:48:36.849358   20402 init_comm.go:68] [console] Mountpoint-cache hash table entries: 512 (order: 0, 4096 bytes)
296I0919 07:48:36.850484   20402 init_comm.go:68] [console] Initializing cgroup subsys io
297I0919 07:48:36.851389   20402 init_comm.go:68] [console] Initializing cgroup subsys memory
298I0919 07:48:36.852328   20402 init_comm.go:68] [console] Initializing cgroup subsys devices
299I0919 07:48:36.852894   20402 init_comm.go:68] [console] Initializing cgroup subsys freezer
300I0919 07:48:36.853784   20402 init_comm.go:68] [console] Initializing cgroup subsys net_cls
301I0919 07:48:36.854727   20402 init_comm.go:68] [console] Initializing cgroup subsys perf_event
302I0919 07:48:36.855646   20402 init_comm.go:68] [console] Initializing cgroup subsys net_prio
303I0919 07:48:36.856498   20402 init_comm.go:68] [console] Initializing cgroup subsys pids
304I0919 07:48:36.857373   20402 init_comm.go:68] [console] Initializing cgroup subsys debug
305I0919 07:48:36.858217   20402 init_comm.go:68] [console] Last level iTLB entries: 4KB 512, 2MB 8, 4MB 8
306I0919 07:48:36.859580   20402 init_comm.go:68] [console] Last level dTLB entries: 4KB 512, 2MB 32, 4MB 32, 1GB 0
307I0919 07:48:36.872392   20402 init_comm.go:68] [console] Freeing SMP alternatives memory: 20K (ffffffff8176b000 - ffffffff81770000)
308I0919 07:48:36.878270   20402 init_comm.go:68] [console] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
309I0919 07:48:36.880532   20402 init_comm.go:68] [console] smpboot: CPU0: Intel(R) Core(TM) i3-2310M CPU @ 2.10GHz (family: 0x6, model: 0x2a, stepping: 0x7)
310I0919 07:48:36.882342   20402 init_comm.go:68] [console] Performance Events: 16-deep LBR, SandyBridge events, Intel PMU driver.
311I0919 07:48:36.884295   20402 init_comm.go:68] [console] perf_event_intel: PEBS disabled due to CPU errata, please upgrade microcode
312I0919 07:48:36.885132   20402 init_comm.go:68] [console] ... version:                2
313I0919 07:48:36.885927   20402 init_comm.go:68] [console] ... bit width:              48
314I0919 07:48:36.886715   20402 init_comm.go:68] [console] ... generic registers:      4
315I0919 07:48:36.887872   20402 init_comm.go:68] [console] ... value mask:             0000ffffffffffff
316I0919 07:48:36.888556   20402 init_comm.go:68] [console] ... max period:             000000007fffffff
317I0919 07:48:36.889285   20402 init_comm.go:68] [console] ... fixed-purpose events:   3
318I0919 07:48:36.890509   20402 init_comm.go:68] [console] ... event mask:             000000070000000f
319I0919 07:48:36.891232   20402 init_comm.go:68] [console] x86: Booted up 1 node, 1 CPUs
320I0919 07:48:36.892699   20402 init_comm.go:68] [console] smpboot: Total of 1 processors activated (4186.40 BogoMIPS)
321I0919 07:48:36.893396   20402 init_comm.go:68] [console] devtmpfs: initialized
322I0919 07:48:36.898645   20402 init_comm.go:68] [console] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
323I0919 07:48:36.899372   20402 init_comm.go:68] [console] NET: Registered protocol family 16
324I0919 07:48:36.900251   20402 init_comm.go:68] [console] cpuidle: using governor ladder
325I0919 07:48:36.900776   20402 init_comm.go:68] [console] cpuidle: using governor menu
326I0919 07:48:36.901270   20402 init_comm.go:68] [console] ACPI: bus type PCI registered
327I0919 07:48:36.902714   20402 init_comm.go:68] [console] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
328I0919 07:48:36.903442   20402 init_comm.go:68] [console] PCI: Using configuration type 1 for base access
329I0919 07:48:36.905433   20402 init_comm.go:68] [console] perf_event_intel: PMU erratum BJ122, BV98, HSD29 workaround disabled, HT off
330I0919 07:48:36.906743   20402 init_comm.go:68] [console] ACPI: Added _OSI(Module Device)
331I0919 07:48:36.907637   20402 init_comm.go:68] [console] ACPI: Added _OSI(Processor Device)
332I0919 07:48:36.908589   20402 init_comm.go:68] [console] ACPI: Added _OSI(3.0 _SCP Extensions)
333I0919 07:48:36.909742   20402 init_comm.go:68] [console] ACPI: Added _OSI(Processor Aggregator Device)
334I0919 07:48:36.911626   20402 init_comm.go:68] [console] ACPI: Interpreter enabled
335I0919 07:48:36.912240   20402 init_comm.go:68] [console] ACPI: (supports S0 S5)
336I0919 07:48:36.913278   20402 init_comm.go:68] [console] ACPI: Using IOAPIC for interrupt routing
337I0919 07:48:36.915490   20402 init_comm.go:68] [console] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
338I0919 07:48:36.919952   20402 init_comm.go:68] [console] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
339I0919 07:48:36.921551   20402 init_comm.go:68] [console] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI]
340I0919 07:48:36.923118   20402 init_comm.go:68] [console] acpi PNP0A03:00: _OSC failed (AE_NOT_FOUND); disabling ASPM
341I0919 07:48:36.924172   20402 init_comm.go:68] [console] acpiphp: Slot [2] registered
342I0919 07:48:36.924689   20402 init_comm.go:68] [console] acpiphp: Slot [3] registered
343I0919 07:48:36.925455   20402 init_comm.go:68] [console] acpiphp: Slot [4] registered
344I0919 07:48:36.925948   20402 init_comm.go:68] [console] acpiphp: Slot [5] registered
345I0919 07:48:36.926716   20402 init_comm.go:68] [console] acpiphp: Slot [6] registered
346I0919 07:48:36.927202   20402 init_comm.go:68] [console] acpiphp: Slot [7] registered
347I0919 07:48:36.927658   20402 init_comm.go:68] [console] acpiphp: Slot [8] registered
348I0919 07:48:36.928430   20402 init_comm.go:68] [console] acpiphp: Slot [9] registered
349I0919 07:48:36.928944   20402 init_comm.go:68] [console] acpiphp: Slot [10] registered
350I0919 07:48:36.929737   20402 init_comm.go:68] [console] acpiphp: Slot [11] registered
351I0919 07:48:36.930222   20402 init_comm.go:68] [console] acpiphp: Slot [12] registered
352I0919 07:48:36.931023   20402 init_comm.go:68] [console] acpiphp: Slot [13] registered
353I0919 07:48:36.931501   20402 init_comm.go:68] [console] acpiphp: Slot [14] registered
354I0919 07:48:36.932292   20402 init_comm.go:68] [console] acpiphp: Slot [15] registered
355I0919 07:48:36.932780   20402 init_comm.go:68] [console] acpiphp: Slot [16] registered
356I0919 07:48:36.933296   20402 init_comm.go:68] [console] acpiphp: Slot [17] registered
357I0919 07:48:36.933795   20402 init_comm.go:68] [console] acpiphp: Slot [18] registered
358I0919 07:48:36.934591   20402 init_comm.go:68] [console] acpiphp: Slot [19] registered
359I0919 07:48:36.935078   20402 init_comm.go:68] [console] acpiphp: Slot [20] registered
360I0919 07:48:36.935553   20402 init_comm.go:68] [console] acpiphp: Slot [21] registered
361I0919 07:48:36.936347   20402 init_comm.go:68] [console] acpiphp: Slot [22] registered
362I0919 07:48:36.937133   20402 init_comm.go:68] [console] acpiphp: Slot [23] registered
363I0919 07:48:36.937947   20402 init_comm.go:68] [console] acpiphp: Slot [24] registered
364I0919 07:48:36.938439   20402 init_comm.go:68] [console] acpiphp: Slot [25] registered
365I0919 07:48:36.938919   20402 init_comm.go:68] [console] acpiphp: Slot [26] registered
366I0919 07:48:36.939412   20402 init_comm.go:68] [console] acpiphp: Slot [27] registered
367I0919 07:48:36.940194   20402 init_comm.go:68] [console] acpiphp: Slot [28] registered
368I0919 07:48:36.941000   20402 init_comm.go:68] [console] acpiphp: Slot [29] registered
369I0919 07:48:36.941801   20402 init_comm.go:68] [console] acpiphp: Slot [30] registered
370I0919 07:48:36.942600   20402 init_comm.go:68] [console] acpiphp: Slot [31] registered
371I0919 07:48:36.943099   20402 init_comm.go:68] [console] PCI host bridge to bus 0000:00
372I0919 07:48:36.944602   20402 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7 window]
373I0919 07:48:36.945478   20402 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [io  0x0d00-0xffff window]
374I0919 07:48:36.947168   20402 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
375I0919 07:48:36.948311   20402 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [mem 0x08000000-0xfebfffff window]
376I0919 07:48:36.949338   20402 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [bus 00-ff]
377I0919 07:48:36.960935   20402 init_comm.go:68] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io  0x01f0-0x01f7]
378I0919 07:48:36.963121   20402 init_comm.go:68] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io  0x03f6]
379I0919 07:48:36.965984   20402 init_comm.go:68] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io  0x0170-0x0177]
380I0919 07:48:36.966012   20402 init_comm.go:68] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io  0x0376]
381I0919 07:48:36.966927   20402 init_comm.go:68] [console] pci 0000:00:01.3: quirk: [io  0x0600-0x063f] claimed by PIIX4 ACPI
382I0919 07:48:36.967890   20402 init_comm.go:68] [console] pci 0000:00:01.3: quirk: [io  0x0700-0x070f] claimed by PIIX4 SMB
383I0919 07:48:37.016314   20402 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11)
384I0919 07:48:37.017703   20402 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 *10 11)
385I0919 07:48:37.019148   20402 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 10 *11)
386I0919 07:48:37.021068   20402 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 10 *11)
387I0919 07:48:37.021156   20402 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKS] (IRQs *9)
388I0919 07:48:37.023336   20402 init_comm.go:68] [console] ACPI: Enabled 16 GPEs in block 00 to 0F
389I0919 07:48:37.023567   20402 init_comm.go:68] [console] vgaarb: loaded
390I0919 07:48:37.023725   20402 init_comm.go:68] [console] SCSI subsystem initialized
391I0919 07:48:37.024691   20402 init_comm.go:68] [console] PCI: Using ACPI for IRQ routing
392I0919 07:48:37.026459   20402 init_comm.go:68] [console] clocksource: Switched to clocksource kvm-clock
393I0919 07:48:37.027983   20402 init_comm.go:68] [console] pnp: PnP ACPI init
394I0919 07:48:37.028268   20402 init_comm.go:68] [console] pnp: PnP ACPI: found 5 devices
395I0919 07:48:37.035603   20402 init_comm.go:68] [console] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
396I0919 07:48:37.036512   20402 init_comm.go:68] [console] NET: Registered protocol family 2
397I0919 07:48:37.038204   20402 init_comm.go:68] [console] TCP established hash table entries: 1024 (order: 1, 8192 bytes)
398I0919 07:48:37.039637   20402 init_comm.go:68] [console] TCP bind hash table entries: 1024 (order: 2, 16384 bytes)
399I0919 07:48:37.040453   20402 init_comm.go:68] [console] TCP: Hash tables configured (established 1024 bind 1024)
400I0919 07:48:37.041729   20402 init_comm.go:68] [console] UDP hash table entries: 256 (order: 1, 8192 bytes)
401I0919 07:48:37.043110   20402 init_comm.go:68] [console] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes)
402I0919 07:48:37.043674   20402 init_comm.go:68] [console] NET: Registered protocol family 1
403I0919 07:48:37.044452   20402 init_comm.go:68] [console] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
404I0919 07:48:37.045673   20402 init_comm.go:68] [console] pci 0000:00:01.0: PIIX3: Enabling Passive Release
405I0919 07:48:37.047022   20402 init_comm.go:68] [console] pci 0000:00:01.0: Activating ISA DMA hang workarounds
406I0919 07:48:37.048287   20402 init_comm.go:68] [console] Trying to unpack rootfs image as initramfs...
407I0919 07:48:37.149953   20402 init_comm.go:68] [console] Freeing initrd memory: 4980K (ffff880007b13000 - ffff880007ff0000)
408I0919 07:48:37.151592   20402 init_comm.go:68] [console] futex hash table entries: 256 (order: 2, 16384 bytes)
409I0919 07:48:37.153071   20402 init_comm.go:68] [console] SGI XFS with ACLs, security attributes, no debug enabled
410I0919 07:48:37.153851   20402 init_comm.go:68] [console] 9p: Installing v9fs 9p2000 file system support
411I0919 07:48:37.157332   20402 init_comm.go:68] [console] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 253)
412I0919 07:48:37.157786   20402 init_comm.go:68] [console] io scheduler noop registered
413I0919 07:48:37.158736   20402 init_comm.go:68] [console] io scheduler cfq registered (default)
414I0919 07:48:37.159494   20402 init_comm.go:68] [console] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
415I0919 07:48:37.160982   20402 init_comm.go:68] [console] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
416I0919 07:48:37.162669   20402 init_comm.go:68] [console] Warning: Processor Platform Limit event detected, but not handled.
417I0919 07:48:37.163972   20402 init_comm.go:68] [console] Consider compiling CPUfreq support into your kernel.
418I0919 07:48:37.195496   20402 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKB] enabled at IRQ 10
419I0919 07:48:37.196473   20402 init_comm.go:68] [console] virtio-pci 0000:00:02.0: virtio_pci: leaving for legacy driver
420I0919 07:48:37.228029   20402 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 11
421I0919 07:48:37.228984   20402 init_comm.go:68] [console] virtio-pci 0000:00:03.0: virtio_pci: leaving for legacy driver
422I0919 07:48:37.261655   20402 volumes.go:29] trying to bind dir /var/lib/hyper/hosts/pod-vSsESEduXU/hosts to /var/run/hyper/vm-TrYQBzUgOJ/share_dir/yoqTlWUUSb
423I0919 07:48:37.264943   20402 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 11
424I0919 07:48:37.266840   20402 storage.go:79] dir /var/lib/hyper/hosts/pod-vSsESEduXU/hosts is bound to yoqTlWUUSb
425I0919 07:48:37.266900   20402 pod.go:1119] configuring log driver [json-file] for pod-vSsESEduXU
426I0919 07:48:37.266989   20402 pod.go:1147] configure container log to /var/run/hyper/Pods/pod-vSsESEduXU/05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b-json.log
427I0919 07:48:37.267065   20402 pod.go:1153] configured logger for pod-vSsESEduXU/05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b (/fedora-0672306655)
428I0919 07:48:37.267120   20402 hypervisor.go:29] vm vm-TrYQBzUgOJ: main event loop got message 34(GENERIC_OPERATION)
429I0919 07:48:37.267139   20402 vm_states.go:296] handle GenericOperation(Attach) on state(INIT)
430I0919 07:48:37.267193   20402 vm_states.go:229] attachment 05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b is pending
431I0919 07:48:37.267252   20402 hypervisor.go:29] vm vm-TrYQBzUgOJ: main event loop got message 34(GENERIC_OPERATION)
432I0919 07:48:37.267267   20402 vm_states.go:296] handle GenericOperation(Attach) on state(INIT)
433I0919 07:48:37.267279   20402 vm_states.go:229] attachment 05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b is pending
434I0919 07:48:37.267295   20402 pod.go:1205] Attach to container 05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b before start pod
435I0919 07:48:37.267336   20402 hypervisor.go:29] vm vm-TrYQBzUgOJ: main event loop got message 21(COMMAND_RUN_POD)
436I0919 07:48:37.267353   20402 vm_states.go:443] got spec, prepare devices
437I0919 07:48:37.267378   20402 context.go:292] #0 Container Info:
438I0919 07:48:37.267567   20402 context.go:295] 
439{
440...|    "Id": "05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b",
441...|    "User": "",
442...|    "MountId": "69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920",
443...|    "Rootfs": "/rootfs",
444...|    "Image": {
445...|        "name": "",
446...|        "source": "/dev/mapper/docker-253:0-398548-69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920",
447...|        "driver": "",
448...|        "option": {
449...|            "monitors": null,
450...|            "user": "",
451...|            "keyring": "",
452...|            "bytespersec": 0,
453...|            "iops": 0
454...|        }
455...|    },
456...|    "Fstype": "xfs",
457...|    "Workdir": "",
458...|    "Entrypoint": null,
459...|    "Cmd": [
460...|        "/bin/bash"
461...|    ],
462...|    "Envs": {
463...|        "PATH": "/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"
464...|    },
465...|    "Initialize": true
466...|}
467I0919 07:48:37.267620   20402 devicemap.go:196] insert volume /dev/mapper/docker-253:0-398548-69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920 source /dev/mapper/docker-253:0-398548-69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920 fstype xfs
468I0919 07:48:37.267644   20402 devicemap.go:280] insert volume etchosts-volume to /etc/hosts on 0
469I0919 07:48:37.268090   20402 vm_states.go:67] initial vm spec: {
470        "hostname": "fedora-0672306655",
471        "containers": [
472            {
473                "id": "05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b",
474                "rootfs": "/rootfs",
475                "fstype": "xfs",
476                "image": "",
477                "fsmap": [
478                    {
479                        "source": "yoqTlWUUSb",
480                        "path": "/etc/hosts",
481                        "readOnly": false,
482                        "dockerVolume": false
483                    }
484                ],
485                "process": {
486                    "terminal": true,
487                    "stdio": 1,
488                    "args": [
489                        "/bin/bash"
490                    ],
491                    "envs": [
492                        {
493                            "env": "PATH",
494                            "value": "/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"
495                        }
496                    ],
497                    "workdir": "/"
498                },
499                "restartPolicy": "never",
500                "initialize": true
501            }
502        ],
503        "shareDir": "share_dir"
504    }
505I0919 07:48:37.268133   20402 context.go:224] found container 05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b at 0
506I0919 07:48:37.268156   20402 vm_states.go:75] attach pending client for 05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b
507I0919 07:48:37.268170   20402 vm_states.go:247] Connecting tty for 05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b on session 1
508I0919 07:48:37.268183   20402 context.go:224] found container 05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b at 0
509I0919 07:48:37.268194   20402 vm_states.go:75] attach pending client for 05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b
510I0919 07:48:37.268205   20402 vm_states.go:247] Connecting tty for 05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b on session 1
511I0919 07:48:37.268247   20402 context.go:260] VM vm-TrYQBzUgOJ: state change from INIT to 'STARTING'
512I0919 07:48:37.268266   20402 qmp_handler.go:296] got new session
513I0919 07:48:37.268285   20402 init_comm.go:68] [console] virtio-pci 0000:00:04.0: virtio_pci: leaving for legacy driver
514I0919 07:48:37.268298   20402 qmp_handler.go:225] Begin process command session
515I0919 07:48:37.268305   20402 init_comm.go:68] [console] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
516I0919 07:48:37.268340   20402 qmp_handler.go:243] sending command (1) {"execute":"human-monitor-command","arguments":{"command-line":"drive_add dummy file=/dev/mapper/docker-253:0-398548-69505ec732ab45a0f3a802ccc72e02ab395385c30cb2f8dd0daf73865253d920,if=none,id=drive0,format=raw,cache=writeback"}}
517I0919 07:48:37.268385   20402 vm.go:162] hyperHandlePodEvent pod pod-vSsESEduXU, vm vm-TrYQBzUgOJ
518I0919 07:48:37.271795   20402 hypervisor.go:29] vm vm-TrYQBzUgOJ: main event loop got message 12(EVENT_INTERFACE_ADD)
519I0919 07:48:37.272002   20402 qmp_wrapper_amd64.go:17] send net to qemu at 28
520I0919 07:48:37.272056   20402 qmp_handler.go:296] got new session
521I0919 07:48:37.272212   20402 qmp_handler.go:103] got a message {"return": "OK\r\n"}
522I0919 07:48:37.272305   20402 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"}}
523I0919 07:48:37.275045   20402 qmp_handler.go:103] got a message {"return": {}}
524I0919 07:48:37.275130   20402 qmp_handler.go:302] session finished, buffer size 2
525I0919 07:48:37.275159   20402 qmp_handler.go:305] success 
526I0919 07:48:37.275398   20402 qmp_handler.go:225] Begin process command session
527I0919 07:48:37.275453   20402 qmp_handler.go:238] send cmd with scm (24 bytes) (1) {"execute":"getfd","arguments":{"fdname":"fdeth0"}}
528I0919 07:48:37.275526   20402 hypervisor.go:29] vm vm-TrYQBzUgOJ: main event loop got message 9(EVENT_BLOCK_INSERTED)
529I0919 07:48:37.276312   20402 qmp_handler.go:103] got a message {"return": {}}
530I0919 07:48:37.276693   20402 qmp_handler.go:243] sending command (1) {"execute":"netdev_add","arguments":{"fd":"fdeth0","id":"eth0","type":"tap"}}
531I0919 07:48:37.283768   20402 qmp_handler.go:103] got a message {"return": {}}
532I0919 07:48:37.284099   20402 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:74:cd:45:47","netdev":"eth0"}}
533I0919 07:48:37.293186   20402 qmp_handler.go:103] got a message {"return": {}}
534I0919 07:48:37.293748   20402 qmp_handler.go:302] session finished, buffer size 1
535I0919 07:48:37.293783   20402 qmp_handler.go:305] success 
536I0919 07:48:37.293805   20402 hypervisor.go:29] vm vm-TrYQBzUgOJ: main event loop got message 14(EVENT_INTERFACE_INSERTED)
537I0919 07:48:37.293864   20402 vm_states.go:470] device ready, could run pod.
538I0919 07:48:37.318993   20402 init_comm.go:68] [console] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
539I0919 07:48:37.322907   20402 init_comm.go:68] [console] pci 0000:00:05.0: BAR 6: assigned [mem 0x08000000-0x0803ffff pref]
540I0919 07:48:37.324509   20402 init_comm.go:68] [console] pci 0000:00:05.0: BAR 1: assigned [mem 0x08040000-0x08040fff]
541I0919 07:48:37.325864   20402 init_comm.go:68] [console] pci 0000:00:05.0: BAR 0: assigned [io  0x1000-0x101f]
542I0919 07:48:37.326729   20402 init_comm.go:68] [console] virtio-pci 0000:00:05.0: enabling device (0000 -> 0003)
543I0919 07:48:37.366954   20402 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 10
544I0919 07:48:37.367881   20402 init_comm.go:68] [console] virtio-pci 0000:00:05.0: virtio_pci: leaving for legacy driver
545I0919 07:48:37.392587   20402 init_comm.go:68] [console] brd: module loaded
546I0919 07:48:37.393525   20402 init_comm.go:68] [console] loop: module loaded
547I0919 07:48:37.395900   20402 init_comm.go:68] [console] scsi host0: Virtio SCSI HBA
548I0919 07:48:37.397794   20402 init_comm.go:68] [console] scsi 0:0:0:0: Direct-Access     QEMU     QEMU HARDDISK    2.0. PQ: 0 ANSI: 5
549I0919 07:48:37.431359   20402 init_comm.go:68] [console] sd 0:0:0:0: Attached scsi generic sg0 type 0
550I0919 07:48:37.433118   20402 init_comm.go:68] [console] rtc_cmos 00:00: RTC can wake from S4
551I0919 07:48:37.434444   20402 init_comm.go:68] [console] rtc_cmos 00:00: rtc core: registered rtc_cmos as rtc0
552I0919 07:48:37.435541   20402 init_comm.go:68] [console] rtc_cmos 00:00: alarms up to one day, y3k, 114 bytes nvram
553I0919 07:48:37.436242   20402 init_comm.go:68] [console] Initializing XFRM netlink socket
554I0919 07:48:37.436883   20402 init_comm.go:68] [console] NET: Registered protocol family 10
555I0919 07:48:37.437715   20402 init_comm.go:68] [console] NET: Registered protocol family 17
556I0919 07:48:37.440386   20402 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.
557I0919 07:48:37.440863   20402 init_comm.go:68] [console] Bridge firewalling registered
558I0919 07:48:37.441361   20402 init_comm.go:68] [console] 9pnet: Installing 9P2000 support
559I0919 07:48:37.443663   20402 init_comm.go:68] [console] sd 0:0:0:0: [sda] 20971520 512-byte logical blocks: (10.7 GB/10.0 GiB)
560I0919 07:48:37.444325   20402 init_comm.go:68] [console] registered taskstats version 1
561I0919 07:48:37.446612   20402 init_comm.go:68] [console] rtc_cmos 00:00: setting system clock to 2016-09-18 23:48:37 UTC (1474242517)
562I0919 07:48:37.447661   20402 init_comm.go:68] [console] sd 0:0:0:0: [sda] Write Protect is off
563I0919 07:48:37.449015   20402 init_comm.go:68] [console] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
564I0919 07:48:37.450539   20402 init_comm.go:68] [console] sd 0:0:0:0: [sda] Attached SCSI disk
565I0919 07:48:37.455445   20402 init_comm.go:68] [console] Freeing unused kernel memory: 876K (ffffffff81690000 - ffffffff8176b000)
566I0919 07:48:37.455482   20402 init_comm.go:68] [console] create directory /sys
567I0919 07:48:37.455499   20402 init_comm.go:68] [console] create directory /sbin
568I0919 07:48:37.455514   20402 init_comm.go:68] [console] create directory /proc
569I0919 07:48:37.455530   20402 init_comm.go:68] [console] uptime 0.56 0.03
570I0919 07:48:37.455545   20402 init_comm.go:68] [console] 
571I0919 07:48:37.458986   20402 qmp_handler.go:103] got a message {"timestamp": {"seconds": 1474242517, "microseconds": 457236}, "event": "VSERPORT_CHANGE", "data": {"open": true, "id": "channel0"}}
572I0919 07:48:37.459114   20402 qmp_handler.go:107] got event: VSERPORT_CHANGE
573I0919 07:48:37.459293   20402 init_comm.go:68] [console] create directory /dev/pts
574I0919 07:48:37.459321   20402 init_comm.go:68] [console] open hyper channel /dev/vport0p1
575I0919 07:48:37.459338   20402 init_comm.go:68] [console] send ready message
576I0919 07:48:37.459351   20402 init_comm.go:68] [console] hyper send type 8, len 0
577I0919 07:48:37.459300   20402 qmp_handler.go:323] got QMP event VSERPORT_CHANGE
578I0919 07:48:37.459750   20402 init_comm.go:68] [console] channel sh.hyper.channel.1, directory sh.hyper.channel.0
579I0919 07:48:37.460101   20402 init_comm.go:106] read 8/8 [length = 0]
580I0919 07:48:37.460130   20402 init_comm.go:110] data length is 8
581I0919 07:48:37.460148   20402 init_comm.go:152] Get init ready message
582I0919 07:48:37.460238   20402 init_comm.go:225] got cmd:1
583I0919 07:48:37.459947   20402 init_comm.go:68] [console] 
584I0919 07:48:37.460390   20402 hypervisor.go:29] vm vm-TrYQBzUgOJ: main event loop got message 5(EVENT_INIT_CONNECTED)
585I0919 07:48:37.460417   20402 vm_states.go:484] begin to wait vm commands
586I0919 07:48:37.460387   20402 init_comm.go:316] send command 1 to init, payload: '{"hostname":"fedora-0672306655","containers":[{"id":"05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b","rootfs":"/rootfs","fstype":"xfs","image":"sda","fsmap":[{"source":"yoqTlWUUSb","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"}'.
587I0919 07:48:37.460418   20402 init_comm.go:96] trying to read 8 bytes
588I0919 07:48:37.460487   20402 init_comm.go:329] write 512 to init, payload: '
�{"hostname":"fedora-0672306655","containers":[{"id":"05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b","rootfs":"/rootfs","fstype":"xfs","image":"sda","fsmap":[{"source":"yoqTlWUUSb","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'.
589I0919 07:48:37.460505   20402 vm.go:275] Get the response from VM, VM id is vm-TrYQBzUgOJ!
590I0919 07:48:37.460517   20402 init_comm.go:334] message sent, set pong timer
591I0919 07:48:37.460561   20402 init_comm.go:225] got cmd:0
592I0919 07:48:37.460597   20402 init_comm.go:316] send command 0 to init, payload: 'null'.
593I0919 07:48:37.460791   20402 init_comm.go:68] [console] open hyper channel /dev/vport0p2
594I0919 07:48:37.461100   20402 qmp_handler.go:103] got a message {"timestamp": {"seconds": 1474242517, "microseconds": 460947}, "event": "VSERPORT_CHANGE", "data": {"open": true, "id": "channel1"}}
595I0919 07:48:37.461177   20402 qmp_handler.go:107] got event: VSERPORT_CHANGE
596I0919 07:48:37.461346   20402 qmp_handler.go:323] got QMP event VSERPORT_CHANGE
597I0919 07:48:37.462290   20402 init_comm.go:68] [console] hyper_init_event hyper channel event 0x61c600, ops 0x61c3e0, fd 3
598I0919 07:48:37.463190   20402 init_comm.go:68] [console] hyper_add_event add event fd 3, 0x61c3e0
599I0919 07:48:37.464468   20402 init_comm.go:68] [console] hyper_init_event hyper ttyfd event 0x61c5c8, ops 0x61c3a0, fd 4
600I0919 07:48:37.465008   20402 init_comm.go:68] [console] hyper_add_event add event fd 4, 0x61c3a0
601I0919 07:48:37.465558   20402 init_comm.go:68] [console] hyper_loop epoll_wait 1
602I0919 07:48:37.466772   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x61c600, fd 3. ops 0x61c3e0
603I0919 07:48:37.467522   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x61c600, fd 3, 0x61c3e0
604I0919 07:48:37.467934   20402 init_comm.go:68] [console] hyper_event_read
605I0919 07:48:37.468315   20402 init_comm.go:68] [console] already read 8 bytes data
606I0919 07:48:37.468884   20402 init_comm.go:68] [console] hyper send type 14, len 4
607I0919 07:48:37.468999   20402 init_comm.go:106] read 8/8 [length = 0]
608I0919 07:48:37.469020   20402 init_comm.go:110] data length is 12
609I0919 07:48:37.469036   20402 init_comm.go:96] trying to read 4 bytes
610I0919 07:48:37.469056   20402 init_comm.go:106] read 12/12 [length = 12]
611I0919 07:48:37.469079   20402 init_comm.go:96] trying to read 8 bytes
612I0919 07:48:37.469106   20402 init_comm.go:225] got cmd:14
613I0919 07:48:37.469123   20402 init_comm.go:288] get command NEXT
614I0919 07:48:37.469139   20402 init_comm.go:291] send 512, receive 8
615I0919 07:48:37.469902   20402 init_comm.go:68] [console] get length 663
616I0919 07:48:37.469919   20402 init_comm.go:68] [console] read 504 bytes data, total data 512
617I0919 07:48:37.470032   20402 init_comm.go:68] [console] hyper send type 14, len 4
618I0919 07:48:37.470141   20402 init_comm.go:106] read 8/8 [length = 0]
619I0919 07:48:37.470195   20402 init_comm.go:110] data length is 12
620I0919 07:48:37.470210   20402 init_comm.go:96] trying to read 4 bytes
621I0919 07:48:37.470315   20402 init_comm.go:106] read 12/12 [length = 12]
622I0919 07:48:37.470375   20402 init_comm.go:96] trying to read 8 bytes
623I0919 07:48:37.470435   20402 init_comm.go:225] got cmd:14
624I0919 07:48:37.470490   20402 init_comm.go:288] get command NEXT
625I0919 07:48:37.470506   20402 init_comm.go:291] send 512, receive 512
626I0919 07:48:37.470532   20402 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"}
627                                                           null'.
628I0919 07:48:37.470968   20402 init_comm.go:68] [console] hyper_loop epoll_wait 1
629I0919 07:48:37.471913   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x61c600, fd 3. ops 0x61c3e0
630I0919 07:48:37.473085   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x61c600, fd 3, 0x61c3e0
631I0919 07:48:37.473501   20402 init_comm.go:68] [console] hyper_event_read
632I0919 07:48:37.473796   20402 init_comm.go:68] [console] get length 663
633I0919 07:48:37.474273   20402 init_comm.go:68] [console] read 151 bytes data, total data 663
634I0919 07:48:37.474838   20402 init_comm.go:68] [console] hyper send type 14, len 4
635I0919 07:48:37.474972   20402 init_comm.go:106] read 8/8 [length = 0]
636I0919 07:48:37.475095   20402 init_comm.go:110] data length is 12
637I0919 07:48:37.475110   20402 init_comm.go:96] trying to read 4 bytes
638I0919 07:48:37.475189   20402 init_comm.go:106] read 12/12 [length = 12]
639I0919 07:48:37.475217   20402 init_comm.go:96] trying to read 8 bytes
640I0919 07:48:37.475258   20402 init_comm.go:225] got cmd:14
641I0919 07:48:37.475276   20402 init_comm.go:288] get command NEXT
642I0919 07:48:37.475291   20402 init_comm.go:291] send 163, receive 151
643I0919 07:48:37.508285   20402 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 66 65 64 6f 72 61 2d 30 36 37 32 33 30 36 36 35 35 22 2c 22 63 6f 6e 74 61 69 6e 65 72 73 22 3a 5b 7b 22 69 64 22 3a 22 30 35 62 32 37 36 37 66 61 38 61 39 65 32 34 66 66 30 33 34 35 30 39 37 38 33 36 35 30 31 33 64 39 62 37 64 36 62 31 39 35 35 32 33 38 36 30 36 61 61 38 66 65 62 65 30 61 32 38 35 61 32 31 62 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 79 6f 71 54 6c 57 55 55 53 62 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 
644I0919 07:48:37.509132   20402 init_comm.go:68] [console]  hyper_channel_handle, type 1, len 663
645I0919 07:48:37.520989   20402 init_comm.go:68] [console] call hyper_start_pod, json {"hostname":"fedora-0672306655","containers":[{"id":"05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b","rootfs":"/rootfs","fstype":"xfs","image":"sda","fsmap":[{"source":"yoqTlWUUSb","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
646I0919 07:48:37.533053   20402 init_comm.go:68] [console] call hyper_start_pod, json {"hostname":"fedora-0672306655","containers":[{"id":"05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b","rootfs":"/rootfs","fstype":"xfs","image":"sda","fsmap":[{"source":"yoqTlWUUSb","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
647I0919 07:48:37.534823   20402 init_comm.go:68] [console] random: busybox urandom read with 18 bits of entropy available
648I0919 07:48:37.535440   20402 init_comm.go:68] [console] jsmn parse successed, n is 67
649I0919 07:48:37.536078   20402 init_comm.go:68] [console] token 0, type is 1, size is 5
650I0919 07:48:37.536734   20402 init_comm.go:68] [console] token 1, type is 3, size is 1
651I0919 07:48:37.537407   20402 init_comm.go:68] [console] hostname is fedora-0672306655
652I0919 07:48:37.537848   20402 init_comm.go:68] [console] token 3, type is 3, size is 1
653I0919 07:48:37.538282   20402 init_comm.go:68] [console] container count 1
654I0919 07:48:37.538632   20402 init_comm.go:68] [console] next container 8
655I0919 07:48:37.538889   20402 init_comm.go:68] [console] 1 name id
656I0919 07:48:37.540344   20402 init_comm.go:68] [console] container id 05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b
657I0919 07:48:37.540726   20402 init_comm.go:68] [console] 3 name rootfs
658I0919 07:48:37.541136   20402 init_comm.go:68] [console] container rootfs /rootfs
659I0919 07:48:37.541510   20402 init_comm.go:68] [console] 5 name fstype
660I0919 07:48:37.542017   20402 init_comm.go:68] [console] container fstype xfs
661I0919 07:48:37.542395   20402 init_comm.go:68] [console] 7 name image
662I0919 07:48:37.542904   20402 init_comm.go:68] [console] container image sda
663I0919 07:48:37.543268   20402 init_comm.go:68] [console] 9 name fsmap
664I0919 07:48:37.543631   20402 init_comm.go:68] [console] fsmap num 1
665I0919 07:48:37.544002   20402 init_comm.go:68] [console] maps 0 source yoqTlWUUSb
666I0919 07:48:37.544533   20402 init_comm.go:68] [console] maps 0 path /etc/hosts
667I0919 07:48:37.544882   20402 init_comm.go:68] [console] maps 0 readonly 0
668I0919 07:48:37.545413   20402 init_comm.go:68] [console] maps 0 docker volume 0
669I0919 07:48:37.545820   20402 init_comm.go:68] [console] 20 name process
670I0919 07:48:37.546222   20402 init_comm.go:68] [console] 1 name terminal
671I0919 07:48:37.546775   20402 init_comm.go:68] [console] container uses terminal
672I0919 07:48:37.547064   20402 init_comm.go:68] [console] 3 name stdio
673I0919 07:48:37.547467   20402 init_comm.go:68] [console] container seq 1
674I0919 07:48:37.547743   20402 init_comm.go:68] [console] 5 name args
675I0919 07:48:37.548451   20402 init_comm.go:68] [console] container init arg 0 /bin/bash
676I0919 07:48:37.548833   20402 init_comm.go:68] [console] 8 name envs
677I0919 07:48:37.549093   20402 init_comm.go:68] [console] envs num 1
678I0919 07:48:37.549529   20402 init_comm.go:68] [console] envs 0 env PATH
679I0919 07:48:37.550960   20402 init_comm.go:68] [console] envs 0 value /usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
680I0919 07:48:37.551296   20402 init_comm.go:68] [console] 15 name workdir
681I0919 07:48:37.551795   20402 init_comm.go:68] [console] container workdir /
682I0919 07:48:37.552356   20402 init_comm.go:68] [console] 38 name restartPolicy
683I0919 07:48:37.552861   20402 init_comm.go:68] [console] restart policy never
684I0919 07:48:37.553338   20402 init_comm.go:68] [console] 40 name initialize
685I0919 07:48:37.553961   20402 init_comm.go:68] [console] need to initialize container
686I0919 07:48:37.554626   20402 init_comm.go:68] [console] token 47, type is 3, size is 1
687I0919 07:48:37.555896   20402 init_comm.go:68] [console] network interfaces num 1
688I0919 07:48:37.555917   20402 init_comm.go:68] [console] net device is eth0
689I0919 07:48:37.555928   20402 init_comm.go:68] [console] net ipaddress is 192.168.123.2
690I0919 07:48:37.556582   20402 init_comm.go:68] [console] net mask is 255.255.255.0
691I0919 07:48:37.557319   20402 init_comm.go:68] [console] token 56, type is 3, size is 1
692I0919 07:48:37.557776   20402 init_comm.go:68] [console] network routes num 1
693I0919 07:48:37.558410   20402 init_comm.go:68] [console] route 0 dest is 0.0.0.0/0
694I0919 07:48:37.559136   20402 init_comm.go:68] [console] route 0 gateway is 192.168.123.1
695I0919 07:48:37.559899   20402 init_comm.go:68] [console] route 0 device is eth0
696I0919 07:48:37.560704   20402 init_comm.go:68] [console] token 65, type is 3, size is 1
697I0919 07:48:37.561226   20402 init_comm.go:68] [console] share tag is share_dir
698I0919 07:48:37.561598   20402 init_comm.go:68] [console] create directory /tmp
699I0919 07:48:37.562227   20402 init_comm.go:68] [console] create directory /tmp/hyper
700I0919 07:48:37.562719   20402 init_comm.go:68] [console] create directory /tmp/hyper/proc
701I0919 07:48:37.563430   20402 init_comm.go:68] [console] finish rescan
702I0919 07:48:37.563874   20402 init_comm.go:68] [console] net device eth0
703I0919 07:48:37.564522   20402 init_comm.go:68] [console] net device sys path is /sys/class/net/eth0/ifindex
704I0919 07:48:37.564929   20402 init_comm.go:68] [console] get ifindex 2
705I0919 07:48:37.565440   20402 init_comm.go:68] [console] interface get netamsk 24 255.255.255.0
706I0919 07:48:37.565704   20402 qmp_handler.go:103] got a message {"timestamp": {"seconds": 1474242517, "microseconds": 565577}, "event": "NIC_RX_FILTER_CHANGED", "data": {"name": "eth0", "path": "/machine/peripheral/eth0/virtio-backend"}}
707I0919 07:48:37.565795   20402 qmp_handler.go:107] got event: NIC_RX_FILTER_CHANGED
708I0919 07:48:37.566004   20402 qmp_handler.go:323] got QMP event NIC_RX_FILTER_CHANGED
709I0919 07:48:37.566082   20402 init_comm.go:68] [console] net device eth0
710I0919 07:48:37.567172   20402 init_comm.go:68] [console] net device sys path is /sys/class/net/eth0/ifindex
711I0919 07:48:37.567711   20402 init_comm.go:68] [console] get ifindex 2
712I0919 07:48:37.568537   20402 init_comm.go:68] [console] create directory /tmp/hyper/shared
713I0919 07:48:37.569714   20402 init_comm.go:68] [console] pod init pid 328
714I0919 07:48:37.570420   20402 init_comm.go:68] [console] hyper send type 8, len 0
715I0919 07:48:37.571458   20402 init_comm.go:68] [console] create directory /tmp/hyper/05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b
716I0919 07:48:37.573322   20402 init_comm.go:68] [console] create directory /tmp/hyper/05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b/devpts
717I0919 07:48:37.575240   20402 init_comm.go:68] [console] create directory /tmp/hyper/05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b/devpts/
718I0919 07:48:37.575790   20402 init_comm.go:68] [console] hyper send type 8, len 0
719I0919 07:48:37.576898   20402 init_comm.go:68] [console] create child process pid=330 in the sandbox
720I0919 07:48:37.577587   20402 init_comm.go:68] [console] path /sys/class/scsi_host/host0/scan
721I0919 07:48:37.598159   20402 init_comm.go:68] [console] finish scan scsi
722I0919 07:48:37.600067   20402 init_comm.go:68] [console] create directory /tmp/hyper/05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b/root
723I0919 07:48:37.601142   20402 init_comm.go:68] [console] create directory /tmp/hyper/05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b/root/
724I0919 07:48:37.603138   20402 init_comm.go:68] [console] container root directory /tmp/hyper/05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b/root/
725I0919 07:48:37.603649   20402 init_comm.go:68] [console] device /dev/sda
726I0919 07:48:37.605339   20402 init_comm.go:68] [console] XFS (sda): Mounting V5 Filesystem
727I0919 07:48:37.632585   20402 init_comm.go:68] [console] XFS (sda): Ending clean mount
728I0919 07:48:37.635539   20402 init_comm.go:68] [console] root directory for container is /tmp/hyper/05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b/root///rootfs, init task /bin/bash
729I0919 07:48:37.636374   20402 init_comm.go:68] [console] recreate file ./etc/hosts
730I0919 07:48:37.637189   20402 init_comm.go:68] [console] recreate file ./etc/hostname
731I0919 07:48:37.637740   20402 init_comm.go:68] [console] recreate symlink ./etc/mtab to /proc/mounts
732I0919 07:48:37.640059   20402 init_comm.go:68] [console] create directory ./lib/modules
733I0919 07:48:37.641102   20402 init_comm.go:68] [console] create directory ./dev/shm
734I0919 07:48:37.642073   20402 init_comm.go:68] [console] create directory .//lib/modules/4.4.12-hyper
735I0919 07:48:37.644233   20402 init_comm.go:68] [console] mount /tmp/hyper/shared/yoqTlWUUSb to .//etc/hosts
736I0919 07:48:37.645188   20402 init_comm.go:68] [console] no dns configured
737I0919 07:48:37.645767   20402 init_comm.go:68] [console] hyper send type 8, len 0
738I0919 07:48:37.647818   20402 init_comm.go:68] [console] get pty device for exec /tmp/hyper/05b2767fa8a9e24ff03450978365013d9b7d6b1955238606aa8febe0a285a21b/devpts//0
739I0919 07:48:37.648387   20402 init_comm.go:68] [console] hyper_setup_exec_tty pts event 0x24b3830, fd 6 7
740I0919 07:48:37.649629   20402 init_comm.go:68] [console] hyper_init_event container pts event 0x24b3830, ops 0x61c540, fd 6
741I0919 07:48:37.650444   20402 init_comm.go:68] [console] hyper_add_event add event fd 6, 0x61c540
742I0919 07:48:37.651263   20402 init_comm.go:68] [console] hyper_add_event add event fd 8, 0x61c500
743I0919 07:48:37.652089   20402 init_comm.go:68] [console] hyper_add_event add event fd 9, 0x61c4c0
744I0919 07:48:37.652651   20402 init_comm.go:68] [console] do_exec_cmd pid 595
745I0919 07:48:37.653399   20402 init_comm.go:68] [console] create child process pid=596 in the sandbox
746I0919 07:48:37.653986   20402 init_comm.go:68] [console] hyper send type 596, len 0
747I0919 07:48:37.654558   20402 init_comm.go:68] [console] hyper_run_process get ready message 596
748I0919 07:48:37.654983   20402 init_comm.go:68] [console] uptime 0.76 0.06
749I0919 07:48:37.655886   20402 init_comm.go:68] [console] 
750I0919 07:48:37.655928   20402 init_comm.go:68] [console] hyper send type 9, len 0
751I0919 07:48:37.655902   20402 init_comm.go:106] read 8/8 [length = 0]
752I0919 07:48:37.655970   20402 init_comm.go:110] data length is 8
753I0919 07:48:37.656006   20402 init_comm.go:96] trying to read 8 bytes
754I0919 07:48:37.656052   20402 init_comm.go:225] got cmd:9
755I0919 07:48:37.656087   20402 init_comm.go:244] ack got, clear pong timer
756I0919 07:48:37.656124   20402 hypervisor.go:29] vm vm-TrYQBzUgOJ: main event loop got message 31(COMMAND_ACK)
757I0919 07:48:37.656154   20402 vm_states.go:494] [starting] got init ack to &{1 859539950832 <nil> [] 859531128096}
758I0919 07:48:37.656305   20402 init_comm.go:68] [console] hyper_loop epoll_wait 2
759I0919 07:48:37.656589   20402 context.go:260] VM vm-TrYQBzUgOJ: state change from STARTING to 'RUNNING'
760I0919 07:48:37.656624   20402 vm_states.go:510] pod start success 
761I0919 07:48:37.656663   20402 vm.go:275] Get the response from VM, VM id is vm-TrYQBzUgOJ!
762I0919 07:48:37.656845   20402 init_comm.go:68] [console] hyper_dup_exec_tty
763I0919 07:48:37.656870   20402 pod.go:1299] Add or Update the VM info for pod(pod-vSsESEduXU)
764I0919 07:48:37.656959   20402 pod.go:332] unlock pod pod-vSsESEduXU for operation start
765I0919 07:48:37.656990   20402 pod.go:335] successfully unlock pod pod-vSsESEduXU for operation start
766I0919 07:48:37.658346   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x61c600, fd 3. ops 0x61c3e0
767I0919 07:48:37.659996   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x61c600, fd 3, 0x61c3e0
768I0919 07:48:37.660867   20402 init_comm.go:68] [console] hyper_event_read
769I0919 07:48:37.662031   20402 init_comm.go:68] [console] already read 8 bytes data
770I0919 07:48:37.662950   20402 init_comm.go:68] [console] hyper send type 14, len 4
771I0919 07:48:37.663394   20402 init_comm.go:68] [console] get length 12
772I0919 07:48:37.663832   20402 init_comm.go:68] [console] read 4 bytes data, total data 12
773I0919 07:48:37.663945   20402 init_comm.go:106] read 8/8 [length = 0]
774I0919 07:48:37.663967   20402 init_comm.go:110] data length is 12
775I0919 07:48:37.663981   20402 init_comm.go:96] trying to read 4 bytes
776I0919 07:48:37.664005   20402 init_comm.go:106] read 12/12 [length = 12]
777I0919 07:48:37.664036   20402 init_comm.go:96] trying to read 8 bytes
778I0919 07:48:37.664068   20402 init_comm.go:225] got cmd:14
779I0919 07:48:37.664083   20402 init_comm.go:288] get command NEXT
780I0919 07:48:37.664091   20402 init_comm.go:291] send 163, receive 159
781I0919 07:48:37.664475   20402 init_comm.go:68] [console] hyper send type 14, len 4
782I0919 07:48:37.664962   20402 init_comm.go:106] read 8/8 [length = 0]
783I0919 07:48:37.664995   20402 init_comm.go:110] data length is 12
784I0919 07:48:37.665012   20402 init_comm.go:96] trying to read 4 bytes
785I0919 07:48:37.665039   20402 init_comm.go:106] read 12/12 [length = 12]
786I0919 07:48:37.665065   20402 init_comm.go:96] trying to read 8 bytes
787I0919 07:48:37.665093   20402 init_comm.go:225] got cmd:14
788I0919 07:48:37.665109   20402 init_comm.go:288] get command NEXT
789I0919 07:48:37.665124   20402 init_comm.go:291] send 163, receive 163
790I0919 07:48:37.665274   20402 init_comm.go:68] [console] 0 0 0 0 0 0 0 c 6e 75 6c 6c 
791I0919 07:48:37.666308   20402 init_comm.go:68] [console]  hyper_channel_handle, type 0, len 12
792I0919 07:48:37.666906   20402 init_comm.go:68] [console] hyper send type 9, len 4
793I0919 07:48:37.667216   20402 init_comm.go:106] read 8/8 [length = 0]
794I0919 07:48:37.667243   20402 init_comm.go:110] data length is 12
795I0919 07:48:37.667258   20402 init_comm.go:96] trying to read 4 bytes
796I0919 07:48:37.667274   20402 init_comm.go:106] read 12/12 [length = 12]
797I0919 07:48:37.667293   20402 init_comm.go:96] trying to read 8 bytes
798I0919 07:48:37.667326   20402 init_comm.go:225] got cmd:9
799I0919 07:48:37.667348   20402 init_comm.go:198] hyperstart API version:4242, VM hyperstart API version: 4242
800I0919 07:48:37.668153   20402 init_comm.go:68] [console] hyper_handle_event get event 4, he 0x24b3830, fd 6. ops 0x61c540
801I0919 07:48:37.669150   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLOUT, he 0x24b3830, fd 6, 0x61c540
802I0919 07:48:37.669976   20402 init_comm.go:68] [console] write_to_stdin, seq 1
803I0919 07:48:37.671368   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 6, 0x24b3830, event 0
804I0919 07:48:37.672250   20402 init_comm.go:68] [console] pid 327 exit normally, status 0
805I0919 07:48:37.672911   20402 init_comm.go:68] [console] exec pid 596, pid 327
806I0919 07:48:37.673779   20402 init_comm.go:68] [console] can not find exec whose pid is 327
807I0919 07:48:37.674625   20402 init_comm.go:68] [console] pid 329 exit normally, status 0
808I0919 07:48:37.675359   20402 init_comm.go:68] [console] exec pid 596, pid 329
809I0919 07:48:37.676348   20402 init_comm.go:68] [console] can not find exec whose pid is 329
810I0919 07:48:37.677356   20402 init_comm.go:68] [console] pid 330 exit normally, status 0
811I0919 07:48:37.678035   20402 init_comm.go:68] [console] exec pid 596, pid 330
812I0919 07:48:37.679001   20402 init_comm.go:68] [console] can not find exec whose pid is 330
813I0919 07:48:37.679929   20402 init_comm.go:68] [console] pid 595 exit normally, status 0
814I0919 07:48:37.680507   20402 init_comm.go:68] [console] exec pid 596, pid 595
815I0919 07:48:37.681823   20402 init_comm.go:68] [console] can not find exec whose pid is 595
816I0919 07:48:37.682515   20402 init_comm.go:68] [console] hyper_loop epoll_wait -1
817I0919 07:48:37.746090   20402 init_comm.go:68] [console] hyper_loop epoll_wait 2
818I0919 07:48:37.747000   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x24b38a0, fd 9. ops 0x61c4c0
819I0919 07:48:37.747831   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x24b38a0, fd 9, 0x61c4c0
820I0919 07:48:37.748175   20402 init_comm.go:68] [console] stderr_loop, seq 0
821I0919 07:48:37.748622   20402 init_comm.go:68] [console] pts_loop: read 25 data
822I0919 07:48:37.749019   20402 init_comm.go:68] [console] pts_loop: read -1 data
823I0919 07:48:37.749765   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 4, 0x61c5c8, event 5
824I0919 07:48:37.750796   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x24b3868, fd 8. ops 0x61c500
825I0919 07:48:37.751899   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x24b3868, fd 8, 0x61c500
826I0919 07:48:37.752459   20402 init_comm.go:68] [console] stdout_loop, seq 1
827I0919 07:48:37.752838   20402 init_comm.go:68] [console] pts_loop: read 28 data
828I0919 07:48:37.753359   20402 init_comm.go:68] [console] pts_loop: read -1 data
829I0919 07:48:37.753742   20402 init_comm.go:68] [console] hyper_loop epoll_wait 1
830I0919 07:48:37.754950   20402 init_comm.go:68] [console] hyper_handle_event get event 4, he 0x61c5c8, fd 4. ops 0x61c3a0
831I0919 07:48:37.755629   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLOUT, he 0x61c5c8, fd 4, 0x61c3a0
832I0919 07:48:37.755748   20402 tty.go:99] tty: read 12/12 [length = 0]
833I0919 07:48:37.755768   20402 tty.go:103] data length is 37
834I0919 07:48:37.755782   20402 tty.go:89] tty: trying to read 25 bytes
835I0919 07:48:37.755803   20402 tty.go:99] tty: read 37/37 [length = 37]
836I0919 07:48:37.755950   20402 tty.go:89] tty: trying to read 12 bytes
837I0919 07:48:37.755988   20402 tty.go:99] tty: read 12/12 [length = 0]
838I0919 07:48:37.756020   20402 tty.go:103] data length is 40
839I0919 07:48:37.756044   20402 tty.go:89] tty: trying to read 28 bytes
840I0919 07:48:37.756074   20402 tty.go:99] tty: read 40/40 [length = 40]
841I0919 07:48:37.756122   20402 tty.go:89] tty: trying to read 12 bytes
842I0919 07:48:37.756711   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 4, 0x61c5c8, event 1
843I0919 07:48:38.156748   20402 init_comm.go:68] [console] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x1e2c1ca2cfa, max_idle_ns: 440795290083 ns
844I0919 07:48:44.981840   20402 tty.go:409] trying to input char: 100 and 1 chars
845I0919 07:48:44.982014   20402 tty.go:124] trying to write to session 1
846I0919 07:48:44.983863   20402 init_comm.go:68] [console] hyper_loop epoll_wait 1
847I0919 07:48:44.985724   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x61c5c8, fd 4. ops 0x61c3a0
848I0919 07:48:44.988752   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x61c5c8, fd 4, 0x61c3a0
849I0919 07:48:44.989580   20402 init_comm.go:68] [console] hyper_event_read
850I0919 07:48:44.990863   20402 init_comm.go:68] [console] already read 12 bytes data
851I0919 07:48:44.991606   20402 init_comm.go:68] [console] get length 13
852I0919 07:48:44.992983   20402 init_comm.go:68] [console] read 1 bytes data, total data 13
853I0919 07:48:44.993898   20402 init_comm.go:68] [console] exec seq 1, seq 1
854I0919 07:48:44.996201   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 6, 0x24b3830, event 4
855I0919 07:48:44.999012   20402 init_comm.go:68] [console] hyper_loop epoll_wait 1
856I0919 07:48:45.005254   20402 init_comm.go:68] [console] hyper_handle_event get event 4, he 0x24b3830, fd 6. ops 0x61c540
857I0919 07:48:45.005333   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLOUT, he 0x24b3830, fd 6, 0x61c540
858I0919 07:48:45.005355   20402 init_comm.go:68] [console] write_to_stdin, seq 1
859I0919 07:48:45.005374   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 6, 0x24b3830, event 0
860I0919 07:48:45.005391   20402 init_comm.go:68] [console] hyper_loop epoll_wait 2
861I0919 07:48:45.006955   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x24b38a0, fd 9. ops 0x61c4c0
862I0919 07:48:45.012232   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x24b38a0, fd 9, 0x61c4c0
863I0919 07:48:45.012261   20402 tty.go:99] tty: read 12/12 [length = 0]
864I0919 07:48:45.012279   20402 init_comm.go:68] [console] stderr_loop, seq 0
865I0919 07:48:45.012290   20402 tty.go:103] data length is 13
866I0919 07:48:45.012300   20402 init_comm.go:68] [console] pts_loop: read 1 data
867I0919 07:48:45.012318   20402 init_comm.go:68] [console] pts_loop: read -1 data
868I0919 07:48:45.012338   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 4, 0x61c5c8, event 5
869I0919 07:48:45.012358   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x24b3868, fd 8. ops 0x61c500
870I0919 07:48:45.012419   20402 tty.go:89] tty: trying to read 1 bytes
871I0919 07:48:45.012453   20402 tty.go:99] tty: read 13/13 [length = 13]
872I0919 07:48:45.012523   20402 tty.go:89] tty: trying to read 12 bytes
873I0919 07:48:45.012904   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x24b3868, fd 8, 0x61c500
874I0919 07:48:45.013407   20402 init_comm.go:68] [console] stdout_loop, seq 1
875I0919 07:48:45.013993   20402 init_comm.go:68] [console] pts_loop: read -1 data
876I0919 07:48:45.014604   20402 init_comm.go:68] [console] hyper_loop epoll_wait 1
877I0919 07:48:45.016184   20402 init_comm.go:68] [console] hyper_handle_event get event 4, he 0x61c5c8, fd 4. ops 0x61c3a0
878I0919 07:48:45.017748   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLOUT, he 0x61c5c8, fd 4, 0x61c3a0
879I0919 07:48:45.019793   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 4, 0x61c5c8, event 1
880I0919 07:48:45.108862   20402 tty.go:409] trying to input char: 102 and 1 chars
881I0919 07:48:45.108974   20402 tty.go:124] trying to write to session 1
882I0919 07:48:45.110440   20402 init_comm.go:68] [console] hyper_loop epoll_wait 1
883I0919 07:48:45.113216   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x61c5c8, fd 4. ops 0x61c3a0
884I0919 07:48:45.116098   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x61c5c8, fd 4, 0x61c3a0
885I0919 07:48:45.117056   20402 init_comm.go:68] [console] hyper_event_read
886I0919 07:48:45.118131   20402 init_comm.go:68] [console] already read 12 bytes data
887I0919 07:48:45.118798   20402 init_comm.go:68] [console] get length 13
888I0919 07:48:45.120069   20402 init_comm.go:68] [console] read 1 bytes data, total data 13
889I0919 07:48:45.120915   20402 init_comm.go:68] [console] exec seq 1, seq 1
890I0919 07:48:45.122881   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 6, 0x24b3830, event 4
891I0919 07:48:45.123904   20402 init_comm.go:68] [console] hyper_loop epoll_wait 1
892I0919 07:48:45.126898   20402 init_comm.go:68] [console] hyper_handle_event get event 4, he 0x24b3830, fd 6. ops 0x61c540
893I0919 07:48:45.128125   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLOUT, he 0x24b3830, fd 6, 0x61c540
894I0919 07:48:45.129212   20402 init_comm.go:68] [console] write_to_stdin, seq 1
895I0919 07:48:45.130647   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 6, 0x24b3830, event 0
896I0919 07:48:45.131557   20402 init_comm.go:68] [console] hyper_loop epoll_wait 2
897I0919 07:48:45.132916   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x24b38a0, fd 9. ops 0x61c4c0
898I0919 07:48:45.134725   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x24b38a0, fd 9, 0x61c4c0
899I0919 07:48:45.135521   20402 init_comm.go:68] [console] stderr_loop, seq 0
900I0919 07:48:45.136359   20402 init_comm.go:68] [console] pts_loop: read 1 data
901I0919 07:48:45.137166   20402 init_comm.go:68] [console] pts_loop: read -1 data
902I0919 07:48:45.138735   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 4, 0x61c5c8, event 5
903I0919 07:48:45.140381   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x24b3868, fd 8. ops 0x61c500
904I0919 07:48:45.142155   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x24b3868, fd 8, 0x61c500
905I0919 07:48:45.142889   20402 init_comm.go:68] [console] stdout_loop, seq 1
906I0919 07:48:45.143404   20402 init_comm.go:68] [console] pts_loop: read -1 data
907I0919 07:48:45.144159   20402 init_comm.go:68] [console] hyper_loop epoll_wait 1
908I0919 07:48:45.145919   20402 init_comm.go:68] [console] hyper_handle_event get event 4, he 0x61c5c8, fd 4. ops 0x61c3a0
909I0919 07:48:45.147625   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLOUT, he 0x61c5c8, fd 4, 0x61c3a0
910I0919 07:48:45.147905   20402 tty.go:99] tty: read 12/12 [length = 0]
911I0919 07:48:45.147954   20402 tty.go:103] data length is 13
912I0919 07:48:45.147972   20402 tty.go:89] tty: trying to read 1 bytes
913I0919 07:48:45.147988   20402 tty.go:99] tty: read 13/13 [length = 13]
914I0919 07:48:45.148047   20402 tty.go:89] tty: trying to read 12 bytes
915I0919 07:48:45.149400   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 4, 0x61c5c8, event 1
916I0919 07:48:45.163820   20402 tty.go:409] trying to input char: 32 and 1 chars
917I0919 07:48:45.163888   20402 tty.go:124] trying to write to session 1
918I0919 07:48:45.164856   20402 init_comm.go:68] [console] hyper_loop epoll_wait 1
919I0919 07:48:45.166353   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x61c5c8, fd 4. ops 0x61c3a0
920I0919 07:48:45.167850   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x61c5c8, fd 4, 0x61c3a0
921I0919 07:48:45.168390   20402 init_comm.go:68] [console] hyper_event_read
922I0919 07:48:45.169095   20402 init_comm.go:68] [console] already read 12 bytes data
923I0919 07:48:45.169574   20402 init_comm.go:68] [console] get length 13
924I0919 07:48:45.170458   20402 init_comm.go:68] [console] read 1 bytes data, total data 13
925I0919 07:48:45.171031   20402 init_comm.go:68] [console] exec seq 1, seq 1
926I0919 07:48:45.172460   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 6, 0x24b3830, event 4
927I0919 07:48:45.173201   20402 init_comm.go:68] [console] hyper_loop epoll_wait 1
928I0919 07:48:45.174352   20402 init_comm.go:68] [console] hyper_handle_event get event 4, he 0x24b3830, fd 6. ops 0x61c540
929I0919 07:48:45.176001   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLOUT, he 0x24b3830, fd 6, 0x61c540
930I0919 07:48:45.176436   20402 init_comm.go:68] [console] write_to_stdin, seq 1
931I0919 07:48:45.177370   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 6, 0x24b3830, event 0
932I0919 07:48:45.177752   20402 init_comm.go:68] [console] hyper_loop epoll_wait 2
933I0919 07:48:45.179211   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x24b38a0, fd 9. ops 0x61c4c0
934I0919 07:48:45.180051   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x24b38a0, fd 9, 0x61c4c0
935I0919 07:48:45.180578   20402 init_comm.go:68] [console] stderr_loop, seq 0
936I0919 07:48:45.181198   20402 init_comm.go:68] [console] pts_loop: read 1 data
937I0919 07:48:45.181731   20402 init_comm.go:68] [console] pts_loop: read -1 data
938I0919 07:48:45.183060   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 4, 0x61c5c8, event 5
939I0919 07:48:45.184013   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x24b3868, fd 8. ops 0x61c500
940I0919 07:48:45.185544   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x24b3868, fd 8, 0x61c500
941I0919 07:48:45.185986   20402 init_comm.go:68] [console] stdout_loop, seq 1
942I0919 07:48:45.186615   20402 init_comm.go:68] [console] pts_loop: read -1 data
943I0919 07:48:45.187066   20402 init_comm.go:68] [console] hyper_loop epoll_wait 1
944I0919 07:48:45.188400   20402 init_comm.go:68] [console] hyper_handle_event get event 4, he 0x61c5c8, fd 4. ops 0x61c3a0
945I0919 07:48:45.189731   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLOUT, he 0x61c5c8, fd 4, 0x61c3a0
946I0919 07:48:45.189885   20402 tty.go:99] tty: read 12/12 [length = 0]
947I0919 07:48:45.189907   20402 tty.go:103] data length is 13
948I0919 07:48:45.189924   20402 tty.go:89] tty: trying to read 1 bytes
949I0919 07:48:45.189949   20402 tty.go:99] tty: read 13/13 [length = 13]
950I0919 07:48:45.189996   20402 tty.go:89] tty: trying to read 12 bytes
951I0919 07:48:45.191169   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 4, 0x61c5c8, event 1
952I0919 07:48:45.338028   20402 tty.go:409] trying to input char: 45 and 1 chars
953I0919 07:48:45.338133   20402 tty.go:124] trying to write to session 1
954I0919 07:48:45.339650   20402 init_comm.go:68] [console] hyper_loop epoll_wait 1
955I0919 07:48:45.342557   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x61c5c8, fd 4. ops 0x61c3a0
956I0919 07:48:45.345284   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x61c5c8, fd 4, 0x61c3a0
957I0919 07:48:45.346186   20402 init_comm.go:68] [console] hyper_event_read
958I0919 07:48:45.347422   20402 init_comm.go:68] [console] already read 12 bytes data
959I0919 07:48:45.348192   20402 init_comm.go:68] [console] get length 13
960I0919 07:48:45.350257   20402 init_comm.go:68] [console] read 1 bytes data, total data 13
961I0919 07:48:45.350875   20402 init_comm.go:68] [console] exec seq 1, seq 1
962I0919 07:48:45.352873   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 6, 0x24b3830, event 4
963I0919 07:48:45.354611   20402 init_comm.go:68] [console] hyper_loop epoll_wait 1
964I0919 07:48:45.356790   20402 init_comm.go:68] [console] hyper_handle_event get event 4, he 0x24b3830, fd 6. ops 0x61c540
965I0919 07:48:45.358839   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLOUT, he 0x24b3830, fd 6, 0x61c540
966I0919 07:48:45.359635   20402 init_comm.go:68] [console] write_to_stdin, seq 1
967I0919 07:48:45.361509   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 6, 0x24b3830, event 0
968I0919 07:48:45.362434   20402 init_comm.go:68] [console] hyper_loop epoll_wait 2
969I0919 07:48:45.364449   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x24b38a0, fd 9. ops 0x61c4c0
970I0919 07:48:45.366663   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x24b38a0, fd 9, 0x61c4c0
971I0919 07:48:45.367632   20402 init_comm.go:68] [console] stderr_loop, seq 0
972I0919 07:48:45.368699   20402 init_comm.go:68] [console] pts_loop: read 1 data
973I0919 07:48:45.369720   20402 init_comm.go:68] [console] pts_loop: read -1 data
974I0919 07:48:45.371635   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 4, 0x61c5c8, event 5
975I0919 07:48:45.373532   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x24b3868, fd 8. ops 0x61c500
976I0919 07:48:45.375317   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x24b3868, fd 8, 0x61c500
977I0919 07:48:45.375827   20402 init_comm.go:68] [console] stdout_loop, seq 1
978I0919 07:48:45.376624   20402 init_comm.go:68] [console] pts_loop: read -1 data
979I0919 07:48:45.377173   20402 init_comm.go:68] [console] hyper_loop epoll_wait 1
980I0919 07:48:45.378990   20402 init_comm.go:68] [console] hyper_handle_event get event 4, he 0x61c5c8, fd 4. ops 0x61c3a0
981I0919 07:48:45.380193   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLOUT, he 0x61c5c8, fd 4, 0x61c3a0
982I0919 07:48:45.380432   20402 tty.go:99] tty: read 12/12 [length = 0]
983I0919 07:48:45.380466   20402 tty.go:103] data length is 13
984I0919 07:48:45.380490   20402 tty.go:89] tty: trying to read 1 bytes
985I0919 07:48:45.380523   20402 tty.go:99] tty: read 13/13 [length = 13]
986I0919 07:48:45.380594   20402 tty.go:89] tty: trying to read 12 bytes
987I0919 07:48:45.381576   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 4, 0x61c5c8, event 1
988I0919 07:48:45.454065   20402 tty.go:409] trying to input char: 104 and 1 chars
989I0919 07:48:45.454199   20402 tty.go:124] trying to write to session 1
990I0919 07:48:45.455457   20402 init_comm.go:68] [console] hyper_loop epoll_wait 1
991I0919 07:48:45.458413   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x61c5c8, fd 4. ops 0x61c3a0
992I0919 07:48:45.461508   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x61c5c8, fd 4, 0x61c3a0
993I0919 07:48:45.462511   20402 init_comm.go:68] [console] hyper_event_read
994I0919 07:48:45.463885   20402 init_comm.go:68] [console] already read 12 bytes data
995I0919 07:48:45.464651   20402 init_comm.go:68] [console] get length 13
996I0919 07:48:45.466062   20402 init_comm.go:68] [console] read 1 bytes data, total data 13
997I0919 07:48:45.467055   20402 init_comm.go:68] [console] exec seq 1, seq 1
998I0919 07:48:45.469431   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 6, 0x24b3830, event 4
999I0919 07:48:45.470505   20402 init_comm.go:68] [console] hyper_loop epoll_wait 1
1000I0919 07:48:45.473394   20402 init_comm.go:68] [console] hyper_handle_event get event 4, he 0x24b3830, fd 6. ops 0x61c540
1001I0919 07:48:45.475372   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLOUT, he 0x24b3830, fd 6, 0x61c540
1002I0919 07:48:45.476222   20402 init_comm.go:68] [console] write_to_stdin, seq 1
1003I0919 07:48:45.478109   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 6, 0x24b3830, event 0
1004I0919 07:48:45.479021   20402 init_comm.go:68] [console] hyper_loop epoll_wait 2
1005I0919 07:48:45.480159   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x24b38a0, fd 9. ops 0x61c4c0
1006I0919 07:48:45.482033   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x24b38a0, fd 9, 0x61c4c0
1007I0919 07:48:45.482661   20402 init_comm.go:68] [console] stderr_loop, seq 0
1008I0919 07:48:45.483433   20402 init_comm.go:68] [console] pts_loop: read 1 data
1009I0919 07:48:45.483903   20402 init_comm.go:68] [console] pts_loop: read -1 data
1010I0919 07:48:45.485379   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 4, 0x61c5c8, event 5
1011I0919 07:48:45.487252   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x24b3868, fd 8. ops 0x61c500
1012I0919 07:48:45.489019   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x24b3868, fd 8, 0x61c500
1013I0919 07:48:45.489687   20402 init_comm.go:68] [console] stdout_loop, seq 1
1014I0919 07:48:45.490474   20402 init_comm.go:68] [console] pts_loop: read -1 data
1015I0919 07:48:45.491294   20402 init_comm.go:68] [console] hyper_loop epoll_wait 1
1016I0919 07:48:45.493043   20402 init_comm.go:68] [console] hyper_handle_event get event 4, he 0x61c5c8, fd 4. ops 0x61c3a0
1017I0919 07:48:45.494775   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLOUT, he 0x61c5c8, fd 4, 0x61c3a0
1018I0919 07:48:45.495096   20402 tty.go:99] tty: read 12/12 [length = 0]
1019I0919 07:48:45.495183   20402 tty.go:103] data length is 13
1020I0919 07:48:45.495259   20402 tty.go:89] tty: trying to read 1 bytes
1021I0919 07:48:45.495338   20402 tty.go:99] tty: read 13/13 [length = 13]
1022I0919 07:48:45.495469   20402 tty.go:89] tty: trying to read 12 bytes
1023I0919 07:48:45.496091   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 4, 0x61c5c8, event 1
1024I0919 07:48:45.565460   20402 tty.go:409] trying to input char: 13 and 1 chars
1025I0919 07:48:45.565545   20402 tty.go:124] trying to write to session 1
1026I0919 07:48:45.566610   20402 init_comm.go:68] [console] hyper_loop epoll_wait 1
1027I0919 07:48:45.568269   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x61c5c8, fd 4. ops 0x61c3a0
1028I0919 07:48:45.569899   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x61c5c8, fd 4, 0x61c3a0
1029I0919 07:48:45.570491   20402 init_comm.go:68] [console] hyper_event_read
1030I0919 07:48:45.571340   20402 init_comm.go:68] [console] already read 12 bytes data
1031I0919 07:48:45.571860   20402 init_comm.go:68] [console] get length 13
1032I0919 07:48:45.572465   20402 init_comm.go:68] [console] read 1 bytes data, total data 13
1033I0919 07:48:45.573083   20402 init_comm.go:68] [console] exec seq 1, seq 1
1034I0919 07:48:45.574687   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 6, 0x24b3830, event 4
1035I0919 07:48:45.575487   20402 init_comm.go:68] [console] hyper_loop epoll_wait 1
1036I0919 07:48:45.579162   20402 init_comm.go:68] [console] hyper_handle_event get event 4, he 0x24b3830, fd 6. ops 0x61c540
1037I0919 07:48:45.579190   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLOUT, he 0x24b3830, fd 6, 0x61c540
1038I0919 07:48:45.579203   20402 init_comm.go:68] [console] write_to_stdin, seq 1
1039I0919 07:48:45.580765   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 6, 0x24b3830, event 0
1040I0919 07:48:45.581669   20402 init_comm.go:68] [console] hyper_loop epoll_wait 2
1041I0919 07:48:45.583569   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x24b38a0, fd 9. ops 0x61c4c0
1042I0919 07:48:45.584606   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x24b38a0, fd 9, 0x61c4c0
1043I0919 07:48:45.585276   20402 init_comm.go:68] [console] stderr_loop, seq 0
1044I0919 07:48:45.585610   20402 init_comm.go:68] [console] pts_loop: read 357 data
1045I0919 07:48:45.586068   20402 init_comm.go:68] [console] pts_loop: read -1 data
1046I0919 07:48:45.586728   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 4, 0x61c5c8, event 5
1047I0919 07:48:45.587975   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x24b3868, fd 8. ops 0x61c500
1048I0919 07:48:45.588712   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x24b3868, fd 8, 0x61c500
1049I0919 07:48:45.589178   20402 init_comm.go:68] [console] stdout_loop, seq 1
1050I0919 07:48:45.589716   20402 init_comm.go:68] [console] pts_loop: read -1 data
1051I0919 07:48:45.590283   20402 init_comm.go:68] [console] hyper_loop epoll_wait 1
1052I0919 07:48:45.591510   20402 init_comm.go:68] [console] hyper_handle_event get event 4, he 0x61c5c8, fd 4. ops 0x61c3a0
1053I0919 07:48:45.592708   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLOUT, he 0x61c5c8, fd 4, 0x61c3a0
1054I0919 07:48:45.592856   20402 tty.go:99] tty: read 12/12 [length = 0]
1055I0919 07:48:45.592879   20402 tty.go:103] data length is 369
1056I0919 07:48:45.592896   20402 tty.go:89] tty: trying to read 357 bytes
1057I0919 07:48:45.592918   20402 tty.go:99] tty: read 369/369 [length = 369]
1058I0919 07:48:45.593064   20402 tty.go:89] tty: trying to read 12 bytes
1059I0919 07:48:45.593992   20402 init_comm.go:68] [console] hyper_modify_event modify event fd 4, 0x61c5c8, event 1
1060I0919 07:49:07.667734   20402 init_comm.go:251] Send ping message to init
1061I0919 07:49:07.667942   20402 init_comm.go:225] got cmd:12
1062I0919 07:49:07.668001   20402 init_comm.go:316] send command 12 to init, payload: 'null'.
1063I0919 07:49:07.668080   20402 init_comm.go:329] write 12 to init, payload: '
1064
1065                                                                            null'.
1066I0919 07:49:07.668125   20402 init_comm.go:334] message sent, set pong timer
1067I0919 07:49:07.669246   20402 init_comm.go:68] [console] hyper_loop epoll_wait 1
1068I0919 07:49:07.670734   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x61c600, fd 3. ops 0x61c3e0
1069I0919 07:49:07.672241   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x61c600, fd 3, 0x61c3e0
1070I0919 07:49:07.672916   20402 init_comm.go:68] [console] hyper_event_read
1071I0919 07:49:07.674060   20402 init_comm.go:68] [console] already read 8 bytes data
1072I0919 07:49:07.674899   20402 init_comm.go:68] [console] hyper send type 14, len 4
1073I0919 07:49:07.675169   20402 init_comm.go:106] read 8/8 [length = 0]
1074I0919 07:49:07.675228   20402 init_comm.go:110] data length is 12
1075I0919 07:49:07.675260   20402 init_comm.go:96] trying to read 4 bytes
1076I0919 07:49:07.675304   20402 init_comm.go:106] read 12/12 [length = 12]
1077I0919 07:49:07.675352   20402 init_comm.go:96] trying to read 8 bytes
1078I0919 07:49:07.675404   20402 init_comm.go:225] got cmd:14
1079I0919 07:49:07.675440   20402 init_comm.go:288] get command NEXT
1080I0919 07:49:07.675472   20402 init_comm.go:291] send 12, receive 8
1081I0919 07:49:07.675872   20402 init_comm.go:68] [console] get length 12
1082I0919 07:49:07.676793   20402 init_comm.go:68] [console] read 4 bytes data, total data 12
1083I0919 07:49:07.677598   20402 init_comm.go:68] [console] hyper send type 14, len 4
1084I0919 07:49:07.677905   20402 init_comm.go:106] read 8/8 [length = 0]
1085I0919 07:49:07.677987   20402 init_comm.go:110] data length is 12
1086I0919 07:49:07.678015   20402 init_comm.go:96] trying to read 4 bytes
1087I0919 07:49:07.678050   20402 init_comm.go:106] read 12/12 [length = 12]
1088I0919 07:49:07.678091   20402 init_comm.go:96] trying to read 8 bytes
1089I0919 07:49:07.678147   20402 init_comm.go:225] got cmd:14
1090I0919 07:49:07.678186   20402 init_comm.go:288] get command NEXT
1091I0919 07:49:07.678214   20402 init_comm.go:291] send 12, receive 12
1092I0919 07:49:07.679027   20402 init_comm.go:68] [console] 0 0 0 c 0 0 0 c 6e 75 6c 6c 
1093I0919 07:49:07.680405   20402 init_comm.go:68] [console]  hyper_channel_handle, type 12, len 12
1094I0919 07:49:07.681506   20402 init_comm.go:68] [console] hyper send type 9, len 0
1095I0919 07:49:07.681754   20402 init_comm.go:106] read 8/8 [length = 0]
1096I0919 07:49:07.681786   20402 init_comm.go:110] data length is 8
1097I0919 07:49:07.681855   20402 init_comm.go:96] trying to read 8 bytes
1098I0919 07:49:07.681899   20402 init_comm.go:225] got cmd:9
1099I0919 07:49:07.681926   20402 init_comm.go:244] ack got, clear pong timer
1100I0919 07:49:37.682403   20402 init_comm.go:251] Send ping message to init
1101I0919 07:49:37.682565   20402 init_comm.go:225] got cmd:12
1102I0919 07:49:37.682631   20402 init_comm.go:316] send command 12 to init, payload: 'null'.
1103I0919 07:49:37.682720   20402 init_comm.go:329] write 12 to init, payload: '
1104
1105                                                                            null'.
1106I0919 07:49:37.682768   20402 init_comm.go:334] message sent, set pong timer
1107I0919 07:49:37.684574   20402 init_comm.go:68] [console] hyper_loop epoll_wait 1
1108I0919 07:49:37.687077   20402 init_comm.go:68] [console] hyper_handle_event get event 1, he 0x61c600, fd 3. ops 0x61c3e0
1109I0919 07:49:37.688953   20402 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, he 0x61c600, fd 3, 0x61c3e0
1110I0919 07:49:37.689957   20402 init_comm.go:68] [console] hyper_event_read
1111I0919 07:49:37.691052   20402 init_comm.go:68] [console] already read 8 bytes data
1112I0919 07:49:37.692381   20402 init_comm.go:68] [console] hyper send type 14, len 4
1113I0919 07:49:37.692798   20402 init_comm.go:106] read 8/8 [length = 0]
1114I0919 07:49:37.692878   20402 init_comm.go:110] data length is 12
1115I0919 07:49:37.692904   20402 init_comm.go:96] trying to read 4 bytes
1116I0919 07:49:37.692933   20402 init_comm.go:106] read 12/12 [length = 12]
1117I0919 07:49:37.692973   20402 init_comm.go:96] trying to read 8 bytes
1118I0919 07:49:37.693023   20402 init_comm.go:225] got cmd:14
1119I0919 07:49:37.693055   20402 init_comm.go:288] get command NEXT
1120I0919 07:49:37.693074   20402 init_comm.go:291] send 12, receive 8
1121I0919 07:49:37.693493   20402 init_comm.go:68] [console] get length 12
1122I0919 07:49:37.694780   20402 init_comm.go:68] [console] read 4 bytes data, total data 12
1123I0919 07:49:37.695843   20402 init_comm.go:68] [console] hyper send type 14, len 4
1124I0919 07:49:37.696125   20402 init_comm.go:106] read 8/8 [length = 0]
1125I0919 07:49:37.696163   20402 init_comm.go:110] data length is 12
1126I0919 07:49:37.696191   20402 init_comm.go:96] trying to read 4 bytes
1127I0919 07:49:37.696223   20402 init_comm.go:106] read 12/12 [length = 12]
1128I0919 07:49:37.696262   20402 init_comm.go:96] trying to read 8 bytes
1129I0919 07:49:37.696310   20402 init_comm.go:225] got cmd:14
1130I0919 07:49:37.696345   20402 init_comm.go:288] get command NEXT
1131I0919 07:49:37.696374   20402 init_comm.go:291] send 12, receive 12
1132I0919 07:49:37.697476   20402 init_comm.go:68] [console] 0 0 0 c 0 0 0 c 6e 75 6c 6c 
1133I0919 07:49:37.699990   20402 init_comm.go:68] [console]  hyper_channel_handle, type 12, len 12
1134I0919 07:49:37.700057   20402 init_comm.go:68] [console] hyper send type 9, len 0
1135I0919 07:49:37.700406   20402 init_comm.go:106] read 8/8 [length = 0]
1136I0919 07:49:37.700466   20402 init_comm.go:110] data length is 8
1137I0919 07:49:37.700507   20402 init_comm.go:96] trying to read 8 bytes
1138I0919 07:49:37.700560   20402 init_comm.go:225] got cmd:9
1139I0919 07:49:37.700597   20402 init_comm.go:244] ack got, clear pong timer