HuKeping
commented
8 years ago There is no log from docker daemon. Log from runv-containerd is:
I0612 13:36:26.044414 4542 server.go:31] gRPC handle CreateContainer
I0612 13:36:26.045544 4542 hyperpod.go:337] Using kernel: ; Initrd: ;
I0612 13:36:26.045598 4542 vm.go:180] hyperHandlePodEvent pod pod-OBxNCyKGTE, vm vm-VTsGRIKAqd
I0612 13:36:26.045668 4542 hypervisor.go:29] vm vm-VTsGRIKAqd: main event loop got message 21(COMMAND_RUN_POD)
I0612 13:36:26.045679 4542 vm_states.go:449] got spec, prepare devices
I0612 13:36:26.045890 4542 vm_states.go:67] initial vm spec: {
"hostname": "28f5d6a3f38a",
"containers": [],
"shareDir": "share_dir"
}
I0612 13:36:26.045902 4542 context.go:212] VM vm-VTsGRIKAqd: state change from INIT to 'STARTING'
I0612 13:36:26.045908 4542 hypervisor.go:29] vm vm-VTsGRIKAqd: main event loop got message 10(EVENT_DEV_SKIP)
I0612 13:36:26.045914 4542 vm_states.go:476] device ready, could run pod.
I0612 13:36:26.046001 4542 qemu.go:318] kvm not exist change to no kvm mode
I0612 13:36:26.046031 4542 qemu_process.go:63] cmdline arguments: -machine pc-i440fx-2.0,usb=off -cpu core2duo -kernel /var/lib/hyper/kernel -initrd /var/lib/hyper/hyper-initrd.img -append console=ttyS0 panic=1 no_timer_check -realtime mlock=off -no-user-config -nodefaults -no-hpet -rtc base=utc,driftfix=slew -no-reboot -display none -boot strict=on -m 128 -smp 1 -qmp unix:/var/run/hyper/vm-VTsGRIKAqd/qmp.sock,server,nowait -serial unix:/var/run/hyper/vm-VTsGRIKAqd/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-VTsGRIKAqd/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-VTsGRIKAqd/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-VTsGRIKAqd/share_dir,security_model=none -device virtio-9p-pci,fsdev=virtio9p,mount_tag=share_dir
I0612 13:36:26.049546 4542 qemu_process.go:74] starting daemon with pid: 4748
I0612 13:36:26.154156 4542 qmp_handler.go:167] connected to /var/run/hyper/vm-VTsGRIKAqd/qmp.sock
I0612 13:36:26.154357 4542 qmp_handler.go:177] begin qmp init...
I0612 13:36:26.154452 4542 init_comm.go:133] Wating for init messages...
I0612 13:36:26.154517 4542 init_comm.go:96] trying to read 8 bytes
I0612 13:36:26.154602 4542 tty.go:144] tty socket connected
I0612 13:36:26.154663 4542 tty.go:87] tty: trying to read 12 bytes
I0612 13:36:26.154728 4542 init_comm.go:53] connected to /var/run/hyper/vm-VTsGRIKAqd/console.sock
I0612 13:36:26.154787 4542 init_comm.go:60] connected /var/run/hyper/vm-VTsGRIKAqd/console.sock as telnet mode.
I0612 13:36:26.166287 4542 qmp_handler.go:186] got qmp welcome, now sending command qmp_capabilities
I0612 13:36:26.166548 4542 qmp_handler.go:201] waiting for response
I0612 13:36:26.166886 4542 qmp_handler.go:103] got a message {"return": {}}
I0612 13:36:26.166972 4542 qmp_handler.go:210] got for response
I0612 13:36:26.167028 4542 qmp_handler.go:213] QMP connection initialized
I0612 13:36:26.167095 4542 qmp_handler.go:346] QMP initialzed, go into main QMP loop
I0612 13:36:26.167154 4542 qmp_handler.go:137] Begin receive QMP message
I0612 13:36:27.382889 4542 init_comm.go:68] [console] Initializing cgroup subsys cpuset
I0612 13:36:27.383541 4542 init_comm.go:68] [console] Initializing cgroup subsys cpu
I0612 13:36:27.384268 4542 init_comm.go:68] [console] Initializing cgroup subsys cpuacct
I0612 13:36:27.385653 4542 init_comm.go:68] [console] Linux version 4.4.11-hyper (dev@hyper.sh) (gcc version 4.8.5 20150623 (Red Hat 4.8.5-4) (GCC) ) #1 SMP Tue May 31 08:00:05 UTC 2016
I0612 13:36:27.386217 4542 init_comm.go:68] [console] Command line: console=ttyS0 panic=1 no_timer_check
I0612 13:36:27.386622 4542 init_comm.go:68] [console] x86/fpu: Legacy x87 FPU detected.
I0612 13:36:27.387135 4542 init_comm.go:68] [console] x86/fpu: Using 'lazy' FPU context switches.
I0612 13:36:27.387572 4542 init_comm.go:68] [console] e820: BIOS-provided physical RAM map:
I0612 13:36:27.388215 4542 init_comm.go:68] [console] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
I0612 13:36:27.388870 4542 init_comm.go:68] [console] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
I0612 13:36:27.389529 4542 init_comm.go:68] [console] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
I0612 13:36:27.390166 4542 init_comm.go:68] [console] BIOS-e820: [mem 0x0000000000100000-0x0000000007ffdfff] usable
I0612 13:36:27.390824 4542 init_comm.go:68] [console] BIOS-e820: [mem 0x0000000007ffe000-0x0000000007ffffff] reserved
I0612 13:36:27.392028 4542 init_comm.go:68] [console] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
I0612 13:36:27.392498 4542 init_comm.go:68] [console] NX (Execute Disable) protection: active
I0612 13:36:27.392768 4542 init_comm.go:68] [console] SMBIOS 2.4 present.
I0612 13:36:27.393348 4542 init_comm.go:68] [console] e820: last_pfn = 0x7ffe max_arch_pfn = 0x400000000
I0612 13:36:27.394370 4542 init_comm.go:68] [console] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WC UC- WT
I0612 13:36:27.395388 4542 init_comm.go:68] [console] found SMP MP-table at [mem 0x000f6630-0x000f663f] mapped at [ffff8800000f6630]
I0612 13:36:27.395888 4542 init_comm.go:68] [console] RAMDISK: [mem 0x07b5f000-0x07feffff]
I0612 13:36:27.396431 4542 init_comm.go:68] [console] ACPI: Early table checksum verification disabled
I0612 13:36:27.396974 4542 init_comm.go:68] [console] ACPI: RSDP 0x00000000000F64B0 000014 (v00 BOCHS )
I0612 13:36:27.397817 4542 init_comm.go:68] [console] ACPI: RSDT 0x0000000007FFF67D 000030 (v01 BOCHS BXPCRSDT 00000001 BXPC 00000001)
I0612 13:36:27.398665 4542 init_comm.go:68] [console] ACPI: FACP 0x0000000007FFEBDA 000074 (v01 BOCHS BXPCFACP 00000001 BXPC 00000001)
I0612 13:36:27.399520 4542 init_comm.go:68] [console] ACPI: DSDT 0x0000000007FFE040 000B9A (v01 BOCHS BXPCDSDT 00000001 BXPC 00000001)
I0612 13:36:27.399950 4542 init_comm.go:68] [console] ACPI: FACS 0x0000000007FFE000 000040
I0612 13:36:27.400796 4542 init_comm.go:68] [console] ACPI: SSDT 0x0000000007FFEC4E 0009B7 (v01 BOCHS BXPCSSDT 00000001 BXPC 00000001)
I0612 13:36:27.401643 4542 init_comm.go:68] [console] ACPI: APIC 0x0000000007FFF605 000078 (v01 BOCHS BXPCAPIC 00000001 BXPC 00000001)
I0612 13:36:27.401987 4542 init_comm.go:68] [console] No NUMA configuration found
I0612 13:36:27.402664 4542 init_comm.go:68] [console] Faking a node at [mem 0x0000000000000000-0x0000000007ffdfff]
I0612 13:36:27.402709 4542 init_comm.go:68] [console] NODE_DATA(0) allocated [mem 0x07b4d000-0x07b5efff]
I0612 13:36:27.402741 4542 init_comm.go:68] [console] Zone ranges:
I0612 13:36:27.402772 4542 init_comm.go:68] [console] DMA [mem 0x0000000000001000-0x0000000000ffffff]
I0612 13:36:27.402802 4542 init_comm.go:68] [console] DMA32 [mem 0x0000000001000000-0x0000000007ffdfff]
I0612 13:36:27.402832 4542 init_comm.go:68] [console] Normal empty
I0612 13:36:27.403054 4542 init_comm.go:68] [console] Movable zone start for each node
I0612 13:36:27.403353 4542 init_comm.go:68] [console] Early memory node ranges
I0612 13:36:27.404558 4542 init_comm.go:68] [console] node 0: [mem 0x0000000000001000-0x000000000009efff]
I0612 13:36:27.405176 4542 init_comm.go:68] [console] node 0: [mem 0x0000000000100000-0x0000000007ffdfff]
I0612 13:36:27.405857 4542 init_comm.go:68] [console] Initmem setup node 0 [mem 0x0000000000001000-0x0000000007ffdfff]
I0612 13:36:27.406222 4542 init_comm.go:68] [console] ACPI: PM-Timer IO Port: 0x608
I0612 13:36:27.406768 4542 init_comm.go:68] [console] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
I0612 13:36:27.407447 4542 init_comm.go:68] [console] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
I0612 13:36:27.408060 4542 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
I0612 13:36:27.408695 4542 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
I0612 13:36:27.409324 4542 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
I0612 13:36:27.409976 4542 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
I0612 13:36:27.410628 4542 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
I0612 13:36:27.411191 4542 init_comm.go:68] [console] Using ACPI (MADT) for SMP configuration information
I0612 13:36:27.411638 4542 init_comm.go:68] [console] smpboot: Allowing 1 CPUs, 0 hotplug CPUs
I0612 13:36:27.412580 4542 init_comm.go:68] [console] e820: [mem 0x08000000-0xfffbffff] available for PCI devices
I0612 13:36:27.412626 4542 init_comm.go:68] [console] Booting paravirtualized kernel on bare hardware
I0612 13:36:27.412658 4542 init_comm.go:68] [console] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
I0612 13:36:27.412690 4542 init_comm.go:68] [console] setup_percpu: NR_CPUS:8 nr_cpumask_bits:8 nr_cpu_ids:1 nr_node_ids:1
I0612 13:36:27.413245 4542 init_comm.go:68] [console] PERCPU: Embedded 31 pages/cpu @ffff880007800000 s89624 r8192 d29160 u2097152
I0612 13:36:27.414932 4542 init_comm.go:68] [console] Built 1 zonelists in Node order, mobility grouping on. Total pages: 32135
I0612 13:36:27.415004 4542 init_comm.go:68] [console] Policy zone: DMA32
I0612 13:36:27.415054 4542 init_comm.go:68] [console] Kernel command line: console=ttyS0 panic=1 no_timer_check
I0612 13:36:27.415101 4542 init_comm.go:68] [console] PID hash table entries: 512 (order: 0, 4096 bytes)
I0612 13:36:27.415151 4542 init_comm.go:68] [console] Memory: 115064K/130672K available (4654K kernel code, 580K rwdata, 1472K rodata, 876K init, 756K bss, 15608K reserved, 0K cma-reserved)
I0612 13:36:27.415558 4542 init_comm.go:68] [console] Hierarchical RCU implementation.
I0612 13:36:27.416067 4542 init_comm.go:68] [console] Build-time adjustment of leaf fanout to 64.
I0612 13:36:27.416680 4542 init_comm.go:68] [console] RCU restricting CPUs from NR_CPUS=8 to nr_cpu_ids=1.
I0612 13:36:27.418716 4542 init_comm.go:68] [console] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=1
I0612 13:36:27.418774 4542 init_comm.go:68] [console] NR_IRQS:4352 nr_irqs:256 16
I0612 13:36:27.418808 4542 init_comm.go:68] [console] Console: colour *CGA 80x25
I0612 13:36:27.418839 4542 init_comm.go:68] [console] console [ttyS0] enabled
I0612 13:36:27.425002 4542 init_comm.go:68] [console] tsc: Fast TSC calibration failed
I0612 13:36:27.495932 4542 init_comm.go:68] [console] tsc: Unable to calibrate against PIT
I0612 13:36:27.496633 4542 init_comm.go:68] [console] tsc: using PMTIMER reference calibration
I0612 13:36:27.497182 4542 init_comm.go:68] [console] tsc: Detected 2394.409 MHz processor
I0612 13:36:27.499213 4542 init_comm.go:68] [console] Calibrating delay loop (skipped), value calculated using timer frequency.. 4788.81 BogoMIPS (lpj=2394409)
I0612 13:36:27.499798 4542 init_comm.go:68] [console] pid_max: default: 32768 minimum: 301
I0612 13:36:27.500575 4542 init_comm.go:68] [console] ACPI: Core revision 20150930
I0612 13:36:27.526882 4542 init_comm.go:68] [console] ACPI: 2 ACPI AML tables successfully acquired and loaded
I0612 13:36:27.529371 4542 init_comm.go:68] [console] Dentry cache hash table entries: 16384 (order: 5, 131072 bytes)
I0612 13:36:27.531462 4542 init_comm.go:68] [console] Inode-cache hash table entries: 8192 (order: 4, 65536 bytes)
I0612 13:36:27.532438 4542 init_comm.go:68] [console] Mount-cache hash table entries: 512 (order: 0, 4096 bytes)
I0612 13:36:27.533217 4542 init_comm.go:68] [console] Mountpoint-cache hash table entries: 512 (order: 0, 4096 bytes)
I0612 13:36:27.543213 4542 init_comm.go:68] [console] Initializing cgroup subsys io
I0612 13:36:27.544483 4542 init_comm.go:68] [console] Initializing cgroup subsys memory
I0612 13:36:27.545409 4542 init_comm.go:68] [console] Initializing cgroup subsys devices
I0612 13:36:27.545938 4542 init_comm.go:68] [console] Initializing cgroup subsys freezer
I0612 13:36:27.546442 4542 init_comm.go:68] [console] Initializing cgroup subsys net_cls
I0612 13:36:27.546987 4542 init_comm.go:68] [console] Initializing cgroup subsys perf_event
I0612 13:36:27.547494 4542 init_comm.go:68] [console] Initializing cgroup subsys net_prio
I0612 13:36:27.547973 4542 init_comm.go:68] [console] Initializing cgroup subsys pids
I0612 13:36:27.548442 4542 init_comm.go:68] [console] Initializing cgroup subsys debug
I0612 13:36:27.550585 4542 init_comm.go:68] [console] process: using mwait in idle threads
I0612 13:36:27.551402 4542 init_comm.go:68] [console] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0
I0612 13:36:27.552011 4542 init_comm.go:68] [console] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0
I0612 13:36:27.730225 4542 init_comm.go:68] [console] Freeing SMP alternatives memory: 20K (ffffffff8176a000 - ffffffff8176f000)
I0612 13:36:27.750647 4542 init_comm.go:68] [console] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
I0612 13:36:28.565470 4542 init_comm.go:68] [console] APIC calibration not consistent with PM-Timer: 800ms instead of 100ms
I0612 13:36:28.566240 4542 init_comm.go:68] [console] APIC delta adjusted to PM-Timer: 6249994 (50031173)
I0612 13:36:28.568503 4542 init_comm.go:68] [console] smpboot: CPU0: Intel(R) Core(TM)2 Duo CPU T7700 @ 2.40GHz (family: 0x6, model: 0xf, stepping: 0xb)
I0612 13:36:28.570399 4542 init_comm.go:68] [console] Performance Events: unsupported p6 CPU model 15 no PMU driver, software events only.
I0612 13:36:28.578165 4542 init_comm.go:68] [console] x86: Booted up 1 node, 1 CPUs
I0612 13:36:28.579140 4542 init_comm.go:68] [console] smpboot: Total of 1 processors activated (4788.81 BogoMIPS)
I0612 13:36:28.588312 4542 init_comm.go:68] [console] devtmpfs: initialized
I0612 13:36:28.609137 4542 init_comm.go:68] [console] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
I0612 13:36:28.617496 4542 init_comm.go:68] [console] NET: Registered protocol family 16
I0612 13:36:28.620699 4542 init_comm.go:68] [console] cpuidle: using governor ladder
I0612 13:36:28.621224 4542 init_comm.go:68] [console] cpuidle: using governor menu
I0612 13:36:28.622072 4542 init_comm.go:68] [console] ACPI: bus type PCI registered
I0612 13:36:28.622787 4542 init_comm.go:68] [console] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
I0612 13:36:28.623789 4542 init_comm.go:68] [console] PCI: Using configuration type 1 for base access
I0612 13:36:28.638419 4542 init_comm.go:68] [console] ACPI: Added _OSI(Module Device)
I0612 13:36:28.639069 4542 init_comm.go:68] [console] ACPI: Added _OSI(Processor Device)
I0612 13:36:28.639525 4542 init_comm.go:68] [console] ACPI: Added _OSI(3.0 _SCP Extensions)
I0612 13:36:28.640041 4542 init_comm.go:68] [console] ACPI: Added _OSI(Processor Aggregator Device)
I0612 13:36:28.659977 4542 init_comm.go:68] [console] ACPI: Interpreter enabled
I0612 13:36:28.660859 4542 init_comm.go:68] [console] ACPI: (supports S0 S5)
I0612 13:36:28.661392 4542 init_comm.go:68] [console] ACPI: Using IOAPIC for interrupt routing
I0612 13:36:28.662690 4542 init_comm.go:68] [console] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
I0612 13:36:28.699987 4542 init_comm.go:68] [console] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
I0612 13:36:28.701264 4542 init_comm.go:68] [console] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI]
I0612 13:36:28.702150 4542 init_comm.go:68] [console] acpi PNP0A03:00: _OSC failed (AE_NOT_FOUND); disabling ASPM
I0612 13:36:28.706330 4542 init_comm.go:68] [console] acpiphp: Slot [2] registered
I0612 13:36:28.707327 4542 init_comm.go:68] [console] acpiphp: Slot [3] registered
I0612 13:36:28.708083 4542 init_comm.go:68] [console] acpiphp: Slot [4] registered
I0612 13:36:28.708671 4542 init_comm.go:68] [console] acpiphp: Slot [5] registered
I0612 13:36:28.709257 4542 init_comm.go:68] [console] acpiphp: Slot [6] registered
I0612 13:36:28.709822 4542 init_comm.go:68] [console] acpiphp: Slot [7] registered
I0612 13:36:28.710397 4542 init_comm.go:68] [console] acpiphp: Slot [8] registered
I0612 13:36:28.710975 4542 init_comm.go:68] [console] acpiphp: Slot [9] registered
I0612 13:36:28.711550 4542 init_comm.go:68] [console] acpiphp: Slot [10] registered
I0612 13:36:28.712128 4542 init_comm.go:68] [console] acpiphp: Slot [11] registered
I0612 13:36:28.712718 4542 init_comm.go:68] [console] acpiphp: Slot [12] registered
I0612 13:36:28.713290 4542 init_comm.go:68] [console] acpiphp: Slot [13] registered
I0612 13:36:28.713855 4542 init_comm.go:68] [console] acpiphp: Slot [14] registered
I0612 13:36:28.715317 4542 init_comm.go:68] [console] acpiphp: Slot [15] registered
I0612 13:36:28.716055 4542 init_comm.go:68] [console] acpiphp: Slot [16] registered
I0612 13:36:28.716641 4542 init_comm.go:68] [console] acpiphp: Slot [17] registered
I0612 13:36:28.717215 4542 init_comm.go:68] [console] acpiphp: Slot [18] registered
I0612 13:36:28.717805 4542 init_comm.go:68] [console] acpiphp: Slot [19] registered
I0612 13:36:28.718380 4542 init_comm.go:68] [console] acpiphp: Slot [20] registered
I0612 13:36:28.718966 4542 init_comm.go:68] [console] acpiphp: Slot [21] registered
I0612 13:36:28.719536 4542 init_comm.go:68] [console] acpiphp: Slot [22] registered
I0612 13:36:28.720120 4542 init_comm.go:68] [console] acpiphp: Slot [23] registered
I0612 13:36:28.720694 4542 init_comm.go:68] [console] acpiphp: Slot [24] registered
I0612 13:36:28.721268 4542 init_comm.go:68] [console] acpiphp: Slot [25] registered
I0612 13:36:28.721855 4542 init_comm.go:68] [console] acpiphp: Slot [26] registered
I0612 13:36:28.722417 4542 init_comm.go:68] [console] acpiphp: Slot [27] registered
I0612 13:36:28.723001 4542 init_comm.go:68] [console] acpiphp: Slot [28] registered
I0612 13:36:28.723583 4542 init_comm.go:68] [console] acpiphp: Slot [29] registered
I0612 13:36:28.724913 4542 init_comm.go:68] [console] acpiphp: Slot [30] registered
I0612 13:36:28.725559 4542 init_comm.go:68] [console] acpiphp: Slot [31] registered
I0612 13:36:28.726209 4542 init_comm.go:68] [console] PCI host bridge to bus 0000:00
I0612 13:36:28.727114 4542 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window]
I0612 13:36:28.727833 4542 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window]
I0612 13:36:28.728604 4542 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
I0612 13:36:28.729357 4542 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [mem 0x08000000-0xfebfffff window]
I0612 13:36:28.730006 4542 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [bus 00-ff]
I0612 13:36:28.742286 4542 init_comm.go:68] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7]
I0612 13:36:28.743182 4542 init_comm.go:68] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6]
I0612 13:36:28.744238 4542 init_comm.go:68] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177]
I0612 13:36:28.745090 4542 init_comm.go:68] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376]
I0612 13:36:28.747133 4542 init_comm.go:68] [console] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI
I0612 13:36:28.747894 4542 init_comm.go:68] [console] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB
I0612 13:36:28.790772 4542 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11)
I0612 13:36:28.792517 4542 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 *10 11)
I0612 13:36:28.793834 4542 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 10 *11)
I0612 13:36:28.795518 4542 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 10 *11)
I0612 13:36:28.796579 4542 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKS] (IRQs *9)
I0612 13:36:28.799204 4542 init_comm.go:68] [console] ACPI: Enabled 16 GPEs in block 00 to 0F
I0612 13:36:28.803475 4542 init_comm.go:68] [console] vgaarb: loaded
I0612 13:36:28.805374 4542 init_comm.go:68] [console] SCSI subsystem initialized
I0612 13:36:28.807002 4542 init_comm.go:68] [console] PCI: Using ACPI for IRQ routing
I0612 13:36:28.814621 4542 init_comm.go:68] [console] clocksource: Switched to clocksource refined-jiffies
I0612 13:36:28.817161 4542 init_comm.go:68] [console] pnp: PnP ACPI init
I0612 13:36:28.823267 4542 init_comm.go:68] [console] pnp: PnP ACPI: found 5 devices
I0612 13:36:28.851878 4542 init_comm.go:68] [console] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
I0612 13:36:28.852872 4542 init_comm.go:68] [console] clocksource: Switched to clocksource acpi_pm
I0612 13:36:28.855681 4542 init_comm.go:68] [console] NET: Registered protocol family 2
I0612 13:36:28.861454 4542 init_comm.go:68] [console] TCP established hash table entries: 1024 (order: 1, 8192 bytes)
I0612 13:36:28.862311 4542 init_comm.go:68] [console] TCP bind hash table entries: 1024 (order: 2, 16384 bytes)
I0612 13:36:28.863082 4542 init_comm.go:68] [console] TCP: Hash tables configured (established 1024 bind 1024)
I0612 13:36:28.864697 4542 init_comm.go:68] [console] UDP hash table entries: 256 (order: 1, 8192 bytes)
I0612 13:36:28.865648 4542 init_comm.go:68] [console] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes)
I0612 13:36:28.867398 4542 init_comm.go:68] [console] NET: Registered protocol family 1
I0612 13:36:28.868311 4542 init_comm.go:68] [console] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
I0612 13:36:28.868950 4542 init_comm.go:68] [console] pci 0000:00:01.0: PIIX3: Enabling Passive Release
I0612 13:36:28.869676 4542 init_comm.go:68] [console] pci 0000:00:01.0: Activating ISA DMA hang workarounds
I0612 13:36:28.875389 4542 init_comm.go:68] [console] Trying to unpack rootfs image as initramfs...
I0612 13:36:29.344307 4542 init_comm.go:68] [console] Freeing initrd memory: 4676K (ffff880007b5f000 - ffff880007ff0000)
I0612 13:36:29.349365 4542 init_comm.go:68] [console] futex hash table entries: 256 (order: 2, 16384 bytes)
I0612 13:36:29.354717 4542 init_comm.go:68] [console] SGI XFS with ACLs, security attributes, no debug enabled
I0612 13:36:29.357508 4542 init_comm.go:68] [console] 9p: Installing v9fs 9p2000 file system support
I0612 13:36:29.390138 4542 init_comm.go:68] [console] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 253)
I0612 13:36:29.391054 4542 init_comm.go:68] [console] io scheduler noop registered
I0612 13:36:29.391655 4542 init_comm.go:68] [console] io scheduler cfq registered (default)
I0612 13:36:29.393089 4542 init_comm.go:68] [console] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
I0612 13:36:29.393884 4542 init_comm.go:68] [console] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
I0612 13:36:29.396011 4542 init_comm.go:68] [console] Warning: Processor Platform Limit event detected, but not handled.
I0612 13:36:29.396615 4542 init_comm.go:68] [console] Consider compiling CPUfreq support into your kernel.
I0612 13:36:29.655022 4542 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKB] enabled at IRQ 10
I0612 13:36:29.656272 4542 init_comm.go:68] [console] virtio-pci 0000:00:02.0: virtio_pci: leaving for legacy driver
I0612 13:36:29.910014 4542 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 11
I0612 13:36:29.911017 4542 init_comm.go:68] [console] virtio-pci 0000:00:03.0: virtio_pci: leaving for legacy driver
I0612 13:36:30.165101 4542 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 11
I0612 13:36:30.166152 4542 init_comm.go:68] [console] virtio-pci 0000:00:04.0: virtio_pci: leaving for legacy driver
I0612 13:36:30.169190 4542 init_comm.go:68] [console] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
I0612 13:36:30.192426 4542 init_comm.go:68] [console] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
I0612 13:36:30.236723 4542 init_comm.go:68] [console] brd: module loaded
I0612 13:36:30.237781 4542 init_comm.go:68] [console] loop: module loaded
I0612 13:36:30.240378 4542 init_comm.go:68] [console] scsi host0: Virtio SCSI HBA
I0612 13:36:30.355738 4542 init_comm.go:68] [console] tsc: Refined TSC clocksource calibration: 2394.446 MHz
I0612 13:36:30.357018 4542 init_comm.go:68] [console] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x2283b8e874b, max_idle_ns: 440795241608 ns
I0612 13:36:30.420347 4542 init_comm.go:68] [console] rtc_cmos 00:00: RTC can wake from S4
I0612 13:36:30.423699 4542 init_comm.go:68] [console] rtc_cmos 00:00: rtc core: registered rtc_cmos as rtc0
I0612 13:36:30.425485 4542 init_comm.go:68] [console] rtc_cmos 00:00: alarms up to one day, 114 bytes nvram
I0612 13:36:30.427132 4542 init_comm.go:68] [console] Initializing XFRM netlink socket
I0612 13:36:30.427990 4542 init_comm.go:68] [console] NET: Registered protocol family 10
I0612 13:36:30.433350 4542 init_comm.go:68] [console] NET: Registered protocol family 17
I0612 13:36:30.435497 4542 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.
I0612 13:36:30.436391 4542 init_comm.go:68] [console] Bridge firewalling registered
I0612 13:36:30.437608 4542 init_comm.go:68] [console] 9pnet: Installing 9P2000 support
I0612 13:36:30.440711 4542 init_comm.go:68] [console] registered taskstats version 1
I0612 13:36:30.444207 4542 init_comm.go:68] [console] rtc_cmos 00:00: setting system clock to 2016-06-12 17:36:30 UTC (1465752990)
I0612 13:36:30.466223 4542 init_comm.go:68] [console] Freeing unused kernel memory: 876K (ffffffff8168f000 - ffffffff8176a000)
I0612 13:36:30.538462 4542 init_comm.go:68] [console] create directory /sys
I0612 13:36:30.540709 4542 init_comm.go:68] [console] create directory /sbin
I0612 13:36:30.542651 4542 init_comm.go:68] [console] create directory /proc
I0612 13:36:30.547315 4542 init_comm.go:68] [console] uptime 1.79 0.03
I0612 13:36:30.548117 4542 init_comm.go:68] [console]
I0612 13:36:30.552947 4542 init_comm.go:68] [console] create directory /dev/pts
I0612 13:36:30.564585 4542 init_comm.go:68] [console] open hyper channel /dev/vport0p1
I0612 13:36:30.566036 4542 qmp_handler.go:103] got a message {"timestamp": {"seconds": 1465752990, "microseconds": 565845}, "event": "VSERPORT_CHANGE", "data": {"open": true, "id": "channel0"}}
I0612 13:36:30.566177 4542 qmp_handler.go:107] got event: VSERPORT_CHANGE
I0612 13:36:30.566249 4542 qmp_handler.go:323] got QMP event VSERPORT_CHANGE
I0612 13:36:30.566885 4542 init_comm.go:68] [console] send ready message
I0612 13:36:30.567666 4542 init_comm.go:68] [console] hyper send type 8, len 0
I0612 13:36:30.568092 4542 init_comm.go:106] read 8/8 [length = 0]
I0612 13:36:30.568164 4542 init_comm.go:110] data length is 8
I0612 13:36:30.568199 4542 init_comm.go:143] Get init ready message
I0612 13:36:30.568232 4542 init_comm.go:190] got cmd:1
I0612 13:36:30.568300 4542 init_comm.go:281] send command 1 to init, payload: '{"hostname":"28f5d6a3f38a","containers":[],"shareDir":"share_dir"}'.
I0612 13:36:30.568346 4542 init_comm.go:294] write 74 to init, payload: 'J{"hostname":"28f5d6a3f38a","containers":[],"shareDir":"share_dir"}'.
I0612 13:36:30.568398 4542 init_comm.go:299] message sent, set pong timer
I0612 13:36:30.568436 4542 hypervisor.go:29] vm vm-VTsGRIKAqd: main event loop got message 5(EVENT_INIT_CONNECTED)
I0612 13:36:30.568473 4542 vm_states.go:490] begin to wait vm commands
I0612 13:36:30.568518 4542 init_comm.go:96] trying to read 8 bytes
I0612 13:36:30.568558 4542 vm.go:263] Get the response from VM, VM id is vm-VTsGRIKAqd!
I0612 13:36:30.571033 4542 init_comm.go:68] [console] channel sh.hyper.channel.1, directory sh.hyper.channel.0
I0612 13:36:30.571147 4542 init_comm.go:68] [console]
I0612 13:36:30.571910 4542 init_comm.go:68] [console] open hyper channel /dev/vport0p2
I0612 13:36:30.575102 4542 init_comm.go:68] [console] hyper_init_event hyper channel event 0x6185a0, ops 0x6183a0, fd 3
I0612 13:36:30.576342 4542 init_comm.go:68] [console] hyper_add_event add event fd 3, 0x6183a0
I0612 13:36:30.577783 4542 init_comm.go:68] [console] hyper_init_event hyper ttyfd event 0x618568, ops 0x618360, fd 4
I0612 13:36:30.578469 4542 init_comm.go:68] [console] hyper_add_event add event fd 4, 0x618360
I0612 13:36:30.579653 4542 init_comm.go:68] [console] hyper_loop epoll_wait 1
I0612 13:36:30.580530 4542 init_comm.go:68] [console] hyper_handle_event get event 1, de 0x6185a0, fd 3. ops 0x6183a0
I0612 13:36:30.581329 4542 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, de 0x6185a0, fd 3, 0x6183a0
I0612 13:36:30.581684 4542 init_comm.go:68] [console] hyper_event_read
I0612 13:36:30.582296 4542 init_comm.go:68] [console] already read 8 bytes data
I0612 13:36:30.582771 4542 init_comm.go:68] [console] hyper send type 14, len 4
I0612 13:36:30.582920 4542 init_comm.go:106] read 8/8 [length = 0]
I0612 13:36:30.582966 4542 init_comm.go:110] data length is 12
I0612 13:36:30.582990 4542 init_comm.go:96] trying to read 4 bytes
I0612 13:36:30.583191 4542 init_comm.go:106] read 12/12 [length = 12]
I0612 13:36:30.583238 4542 init_comm.go:96] trying to read 8 bytes
I0612 13:36:30.583277 4542 init_comm.go:190] got cmd:14
I0612 13:36:30.583304 4542 init_comm.go:253] get command NEXT
I0612 13:36:30.583334 4542 init_comm.go:256] send 74, receive 8
I0612 13:36:30.583662 4542 init_comm.go:68] [console] get length 74
I0612 13:36:30.586166 4542 init_comm.go:68] [console] read 66 bytes data, total data 74
I0612 13:36:30.586711 4542 init_comm.go:68] [console] hyper send type 14, len 4
I0612 13:36:30.586857 4542 init_comm.go:106] read 8/8 [length = 0]
I0612 13:36:30.586919 4542 init_comm.go:110] data length is 12
I0612 13:36:30.586929 4542 init_comm.go:96] trying to read 4 bytes
I0612 13:36:30.587066 4542 init_comm.go:106] read 12/12 [length = 12]
I0612 13:36:30.587127 4542 init_comm.go:96] trying to read 8 bytes
I0612 13:36:30.587166 4542 init_comm.go:190] got cmd:14
I0612 13:36:30.587201 4542 init_comm.go:253] get command NEXT
I0612 13:36:30.587211 4542 init_comm.go:256] send 74, receive 74
I0612 13:36:30.589715 4542 init_comm.go:68] [console] 0 0 0 1 0 0 0 4a 7b 22 68 6f 73 74 6e 61 6d 65 22 3a 22 32 38 66 35 64 36 61 33 66 33 38 61 22 2c 22 63 6f 6e 74 61 69 6e 65 72 73 22 3a 5b 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
I0612 13:36:30.590309 4542 init_comm.go:68] [console] hyper_channel_handle, type 1, len 74
I0612 13:36:30.591541 4542 init_comm.go:68] [console] call hyper_start_pod, json {"hostname":"28f5d6a3f38a","containers":[],"shareDir":"share_dir"}, len 66
I0612 13:36:30.599654 4542 init_comm.go:68] [console] call hyper_start_pod, json {"hostname":"28f5d6a3f38a","containers":[],"shareDir":"share_dir"}, len 66
I0612 13:36:30.605079 4542 init_comm.go:68] [console] jsmn parse successed, n is 7
I0612 13:36:30.605806 4542 init_comm.go:68] [console] token 0, type is 1, size is 3
I0612 13:36:30.606288 4542 init_comm.go:68] [console] token 1, type is 3, size is 1
I0612 13:36:30.606986 4542 init_comm.go:68] [console] hostname is 28f5d6a3f38a
I0612 13:36:30.607459 4542 init_comm.go:68] [console] token 3, type is 3, size is 1
I0612 13:36:30.607851 4542 init_comm.go:68] [console] container count 0
I0612 13:36:30.608322 4542 init_comm.go:68] [console] token 5, type is 3, size is 1
I0612 13:36:30.608779 4542 init_comm.go:68] [console] share tag is share_dir
I0612 13:36:30.609334 4542 init_comm.go:68] [console] create directory /tmp
I0612 13:36:30.609834 4542 init_comm.go:68] [console] create directory /tmp/hyper
I0612 13:36:30.610375 4542 init_comm.go:68] [console] create directory /tmp/hyper/proc
I0612 13:36:30.612181 4542 init_comm.go:68] [console] finish rescan
I0612 13:36:30.631041 4542 init_comm.go:68] [console] random: busybox urandom read with 11 bits of entropy available
I0612 13:36:30.643278 4542 init_comm.go:68] [console] create directory /tmp/hyper/shared
I0612 13:36:30.660668 4542 init_comm.go:68] [console] pod init pid 327
I0612 13:36:30.666391 4542 init_comm.go:68] [console] hyper send type 8, len 0
I0612 13:36:30.669081 4542 init_comm.go:68] [console] uptime 1.91 0.04
I0612 13:36:30.669252 4542 init_comm.go:68] [console]
I0612 13:36:30.669806 4542 init_comm.go:68] [console] hyper send type 9, len 0
I0612 13:36:30.669972 4542 init_comm.go:106] read 8/8 [length = 0]
I0612 13:36:30.670036 4542 init_comm.go:110] data length is 8
I0612 13:36:30.670074 4542 init_comm.go:96] trying to read 8 bytes
I0612 13:36:30.670094 4542 init_comm.go:190] got cmd:9
I0612 13:36:30.670137 4542 init_comm.go:209] ack got, clear pong timer
I0612 13:36:30.670178 4542 hypervisor.go:29] vm vm-VTsGRIKAqd: main event loop got message 31(COMMAND_ACK)
I0612 13:36:30.670230 4542 vm_states.go:500] [starting] got init ack to &{1 859530718160 <nil> [] 859530378176}
I0612 13:36:30.670713 4542 context.go:212] VM vm-VTsGRIKAqd: state change from STARTING to 'RUNNING'
I0612 13:36:30.670781 4542 vm_states.go:516] pod start success
I0612 13:36:30.670840 4542 vm.go:263] Get the response from VM, VM id is vm-VTsGRIKAqd!
I0612 13:36:30.670901 4542 hyperpod.go:373] result: code 0 Start POD success
I0612 13:36:30.670939 4542 hyperpod.go:186] get exec path /root/go/src/github.com/hyperhq/runv/runv-containerd
I0612 13:36:30.694153 4542 init_comm.go:68] [console] pid 326 exit normally, status 0
I0612 13:36:30.694770 4542 init_comm.go:68] [console] can not find exec whose pid is 326
I0612 13:36:30.694820 4542 init_comm.go:68] [console] hyper_loop epoll_wait -1
I0612 13:36:30.697518 4542 hyperpod.go:235] nsListener pid is 4771
I0612 13:36:30.697598 4542 supervisor.go:168] createHyperPod() returns
I0612 13:36:30.697648 4542 hyperpod.go:258] createContainer()
I0612 13:36:30.697685 4542 process.go:33] process setupIO: stdin /var/run/docker/libcontainerd/28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31/init-stdin, stdout /var/run/docker/libcontainerd/28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31/init-stdout, stderr /var/run/docker/libcontainerd/28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31/init-stderr
I0612 13:36:30.697887 4542 process.go:59] process setupIO() success
I0612 13:36:30.697931 4542 hyperpod.go:284] createContainer()
I0612 13:36:30.697963 4542 hyperpod.go:290] createContainer() calls c.run(p)
I0612 13:36:30.698012 4542 supervisor.go:53] Supervisor.CreateContainer() return: c:&{28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31 /var/run/docker/libcontainerd/28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31 0xc820153200 map[init:0xc82005fb00] 0xc820268cc0} p:&{init /var/run/docker/libcontainerd/28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31/init-stdin /var/run/docker/libcontainerd/28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31/init-stdout /var/run/docker/libcontainerd/28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31/init-stderr 0xc820153230 -1 28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31-init 0xc820268f00 true 0xc820268f40 <nil>}
I0612 13:36:30.698104 4542 server.go:50] end Supervisor.CreateContainer(), build api Container
I0612 13:36:30.698156 4542 server.go:55] gRPC respond CreateContainer
I0612 13:36:30.698408 4542 container.go:64] save state id 28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31, boundle /var/run/docker/libcontainerd/28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31
I0612 13:36:30.698582 4542 container.go:95] prepare hypervisor info
I0612 13:36:30.698630 4542 ocf-linux.go:21] env: PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
I0612 13:36:30.698665 4542 ocf-linux.go:21] env: HOSTNAME=28f5d6a3f38a
I0612 13:36:30.698696 4542 ocf-linux.go:21] env: TERM=xterm
I0612 13:36:30.701179 4542 container.go:311] Skip mount point "/proc" of type proc
I0612 13:36:30.701246 4542 container.go:311] Skip mount point "/dev" of type tmpfs
I0612 13:36:30.707086 4542 container.go:311] Skip mount point "/sys" of type sysfs
I0612 13:36:30.707173 4542 container.go:311] Skip mount point "/sys/fs/cgroup" of type cgroup
I0612 13:36:30.707226 4542 container.go:311] Skip mount point "/dev/mqueue" of type mqueue
I0612 13:36:30.724970 4542 hypervisor.go:29] vm vm-VTsGRIKAqd: main event loop got message 30(COMMAND_WINDOWSIZE)
E0612 13:36:30.725142 4542 vm_states.go:172] cannot resolve client tag 28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31-init
I0612 13:36:30.725425 4542 hypervisor.go:29] vm vm-VTsGRIKAqd: main event loop got message 34(GENERIC_OPERATION)
I0612 13:36:30.725491 4542 vm_states.go:303] handle GenericOperation(Attach) on state(RUNNING)
I0612 13:36:30.725540 4542 context.go:180] can not found container 28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31
I0612 13:36:30.725587 4542 vm_states.go:220] attachment 28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31-init is pending
I0612 13:36:30.752756 4542 hyperpod.go:128] interface configuration of pod ns is []
I0612 13:36:30.753291 4542 hypervisor.go:29] vm vm-VTsGRIKAqd: main event loop got message 34(GENERIC_OPERATION)
I0612 13:36:30.753352 4542 vm_states.go:303] handle GenericOperation(AddRoute) on state(RUNNING)
I0612 13:36:30.753416 4542 events.go:121] notifySubscribers: {28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31 start-container 2016-06-12 13:36:30.753408707 -0400 EDT 0}
I0612 13:36:30.753644 4542 hypervisor.go:29] vm vm-VTsGRIKAqd: main event loop got message 26(COMMAND_NEWCONTAINER)
I0612 13:36:30.753722 4542 context.go:176] found container 28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31 at 0
I0612 13:36:30.753774 4542 vm_states.go:114] attach pending client 28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31-init for 28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31
I0612 13:36:30.753826 4542 vm_states.go:239] Connecting tty for 28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31 on session 1
I0612 13:36:30.753874 4542 vm_states.go:127] start sending INIT_NEWCONTAINER
I0612 13:36:30.754373 4542 vm_states.go:132] sent INIT_NEWCONTAINER
I0612 13:36:30.754562 4542 init_comm.go:190] got cmd:17
I0612 13:36:30.754643 4542 init_comm.go:281] send command 17 to init, payload: '{"id":"28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31","rootfs":"rootfs","image":"28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31","process":{"terminal":true,"stdio":1,"args":["ifconfig"],"envs":[{"env":"PATH","value":"/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"},{"env":"HOSTNAME","value":"28f5d6a3f38a"},{"env":"TERM","value":"xterm"}],"workdir":"/"},"restartPolicy":"never","initialize":false}'.
I0612 13:36:30.764210 4542 init_comm.go:294] write 457 to init, payload: 'Ȼ"id":"28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31","rootfs":"rootfs","image":"28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31","process":{"terminal":true,"stdio":1,"args":["ifconfig"],"envs":[{"env":"PATH","value":"/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"},{"env":"HOSTNAME","value":"28f5d6a3f38a"},{"env":"TERM","value":"xterm"}],"workdir":"/"},"restartPolicy":"never","initialize":false}'.
I0612 13:36:30.764356 4542 init_comm.go:299] message sent, set pong timer
I0612 13:36:30.764423 4542 events.go:54] write event log: {28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31 start-container 2016-06-12 13:36:30.753408707 -0400 EDT 0}
I0612 13:36:30.764647 4542 init_comm.go:68] [console] hyper_loop epoll_wait 1
I0612 13:36:30.764664 4542 init_comm.go:68] [console] hyper_handle_event get event 1, de 0x6185a0, fd 3. ops 0x6183a0
I0612 13:36:30.764673 4542 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, de 0x6185a0, fd 3, 0x6183a0
I0612 13:36:30.764681 4542 init_comm.go:68] [console] hyper_event_read
I0612 13:36:30.764689 4542 init_comm.go:68] [console] already read 8 bytes data
I0612 13:36:30.764697 4542 init_comm.go:68] [console] hyper send type 14, len 4
I0612 13:36:30.764704 4542 init_comm.go:68] [console] get length 457
I0612 13:36:30.764712 4542 init_comm.go:68] [console] read 449 bytes data, total data 457
I0612 13:36:30.764723 4542 init_comm.go:106] read 8/8 [length = 0]
I0612 13:36:30.764734 4542 init_comm.go:110] data length is 12
I0612 13:36:30.764741 4542 init_comm.go:96] trying to read 4 bytes
I0612 13:36:30.764751 4542 init_comm.go:106] read 12/12 [length = 12]
I0612 13:36:30.764760 4542 init_comm.go:96] trying to read 8 bytes
I0612 13:36:30.764769 4542 init_comm.go:106] read 8/8 [length = 0]
I0612 13:36:30.764777 4542 init_comm.go:110] data length is 12
I0612 13:36:30.764784 4542 init_comm.go:96] trying to read 4 bytes
I0612 13:36:30.764792 4542 init_comm.go:106] read 12/12 [length = 12]
I0612 13:36:30.764800 4542 init_comm.go:96] trying to read 8 bytes
I0612 13:36:30.764811 4542 init_comm.go:190] got cmd:14
I0612 13:36:30.764820 4542 init_comm.go:253] get command NEXT
I0612 13:36:30.764829 4542 init_comm.go:256] send 457, receive 8
I0612 13:36:30.764840 4542 init_comm.go:190] got cmd:14
I0612 13:36:30.764849 4542 init_comm.go:253] get command NEXT
I0612 13:36:30.764857 4542 init_comm.go:256] send 457, receive 457
I0612 13:36:30.765394 4542 init_comm.go:68] [console] hyper send type 14, len 4
I0612 13:36:30.779166 4542 init_comm.go:68] [console] 0 0 0 11 0 0 1 c9 7b 22 69 64 22 3a 22 32 38 66 35 64 36 61 33 66 33 38 61 66 32 30 38 30 31 63 66 39 62 64 33 31 31 34 36 61 36 36 66 38 63 34 39 38 39 63 35 39 33 36 66 35 34 33 64 30 34 34 65 34 37 62 35 35 64 38 33 61 66 33 31 22 2c 22 72 6f 6f 74 66 73 22 3a 22 72 6f 6f 74 66 73 22 2c 22 69 6d 61 67 65 22 3a 22 32 38 66 35 64 36 61 33 66 33 38 61 66 32 30 38 30 31 63 66 39 62 64 33 31 31 34 36 61 36 36 66 38 63 34 39 38 39 63 35 39 33 36 66 35 34 33 64 30 34 34 65 34 37 62 35 35 64 38 33 61 66 33 31 22 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 69 66 63 6f 6e 66 69 67 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 2c 7b 22 65 6e 76 22 3a 22 48 4f 53 54 4e 41 4d 45 22 2c 22 76 61 6c 75 65 22 3a 22 32 38 66 35 64 36 61 33 66 33 38 61 22 7d 2c 7b 22 65 6e 76 22 3a 22 54 45 52 4d 22 2c 22 76 61 6c 75 65 22 3a 22 78 74 65 72 6d 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 66 61 6c 73 65 7d
I0612 13:36:30.779745 4542 init_comm.go:68] [console] hyper_channel_handle, type 17, len 457
I0612 13:36:30.784756 4542 init_comm.go:68] [console] call hyper_new_container, json {"id":"28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31","rootfs":"rootfs","image":"28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31","process":{"terminal":true,"stdio":1,"args":["ifconfig"],"envs":[{"env":"PATH","value":"/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"},{"env":"HOSTNAME","value":"28f5d6a3f38a"},{"env":"TERM","value":"xterm"}],"workdir":"/"},"restartPolicy":"never","initialize":false}, len 449
I0612 13:36:30.785077 4542 init_comm.go:68] [console] next container 6
I0612 13:36:30.785255 4542 init_comm.go:68] [console] 1 name id
I0612 13:36:30.786088 4542 init_comm.go:68] [console] container id 28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31
I0612 13:36:30.786296 4542 init_comm.go:68] [console] 3 name rootfs
I0612 13:36:30.786601 4542 init_comm.go:68] [console] container rootfs rootfs
I0612 13:36:30.786801 4542 init_comm.go:68] [console] 5 name image
I0612 13:36:30.787679 4542 init_comm.go:68] [console] container image 28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31
I0612 13:36:30.787906 4542 init_comm.go:68] [console] 7 name process
I0612 13:36:30.788135 4542 init_comm.go:68] [console] 1 name terminal
I0612 13:36:30.788449 4542 init_comm.go:68] [console] container uses terminal
I0612 13:36:30.788636 4542 init_comm.go:68] [console] 3 name stdio
I0612 13:36:30.788848 4542 init_comm.go:68] [console] container seq 1
I0612 13:36:30.789019 4542 init_comm.go:68] [console] 5 name args
I0612 13:36:30.789368 4542 init_comm.go:68] [console] container init arg 0 ifconfig
I0612 13:36:30.789541 4542 init_comm.go:68] [console] 8 name envs
I0612 13:36:30.789703 4542 init_comm.go:68] [console] envs num 3
I0612 13:36:30.789914 4542 init_comm.go:68] [console] envs 0 env PATH
I0612 13:36:30.790698 4542 init_comm.go:68] [console] envs 0 value /usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
I0612 13:36:30.790962 4542 init_comm.go:68] [console] envs 1 env HOSTNAME
I0612 13:36:30.791275 4542 init_comm.go:68] [console] envs 1 value 28f5d6a3f38a
I0612 13:36:30.791487 4542 init_comm.go:68] [console] envs 2 env TERM
I0612 13:36:30.791727 4542 init_comm.go:68] [console] envs 2 value xterm
I0612 13:36:30.791938 4542 init_comm.go:68] [console] 25 name workdir
I0612 13:36:30.792188 4542 init_comm.go:68] [console] container workdir /
I0612 13:36:30.792459 4542 init_comm.go:68] [console] 35 name restartPolicy
I0612 13:36:30.792720 4542 init_comm.go:68] [console] restart policy never
I0612 13:36:30.792959 4542 init_comm.go:68] [console] 37 name initialize
I0612 13:36:30.798148 4542 init_comm.go:68] [console] create directory /tmp/hyper/28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31
I0612 13:36:30.799852 4542 init_comm.go:68] [console] create directory /tmp/hyper/28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31/devpts
I0612 13:36:30.801081 4542 init_comm.go:68] [console] create directory /tmp/hyper/28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31/devpts/
I0612 13:36:30.807156 4542 init_comm.go:68] [console] get pty device for exec /tmp/hyper/28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31/devpts//0
I0612 13:36:30.808255 4542 init_comm.go:68] [console] hyper_setup_exec_tty pts event 0xe9a8a8, fd 13 14
I0612 13:36:30.809154 4542 init_comm.go:68] [console] hyper_init_event container pts event 0xe9a8a8, ops 0x6184e0, fd 13
I0612 13:36:30.809823 4542 init_comm.go:68] [console] hyper_add_event add event fd 13, 0x6184e0
I0612 13:36:30.810710 4542 init_comm.go:68] [console] hyper_add_event add event fd 15, 0x6184a0
I0612 13:36:30.811400 4542 init_comm.go:68] [console] hyper_add_event add event fd 16, 0x618460
I0612 13:36:30.815841 4542 init_comm.go:68] [console] hyper_container_init in
I0612 13:36:30.817514 4542 init_comm.go:68] [console] path /sys/class/scsi_host/host0/scan
I0612 13:36:30.988837 4542 init_comm.go:68] [console] finish scan scsi
I0612 13:36:30.992397 4542 init_comm.go:68] [console] create directory /tmp/hyper/28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31/root
I0612 13:36:30.993626 4542 init_comm.go:68] [console] create directory /tmp/hyper/28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31/root/
I0612 13:36:30.996544 4542 init_comm.go:68] [console] container root directory /tmp/hyper/28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31/root/
I0612 13:36:30.998267 4542 init_comm.go:68] [console] src directory /tmp/hyper/shared/28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31/
I0612 13:36:31.001772 4542 init_comm.go:68] [console] root directory for container is /tmp/hyper/28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31/root//rootfs, init task ifconfig
I0612 13:36:31.003773 4542 init_comm.go:68] [console] create directory ./proc
I0612 13:36:31.007030 4542 init_comm.go:68] [console] create directory ./sys
I0612 13:36:31.009623 4542 init_comm.go:68] [console] create directory ./lib
I0612 13:36:31.010858 4542 init_comm.go:68] [console] create directory ./lib/modules
I0612 13:36:31.014446 4542 init_comm.go:68] [console] create directory ./dev/shm
I0612 13:36:31.019894 4542 init_comm.go:68] [console] create directory .//lib/modules/4.4.11-hyper
I0612 13:36:31.022810 4542 init_comm.go:68] [console] no dns configured
I0612 13:36:31.023898 4542 init_comm.go:68] [console] hyper send type 8, len 0
I0612 13:36:31.026449 4542 init_comm.go:68] [console] container 28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31,init pid 329,ref 4
I0612 13:36:31.026984 4542 init_comm.go:68] [console] hyper send type 8, len 0
I0612 13:36:31.030182 4542 init_comm.go:68] [console] hyper send type 9, len 0
I0612 13:36:31.030369 4542 init_comm.go:106] read 8/8 [length = 0]
I0612 13:36:31.030434 4542 init_comm.go:110] data length is 8
I0612 13:36:31.030471 4542 init_comm.go:96] trying to read 8 bytes
I0612 13:36:31.030513 4542 init_comm.go:190] got cmd:9
I0612 13:36:31.030553 4542 init_comm.go:209] ack got, clear pong timer
I0612 13:36:31.030591 4542 hypervisor.go:29] vm vm-VTsGRIKAqd: main event loop got message 31(COMMAND_ACK)
I0612 13:36:31.030627 4542 vm_states.go:562] [running] got init ack to &{17 859530828320 <nil> [] 859532999232}
I0612 13:36:31.030699 4542 vm_states.go:565] Get ack for new container
I0612 13:36:31.034795 4542 init_comm.go:68] [console] hyper_loop epoll_wait 1
I0612 13:36:31.035065 4542 init_comm.go:68] [console] hyper_handle_event get event 4, de 0xe9a8a8, fd 13. ops 0x6184e0
I0612 13:36:31.035126 4542 init_comm.go:68] [console] hyper_handle_event event EPOLLOUT, de 0xe9a8a8, fd 13, 0x6184e0
I0612 13:36:31.035174 4542 init_comm.go:68] [console] write_to_stdin, seq 1
I0612 13:36:31.035219 4542 init_comm.go:68] [console] hyper_modify_event modify event fd 13, 0xe9a8a8, event 1
I0612 13:36:31.035266 4542 init_comm.go:68] [console] hyper_dup_exec_tty
I0612 13:36:31.039326 4542 init_comm.go:68] [console] hyper_loop epoll_wait 3
I0612 13:36:31.040159 4542 init_comm.go:68] [console] hyper_handle_event get event 1, de 0xe9a918, fd 16. ops 0x618460
I0612 13:36:31.040934 4542 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, de 0xe9a918, fd 16, 0x618460
I0612 13:36:31.041302 4542 init_comm.go:68] [console] stderr_loop, seq 0
I0612 13:36:31.042348 4542 init_comm.go:68] [console] pts_loop: read 40 data
I0612 13:36:31.042908 4542 init_comm.go:68] [console] pts_loop: read -1 data
I0612 13:36:31.043643 4542 init_comm.go:68] [console] hyper_modify_event modify event fd 4, 0x618568, event 5
I0612 13:36:31.045460 4542 init_comm.go:68] [console] hyper_handle_event get event 1, de 0xe9a8e0, fd 15. ops 0x6184a0
I0612 13:36:31.050797 4542 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, de 0xe9a8e0, fd 15, 0x6184a0
I0612 13:36:31.051208 4542 init_comm.go:68] [console] stdout_loop, seq 1
I0612 13:36:31.051631 4542 init_comm.go:68] [console] pts_loop: read -1 data
I0612 13:36:31.052431 4542 init_comm.go:68] [console] hyper_handle_event get event 1, de 0xe9a8a8, fd 13. ops 0x6184e0
I0612 13:36:31.052879 4542 init_comm.go:68] [console] hyper_loop epoll_wait 1
I0612 13:36:31.053664 4542 init_comm.go:68] [console] hyper_handle_event get event 4, de 0x618568, fd 4. ops 0x618360
I0612 13:36:31.055262 4542 init_comm.go:68] [console] hyper_handle_event event EPOLLOUT, de 0x618568, fd 4, 0x618360
I0612 13:36:31.055573 4542 tty.go:97] tty: read 12/12 [length = 0]
I0612 13:36:31.055642 4542 tty.go:101] data length is 52
I0612 13:36:31.055676 4542 tty.go:87] tty: trying to read 40 bytes
I0612 13:36:31.055690 4542 tty.go:97] tty: read 52/52 [length = 52]
I0612 13:36:31.055965 4542 tty.go:87] tty: trying to read 12 bytes
I0612 13:36:31.057087 4542 init_comm.go:68] [console] hyper_modify_event modify event fd 4, 0x618568, event 1
I0612 13:36:31.058527 4542 init_comm.go:68] [console] pid 329 exit normally, status 127
I0612 13:36:31.058961 4542 init_comm.go:68] [console] exec pid 329, pid 329
I0612 13:36:31.060390 4542 init_comm.go:68] [console] hyper_handle_exec_exit exec exit pid 329, seq 1, container 28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31
I0612 13:36:31.061163 4542 init_comm.go:68] [console] still have 3 user of exec
I0612 13:36:31.061717 4542 init_comm.go:68] [console] container init process 329
I0612 13:36:31.068619 4542 init_comm.go:68] [console] hyper_loop epoll_wait -1
I0612 13:36:31.069761 4542 init_comm.go:68] [console] hyper_loop epoll_wait 3
I0612 13:36:31.070593 4542 init_comm.go:68] [console] hyper_handle_event get event 16, de 0xe9a918, fd 16. ops 0x618460
I0612 13:36:31.071417 4542 init_comm.go:68] [console] hyper_handle_event event EPOLLHUP, de 0xe9a918, fd 16, 0x618460
I0612 13:36:31.071717 4542 init_comm.go:68] [console] stderr_hup
I0612 13:36:31.072047 4542 init_comm.go:68] [console] pts_hup, seq 1
I0612 13:36:31.072733 4542 init_comm.go:68] [console] still have 2 user of exec
I0612 13:36:31.073561 4542 init_comm.go:68] [console] hyper_handle_event get event 16, de 0xe9a8e0, fd 15. ops 0x6184a0
I0612 13:36:31.075466 4542 init_comm.go:68] [console] hyper_handle_event event EPOLLHUP, de 0xe9a8e0, fd 15, 0x6184a0
I0612 13:36:31.076074 4542 init_comm.go:68] [console] stdout_hup
I0612 13:36:31.076406 4542 init_comm.go:68] [console] pts_hup, seq 1
I0612 13:36:31.076879 4542 init_comm.go:68] [console] still have 1 user of exec
I0612 13:36:31.077696 4542 init_comm.go:68] [console] hyper_handle_event get event 16, de 0xe9a8a8, fd 13. ops 0x6184e0
I0612 13:36:31.078474 4542 init_comm.go:68] [console] hyper_handle_event event EPOLLHUP, de 0xe9a8a8, fd 13, 0x6184e0
I0612 13:36:31.078741 4542 init_comm.go:68] [console] stdin_hup
I0612 13:36:31.079067 4542 init_comm.go:68] [console] pts_hup, seq 1
I0612 13:36:31.082428 4542 init_comm.go:68] [console] last user of exec exit, release
I0612 13:36:31.083396 4542 init_comm.go:68] [console] hyper_modify_event modify event fd 4, 0x618568, event 5
I0612 13:36:31.084732 4542 init_comm.go:68] [console] hyper_release_exec exit code 127
I0612 13:36:31.086235 4542 init_comm.go:68] [console] hyper_release_exec container init exited, type 17, remains 1, policy 0
I0612 13:36:31.086765 4542 init_comm.go:68] [console] hyper send type 13, len 4
I0612 13:36:31.086934 4542 init_comm.go:106] read 8/8 [length = 0]
I0612 13:36:31.086999 4542 init_comm.go:110] data length is 12
I0612 13:36:31.087033 4542 init_comm.go:96] trying to read 4 bytes
I0612 13:36:31.087184 4542 init_comm.go:106] read 12/12 [length = 12]
I0612 13:36:31.087232 4542 init_comm.go:96] trying to read 8 bytes
I0612 13:36:31.087275 4542 init_comm.go:190] got cmd:13
I0612 13:36:31.087323 4542 init_comm.go:246] Pod finished, returned 1 values
I0612 13:36:31.087362 4542 hypervisor.go:29] vm vm-VTsGRIKAqd: main event loop got message 4(EVENT_POD_FINISH)
I0612 13:36:31.087402 4542 context.go:212] VM vm-VTsGRIKAqd: state change from RUNNING to 'TERMINATING'
I0612 13:36:31.087442 4542 init_comm.go:190] got cmd:4
I0612 13:36:31.087481 4542 init_comm.go:281] send command 4 to init, payload: 'null'.
I0612 13:36:31.087521 4542 init_comm.go:294] write 12 to init, payload: '
null'.
I0612 13:36:31.087567 4542 init_comm.go:299] message sent, set pong timer
I0612 13:36:31.088332 4542 init_comm.go:68] [console] fopen /proc/327/status
I0612 13:36:31.092144 4542 init_comm.go:68] [console] find sigign 0000000000000000
I0612 13:36:31.092492 4542 init_comm.go:68] [console] mask is 0
I0612 13:36:31.105497 4542 init_comm.go:68] [console] open /tmp/hyper/resolv.conf failed: No such file or directory
I0612 13:36:31.106629 4542 init_comm.go:68] [console] hyper_loop epoll_wait 2
I0612 13:36:31.107443 4542 init_comm.go:68] [console] hyper_handle_event get event 4, de 0x618568, fd 4. ops 0x618360
I0612 13:36:31.108216 4542 init_comm.go:68] [console] hyper_handle_event event EPOLLOUT, de 0x618568, fd 4, 0x618360
I0612 13:36:31.108360 4542 tty.go:97] tty: read 12/12 [length = 0]
I0612 13:36:31.108419 4542 tty.go:101] data length is 12
I0612 13:36:31.108456 4542 tty.go:158] session 1 closed by peer, close pty
I0612 13:36:31.108488 4542 tty.go:87] tty: trying to read 12 bytes
I0612 13:36:31.108521 4542 tty.go:97] tty: read 12/12 [length = 0]
I0612 13:36:31.108531 4542 tty.go:101] data length is 13
I0612 13:36:31.108560 4542 tty.go:87] tty: trying to read 1 bytes
I0612 13:36:31.108572 4542 tty.go:97] tty: read 13/13 [length = 13]
I0612 13:36:31.108604 4542 tty.go:165] session 1, exit code 127
I0612 13:36:31.108636 4542 tty.go:233] Close tty 28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31-init
I0612 13:36:31.108776 4542 tty.go:87] tty: trying to read 12 bytes
I0612 13:36:31.108819 4542 tty.go:38] Got response: 8: Command finished
I0612 13:36:31.108853 4542 tty.go:41] Exit code 127
I0612 13:36:31.108865 4542 events.go:121] notifySubscribers: {28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31 exit 2016-06-12 13:36:31.108862227 -0400 EDT init 127}
I0612 13:36:31.112172 4542 events.go:54] write event log: {28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31 exit 2016-06-12 13:36:31.108862227 -0400 EDT init 127}
I0612 13:36:31.112292 4542 supervisor.go:115] reap container 28f5d6a3f38af20801cf9bd31146a66f8c4989c5936f543d044e47b55d83af31 processId init
I0612 13:36:31.112358 4542 hyperpod.go:396] StopPod fail: QEMU response data is nil
I0612 13:36:31.115802 4542 tty.go:382] a stdin closed, EOF
I0612 13:36:31.117559 4542 init_comm.go:68] [console] hyper_modify_event modify event fd 4, 0x618568, event 1
I0612 13:36:31.118396 4542 init_comm.go:68] [console] hyper_handle_event get event 1, de 0x6185a0, fd 3. ops 0x6183a0
I0612 13:36:31.119175 4542 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, de 0x6185a0, fd 3, 0x6183a0
I0612 13:36:31.119499 4542 init_comm.go:68] [console] hyper_event_read
I0612 13:36:31.120069 4542 init_comm.go:68] [console] already read 8 bytes data
I0612 13:36:31.120483 4542 init_comm.go:68] [console] hyper send type 14, len 4
I0612 13:36:31.120621 4542 init_comm.go:106] read 8/8 [length = 0]
I0612 13:36:31.120667 4542 init_comm.go:110] data length is 12
I0612 13:36:31.120698 4542 init_comm.go:96] trying to read 4 bytes
I0612 13:36:31.120832 4542 init_comm.go:106] read 12/12 [length = 12]
I0612 13:36:31.120890 4542 init_comm.go:96] trying to read 8 bytes
I0612 13:36:31.120929 4542 init_comm.go:190] got cmd:14
I0612 13:36:31.120959 4542 init_comm.go:253] get command NEXT
I0612 13:36:31.120982 4542 init_comm.go:256] send 12, receive 8
I0612 13:36:31.121260 4542 init_comm.go:68] [console] get length 12
I0612 13:36:31.121753 4542 init_comm.go:68] [console] read 4 bytes data, total data 12
I0612 13:36:31.122140 4542 init_comm.go:68] [console] hyper send type 14, len 4
I0612 13:36:31.122254 4542 init_comm.go:106] read 8/8 [length = 0]
I0612 13:36:31.122297 4542 init_comm.go:110] data length is 12
I0612 13:36:31.122319 4542 init_comm.go:96] trying to read 4 bytes
I0612 13:36:31.122428 4542 init_comm.go:106] read 12/12 [length = 12]
I0612 13:36:31.122472 4542 init_comm.go:96] trying to read 8 bytes
I0612 13:36:31.122510 4542 init_comm.go:190] got cmd:14
I0612 13:36:31.122535 4542 init_comm.go:253] get command NEXT
I0612 13:36:31.122557 4542 init_comm.go:256] send 12, receive 12
I0612 13:36:31.123012 4542 init_comm.go:68] [console] 0 0 0 4 0 0 0 c 6e 75 6c 6c
I0612 13:36:31.123521 4542 init_comm.go:68] [console] hyper_channel_handle, type 4, len 12
I0612 13:36:31.123890 4542 init_comm.go:68] [console] get DESTROYPOD message
I0612 13:36:31.127844 4542 init_comm.go:68] [console] hyper send type 9, len 0
I0612 13:36:31.130506 4542 init_comm.go:106] read 8/8 [length = 0]
I0612 13:36:31.130576 4542 init_comm.go:110] data length is 8
I0612 13:36:31.130591 4542 init_comm.go:96] trying to read 8 bytes
I0612 13:36:31.130630 4542 init_comm.go:190] got cmd:9
I0612 13:36:31.130668 4542 init_comm.go:194] got response of shutdown command, last round of command to init
I0612 13:36:31.130703 4542 init_comm.go:209] ack got, clear pong timer
I0612 13:36:31.130740 4542 hypervisor.go:29] vm vm-VTsGRIKAqd: main event loop got message 31(COMMAND_ACK)
I0612 13:36:31.130776 4542 vm_states.go:639] [Terminating] Got reply to &{4 <nil> <nil> [] 859533000000}: ''
I0612 13:36:31.130821 4542 vm_states.go:641] POD destroyed
I0612 13:36:31.130893 4542 qmp_handler.go:296] got new session
I0612 13:36:31.130960 4542 qmp_handler.go:225] Begin process command session
I0612 13:36:31.131017 4542 qmp_handler.go:243] sending command (1) {"execute":"quit"}
I0612 13:36:31.131360 4542 qmp_handler.go:103] got a message {"return": {}}
I0612 13:36:31.131842 4542 qmp_handler.go:103] got a message {"timestamp": {"seconds": 1465752991, "microseconds": 131265}, "event": "SHUTDOWN"}
I0612 13:36:31.131899 4542 qmp_handler.go:107] got event: SHUTDOWN
I0612 13:36:31.131937 4542 qmp_handler.go:152] Shutdown, quit QMP receiver
I0612 13:36:31.131974 4542 qmp_handler.go:323] got QMP event SHUTDOWN
I0612 13:36:31.132006 4542 qmp_handler.go:325] got QMP shutdown event, quit...
I0612 13:36:31.132041 4542 hypervisor.go:29] vm vm-VTsGRIKAqd: main event loop got message 1(EVENT_VM_EXIT)
I0612 13:36:31.132076 4542 vm_states.go:623] Got VM shutdown event while terminating, go to cleaning up
I0612 13:36:31.132108 4542 vm_states.go:36] VM has exit...
I0612 13:36:31.132143 4542 context.go:199] no more device to release/remove/umount, quit
I0612 13:36:31.132189 4542 qemu_process.go:19] quit watch dog.
E0612 13:36:31.137354 4542 init_comm.go:99] read init data failed
E0612 13:36:31.137555 4542 tty.go:90] read tty data failed
I0612 13:36:31.137571 4542 tty.go:151] tty socket closed, quit the reading goroutine EOF
I0612 13:36:31.137593 4542 tty.go:118] tty chan closed, quit sent goroutine
I0612 13:36:31.137651 4542 tty.go:428] Input byte chan closed, close the output string chan
I0612 13:36:31.137666 4542 init_comm.go:70] console output end
gao-feng
laijs
runv commit dbc1d243b3040d887aef0849c78999792bd0fe0c upstream.
runv-containerd version 0.01