Skip to content

Instantly share code, notes, and snippets.

@carmark

carmark/error_log.txt

Last active March 12, 2016 10:56
Show Gist options

  • Select an option

    Learn more about clone URLs
  • Save carmark/21293b2d19cab8cddf33 to your computer and use it in GitHub Desktop.

Select an option

Learn more about clone URLs
Save carmark/21293b2d19cab8cddf33 to your computer and use it in GitHub Desktop.
Download ZIP
Raw
error_log.txt
I0312 18:54:33.001941 47898 init_comm.go:90] data length is 12
I0312 18:54:33.001945 47898 init_comm.go:76] trying to read 4 bytes
I0312 18:54:33.001951 47898 init_comm.go:86] read 12/12 [length = 12]
I0312 18:54:33.001957 47898 init_comm.go:76] trying to read 8 bytes
I0312 18:54:33.001961 47898 init_comm.go:86] read 8/8 [length = 0]
I0312 18:54:33.001964 47898 init_comm.go:90] data length is 8
I0312 18:54:33.001967 47898 init_comm.go:76] trying to read 8 bytes
I0312 18:54:33.001974 47898 init_comm.go:167] got cmd:14
I0312 18:54:33.001978 47898 init_comm.go:235] get command NEXT
I0312 18:54:33.001982 47898 init_comm.go:238] send 8, receive 8
I0312 18:54:33.001985 47898 init_comm.go:167] got cmd:9
I0312 18:54:33.001990 47898 init_comm.go:171] got response of shutdown command, last round of command to init
I0312 18:54:33.002006 47898 init_comm.go:190] ack got, clear pong timer
I0312 18:54:33.002012 47898 hypervisor.go:29] main event loop got message 41(COMMAND_ACK)
I0312 18:54:33.002018 47898 vm_states.go:767] [Terminating] Got reply to &{4 [] <nil>}: ''
I0312 18:54:33.002032 47898 vm_states.go:769] POD destroyed
I0312 18:54:33.005685 47898 init_comm.go:48] [console] token 3, type isd 0:0:0:0: [sda] Synchronizing SCSI cache
I0312 18:54:33.005706 47898 init_comm.go:48] [console] s 3, size is 1
I0312 18:54:33.005713 47898 init_comm.go:48] [console] container count 1
I0312 18:54:33.005718 47898 init_comm.go:48] [console] next container 13
I0312 18:54:33.005724 47898 init_comm.go:48] [console] 1 name id
I0312 18:54:33.006835 47898 init_comm.go:48] [console] container id 4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b
I0312 18:54:33.007124 47898 init_comm.go:48] [console] 3 name rootfs
I0312 18:54:33.007716 47898 init_comm.go:48] [console] container rootfs /rootfs
I0312 18:54:33.008139 47898 init_comm.go:48] [console] 5 name fstype
I0312 18:54:33.008619 47898 init_comm.go:48] [console] container fstype ext4
I0312 18:54:33.008972 47898 init_comm.go:48] [console] 7 name image
E0312 18:54:33.065855 47898 tty.go:100] read tty data failed
I0312 18:54:33.065885 47898 tty.go:161] tty socket closed, quit the reading goroutine EOF
I0312 18:54:33.065914 47898 tty.go:128] tty chan closed, quit sent goroutine
I0312 18:54:33.065925 47898 hypervisor.go:29] main event loop got message 46(ERROR_INTERRUPTED)
I0312 18:54:33.065937 47898 vm_states.go:782] Connection interrupted while terminating
E0312 18:54:33.065948 47898 init_comm.go:79] read init data failed
I0312 18:54:33.065955 47898 hypervisor.go:29] main event loop got message 46(ERROR_INTERRUPTED)
I0312 18:54:33.065963 47898 vm_states.go:782] Connection interrupted while terminating
I0312 18:54:33.065987 47898 tty.go:356] Input byte chan closed, close the output string chan
I0312 18:54:33.065995 47898 init_comm.go:50] console output end
I0312 18:54:33.215624 47898 hypervisor.go:29] main event loop got message 1(EVENT_VM_EXIT)
I0312 18:54:33.215655 47898 vm_states.go:751] Got VM shutdown event while terminating, go to cleaning up
I0312 18:54:33.215663 47898 vm_states.go:21] VM has exit...
I0312 18:54:33.215686 47898 devicemap.go:427] need umount dir qcDuQpWGlj
I0312 18:54:33.215791 47898 devicemap.go:437] need remove dm filerbd:hyper/docker_image_f3c70e73f64b069617522d646ec992c018f74b4f971fba5c0dd72baa08670913
I0312 18:54:33.215812 47898 devicemap.go:507] remove network card 0: 172.16.18.183
I0312 18:54:33.215824 47898 context.go:211] VM vm-dpfFUuCKqX: state change from TERMINATING to 'DESTROYING'
I0312 18:54:33.215869 47898 hypervisor.go:29] main event loop got message 14(EVENT_INTERFACE_DELETE)
I0312 18:54:33.215879 47898 devicemap.go:395] interface 0 released
I0312 18:54:33.215885 47898 vm_states.go:434] Unplug interface return with true
I0312 18:54:33.215902 47898 vm.go:81] Got response: 2: VM shut down
E0312 18:54:33.215913 47898 pod.go:65] VM response data is nil
I0312 18:54:33.215919 47898 pod.go:66] unlock PodList
E0312 18:54:33.215931 47898 server.go:170] Handler for POST /pod/start returned error: VM response data is nil
I0312 18:54:33.216014 47898 list.go:25] lock read of PodList
I0312 18:54:33.216027 47898 list.go:111] unlock read of PodList
I0312 18:54:33.217106 47898 hypervisor.go:29] main event loop got message 12(EVENT_BLOCK_EJECTED)
I0312 18:54:33.217145 47898 devicemap.go:404] volume etchosts-volume umounted
I0312 18:54:33.217158 47898 vm_states.go:437] Unplug block device return with true
I0312 18:54:33.225759 47898 list.go:25] lock read of PodList
I0312 18:54:33.225886 47898 list.go:41] unlock read of PodList
E0312 18:54:33.225904 47898 server.go:170] Handler for GET /list returned error: Cannot find specified vm vm-dpfFUuCKqX
I0312 18:54:33.226199 47898 list.go:25] lock read of PodList
I0312 18:54:33.226270 47898 list.go:111] unlock read of PodList
I0312 18:54:33.234549 47898 server.go:152] Calling DELETE /pod
I0312 18:54:33.234604 47898 rm.go:17] lock PodList
I0312 18:54:33.234849 47898 rm.go:21] unlock PodList
I0312 18:54:33.235012 47898 server.go:152] Calling GET /pod/info
I0312 18:54:33.235060 47898 info.go:18] lock read of PodList
I0312 18:54:33.235072 47898 info.go:29] unlock read of PodList
E0312 18:54:33.235083 47898 server.go:170] Handler for GET /pod/info returned error: Can not get Pod info with pod ID(pod-oahDJkKDMB)
I0312 18:54:33.235155 47898 server.go:152] Calling GET /list
I0312 18:54:33.235207 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [vm-dpfFUuCKqX], list auxiliary pod: false
I0312 18:54:33.235218 47898 list.go:25] lock read of PodList
I0312 18:54:33.235229 47898 list.go:41] unlock read of PodList
E0312 18:54:33.235235 47898 server.go:170] Handler for GET /list returned error: Cannot find specified vm vm-dpfFUuCKqX
I0312 18:54:33.235310 47898 server.go:152] Calling GET /pod/info
I0312 18:54:33.235372 47898 info.go:18] lock read of PodList
I0312 18:54:33.235381 47898 info.go:29] unlock read of PodList
E0312 18:54:33.235389 47898 server.go:170] Handler for GET /pod/info returned error: Can not get Pod info with pod ID(pod-oahDJkKDMB)
I0312 18:54:33.239508 47898 server.go:152] Calling GET /list
I0312 18:54:33.239556 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:33.239564 47898 list.go:25] lock read of PodList
I0312 18:54:33.239570 47898 list.go:111] unlock read of PodList
I0312 18:54:33.239655 47898 server.go:152] Calling GET /list
I0312 18:54:33.239676 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [vm-dpfFUuCKqX], list auxiliary pod: false
I0312 18:54:33.239681 47898 list.go:25] lock read of PodList
I0312 18:54:33.239687 47898 list.go:41] unlock read of PodList
E0312 18:54:33.239691 47898 server.go:170] Handler for GET /list returned error: Cannot find specified vm vm-dpfFUuCKqX
W0312 18:54:33.242444 47898 volume_linux.go:107] Cannot umount device rbd:hyper/docker_image_f3c70e73f64b069617522d646ec992c018f74b4f971fba5c0dd72baa08670913: exit status 1, Device rbd:hyper/docker_image_f3c70e73f64b069617522d646ec992c018f74b4f971fba5c0dd72baa08670913 not found
Device rbd:hyper/docker_image_f3c70e73f64b069617522d646ec992c018f74b4f971fba5c0dd72baa08670913 not found
Device rbd:hyper/docker_image_f3c70e73f64b069617522d646ec992c018f74b4f971fba5c0dd72baa08670913 not found
Command failed
I0312 18:54:33.255304 47898 hypervisor.go:29] main event loop got message 9(EVENT_VOLUME_DELETE)
I0312 18:54:33.255378 47898 devicemap.go:418] blockdev rbd:hyper/docker_image_f3c70e73f64b069617522d646ec992c018f74b4f971fba5c0dd72baa08670913 deleted
I0312 18:54:33.255397 47898 vm_states.go:440] release volume return with false
I0312 18:54:33.255404 47898 context.go:198] no more device to release/remove/umount, quit
I0312 18:54:33.255432 47898 vm_states.go:839] resources reclaimed, quit...
I0312 18:54:34.805890 47898 server.go:152] Calling GET /list
I0312 18:54:34.805988 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:34.806010 47898 list.go:25] lock read of PodList
I0312 18:54:34.806025 47898 list.go:111] unlock read of PodList
I0312 18:54:34.807096 47898 server.go:152] Calling GET /list
I0312 18:54:34.807211 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:34.807230 47898 list.go:25] lock read of PodList
I0312 18:54:34.807245 47898 list.go:111] unlock read of PodList
I0312 18:54:36.238715 47898 server.go:152] Calling GET /list
I0312 18:54:36.238774 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:36.238785 47898 list.go:25] lock read of PodList
I0312 18:54:36.238792 47898 list.go:111] unlock read of PodList
I0312 18:54:36.805533 47898 server.go:152] Calling GET /list
I0312 18:54:36.805606 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:36.805616 47898 list.go:25] lock read of PodList
I0312 18:54:36.805622 47898 list.go:111] unlock read of PodList
I0312 18:54:38.232509 47898 server.go:152] Calling GET /images/get
I0312 18:54:38.805638 47898 server.go:152] Calling GET /list
I0312 18:54:38.805741 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:38.805759 47898 list.go:25] lock read of PodList
I0312 18:54:38.805773 47898 list.go:111] unlock read of PodList
I0312 18:54:38.806330 47898 server.go:152] Calling GET /list
I0312 18:54:38.806436 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:38.806453 47898 list.go:25] lock read of PodList
I0312 18:54:38.806468 47898 list.go:111] unlock read of PodList
I0312 18:54:39.241996 47898 server.go:152] Calling GET /list
I0312 18:54:39.242063 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:39.242073 47898 list.go:25] lock read of PodList
I0312 18:54:39.242079 47898 list.go:111] unlock read of PodList
I0312 18:54:40.805280 47898 server.go:152] Calling GET /list
I0312 18:54:40.805326 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:40.805334 47898 list.go:25] lock read of PodList
I0312 18:54:40.805353 47898 list.go:111] unlock read of PodList
I0312 18:54:42.242958 47898 server.go:152] Calling GET /list
I0312 18:54:42.243021 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:42.243033 47898 list.go:25] lock read of PodList
I0312 18:54:42.243040 47898 list.go:111] unlock read of PodList
I0312 18:54:42.805792 47898 server.go:152] Calling GET /list
I0312 18:54:42.805906 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:42.805928 47898 list.go:25] lock read of PodList
I0312 18:54:42.805938 47898 list.go:111] unlock read of PodList
I0312 18:54:42.806889 47898 server.go:152] Calling GET /list
I0312 18:54:42.806987 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:42.807086 47898 list.go:25] lock read of PodList
I0312 18:54:42.807114 47898 list.go:111] unlock read of PodList
I0312 18:54:43.805910 47898 server.go:152] Calling GET /list
I0312 18:54:43.806008 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:43.806028 47898 list.go:25] lock read of PodList
I0312 18:54:43.806042 47898 list.go:111] unlock read of PodList
I0312 18:54:43.806982 47898 server.go:152] Calling GET /list
I0312 18:54:43.807114 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:43.807134 47898 list.go:25] lock read of PodList
I0312 18:54:43.807150 47898 list.go:111] unlock read of PodList
I0312 18:54:44.529264 47898 server.go:152] Calling GET /list
I0312 18:54:44.529308 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:44.529315 47898 list.go:25] lock read of PodList
I0312 18:54:44.529321 47898 list.go:111] unlock read of PodList
I0312 18:54:44.805472 47898 server.go:152] Calling GET /list
I0312 18:54:44.805587 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:44.805603 47898 list.go:25] lock read of PodList
I0312 18:54:44.805613 47898 list.go:111] unlock read of PodList
I0312 18:54:45.244585 47898 server.go:152] Calling GET /list
I0312 18:54:45.244700 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:45.244715 47898 list.go:25] lock read of PodList
I0312 18:54:45.244725 47898 list.go:111] unlock read of PodList
I0312 18:54:46.805107 47898 server.go:152] Calling GET /list
I0312 18:54:46.805175 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:46.805185 47898 list.go:25] lock read of PodList
I0312 18:54:46.805191 47898 list.go:111] unlock read of PodList
I0312 18:54:46.805680 47898 server.go:152] Calling GET /list
I0312 18:54:46.805733 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:46.805744 47898 list.go:25] lock read of PodList
I0312 18:54:46.805753 47898 list.go:111] unlock read of PodList
I0312 18:54:48.246129 47898 server.go:152] Calling GET /list
I0312 18:54:48.246176 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:48.246184 47898 list.go:25] lock read of PodList
I0312 18:54:48.246189 47898 list.go:111] unlock read of PodList
I0312 18:54:48.248110 47898 server.go:152] Calling GET /images/get
I0312 18:54:48.805712 47898 server.go:152] Calling GET /list
I0312 18:54:48.805786 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:48.805799 47898 list.go:25] lock read of PodList
I0312 18:54:48.805808 47898 list.go:111] unlock read of PodList
I0312 18:54:48.806292 47898 server.go:152] Calling GET /list
I0312 18:54:48.806371 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:48.806383 47898 list.go:25] lock read of PodList
I0312 18:54:48.806392 47898 list.go:111] unlock read of PodList
I0312 18:54:50.805232 47898 server.go:152] Calling GET /list
I0312 18:54:50.805282 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:50.805291 47898 list.go:25] lock read of PodList
I0312 18:54:50.805296 47898 list.go:111] unlock read of PodList
I0312 18:54:51.248499 47898 server.go:152] Calling GET /list
I0312 18:54:51.248574 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:51.248587 47898 list.go:25] lock read of PodList
I0312 18:54:51.248596 47898 list.go:111] unlock read of PodList
I0312 18:54:52.805441 47898 server.go:152] Calling GET /list
I0312 18:54:52.805505 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:52.805513 47898 list.go:25] lock read of PodList
I0312 18:54:52.805519 47898 list.go:111] unlock read of PodList
I0312 18:54:52.807232 47898 server.go:152] Calling GET /list
I0312 18:54:52.807279 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:52.807288 47898 list.go:25] lock read of PodList
I0312 18:54:52.807294 47898 list.go:111] unlock read of PodList
I0312 18:54:54.251017 47898 server.go:152] Calling GET /list
I0312 18:54:54.251077 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:54.251088 47898 list.go:25] lock read of PodList
I0312 18:54:54.251095 47898 list.go:111] unlock read of PodList
I0312 18:54:54.805431 47898 server.go:152] Calling GET /list
I0312 18:54:54.805481 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:54.805490 47898 list.go:25] lock read of PodList
I0312 18:54:54.805496 47898 list.go:111] unlock read of PodList
I0312 18:54:54.805900 47898 server.go:152] Calling GET /list
I0312 18:54:54.805934 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:54.805941 47898 list.go:25] lock read of PodList
I0312 18:54:54.805945 47898 list.go:111] unlock read of PodList
I0312 18:54:54.806009 47898 server.go:152] Calling GET /list
I0312 18:54:54.806029 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:54.806034 47898 list.go:25] lock read of PodList
I0312 18:54:54.806038 47898 list.go:111] unlock read of PodList
I0312 18:54:54.806470 47898 server.go:152] Calling GET /list
I0312 18:54:54.806501 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:54.806507 47898 list.go:25] lock read of PodList
I0312 18:54:54.806511 47898 list.go:111] unlock read of PodList
I0312 18:54:55.389990 47898 server.go:152] Calling POST /pod/create
I0312 18:54:55.390058 47898 pod_routes.go:76] Args string is {"containers":[{"envs":[{"env":"KUBERNETES_SERVICE_PORT","value":"443"},{"env":"KUBERNETES_SERVICE_PORT_HTTPS","value":"443"},{"env":"KUBERNETES_PORT","value":"tcp://10.254.0.1:443"},{"env":"KUBERNETES_PORT_443_TCP","value":"tcp://10.254.0.1:443"},{"env":"KUBERNETES_PORT_443_TCP_PROTO","value":"tcp"},{"env":"KUBERNETES_PORT_443_TCP_PORT","value":"443"},{"env":"KUBERNETES_PORT_443_TCP_ADDR","value":"10.254.0.1"},{"env":"KUBERNETES_SERVICE_HOST","value":"10.254.0.1"}],"image":"ubuntu","name":"kube_cbcf96a7-e840-11e5-a602-000c29ecb535_4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b_ceb308ae1be7495eb09dddc8741f717a-bridge_tender-hopper_0_6758a317","ports":null,"tty":true}],"dns":["172.16.0.2","172.16.69.2"],"hostname":"4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433","id":"4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b_ceb308ae1be7495eb09dddc8741f717a-bridge","interfaces":[{"bridge":"qbr3bbf0a2c-74","gateway":"172.16.0.1","ifname":"tap3bbf0a2c-74","ip":"172.16.18.184/16","mac":"fa:16:3e:72:15:34"}],"labels":{"extra.sh.hyper.cloud":"true","extra.sh.hyper.container.0.head":"4e2f0205e61ff42ef0f07b593e59ee5f","extra.sh.hyper.container.0.tail":"c25d19ec94d1a93c3dbc7420ef5b433b","k8s.hyper.sh/uid":"cbcf96a7-e840-11e5-a602-000c29ecb535"},"resource":{"memory":128,"vcpu":1},"services":[{"hosts":null,"protocol":"","serviceip":"127.0.0.2","serviceport":65534}],"tty":false,"volumes":[]}, autoremove false
I0312 18:54:55.390093 47898 pod.go:348] podArgs: {"containers":[{"envs":[{"env":"KUBERNETES_SERVICE_PORT","value":"443"},{"env":"KUBERNETES_SERVICE_PORT_HTTPS","value":"443"},{"env":"KUBERNETES_PORT","value":"tcp://10.254.0.1:443"},{"env":"KUBERNETES_PORT_443_TCP","value":"tcp://10.254.0.1:443"},{"env":"KUBERNETES_PORT_443_TCP_PROTO","value":"tcp"},{"env":"KUBERNETES_PORT_443_TCP_PORT","value":"443"},{"env":"KUBERNETES_PORT_443_TCP_ADDR","value":"10.254.0.1"},{"env":"KUBERNETES_SERVICE_HOST","value":"10.254.0.1"}],"image":"ubuntu","name":"kube_cbcf96a7-e840-11e5-a602-000c29ecb535_4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b_ceb308ae1be7495eb09dddc8741f717a-bridge_tender-hopper_0_6758a317","ports":null,"tty":true}],"dns":["172.16.0.2","172.16.69.2"],"hostname":"4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433","id":"4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b_ceb308ae1be7495eb09dddc8741f717a-bridge","interfaces":[{"bridge":"qbr3bbf0a2c-74","gateway":"172.16.0.1","ifname":"tap3bbf0a2c-74","ip":"172.16.18.184/16","mac":"fa:16:3e:72:15:34"}],"labels":{"extra.sh.hyper.cloud":"true","extra.sh.hyper.container.0.head":"4e2f0205e61ff42ef0f07b593e59ee5f","extra.sh.hyper.container.0.tail":"c25d19ec94d1a93c3dbc7420ef5b433b","k8s.hyper.sh/uid":"cbcf96a7-e840-11e5-a602-000c29ecb535"},"resource":{"memory":128,"vcpu":1},"services":[{"hosts":null,"protocol":"","serviceip":"127.0.0.2","serviceport":65534}],"tty":false,"volumes":[]}
I0312 18:54:55.390253 47898 pod.go:241] Process the Cloud Container section in POD SPEC
I0312 18:54:55.390886 47898 mongostore.go:75] GetMountedLayer 4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b
I0312 18:54:55.391145 47898 mounted_layer.go:71] mountedLayer Metadata 4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b f3c70e73f64b069617522d646ec992c018f74b4f971fba5c0dd72baa08670913
I0312 18:54:55.391200 47898 pod.go:361] lock PodList
I0312 18:54:55.391292 47898 pod.go:370] unlock PodList
I0312 18:54:55.391793 47898 server.go:152] Calling POST /pod/start
I0312 18:54:55.391856 47898 pod.go:50] pod:pod-QIdWeYOBoE, vm:
I0312 18:54:55.391865 47898 pod.go:53] lock PodList
I0312 18:54:55.391880 47898 vm.go:125] The config: kernel=/var/lib/hyper/kernel, initrd=/var/lib/hyper/hyper-initrd.img
I0312 18:54:55.392598 47898 libvirt.go:443] domainXML: <domain type="kvm"><name>vm-FuHKePnQzb</name><memory unit="MiB">128</memory><vcpu placement="static" current="1">1</vcpu><os supported="yes"><type arch="x86_64" machine="pc-i440fx-2.0">hvm</type><loader type="pflash" readonly="yes">/var/lib/hyper/bios-qboot.bin</loader><nvram>/var/lib/hyper/cbfs-qboot.rom</nvram></os><features><acpi></acpi></features><cpu mode="host-passthrough"></cpu><on_poweroff>destroy</on_poweroff><on_reboot>destroy</on_reboot><on_crash>destroy</on_crash><devices><emulator>/usr/bin/qemu-system-x86_64</emulator><controller type="pci" index="0" model="pci-root"></controller><controller type="virtio-serial" index="0"><address type="pci" domain="0x0000" bus="0x00" slot="0x02" function="0x00"></address></controller><controller type="scsi" index="0" model="virtio-scsi"><address type="pci" domain="0x0000" bus="0x00" slot="0x03" function="0x00"></address></controller><controller type="usb" model="none"></controller><filesystem type="mount" accessmode="squash"><driver type="path"></driver><source dir="/var/run/hyper/vm-FuHKePnQzb/share_dir"></source><target dir="share_dir"></target><address type="pci" domain="0x0000" bus="0x00" slot="0x04" function="0x00"></address></filesystem><channel type="unix"><source mode="bind" path="/var/run/hyper/vm-FuHKePnQzb/hyper.sock"></source><target type="virtio" name="sh.hyper.channel.0"></target></channel><channel type="unix"><source mode="bind" path="/var/run/hyper/vm-FuHKePnQzb/tty.sock"></source><target type="virtio" name="sh.hyper.channel.1"></target></channel><console type="unix"><source mode="bind" path="/var/run/hyper/vm-FuHKePnQzb/console.sock"></source><target type="serial" port="0"></target></console><memballoon model="virtio"><address type="pci" domain="0x0000" bus="0x00" slot="0x05" function="0x00"></address></memballoon></devices><seclabel type="none"></seclabel></domain>
I0312 18:54:55.393216 47898 mongostore.go:75] GetMountedLayer 4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b
I0312 18:54:55.393561 47898 mounted_layer.go:71] mountedLayer Metadata 4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b f3c70e73f64b069617522d646ec992c018f74b4f971fba5c0dd72baa08670913
I0312 18:54:55.393589 47898 pod.go:449] container name /tender_hopper, image ubuntu
I0312 18:54:55.393598 47898 pod.go:456] container ID: 4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b, mountId f3c70e73f64b069617522d646ec992c018f74b4f971fba5c0dd72baa08670913
I0312 18:54:55.393607 47898 pod.go:466] container info config &{4e2f0205e61f true true true map[] true true true [] 0xc8210eb800 false ubuntu map[] <nil> true [] map[] SIGTERM}, Cmd [], Args []
I0312 18:54:55.393641 47898 pod.go:485] Container Info is
&{4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b /rootfs { rbd:hyper/docker_image_f3c70e73f64b069617522d646ec992c018f74b4f971fba5c0dd72baa08670913 raw {[172.16.69.169:6789] admin AQCZxONWRaRrAxAAJI7FMiwBNQ4DujJ5WgTl/Q==}} ext4 [] [] map[KUBERNETES_SERVICE_PORT_HTTPS:443 KUBERNETES_PORT:tcp://10.254.0.1:443 KUBERNETES_PORT_443_TCP:tcp://10.254.0.1:443 KUBERNETES_PORT_443_TCP_PROTO:tcp KUBERNETES_PORT_443_TCP_PORT:443 KUBERNETES_PORT_443_TCP_ADDR:10.254.0.1 KUBERNETES_SERVICE_HOST:10.254.0.1 KUBERNETES_SERVICE_PORT:443]}
I0312 18:54:55.393709 47898 volumes.go:28] trying to bind dir /var/lib/hyper/hosts/pod-QIdWeYOBoE/hosts to /var/run/hyper/vm-FuHKePnQzb/share_dir/wmUGfGMdxA
I0312 18:54:55.394164 47898 storage.go:78] dir /var/lib/hyper/hosts/pod-QIdWeYOBoE/hosts is bound to wmUGfGMdxA
I0312 18:54:55.394180 47898 pod.go:812] configuring log driver [json-file] for pod-QIdWeYOBoE
I0312 18:54:55.394192 47898 pod.go:831] configure container log to /var/run/hyper/Pods/pod-QIdWeYOBoE/4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b-json.log
I0312 18:54:55.394257 47898 pod.go:837] configured logger for pod-QIdWeYOBoE/4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b (/tender_hopper)
I0312 18:54:55.394307 47898 vm.go:180] hyperHandlePodEvent pod pod-QIdWeYOBoE, vm vm-FuHKePnQzb
I0312 18:54:55.417730 47898 server.go:152] Calling GET /list
I0312 18:54:55.417778 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [vm-FuHKePnQzb], list auxiliary pod: false
I0312 18:54:55.506139 47898 init_comm.go:113] Wating for init messages...
I0312 18:54:55.506164 47898 init_comm.go:76] trying to read 8 bytes
I0312 18:54:55.506203 47898 init_comm.go:33] connected to /var/run/hyper/vm-FuHKePnQzb/console.sock
I0312 18:54:55.506214 47898 init_comm.go:40] connected /var/run/hyper/vm-FuHKePnQzb/console.sock as telnet mode.
I0312 18:54:55.506272 47898 tty.go:154] tty socket connected
I0312 18:54:55.506281 47898 tty.go:97] tty: trying to read 12 bytes
I0312 18:54:55.788555 47898 hypervisor.go:29] main event loop got message 38(COMMAND_ATTACH)
I0312 18:54:55.788586 47898 vm_states.go:277] attachment log-40jfwgbs is pending
I0312 18:54:55.788594 47898 hypervisor.go:29] main event loop got message 23(COMMAND_RUN_POD)
I0312 18:54:55.788602 47898 vm_states.go:547] got spec, prepare devices
I0312 18:54:55.788616 47898 context.go:243] #0 Container Info:
I0312 18:54:55.788706 47898 context.go:246]
{
...| "Id": "4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b",
...| "Rootfs": "/rootfs",
...| "Image": {
...| "name": "",
...| "source": "rbd:hyper/docker_image_f3c70e73f64b069617522d646ec992c018f74b4f971fba5c0dd72baa08670913",
...| "driver": "raw",
...| "option": {
...| "monitors": [
...| "172.16.69.169:6789"
...| ],
...| "user": "admin",
...| "keyring": "AQCZxONWRaRrAxAAJI7FMiwBNQ4DujJ5WgTl/Q=="
...| }
...| },
...| "Fstype": "ext4",
...| "Workdir": "",
...| "Entrypoint": null,
...| "Cmd": null,
...| "Envs": {
...| "KUBERNETES_PORT": "tcp://10.254.0.1:443",
...| "KUBERNETES_PORT_443_TCP": "tcp://10.254.0.1:443",
...| "KUBERNETES_PORT_443_TCP_ADDR": "10.254.0.1",
...| "KUBERNETES_PORT_443_TCP_PORT": "443",
...| "KUBERNETES_PORT_443_TCP_PROTO": "tcp",
...| "KUBERNETES_SERVICE_HOST": "10.254.0.1",
...| "KUBERNETES_SERVICE_PORT": "443",
...| "KUBERNETES_SERVICE_PORT_HTTPS": "443"
...| }
...|}
I0312 18:54:55.788736 47898 devicemap.go:245] insert volume etchosts-volume to /etc/hosts on 0
I0312 18:54:55.788817 47898 vm_states.go:59] initial vm spec: {
"hostname": "4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433",
"containers": [
{
"id": "4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b",
"rootfs": "/rootfs",
"fstype": "ext4",
"image": "",
"fsmap": [
{
"source": "wmUGfGMdxA",
"path": "/etc/hosts",
"readOnly": false
}
],
"tty": false,
"stdio": 1,
"stderr": 2,
"workdir": "/",
"cmd": null,
"envs": [
{
"env": "KUBERNETES_SERVICE_PORT",
"value": "443"
},
{
"env": "KUBERNETES_SERVICE_PORT_HTTPS",
"value": "443"
},
{
"env": "KUBERNETES_PORT",
"value": "tcp://10.254.0.1:443"
},
{
"env": "KUBERNETES_PORT_443_TCP",
"value": "tcp://10.254.0.1:443"
},
{
"env": "KUBERNETES_PORT_443_TCP_PROTO",
"value": "tcp"
},
{
"env": "KUBERNETES_PORT_443_TCP_PORT",
"value": "443"
},
{
"env": "KUBERNETES_PORT_443_TCP_ADDR",
"value": "10.254.0.1"
},
{
"env": "KUBERNETES_SERVICE_HOST",
"value": "10.254.0.1"
}
],
"restartPolicy": "never"
}
],
"dns": [
"172.16.0.2",
"172.16.69.2"
],
"shareDir": "share_dir"
}
I0312 18:54:55.788829 47898 context.go:175] found container 4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b at 0
I0312 18:54:55.788837 47898 vm_states.go:67] attach pending client log-40jfwgbs for 4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b
I0312 18:54:55.788846 47898 vm_states.go:300] Connecting tty for 4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b on session 1
I0312 18:54:55.802140 47898 libvirt.go:729] diskxml: <disk type="network" device="disk"><driver><Type>raw</Type></driver><source protocol="rbd" name="hyper/docker_image_f3c70e73f64b069617522d646ec992c018f74b4f971fba5c0dd72baa08670913"><host name="172.16.69.169" port="6789"></host></source><target dev="sda" bus="scsi"></target><address type="drive" controller="0" bus="0"></address><auth username="admin"><secret type="ceph" uuid="498ff7a5-237a-4938-9869-af978e4a50f8"></secret></auth></disk>
I0312 18:54:56.019384 47898 context.go:211] VM vm-FuHKePnQzb: state change from to 'STARTING'
I0312 18:54:56.019423 47898 hypervisor.go:29] main event loop got message 13(EVENT_INTERFACE_ADD)
I0312 18:54:56.019470 47898 libvirt.go:868] nicxml: <interface type="bridge"><mac address="fa:16:3e:72:15:34"></mac><source bridge="qbr3bbf0a2c-74"></source><target dev="tap3bbf0a2c-74"></target><model type="virtio"></model><address type="pci" domain="0x0000" bus="0x00" slot="0x6" function="0x0"></address></interface>
I0312 18:54:56.048866 47898 init_comm.go:48] [console] Initializing cgroup subsys cpu
I0312 18:54:56.055752 47898 init_comm.go:48] [console] Linux version 4.4.0-hyper+ (laijs@ubox) (gcc version 5.2.1 20151010 (Ubuntu 5.2.1-22ubuntu2) ) #0 SMP Mon Jan 25 01:10:46 CST 2016
I0312 18:54:56.059999 47898 init_comm.go:48] [console] Command line: console=ttyS0 panic=1 no_timer_check
I0312 18:54:56.060022 47898 init_comm.go:48] [console]
I0312 18:54:56.061490 47898 init_comm.go:48] [console] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256
I0312 18:54:56.074837 47898 init_comm.go:48] [console] x86/fpu: Supporting XSAVE feature 0x01: 'x87 floating point registers'
I0312 18:54:56.074853 47898 init_comm.go:48] [console] x86/fpu: Supporting XSAVE feature 0x02: 'SSE registers'
I0312 18:54:56.074857 47898 init_comm.go:48] [console] x86/fpu: Supporting XSAVE feature 0x04: 'AVX registers'
I0312 18:54:56.084628 47898 init_comm.go:48] [console] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format.
I0312 18:54:56.084646 47898 init_comm.go:48] [console] x86/fpu: Using 'eager' FPU context switches.
I0312 18:54:56.084649 47898 init_comm.go:48] [console] e820: BIOS-provided physical RAM map:
I0312 18:54:56.084652 47898 init_comm.go:48] [console] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
I0312 18:54:56.084655 47898 init_comm.go:48] [console] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
I0312 18:54:56.095446 47898 init_comm.go:48] [console] BIOS-e820: [mem 0x00000000000d0000-0x00000000000effff] ACPI NVS
I0312 18:54:56.095472 47898 init_comm.go:48] [console] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
I0312 18:54:56.095479 47898 init_comm.go:48] [console] BIOS-e820: [mem 0x0000000000100000-0x0000000007ffffff] usable
I0312 18:54:56.095485 47898 init_comm.go:48] [console] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved
I0312 18:54:56.095491 47898 init_comm.go:48] [console] NX (Execute Disable) protection: active
I0312 18:54:56.098412 47898 init_comm.go:48] [console] DMI not present or invalid.
I0312 18:54:56.098429 47898 init_comm.go:48] [console] Hypervisor detected: KVM
I0312 18:54:56.101012 47898 hypervisor.go:29] main event loop got message 10(EVENT_BLOCK_INSERTED)
I0312 18:54:56.101047 47898 hypervisor.go:29] main event loop got message 15(EVENT_INTERFACE_INSERTED)
I0312 18:54:56.101062 47898 vm_states.go:565] device ready, could run pod.
I0312 18:54:56.110301 47898 init_comm.go:48] [console] e820: last_pfn = 0x8000 max_arch_pfn = 0x400000000
I0312 18:54:56.110322 47898 init_comm.go:48] [console] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WC UC- WT
I0312 18:54:56.110325 47898 init_comm.go:48] [console] MTRR: Disabled
I0312 18:54:56.110328 47898 init_comm.go:48] [console] CPU MTRRs all blank - virtualized system.
I0312 18:54:56.110331 47898 init_comm.go:48] [console] RAMDISK: [mem 0x07f00000-0x07ffffff]
I0312 18:54:56.115660 47898 init_comm.go:48] [console] ACPI: Early table checksum verification disabled
I0312 18:54:56.118025 47898 init_comm.go:48] [console] ACPI: RSDP 0x00000000000F29A0 000014 (v00 BOCHS )
I0312 18:54:56.120104 47898 init_comm.go:48] [console] ACPI: RSDT 0x00000000000EF6C0 000034 (v01 BOCHS BXPCRSDT 00000001 BXPC 00000001)
I0312 18:54:56.125541 47898 init_comm.go:48] [console] ACPI: FACP 0x00000000000EEBDA 000074 (v01 BOCHS BXPCFACP 00000001 BXPC 00000001)
I0312 18:54:56.129214 47898 init_comm.go:48] [console] ACPI: DSDT 0x00000000000EE040 000B9A (v01 BOCHS BXPCDSDT 00000001 BXPC 00000001)
I0312 18:54:56.130515 47898 init_comm.go:48] [console] ACPI: FACS 0x00000000000EE000 000040
I0312 18:54:56.133888 47898 init_comm.go:48] [console] ACPI: SSDT 0x00000000000EEC4E 0009C2 (v01 BOCHS BXPCSSDT 00000001 BXPC 00000001)
I0312 18:54:56.137862 47898 init_comm.go:48] [console] ACPI: APIC 0x00000000000EF610 000078 (v01 BOCHS BXPCAPIC 00000001 BXPC 00000001)
I0312 18:54:56.139929 47898 init_comm.go:48] [console] ACPI: HPET 0x00000000000EF688 000038 (v01 BOCHS BXPCHPET 00000001 BXPC 00000001)
I0312 18:54:56.140322 47898 init_comm.go:48] [console] No NUMA configuration found
I0312 18:54:56.141946 47898 init_comm.go:48] [console] Faking a node at [mem 0x0000000000000000-0x0000000007ffffff]
I0312 18:54:56.143728 47898 init_comm.go:48] [console] NODE_DATA(0) allocated [mem 0x07eee000-0x07efffff]
I0312 18:54:56.145223 47898 init_comm.go:48] [console] kvm-clock: Using msrs 4b564d01 and 4b564d00
I0312 18:54:56.146906 47898 init_comm.go:48] [console] kvm-clock: cpu 0, msr 0:7eed001, primary cpu clock
I0312 18:54:56.147907 47898 init_comm.go:48] [console] kvm-clock: using sched offset of 358496697 cycles
I0312 18:54:56.149629 47898 init_comm.go:48] [console] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
I0312 18:54:56.150394 47898 init_comm.go:48] [console] Zone ranges:
I0312 18:54:56.151383 47898 init_comm.go:48] [console] DMA [mem 0x0000000000001000-0x0000000000ffffff]
I0312 18:54:56.152749 47898 init_comm.go:48] [console] DMA32 [mem 0x0000000001000000-0x0000000007ffffff]
I0312 18:54:56.153375 47898 init_comm.go:48] [console] Normal empty
I0312 18:54:56.154337 47898 init_comm.go:48] [console] Movable zone start for each node
I0312 18:54:56.155977 47898 init_comm.go:48] [console] Early memory node ranges
I0312 18:54:56.157680 47898 init_comm.go:48] [console] node 0: [mem 0x0000000000001000-0x000000000009efff]
I0312 18:54:56.160432 47898 init_comm.go:48] [console] node 0: [mem 0x0000000000100000-0x0000000007ffffff]
I0312 18:54:56.165097 47898 init_comm.go:48] [console] Initmem setup node 0 [mem 0x0000000000001000-0x0000000007ffffff]
I0312 18:54:56.165127 47898 init_comm.go:48] [console] ACPI: PM-Timer IO Port: 0x608
I0312 18:54:56.167420 47898 init_comm.go:48] [console] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
I0312 18:54:56.171247 47898 init_comm.go:48] [console] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
I0312 18:54:56.178184 47898 init_comm.go:48] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
I0312 18:54:56.179048 47898 init_comm.go:48] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
I0312 18:54:56.181762 47898 init_comm.go:48] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
I0312 18:54:56.185079 47898 init_comm.go:48] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
I0312 18:54:56.185731 47898 init_comm.go:48] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
I0312 18:54:56.187593 47898 init_comm.go:48] [console] Using ACPI (MADT) for SMP configuration information
I0312 18:54:56.189189 47898 init_comm.go:48] [console] ACPI: HPET id: 0x8086a201 base: 0xfed00000
I0312 18:54:56.190688 47898 init_comm.go:48] [console] smpboot: Allowing 1 CPUs, 0 hotplug CPUs
I0312 18:54:56.197305 47898 init_comm.go:48] [console] e820: [mem 0x08000000-0xfeffbfff] available for PCI devices
I0312 18:54:56.197326 47898 init_comm.go:48] [console] Booting paravirtualized kernel on KVM
I0312 18:54:56.201503 47898 init_comm.go:48] [console] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
I0312 18:54:56.205387 47898 init_comm.go:48] [console] setup_percpu: NR_CPUS:8 nr_cpumask_bits:8 nr_cpu_ids:1 nr_node_ids:1
I0312 18:54:56.205403 47898 init_comm.go:48] [console] PERCPU: Embedded 31 pages/cpu @ffff880007c00000 s89560 r8192 d29224 u2097152
I0312 18:54:56.209505 47898 init_comm.go:48] [console] KVM setup async PF for cpu 0
I0312 18:54:56.209541 47898 init_comm.go:48] [console] kvm-stealtime: cpu 0, msr 7c0d480
I0312 18:54:56.213558 47898 init_comm.go:48] [console] Built 1 zonelists in Node order, mobility grouping on. Total pages: 32201
I0312 18:54:56.213606 47898 init_comm.go:48] [console] Policy zone: DMA32
I0312 18:54:56.225196 47898 init_comm.go:48] [console] Kernel command line: console=ttyS0 panic=1 no_timer_check
I0312 18:54:56.225213 47898 init_comm.go:48] [console]
I0312 18:54:56.225217 47898 init_comm.go:48] [console] PID hash table entries: 512 (order: 0, 4096 bytes)
I0312 18:54:56.236028 47898 init_comm.go:48] [console] Memory: 119736K/130680K available (4225K kernel code, 452K rwdata, 1280K rodata, 860K init, 752K bss, 10944K reserved, 0K cma-reserved)
I0312 18:54:56.236046 47898 init_comm.go:48] [console] Hierarchical RCU implementation.
I0312 18:54:56.236049 47898 init_comm.go:48] [console] Build-time adjustment of leaf fanout to 64.
I0312 18:54:56.236052 47898 init_comm.go:48] [console] RCU restricting CPUs from NR_CPUS=8 to nr_cpu_ids=1.
I0312 18:54:56.236055 47898 init_comm.go:48] [console] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=1
I0312 18:54:56.236058 47898 init_comm.go:48] [console] NR_IRQS:4352 nr_irqs:256 16
I0312 18:54:56.239096 47898 init_comm.go:48] [console] Offload RCU callbacks from all CPUs
I0312 18:54:56.239113 47898 init_comm.go:48] [console] Offload RCU callbacks from CPUs: 0.
I0312 18:54:56.239116 47898 init_comm.go:48] [console] Console: colour *CGA 80x25
I0312 18:54:56.239119 47898 init_comm.go:48] [console] console [ttyS0] enabled
I0312 18:54:56.244287 47898 init_comm.go:48] [console] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns
I0312 18:54:56.244305 47898 init_comm.go:48] [console] tsc: Detected 2700.140 MHz processor
I0312 18:54:56.249076 47898 init_comm.go:48] [console] Calibrating delay loop (skipped) preset value.. 5400.28 BogoMIPS (lpj=2700140)
I0312 18:54:56.249099 47898 init_comm.go:48] [console] pid_max: default: 32768 minimum: 301
I0312 18:54:56.253903 47898 init_comm.go:48] [console] ACPI: Core revision 20150930
I0312 18:54:56.259287 47898 init_comm.go:48] [console] ACPI: 2 ACPI AML tables successfully acquired and loaded
I0312 18:54:56.259309 47898 init_comm.go:48] [console] Dentry cache hash table entries: 16384 (order: 5, 131072 bytes)
I0312 18:54:56.263763 47898 init_comm.go:48] [console] Inode-cache hash table entries: 8192 (order: 4, 65536 bytes)
I0312 18:54:56.269061 47898 init_comm.go:48] [console] Mount-cache hash table entries: 512 (order: 0, 4096 bytes)
I0312 18:54:56.269798 47898 init_comm.go:48] [console] Mountpoint-cache hash table entries: 512 (order: 0, 4096 bytes)
I0312 18:54:56.277445 47898 init_comm.go:48] [console] Last level iTLB entries: 4KB 64, 2MB 8, 4MB 8
I0312 18:54:56.277468 47898 init_comm.go:48] [console] Last level dTLB entries: 4KB 64, 2MB 0, 4MB 0, 1GB 4
I0312 18:54:56.319470 47898 init_comm.go:48] [console] Freeing SMP alternatives memory: 20K (ffffffff816ac000 - ffffffff816b1000)
I0312 18:54:56.342015 47898 init_comm.go:48] [console] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
I0312 18:54:56.346078 47898 init_comm.go:48] [console] smpboot: CPU0: Intel(R) Core(TM) i5-5257U CPU @ 2.70GHz (family: 0x6, model: 0x3d, stepping: 0x4)
I0312 18:54:56.348586 47898 init_comm.go:48] [console] Performance Events: 16-deep LBR, Broadwell events, core PMU driver.
I0312 18:54:56.350326 47898 init_comm.go:48] [console] perf_event_intel: CPUID marked event: 'cpu cycles' unavailable
I0312 18:54:56.365611 47898 init_comm.go:48] [console] perf_event_intel: CPUID marked event: 'instructions' unavailable
I0312 18:54:56.365637 47898 init_comm.go:48] [console] perf_event_intel: CPUID marked event: 'bus cycles' unavailable
I0312 18:54:56.365644 47898 init_comm.go:48] [console] perf_event_intel: CPUID marked event: 'cache references' unavailable
I0312 18:54:56.365649 47898 init_comm.go:48] [console] perf_event_intel: CPUID marked event: 'cache misses' unavailable
I0312 18:54:56.370461 47898 init_comm.go:48] [console] perf_event_intel: CPUID marked event: 'branch instructions' unavailable
I0312 18:54:56.373457 47898 init_comm.go:48] [console] perf_event_intel: CPUID marked event: 'branch misses' unavailable
I0312 18:54:56.376065 47898 init_comm.go:48] [console] ... version: 1
I0312 18:54:56.376085 47898 init_comm.go:48] [console] ... bit width: 48
I0312 18:54:56.376089 47898 init_comm.go:48] [console] ... generic registers: 4
I0312 18:54:56.386518 47898 init_comm.go:48] [console] ... value mask: 0000ffffffffffff
I0312 18:54:56.386536 47898 init_comm.go:48] [console] ... max period: 000000007fffffff
I0312 18:54:56.386540 47898 init_comm.go:48] [console] ... fixed-purpose events: 0
I0312 18:54:56.386543 47898 init_comm.go:48] [console] ... event mask: 000000000000000f
I0312 18:54:56.386546 47898 init_comm.go:48] [console] x86: Booted up 1 node, 1 CPUs
I0312 18:54:56.386549 47898 init_comm.go:48] [console] smpboot: Total of 1 processors activated (5400.28 BogoMIPS)
I0312 18:54:56.396603 47898 init_comm.go:48] [console] devtmpfs: initialized
I0312 18:54:56.396629 47898 init_comm.go:48] [console] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
I0312 18:54:56.396633 47898 init_comm.go:48] [console] NET: Registered protocol family 16
I0312 18:54:56.396636 47898 init_comm.go:48] [console] cpuidle: using governor ladder
I0312 18:54:56.396639 47898 init_comm.go:48] [console] cpuidle: using governor menu
I0312 18:54:56.396641 47898 init_comm.go:48] [console] ACPI: bus type PCI registered
I0312 18:54:56.404634 47898 init_comm.go:48] [console] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
I0312 18:54:56.404652 47898 init_comm.go:48] [console] PCI: Using configuration type 1 for base access
I0312 18:54:56.404655 47898 init_comm.go:48] [console] ACPI: Added _OSI(Module Device)
I0312 18:54:56.404658 47898 init_comm.go:48] [console] ACPI: Added _OSI(Processor Device)
I0312 18:54:56.404661 47898 init_comm.go:48] [console] ACPI: Added _OSI(3.0 _SCP Extensions)
I0312 18:54:56.404664 47898 init_comm.go:48] [console] ACPI: Added _OSI(Processor Aggregator Device)
I0312 18:54:56.416507 47898 init_comm.go:48] [console] ACPI: Interpreter enabled
I0312 18:54:56.416526 47898 init_comm.go:48] [console] ACPI: (supports S0 S5)
I0312 18:54:56.416530 47898 init_comm.go:48] [console] ACPI: Using IOAPIC for interrupt routing
I0312 18:54:56.416533 47898 init_comm.go:48] [console] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
I0312 18:54:56.427652 47898 init_comm.go:48] [console] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
I0312 18:54:56.427676 47898 init_comm.go:48] [console] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI]
I0312 18:54:56.427684 47898 init_comm.go:48] [console] acpi PNP0A03:00: _OSC failed (AE_NOT_FOUND); disabling ASPM
I0312 18:54:56.427690 47898 init_comm.go:48] [console] acpiphp: Slot [2] registered
I0312 18:54:56.427695 47898 init_comm.go:48] [console] acpiphp: Slot [3] registered
I0312 18:54:56.437535 47898 init_comm.go:48] [console] acpiphp: Slot [4] registered
I0312 18:54:56.437553 47898 init_comm.go:48] [console] acpiphp: Slot [5] registered
I0312 18:54:56.437556 47898 init_comm.go:48] [console] acpiphp: Slot [6] registered
I0312 18:54:56.437559 47898 init_comm.go:48] [console] acpiphp: Slot [7] registered
I0312 18:54:56.437562 47898 init_comm.go:48] [console] acpiphp: Slot [8] registered
I0312 18:54:56.437565 47898 init_comm.go:48] [console] acpiphp: Slot [9] registered
I0312 18:54:56.437567 47898 init_comm.go:48] [console] acpiphp: Slot [10] registered
I0312 18:54:56.437570 47898 init_comm.go:48] [console] acpiphp: Slot [11] registered
I0312 18:54:56.437573 47898 init_comm.go:48] [console] acpiphp: Slot [12] registered
I0312 18:54:56.441621 47898 init_comm.go:48] [console] acpiphp: Slot [13] registered
I0312 18:54:56.441640 47898 init_comm.go:48] [console] acpiphp: Slot [14] registered
I0312 18:54:56.452785 47898 init_comm.go:48] [console] acpiphp: Slot [15] registered
I0312 18:54:56.452820 47898 init_comm.go:48] [console] acpiphp: Slot [16] registered
I0312 18:54:56.452830 47898 init_comm.go:48] [console] acpiphp: Slot [17] registered
I0312 18:54:56.452836 47898 init_comm.go:48] [console] acpiphp: Slot [18] registered
I0312 18:54:56.452842 47898 init_comm.go:48] [console] acpiphp: Slot [19] registered
I0312 18:54:56.452847 47898 init_comm.go:48] [console] acpiphp: Slot [20] registered
I0312 18:54:56.452852 47898 init_comm.go:48] [console] acpiphp: Slot [21] registered
I0312 18:54:56.452857 47898 init_comm.go:48] [console] acpiphp: Slot [22] registered
I0312 18:54:56.464046 47898 init_comm.go:48] [console] acpiphp: Slot [23] registered
I0312 18:54:56.464752 47898 init_comm.go:48] [console] acpiphp: Slot [24] registered
I0312 18:54:56.465891 47898 init_comm.go:48] [console] acpiphp: Slot [25] registered
I0312 18:54:56.466800 47898 init_comm.go:48] [console] acpiphp: Slot [26] registered
I0312 18:54:56.467881 47898 init_comm.go:48] [console] acpiphp: Slot [27] registered
I0312 18:54:56.469160 47898 init_comm.go:48] [console] acpiphp: Slot [28] registered
I0312 18:54:56.470588 47898 init_comm.go:48] [console] acpiphp: Slot [29] registered
I0312 18:54:56.472321 47898 init_comm.go:48] [console] acpiphp: Slot [30] registered
I0312 18:54:56.478453 47898 init_comm.go:48] [console] acpiphp: Slot [31] registered
I0312 18:54:56.478475 47898 init_comm.go:48] [console] PCI host bridge to bus 0000:00
I0312 18:54:56.481564 47898 init_comm.go:48] [console] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window]
I0312 18:54:56.481587 47898 init_comm.go:48] [console] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window]
I0312 18:54:56.484714 47898 init_comm.go:48] [console] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
I0312 18:54:56.484733 47898 init_comm.go:48] [console] pci_bus 0000:00: root bus resource [mem 0x08000000-0xfebfffff window]
I0312 18:54:56.489461 47898 init_comm.go:48] [console] pci_bus 0000:00: root bus resource [bus 00-ff]
I0312 18:54:56.493466 47898 init_comm.go:48] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7]
I0312 18:54:56.497481 47898 init_comm.go:48] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6]
I0312 18:54:56.501461 47898 init_comm.go:48] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177]
I0312 18:54:56.503577 47898 init_comm.go:48] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376]
I0312 18:54:56.510771 47898 init_comm.go:48] [console] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI
I0312 18:54:56.513658 47898 init_comm.go:48] [console] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB
I0312 18:54:56.527153 47898 init_comm.go:48] [console] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11)
I0312 18:54:56.529143 47898 init_comm.go:48] [console] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 *10 11)
I0312 18:54:56.532678 47898 init_comm.go:48] [console] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 10 *11)
I0312 18:54:56.536727 47898 init_comm.go:48] [console] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 10 *11)
I0312 18:54:56.545486 47898 init_comm.go:48] [console] ACPI: PCI Interrupt Link [LNKS] (IRQs *9)
I0312 18:54:56.545510 47898 init_comm.go:48] [console] ACPI: Enabled 16 GPEs in block 00 to 0F
I0312 18:54:56.545517 47898 init_comm.go:48] [console] vgaarb: loaded
I0312 18:54:56.545523 47898 init_comm.go:48] [console] SCSI subsystem initialized
I0312 18:54:56.545528 47898 init_comm.go:48] [console] dmi: Firmware registration failed.
I0312 18:54:56.553472 47898 init_comm.go:48] [console] PCI: Using ACPI for IRQ routing
I0312 18:54:56.553497 47898 init_comm.go:48] [console] clocksource: Switched to clocksource kvm-clock
I0312 18:54:56.553504 47898 init_comm.go:48] [console] pnp: PnP ACPI init
I0312 18:54:56.565480 47898 init_comm.go:48] [console] pnp: PnP ACPI: found 5 devices
I0312 18:54:56.576404 47898 init_comm.go:48] [console] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
I0312 18:54:56.576430 47898 init_comm.go:48] [console] pci 0000:00:06.0: BAR 6: assigned [mem 0x08000000-0x0803ffff pref]
I0312 18:54:56.576434 47898 init_comm.go:48] [console] pci 0000:00:02.0: BAR 1: assigned [mem 0x08040000-0x08040fff]
I0312 18:54:56.576437 47898 init_comm.go:48] [console] pci 0000:00:03.0: BAR 1: assigned [mem 0x08041000-0x08041fff]
I0312 18:54:56.576440 47898 init_comm.go:48] [console] pci 0000:00:04.0: BAR 1: assigned [mem 0x08042000-0x08042fff]
I0312 18:54:56.587968 47898 init_comm.go:48] [console] pci 0000:00:06.0: BAR 1: assigned [mem 0x08043000-0x08043fff]
I0312 18:54:56.587996 47898 init_comm.go:48] [console] pci 0000:00:03.0: BAR 0: assigned [io 0x1000-0x103f]
I0312 18:54:56.588003 47898 init_comm.go:48] [console] pci 0000:00:04.0: BAR 0: assigned [io 0x1040-0x107f]
I0312 18:54:56.588009 47898 init_comm.go:48] [console] pci 0000:00:02.0: BAR 0: assigned [io 0x1080-0x109f]
I0312 18:54:56.588015 47898 init_comm.go:48] [console] pci 0000:00:05.0: BAR 0: assigned [io 0x10a0-0x10bf]
I0312 18:54:56.600354 47898 init_comm.go:48] [console] pci 0000:00:06.0: BAR 0: assigned [io 0x10c0-0x10df]
I0312 18:54:56.600386 47898 init_comm.go:48] [console] pci 0000:00:01.1: BAR 4: assigned [io 0x10e0-0x10ef]
I0312 18:54:56.600395 47898 init_comm.go:48] [console] NET: Registered protocol family 2
I0312 18:54:56.600402 47898 init_comm.go:48] [console] TCP established hash table entries: 1024 (order: 1, 8192 bytes)
I0312 18:54:56.612207 47898 init_comm.go:48] [console] TCP bind hash table entries: 1024 (order: 2, 16384 bytes)
I0312 18:54:56.612239 47898 init_comm.go:48] [console] TCP: Hash tables configured (established 1024 bind 1024)
I0312 18:54:56.612249 47898 init_comm.go:48] [console] UDP hash table entries: 256 (order: 1, 8192 bytes)
I0312 18:54:56.612255 47898 init_comm.go:48] [console] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes)
I0312 18:54:56.624457 47898 init_comm.go:48] [console] NET: Registered protocol family 1
I0312 18:54:56.624482 47898 init_comm.go:48] [console] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
I0312 18:54:56.624489 47898 init_comm.go:48] [console] pci 0000:00:01.0: PIIX3: Enabling Passive Release
I0312 18:54:56.624495 47898 init_comm.go:48] [console] pci 0000:00:01.0: Activating ISA DMA hang workarounds
I0312 18:54:56.635929 47898 init_comm.go:48] [console] Trying to unpack rootfs image as initramfs...
I0312 18:54:56.657526 47898 init_comm.go:48] [console] Freeing initrd memory: 1024K (ffff880007f00000 - ffff880008000000)
I0312 18:54:56.657548 47898 init_comm.go:48] [console] futex hash table entries: 256 (order: 2, 16384 bytes)
I0312 18:54:56.657556 47898 init_comm.go:48] [console] SGI XFS with ACLs, security attributes, no debug enabled
I0312 18:54:56.669025 47898 init_comm.go:48] [console] 9p: Installing v9fs 9p2000 file system support
I0312 18:54:56.669049 47898 init_comm.go:48] [console] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 254)
I0312 18:54:56.669056 47898 init_comm.go:48] [console] io scheduler noop registered
I0312 18:54:56.669061 47898 init_comm.go:48] [console] io scheduler cfq registered (default)
I0312 18:54:56.680537 47898 init_comm.go:48] [console] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
I0312 18:54:56.680558 47898 init_comm.go:48] [console] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
I0312 18:54:56.680561 47898 init_comm.go:48] [console] Warning: Processor Platform Limit event detected, but not handled.
I0312 18:54:56.680564 47898 init_comm.go:48] [console] Consider compiling CPUfreq support into your kernel.
I0312 18:54:56.705457 47898 init_comm.go:48] [console] ACPI: PCI Interrupt Link [LNKB] enabled at IRQ 10
I0312 18:54:56.705476 47898 init_comm.go:48] [console] virtio-pci 0000:00:02.0: enabling device (0000 -> 0003)
I0312 18:54:56.716745 47898 init_comm.go:48] [console] virtio-pci 0000:00:02.0: virtio_pci: leaving for legacy driver
I0312 18:54:56.743332 47898 init_comm.go:48] [console] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 11
I0312 18:54:56.743903 47898 init_comm.go:48] [console] virtio-pci 0000:00:03.0: enabling device (0000 -> 0003)
I0312 18:54:56.753462 47898 init_comm.go:48] [console] virtio-pci 0000:00:03.0: virtio_pci: leaving for legacy driver
I0312 18:54:56.781282 47898 init_comm.go:48] [console] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 11
I0312 18:54:56.783232 47898 init_comm.go:48] [console] virtio-pci 0000:00:04.0: enabling device (0000 -> 0003)
I0312 18:54:56.794075 47898 init_comm.go:48] [console] virtio-pci 0000:00:04.0: virtio_pci: leaving for legacy driver
I0312 18:54:56.800499 47898 server.go:152] Calling GET /list
I0312 18:54:56.800584 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:56.808707 47898 server.go:152] Calling GET /list
I0312 18:54:56.808776 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:56.820751 47898 init_comm.go:48] [console] ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 10
I0312 18:54:56.822423 47898 init_comm.go:48] [console] virtio-pci 0000:00:05.0: enabling device (0000 -> 0001)
I0312 18:54:56.824829 47898 init_comm.go:48] [console] virtio-pci 0000:00:05.0: virtio_pci: leaving for legacy driver
I0312 18:54:56.848070 47898 init_comm.go:48] [console] virtio-pci 0000:00:06.0: enabling device (0000 -> 0003)
I0312 18:54:56.852844 47898 init_comm.go:48] [console] virtio-pci 0000:00:06.0: virtio_pci: leaving for legacy driver
I0312 18:54:56.857441 47898 init_comm.go:48] [console] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
I0312 18:54:56.888904 47898 init_comm.go:48] [console] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
I0312 18:54:56.927287 47898 init_comm.go:48] [console] brd: module loaded
I0312 18:54:56.928062 47898 init_comm.go:48] [console] loop: module loaded
I0312 18:54:56.945726 47898 server.go:152] Calling GET /list
I0312 18:54:56.945782 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [vm-FuHKePnQzb], list auxiliary pod: false
I0312 18:54:56.955284 47898 init_comm.go:48] [console] scsi host0: Virtio SCSI HBA
I0312 18:54:56.962601 47898 init_comm.go:48] [console] scsi 0:0:0:0: Direct-Access QEMU QEMU HARDDISK 2.4. PQ: 0 ANSI: 5
I0312 18:54:56.995129 47898 init_comm.go:48] [console] sd 0:0:0:0: Attached scsi generic sg0 type 0
I0312 18:54:57.022063 47898 init_comm.go:48] [console] e1000: Intel(R) PRO/1000 Network Driver - version 7.3.21-k8-NAPI
I0312 18:54:57.024492 47898 init_comm.go:48] [console] e1000: Copyright (c) 1999-2006 Intel Corporation.
I0312 18:54:57.026390 47898 init_comm.go:48] [console] NET: Registered protocol family 10
I0312 18:54:57.028796 47898 init_comm.go:48] [console] NET: Registered protocol family 17
I0312 18:54:57.030507 47898 init_comm.go:48] [console] 9pnet: Installing 9P2000 support
I0312 18:54:57.055489 47898 init_comm.go:48] [console] registered taskstats version 1
I0312 18:54:57.062638 47898 init_comm.go:48] [console] sd 0:0:0:0: [sda] 20971520 512-byte logical blocks: (10.7 GB/10.0 GiB)
I0312 18:54:57.062660 47898 init_comm.go:48] [console] sd 0:0:0:0: [sda] Write Protect is off
I0312 18:54:57.063224 47898 init_comm.go:48] [console] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
I0312 18:54:57.071554 47898 init_comm.go:48] [console] sd 0:0:0:0: [sda] Attached SCSI disk
I0312 18:54:57.071575 47898 init_comm.go:48] [console] Freeing unused kernel memory: 860K (ffffffff815d5000 - ffffffff816ac000)
I0312 18:54:57.072315 47898 init_comm.go:48] [console] create directory /dev
I0312 18:54:57.073287 47898 init_comm.go:48] [console] create directory /sys
I0312 18:54:57.074123 47898 init_comm.go:48] [console] create directory /proc
I0312 18:54:57.074787 47898 init_comm.go:48] [console] uptime 0.63 0.00
I0312 18:54:57.075127 47898 init_comm.go:48] [console]
I0312 18:54:57.076172 47898 init_comm.go:48] [console] create directory /dev/pts
I0312 18:54:57.077683 47898 init_comm.go:48] [console] create directory /dev
I0312 18:54:57.077984 47898 init_comm.go:48] [console] open hyper channel /dev/vport0p1
I0312 18:54:57.079511 47898 init_comm.go:48] [console] send ready message
I0312 18:54:57.080212 47898 init_comm.go:48] [console] hyper send type 8, len 0
I0312 18:54:57.081631 47898 init_comm.go:86] read 8/8 [length = 0]
I0312 18:54:57.081651 47898 init_comm.go:90] data length is 8
I0312 18:54:57.081657 47898 init_comm.go:123] Get init ready message
I0312 18:54:57.081682 47898 init_comm.go:167] got cmd:1
I0312 18:54:57.081707 47898 init_comm.go:248] send command 1 to init, payload: '{"hostname":"4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433","containers":[{"id":"4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b","rootfs":"/rootfs","fstype":"ext4","image":"sda","addr":"0:0","fsmap":[{"source":"wmUGfGMdxA","path":"/etc/hosts","readOnly":false}],"tty":false,"stdio":1,"stderr":2,"workdir":"/","cmd":null,"envs":[{"env":"KUBERNETES_SERVICE_PORT","value":"443"},{"env":"KUBERNETES_SERVICE_PORT_HTTPS","value":"443"},{"env":"KUBERNETES_PORT","value":"tcp://10.254.0.1:443"},{"env":"KUBERNETES_PORT_443_TCP","value":"tcp://10.254.0.1:443"},{"env":"KUBERNETES_PORT_443_TCP_PROTO","value":"tcp"},{"env":"KUBERNETES_PORT_443_TCP_PORT","value":"443"},{"env":"KUBERNETES_PORT_443_TCP_ADDR","value":"10.254.0.1"},{"env":"KUBERNETES_SERVICE_HOST","value":"10.254.0.1"}],"restartPolicy":"never"}],"interfaces":[{"device":"lo","ipAddress":"127.0.0.2","netMask":"255.255.255.255"},{"device":"eth0","ipAddress":"172.16.18.184","netMask":"255.255.0.0"}],"dns":["172.16.0.2","172.16.69.2"],"routes":[{"dest":"0.0.0.0/0","gateway":"172.16.0.1","device":"eth0"}],"shareDir":"share_dir"}'.
I0312 18:54:57.081732 47898 init_comm.go:261] write 512 to init, payload: 'g{"hostname":"4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433","containers":[{"id":"4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b","rootfs":"/rootfs","fstype":"ext4","image":"sda","addr":"0:0","fsmap":[{"source":"wmUGfGMdxA","path":"/etc/hosts","readOnly":false}],"tty":false,"stdio":1,"stderr":2,"workdir":"/","cmd":null,"envs":[{"env":"KUBERNETES_SERVICE_PORT","value":"443"},{"env":"KUBERNETES_SERVICE_PORT_HTTPS","value":"443"},{"env":"KUBERNETES_PORT","value":"tcp:'.
I0312 18:54:57.081761 47898 init_comm.go:266] message sent, set pong timer
I0312 18:54:57.081771 47898 init_comm.go:76] trying to read 8 bytes
I0312 18:54:57.081778 47898 hypervisor.go:29] main event loop got message 5(EVENT_INIT_CONNECTED)
I0312 18:54:57.081783 47898 vm_states.go:579] begin to wait vm commands
I0312 18:54:57.081796 47898 vm.go:267] Get the response from VM, VM id is vm-FuHKePnQzb!
I0312 18:54:57.083036 47898 init_comm.go:48] [console] channel sh.hyper.channel.1, directory sh.hyper.channel.0
I0312 18:54:57.083055 47898 init_comm.go:48] [console]
I0312 18:54:57.083433 47898 init_comm.go:48] [console] open hyper channel /dev/vport0p2
I0312 18:54:57.090983 47898 init_comm.go:86] read 8/8 [length = 0]
I0312 18:54:57.091004 47898 init_comm.go:90] data length is 12
I0312 18:54:57.091008 47898 init_comm.go:76] trying to read 4 bytes
I0312 18:54:57.091013 47898 init_comm.go:86] read 12/12 [length = 12]
I0312 18:54:57.091019 47898 init_comm.go:76] trying to read 8 bytes
I0312 18:54:57.091023 47898 init_comm.go:86] read 8/8 [length = 0]
I0312 18:54:57.091026 47898 init_comm.go:90] data length is 12
I0312 18:54:57.091028 47898 init_comm.go:76] trying to read 4 bytes
I0312 18:54:57.091027 47898 init_comm.go:48] [console] hyper_init_event hyper channel event 0x612500, ops 0x612340, fd 3
I0312 18:54:57.091037 47898 init_comm.go:167] got cmd:14
I0312 18:54:57.091041 47898 init_comm.go:48] [console] hyper_add_event add event fd 3, 0x612340
I0312 18:54:57.091043 47898 init_comm.go:235] get command NEXT
I0312 18:54:57.091045 47898 init_comm.go:48] [console] hyper_init_event hyper ttyfd event 0x6124c8, ops 0x612300, fd 4
I0312 18:54:57.091055 47898 init_comm.go:48] [console] hyper_add_event add event fd 4, 0x612300
I0312 18:54:57.091058 47898 init_comm.go:48] [console] hyper_loop epoll_wait 1
I0312 18:54:57.091047 47898 init_comm.go:238] send 512, receive 8
I0312 18:54:57.091032 47898 init_comm.go:86] read 12/12 [length = 12]
I0312 18:54:57.091066 47898 init_comm.go:76] trying to read 8 bytes
I0312 18:54:57.091072 47898 init_comm.go:167] got cmd:14
I0312 18:54:57.091076 47898 init_comm.go:235] get command NEXT
I0312 18:54:57.091079 47898 init_comm.go:238] send 512, receive 512
I0312 18:54:57.091086 47898 init_comm.go:261] write 512 to init, payload: '//10.254.0.1:443"},{"env":"KUBERNETES_PORT_443_TCP","value":"tcp://10.254.0.1:443"},{"env":"KUBERNETES_PORT_443_TCP_PROTO","value":"tcp"},{"env":"KUBERNETES_PORT_443_TCP_PORT","value":"443"},{"env":"KUBERNETES_PORT_443_TCP_ADDR","value":"10.254.0.1"},{"env":"KUBERNETES_SERVICE_HOST","value":"10.254.0.1"}],"restartPolicy":"never"}],"interfaces":[{"device":"lo","ipAddress":"127.0.0.2","netMask":"255.255.255.255"},{"device":"eth0","ipAddress":"172.16.18.184","netMask":"255.255.0.0"}],"dns":["172.16.0.2","172.1'.
I0312 18:54:57.095994 47898 init_comm.go:48] [console] hyper_handle_event get event 1, de 0x612500, fd 3. ops 0x612340
I0312 18:54:57.096013 47898 init_comm.go:48] [console] hyper_handle_event event EPOLLIN, de 0x612500, fd 3, 0x612340
I0312 18:54:57.096016 47898 init_comm.go:48] [console] hyper_event_read
I0312 18:54:57.096019 47898 init_comm.go:48] [console] already read 8 bytes data
I0312 18:54:57.096022 47898 init_comm.go:48] [console] hyper send type 14, len 4
I0312 18:54:57.096025 47898 init_comm.go:48] [console] get length 1127
I0312 18:54:57.096027 47898 init_comm.go:48] [console] read 504 bytes data, total data 512
I0312 18:54:57.096030 47898 init_comm.go:48] [console] hyper send type 14, len 4
I0312 18:54:57.096033 47898 init_comm.go:48] [console] hyper_loop epoll_wait 1
I0312 18:54:57.096040 47898 init_comm.go:86] read 8/8 [length = 0]
I0312 18:54:57.096046 47898 init_comm.go:90] data length is 12
I0312 18:54:57.096048 47898 init_comm.go:76] trying to read 4 bytes
I0312 18:54:57.096053 47898 init_comm.go:86] read 12/12 [length = 12]
I0312 18:54:57.096062 47898 init_comm.go:76] trying to read 8 bytes
I0312 18:54:57.096067 47898 init_comm.go:167] got cmd:14
I0312 18:54:57.096072 47898 init_comm.go:235] get command NEXT
I0312 18:54:57.096075 47898 init_comm.go:238] send 512, receive 512
I0312 18:54:57.096082 47898 init_comm.go:261] write 103 to init, payload: '6.69.2"],"routes":[{"dest":"0.0.0.0/0","gateway":"172.16.0.1","device":"eth0"}],"shareDir":"share_dir"}'.
I0312 18:54:57.098545 47898 init_comm.go:48] [console] hyper_handle_event get event 1, de 0x612500, fd 3. ops 0x612340
I0312 18:54:57.098562 47898 init_comm.go:48] [console] hyper_handle_event event EPOLLIN, de 0x612500, fd 3, 0x612340
I0312 18:54:57.098566 47898 init_comm.go:48] [console] hyper_event_read
I0312 18:54:57.098569 47898 init_comm.go:48] [console] get length 1127
I0312 18:54:57.099170 47898 init_comm.go:48] [console] read 512 bytes data, total data 1024
I0312 18:54:57.099700 47898 init_comm.go:48] [console] hyper send type 14, len 4
I0312 18:54:57.100793 47898 init_comm.go:48] [console] hyper_loop epoll_wait 1
I0312 18:54:57.102106 47898 init_comm.go:48] [console] hyper_handle_event get event 1, de 0x612500, fd 3. ops 0x612340
I0312 18:54:57.107732 47898 init_comm.go:48] [console] hyper_handle_event event EPOLLIN, de 0x612500, fd 3, 0x612340
I0312 18:54:57.107759 47898 init_comm.go:48] [console] hyper_event_read
I0312 18:54:57.107767 47898 init_comm.go:48] [console] get length 1127
I0312 18:54:57.107773 47898 init_comm.go:48] [console] read 103 bytes data, total data 1127
I0312 18:54:57.110751 47898 init_comm.go:48] [console] hyper send type 14, len 4
I0312 18:54:57.115803 47898 init_comm.go:86] read 8/8 [length = 0]
I0312 18:54:57.115824 47898 init_comm.go:90] data length is 12
I0312 18:54:57.115833 47898 init_comm.go:76] trying to read 4 bytes
I0312 18:54:57.115839 47898 init_comm.go:86] read 12/12 [length = 12]
I0312 18:54:57.115846 47898 init_comm.go:76] trying to read 8 bytes
I0312 18:54:57.115851 47898 init_comm.go:167] got cmd:14
I0312 18:54:57.115856 47898 init_comm.go:235] get command NEXT
I0312 18:54:57.115859 47898 init_comm.go:238] send 103, receive 103
I0312 18:54:57.195362 47898 init_comm.go:48] [console] 0 0 0 1 0 0 4 67 7b 22 68 6f 73 74 6e 61 6d 65 22 3a 22 34 65 32 66 30 32 30 35 65 36 31 66 66 34 32 65 66 30 66 30 37 62 35 39 33 65 35 39 65 65 35 66 63 32 35 64 31 39 65 63 39 34 64 31 61 39 33 63 33 64 62 63 37 34 32 30 65 66 35 62 34 33 33 22 2c 22 63 6f 6e 74 61 69 6e 65 72 73 22 3a 5b 7b 22 69 64 22 3a 22 34 65 32 66 30 32 30 35 65 36 31 66 66 34 32 65 66 30 66 30 37 62 35 39 33 65 35 39 65 65 35 66 63 32 35 64 31 39 65 63 39 34 64 31 61 39 33 63 33 64 62 63 37 34 32 30 65 66 35 62 34 33 33 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 65 78 74 34 22 2c 22 69 6d 61 67 65 22 3a 22 73 64 61 22 2c 22 61 64 64 72 22 3a 22 30 3a 30 22 2c 22 66 73 6d 61 70 22 3a 5b 7b 22 73 6f 75 72 63 65 22 3a 22 77 6d 55 47 66 47 4d 64 78 41 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 7d 5d 2c 22 74 74 79 22 3a 66 61 6c 73 65 2c 22 73 74 64 69 6f 22 3a 31 2c 22 73 74 64 65 72 72 22 3a 32 2c 22 77 6f 72 6b 64 69 72 22 3a 22 2f 22 2c 22 63 6d 64 22 3a 6e 75 6c 6c 2c 22 65 6e 76 73 22 3a 5b 7b 22 65 6e 76 22 3a 22 4b 55 42 45 52 4e 45 54 45 53 5f 53 45 52 56 49 43 45 5f 50 4f 52 54 22 2c 22 76 61 6c 75 65 22 3a 22 34 34 33 22 7d 2c 7b 22 65 6e 76 22 3a 22 4b 55 42 45 52 4e 45 54 45 53 5f 53 45 52 56 49 43 45 5f 50 4f 52 54 5f 48 54 54 50 53 22 2c 22 76 61 6c 75 65 22 3a 22 34 34 33 22 7d 2c 7b 22 65 6e 76 22 3a 22 4b 55 42 45 52 4e 45 54 45 53 5f 50 4f 52 54 22 2c 22 76 61 6c 75 65 22 3a 22 74 63 70 3a 2f 2f 31 30 2e 32 35 34 2e 30 2e 31 3a 34 34 33 22 7d 2c 7b 22 65 6e 76 22 3a 22 4b 55 42 45 52 4e 45 54 45 53 5f 50 4f 52 54 5f 34 34 33 5f 54 43 50 22 2c 22 76 61 6c 75 65 22 3a 22 74 63 70 3a 2f 2f 31 30 2e 32 35 34 2e 30 2e 31 3a 34 34 33 22 7d 2c 7b 22 65 6e 76 22 3a 22 4b 55 42 45 52 4e 45 54 45 53 5f 50 4f 52 54 5f 34 34 33 5f 54 43 50 5f 50 52 4f 54 4f 22 2c 22 76 61 6c 75 65 22 3a 22 74 63 70 22 7d 2c 7b 22 65 6e 76 22 3a 22 4b 55 42 45 52 4e 45 54 45 53 5f 50 4f 52 54 5f 34 34 33 5f 54 43 50 5f 50 4f 52 54 22 2c 22 76 61 6c 75 65 22 3a 22 34 34 33 22 7d 2c 7b 22 65 6e 76 22 3a 22 4b 55 42 45 52 4e 45 54 45 53 5f 50 4f 52 54 5f 34 34 33 5f 54 43 50 5f 41 44 44 52 22 2c 22 76 61 6c 75 65 22 3a 22 31 30 2e 32 35 34 2e 30 2e 31 22 7d 2c 7b 22 65 6e 76 22 3a 22 4b 55 42 45 52 4e 45 54 45 53 5f 53 45 52 56 49 43 45 5f 48 4f 53 54 22 2c 22 76 61 6c 75 65 22 3a 22 31 30 2e 32 35 34 2e 30 2e 31 22 7d 5d 2c 22 72 65 73 74 61 72 74 50 6f 6c 69 63 79 22 3a 22 6e 65 76 65 72 22 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 6c 6f 22 2c 22 69 70 41 64 64 72 65 73 73 22 3a 22 31 32 37 2e 30 2e 30 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 32 35 35 22 7d 2c 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 37 32 2e 31 36 2e 31 38 2e 31 38 34 22 2c 22 6e 65 74 4d 61 73 6b 22 3a 22 32 35 35 2e 32 35 35 2e 30 2e 30 22 7d 5d 2c 22 64 6e 73 22 3a 5b 22 31 37 32 2e 31 36 2e 30 2e 32 22 2c 22 31 37 32 2e 31 36 2e 36 39 2e 32 22 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 37 32 2e 31 36 2e 30 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
I0312 18:54:57.195390 47898 init_comm.go:48] [console] hyper_channel_handle, type 1, len 1127
I0312 18:54:57.220610 47898 init_comm.go:48] [console] call hyper_start_pod, json {"hostname":"4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433","containers":[{"id":"4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b","rootfs":"/rootfs","fstype":"ext4","image":"sda","addr":"0:0","fsmap":[{"source":"wmUGfGMdxA","path":"/etc/hosts","readOnly":false}],"tty":false,"stdio":1,"stderr":2,"workdir":"/","cmd":null,"envs":[{"env":"KUBERNETES_SERVICE_PORT","value":"443"},{"env":"KUBERNETES_SERVICE_PORT_HTTPS","value":"443"},{"env":"KUBERNETES_PORT","value":"tcp://10.254.0.1:443"},{"env":"KUBERNETES_PORT_443_TCP","value":"tcp://10.254.0.1:443"},{"env":"KUBERNETES_PORT_443_TCP_PROTO","value":"tcp"},{"env":"KUBERNETES_PORT_443_TCP_PORT","value":"443"},{"env":"KUBERNETES_PORT_443_TCP_ADDR","value":"10.254.0.1"},{"env":"KUBERNETES_SERVICE_HOST","value":"10.254.0.1"}],"restartPolicy":"never"}],"interfaces":[{"device":"lo","ipAddress":"127.0.0.2","netMask":"255.255.255.255"},{"device":"eth0","ipAddress":"172.16.18.184","netMask":"255.255.0.0"}],"dns":["172.16.0.2","172.16.69.2"],"routes":[{"dest":"0.0.0.0/0","gateway":"172.16.0.1","device":"eth0"}],"shareDir":"share_dir"}, len 1119
I0312 18:54:57.244974 47898 init_comm.go:48] [console] call hyper_start_pod, json {"hostname":"4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433","containers":[{"id":"4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b","rootfs":"/rootfs","fstype":"ext4","image":"sda","addr":"0:0","fsmap":[{"source":"wmUGfGMdxA","path":"/etc/hosts","readOnly":false}],"tty":false,"stdio":1,"stderr":2,"workdir":"/","cmd":null,"envs":[{"env":"KUBERNETES_SERVICE_PORT","value":"443"},{"env":"KUBERNETES_SERVICE_PORT_HTTPS","value":"443"},{"env":"KUBERNETES_PORT","value":"tcp://10.254.0.1:443"},{"env":"KUBERNETES_PORT_443_TCP","value":"tcp://10.254.0.1:443"},{"env":"KUBERNETES_PORT_443_TCP_PROTO","value":"tcp"},{"env":"KUBERNETES_PORT_443_TCP_PORT","value":"443"},{"env":"KUBERNETES_PORT_443_TCP_ADDR","value":"10.254.0.1"},{"env":"KUBERNETES_SERVICE_HOST","value":"10.254.0.1"}],"restartPolicy":"never"}],"interfaces":[{"device":"lo","ipAddress":"127.0.0.2","netMask":"255.255.255.255"},{"device":"eth0","ipAddress":"172.16.18.184","netMask":"255.255.0.0"}],"dns":["172.16.0.2","172.16.69.2"],"routes":[{"dest":"0.0.0.0/0","gateway":"172.16.0.1","device":"eth0"}],"shareDir":"share_dir"}, len 1119
I0312 18:54:57.245738 47898 init_comm.go:48] [console] jsmn parse failed, n is -1
I0312 18:54:57.257718 47898 server.go:152] Calling GET /list
I0312 18:54:57.257794 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:57.278364 47898 init_comm.go:48] [console] call hyper_start_pod, json {"hostname":"4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433","containers":[{"id":"4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b","rootfs":"/rootfs","fstype":"ext4","image":"sda","addr":"0:0","fsmap":[{"source":"wmUGfGMdxA","path":"/etc/hosts","readOnly":false}],"tty":false,"stdio":1,"stderr":2,"workdir":"/","cmd":null,"envs":[{"env":"KUBERNETES_SERVICE_PORT","value":"443"},{"env":"KUBERNETES_SERVICE_PORT_HTTPS","value":"443"},{"env":"KUBERNETES_PORT","value":"tcp://10.254.0.1:443"},{"env":"KUBERNETES_PORT_443_TCP","value":"tcp://10.254.0.1:443"},{"env":"KUBERNETES_PORT_443_TCP_PROTO","value":"tcp"},{"env":"KUBERNETES_PORT_443_TCP_PORT","value":"443"},{"env":"KUBERNETES_PORT_443_TCP_ADDR","value":"10.254.0.1"},{"env":"KUBERNETES_SERVICE_HOST","value":"10.254.0.1"}],"restartPolicy":"never"}],"interfaces":[{"device":"lo","ipAddress":"127.0.0.2","netMask":"255.255.255.255"},{"device":"eth0","ipAddress":"172.16.18.184","netMask":"255.255.0.0"}],"dns":["172.16.0.2","172.16.69.2"],"routes":[{"dest":"0.0.0.0/0","gateway":"172.16.0.1","device":"eth0"}],"shareDir":"share_dir"}, len 1119
I0312 18:54:57.279489 47898 init_comm.go:48] [console] jsmn parse successed, n is 110
I0312 18:54:57.279508 47898 init_comm.go:48] [console] token 0, type is 1, size is 6
I0312 18:54:57.279943 47898 init_comm.go:48] [console] token 1, type is 3, size is 1
I0312 18:54:57.281282 47898 init_comm.go:48] [console] hostname is 4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433
I0312 18:54:57.281898 47898 init_comm.go:48] [console] token 3, type is 3, size is 1
I0312 18:54:57.282294 47898 init_comm.go:48] [console] container count 1
I0312 18:54:57.283356 47898 init_comm.go:48] [console] next container 13
I0312 18:54:57.283368 47898 init_comm.go:48] [console] 1 name id
I0312 18:54:57.283855 47898 init_comm.go:48] [console] container id 4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b
I0312 18:54:57.284089 47898 init_comm.go:48] [console] 3 name rootfs
I0312 18:54:57.284646 47898 init_comm.go:48] [console] container rootfs /rootfs
I0312 18:54:57.285002 47898 init_comm.go:48] [console] 5 name fstype
I0312 18:54:57.285261 47898 init_comm.go:48] [console] container fstype ext4
I0312 18:54:57.285590 47898 init_comm.go:48] [console] 7 name image
I0312 18:54:57.286045 47898 init_comm.go:48] [console] container image sda
I0312 18:54:57.286723 47898 init_comm.go:48] [console] 9 name addr
I0312 18:54:57.287073 47898 init_comm.go:48] [console] container image scsi id 0:0
I0312 18:54:57.287103 47898 init_comm.go:48] [console] 11 name fsmap
I0312 18:54:57.287503 47898 init_comm.go:48] [console] fsmap num 1
I0312 18:54:57.287837 47898 init_comm.go:48] [console] maps 0 source wmUGfGMdxA
I0312 18:54:57.288375 47898 init_comm.go:48] [console] maps 0 path /etc/hosts
I0312 18:54:57.288715 47898 init_comm.go:48] [console] maps 0 readonly 0
I0312 18:54:57.288998 47898 init_comm.go:48] [console] 20 name tty
I0312 18:54:57.289525 47898 init_comm.go:48] [console] container doesn't use terminal
I0312 18:54:57.289800 47898 init_comm.go:48] [console] 22 name stdio
I0312 18:54:57.290032 47898 init_comm.go:48] [console] container seq 1
I0312 18:54:57.290258 47898 init_comm.go:48] [console] 24 name stderr
I0312 18:54:57.290496 47898 init_comm.go:48] [console] container stderr seq 2
I0312 18:54:57.290713 47898 init_comm.go:48] [console] 26 name workdir
I0312 18:54:57.291510 47898 init_comm.go:48] [console] container workdir /
I0312 18:54:57.292373 47898 init_comm.go:48] [console] 28 name cmd
I0312 18:54:57.293211 47898 init_comm.go:48] [console] parse pod json failed
I0312 18:54:57.294439 47898 init_comm.go:48] [console] cmd need arrayuptime 0.85 0.10
I0312 18:54:57.294799 47898 init_comm.go:48] [console]
I0312 18:54:57.295954 47898 init_comm.go:48] [console] hyper send type 10, len 0
I0312 18:54:57.296242 47898 init_comm.go:86] read 8/8 [length = 0]
I0312 18:54:57.296258 47898 init_comm.go:90] data length is 8
I0312 18:54:57.296269 47898 init_comm.go:76] trying to read 8 bytes
I0312 18:54:57.296276 47898 init_comm.go:167] got cmd:10
I0312 18:54:57.296284 47898 init_comm.go:190] ack got, clear pong timer
I0312 18:54:57.296292 47898 hypervisor.go:29] main event loop got message 47(ERROR_CMD_FAIL)
E0312 18:54:57.296300 47898 vm_states.go:354] Shutting down because of an exception: Start POD failed
I0312 18:54:57.296314 47898 context.go:211] VM vm-FuHKePnQzb: state change from STARTING to 'TERMINATING'
E0312 18:54:57.296320 47898 vm_states.go:614] Start POD failed
I0312 18:54:57.296324 47898 init_comm.go:167] got cmd:4
I0312 18:54:57.296328 47898 init_comm.go:248] send command 4 to init, payload: ''.
I0312 18:54:57.296337 47898 init_comm.go:261] write 8 to init, payload: '.
I0312 18:54:57.296354 47898 init_comm.go:266] message sent, set pong timer
I0312 18:54:57.296367 47898 vm.go:267] Get the response from VM, VM id is vm-FuHKePnQzb!
I0312 18:54:57.296387 47898 hypervisor.go:29] main event loop got message 26(COMMAND_SHUTDOWN)
I0312 18:54:57.296395 47898 vm.go:81] Got response: 18: unexpected event during terminating
I0312 18:54:57.302517 47898 init_comm.go:48] [console] hyper_loop epoll_wait 1
I0312 18:54:57.302541 47898 init_comm.go:48] [console] hyper_handle_event get event 1, de 0x612500, fd 3. ops 0x612340
I0312 18:54:57.302547 47898 init_comm.go:48] [console] hyper_handle_event event EPOLLIN, de 0x612500, fd 3, 0x612340
I0312 18:54:57.302553 47898 init_comm.go:48] [console] hyper_event_read
I0312 18:54:57.302573 47898 init_comm.go:48] [console] already read 8 bytes data
I0312 18:54:57.302579 47898 init_comm.go:48] [console] hyper send type 14, len 4
I0312 18:54:57.304637 47898 init_comm.go:48] [console] get length 8
I0312 18:54:57.304662 47898 init_comm.go:48] [console] 0 0 0 4 0 0 0 8
I0312 18:54:57.304710 47898 init_comm.go:86] read 8/8 [length = 0]
I0312 18:54:57.304725 47898 init_comm.go:90] data length is 12
I0312 18:54:57.304731 47898 init_comm.go:76] trying to read 4 bytes
I0312 18:54:57.304757 47898 init_comm.go:86] read 12/12 [length = 12]
I0312 18:54:57.304770 47898 init_comm.go:76] trying to read 8 bytes
I0312 18:54:57.304806 47898 init_comm.go:167] got cmd:14
I0312 18:54:57.304819 47898 init_comm.go:235] get command NEXT
I0312 18:54:57.304826 47898 init_comm.go:238] send 8, receive 8
I0312 18:54:57.309314 47898 init_comm.go:48] [console] hyper_channel_handle, type 4, len 8
I0312 18:54:57.309380 47898 init_comm.go:48] [console] get DESTROYPOD message
I0312 18:54:57.310379 47898 init_comm.go:48] [console] hyper send type 9, len 0
I0312 18:54:57.311846 47898 init_comm.go:48] [console] sd 0:0:0:0: [sda] Synchronizing SCSI cache
I0312 18:54:57.312672 47898 init_comm.go:86] read 8/8 [length = 0]
I0312 18:54:57.312698 47898 init_comm.go:90] data length is 8
I0312 18:54:57.312714 47898 init_comm.go:76] trying to read 8 bytes
I0312 18:54:57.312727 47898 init_comm.go:167] got cmd:9
I0312 18:54:57.312737 47898 init_comm.go:171] got response of shutdown command, last round of command to init
I0312 18:54:57.312748 47898 init_comm.go:190] ack got, clear pong timer
I0312 18:54:57.312758 47898 hypervisor.go:29] main event loop got message 41(COMMAND_ACK)
I0312 18:54:57.312767 47898 vm_states.go:767] [Terminating] Got reply to &{4 [] <nil>}: ''
I0312 18:54:57.312786 47898 vm_states.go:769] POD destroyed
E0312 18:54:57.387497 47898 tty.go:100] read tty data failed
I0312 18:54:57.387518 47898 tty.go:161] tty socket closed, quit the reading goroutine EOF
I0312 18:54:57.387539 47898 tty.go:128] tty chan closed, quit sent goroutine
I0312 18:54:57.387545 47898 hypervisor.go:29] main event loop got message 46(ERROR_INTERRUPTED)
I0312 18:54:57.387553 47898 vm_states.go:782] Connection interrupted while terminating
E0312 18:54:57.387560 47898 init_comm.go:79] read init data failed
I0312 18:54:57.387564 47898 hypervisor.go:29] main event loop got message 46(ERROR_INTERRUPTED)
I0312 18:54:57.387568 47898 vm_states.go:782] Connection interrupted while terminating
I0312 18:54:57.387580 47898 tty.go:356] Input byte chan closed, close the output string chan
I0312 18:54:57.387585 47898 init_comm.go:50] console output end
I0312 18:54:57.532462 47898 hypervisor.go:29] main event loop got message 1(EVENT_VM_EXIT)
I0312 18:54:57.532492 47898 vm_states.go:751] Got VM shutdown event while terminating, go to cleaning up
I0312 18:54:57.532500 47898 vm_states.go:21] VM has exit...
I0312 18:54:57.532514 47898 devicemap.go:427] need umount dir wmUGfGMdxA
I0312 18:54:57.532612 47898 devicemap.go:437] need remove dm filerbd:hyper/docker_image_f3c70e73f64b069617522d646ec992c018f74b4f971fba5c0dd72baa08670913
I0312 18:54:57.532625 47898 devicemap.go:507] remove network card 0: 172.16.18.184
I0312 18:54:57.532635 47898 context.go:211] VM vm-FuHKePnQzb: state change from TERMINATING to 'DESTROYING'
I0312 18:54:57.532674 47898 hypervisor.go:29] main event loop got message 14(EVENT_INTERFACE_DELETE)
I0312 18:54:57.532683 47898 devicemap.go:395] interface 0 released
I0312 18:54:57.532691 47898 vm_states.go:434] Unplug interface return with true
I0312 18:54:57.532708 47898 vm.go:81] Got response: 2: VM shut down
E0312 18:54:57.532719 47898 pod.go:65] VM response data is nil
I0312 18:54:57.532726 47898 pod.go:66] unlock PodList
E0312 18:54:57.532736 47898 server.go:170] Handler for POST /pod/start returned error: VM response data is nil
I0312 18:54:57.532792 47898 list.go:25] lock read of PodList
I0312 18:54:57.532811 47898 list.go:111] unlock read of PodList
I0312 18:54:57.534644 47898 list.go:25] lock read of PodList
I0312 18:54:57.534674 47898 list.go:41] unlock read of PodList
E0312 18:54:57.534683 47898 server.go:170] Handler for GET /list returned error: Cannot find specified vm vm-FuHKePnQzb
I0312 18:54:57.535790 47898 hypervisor.go:29] main event loop got message 12(EVENT_BLOCK_EJECTED)
I0312 18:54:57.535849 47898 devicemap.go:404] volume etchosts-volume umounted
I0312 18:54:57.535872 47898 vm_states.go:437] Unplug block device return with true
I0312 18:54:57.535899 47898 list.go:25] lock read of PodList
I0312 18:54:57.535957 47898 list.go:111] unlock read of PodList
I0312 18:54:57.536217 47898 list.go:25] lock read of PodList
I0312 18:54:57.536236 47898 list.go:111] unlock read of PodList
I0312 18:54:57.536376 47898 list.go:25] lock read of PodList
I0312 18:54:57.536391 47898 list.go:41] unlock read of PodList
E0312 18:54:57.536398 47898 server.go:170] Handler for GET /list returned error: Cannot find specified vm vm-FuHKePnQzb
I0312 18:54:57.542420 47898 server.go:152] Calling GET /list
I0312 18:54:57.542490 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [vm-FuHKePnQzb], list auxiliary pod: false
I0312 18:54:57.542505 47898 list.go:25] lock read of PodList
I0312 18:54:57.542517 47898 list.go:41] unlock read of PodList
E0312 18:54:57.542523 47898 server.go:170] Handler for GET /list returned error: Cannot find specified vm vm-FuHKePnQzb
I0312 18:54:57.542668 47898 server.go:152] Calling GET /pod/info
I0312 18:54:57.542705 47898 info.go:18] lock read of PodList
I0312 18:54:57.543100 47898 server.go:152] Calling DELETE /pod
I0312 18:54:57.543203 47898 server.go:152] Calling GET /list
I0312 18:54:57.543241 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [vm-FuHKePnQzb], list auxiliary pod: false
I0312 18:54:57.543297 47898 server.go:152] Calling GET /pod/info
I0312 18:54:57.543408 47898 server.go:152] Calling GET /pod/info
I0312 18:54:57.544457 47898 mongostore.go:75] GetMountedLayer 4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b
I0312 18:54:57.544876 47898 mounted_layer.go:71] mountedLayer Metadata 4e2f0205e61ff42ef0f07b593e59ee5fc25d19ec94d1a93c3dbc7420ef5b433b f3c70e73f64b069617522d646ec992c018f74b4f971fba5c0dd72baa08670913
I0312 18:54:57.547300 47898 info.go:161] unlock read of PodList
I0312 18:54:57.547798 47898 rm.go:17] lock PodList
I0312 18:54:57.548110 47898 rm.go:21] unlock PodList
I0312 18:54:57.548195 47898 info.go:18] lock read of PodList
I0312 18:54:57.548205 47898 info.go:29] unlock read of PodList
E0312 18:54:57.548212 47898 server.go:170] Handler for GET /pod/info returned error: Can not get Pod info with pod ID(pod-QIdWeYOBoE)
I0312 18:54:57.548263 47898 list.go:25] lock read of PodList
I0312 18:54:57.548274 47898 list.go:41] unlock read of PodList
E0312 18:54:57.548279 47898 server.go:170] Handler for GET /list returned error: Cannot find specified vm vm-FuHKePnQzb
I0312 18:54:57.548303 47898 info.go:18] lock read of PodList
I0312 18:54:57.548309 47898 info.go:29] unlock read of PodList
E0312 18:54:57.548314 47898 server.go:170] Handler for GET /pod/info returned error: Can not get Pod info with pod ID(pod-QIdWeYOBoE)
I0312 18:54:57.553910 47898 server.go:152] Calling GET /list
I0312 18:54:57.553995 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:57.554011 47898 list.go:25] lock read of PodList
I0312 18:54:57.554024 47898 list.go:111] unlock read of PodList
I0312 18:54:57.554224 47898 server.go:152] Calling GET /list
I0312 18:54:57.554261 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [vm-FuHKePnQzb], list auxiliary pod: false
I0312 18:54:57.554269 47898 list.go:25] lock read of PodList
I0312 18:54:57.554277 47898 list.go:41] unlock read of PodList
E0312 18:54:57.554283 47898 server.go:170] Handler for GET /list returned error: Cannot find specified vm vm-FuHKePnQzb
W0312 18:54:57.565811 47898 volume_linux.go:107] Cannot umount device rbd:hyper/docker_image_f3c70e73f64b069617522d646ec992c018f74b4f971fba5c0dd72baa08670913: exit status 1, Device rbd:hyper/docker_image_f3c70e73f64b069617522d646ec992c018f74b4f971fba5c0dd72baa08670913 not found
Device rbd:hyper/docker_image_f3c70e73f64b069617522d646ec992c018f74b4f971fba5c0dd72baa08670913 not found
Device rbd:hyper/docker_image_f3c70e73f64b069617522d646ec992c018f74b4f971fba5c0dd72baa08670913 not found
Command failed
I0312 18:54:57.571764 47898 hypervisor.go:29] main event loop got message 9(EVENT_VOLUME_DELETE)
I0312 18:54:57.571807 47898 devicemap.go:418] blockdev rbd:hyper/docker_image_f3c70e73f64b069617522d646ec992c018f74b4f971fba5c0dd72baa08670913 deleted
I0312 18:54:57.571817 47898 vm_states.go:440] release volume return with false
I0312 18:54:57.571823 47898 context.go:198] no more device to release/remove/umount, quit
I0312 18:54:57.571855 47898 vm_states.go:839] resources reclaimed, quit...
I0312 18:54:58.264070 47898 server.go:152] Calling GET /images/get
I0312 18:54:58.805256 47898 server.go:152] Calling GET /list
I0312 18:54:58.805453 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:58.805473 47898 list.go:25] lock read of PodList
I0312 18:54:58.805484 47898 list.go:111] unlock read of PodList
I0312 18:54:58.806320 47898 server.go:152] Calling GET /list
I0312 18:54:58.806402 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:54:58.806415 47898 list.go:25] lock read of PodList
I0312 18:54:58.806424 47898 list.go:111] unlock read of PodList
I0312 18:55:00.550068 47898 server.go:152] Calling GET /list
I0312 18:55:00.550192 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:55:00.550209 47898 list.go:25] lock read of PodList
I0312 18:55:00.550220 47898 list.go:111] unlock read of PodList
I0312 18:55:00.805536 47898 server.go:152] Calling GET /list
I0312 18:55:00.805644 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:55:00.805659 47898 list.go:25] lock read of PodList
I0312 18:55:00.805668 47898 list.go:111] unlock read of PodList
I0312 18:55:00.806638 47898 server.go:152] Calling GET /list
I0312 18:55:00.806698 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:55:00.806710 47898 list.go:25] lock read of PodList
I0312 18:55:00.806719 47898 list.go:111] unlock read of PodList
I0312 18:55:02.806170 47898 server.go:152] Calling GET /list
I0312 18:55:02.806241 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:55:02.806254 47898 list.go:25] lock read of PodList
I0312 18:55:02.806263 47898 list.go:111] unlock read of PodList
I0312 18:55:02.807959 47898 server.go:152] Calling GET /list
I0312 18:55:02.808034 47898 pod_routes.go:52] List type is pod, specified pod: [], specified vm: [], list auxiliary pod: false
I0312 18:55:02.808047 47898 list.go:25] lock read of PodList
I0312 18:55:02.808056 47898 list.go:111] unlock read of PodList
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment