hyperhq / runv

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

runv-containerd can't start container #240

Closed WeiZhang555 closed 8 years ago

WeiZhang555 commented 8 years ago

I'll paste logs directly here.

Try to run docker run -tid --net none busybox sh with runv-containerd, it reports error:

I0526 14:41:14.338046   21767 server.go:31] gRPC handle CreateContainer
I0526 14:41:14.338853   21767 vm.go:179] hyperHandlePodEvent pod pod-qBJGmhcgni, vm vm-DNlnLYiACB
I0526 14:41:14.338910   21767 hypervisor.go:29] vm vm-DNlnLYiACB: main event loop got message 21(COMMAND_RUN_POD)
I0526 14:41:14.338932   21767 vm_states.go:449] got spec, prepare devices
I0526 14:41:14.338960   21767 vm_states.go:67] initial vm spec: {
        "hostname": "d6a01446059e",
        "containers": [],
        "shareDir": "share_dir"
    }
I0526 14:41:14.338983   21767 context.go:211] VM vm-DNlnLYiACB: state change from INIT to 'STARTING'
I0526 14:41:14.338995   21767 hypervisor.go:29] vm vm-DNlnLYiACB: main event loop got message 10(EVENT_DEV_SKIP)
I0526 14:41:14.339004   21767 vm_states.go:476] device ready, could run pod.
I0526 14:41:14.339068   21767 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-DNlnLYiACB/qmp.sock,server,nowait -serial unix:/var/run/hyper/vm-DNlnLYiACB/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-DNlnLYiACB/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-DNlnLYiACB/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-DNlnLYiACB/share_dir,security_model=none -device virtio-9p-pci,fsdev=virtio9p,mount_tag=share_dir
I0526 14:41:14.339894   21767 qemu_process.go:74] starting daemon with pid: 22766
I0526 14:41:14.359240   21767 init_comm.go:133] Wating for init messages...
I0526 14:41:14.359346   21767 init_comm.go:96] trying to read 8 bytes
I0526 14:41:14.359240   21767 init_comm.go:53] connected to /var/run/hyper/vm-DNlnLYiACB/console.sock
I0526 14:41:14.359376   21767 init_comm.go:60] connected /var/run/hyper/vm-DNlnLYiACB/console.sock as telnet mode.
I0526 14:41:14.359302   21767 tty.go:144] tty socket connected
I0526 14:41:14.359418   21767 tty.go:87] tty: trying to read 12 bytes
I0526 14:41:14.359311   21767 qmp_handler.go:167] connected to /var/run/hyper/vm-DNlnLYiACB/qmp.sock
I0526 14:41:14.359445   21767 qmp_handler.go:177] begin qmp init...
I0526 14:41:14.372537   21767 qmp_handler.go:186] got qmp welcome, now sending command qmp_capabilities
I0526 14:41:14.372584   21767 qmp_handler.go:201] waiting for response
I0526 14:41:14.372760   21767 qmp_handler.go:103] got a message {"return": {}}
I0526 14:41:14.372789   21767 qmp_handler.go:210] got for response
I0526 14:41:14.372802   21767 qmp_handler.go:213] QMP connection initialized
I0526 14:41:14.372831   21767 qmp_handler.go:346] QMP initialzed, go into main QMP loop
I0526 14:41:14.372844   21767 qmp_handler.go:137] Begin receive QMP message
I0526 14:41:15.096072   21767 init_comm.go:68] [console] Initializing cgroup subsys cpuset
I0526 14:41:15.096351   21767 init_comm.go:68] [console] Initializing cgroup subsys cpu
I0526 14:41:15.096677   21767 init_comm.go:68] [console] Initializing cgroup subsys cpuacct
I0526 14:41:15.097871   21767 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 14:41:15.098326   21767 init_comm.go:68] [console] Command line: console=ttyS0 panic=1 no_timer_check
I0526 14:41:15.098814   21767 init_comm.go:68] [console] x86/fpu: xstate_offset[2]:  576, xstate_sizes[2]:  256
I0526 14:41:15.099452   21767 init_comm.go:68] [console] x86/fpu: Supporting XSAVE feature 0x01: 'x87 floating point registers'
I0526 14:41:15.099955   21767 init_comm.go:68] [console] x86/fpu: Supporting XSAVE feature 0x02: 'SSE registers'
I0526 14:41:15.100463   21767 init_comm.go:68] [console] x86/fpu: Supporting XSAVE feature 0x04: 'AVX registers'
I0526 14:41:15.101263   21767 init_comm.go:68] [console] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format.
I0526 14:41:15.101670   21767 init_comm.go:68] [console] x86/fpu: Using 'eager' FPU context switches.
I0526 14:41:15.102022   21767 init_comm.go:68] [console] e820: BIOS-provided physical RAM map:
I0526 14:41:15.102572   21767 init_comm.go:68] [console] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
I0526 14:41:15.103151   21767 init_comm.go:68] [console] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
I0526 14:41:15.103718   21767 init_comm.go:68] [console] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
I0526 14:41:15.104270   21767 init_comm.go:68] [console] BIOS-e820: [mem 0x0000000000100000-0x0000000007ffdfff] usable
I0526 14:41:15.104830   21767 init_comm.go:68] [console] BIOS-e820: [mem 0x0000000007ffe000-0x0000000007ffffff] reserved
I0526 14:41:15.105403   21767 init_comm.go:68] [console] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved
I0526 14:41:15.105972   21767 init_comm.go:68] [console] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
I0526 14:41:15.106331   21767 init_comm.go:68] [console] NX (Execute Disable) protection: active
I0526 14:41:15.106516   21767 init_comm.go:68] [console] SMBIOS 2.4 present.
I0526 14:41:15.106749   21767 init_comm.go:68] [console] Hypervisor detected: KVM
I0526 14:41:15.107200   21767 init_comm.go:68] [console] e820: last_pfn = 0x7ffe max_arch_pfn = 0x400000000
I0526 14:41:15.107766   21767 init_comm.go:68] [console] x86/PAT: Configuration [0-7]: WB  WC  UC- UC  WB  WC  UC- WT  
I0526 14:41:15.108464   21767 init_comm.go:68] [console] found SMP MP-table at [mem 0x000f64b0-0x000f64bf] mapped at [ffff8800000f64b0]
I0526 14:41:15.108796   21767 init_comm.go:68] [console] RAMDISK: [mem 0x07dda000-0x07feffff]
I0526 14:41:15.109232   21767 init_comm.go:68] [console] ACPI: Early table checksum verification disabled
I0526 14:41:15.109673   21767 init_comm.go:68] [console] ACPI: RSDP 0x00000000000F6330 000014 (v00 BOCHS )
I0526 14:41:15.110398   21767 init_comm.go:68] [console] ACPI: RSDT 0x0000000007FFF688 000030 (v01 BOCHS  BXPCRSDT 00000001 BXPC 00000001)
I0526 14:41:15.111117   21767 init_comm.go:68] [console] ACPI: FACP 0x0000000007FFEBDA 000074 (v01 BOCHS  BXPCFACP 00000001 BXPC 00000001)
I0526 14:41:15.111839   21767 init_comm.go:68] [console] ACPI: DSDT 0x0000000007FFE040 000B9A (v01 BOCHS  BXPCDSDT 00000001 BXPC 00000001)
I0526 14:41:15.112168   21767 init_comm.go:68] [console] ACPI: FACS 0x0000000007FFE000 000040
I0526 14:41:15.112890   21767 init_comm.go:68] [console] ACPI: SSDT 0x0000000007FFEC4E 0009C2 (v01 BOCHS  BXPCSSDT 00000001 BXPC 00000001)
I0526 14:41:15.113606   21767 init_comm.go:68] [console] ACPI: APIC 0x0000000007FFF610 000078 (v01 BOCHS  BXPCAPIC 00000001 BXPC 00000001)
I0526 14:41:15.113868   21767 init_comm.go:68] [console] No NUMA configuration found
I0526 14:41:15.114407   21767 init_comm.go:68] [console] Faking a node at [mem 0x0000000000000000-0x0000000007ffdfff]
I0526 14:41:15.114862   21767 init_comm.go:68] [console] NODE_DATA(0) allocated [mem 0x07dc8000-0x07dd9fff]
I0526 14:41:15.115246   21767 init_comm.go:68] [console] kvm-clock: Using msrs 4b564d01 and 4b564d00
I0526 14:41:15.115710   21767 init_comm.go:68] [console] kvm-clock: cpu 0, msr 0:7ffd001, primary cpu clock
I0526 14:41:15.116153   21767 init_comm.go:68] [console] kvm-clock: using sched offset of 712495973 cycles
I0526 14:41:15.117065   21767 init_comm.go:68] [console] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
I0526 14:41:15.117190   21767 init_comm.go:68] [console] Zone ranges:
I0526 14:41:15.117686   21767 init_comm.go:68] [console]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
I0526 14:41:15.118172   21767 init_comm.go:68] [console]   DMA32    [mem 0x0000000001000000-0x0000000007ffdfff]
I0526 14:41:15.118336   21767 init_comm.go:68] [console]   Normal   empty
I0526 14:41:15.118636   21767 init_comm.go:68] [console] Movable zone start for each node
I0526 14:41:15.118869   21767 init_comm.go:68] [console] Early memory node ranges
I0526 14:41:15.119364   21767 init_comm.go:68] [console]   node   0: [mem 0x0000000000001000-0x000000000009efff]
I0526 14:41:15.119862   21767 init_comm.go:68] [console]   node   0: [mem 0x0000000000100000-0x0000000007ffdfff]
I0526 14:41:15.120433   21767 init_comm.go:68] [console] Initmem setup node 0 [mem 0x0000000000001000-0x0000000007ffdfff]
I0526 14:41:15.120707   21767 init_comm.go:68] [console] ACPI: PM-Timer IO Port: 0x608
I0526 14:41:15.121154   21767 init_comm.go:68] [console] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
I0526 14:41:15.121700   21767 init_comm.go:68] [console] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
I0526 14:41:15.122205   21767 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
I0526 14:41:15.122735   21767 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
I0526 14:41:15.123266   21767 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
I0526 14:41:15.123816   21767 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
I0526 14:41:15.124362   21767 init_comm.go:68] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
I0526 14:41:15.124821   21767 init_comm.go:68] [console] Using ACPI (MADT) for SMP configuration information
I0526 14:41:15.125190   21767 init_comm.go:68] [console] smpboot: Allowing 1 CPUs, 0 hotplug CPUs
I0526 14:41:15.125721   21767 init_comm.go:68] [console] e820: [mem 0x08000000-0xfeffbfff] available for PCI devices
I0526 14:41:15.126068   21767 init_comm.go:68] [console] Booting paravirtualized kernel on KVM
I0526 14:41:15.126965   21767 init_comm.go:68] [console] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
I0526 14:41:15.127583   21767 init_comm.go:68] [console] setup_percpu: NR_CPUS:8 nr_cpumask_bits:8 nr_cpu_ids:1 nr_node_ids:1
I0526 14:41:15.128258   21767 init_comm.go:68] [console] PERCPU: Embedded 31 pages/cpu @ffff880007a00000 s89496 r8192 d29288 u2097152
I0526 14:41:15.128519   21767 init_comm.go:68] [console] KVM setup async PF for cpu 0
I0526 14:41:15.128827   21767 init_comm.go:68] [console] kvm-stealtime: cpu 0, msr 7a0d480
I0526 14:41:15.129486   21767 init_comm.go:68] [console] Built 1 zonelists in Node order, mobility grouping on.  Total pages: 32135
I0526 14:41:15.129667   21767 init_comm.go:68] [console] Policy zone: DMA32
I0526 14:41:15.130178   21767 init_comm.go:68] [console] Kernel command line: console=ttyS0 panic=1 no_timer_check
I0526 14:41:15.130631   21767 init_comm.go:68] [console] PID hash table entries: 512 (order: 0, 4096 bytes)
I0526 14:41:15.131811   21767 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 14:41:15.132107   21767 init_comm.go:68] [console] Hierarchical RCU implementation.
I0526 14:41:15.132505   21767 init_comm.go:68] [console]    Build-time adjustment of leaf fanout to 64.
I0526 14:41:15.132979   21767 init_comm.go:68] [console]    RCU restricting CPUs from NR_CPUS=8 to nr_cpu_ids=1.
I0526 14:41:15.133521   21767 init_comm.go:68] [console] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=1
I0526 14:41:15.133778   21767 init_comm.go:68] [console] NR_IRQS:4352 nr_irqs:256 16
I0526 14:41:15.134038   21767 init_comm.go:68] [console] Console: colour *CGA 80x25
I0526 14:41:15.134256   21767 init_comm.go:68] [console] console [ttyS0] enabled
I0526 14:41:15.134616   21767 init_comm.go:68] [console] tsc: Detected 3092.974 MHz processor
I0526 14:41:15.135329   21767 init_comm.go:68] [console] Calibrating delay loop (skipped) preset value.. 6185.94 BogoMIPS (lpj=3092974)
I0526 14:41:15.135685   21767 init_comm.go:68] [console] pid_max: default: 32768 minimum: 301
I0526 14:41:15.135972   21767 init_comm.go:68] [console] ACPI: Core revision 20150930
I0526 14:41:15.137372   21767 init_comm.go:68] [console] ACPI: 2 ACPI AML tables successfully acquired and loaded
I0526 14:41:15.137971   21767 init_comm.go:68] [console] Dentry cache hash table entries: 16384 (order: 5, 131072 bytes)
I0526 14:41:15.138605   21767 init_comm.go:68] [console] Inode-cache hash table entries: 8192 (order: 4, 65536 bytes)
I0526 14:41:15.139180   21767 init_comm.go:68] [console] Mount-cache hash table entries: 512 (order: 0, 4096 bytes)
I0526 14:41:15.139742   21767 init_comm.go:68] [console] Mountpoint-cache hash table entries: 512 (order: 0, 4096 bytes)
I0526 14:41:15.140263   21767 init_comm.go:68] [console] Initializing cgroup subsys io
I0526 14:41:15.140572   21767 init_comm.go:68] [console] Initializing cgroup subsys memory
I0526 14:41:15.140914   21767 init_comm.go:68] [console] Initializing cgroup subsys devices
I0526 14:41:15.141236   21767 init_comm.go:68] [console] Initializing cgroup subsys freezer
I0526 14:41:15.141550   21767 init_comm.go:68] [console] Initializing cgroup subsys net_cls
I0526 14:41:15.141910   21767 init_comm.go:68] [console] Initializing cgroup subsys perf_event
I0526 14:41:15.142206   21767 init_comm.go:68] [console] Initializing cgroup subsys pids
I0526 14:41:15.142510   21767 init_comm.go:68] [console] Initializing cgroup subsys debug
I0526 14:41:15.143028   21767 init_comm.go:68] [console] Last level iTLB entries: 4KB 512, 2MB 8, 4MB 8
I0526 14:41:15.143528   21767 init_comm.go:68] [console] Last level dTLB entries: 4KB 512, 2MB 32, 4MB 32, 1GB 0
I0526 14:41:15.154587   21767 init_comm.go:68] [console] Freeing SMP alternatives memory: 20K (ffffffff816f6000 - ffffffff816fb000)
I0526 14:41:15.157946   21767 init_comm.go:68] [console] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
I0526 14:41:15.158836   21767 init_comm.go:68] [console] smpboot: CPU0: Intel(R) Core(TM) i5-2400 CPU @ 3.10GHz (family: 0x6, model: 0x2a, stepping: 0x7)
I0526 14:41:15.159543   21767 init_comm.go:68] [console] Performance Events: 16-deep LBR, SandyBridge events, Intel PMU driver.
I0526 14:41:15.160197   21767 init_comm.go:68] [console] perf_event_intel: PEBS disabled due to CPU errata, please upgrade microcode
I0526 14:41:15.160483   21767 init_comm.go:68] [console] ... version:                2
I0526 14:41:15.160760   21767 init_comm.go:68] [console] ... bit width:              48
I0526 14:41:15.161027   21767 init_comm.go:68] [console] ... generic registers:      8
I0526 14:41:15.161424   21767 init_comm.go:68] [console] ... value mask:             0000ffffffffffff
I0526 14:41:15.161830   21767 init_comm.go:68] [console] ... max period:             000000007fffffff
I0526 14:41:15.162100   21767 init_comm.go:68] [console] ... fixed-purpose events:   3
I0526 14:41:15.162496   21767 init_comm.go:68] [console] ... event mask:             00000007000000ff
I0526 14:41:15.163006   21767 init_comm.go:68] [console] x86: Booted up 1 node, 1 CPUs
I0526 14:41:15.163534   21767 init_comm.go:68] [console] smpboot: Total of 1 processors activated (6185.94 BogoMIPS)
I0526 14:41:15.164210   21767 init_comm.go:68] [console] devtmpfs: initialized
I0526 14:41:15.166616   21767 init_comm.go:68] [console] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
I0526 14:41:15.167098   21767 init_comm.go:68] [console] NET: Registered protocol family 16
I0526 14:41:15.167470   21767 init_comm.go:68] [console] cpuidle: using governor ladder
I0526 14:41:15.167742   21767 init_comm.go:68] [console] cpuidle: using governor menu
I0526 14:41:15.168048   21767 init_comm.go:68] [console] ACPI: bus type PCI registered
I0526 14:41:15.168568   21767 init_comm.go:68] [console] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
I0526 14:41:15.169020   21767 init_comm.go:68] [console] PCI: Using configuration type 1 for base access
I0526 14:41:15.169754   21767 init_comm.go:68] [console] perf_event_intel: PMU erratum BJ122, BV98, HSD29 workaround disabled, HT off
I0526 14:41:15.170685   21767 init_comm.go:68] [console] ACPI: Added _OSI(Module Device)
I0526 14:41:15.171000   21767 init_comm.go:68] [console] ACPI: Added _OSI(Processor Device)
I0526 14:41:15.171338   21767 init_comm.go:68] [console] ACPI: Added _OSI(3.0 _SCP Extensions)
I0526 14:41:15.171758   21767 init_comm.go:68] [console] ACPI: Added _OSI(Processor Aggregator Device)
I0526 14:41:15.172760   21767 init_comm.go:68] [console] ACPI: Interpreter enabled
I0526 14:41:15.172990   21767 init_comm.go:68] [console] ACPI: (supports S0 S5)
I0526 14:41:15.173339   21767 init_comm.go:68] [console] ACPI: Using IOAPIC for interrupt routing
I0526 14:41:15.174126   21767 init_comm.go:68] [console] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
I0526 14:41:15.176737   21767 init_comm.go:68] [console] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
I0526 14:41:15.177294   21767 init_comm.go:68] [console] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI]
I0526 14:41:15.177822   21767 init_comm.go:68] [console] acpi PNP0A03:00: _OSC failed (AE_NOT_FOUND); disabling ASPM
I0526 14:41:15.178182   21767 init_comm.go:68] [console] acpiphp: Slot [2] registered
I0526 14:41:15.178466   21767 init_comm.go:68] [console] acpiphp: Slot [3] registered
I0526 14:41:15.178747   21767 init_comm.go:68] [console] acpiphp: Slot [4] registered
I0526 14:41:15.179044   21767 init_comm.go:68] [console] acpiphp: Slot [5] registered
I0526 14:41:15.179329   21767 init_comm.go:68] [console] acpiphp: Slot [6] registered
I0526 14:41:15.179625   21767 init_comm.go:68] [console] acpiphp: Slot [7] registered
I0526 14:41:15.179909   21767 init_comm.go:68] [console] acpiphp: Slot [8] registered
I0526 14:41:15.180200   21767 init_comm.go:68] [console] acpiphp: Slot [9] registered
I0526 14:41:15.180498   21767 init_comm.go:68] [console] acpiphp: Slot [10] registered
I0526 14:41:15.180789   21767 init_comm.go:68] [console] acpiphp: Slot [11] registered
I0526 14:41:15.181079   21767 init_comm.go:68] [console] acpiphp: Slot [12] registered
I0526 14:41:15.181371   21767 init_comm.go:68] [console] acpiphp: Slot [13] registered
I0526 14:41:15.181677   21767 init_comm.go:68] [console] acpiphp: Slot [14] registered
I0526 14:41:15.181964   21767 init_comm.go:68] [console] acpiphp: Slot [15] registered
I0526 14:41:15.182261   21767 init_comm.go:68] [console] acpiphp: Slot [16] registered
I0526 14:41:15.182555   21767 init_comm.go:68] [console] acpiphp: Slot [17] registered
I0526 14:41:15.182855   21767 init_comm.go:68] [console] acpiphp: Slot [18] registered
I0526 14:41:15.183140   21767 init_comm.go:68] [console] acpiphp: Slot [19] registered
I0526 14:41:15.183452   21767 init_comm.go:68] [console] acpiphp: Slot [20] registered
I0526 14:41:15.183746   21767 init_comm.go:68] [console] acpiphp: Slot [21] registered
I0526 14:41:15.184043   21767 init_comm.go:68] [console] acpiphp: Slot [22] registered
I0526 14:41:15.184334   21767 init_comm.go:68] [console] acpiphp: Slot [23] registered
I0526 14:41:15.184629   21767 init_comm.go:68] [console] acpiphp: Slot [24] registered
I0526 14:41:15.184927   21767 init_comm.go:68] [console] acpiphp: Slot [25] registered
I0526 14:41:15.185238   21767 init_comm.go:68] [console] acpiphp: Slot [26] registered
I0526 14:41:15.185526   21767 init_comm.go:68] [console] acpiphp: Slot [27] registered
I0526 14:41:15.185823   21767 init_comm.go:68] [console] acpiphp: Slot [28] registered
I0526 14:41:15.186118   21767 init_comm.go:68] [console] acpiphp: Slot [29] registered
I0526 14:41:15.186416   21767 init_comm.go:68] [console] acpiphp: Slot [30] registered
I0526 14:41:15.186714   21767 init_comm.go:68] [console] acpiphp: Slot [31] registered
I0526 14:41:15.187007   21767 init_comm.go:68] [console] PCI host bridge to bus 0000:00
I0526 14:41:15.187549   21767 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7 window]
I0526 14:41:15.188091   21767 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [io  0x0d00-0xffff window]
I0526 14:41:15.188701   21767 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
I0526 14:41:15.189310   21767 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [mem 0x08000000-0xfebfffff window]
I0526 14:41:15.189727   21767 init_comm.go:68] [console] pci_bus 0000:00: root bus resource [bus 00-ff]
I0526 14:41:15.193661   21767 init_comm.go:68] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io  0x01f0-0x01f7]
I0526 14:41:15.194169   21767 init_comm.go:68] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io  0x03f6]
I0526 14:41:15.194749   21767 init_comm.go:68] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io  0x0170-0x0177]
I0526 14:41:15.195265   21767 init_comm.go:68] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io  0x0376]
I0526 14:41:15.196274   21767 init_comm.go:68] [console] pci 0000:00:01.3: quirk: [io  0x0600-0x063f] claimed by PIIX4 ACPI
I0526 14:41:15.196869   21767 init_comm.go:68] [console] pci 0000:00:01.3: quirk: [io  0x0700-0x070f] claimed by PIIX4 SMB
I0526 14:41:15.215000   21767 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11)
I0526 14:41:15.215553   21767 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 *10 11)
I0526 14:41:15.216107   21767 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 10 *11)
I0526 14:41:15.216659   21767 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 10 *11)
I0526 14:41:15.217115   21767 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKS] (IRQs *9)
I0526 14:41:15.217703   21767 init_comm.go:68] [console] ACPI: Enabled 16 GPEs in block 00 to 0F
I0526 14:41:15.217965   21767 init_comm.go:68] [console] vgaarb: loaded
I0526 14:41:15.218279   21767 init_comm.go:68] [console] SCSI subsystem initialized
I0526 14:41:15.218596   21767 init_comm.go:68] [console] PCI: Using ACPI for IRQ routing
I0526 14:41:15.219229   21767 init_comm.go:68] [console] clocksource: Switched to clocksource kvm-clock
I0526 14:41:15.219529   21767 init_comm.go:68] [console] pnp: PnP ACPI init
I0526 14:41:15.220161   21767 init_comm.go:68] [console] pnp: PnP ACPI: found 5 devices
I0526 14:41:15.227208   21767 init_comm.go:68] [console] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
I0526 14:41:15.227556   21767 init_comm.go:68] [console] NET: Registered protocol family 2
I0526 14:41:15.228223   21767 init_comm.go:68] [console] TCP established hash table entries: 1024 (order: 1, 8192 bytes)
I0526 14:41:15.228737   21767 init_comm.go:68] [console] TCP bind hash table entries: 1024 (order: 2, 16384 bytes)
I0526 14:41:15.229257   21767 init_comm.go:68] [console] TCP: Hash tables configured (established 1024 bind 1024)
I0526 14:41:15.229753   21767 init_comm.go:68] [console] UDP hash table entries: 256 (order: 1, 8192 bytes)
I0526 14:41:15.230254   21767 init_comm.go:68] [console] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes)
I0526 14:41:15.230601   21767 init_comm.go:68] [console] NET: Registered protocol family 1
I0526 14:41:15.231074   21767 init_comm.go:68] [console] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
I0526 14:41:15.231521   21767 init_comm.go:68] [console] pci 0000:00:01.0: PIIX3: Enabling Passive Release
I0526 14:41:15.232006   21767 init_comm.go:68] [console] pci 0000:00:01.0: Activating ISA DMA hang workarounds
I0526 14:41:15.232496   21767 init_comm.go:68] [console] Trying to unpack rootfs image as initramfs...
I0526 14:41:15.263172   21767 init_comm.go:68] [console] Freeing initrd memory: 2136K (ffff880007dda000 - ffff880007ff0000)
I0526 14:41:15.263899   21767 init_comm.go:68] [console] futex hash table entries: 256 (order: 2, 16384 bytes)
I0526 14:41:15.264704   21767 init_comm.go:68] [console] SGI XFS with ACLs, security attributes, no debug enabled
I0526 14:41:15.265228   21767 init_comm.go:68] [console] 9p: Installing v9fs 9p2000 file system support
I0526 14:41:15.267243   21767 init_comm.go:68] [console] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 253)
I0526 14:41:15.267519   21767 init_comm.go:68] [console] io scheduler noop registered
I0526 14:41:15.267857   21767 init_comm.go:68] [console] io scheduler cfq registered (default)
I0526 14:41:15.268317   21767 init_comm.go:68] [console] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
I0526 14:41:15.268838   21767 init_comm.go:68] [console] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
I0526 14:41:15.269449   21767 init_comm.go:68] [console] Warning: Processor Platform Limit event detected, but not handled.
I0526 14:41:15.269906   21767 init_comm.go:68] [console] Consider compiling CPUfreq support into your kernel.
I0526 14:41:15.290067   21767 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKB] enabled at IRQ 10
I0526 14:41:15.290647   21767 init_comm.go:68] [console] virtio-pci 0000:00:02.0: virtio_pci: leaving for legacy driver
I0526 14:41:15.311005   21767 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 11
I0526 14:41:15.311586   21767 init_comm.go:68] [console] virtio-pci 0000:00:03.0: virtio_pci: leaving for legacy driver
I0526 14:41:15.331660   21767 init_comm.go:68] [console] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 11
I0526 14:41:15.332233   21767 init_comm.go:68] [console] virtio-pci 0000:00:04.0: virtio_pci: leaving for legacy driver
I0526 14:41:15.333075   21767 init_comm.go:68] [console] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
I0526 14:41:15.356643   21767 init_comm.go:68] [console] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
I0526 14:41:15.381688   21767 init_comm.go:68] [console] brd: module loaded
I0526 14:41:15.381903   21767 init_comm.go:68] [console] loop: module loaded
I0526 14:41:15.402271   21767 init_comm.go:68] [console] scsi host0: Virtio SCSI HBA
I0526 14:41:15.418581   21767 init_comm.go:68] [console] rtc_cmos 00:00: RTC can wake from S4
I0526 14:41:15.419243   21767 init_comm.go:68] [console] rtc_cmos 00:00: rtc core: registered rtc_cmos as rtc0
I0526 14:41:15.419795   21767 init_comm.go:68] [console] rtc_cmos 00:00: alarms up to one day, 114 bytes nvram
I0526 14:41:15.420206   21767 init_comm.go:68] [console] NET: Registered protocol family 10
I0526 14:41:15.420648   21767 init_comm.go:68] [console] NET: Registered protocol family 17
I0526 14:41:15.420974   21767 init_comm.go:68] [console] 9pnet: Installing 9P2000 support
I0526 14:41:15.441464   21767 init_comm.go:68] [console] registered taskstats version 1
I0526 14:41:15.442312   21767 init_comm.go:68] [console] rtc_cmos 00:00: setting system clock to 2016-05-26 06:41:15 UTC (1464244875)
I0526 14:41:15.443547   21767 init_comm.go:68] [console] Freeing unused kernel memory: 860K (ffffffff8161f000 - ffffffff816f6000)
I0526 14:41:15.444064   21767 init_comm.go:68] [console] create directory /sys
I0526 14:41:15.444298   21767 init_comm.go:68] [console] create directory /sbin
I0526 14:41:15.444511   21767 init_comm.go:68] [console] create directory /proc
I0526 14:41:15.444706   21767 init_comm.go:68] [console] uptime 0.30 0.02
I0526 14:41:15.444796   21767 init_comm.go:68] [console] 
I0526 14:41:15.445078   21767 init_comm.go:68] [console] create directory /dev/pts
I0526 14:41:15.445408   21767 init_comm.go:68] [console] open hyper channel /dev/vport0p1
I0526 14:41:15.445637   21767 qmp_handler.go:103] got a message {"timestamp": {"seconds": 1464244875, "microseconds": 445472}, "event": "VSERPORT_CHANGE", "data": {"open": true, "id": "channel0"}}
I0526 14:41:15.445667   21767 qmp_handler.go:107] got event: VSERPORT_CHANGE
I0526 14:41:15.445685   21767 qmp_handler.go:323] got QMP event VSERPORT_CHANGE
I0526 14:41:15.445734   21767 init_comm.go:68] [console] send ready message
I0526 14:41:15.445998   21767 init_comm.go:68] [console] hyper send type 8, len 0
I0526 14:41:15.446061   21767 init_comm.go:106] read 8/8 [length = 0]
I0526 14:41:15.446077   21767 init_comm.go:110] data length is 8
I0526 14:41:15.446086   21767 init_comm.go:143] Get init ready message
I0526 14:41:15.446111   21767 init_comm.go:190] got cmd:1
I0526 14:41:15.446134   21767 init_comm.go:281] send command 1 to init, payload: '{"hostname":"d6a01446059e","containers":[],"shareDir":"share_dir"}'.
I0526 14:41:15.446152   21767 init_comm.go:294] write 74 to init, payload: 'J{"hostname":"d6a01446059e","containers":[],"shareDir":"share_dir"}'.
I0526 14:41:15.446257   21767 init_comm.go:299] message sent, set pong timer
I0526 14:41:15.446273   21767 hypervisor.go:29] vm vm-DNlnLYiACB: main event loop got message 5(EVENT_INIT_CONNECTED)
I0526 14:41:15.446287   21767 vm_states.go:490] begin to wait vm commands
I0526 14:41:15.446313   21767 init_comm.go:96] trying to read 8 bytes
I0526 14:41:15.446329   21767 vm.go:260] Get the response from VM, VM id is vm-DNlnLYiACB!
I0526 14:41:15.446487   21767 init_comm.go:68] [console] channel sh.hyper.channel.1, directory sh.hyper.channel.0
I0526 14:41:15.446550   21767 init_comm.go:68] [console] 
I0526 14:41:15.446821   21767 init_comm.go:68] [console] open hyper channel /dev/vport0p2
I0526 14:41:15.447403   21767 init_comm.go:68] [console] hyper_init_event hyper channel event 0x6165c0, ops 0x6163c0, fd 3
I0526 14:41:15.447727   21767 init_comm.go:68] [console] hyper_add_event add event fd 3, 0x6163c0
I0526 14:41:15.448174   21767 init_comm.go:68] [console] hyper_init_event hyper ttyfd event 0x616588, ops 0x616380, fd 4
I0526 14:41:15.448498   21767 init_comm.go:68] [console] hyper_add_event add event fd 4, 0x616380
I0526 14:41:15.448723   21767 init_comm.go:68] [console] hyper_loop epoll_wait 1
I0526 14:41:15.449183   21767 init_comm.go:68] [console] hyper_handle_event get event 1, de 0x6165c0, fd 3. ops 0x6163c0
I0526 14:41:15.449615   21767 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, de 0x6165c0, fd 3, 0x6163c0
I0526 14:41:15.449787   21767 init_comm.go:68] [console] hyper_event_read
I0526 14:41:15.450024   21767 init_comm.go:68] [console] already read 8 bytes data
I0526 14:41:15.450250   21767 init_comm.go:68] [console] hyper send type 14, len 4
I0526 14:41:15.450306   21767 init_comm.go:106] read 8/8 [length = 0]
I0526 14:41:15.450332   21767 init_comm.go:110] data length is 12
I0526 14:41:15.450341   21767 init_comm.go:96] trying to read 4 bytes
I0526 14:41:15.450352   21767 init_comm.go:106] read 12/12 [length = 12]
I0526 14:41:15.450364   21767 init_comm.go:96] trying to read 8 bytes
I0526 14:41:15.450381   21767 init_comm.go:190] got cmd:14
I0526 14:41:15.450401   21767 init_comm.go:253] get command NEXT
I0526 14:41:15.450409   21767 init_comm.go:256] send 74, receive 8
I0526 14:41:15.450998   21767 init_comm.go:106] read 8/8 [length = 0]
I0526 14:41:15.451016   21767 init_comm.go:110] data length is 12
I0526 14:41:15.451024   21767 init_comm.go:96] trying to read 4 bytes
I0526 14:41:15.451035   21767 init_comm.go:106] read 12/12 [length = 12]
I0526 14:41:15.451048   21767 init_comm.go:96] trying to read 8 bytes
I0526 14:41:15.451063   21767 init_comm.go:190] got cmd:14
I0526 14:41:15.451074   21767 init_comm.go:253] get command NEXT
I0526 14:41:15.451082   21767 init_comm.go:256] send 74, receive 74
I0526 14:41:15.451122   21767 init_comm.go:68] [console] get length 74
I0526 14:41:15.451134   21767 init_comm.go:68] [console] read 66 bytes data, total data 74
I0526 14:41:15.451143   21767 init_comm.go:68] [console] hyper send type 14, len 4
I0526 14:41:15.452336   21767 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 64 36 61 30 31 34 34 36 30 35 39 65 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 14:41:15.452639   21767 init_comm.go:68] [console]  hyper_channel_handle, type 1, len 74
I0526 14:41:15.453309   21767 init_comm.go:68] [console] call hyper_start_pod, json {"hostname":"d6a01446059e","containers":[],"shareDir":"share_dir"}, len 66
I0526 14:41:15.454058   21767 init_comm.go:68] [console] call hyper_start_pod, json {"hostname":"d6a01446059e","containers":[],"shareDir":"share_dir"}, len 66
I0526 14:41:15.454304   21767 init_comm.go:68] [console] jsmn parse successed, n is 7
I0526 14:41:15.454559   21767 init_comm.go:68] [console] token 0, type is 1, size is 3
I0526 14:41:15.454818   21767 init_comm.go:68] [console] token 1, type is 3, size is 1
I0526 14:41:15.455072   21767 init_comm.go:68] [console] hostname is d6a01446059e
I0526 14:41:15.455321   21767 init_comm.go:68] [console] token 3, type is 3, size is 1
I0526 14:41:15.455525   21767 init_comm.go:68] [console] container count 0
I0526 14:41:15.455789   21767 init_comm.go:68] [console] token 5, type is 3, size is 1
I0526 14:41:15.456017   21767 init_comm.go:68] [console] share tag is share_dir
I0526 14:41:15.456245   21767 init_comm.go:68] [console] create directory /tmp
I0526 14:41:15.456503   21767 init_comm.go:68] [console] create directory /tmp/hyper
I0526 14:41:15.456765   21767 init_comm.go:68] [console] create directory /tmp/hyper/proc
I0526 14:41:15.457487   21767 init_comm.go:68] [console] random: busybox urandom read with 8 bits of entropy available
I0526 14:41:15.457947   21767 init_comm.go:68] [console] finish rescan
I0526 14:41:15.458322   21767 init_comm.go:68] [console] create directory /tmp/hyper/shared
I0526 14:41:15.459775   21767 init_comm.go:68] [console] pod init pid 325
I0526 14:41:15.460086   21767 init_comm.go:68] [console] hyper send type 8, len 0
I0526 14:41:15.460285   21767 init_comm.go:68] [console] uptime 0.31 0.02
I0526 14:41:15.460373   21767 init_comm.go:68] [console] 
I0526 14:41:15.460600   21767 init_comm.go:68] [console] hyper send type 9, len 0
I0526 14:41:15.460676   21767 init_comm.go:106] read 8/8 [length = 0]
I0526 14:41:15.460690   21767 init_comm.go:110] data length is 8
I0526 14:41:15.460699   21767 init_comm.go:96] trying to read 8 bytes
I0526 14:41:15.460713   21767 init_comm.go:190] got cmd:9
I0526 14:41:15.460726   21767 init_comm.go:209] ack got, clear pong timer
I0526 14:41:15.460744   21767 hypervisor.go:29] vm vm-DNlnLYiACB: main event loop got message 31(COMMAND_ACK)
I0526 14:41:15.460757   21767 vm_states.go:500] [starting] got init ack to &{1 859533633536 <nil> [] 859531513408}
I0526 14:41:15.460859   21767 context.go:211] VM vm-DNlnLYiACB: state change from STARTING to 'RUNNING'
I0526 14:41:15.460873   21767 vm_states.go:516] pod start success 
I0526 14:41:15.460897   21767 vm.go:260] Get the response from VM, VM id is vm-DNlnLYiACB!
I0526 14:41:15.460919   21767 hyperpod.go:319] result: code 0 Start POD success
I0526 14:41:15.460932   21767 hyperpod.go:185] get exec path /home/darcy/gocode/src/github.com/hyperhq/runv/runv-containerd
I0526 14:41:15.460951   21767 init_comm.go:68] [console] pid 324 exit normally, status 0
I0526 14:41:15.461252   21767 init_comm.go:68] [console] can not find exec whose pid is 324
I0526 14:41:15.461469   21767 init_comm.go:68] [console] hyper_loop epoll_wait -1
I0526 14:41:15.470628   21767 hyperpod.go:234] nsListener pid is 22771
I0526 14:41:15.470657   21767 supervisor.go:168] createHyperPod() returns
I0526 14:41:15.470667   21767 hyperpod.go:257] createContainer()
I0526 14:41:15.470677   21767 process.go:33] process setupIO: stdin /var/run/docker/libcontainerd/d6a01446059ea660f3281ff4ceba4d307e9dc8c469185e74b34157129cb3bc2b/init-stdin, stdout /var/run/docker/libcontainerd/d6a01446059ea660f3281ff4ceba4d307e9dc8c469185e74b34157129cb3bc2b/init-stdout, stderr /var/run/docker/libcontainerd/d6a01446059ea660f3281ff4ceba4d307e9dc8c469185e74b34157129cb3bc2b/init-stderr
I0526 14:41:15.470715   21767 process.go:59] process setupIO() success
I0526 14:41:15.470731   21767 hyperpod.go:283] createContainer()
I0526 14:41:15.470740   21767 hyperpod.go:289] createContainer() calls c.run(p)
I0526 14:41:15.470752   21767 supervisor.go:53] Supervisor.CreateContainer() return: c:&{d6a01446059ea660f3281ff4ceba4d307e9dc8c469185e74b34157129cb3bc2b /var/run/docker/libcontainerd/d6a01446059ea660f3281ff4ceba4d307e9dc8c469185e74b34157129cb3bc2b 0xc82006cd80 map[init:0xc820332ea0] 0xc820495d00} p:&{init /var/run/docker/libcontainerd/d6a01446059ea660f3281ff4ceba4d307e9dc8c469185e74b34157129cb3bc2b/init-stdin /var/run/docker/libcontainerd/d6a01446059ea660f3281ff4ceba4d307e9dc8c469185e74b34157129cb3bc2b/init-stdout /var/run/docker/libcontainerd/d6a01446059ea660f3281ff4ceba4d307e9dc8c469185e74b34157129cb3bc2b/init-stderr 0xc82006cdb0 -1 d6a01446059ea660f3281ff4ceba4d307e9dc8c469185e74b34157129cb3bc2b-init 0xc820495f40 true 0xc820495f80 <nil>}
I0526 14:41:15.470789   21767 server.go:50] end Supervisor.CreateContainer(), build api Container
I0526 14:41:15.470801   21767 server.go:55] gRPC respond CreateContainer
I0526 14:41:15.471080   21767 container.go:64] save state id d6a01446059ea660f3281ff4ceba4d307e9dc8c469185e74b34157129cb3bc2b, boundle /var/run/docker/libcontainerd/d6a01446059ea660f3281ff4ceba4d307e9dc8c469185e74b34157129cb3bc2b
I0526 14:41:15.471188   21767 container.go:95] prepare hypervisor info
I0526 14:41:15.471231   21767 ocf-linux.go:21] env: PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
I0526 14:41:15.471279   21767 ocf-linux.go:21] env: HOSTNAME=d6a01446059e
I0526 14:41:15.471309   21767 ocf-linux.go:21] env: TERM=xterm
I0526 14:41:15.474188   21767 container.go:311] Skip mount point "/proc" of type proc
I0526 14:41:15.474259   21767 container.go:311] Skip mount point "/dev" of type tmpfs
I0526 14:41:15.479320   21767 container.go:311] Skip mount point "/sys" of type sysfs
I0526 14:41:15.479390   21767 container.go:311] Skip mount point "/sys/fs/cgroup" of type cgroup
I0526 14:41:15.479443   21767 container.go:311] Skip mount point "/dev/mqueue" of type mqueue
I0526 14:41:15.499909   21767 hypervisor.go:29] vm vm-DNlnLYiACB: main event loop got message 34(GENERIC_OPERATION)
I0526 14:41:15.500004   21767 vm_states.go:303] handle GenericOperation(Attach) on state(RUNNING)
I0526 14:41:15.500037   21767 context.go:179] can not found container d6a01446059ea660f3281ff4ceba4d307e9dc8c469185e74b34157129cb3bc2b
I0526 14:41:15.500070   21767 vm_states.go:220] attachment d6a01446059ea660f3281ff4ceba4d307e9dc8c469185e74b34157129cb3bc2b-init is pending
I0526 14:41:15.573625   21767 hyperpod.go:127] interface configuration of pod ns is []
I0526 14:41:15.573671   21767 hypervisor.go:29] vm vm-DNlnLYiACB: main event loop got message 34(GENERIC_OPERATION)
I0526 14:41:15.573685   21767 vm_states.go:303] handle GenericOperation(AddRoute) on state(RUNNING)
I0526 14:41:15.573702   21767 init_comm.go:190] got cmd:21
I0526 14:41:15.573719   21767 init_comm.go:281] send command 21 to init, payload: '{}'.
I0526 14:41:15.573738   21767 init_comm.go:294] write 10 to init, payload: ' 
{}'.
I0526 14:41:15.573754   21767 init_comm.go:299] message sent, set pong timer
I0526 14:41:15.574104   21767 init_comm.go:68] [console] hyper_loop epoll_wait 1
I0526 14:41:15.574533   21767 init_comm.go:68] [console] hyper_handle_event get event 1, de 0x6165c0, fd 3. ops 0x6163c0
I0526 14:41:15.574971   21767 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, de 0x6165c0, fd 3, 0x6163c0
I0526 14:41:15.575139   21767 init_comm.go:68] [console] hyper_event_read
I0526 14:41:15.575379   21767 init_comm.go:68] [console] already read 8 bytes data
I0526 14:41:15.575615   21767 init_comm.go:68] [console] hyper send type 14, len 4
I0526 14:41:15.575685   21767 init_comm.go:106] read 8/8 [length = 0]
I0526 14:41:15.575705   21767 init_comm.go:110] data length is 12
I0526 14:41:15.575713   21767 init_comm.go:96] trying to read 4 bytes
I0526 14:41:15.575725   21767 init_comm.go:106] read 12/12 [length = 12]
I0526 14:41:15.575742   21767 init_comm.go:96] trying to read 8 bytes
I0526 14:41:15.575765   21767 init_comm.go:190] got cmd:14
I0526 14:41:15.575777   21767 init_comm.go:253] get command NEXT
I0526 14:41:15.575785   21767 init_comm.go:256] send 10, receive 8
I0526 14:41:15.576382   21767 init_comm.go:106] read 8/8 [length = 0]
I0526 14:41:15.576397   21767 init_comm.go:110] data length is 12
I0526 14:41:15.576405   21767 init_comm.go:96] trying to read 4 bytes
I0526 14:41:15.576415   21767 init_comm.go:106] read 12/12 [length = 12]
I0526 14:41:15.576417   21767 init_comm.go:68] [console] get length 10
I0526 14:41:15.576434   21767 init_comm.go:190] got cmd:14
I0526 14:41:15.576451   21767 init_comm.go:253] get command NEXT
I0526 14:41:15.576464   21767 init_comm.go:256] send 10, receive 10
I0526 14:41:15.576438   21767 init_comm.go:68] [console] read 2 bytes data, total data 10
I0526 14:41:15.576480   21767 init_comm.go:68] [console] hyper send type 14, len 4
I0526 14:41:15.576427   21767 init_comm.go:96] trying to read 8 bytes
I0526 14:41:15.576701   21767 init_comm.go:68] [console] 0 0 0 15 0 0 0 a 7b 7d 
I0526 14:41:15.577019   21767 init_comm.go:68] [console]  hyper_channel_handle, type 21, len 10
I0526 14:41:15.577226   21767 init_comm.go:68] [console] routes need array
I0526 14:41:15.577433   21767 init_comm.go:68] [console] fail to parse routes
I0526 14:41:15.577620   21767 init_comm.go:68] [console] parse route failed
I0526 14:41:15.577874   21767 init_comm.go:68] [console] hyper send type 10, len 0
I0526 14:41:15.577952   21767 init_comm.go:106] read 8/8 [length = 0]
I0526 14:41:15.577967   21767 init_comm.go:110] data length is 8
I0526 14:41:15.577976   21767 init_comm.go:96] trying to read 8 bytes
I0526 14:41:15.577989   21767 init_comm.go:190] got cmd:10
I0526 14:41:15.578004   21767 init_comm.go:209] ack got, clear pong timer
E0526 14:41:15.578016   21767 hyperpod.go:152] Error: 
E0526 14:41:15.578034   21767 container.go:145] fail to initialize pod network Error: 
I0526 14:41:15.578046   21767 supervisor.go:115] reap container d6a01446059ea660f3281ff4ceba4d307e9dc8c469185e74b34157129cb3bc2b processId init
I0526 14:41:15.578070   21767 hypervisor.go:29] vm vm-DNlnLYiACB: main event loop got message 24(COMMAND_SHUTDOWN)
I0526 14:41:15.578082   21767 vm_states.go:328] got shutdown command, shutting down
I0526 14:41:15.578097   21767 context.go:211] VM vm-DNlnLYiACB: state change from RUNNING to 'TERMINATING'
I0526 14:41:15.578108   21767 init_comm.go:190] got cmd:4
I0526 14:41:15.578122   21767 init_comm.go:281] send command 4 to init, payload: 'null'.
I0526 14:41:15.578139   21767 init_comm.go:294] write 12 to init, payload: ' 
                                                                            null'.
