search

hyperhq / runv

Hypervisor-based Runtime for OCI
Apache License 2.0
827 stars 129 forks source link

runv-containerd can't get network configure from docker #241

Closed WeiZhang555 closed 8 years ago

WeiZhang555 commented 8 years ago

docker run -tid busybox sh:

runv-containerd log:

I0526 17:46:15.539427   22828 server.go:31] gRPC handle CreateContainer
I0526 17:46:15.540419   22828 hypervisor.go:29] vm vm-pEwxFWdQnA: main event loop got message 21(COMMAND_RUN_POD)
I0526 17:46:15.540502   22828 vm_states.go:449] got spec, prepare devices
I0526 17:46:15.540536   22828 vm_states.go:67] initial vm spec: {
        "hostname": "68988a52009d",
        "containers": [],
        "shareDir": "share_dir"
    }
I0526 17:46:15.540568   22828 context.go:211] VM vm-pEwxFWdQnA: state change from INIT to 'STARTING'
I0526 17:46:15.540582   22828 hypervisor.go:29] vm vm-pEwxFWdQnA: main event loop got message 10(EVENT_DEV_SKIP)
I0526 17:46:15.540594   22828 vm_states.go:476] device ready, could run pod.
I0526 17:46:15.540475   22828 qemu_process.go:63] cmdline arguments: -machine pc-i440fx-2.0,accel=kvm,usb=off -global kvm-pit.lost_tick_policy=discard -cpu host -kernel /var/lib/hyper/kernel -initrd /var/lib/hyper/hyper-initrd.img -append console=ttyS0 panic=1 no_timer_check -realtime mlock=off -no-user-config -nodefaults -no-hpet -rtc base=utc,driftfix=slew -no-reboot -display none -boot strict=on -m 128 -smp 1 -qmp unix:/var/run/hyper/vm-pEwxFWdQnA/qmp.sock,server,nowait -serial unix:/var/run/hyper/vm-pEwxFWdQnA/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-pEwxFWdQnA/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-pEwxFWdQnA/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-pEwxFWdQnA/share_dir,security_model=none -device virtio-9p-pci,fsdev=virtio9p,mount_tag=share_dir
I0526 17:46:15.540345   22828 vm.go:179] hyperHandlePodEvent pod pod-cRZjBcrYMI, vm vm-pEwxFWdQnA
I0526 17:46:15.562283   22828 qemu_process.go:74] starting daemon with pid: 23570
I0526 17:46:15.580748   22828 init_comm.go:53] connected to /var/run/hyper/vm-pEwxFWdQnA/console.sock
I0526 17:46:15.580869   22828 init_comm.go:60] connected /var/run/hyper/vm-pEwxFWdQnA/console.sock as telnet mode.
I0526 17:46:15.580792   22828 tty.go:144] tty socket connected
I0526 17:46:15.580924   22828 tty.go:87] tty: trying to read 12 bytes
I0526 17:46:15.580833   22828 qmp_handler.go:167] connected to /var/run/hyper/vm-pEwxFWdQnA/qmp.sock
I0526 17:46:15.580948   22828 qmp_handler.go:177] begin qmp init...
I0526 17:46:15.580871   22828 init_comm.go:133] Wating for init messages...
I0526 17:46:15.580973   22828 init_comm.go:96] trying to read 8 bytes
I0526 17:46:15.617682   22828 qmp_handler.go:186] got qmp welcome, now sending command qmp_capabilities
I0526 17:46:15.617736   22828 qmp_handler.go:201] waiting for response
I0526 17:46:15.628141   22828 qmp_handler.go:103] got a message {"return": {}}
I0526 17:46:15.628246   22828 qmp_handler.go:210] got for response
I0526 17:46:15.628284   22828 qmp_handler.go:213] QMP connection initialized
I0526 17:46:15.628340   22828 qmp_handler.go:346] QMP initialzed, go into main QMP loop
I0526 17:46:15.628385   22828 qmp_handler.go:137] Begin receive QMP message
I0526 17:46:17.171967   22828 init_comm.go:68] [console] Initializing cgroup subsys cpuset
I0526 17:46:17.172231   22828 init_comm.go:68] [console] Initializing cgroup subsys cpu
I0526 17:46:17.172564   22828 init_comm.go:68] [console] Initializing cgroup subsys cpuacct
I0526 17:46:17.173795   22828 init_comm.go:68] [console] Linux version 4.4.7-hyper+ (bergwolf@vmfarm) (gcc version 5.2.1 20151010 (Ubuntu 5.2.1-22ubuntu2) ) #10 SMP Wed May 4 17:03:36 CST 2016
I0526 17:46:17.174264   22828 init_comm.go:68] [console] Command line: console=ttyS0 panic=1 no_timer_check
I0526 17:46:17.174777   22828 init_comm.go:68] [console] x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256
I0526 17:46:17.175433   22828 init_comm.go:68] [console] x86/fpu: Supporting XSAVE feature 0x01: 'x87 floating point registers'
I0526 17:46:17.175949   22828 init_comm.go:68] [console] x86/fpu: Supporting XSAVE feature 0x02: 'SSE registers'
I0526 17:46:17.176465   22828 init_comm.go:68] [console] x86/fpu: Supporting XSAVE feature 0x04: 'AVX registers'
I0526 17:46:17.177292   22828 init_comm.go:68] [console] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format.
I0526 17:46:17.177704   22828 init_comm.go:68] [console] x86/fpu: Using 'eager' FPU context switches.
I0526 17:46:17.178061   22828 init_comm.go:68] [console] e820: BIOS-provided physical RAM map:
I0526 17:46:17.178634   22828 init_comm.go:68] [console] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
I0526 17:46:17.179225   22828 init_comm.go:68] [console] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
I0526 17:46:17.179822   22828 init_comm.go:68] [console] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
I0526 17:46:17.180394   22828 init_comm.go:68] [console] BIOS-e820: [mem 0x0000000000100000-0x0000000007ffdfff] usable
I0526 17:46:17.180985   22828 init_comm.go:68] [console] BIOS-e820: [mem 0x0000000007ffe000-0x0000000007ffffff] reserved
I0526 17:46:17.181564   22828 init_comm.go:68] [console] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved
I0526 17:46:17.182151   22828 init_comm.go:68] [console] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
I0526 17:46:17.182523   22828 init_comm.go:68] [console] NX (Execute Disable) protection: active
I0526 17:46:17.182709   22828 init_comm.go:68] [console] SMBIOS 2.4 present.
I0526 17:46:17.182944   22828 init_comm.go:68] [console] Hypervisor detected: KVM
I0526 17:46:17.195427   22828 init_comm.go:68] [console] e820: last_pfn = 0x7ffe max_arch_pfn = 0x400000000
I0526 17:46:17.196012   22828 init_comm.go:68] [console] x86/PAT: Configuration [0-7]: WB  WC  UC- UC  WB  WC  UC- WT  
I0526 17:46:17.196738   22828 init_comm.go:68] [console] found SMP MP-table at [mem 0x000f64b0-0x000f64bf] mapped at [ffff8800000f64b0]
I0526 17:46:17.197084   22828 init_comm.go:68] [console] RAMDISK: [mem 0x07dda000-0x07feffff]
I0526 17:46:17.197540   22828 init_comm.go:68] [console] ACPI: Early table checksum verification disabled
I0526 17:46:17.198009   22828 init_comm.go:68] [console] ACPI: RSDP 0x00000000000F6330 000014 (v00 BOCHS )
I0526 17:46:17.198763   22828 init_comm.go:68] [console] ACPI: RSDT 0x0000000007FFF688 000030 (v01 BOCHS  BXPCRSDT 00000001 BXPC 00000001)
I0526 17:46:17.199524   22828 init_comm.go:68] [console] ACPI: FACP 0x0000000007FFEBDA 000074 (v01 BOCHS  BXPCFACP 00000001 BXPC 00000001)
I0526 17:46:17.200282   22828 init_comm.go:68] [console] ACPI: DSDT 0x0000000007FFE040 000B9A (v01 BOCHS  BXPCDSDT 00000001 BXPC 00000001)
I0526 17:46:17.200622   22828 init_comm.go:68] [console] ACPI: FACS 0x0000000007FFE000 000040
I0526 17:46:17.201380   22828 init_comm.go:68] [console] ACPI: SSDT 0x0000000007FFEC4E 0009C2 (v01 BOCHS  BXPCSSDT 00000001 BXPC 00000001)
I0526 17:46:17.202139   22828 init_comm.go:68] [console] ACPI: APIC 0x0000000007FFF610 000078 (v01 BOCHS  BXPCAPIC 00000001 BXPC 00000001)
I0526 17:46:17.202399   22828 init_comm.go:68] [console] No NUMA configuration found
I0526 17:46:17.202953   22828 init_comm.go:68] [console] Faking a node at [mem 0x0000000000000000-0x0000000007ffdfff]
I0526 17:46:17.203434   22828 init_comm.go:68] [console] NODE_DATA(0) allocated [mem 0x07dc8000-0x07dd9fff]
I0526 17:46:17.203839   22828 init_comm.go:68] [console] kvm-clock: Using msrs 4b564d01 and 4b564d00
I0526 17:46:17.204304   22828 init_comm.go:68] [console] kvm-clock: cpu 0, msr 0:7ffd001, primary cpu clock
I0526 17:46:17.204775   22828 init_comm.go:68] [console] kvm-clock: using sched offset of 1431406850 cycles
I0526 17:46:17.205732   22828 init_comm.go:68] [console] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
I0526 17:46:17.205861   22828 init_comm.go:68] [console] Zone ranges:
I0526 17:46:17.206362   22828 init_comm.go:68] [console]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
I0526 17:46:17.206873   22828 init_comm.go:68] [console]   DMA32    [mem 0x0000000001000000-0x0000000007ffdfff]
I0526 17:46:17.207042   22828 init_comm.go:68] [console]   Normal   empty
I0526 17:46:17.207353   22828 init_comm.go:68] [console] Movable zone start for each node
I0526 17:46:17.219602   22828 init_comm.go:68] [console] Early memory node ranges
I0526 17:46:17.220117   22828 init_comm.go:68] [console]   node   0: [mem 0x0000000000001000-0x000000000009efff]
I0526 17:46:17.220632   22828 init_comm.go:68] [console]   node   0: [mem 0x0000000000100000-0x0000000007ffdfff]
I0526 17:46:17.221224   22828 init_comm.go:68] [console] Initmem setup node 0 [mem 0x0000000000001000-0x0000000007ffdfff]
I0526 17:46:17.221514   22828 init_comm.go:68] [console] ACPI: PM-Timer IO Port: 0x608
I0526 17:46:17.221964   22828 init_comm.go:68] [console] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
I0526 17:46:17.222543   22828 init_comm.go:68] [console] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
I0526 17:46:17.223070   22828 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
I0526 17:46:17.223617   22828 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
I0526 17:46:17.224169   22828 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
I0526 17:46:17.224735   22828 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
I0526 17:46:17.225306   22828 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
I0526 17:46:17.225785   22828 init_comm.go:68] [console] Using ACPI (MADT) for SMP configuration information
I0526 17:46:17.226158   22828 init_comm.go:68] [console] smpboot: Allowing 1 CPUs, 0 hotplug CPUs
I0526 17:46:17.226705   22828 init_comm.go:68] [console] e820: [mem 0x08000000-0xfeffbfff] available for PCI devices
I0526 17:46:17.227055   22828 init_comm.go:68] [console] Booting paravirtualized kernel on KVM
I0526 17:46:17.228004   22828 init_comm.go:68] [console] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
I0526 17:46:17.228633   22828 init_comm.go:68] [console] setup_percpu: NR_CPUS:8 nr_cpumask_bits:8 nr_cpu_ids:1 nr_node_ids:1
I0526 17:46:17.229344   22828 init_comm.go:68] [console] PERCPU: Embedded 31 pages/cpu @ffff880007a00000 s89496 r8192 d29288 u2097152
I0526 17:46:17.229612   22828 init_comm.go:68] [console] KVM setup async PF for cpu 0
I0526 17:46:17.229933   22828 init_comm.go:68] [console] kvm-stealtime: cpu 0, msr 7a0d480
I0526 17:46:17.230619   22828 init_comm.go:68] [console] Built 1 zonelists in Node order, mobility grouping on.  Total pages: 32135
I0526 17:46:17.230800   22828 init_comm.go:68] [console] Policy zone: DMA32
I0526 17:46:17.231335   22828 init_comm.go:68] [console] Kernel command line: console=ttyS0 panic=1 no_timer_check
I0526 17:46:17.243816   22828 init_comm.go:68] [console] PID hash table entries: 512 (order: 0, 4096 bytes)
I0526 17:46:17.245050   22828 init_comm.go:68] [console] Memory: 118064K/130672K available (4306K kernel code, 548K rwdata, 1400K rodata, 860K init, 756K bss, 12608K reserved, 0K cma-reserved)
I0526 17:46:17.245341   22828 init_comm.go:68] [console] Hierarchical RCU implementation.
I0526 17:46:17.245752   22828 init_comm.go:68] [console]    Build-time adjustment of leaf fanout to 64.
I0526 17:46:17.246233   22828 init_comm.go:68] [console]    RCU restricting CPUs from NR_CPUS=8 to nr_cpu_ids=1.
I0526 17:46:17.246781   22828 init_comm.go:68] [console] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=1
I0526 17:46:17.247045   22828 init_comm.go:68] [console] NR_IRQS:4352 nr_irqs:256 16
I0526 17:46:17.247300   22828 init_comm.go:68] [console] Console: colour *CGA 80x25
I0526 17:46:17.247534   22828 init_comm.go:68] [console] console [ttyS0] enabled
I0526 17:46:17.247937   22828 init_comm.go:68] [console] tsc: Detected 3092.974 MHz processor
I0526 17:46:17.248677   22828 init_comm.go:68] [console] Calibrating delay loop (skipped) preset value.. 6185.94 BogoMIPS (lpj=3092974)
I0526 17:46:17.249023   22828 init_comm.go:68] [console] pid_max: default: 32768 minimum: 301
I0526 17:46:17.249306   22828 init_comm.go:68] [console] ACPI: Core revision 20150930
I0526 17:46:17.250738   22828 init_comm.go:68] [console] ACPI: 2 ACPI AML tables successfully acquired and loaded
I0526 17:46:17.251370   22828 init_comm.go:68] [console] Dentry cache hash table entries: 16384 (order: 5, 131072 bytes)
I0526 17:46:17.252016   22828 init_comm.go:68] [console] Inode-cache hash table entries: 8192 (order: 4, 65536 bytes)
I0526 17:46:17.252622   22828 init_comm.go:68] [console] Mount-cache hash table entries: 512 (order: 0, 4096 bytes)
I0526 17:46:17.253228   22828 init_comm.go:68] [console] Mountpoint-cache hash table entries: 512 (order: 0, 4096 bytes)
I0526 17:46:17.253767   22828 init_comm.go:68] [console] Initializing cgroup subsys io
I0526 17:46:17.254101   22828 init_comm.go:68] [console] Initializing cgroup subsys memory
I0526 17:46:17.254450   22828 init_comm.go:68] [console] Initializing cgroup subsys devices
I0526 17:46:17.254784   22828 init_comm.go:68] [console] Initializing cgroup subsys freezer
I0526 17:46:17.255135   22828 init_comm.go:68] [console] Initializing cgroup subsys net_cls
I0526 17:46:17.267508   22828 init_comm.go:68] [console] Initializing cgroup subsys perf_event
I0526 17:46:17.267810   22828 init_comm.go:68] [console] Initializing cgroup subsys pids
I0526 17:46:17.268127   22828 init_comm.go:68] [console] Initializing cgroup subsys debug
I0526 17:46:17.268659   22828 init_comm.go:68] [console] Last level iTLB entries: 4KB 512, 2MB 8, 4MB 8
I0526 17:46:17.269185   22828 init_comm.go:68] [console] Last level dTLB entries: 4KB 512, 2MB 32, 4MB 32, 1GB 0
I0526 17:46:17.291237   22828 init_comm.go:68] [console] Freeing SMP alternatives memory: 20K (ffffffff816f6000 - ffffffff816fb000)
I0526 17:46:17.300636   22828 init_comm.go:68] [console] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
I0526 17:46:17.301564   22828 init_comm.go:68] [console] smpboot: CPU0: Intel(R) Core(TM) i5-2400 CPU @ 3.10GHz (family: 0x6, model: 0x2a, stepping: 0x7)
I0526 17:46:17.302316   22828 init_comm.go:68] [console] Performance Events: 16-deep LBR, SandyBridge events, Intel PMU driver.
I0526 17:46:17.302993   22828 init_comm.go:68] [console] perf_event_intel: PEBS disabled due to CPU errata, please upgrade microcode
I0526 17:46:17.303286   22828 init_comm.go:68] [console] ... version:                2
I0526 17:46:17.307588   22828 init_comm.go:68] [console] ... bit width:              48
I0526 17:46:17.307874   22828 init_comm.go:68] [console] ... generic registers:      8
I0526 17:46:17.308269   22828 init_comm.go:68] [console] ... value mask:             0000ffffffffffff
I0526 17:46:17.308679   22828 init_comm.go:68] [console] ... max period:             000000007fffffff
I0526 17:46:17.308968   22828 init_comm.go:68] [console] ... fixed-purpose events:   3
I0526 17:46:17.309356   22828 init_comm.go:68] [console] ... event mask:             00000007000000ff
I0526 17:46:17.309915   22828 init_comm.go:68] [console] x86: Booted up 1 node, 1 CPUs
I0526 17:46:17.310460   22828 init_comm.go:68] [console] smpboot: Total of 1 processors activated (6185.94 BogoMIPS)
I0526 17:46:17.311196   22828 init_comm.go:68] [console] devtmpfs: initialized
I0526 17:46:17.321866   22828 init_comm.go:68] [console] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
I0526 17:46:17.322861   22828 init_comm.go:68] [console] NET: Registered protocol family 16
I0526 17:46:17.323554   22828 init_comm.go:68] [console] cpuidle: using governor ladder
I0526 17:46:17.324146   22828 init_comm.go:68] [console] cpuidle: using governor menu
I0526 17:46:17.324753   22828 init_comm.go:68] [console] ACPI: bus type PCI registered
I0526 17:46:17.325324   22828 init_comm.go:68] [console] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
I0526 17:46:17.326246   22828 init_comm.go:68] [console] PCI: Using configuration type 1 for base access
I0526 17:46:17.327826   22828 init_comm.go:68] [console] perf_event_intel: PMU erratum BJ122, BV98, HSD29 workaround disabled, HT off
I0526 17:46:17.331997   22828 init_comm.go:68] [console] ACPI: Added _OSI(Module Device)
I0526 17:46:17.332788   22828 init_comm.go:68] [console] ACPI: Added _OSI(Processor Device)
I0526 17:46:17.333646   22828 init_comm.go:68] [console] ACPI: Added _OSI(3.0 _SCP Extensions)
I0526 17:46:17.334673   22828 init_comm.go:68] [console] ACPI: Added _OSI(Processor Aggregator Device)
I0526 17:46:17.347770   22828 init_comm.go:68] [console] ACPI: Interpreter enabled
I0526 17:46:17.348329   22828 init_comm.go:68] [console] ACPI: (supports S0 S5)
I0526 17:46:17.349249   22828 init_comm.go:68] [console] ACPI: Using IOAPIC for interrupt routing
I0526 17:46:17.351196   22828 init_comm.go:68] [console] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
I0526 17:46:17.354573   22828 init_comm.go:68] [console] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
I0526 17:46:17.355989   22828 init_comm.go:68] [console] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI]
I0526 17:46:17.357335   22828 init_comm.go:68] [console] acpi PNP0A03:00: _OSC failed (AE_NOT_FOUND); disabling ASPM
I0526 17:46:17.358110   22828 init_comm.go:68] [console] acpiphp: Slot [2] registered
I0526 17:46:17.358809   22828 init_comm.go:68] [console] acpiphp: Slot [3] registered
I0526 17:46:17.359530   22828 init_comm.go:68] [console] acpiphp: Slot [4] registered
I0526 17:46:17.360351   22828 init_comm.go:68] [console] acpiphp: Slot [5] registered
I0526 17:46:17.361158   22828 init_comm.go:68] [console] acpiphp: Slot [6] registered
I0526 17:46:17.361963   22828 init_comm.go:68] [console] acpiphp: Slot [7] registered
I0526 17:46:17.362763   22828 init_comm.go:68] [console] acpiphp: Slot [8] registered
I0526 17:46:17.363564   22828 init_comm.go:68] [console] acpiphp: Slot [9] registered
I0526 17:46:17.364390   22828 init_comm.go:68] [console] acpiphp: Slot [10] registered
I0526 17:46:17.365211   22828 init_comm.go:68] [console] acpiphp: Slot [11] registered
I0526 17:46:17.366038   22828 init_comm.go:68] [console] acpiphp: Slot [12] registered
I0526 17:46:17.366865   22828 init_comm.go:68] [console] acpiphp: Slot [13] registered
I0526 17:46:17.367695   22828 init_comm.go:68] [console] acpiphp: Slot [14] registered
I0526 17:46:17.380071   22828 init_comm.go:68] [console] acpiphp: Slot [15] registered
I0526 17:46:17.380912   22828 init_comm.go:68] [console] acpiphp: Slot [16] registered
I0526 17:46:17.381735   22828 init_comm.go:68] [console] acpiphp: Slot [17] registered
I0526 17:46:17.382565   22828 init_comm.go:68] [console] acpiphp: Slot [18] registered
I0526 17:46:17.383387   22828 init_comm.go:68] [console] acpiphp: Slot [19] registered
I0526 17:46:17.384223   22828 init_comm.go:68] [console] acpiphp: Slot [20] registered
I0526 17:46:17.385047   22828 init_comm.go:68] [console] acpiphp: Slot [21] registered
I0526 17:46:17.385872   22828 init_comm.go:68] [console] acpiphp: Slot [22] registered
I0526 17:46:17.386692   22828 init_comm.go:68] [console] acpiphp: Slot [23] registered
I0526 17:46:17.387529   22828 init_comm.go:68] [console] acpiphp: Slot [24] registered
I0526 17:46:17.388356   22828 init_comm.go:68] [console] acpiphp: Slot [25] registered
I0526 17:46:17.389182   22828 init_comm.go:68] [console] acpiphp: Slot [26] registered
I0526 17:46:17.390008   22828 init_comm.go:68] [console] acpiphp: Slot [27] registered
I0526 17:46:17.390835   22828 init_comm.go:68] [console] acpiphp: Slot [28] registered
I0526 17:46:17.391665   22828 init_comm.go:68] [console] acpiphp: Slot [29] registered
I0526 17:46:17.392494   22828 init_comm.go:68] [console] acpiphp: Slot [30] registered
I0526 17:46:17.393326   22828 init_comm.go:68] [console] acpiphp: Slot [31] registered
I0526 17:46:17.394162   22828 init_comm.go:68] [console] PCI host bridge to bus 0000:00
I0526 17:46:17.395704   22828 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7 window]
I0526 17:46:17.397250   22828 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [io  0x0d00-0xffff window]
I0526 17:46:17.398977   22828 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
I0526 17:46:17.400712   22828 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [mem 0x08000000-0xfebfffff window]
I0526 17:46:17.401908   22828 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [bus 00-ff]
I0526 17:46:17.418268   22828 init_comm.go:68] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io  0x01f0-0x01f7]
I0526 17:46:17.418369   22828 init_comm.go:68] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io  0x03f6]
I0526 17:46:17.418406   22828 init_comm.go:68] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io  0x0170-0x0177]
I0526 17:46:17.418437   22828 init_comm.go:68] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io  0x0376]
I0526 17:46:17.419420   22828 init_comm.go:68] [console] pci 0000:00:01.3: quirk: [io  0x0600-0x063f] claimed by PIIX4 ACPI
I0526 17:46:17.421039   22828 init_comm.go:68] [console] pci 0000:00:01.3: quirk: [io  0x0700-0x070f] claimed by PIIX4 SMB
I0526 17:46:17.460650   22828 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11)
I0526 17:46:17.462117   22828 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 *10 11)
I0526 17:46:17.463485   22828 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 10 *11)
I0526 17:46:17.464845   22828 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 10 *11)
I0526 17:46:17.466007   22828 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKS] (IRQs *9)
I0526 17:46:17.467295   22828 init_comm.go:68] [console] ACPI: Enabled 16 GPEs in block 00 to 0F
I0526 17:46:17.467867   22828 init_comm.go:68] [console] vgaarb: loaded
I0526 17:46:17.468665   22828 init_comm.go:68] [console] SCSI subsystem initialized
I0526 17:46:17.469545   22828 init_comm.go:68] [console] PCI: Using ACPI for IRQ routing
I0526 17:46:17.470967   22828 init_comm.go:68] [console] clocksource: Switched to clocksource kvm-clock
I0526 17:46:17.471617   22828 init_comm.go:68] [console] pnp: PnP ACPI init
I0526 17:46:17.472813   22828 init_comm.go:68] [console] pnp: PnP ACPI: found 5 devices
I0526 17:46:17.521474   22828 init_comm.go:68] [console] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
I0526 17:46:17.522508   22828 init_comm.go:68] [console] NET: Registered protocol family 2
I0526 17:46:17.524250   22828 init_comm.go:68] [console] TCP established hash table entries: 1024 (order: 1, 8192 bytes)
I0526 17:46:17.525716   22828 init_comm.go:68] [console] TCP bind hash table entries: 1024 (order: 2, 16384 bytes)
I0526 17:46:17.527156   22828 init_comm.go:68] [console] TCP: Hash tables configured (established 1024 bind 1024)
I0526 17:46:17.528500   22828 init_comm.go:68] [console] UDP hash table entries: 256 (order: 1, 8192 bytes)
I0526 17:46:17.529919   22828 init_comm.go:68] [console] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes)
I0526 17:46:17.530875   22828 init_comm.go:68] [console] NET: Registered protocol family 1
I0526 17:46:17.532207   22828 init_comm.go:68] [console] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
I0526 17:46:17.533484   22828 init_comm.go:68] [console] pci 0000:00:01.0: PIIX3: Enabling Passive Release
I0526 17:46:17.534858   22828 init_comm.go:68] [console] pci 0000:00:01.0: Activating ISA DMA hang workarounds
I0526 17:46:17.536128   22828 init_comm.go:68] [console] Trying to unpack rootfs image as initramfs...
I0526 17:46:17.575384   22828 init_comm.go:68] [console] Freeing initrd memory: 2136K (ffff880007dda000 - ffff880007ff0000)
I0526 17:46:17.577117   22828 init_comm.go:68] [console] futex hash table entries: 256 (order: 2, 16384 bytes)
I0526 17:46:17.578890   22828 init_comm.go:68] [console] SGI XFS with ACLs, security attributes, no debug enabled
I0526 17:46:17.580306   22828 init_comm.go:68] [console] 9p: Installing v9fs 9p2000 file system support
I0526 17:46:17.583519   22828 init_comm.go:68] [console] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 253)
I0526 17:46:17.584310   22828 init_comm.go:68] [console] io scheduler noop registered
I0526 17:46:17.585317   22828 init_comm.go:68] [console] io scheduler cfq registered (default)
I0526 17:46:17.586582   22828 init_comm.go:68] [console] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
I0526 17:46:17.588097   22828 init_comm.go:68] [console] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
I0526 17:46:17.589847   22828 init_comm.go:68] [console] Warning: Processor Platform Limit event detected, but not handled.
I0526 17:46:17.591182   22828 init_comm.go:68] [console] Consider compiling CPUfreq support into your kernel.
I0526 17:46:17.612244   22828 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKB] enabled at IRQ 10
I0526 17:46:17.613874   22828 init_comm.go:68] [console] virtio-pci 0000:00:02.0: virtio_pci: leaving for legacy driver
I0526 17:46:17.635136   22828 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 11
I0526 17:46:17.636764   22828 init_comm.go:68] [console] virtio-pci 0000:00:03.0: virtio_pci: leaving for legacy driver
I0526 17:46:17.657712   22828 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 11
I0526 17:46:17.659346   22828 init_comm.go:68] [console] virtio-pci 0000:00:04.0: virtio_pci: leaving for legacy driver
I0526 17:46:17.661192   22828 init_comm.go:68] [console] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
I0526 17:46:17.748385   22828 init_comm.go:68] [console] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
I0526 17:46:17.852834   22828 init_comm.go:68] [console] brd: module loaded
I0526 17:46:17.853038   22828 init_comm.go:68] [console] loop: module loaded
I0526 17:46:17.885837   22828 init_comm.go:68] [console] scsi host0: Virtio SCSI HBA
I0526 17:46:17.946483   22828 init_comm.go:68] [console] rtc_cmos 00:00: RTC can wake from S4
I0526 17:46:17.947186   22828 init_comm.go:68] [console] rtc_cmos 00:00: rtc core: registered rtc_cmos as rtc0
I0526 17:46:17.947774   22828 init_comm.go:68] [console] rtc_cmos 00:00: alarms up to one day, 114 bytes nvram
I0526 17:46:17.948176   22828 init_comm.go:68] [console] NET: Registered protocol family 10
I0526 17:46:17.948665   22828 init_comm.go:68] [console] NET: Registered protocol family 17
I0526 17:46:17.948987   22828 init_comm.go:68] [console] 9pnet: Installing 9P2000 support
I0526 17:46:17.993684   22828 init_comm.go:68] [console] registered taskstats version 1
I0526 17:46:17.994626   22828 init_comm.go:68] [console] rtc_cmos 00:00: setting system clock to 2016-05-26 09:46:17 UTC (1464255977)
I0526 17:46:17.995994   22828 init_comm.go:68] [console] Freeing unused kernel memory: 860K (ffffffff8161f000 - ffffffff816f6000)
I0526 17:46:17.996554   22828 init_comm.go:68] [console] create directory /sys
I0526 17:46:17.996789   22828 init_comm.go:68] [console] create directory /sbin
I0526 17:46:17.997030   22828 init_comm.go:68] [console] create directory /proc
I0526 17:46:17.997249   22828 init_comm.go:68] [console] uptime 0.62 0.02
I0526 17:46:17.997335   22828 init_comm.go:68] [console] 
I0526 17:46:17.997618   22828 init_comm.go:68] [console] create directory /dev/pts
I0526 17:46:17.997986   22828 init_comm.go:68] [console] open hyper channel /dev/vport0p1
I0526 17:46:17.998232   22828 qmp_handler.go:103] got a message {"timestamp": {"seconds": 1464255977, "microseconds": 998055}, "event": "VSERPORT_CHANGE", "data": {"open": true, "id": "channel0"}}
I0526 17:46:17.998297   22828 qmp_handler.go:107] got event: VSERPORT_CHANGE
I0526 17:46:17.998345   22828 qmp_handler.go:323] got QMP event VSERPORT_CHANGE
I0526 17:46:18.000540   22828 init_comm.go:68] [console] send ready message
I0526 17:46:18.000773   22828 init_comm.go:68] [console] hyper send type 8, len 0
I0526 17:46:18.000847   22828 init_comm.go:106] read 8/8 [length = 0]
I0526 17:46:18.000892   22828 init_comm.go:110] data length is 8
I0526 17:46:18.000925   22828 init_comm.go:143] Get init ready message
I0526 17:46:18.000985   22828 init_comm.go:190] got cmd:1
I0526 17:46:18.001053   22828 init_comm.go:281] send command 1 to init, payload: '{"hostname":"68988a52009d","containers":[],"shareDir":"share_dir"}'.
I0526 17:46:18.001098   22828 init_comm.go:294] write 74 to init, payload: 'J{"hostname":"68988a52009d","containers":[],"shareDir":"share_dir"}'.
I0526 17:46:18.001145   22828 init_comm.go:299] message sent, set pong timer
I0526 17:46:18.001015   22828 init_comm.go:96] trying to read 8 bytes
I0526 17:46:18.001001   22828 hypervisor.go:29] vm vm-pEwxFWdQnA: main event loop got message 5(EVENT_INIT_CONNECTED)
I0526 17:46:18.001415   22828 vm_states.go:490] begin to wait vm commands
I0526 17:46:18.001469   22828 vm.go:260] Get the response from VM, VM id is vm-pEwxFWdQnA!
I0526 17:46:18.011911   22828 init_comm.go:68] [console] channel sh.hyper.channel.1, directory sh.hyper.channel.0
I0526 17:46:18.011976   22828 init_comm.go:68] [console] 
I0526 17:46:18.012271   22828 init_comm.go:68] [console] open hyper channel /dev/vport0p2
I0526 17:46:18.012852   22828 init_comm.go:68] [console] hyper_init_event hyper channel event 0x6165c0, ops 0x6163c0, fd 3
I0526 17:46:18.013196   22828 init_comm.go:68] [console] hyper_add_event add event fd 3, 0x6163c0
I0526 17:46:18.013667   22828 init_comm.go:68] [console] hyper_init_event hyper ttyfd event 0x616588, ops 0x616380, fd 4
I0526 17:46:18.014006   22828 init_comm.go:68] [console] hyper_add_event add event fd 4, 0x616380
I0526 17:46:18.014244   22828 init_comm.go:68] [console] hyper_loop epoll_wait 1
I0526 17:46:18.014706   22828 init_comm.go:68] [console] hyper_handle_event get event 1, de 0x6165c0, fd 3. ops 0x6163c0
I0526 17:46:18.015172   22828 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, de 0x6165c0, fd 3, 0x6163c0
I0526 17:46:18.015359   22828 init_comm.go:68] [console] hyper_event_read
I0526 17:46:18.015603   22828 init_comm.go:68] [console] already read 8 bytes data
I0526 17:46:18.015841   22828 init_comm.go:68] [console] hyper send type 14, len 4
I0526 17:46:18.015938   22828 init_comm.go:106] read 8/8 [length = 0]
I0526 17:46:18.015956   22828 init_comm.go:110] data length is 12
I0526 17:46:18.015980   22828 init_comm.go:96] trying to read 4 bytes
I0526 17:46:18.016007   22828 init_comm.go:106] read 12/12 [length = 12]
I0526 17:46:18.016022   22828 init_comm.go:96] trying to read 8 bytes
I0526 17:46:18.016040   22828 init_comm.go:190] got cmd:14
I0526 17:46:18.016068   22828 init_comm.go:253] get command NEXT
I0526 17:46:18.016077   22828 init_comm.go:256] send 74, receive 8
I0526 17:46:18.016054   22828 init_comm.go:68] [console] get length 74
I0526 17:46:18.016336   22828 init_comm.go:68] [console] read 66 bytes data, total data 74
I0526 17:46:18.016570   22828 init_comm.go:68] [console] hyper send type 14, len 4
I0526 17:46:18.016633   22828 init_comm.go:106] read 8/8 [length = 0]
I0526 17:46:18.016672   22828 init_comm.go:110] data length is 12
I0526 17:46:18.016703   22828 init_comm.go:96] trying to read 4 bytes
I0526 17:46:18.016740   22828 init_comm.go:106] read 12/12 [length = 12]
I0526 17:46:18.016775   22828 init_comm.go:96] trying to read 8 bytes
I0526 17:46:18.016815   22828 init_comm.go:190] got cmd:14
I0526 17:46:18.016847   22828 init_comm.go:253] get command NEXT
I0526 17:46:18.016881   22828 init_comm.go:256] send 74, receive 74
I0526 17:46:18.017950   22828 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 36 38 39 38 38 61 35 32 30 30 39 64 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 
I0526 17:46:18.018257   22828 init_comm.go:68] [console]  hyper_channel_handle, type 1, len 74
I0526 17:46:18.018957   22828 init_comm.go:68] [console] call hyper_start_pod, json {"hostname":"68988a52009d","containers":[],"shareDir":"share_dir"}, len 66
I0526 17:46:18.040241   22828 init_comm.go:68] [console] random: busybox urandom read with 7 bits of entropy available
I0526 17:46:18.041122   22828 init_comm.go:68] [console] call hyper_start_pod, json {"hostname":"68988a52009d","containers":[],"shareDir":"share_dir"}, len 66
I0526 17:46:18.041385   22828 init_comm.go:68] [console] jsmn parse successed, n is 7
I0526 17:46:18.041642   22828 init_comm.go:68] [console] token 0, type is 1, size is 3
I0526 17:46:18.041906   22828 init_comm.go:68] [console] token 1, type is 3, size is 1
I0526 17:46:18.042144   22828 init_comm.go:68] [console] hostname is 68988a52009d
I0526 17:46:18.042405   22828 init_comm.go:68] [console] token 3, type is 3, size is 1
I0526 17:46:18.042594   22828 init_comm.go:68] [console] container count 0
I0526 17:46:18.042846   22828 init_comm.go:68] [console] token 5, type is 3, size is 1
I0526 17:46:18.043078   22828 init_comm.go:68] [console] share tag is share_dir
I0526 17:46:18.043303   22828 init_comm.go:68] [console] create directory /tmp
I0526 17:46:18.043562   22828 init_comm.go:68] [console] create directory /tmp/hyper
I0526 17:46:18.043839   22828 init_comm.go:68] [console] create directory /tmp/hyper/proc
I0526 17:46:18.044227   22828 init_comm.go:68] [console] finish rescan
I0526 17:46:18.044624   22828 init_comm.go:68] [console] create directory /tmp/hyper/shared
I0526 17:46:18.067861   22828 init_comm.go:68] [console] pod init pid 325
I0526 17:46:18.068181   22828 init_comm.go:68] [console] hyper send type 8, len 0
I0526 17:46:18.068390   22828 init_comm.go:68] [console] uptime 0.69 0.03
I0526 17:46:18.068476   22828 init_comm.go:68] [console] 
I0526 17:46:18.068715   22828 init_comm.go:68] [console] hyper send type 9, len 0
I0526 17:46:18.068797   22828 init_comm.go:106] read 8/8 [length = 0]
I0526 17:46:18.068813   22828 init_comm.go:110] data length is 8
I0526 17:46:18.068824   22828 init_comm.go:96] trying to read 8 bytes
I0526 17:46:18.068841   22828 init_comm.go:190] got cmd:9
I0526 17:46:18.068856   22828 init_comm.go:209] ack got, clear pong timer
I0526 17:46:18.068871   22828 hypervisor.go:29] vm vm-pEwxFWdQnA: main event loop got message 31(COMMAND_ACK)
I0526 17:46:18.068885   22828 vm_states.go:500] [starting] got init ack to &{1 859533981568 <nil> [] 859532519968}
I0526 17:46:18.069014   22828 init_comm.go:68] [console] pid 324 exit normally, status 0
I0526 17:46:18.069033   22828 context.go:211] VM vm-pEwxFWdQnA: state change from STARTING to 'RUNNING'
I0526 17:46:18.069049   22828 vm_states.go:516] pod start success 
I0526 17:46:18.069068   22828 vm.go:260] Get the response from VM, VM id is vm-pEwxFWdQnA!
I0526 17:46:18.069086   22828 hyperpod.go:319] result: code 0 Start POD success
I0526 17:46:18.069098   22828 hyperpod.go:185] get exec path /home/darcy/gocode/src/github.com/hyperhq/runv/runv-containerd
I0526 17:46:18.069398   22828 init_comm.go:68] [console] can not find exec whose pid is 324
I0526 17:46:18.069526   22828 init_comm.go:68] [console] hyper_loop epoll_wait -1
I0526 17:46:18.109406   22828 hyperpod.go:234] nsListener pid is 23581
I0526 17:46:18.109437   22828 supervisor.go:168] createHyperPod() returns
I0526 17:46:18.109448   22828 hyperpod.go:257] createContainer()
I0526 17:46:18.109458   22828 process.go:33] process setupIO: stdin /var/run/docker/libcontainerd/68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b/init-stdin, stdout /var/run/docker/libcontainerd/68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b/init-stdout, stderr /var/run/docker/libcontainerd/68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b/init-stderr
I0526 17:46:18.109493   22828 process.go:59] process setupIO() success
I0526 17:46:18.109504   22828 hyperpod.go:283] createContainer()
I0526 17:46:18.109512   22828 hyperpod.go:289] createContainer() calls c.run(p)
I0526 17:46:18.109533   22828 supervisor.go:53] Supervisor.CreateContainer() return: c:&{68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b /var/run/docker/libcontainerd/68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b 0xc8204a4000 map[init:0xc82017f200] 0xc8204fc700} p:&{init /var/run/docker/libcontainerd/68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b/init-stdin /var/run/docker/libcontainerd/68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b/init-stdout /var/run/docker/libcontainerd/68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b/init-stderr 0xc8204a4030 -1 68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b-init 0xc8204fc880 true 0xc8204fc8c0 <nil>}
I0526 17:46:18.109571   22828 server.go:50] end Supervisor.CreateContainer(), build api Container
I0526 17:46:18.109583   22828 server.go:55] gRPC respond CreateContainer
I0526 17:46:18.109682   22828 container.go:64] save state id 68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b, boundle /var/run/docker/libcontainerd/68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b
I0526 17:46:18.109773   22828 container.go:95] prepare hypervisor info
I0526 17:46:18.109785   22828 ocf-linux.go:21] env: PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
I0526 17:46:18.109796   22828 ocf-linux.go:21] env: HOSTNAME=68988a52009d
I0526 17:46:18.109804   22828 ocf-linux.go:21] env: TERM=xterm
I0526 17:46:18.109871   22828 container.go:311] Skip mount point "/proc" of type proc
I0526 17:46:18.109894   22828 container.go:311] Skip mount point "/dev" of type tmpfs
I0526 17:46:18.129457   22828 container.go:311] Skip mount point "/sys" of type sysfs
I0526 17:46:18.129490   22828 container.go:311] Skip mount point "/sys/fs/cgroup" of type cgroup
I0526 17:46:18.129502   22828 container.go:311] Skip mount point "/dev/mqueue" of type mqueue
I0526 17:46:18.160401   22828 hypervisor.go:29] vm vm-pEwxFWdQnA: main event loop got message 34(GENERIC_OPERATION)
I0526 17:46:18.160436   22828 vm_states.go:303] handle GenericOperation(Attach) on state(RUNNING)
I0526 17:46:18.160446   22828 context.go:179] can not found container 68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b
I0526 17:46:18.160457   22828 vm_states.go:220] attachment 68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b-init is pending
I0526 17:46:18.357088   22828 hyperpod.go:127] interface configuration of pod ns is [{508 0 172.17.0.3/16}]
E0526 17:46:18.357548   22828 hyperpod.go:131] cann't find nic whose ifindex is 0
I0526 17:46:18.357606   22828 hypervisor.go:29] vm vm-pEwxFWdQnA: main event loop got message 34(GENERIC_OPERATION)
I0526 17:46:18.357651   22828 vm_states.go:303] handle GenericOperation(AddRoute) on state(RUNNING)
I0526 17:46:18.357691   22828 events.go:121] notifySubscribers: {68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b start-container 2016-05-26 17:46:18.357688822 +0800 CST  0}
I0526 17:46:18.357752   22828 events.go:54] write event log: {68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b start-container 2016-05-26 17:46:18.357688822 +0800 CST  0}
I0526 17:46:18.357819   22828 hypervisor.go:29] vm vm-pEwxFWdQnA: main event loop got message 26(COMMAND_NEWCONTAINER)
I0526 17:46:18.357867   22828 context.go:175] found container 68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b at 0
I0526 17:46:18.357961   22828 vm_states.go:114] attach pending client 68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b-init for 68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b
I0526 17:46:18.358004   22828 vm_states.go:239] Connecting tty for 68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b on session 1
I0526 17:46:18.358040   22828 vm_states.go:127] start sending INIT_NEWCONTAINER
I0526 17:46:18.358074   22828 vm_states.go:132] sent INIT_NEWCONTAINER
I0526 17:46:18.358119   22828 init_comm.go:190] got cmd:17
I0526 17:46:18.358180   22828 init_comm.go:281] send command 17 to init, payload: '{"id":"68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b","rootfs":"rootfs","image":"68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b","process":{"terminal":true,"stdio":1,"args":["sh"],"envs":[{"env":"PATH","value":"/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"},{"env":"HOSTNAME","value":"68988a52009d"},{"env":"TERM","value":"xterm"}],"workdir":"/"},"restartPolicy":"never","initialize":false}'.
I0526 17:46:18.358236   22828 init_comm.go:294] write 451 to init, payload: '»"id":"68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b","rootfs":"rootfs","image":"68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b","process":{"terminal":true,"stdio":1,"args":["sh"],"envs":[{"env":"PATH","value":"/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"},{"env":"HOSTNAME","value":"68988a52009d"},{"env":"TERM","value":"xterm"}],"workdir":"/"},"restartPolicy":"never","initialize":false}'.
I0526 17:46:18.358285   22828 init_comm.go:299] message sent, set pong timer
I0526 17:46:18.358614   22828 init_comm.go:68] [console] hyper_loop epoll_wait 1
I0526 17:46:18.360335   22828 init_comm.go:68] [console] hyper_handle_event get event 1, de 0x6165c0, fd 3. ops 0x6163c0
I0526 17:46:18.360372   22828 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, de 0x6165c0, fd 3, 0x6163c0
I0526 17:46:18.360408   22828 init_comm.go:68] [console] hyper_event_read
I0526 17:46:18.360440   22828 init_comm.go:68] [console] already read 8 bytes data
I0526 17:46:18.360484   22828 init_comm.go:68] [console] hyper send type 14, len 4
I0526 17:46:18.360273   22828 init_comm.go:106] read 8/8 [length = 0]
I0526 17:46:18.360549   22828 init_comm.go:110] data length is 12
I0526 17:46:18.360580   22828 init_comm.go:96] trying to read 4 bytes
I0526 17:46:18.360617   22828 init_comm.go:106] read 12/12 [length = 12]
I0526 17:46:18.360658   22828 init_comm.go:96] trying to read 8 bytes
I0526 17:46:18.360700   22828 init_comm.go:190] got cmd:14
I0526 17:46:18.360735   22828 init_comm.go:253] get command NEXT
I0526 17:46:18.360766   22828 init_comm.go:256] send 451, receive 8
I0526 17:46:18.362609   22828 init_comm.go:106] read 8/8 [length = 0]
I0526 17:46:18.362709   22828 init_comm.go:110] data length is 12
I0526 17:46:18.362718   22828 init_comm.go:96] trying to read 4 bytes
I0526 17:46:18.362729   22828 init_comm.go:106] read 12/12 [length = 12]
I0526 17:46:18.362740   22828 init_comm.go:96] trying to read 8 bytes
I0526 17:46:18.362751   22828 init_comm.go:190] got cmd:14
I0526 17:46:18.362760   22828 init_comm.go:253] get command NEXT
I0526 17:46:18.362768   22828 init_comm.go:256] send 451, receive 451
I0526 17:46:18.362691   22828 init_comm.go:68] [console] get length 451
I0526 17:46:18.362790   22828 init_comm.go:68] [console] read 443 bytes data, total data 451
I0526 17:46:18.362799   22828 init_comm.go:68] [console] hyper send type 14, len 4
I0526 17:46:18.395866   22828 init_comm.go:68] [console] 0 0 0 11 0 0 1 c3 7b 22 69 64 22 3a 22 36 38 39 38 38 61 35 32 30 30 39 64 38 38 35 64 35 39 62 36 39 30 64 33 36 61 34 37 64 30 33 33 65 32 65 61 39 32 31 32 38 37 31 63 33 32 37 35 34 34 36 64 37 39 32 36 35 63 61 37 34 66 30 62 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 36 38 39 38 38 61 35 32 30 30 39 64 38 38 35 64 35 39 62 36 39 30 64 33 36 61 34 37 64 30 33 33 65 32 65 61 39 32 31 32 38 37 31 63 33 32 37 35 34 34 36 64 37 39 32 36 35 63 61 37 34 66 30 62 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 73 68 22 5d 2c 22 65 6e 76 73 22 3a 5b 7b 22 65 6e 76 22 3a 22 50 41 54 48 22 2c 22 76 61 6c 75 65 22 3a 22 2f 75 73 72 2f 6c 6f 63 61 6c 2f 73 62 69 6e 3a 2f 75 73 72 2f 6c 6f 63 61 6c 2f 62 69 6e 3a 2f 75 73 72 2f 73 62 69 6e 3a 2f 75 73 72 2f 62 69 6e 3a 2f 73 62 69 6e 3a 2f 62 69 6e 22 7d 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 36 38 39 38 38 61 35 32 30 30 39 64 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 
I0526 17:46:18.396862   22828 init_comm.go:68] [console]  hyper_channel_handle, type 17, len 451
I0526 17:46:18.406461   22828 init_comm.go:68] [console] call hyper_new_container, json {"id":"68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b","rootfs":"rootfs","image":"68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b","process":{"terminal":true,"stdio":1,"args":["sh"],"envs":[{"env":"PATH","value":"/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin"},{"env":"HOSTNAME","value":"68988a52009d"},{"env":"TERM","value":"xterm"}],"workdir":"/"},"restartPolicy":"never","initialize":false}, len 443
I0526 17:46:18.406988   22828 init_comm.go:68] [console] next container 6
I0526 17:46:18.407357   22828 init_comm.go:68] [console] 1 name id
I0526 17:46:18.419686   22828 init_comm.go:68] [console] container id 68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b
I0526 17:46:18.420139   22828 init_comm.go:68] [console] 3 name rootfs
I0526 17:46:18.420782   22828 init_comm.go:68] [console] container rootfs rootfs
I0526 17:46:18.421208   22828 init_comm.go:68] [console] 5 name image
I0526 17:46:18.422940   22828 init_comm.go:68] [console] container image 68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b
I0526 17:46:18.423408   22828 init_comm.go:68] [console] 7 name process
I0526 17:46:18.423882   22828 init_comm.go:68] [console] 1 name terminal
I0526 17:46:18.424526   22828 init_comm.go:68] [console] container uses terminal
I0526 17:46:18.424954   22828 init_comm.go:68] [console] 3 name stdio
I0526 17:46:18.425421   22828 init_comm.go:68] [console] container seq 1
I0526 17:46:18.425823   22828 init_comm.go:68] [console] 5 name args
I0526 17:46:18.426468   22828 init_comm.go:68] [console] container init arg 0 sh
I0526 17:46:18.426875   22828 init_comm.go:68] [console] 8 name envs
I0526 17:46:18.427267   22828 init_comm.go:68] [console] envs num 3
I0526 17:46:18.427744   22828 init_comm.go:68] [console] envs 0 env PATH
I0526 17:46:18.429369   22828 init_comm.go:68] [console] envs 0 value /usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
I0526 17:46:18.429944   22828 init_comm.go:68] [console] envs 1 env HOSTNAME
I0526 17:46:18.430621   22828 init_comm.go:68] [console] envs 1 value 68988a52009d
I0526 17:46:18.431105   22828 init_comm.go:68] [console] envs 2 env TERM
I0526 17:46:18.431645   22828 init_comm.go:68] [console] envs 2 value xterm
I0526 17:46:18.432131   22828 init_comm.go:68] [console] 25 name workdir
I0526 17:46:18.432686   22828 init_comm.go:68] [console] container workdir /
I0526 17:46:18.433295   22828 init_comm.go:68] [console] 35 name restartPolicy
I0526 17:46:18.433884   22828 init_comm.go:68] [console] restart policy never
I0526 17:46:18.434439   22828 init_comm.go:68] [console] 37 name initialize
I0526 17:46:18.436552   22828 init_comm.go:68] [console] create directory /tmp/hyper/68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b
I0526 17:46:18.438703   22828 init_comm.go:68] [console] create directory /tmp/hyper/68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b/devpts
I0526 17:46:18.440873   22828 init_comm.go:68] [console] create directory /tmp/hyper/68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b/devpts/
I0526 17:46:18.453553   22828 init_comm.go:68] [console] get pty device for exec /tmp/hyper/68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b/devpts//0
I0526 17:46:18.454724   22828 init_comm.go:68] [console] hyper_setup_exec_tty pts event 0xc4f898, fd 13 14
I0526 17:46:18.456227   22828 init_comm.go:68] [console] hyper_init_event container pts event 0xc4f898, ops 0x616500, fd 13
I0526 17:46:18.457232   22828 init_comm.go:68] [console] hyper_add_event add event fd 13, 0x616500
I0526 17:46:18.458236   22828 init_comm.go:68] [console] hyper_add_event add event fd 15, 0x6164c0
I0526 17:46:18.459240   22828 init_comm.go:68] [console] hyper_add_event add event fd 16, 0x616480
I0526 17:46:18.460071   22828 init_comm.go:68] [console] hyper_container_init in
I0526 17:46:18.461021   22828 init_comm.go:68] [console] path /sys/class/scsi_host/host0/scan
I0526 17:46:18.497344   22828 init_comm.go:68] [console] finish scan scsi
I0526 17:46:18.497435   22828 init_comm.go:68] [console] create directory /tmp/hyper/68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b/root
I0526 17:46:18.497475   22828 init_comm.go:68] [console] create directory /tmp/hyper/68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b/root/
I0526 17:46:18.498378   22828 init_comm.go:68] [console] container root directory /tmp/hyper/68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b/root/
I0526 17:46:18.500361   22828 init_comm.go:68] [console] src directory /tmp/hyper/shared/68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b/
I0526 17:46:18.503360   22828 init_comm.go:68] [console] root directory for container is /tmp/hyper/68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b/root//rootfs, init task sh
I0526 17:46:18.536320   22828 init_comm.go:68] [console] create directory ./lib
I0526 17:46:18.536949   22828 init_comm.go:68] [console] create directory ./lib/modules
I0526 17:46:18.538114   22828 init_comm.go:68] [console] create directory ./dev/shm
I0526 17:46:18.539572   22828 init_comm.go:68] [console] create directory .//lib/modules/4.4.7-hyper+
I0526 17:46:18.542064   22828 init_comm.go:68] [console] no dns configured
I0526 17:46:18.542155   22828 init_comm.go:68] [console] hyper send type 8, len 0
I0526 17:46:18.542196   22828 init_comm.go:68] [console] container 68988a52009d885d59b690d36a47d033e2ea9212871c3275446d79265ca74f0b,init pid 327,ref 4
I0526 17:46:18.542228   22828 init_comm.go:68] [console] hyper send type 8, len 0
I0526 17:46:18.542263   22828 init_comm.go:68] [console] hyper send type 9, len 0
I0526 17:46:18.542084   22828 init_comm.go:106] read 8/8 [length = 0]
I0526 17:46:18.542315   22828 init_comm.go:110] data length is 8
I0526 17:46:18.542349   22828 init_comm.go:96] trying to read 8 bytes
I0526 17:46:18.542391   22828 init_comm.go:190] got cmd:9
I0526 17:46:18.542431   22828 init_comm.go:209] ack got, clear pong timer
I0526 17:46:18.542469   22828 hypervisor.go:29] vm vm-pEwxFWdQnA: main event loop got message 31(COMMAND_ACK)
I0526 17:46:18.542518   22828 vm_states.go:562] [running] got init ack to &{17 859534740928 <nil> [] 859535645056}
I0526 17:46:18.542569   22828 vm_states.go:565] Get ack for new container
I0526 17:46:18.544583   22828 init_comm.go:68] [console] hyper_loop epoll_wait 1
I0526 17:46:18.544603   22828 init_comm.go:68] [console] hyper_handle_event get event 4, de 0xc4f898, fd 13. ops 0x616500
I0526 17:46:18.544612   22828 init_comm.go:68] [console] hyper_handle_event event EPOLLOUT, de 0xc4f898, fd 13, 0x616500
I0526 17:46:18.544620   22828 init_comm.go:68] [console] write_to_stdin, seq 1
I0526 17:46:18.544629   22828 init_comm.go:68] [console] hyper_modify_event modify event fd 13, 0xc4f898, event 1
I0526 17:46:18.544637   22828 init_comm.go:68] [console] hyper_dup_exec_tty
I0526 17:46:18.552764   22828 init_comm.go:68] [console] hyper_loop epoll_wait 3
I0526 17:46:18.552834   22828 init_comm.go:68] [console] hyper_handle_event get event 1, de 0xc4f908, fd 16. ops 0x616480
I0526 17:46:18.552869   22828 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, de 0xc4f908, fd 16, 0x616480
I0526 17:46:18.552900   22828 init_comm.go:68] [console] stderr_loop, seq 0
I0526 17:46:18.552931   22828 init_comm.go:68] [console] pts_loop: read 4 data
I0526 17:46:18.552961   22828 init_comm.go:68] [console] pts_loop: read -1 data
I0526 17:46:18.552992   22828 init_comm.go:68] [console] hyper_modify_event modify event fd 4, 0x616588, event 5
I0526 17:46:18.553422   22828 tty.go:97] tty: read 12/12 [length = 0]
I0526 17:46:18.553437   22828 tty.go:101] data length is 16
I0526 17:46:18.553470   22828 tty.go:87] tty: trying to read 4 bytes
I0526 17:46:18.553483   22828 tty.go:97] tty: read 16/16 [length = 16]
I0526 17:46:18.553512   22828 tty.go:87] tty: trying to read 12 bytes
I0526 17:46:18.554507   22828 init_comm.go:68] [console] hyper_handle_event get event 1, de 0xc4f8d0, fd 15. ops 0x6164c0
I0526 17:46:18.555738   22828 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, de 0xc4f8d0, fd 15, 0x6164c0
I0526 17:46:18.556158   22828 init_comm.go:68] [console] stdout_loop, seq 1
I0526 17:46:18.556635   22828 init_comm.go:68] [console] pts_loop: read -1 data
I0526 17:46:18.557885   22828 init_comm.go:68] [console] hyper_handle_event get event 1, de 0xc4f898, fd 13. ops 0x616500
I0526 17:46:18.558406   22828 init_comm.go:68] [console] hyper_loop epoll_wait 1
I0526 17:46:18.559733   22828 init_comm.go:68] [console] hyper_handle_event get event 4, de 0x616588, fd 4. ops 0x616380
I0526 17:46:18.561043   22828 init_comm.go:68] [console] hyper_handle_event event EPOLLOUT, de 0x616588, fd 4, 0x616380
I0526 17:46:18.562199   22828 init_comm.go:68] [console] hyper_modify_event modify event fd 4, 0x616588, event 1
I0526 17:46:18.580148   22828 init_comm.go:68] [console] tsc: Refined TSC clocksource calibration: 3092.974 MHz
I0526 17:46:18.580209   22828 init_comm.go:68] [console] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x2c955ac38be, max_idle_ns: 440795348546 ns
I0526 17:46:18.998654   22828 qmp_handler.go:103] got a message {"timestamp": {"seconds": 1464255978, "microseconds": 12324}, "event": "VSERPORT_CHANGE", "data": {"open": true, "id": "channel1"}}
I0526 17:46:18.998759   22828 qmp_handler.go:107] got event: VSERPORT_CHANGE
I0526 17:46:18.998812   22828 qmp_handler.go:323] got QMP event VSERPORT_CHANGE
I0526 17:46:24.623416   22828 init_comm.go:216] Send ping message to init
I0526 17:46:24.623526   22828 init_comm.go:190] got cmd:12
I0526 17:46:24.623584   22828 init_comm.go:281] send command 12 to init, payload: 'null'.
I0526 17:46:24.623635   22828 init_comm.go:294] write 12 to init, payload: '

                                                                            null'.