I0526 14:41:15.584221   21767 init_comm.go:299] message sent, set pong timer
I0526 14:41:15.580794   21767 init_comm.go:68] [console] hyper_loop epoll_wait 1
I0526 14:41:15.584243   21767 init_comm.go:68] [console] hyper_handle_event get event 1, de 0x6165c0, fd 3. ops 0x6163c0
I0526 14:41:15.586745   21767 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, de 0x6165c0, fd 3, 0x6163c0
I0526 14:41:15.586943   21767 init_comm.go:68] [console] hyper_event_read
I0526 14:41:15.587197   21767 init_comm.go:68] [console] already read 8 bytes data
I0526 14:41:15.587442   21767 init_comm.go:68] [console] hyper send type 14, len 4
I0526 14:41:15.587530   21767 init_comm.go:106] read 8/8 [length = 0]
I0526 14:41:15.587549   21767 init_comm.go:110] data length is 12
I0526 14:41:15.587557   21767 init_comm.go:96] trying to read 4 bytes
I0526 14:41:15.587568   21767 init_comm.go:106] read 12/12 [length = 12]
I0526 14:41:15.587584   21767 init_comm.go:96] trying to read 8 bytes
I0526 14:41:15.587601   21767 init_comm.go:190] got cmd:14
I0526 14:41:15.587612   21767 init_comm.go:253] get command NEXT
I0526 14:41:15.587620   21767 init_comm.go:256] send 12, receive 8
I0526 14:41:15.587695   21767 init_comm.go:68] [console] get length 12
I0526 14:41:15.587980   21767 init_comm.go:68] [console] read 4 bytes data, total data 12
I0526 14:41:15.588225   21767 init_comm.go:68] [console] hyper send type 14, len 4
I0526 14:41:15.588284   21767 init_comm.go:106] read 8/8 [length = 0]
I0526 14:41:15.588297   21767 init_comm.go:110] data length is 12
I0526 14:41:15.588304   21767 init_comm.go:96] trying to read 4 bytes
I0526 14:41:15.588315   21767 init_comm.go:106] read 12/12 [length = 12]
I0526 14:41:15.588330   21767 init_comm.go:96] trying to read 8 bytes
I0526 14:41:15.588344   21767 init_comm.go:190] got cmd:14
I0526 14:41:15.588354   21767 init_comm.go:253] get command NEXT
I0526 14:41:15.588363   21767 init_comm.go:256] send 12, receive 12
I0526 14:41:15.588544   21767 init_comm.go:68] [console] 0 0 0 4 0 0 0 c 6e 75 6c 6c 
I0526 14:41:15.588829   21767 init_comm.go:68] [console]  hyper_channel_handle, type 4, len 12
I0526 14:41:15.589051   21767 init_comm.go:68] [console] get DESTROYPOD message
I0526 14:41:15.589520   21767 init_comm.go:68] [console] Sending SIGTERM
I0526 14:41:15.589689   21767 init_comm.go:68] [console] kill process 325
I0526 14:41:15.589883   21767 init_comm.go:68] [console] kill process 323
I0526 14:41:15.590053   21767 init_comm.go:68] [console] kill process 322
I0526 14:41:15.590215   21767 init_comm.go:68] [console] kill process 65
I0526 14:41:15.590400   21767 init_comm.go:68] [console] kill process 64
I0526 14:41:15.590565   21767 init_comm.go:68] [console] kill process 63
I0526 14:41:15.590732   21767 init_comm.go:68] [console] kill process 62
I0526 14:41:15.590903   21767 init_comm.go:68] [console] kill process 61
I0526 14:41:15.591078   21767 init_comm.go:68] [console] kill process 60
I0526 14:41:15.591237   21767 init_comm.go:68] [console] kill process 59
I0526 14:41:15.591430   21767 init_comm.go:68] [console] kill process 58
I0526 14:41:15.591597   21767 init_comm.go:68] [console] kill process 57
I0526 14:41:15.591761   21767 init_comm.go:68] [console] kill process 56
I0526 14:41:15.591950   21767 init_comm.go:68] [console] kill process 55
I0526 14:41:15.592115   21767 init_comm.go:68] [console] kill process 54
I0526 14:41:15.592281   21767 init_comm.go:68] [console] kill process 53
I0526 14:41:15.592444   21767 init_comm.go:68] [console] kill process 52
I0526 14:41:15.592621   21767 init_comm.go:68] [console] kill process 51
I0526 14:41:15.592787   21767 init_comm.go:68] [console] kill process 50
I0526 14:41:15.592974   21767 init_comm.go:68] [console] kill process 49
I0526 14:41:15.593138   21767 init_comm.go:68] [console] kill process 48
I0526 14:41:15.593303   21767 init_comm.go:68] [console] kill process 47
I0526 14:41:15.593480   21767 init_comm.go:68] [console] kill process 37
I0526 14:41:15.593646   21767 init_comm.go:68] [console] kill process 23
I0526 14:41:15.593823   21767 init_comm.go:68] [console] kill process 22
I0526 14:41:15.593998   21767 init_comm.go:68] [console] kill process 21
I0526 14:41:15.594165   21767 init_comm.go:68] [console] kill process 20
I0526 14:41:15.594324   21767 init_comm.go:68] [console] kill process 19
I0526 14:41:15.594489   21767 init_comm.go:68] [console] kill process 18
I0526 14:41:15.594674   21767 init_comm.go:68] [console] kill process 17
I0526 14:41:15.594848   21767 init_comm.go:68] [console] kill process 16
I0526 14:41:15.595014   21767 init_comm.go:68] [console] kill process 15
I0526 14:41:15.595175   21767 init_comm.go:68] [console] kill process 14
I0526 14:41:15.595362   21767 init_comm.go:68] [console] kill process 13
I0526 14:41:15.595542   21767 init_comm.go:68] [console] kill process 12
I0526 14:41:15.595697   21767 init_comm.go:68] [console] kill process 11
I0526 14:41:15.595884   21767 init_comm.go:68] [console] kill process 10
I0526 14:41:15.596044   21767 init_comm.go:68] [console] kill process 9
I0526 14:41:15.596205   21767 init_comm.go:68] [console] kill process 8
I0526 14:41:15.596363   21767 init_comm.go:68] [console] kill process 7
I0526 14:41:15.596522   21767 init_comm.go:68] [console] kill process 6
I0526 14:41:15.596697   21767 init_comm.go:68] [console] kill process 5
I0526 14:41:15.596870   21767 init_comm.go:68] [console] kill process 4
I0526 14:41:15.597032   21767 init_comm.go:68] [console] kill process 3
I0526 14:41:15.597187   21767 init_comm.go:68] [console] kill process 2
I0526 14:41:16.267414   21767 init_comm.go:68] [console] tsc: Refined TSC clocksource calibration: 3092.974 MHz
I0526 14:41:16.268277   21767 init_comm.go:68] [console] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x2c955ac38be, max_idle_ns: 440795348546 ns
I0526 14:41:16.445769   21767 qmp_handler.go:103] got a message {"timestamp": {"seconds": 1464244875, "microseconds": 446884}, "event": "VSERPORT_CHANGE", "data": {"open": true, "id": "channel1"}}
I0526 14:41:16.445810   21767 qmp_handler.go:107] got event: VSERPORT_CHANGE
I0526 14:41:16.445833   21767 qmp_handler.go:323] got QMP event VSERPORT_CHANGE
I0526 14:41:25.578208   21767 hypervisor.go:29] vm vm-DNlnLYiACB: main event loop got message 3(EVENT_VM_TIMEOUT)
W0526 14:41:25.578256   21767 vm_states.go:651] VM did not exit in time, try to stop it
E0526 14:41:25.578273   21767 vm_states.go:294] Shutting down because of an exception: vm terminating timeout
I0526 14:41:25.578293   21767 qmp_handler.go:296] got new session
I0526 14:41:25.578314   21767 qmp_handler.go:225] Begin process command session
I0526 14:41:25.578338   21767 qmp_handler.go:243] sending command (1) {"execute":"quit"}
I0526 14:41:25.578374   21767 vm.go:298] Got response: 7: vm terminating timeout
I0526 14:41:25.578770   21767 qmp_handler.go:103] got a message {"return": {}}
I0526 14:41:25.578839   21767 qmp_handler.go:103] got a message {"timestamp": {"seconds": 1464244885, "microseconds": 578746}, "event": "SHUTDOWN"}
I0526 14:41:25.578865   21767 qmp_handler.go:107] got event: SHUTDOWN
I0526 14:41:25.578875   21767 qmp_handler.go:152] Shutdown, quit QMP receiver
I0526 14:41:25.578886   21767 qmp_handler.go:323] got QMP event SHUTDOWN
I0526 14:41:25.578895   21767 qmp_handler.go:325] got QMP shutdown event, quit...
I0526 14:41:25.578904   21767 hypervisor.go:29] vm vm-DNlnLYiACB: main event loop got message 1(EVENT_VM_EXIT)
I0526 14:41:25.578915   21767 vm_states.go:623] Got VM shutdown event while terminating, go to cleaning up
I0526 14:41:25.578929   21767 vm_states.go:36] VM has exit...
I0526 14:41:25.578941   21767 devicemap.go:93] All resource being released, someone is waiting for us...
I0526 14:41:25.578949   21767 context.go:198] no more device to release/remove/umount, quit
I0526 14:41:25.578959   21767 tty.go:233] Close tty d6a01446059ea660f3281ff4ceba4d307e9dc8c469185e74b34157129cb3bc2b-init
I0526 14:41:25.579018   21767 qemu_process.go:19] quit watch dog.
I0526 14:41:25.579046   21767 vm.go:298] Got response: 2: VM shut down
I0526 14:41:25.579060   21767 hyperpod.go:342] StopPod fail: QEMU response data is nil
E0526 14:41:25.583432   21767 tty.go:90] read tty data failed
I0526 14:41:25.583457   21767 tty.go:151] tty socket closed, quit the reading goroutine EOF
I0526 14:41:25.583488   21767 tty.go:118] tty chan closed, quit sent goroutine
E0526 14:41:25.583500   21767 init_comm.go:99] read init data failed
I0526 14:41:25.583432   21767 tty.go:428] Input byte chan closed, close the output string chan
I0526 14:41:25.583617   21767 init_comm.go:70] console output end
I0526 14:41:45.578123   21767 init_comm.go:216] Send ping message to init
I0526 14:41:45.578197   21767 init_comm.go:190] got cmd:12
I0526 14:41:45.578216   21767 init_comm.go:281] send command 12 to init, payload: 'null'.
I0526 14:41:45.578254   21767 init_comm.go:294] write 0 to init, payload: '

                                                                           null'.