I0526 17:46:24.623672   22828 init_comm.go:299] message sent, set pong timer
I0526 17:46:24.623933   22828 init_comm.go:68] [console] hyper_loop epoll_wait 1
I0526 17:46:24.624374   22828 init_comm.go:68] [console] hyper_handle_event get event 1, de 0x6165c0, fd 3. ops 0x6163c0
I0526 17:46:24.624798   22828 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, de 0x6165c0, fd 3, 0x6163c0
I0526 17:46:24.624964   22828 init_comm.go:68] [console] hyper_event_read
I0526 17:46:24.625203   22828 init_comm.go:68] [console] already read 8 bytes data
I0526 17:46:24.625449   22828 init_comm.go:68] [console] hyper send type 14, len 4
I0526 17:46:24.625521   22828 init_comm.go:106] read 8/8 [length = 0]
I0526 17:46:24.625559   22828 init_comm.go:110] data length is 12
I0526 17:46:24.625590   22828 init_comm.go:96] trying to read 4 bytes
I0526 17:46:24.625627   22828 init_comm.go:106] read 12/12 [length = 12]
I0526 17:46:24.625661   22828 init_comm.go:96] trying to read 8 bytes
I0526 17:46:24.625699   22828 init_comm.go:190] got cmd:14
I0526 17:46:24.625773   22828 init_comm.go:253] get command NEXT
I0526 17:46:24.625808   22828 init_comm.go:256] send 12, receive 8
I0526 17:46:24.625743   22828 init_comm.go:68] [console] get length 12
I0526 17:46:24.625883   22828 init_comm.go:68] [console] read 4 bytes data, total data 12
I0526 17:46:24.626125   22828 init_comm.go:68] [console] hyper send type 14, len 4
I0526 17:46:24.626184   22828 init_comm.go:106] read 8/8 [length = 0]
I0526 17:46:24.626218   22828 init_comm.go:110] data length is 12
I0526 17:46:24.626252   22828 init_comm.go:96] trying to read 4 bytes
I0526 17:46:24.626285   22828 init_comm.go:106] read 12/12 [length = 12]
I0526 17:46:24.626340   22828 init_comm.go:96] trying to read 8 bytes
I0526 17:46:24.626380   22828 init_comm.go:68] [console] 0 0 0 c 0 0 0 c 6e 75 6c 6c 
I0526 17:46:24.626380   22828 init_comm.go:190] got cmd:14
I0526 17:46:24.626404   22828 init_comm.go:253] get command NEXT
I0526 17:46:24.626415   22828 init_comm.go:256] send 12, receive 12
I0526 17:46:24.626696   22828 init_comm.go:68] [console]  hyper_channel_handle, type 12, len 12
I0526 17:46:24.626915   22828 init_comm.go:68] [console] hyper send type 9, len 0
I0526 17:46:24.626976   22828 init_comm.go:106] read 8/8 [length = 0]
I0526 17:46:24.627013   22828 init_comm.go:110] data length is 8
I0526 17:46:24.627045   22828 init_comm.go:96] trying to read 8 bytes
I0526 17:46:24.627087   22828 init_comm.go:190] got cmd:9
I0526 17:46:24.627122   22828 init_comm.go:209] ack got, clear pong timer
I0526 17:46:48.542563   22828 init_comm.go:216] Send ping message to init
I0526 17:46:48.542623   22828 init_comm.go:190] got cmd:12
I0526 17:46:48.542670   22828 init_comm.go:281] send command 12 to init, payload: 'null'.
I0526 17:46:48.542720   22828 init_comm.go:294] write 12 to init, payload: '

                                                                            null'.