WeiZhang555 commented 8 years ago

Run docker run -tid busybox sh with runv-containerd, note that network is default:

I0526 15:17:24.086326   29979 server.go:31] gRPC handle CreateContainer
I0526 15:17:24.087356   29979 vm.go:179] hyperHandlePodEvent pod pod-dZmchdHooY, vm vm-XNcIHLnhlU
I0526 15:17:24.087453   29979 hypervisor.go:29] vm vm-XNcIHLnhlU: main event loop got message 21(COMMAND_RUN_POD)
I0526 15:17:24.087559   29979 vm_states.go:449] got spec, prepare devices
I0526 15:17:24.087737   29979 vm_states.go:67] initial vm spec: {
        "hostname": "5663675f1fab",
        "containers": [],
        "shareDir": "share_dir"
    }
I0526 15:17:24.087764   29979 context.go:211] VM vm-XNcIHLnhlU: state change from INIT to 'STARTING'
I0526 15:17:24.087776   29979 hypervisor.go:29] vm vm-XNcIHLnhlU: main event loop got message 10(EVENT_DEV_SKIP)
I0526 15:17:24.087787   29979 vm_states.go:476] device ready, could run pod.
I0526 15:17:24.087509   29979 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-XNcIHLnhlU/qmp.sock,server,nowait -serial unix:/var/run/hyper/vm-XNcIHLnhlU/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-XNcIHLnhlU/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-XNcIHLnhlU/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-XNcIHLnhlU/share_dir,security_model=none -device virtio-9p-pci,fsdev=virtio9p,mount_tag=share_dir
I0526 15:17:24.095480   29979 qemu_process.go:74] starting daemon with pid: 30108
I0526 15:17:24.107616   29979 init_comm.go:133] Wating for init messages...
I0526 15:17:24.107718   29979 init_comm.go:96] trying to read 8 bytes
I0526 15:17:24.107616   29979 init_comm.go:53] connected to /var/run/hyper/vm-XNcIHLnhlU/console.sock
I0526 15:17:24.107762   29979 init_comm.go:60] connected /var/run/hyper/vm-XNcIHLnhlU/console.sock as telnet mode.
I0526 15:17:24.107616   29979 qmp_handler.go:167] connected to /var/run/hyper/vm-XNcIHLnhlU/qmp.sock
I0526 15:17:24.107803   29979 qmp_handler.go:177] begin qmp init...
I0526 15:17:24.107667   29979 tty.go:144] tty socket connected
I0526 15:17:24.107823   29979 tty.go:87] tty: trying to read 12 bytes
E0526 15:17:24.117467   29979 qmp_handler.go:181] get qmp welcome failed: read unix @->/var/run/hyper/vm-XNcIHLnhlU/qmp.sock: read: connection reset by peer
E0526 15:17:24.117826   29979 qmp_handler.go:361] QMP initialize failed
I0526 15:17:24.117873   29979 hypervisor.go:29] vm vm-XNcIHLnhlU: main event loop got message 35(ERROR_INIT_FAIL)
E0526 15:17:24.117908   29979 vm_states.go:408] read unix @->/var/run/hyper/vm-XNcIHLnhlU/qmp.sock: read: connection reset by peer
E0526 15:17:24.117943   29979 vm_states.go:285] Shutting down because of an exception: Fail during init pod running environment
I0526 15:17:24.117979   29979 context.go:211] VM vm-XNcIHLnhlU: state change from STARTING to 'TERMINATING'
I0526 15:17:24.118034   29979 vm.go:260] Get the response from VM, VM id is vm-XNcIHLnhlU!
I0526 15:17:24.118075   29979 hypervisor.go:29] vm vm-XNcIHLnhlU: main event loop got message 24(COMMAND_SHUTDOWN)
I0526 15:17:24.118116   29979 vm.go:81] Got response: 13: unexpected event during terminating
E0526 15:17:24.118169   29979 init_comm.go:99] read init data failed
E0526 15:17:24.118182   29979 init_comm.go:137] read init message failed... read unix @->/var/run/hyper/vm-XNcIHLnhlU/hyper.sock: read: connection reset by peer
I0526 15:17:24.118200   29979 hypervisor.go:29] vm vm-XNcIHLnhlU: main event loop got message 35(ERROR_INIT_FAIL)
W0526 15:17:24.118213   29979 vm_states.go:399] got unexpected event during terminating
E0526 15:17:24.118251   29979 tty.go:90] read tty data failed
I0526 15:17:24.118264   29979 tty.go:151] tty socket closed, quit the reading goroutine read unix @->/var/run/hyper/vm-XNcIHLnhlU/tty.sock: read: connection reset by peer
I0526 15:17:24.118284   29979 tty.go:118] tty chan closed, quit sent goroutine
I0526 15:17:24.118294   29979 hypervisor.go:29] vm vm-XNcIHLnhlU: main event loop got message 37(ERROR_INTERRUPTED)
I0526 15:17:24.118304   29979 vm_states.go:654] Connection interrupted while terminating
I0526 15:17:24.118357   29979 tty.go:428] Input byte chan closed, close the output string chan
I0526 15:17:24.118382   29979 init_comm.go:70] console output end
I0526 15:17:34.118083   29979 hypervisor.go:29] vm vm-XNcIHLnhlU: main event loop got message 3(EVENT_VM_TIMEOUT)
W0526 15:17:34.118118   29979 vm_states.go:651] VM did not exit in time, try to stop it
E0526 15:17:34.118184   29979 vm_states.go:294] Shutting down because of an exception: vm terminating timeout
I0526 15:17:34.118214   29979 vm.go:81] Got response: 7: vm terminating timeout
I0526 15:17:44.118309   29979 qemu_process.go:24] kill Qemu... 30108
I0526 15:17:44.118365   29979 hypervisor.go:29] vm vm-XNcIHLnhlU: main event loop got message 2(EVENT_VM_KILL)
I0526 15:17:44.118380   29979 vm_states.go:629] Got VM force killed message, go to cleaning up
I0526 15:17:44.118389   29979 vm_states.go:36] VM has exit...
I0526 15:17:44.118404   29979 context.go:198] no more device to release/remove/umount, quit
I0526 15:17:44.118429   29979 vm.go:81] Got response: 2: VM shut down
I0526 15:17:44.118439   29979 hyperpod.go:316] StartPod fail: QEMU response data is nil
I0526 15:17:44.118448   29979 supervisor.go:168] createHyperPod() returns
WeiZhang555 commented 8 years ago

Looks like it's network related error, this piece of code can remove the error:

diff --git a/supervisor/container.go b/supervisor/container.go
index b460a71..87a00e9 100644
--- a/supervisor/container.go
+++ b/supervisor/container.go
@@ -140,11 +140,12 @@ func (c *Container) start(p *Process) error {
                return err
        }

-       err = c.ownerPod.initPodNetwork(c)
-       if err != nil {
-               glog.Errorf("fail to initialize pod network %v", err)
-               return err
-       }
+       /*
+               err = c.ownerPod.initPodNetwork(c)
+               if err != nil {
+                       glog.Errorf("fail to initialize pod network %v", err)
+                       return err
+               }*/

        c.ownerPod.podStatus.AddContainer(c.Id, c.ownerPod.podStatus.Id, "", []string{}, types.S_POD_CREATED)
        return c.ownerPod.vm.NewContainer(u, info)
WeiZhang555 commented 8 years ago

Latest version works now. Close this because it's resolved.