I0526 17:46:48.545306   22828 init_comm.go:299] message sent, set pong timer
I0526 17:46:48.545253   22828 init_comm.go:68] [console] hyper_loop epoll_wait 1
I0526 17:46:48.545349   22828 init_comm.go:68] [console] hyper_handle_event get event 1, de 0x6165c0, fd 3. ops 0x6163c0
I0526 17:46:48.545373   22828 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, de 0x6165c0, fd 3, 0x6163c0
I0526 17:46:48.545539   22828 init_comm.go:68] [console] hyper_event_read
I0526 17:46:48.545569   22828 init_comm.go:68] [console] already read 8 bytes data
I0526 17:46:48.545580   22828 init_comm.go:68] [console] hyper send type 14, len 4
I0526 17:46:48.545601   22828 init_comm.go:68] [console] get length 12
I0526 17:46:48.545622   22828 init_comm.go:68] [console] read 4 bytes data, total data 12
I0526 17:46:48.545506   22828 init_comm.go:106] read 8/8 [length = 0]
I0526 17:46:48.545653   22828 init_comm.go:110] data length is 12
I0526 17:46:48.545675   22828 init_comm.go:96] trying to read 4 bytes
I0526 17:46:48.545702   22828 init_comm.go:106] read 12/12 [length = 12]
I0526 17:46:48.545733   22828 init_comm.go:96] trying to read 8 bytes
I0526 17:46:48.545764   22828 init_comm.go:106] read 8/8 [length = 0]
I0526 17:46:48.545790   22828 init_comm.go:110] data length is 12
I0526 17:46:48.545812   22828 init_comm.go:96] trying to read 4 bytes
I0526 17:46:48.545835   22828 init_comm.go:106] read 12/12 [length = 12]
I0526 17:46:48.545860   22828 init_comm.go:96] trying to read 8 bytes
I0526 17:46:48.545915   22828 init_comm.go:106] read 8/8 [length = 0]
I0526 17:46:48.545941   22828 init_comm.go:110] data length is 8
I0526 17:46:48.545973   22828 init_comm.go:96] trying to read 8 bytes
I0526 17:46:48.545874   22828 init_comm.go:190] got cmd:14
I0526 17:46:48.546013   22828 init_comm.go:253] get command NEXT
I0526 17:46:48.546041   22828 init_comm.go:256] send 12, receive 8
I0526 17:46:48.546069   22828 init_comm.go:190] got cmd:14
I0526 17:46:48.546103   22828 init_comm.go:253] get command NEXT
I0526 17:46:48.546129   22828 init_comm.go:256] send 12, receive 12
I0526 17:46:48.546152   22828 init_comm.go:190] got cmd:9
I0526 17:46:48.546176   22828 init_comm.go:209] ack got, clear pong timer
I0526 17:46:48.546320   22828 init_comm.go:68] [console] hyper send type 14, len 4
I0526 17:46:48.546492   22828 init_comm.go:68] [console] 0 0 0 c 0 0 0 c 6e 75 6c 6c 
I0526 17:46:48.546723   22828 init_comm.go:68] [console]  hyper_channel_handle, type 12, len 12
I0526 17:46:48.546880   22828 init_comm.go:68] [console] hyper send type 9, len 0
WeiZhang555 commented 8 years ago

So it turn out to be dependent on kernel version, at least my kernel of 3.19 doesn't work but 4.1 works. So I'm closing this now since it's resolved.

So we only need to mentioned that there's some restrictions on kernel version if we want network feature works.