search

hyperhq / runv

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

Unable to start a container (showing pod timeout) on ubuntu 15.04, qemu version 2.5.50 #162

Closed abdasgupta closed 8 years ago

abdasgupta commented 8 years ago

Output on console for my environment: abhishek@abhishek-ThinkPad-T450:~/Documents/Works/rootfs$ ls busybox.tar config.json hyper-initrd.img kernel rootfs runtime.json runv

abhishek@abhishek-ThinkPad-T450:~/Documents/Works/rootfs$ sudo ./runv --kernel kernel --initrd hyper-initrd.img start -v=3

Below is the log:

Log file created at: 2016/04/06 19:04:17 Running on machine: abhishek-ThinkPad-T450 Binary: Built with gc go1.6 for linux/amd64 Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg I0406 19:04:16.209307 29345 init_comm.go:72] trying to read 8 bytes I0406 19:04:17.209827 29345 init_comm.go:83] read 8/8 [length = 0] I0406 19:04:18.209957 29345 init_comm.go:87] data length is 1482 I0406 19:04:19.210091 29345 init_comm.go:72] trying to read 512 bytes I0406 19:04:20.210245 29345 init_comm.go:83] read 520/1482 [length = 1482] I0406 19:04:21.210377 29345 init_comm.go:72] trying to read 512 bytes I0406 19:04:22.210527 29345 init_comm.go:83] read 1032/1482 [length = 1482] I0406 19:04:23.210655 29345 init_comm.go:72] trying to read 450 bytes I0406 19:04:24.210825 29345 init_comm.go:83] read 1482/1482 [length = 1482] I0406 19:04:25.211448 29345 vm.go:180] hyperHandlePodEvent pod pod-rrYksDEGKS, vm vm-EvCFIREQIF I0406 19:04:25.211531 29345 hypervisor.go:29] main event loop got message 23(COMMAND_RUN_POD) I0406 19:04:27.215133 29345 vm_states.go:544] got spec, prepare devices I0406 19:04:28.217454 29345 vm_states.go:72] initial vm spec: { "hostname": "shell", "containers": [], "shareDir": "share_dir" } I0406 19:04:29.217680 29345 context.go:212] VM vm-EvCFIREQIF: state change from INIT to 'STARTING' I0406 19:04:30.217817 29345 hypervisor.go:29] main event loop got message 11(EVENT_DEV_SKIP) I0406 19:04:31.217933 29345 vm_states.go:573] device ready, could run pod. I0406 19:04:25.211638 29345 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 /home/abhishek/Documents/Works/rootfs/kernel -initrd /home/abhishek/Documents/Works/rootfs/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-EvCFIREQIF/qmp.sock,server,nowait -serial unix:/var/run/hyper/vm-EvCFIREQIF/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-EvCFIREQIF/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-EvCFIREQIF/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-EvCFIREQIF/share_dir,security_model=none -device virtio-9p-pci,fsdev=virtio9p,mount_tag=share_dir I0406 19:04:33.225863 29345 qemu_process.go:74] starting daemon with pid: 29390 I0406 19:04:33.246408 29345 tty.go:157] tty socket connected I0406 19:04:35.228445 29345 tty.go:100] tty: trying to read 12 bytes I0406 19:04:33.248296 29345 init_comm.go:110] Wating for init messages... I0406 19:04:37.228709 29345 init_comm.go:72] trying to read 8 bytes I0406 19:04:33.246453 29345 init_comm.go:29] connected to /var/run/hyper/vm-EvCFIREQIF/console.sock I0406 19:04:39.232321 29345 init_comm.go:36] connected /var/run/hyper/vm-EvCFIREQIF/console.sock as telnet mode. I0406 19:04:33.248306 29345 qmp_handler.go:167] connected to /var/run/hyper/vm-EvCFIREQIF/qmp.sock I0406 19:04:41.235230 29345 qmp_handler.go:177] begin qmp init... I0406 19:04:42.235415 29345 qmp_handler.go:186] got qmp welcome, now sending command qmp_capabilities I0406 19:04:43.235614 29345 qmp_handler.go:201] waiting for response I0406 19:04:40.232705 29345 init_comm.go:44] [console] Initializing cgroup subsys cpu I0406 19:04:45.235872 29345 init_comm.go:44] [console] Linux version 4.4.0-hyper+ (laijs@ubox) (gcc version 5.2.1 20151010 (Ubuntu 5.2.1-22ubuntu2) ) #0 SMP Mon Jan 25 01:10:46 CST 2016 I0406 19:04:46.236019 29345 init_comm.go:44] [console] Command line: "console=ttyS0 panic=1 no_timer_check" I0406 19:04:47.236154 29345 init_comm.go:44] [console] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 I0406 19:04:48.236292 29345 init_comm.go:44] [console] x86/fpu: Supporting XSAVE feature 0x01: 'x87 floating point registers' I0406 19:04:49.236427 29345 init_comm.go:44] [console] x86/fpu: Supporting XSAVE feature 0x02: 'SSE registers' I0406 19:04:50.236555 29345 init_comm.go:44] [console] x86/fpu: Supporting XSAVE feature 0x04: 'AVX registers' I0406 19:04:51.236695 29345 init_comm.go:44] [console] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. I0406 19:04:52.236831 29345 init_comm.go:44] [console] x86/fpu: Using 'eager' FPU context switches. I0406 19:04:53.236965 29345 init_comm.go:44] [console] e820: BIOS-provided physical RAM map: I0406 19:04:54.237095 29345 init_comm.go:44] [console] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable I0406 19:04:55.237228 29345 init_comm.go:44] [console] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved I0406 19:04:56.237387 29345 init_comm.go:44] [console] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved I0406 19:04:57.237523 29345 init_comm.go:44] [console] BIOS-e820: [mem 0x0000000000100000-0x0000000007ffdfff] usable I0406 19:04:58.237663 29345 init_comm.go:44] [console] BIOS-e820: [mem 0x0000000007ffe000-0x0000000007ffffff] reserved I0406 19:04:59.237794 29345 init_comm.go:44] [console] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved I0406 19:05:00.237926 29345 init_comm.go:44] [console] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved I0406 19:05:01.238060 29345 init_comm.go:44] [console] NX (Execute Disable) protection: active I0406 19:05:02.238194 29345 init_comm.go:44] [console] SMBIOS 2.4 present. I0406 19:05:03.238328 29345 init_comm.go:44] [console] Hypervisor detected: KVM I0406 19:05:04.238461 29345 init_comm.go:44] [console] e820: last_pfn = 0x7ffe max_arch_pfn = 0x400000000 I0406 19:05:05.238603 29345 init_comm.go:44] [console] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WC UC- WT
I0406 19:05:06.238737 29345 init_comm.go:44] [console] found SMP MP-table at [mem 0x000f6bd0-0x000f6bdf] mapped at [ffff8800000f6bd0] I0406 19:05:07.238873 29345 init_comm.go:44] [console] Using GB pages for direct mapping I0406 19:05:08.239010 29345 init_comm.go:44] [console] RAMDISK: [mem 0x07e58000-0x07feffff] I0406 19:05:09.239148 29345 init_comm.go:44] [console] ACPI: Early table checksum verification disabled I0406 19:05:10.239284 29345 init_comm.go:44] [console] ACPI: RSDP 0x00000000000F6A50 000014 (v00 BOCHS ) I0406 19:05:11.239416 29345 init_comm.go:44] [console] ACPI: RSDT 0x0000000007FFF6D8 00002C (v01 BOCHS BXPCRSDT 00000001 BXPC 00000001) I0406 19:05:12.239559 29345 init_comm.go:44] [console] ACPI: FACP 0x0000000007FFF5EC 000074 (v01 BOCHS BXPCFACP 00000001 BXPC 00000001) I0406 19:05:13.239698 29345 init_comm.go:44] [console] ACPI: DSDT 0x0000000007FFE040 0015AC (v01 BOCHS BXPCDSDT 00000001 BXPC 00000001) I0406 19:05:14.239834 29345 init_comm.go:44] [console] ACPI: FACS 0x0000000007FFE000 000040 I0406 19:05:15.240001 29345 init_comm.go:44] [console] ACPI: APIC 0x0000000007FFF660 000078 (v01 BOCHS BXPCAPIC 00000001 BXPC 00000001) I0406 19:05:16.240139 29345 init_comm.go:44] [console] No NUMA configuration found I0406 19:05:17.240297 29345 init_comm.go:44] [console] Faking a node at [mem 0x0000000000000000-0x0000000007ffdfff] I0406 19:05:18.240433 29345 init_comm.go:44] [console] NODE_DATA(0) allocated [mem 0x07e46000-0x07e57fff] I0406 19:05:19.240825 29345 init_comm.go:44] [console] kvm-clock: Using msrs 4b564d01 and 4b564d00 I0406 19:05:20.240981 29345 init_comm.go:44] [console] kvm-clock: cpu 0, msr 0:7ffd001, primary cpu clock I0406 19:05:21.241119 29345 init_comm.go:44] [console] kvm-clock: using sched offset of 1238972380 cycles I0406 19:05:22.241260 29345 init_comm.go:44] [console] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns I0406 19:05:23.241396 29345 init_comm.go:44] [console] Zone ranges: I0406 19:05:24.241532 29345 init_comm.go:44] [console] DMA [mem 0x0000000000001000-0x0000000000ffffff] I0406 19:05:25.241691 29345 init_comm.go:44] [console] DMA32 [mem 0x0000000001000000-0x0000000007ffdfff] I0406 19:05:26.241825 29345 init_comm.go:44] [console] Normal empty I0406 19:05:27.241960 29345 init_comm.go:44] [console] Movable zone start for each node I0406 19:05:28.242093 29345 init_comm.go:44] [console] Early memory node ranges I0406 19:05:29.242232 29345 init_comm.go:44] [console] node 0: [mem 0x0000000000001000-0x000000000009efff] I0406 19:05:30.242366 29345 init_comm.go:44] [console] node 0: [mem 0x0000000000100000-0x0000000007ffdfff] I0406 19:05:31.242498 29345 init_comm.go:44] [console] Initmem setup node 0 [mem 0x0000000000001000-0x0000000007ffdfff] I0406 19:05:32.242631 29345 init_comm.go:44] [console] ACPI: PM-Timer IO Port: 0x608 I0406 19:05:33.242766 29345 init_comm.go:44] [console] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) I0406 19:05:34.242908 29345 init_comm.go:44] [console] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 I0406 19:05:35.243042 29345 init_comm.go:44] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) I0406 19:05:36.243181 29345 init_comm.go:44] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) I0406 19:05:37.243319 29345 init_comm.go:44] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) I0406 19:05:38.243453 29345 init_comm.go:44] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) I0406 19:05:39.243590 29345 init_comm.go:44] [console] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) I0406 19:05:40.243726 29345 init_comm.go:44] [console] Using ACPI (MADT) for SMP configuration information I0406 19:05:41.243889 29345 init_comm.go:44] [console] smpboot: Allowing 1 CPUs, 0 hotplug CPUs I0406 19:05:42.244025 29345 init_comm.go:44] [console] e820: [mem 0x08000000-0xfeffbfff] available for PCI devices I0406 19:05:43.244162 29345 init_comm.go:44] [console] Booting paravirtualized kernel on KVM I0406 19:05:44.244298 29345 init_comm.go:44] [console] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns I0406 19:05:45.244442 29345 init_comm.go:44] [console] setup_percpu: NR_CPUS:8 nr_cpumask_bits:8 nr_cpu_ids:1 nr_node_ids:1 I0406 19:05:46.244577 29345 init_comm.go:44] [console] PERCPU: Embedded 31 pages/cpu @ffff880007c00000 s89560 r8192 d29224 u2097152 I0406 19:05:47.244711 29345 init_comm.go:44] [console] KVM setup async PF for cpu 0 I0406 19:05:48.244847 29345 init_comm.go:44] [console] kvm-stealtime: cpu 0, msr 7c0d480 I0406 19:05:49.244979 29345 init_comm.go:44] [console] Built 1 zonelists in Node order, mobility grouping on. Total pages: 32199 I0406 19:05:50.245110 29345 init_comm.go:44] [console] Policy zone: DMA32 I0406 19:05:51.245265 29345 init_comm.go:44] [console] Kernel command line: "console=ttyS0 panic=1 no_timer_check" I0406 19:05:52.245399 29345 init_comm.go:44] [console] PID hash table entries: 512 (order: 0, 4096 bytes) I0406 19:05:53.245535 29345 init_comm.go:44] [console] Memory: 119124K/130672K available (4225K kernel code, 452K rwdata, 1280K rodata, 860K init, 752K bss, 11548K reserved, 0K cma-reserved) I0406 19:05:54.245695 29345 init_comm.go:44] [console] Hierarchical RCU implementation. I0406 19:05:55.245829 29345 init_comm.go:44] [console] Build-time adjustment of leaf fanout to 64. I0406 19:05:56.245978 29345 init_comm.go:44] [console] RCU restricting CPUs from NR_CPUS=8 to nr_cpu_ids=1. I0406 19:05:57.246132 29345 init_comm.go:44] [console] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=1 I0406 19:05:58.246272 29345 init_comm.go:44] [console] NR_IRQS:4352 nr_irqs:256 16 I0406 19:05:59.246420 29345 init_comm.go:44] [console] Offload RCU callbacks from all CPUs I0406 19:06:00.246571 29345 init_comm.go:44] [console] Offload RCU callbacks from CPUs: 0. I0406 19:06:01.246707 29345 init_comm.go:44] [console] Console: colour *CGA 80x25 I0406 19:06:02.246846 29345 init_comm.go:44] [console] console [ttyS0] enabled I0406 19:06:03.246983 29345 init_comm.go:44] [console] tsc: Detected 2294.688 MHz processor I0406 19:06:04.247115 29345 init_comm.go:44] [console] Calibrating delay loop (skipped) preset value.. 4589.37 BogoMIPS (lpj=2294688) I0406 19:06:05.247255 29345 init_comm.go:44] [console] pid_max: default: 32768 minimum: 301 I0406 19:06:06.247396 29345 init_comm.go:44] [console] ACPI: Core revision 20150930 I0406 19:06:07.247532 29345 init_comm.go:44] [console] ACPI: 1 ACPI AML tables successfully acquired and loaded I0406 19:06:08.247672 29345 init_comm.go:44] [console] Dentry cache hash table entries: 16384 (order: 5, 131072 bytes) I0406 19:06:09.247811 29345 init_comm.go:44] [console] Inode-cache hash table entries: 8192 (order: 4, 65536 bytes) I0406 19:06:10.247946 29345 init_comm.go:44] [console] Mount-cache hash table entries: 512 (order: 0, 4096 bytes) I0406 19:06:11.248084 29345 init_comm.go:44] [console] Mountpoint-cache hash table entries: 512 (order: 0, 4096 bytes) I0406 19:06:12.248222 29345 init_comm.go:44] [console] Last level iTLB entries: 4KB 64, 2MB 8, 4MB 8 I0406 19:06:13.248381 29345 init_comm.go:44] [console] Last level dTLB entries: 4KB 64, 2MB 0, 4MB 0, 1GB 4 I0406 19:06:14.248521 29345 init_comm.go:44] [console] Freeing SMP alternatives memory: 20K (ffffffff816ac000 - ffffffff816b1000) I0406 19:06:15.248659 29345 init_comm.go:44] [console] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 I0406 19:06:16.248792 29345 init_comm.go:44] [console] smpboot: CPU0: Intel(R) Core(TM) i5-5300U CPU @ 2.30GHz (family: 0x6, model: 0x3d, stepping: 0x4) I0406 19:06:17.248928 29345 init_comm.go:44] [console] Performance Events: 16-deep LBR, Broadwell events, Intel PMU driver. I0406 19:06:18.249061 29345 init_comm.go:44] [console] ... version: 2 I0406 19:06:19.249380 29345 init_comm.go:44] [console] ... bit width: 48 I0406 19:06:20.249515 29345 init_comm.go:44] [console] ... generic registers: 4 I0406 19:06:21.249648 29345 init_comm.go:44] [console] ... value mask: 0000ffffffffffff I0406 19:06:22.249781 29345 init_comm.go:44] [console] ... max period: 000000007fffffff I0406 19:06:23.249925 29345 init_comm.go:44] [console] ... fixed-purpose events: 3 I0406 19:06:24.250069 29345 init_comm.go:44] [console] ... event mask: 000000070000000f I0406 19:06:25.250228 29345 init_comm.go:44] [console] x86: Booted up 1 node, 1 CPUs I0406 19:06:26.250362 29345 init_comm.go:44] [console] smpboot: Total of 1 processors activated (4589.37 BogoMIPS) I0406 19:06:27.250493 29345 init_comm.go:44] [console] devtmpfs: initialized I0406 19:06:28.250624 29345 init_comm.go:44] [console] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns I0406 19:06:29.250782 29345 init_comm.go:44] [console] NET: Registered protocol family 16 I0406 19:06:30.250883 29345 init_comm.go:44] [console] cpuidle: using governor ladder I0406 19:06:31.251015 29345 init_comm.go:44] [console] cpuidle: using governor menu I0406 19:06:32.251149 29345 init_comm.go:44] [console] ACPI: bus type PCI registered I0406 19:06:33.251290 29345 init_comm.go:44] [console] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 I0406 19:06:34.251427 29345 init_comm.go:44] [console] PCI: Using configuration type 1 for base access I0406 19:06:35.251557 29345 init_comm.go:44] [console] ACPI: Added _OSI(Module Device) I0406 19:06:36.251686 29345 init_comm.go:44] [console] ACPI: Added _OSI(Processor Device) I0406 19:06:37.251821 29345 init_comm.go:44] [console] ACPI: Added _OSI(3.0 _SCP Extensions) I0406 19:06:38.251937 29345 init_comm.go:44] [console] ACPI: Added _OSI(Processor Aggregator Device) I0406 19:06:39.252082 29345 init_comm.go:44] [console] ACPI: Interpreter enabled I0406 19:06:40.252213 29345 init_comm.go:44] [console] ACPI: (supports S0 S5) I0406 19:06:41.252363 29345 init_comm.go:44] [console] ACPI: Using IOAPIC for interrupt routing I0406 19:06:42.252508 29345 init_comm.go:44] [console] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug I0406 19:06:43.252638 29345 init_comm.go:44] [console] ACPI: PCI Root Bridge [PCI0](domain 0000 [bus 00-ff]) I0406 19:06:44.252769 29345 init_comm.go:44] [console] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI] I0406 19:06:45.252924 29345 init_comm.go:44] [console] acpi PNP0A03:00: _OSC failed (AE_NOT_FOUND); disabling ASPM I0406 19:06:46.253049 29345 init_comm.go:44] [console] acpiphp: Slot [2] registered I0406 19:06:47.253187 29345 init_comm.go:44] [console] acpiphp: Slot [3] registered I0406 19:06:48.253319 29345 init_comm.go:44] [console] acpiphp: Slot [4] registered I0406 19:06:49.253451 29345 init_comm.go:44] [console] acpiphp: Slot [5] registered I0406 19:06:50.253582 29345 init_comm.go:44] [console] acpiphp: Slot [6] registered I0406 19:06:51.253727 29345 init_comm.go:44] [console] acpiphp: Slot [7] registered I0406 19:06:52.253862 29345 init_comm.go:44] [console] acpiphp: Slot [8] registered I0406 19:06:53.253988 29345 init_comm.go:44] [console] acpiphp: Slot [9] registered I0406 19:06:54.254121 29345 init_comm.go:44] [console] acpiphp: Slot [10] registered I0406 19:06:55.254256 29345 init_comm.go:44] [console] acpiphp: Slot [11] registered I0406 19:06:56.254388 29345 init_comm.go:44] [console] acpiphp: Slot [12] registered I0406 19:06:57.254520 29345 init_comm.go:44] [console] acpiphp: Slot [13] registered I0406 19:06:58.254655 29345 init_comm.go:44] [console] acpiphp: Slot [14] registered I0406 19:06:59.254788 29345 init_comm.go:44] [console] acpiphp: Slot [15] registered I0406 19:07:00.254924 29345 init_comm.go:44] [console] acpiphp: Slot [16] registered I0406 19:07:01.255084 29345 init_comm.go:44] [console] acpiphp: Slot [17] registered I0406 19:07:02.255218 29345 init_comm.go:44] [console] acpiphp: Slot [18] registered I0406 19:07:03.255347 29345 init_comm.go:44] [console] acpiphp: Slot [19] registered I0406 19:07:04.255499 29345 init_comm.go:44] [console] acpiphp: Slot [20] registered I0406 19:07:05.255634 29345 init_comm.go:44] [console] acpiphp: Slot [21] registered I0406 19:07:06.255766 29345 init_comm.go:44] [console] acpiphp: Slot [22] registered I0406 19:07:07.255912 29345 init_comm.go:44] [console] acpiphp: Slot [23] registered I0406 19:07:08.256040 29345 init_comm.go:44] [console] acpiphp: Slot [24] registered I0406 19:07:09.256167 29345 init_comm.go:44] [console] acpiphp: Slot [25] registered I0406 19:07:10.256289 29345 init_comm.go:44] [console] acpiphp: Slot [26] registered I0406 19:07:11.256417 29345 init_comm.go:44] [console] acpiphp: Slot [27] registered I0406 19:07:12.256542 29345 init_comm.go:44] [console] acpiphp: Slot [28] registered I0406 19:07:13.256650 29345 init_comm.go:44] [console] acpiphp: Slot [29] registered I0406 19:07:14.256780 29345 init_comm.go:44] [console] acpiphp: Slot [30] registered I0406 19:07:15.256856 29345 init_comm.go:44] [console] acpiphp: Slot [31] registered I0406 19:07:16.256987 29345 init_comm.go:44] [console] PCI host bridge to bus 0000:00 I0406 19:07:17.257132 29345 init_comm.go:44] [console] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] I0406 19:07:18.257272 29345 init_comm.go:44] [console] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] I0406 19:07:19.257404 29345 init_comm.go:44] [console] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] I0406 19:07:20.257536 29345 init_comm.go:44] [console] pci_bus 0000:00: root bus resource [mem 0x08000000-0xfebfffff window] I0406 19:07:21.257667 29345 init_comm.go:44] [console] pci_bus 0000:00: root bus resource [bus 00-ff] I0406 19:07:22.257801 29345 init_comm.go:44] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] I0406 19:07:23.257946 29345 init_comm.go:44] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] I0406 19:07:24.258091 29345 init_comm.go:44] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] I0406 19:07:25.258225 29345 init_comm.go:44] [console] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] I0406 19:07:26.258374 29345 init_comm.go:44] [console] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI I0406 19:07:27.258519 29345 init_comm.go:44] [console] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB I0406 19:07:28.258665 29345 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKA](IRQs 5 10 11) I0406 19:07:29.258812 29345 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKB](IRQs 5 10 11) I0406 19:07:30.258948 29345 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKC](IRQs 5 10 11) I0406 19:07:31.259077 29345 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKD](IRQs 5 10 11) I0406 19:07:32.259415 29345 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKS](IRQs *9) I0406 19:07:33.259639 29345 init_comm.go:44] [console] ACPI: Enabled 16 GPEs in block 00 to 0F I0406 19:07:34.259776 29345 init_comm.go:44] [console] vgaarb: loaded I0406 19:07:35.259917 29345 init_comm.go:44] [console] SCSI subsystem initialized I0406 19:07:36.260055 29345 init_comm.go:44] [console] PCI: Using ACPI for IRQ routing I0406 19:07:37.260206 29345 init_comm.go:44] [console] clocksource: Switched to clocksource kvm-clock I0406 19:07:38.260340 29345 init_comm.go:44] [console] pnp: PnP ACPI init I0406 19:07:39.260470 29345 init_comm.go:44] [console] pnp: PnP ACPI: found 5 devices I0406 19:07:40.260605 29345 init_comm.go:44] [console] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns I0406 19:07:41.260735 29345 init_comm.go:44] [console] NET: Registered protocol family 2 I0406 19:07:42.260865 29345 init_comm.go:44] [console] TCP established hash table entries: 1024 (order: 1, 8192 bytes) I0406 19:07:43.260994 29345 init_comm.go:44] [console] TCP bind hash table entries: 1024 (order: 2, 16384 bytes) I0406 19:07:44.261125 29345 init_comm.go:44] [console] TCP: Hash tables configured (established 1024 bind 1024) I0406 19:07:45.261252 29345 init_comm.go:44] [console] UDP hash table entries: 256 (order: 1, 8192 bytes) I0406 19:07:46.261381 29345 init_comm.go:44] [console] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes) I0406 19:07:47.261486 29345 init_comm.go:44] [console] NET: Registered protocol family 1 I0406 19:07:48.261617 29345 init_comm.go:44] [console] pci 0000:00:00.0: Limiting direct PCI/PCI transfers I0406 19:07:49.261772 29345 init_comm.go:44] [console] pci 0000:00:01.0: PIIX3: Enabling Passive Release I0406 19:07:50.261899 29345 init_comm.go:44] [console] pci 0000:00:01.0: Activating ISA DMA hang workarounds I0406 19:07:51.262029 29345 init_comm.go:44] [console] Trying to unpack rootfs image as initramfs... I0406 19:07:52.262160 29345 init_comm.go:44] [console] Freeing initrd memory: 1632K (ffff880007e58000 - ffff880007ff0000) I0406 19:07:53.262298 29345 init_comm.go:44] [console] futex hash table entries: 256 (order: 2, 16384 bytes) I0406 19:07:54.262431 29345 init_comm.go:44] [console] SGI XFS with ACLs, security attributes, no debug enabled I0406 19:07:55.262570 29345 init_comm.go:44] [console] 9p: Installing v9fs 9p2000 file system support I0406 19:07:56.262707 29345 init_comm.go:44] [console] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 254) I0406 19:07:57.262841 29345 init_comm.go:44] [console] io scheduler noop registered I0406 19:07:58.262975 29345 init_comm.go:44] [console] io scheduler cfq registered (default) I0406 19:07:59.263111 29345 init_comm.go:44] [console] pci_hotplug: PCI Hot Plug PCI Core version: 0.5 I0406 19:08:00.263243 29345 init_comm.go:44] [console] pciehp: PCI Express Hot Plug Controller Driver version: 0.4 I0406 19:08:01.263366 29345 init_comm.go:44] [console] Warning: Processor Platform Limit event detected, but not handled. I0406 19:08:02.263502 29345 init_comm.go:44] [console] Consider compiling CPUfreq support into your kernel. I0406 19:08:03.263629 29345 init_comm.go:44] [console] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x21139aef754, max_idle_ns: 440795211890 ns I0406 19:08:04.263758 29345 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKB] enabled at IRQ 10 I0406 19:08:05.263922 29345 init_comm.go:44] [console] virtio-pci 0000:00:02.0: virtio_pci: leaving for legacy driver I0406 19:08:06.264072 29345 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 11 I0406 19:08:07.264204 29345 init_comm.go:44] [console] virtio-pci 0000:00:03.0: virtio_pci: leaving for legacy driver I0406 19:08:08.264343 29345 init_comm.go:44] [console] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 11 I0406 19:08:09.264485 29345 init_comm.go:44] [console] virtio-pci 0000:00:04.0: virtio_pci: leaving for legacy driver I0406 19:08:10.264616 29345 init_comm.go:44] [console] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled I0406 19:08:11.264745 29345 init_comm.go:44] [console] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A I0406 19:08:12.264877 29345 init_comm.go:44] [console] brd: module loaded I0406 19:08:13.265007 29345 init_comm.go:44] [console] loop: module loaded I0406 19:08:14.265140 29345 init_comm.go:44] [console] scsi host0: Virtio SCSI HBA I0406 19:08:15.265269 29345 init_comm.go:44] [console] e1000: Intel(R) PRO/1000 Network Driver - version 7.3.21-k8-NAPI I0406 19:08:16.265398 29345 init_comm.go:44] [console] e1000: Copyright (c) 1999-2006 Intel Corporation. I0406 19:08:17.265529 29345 init_comm.go:44] [console] NET: Registered protocol family 10 I0406 19:08:18.265657 29345 init_comm.go:44] [console] NET: Registered protocol family 17 I0406 19:08:19.265787 29345 init_comm.go:44] [console] 9pnet: Installing 9P2000 support I0406 19:08:20.265916 29345 init_comm.go:44] [console] registered taskstats version 1 I0406 19:08:21.266068 29345 init_comm.go:44] [console] Freeing unused kernel memory: 860K (ffffffff815d5000 - ffffffff816ac000) I0406 19:08:22.266211 29345 init_comm.go:44] [console] create directory /sys I0406 19:08:23.266340 29345 init_comm.go:44] [console] create directory /proc I0406 19:08:24.266474 29345 init_comm.go:44] [console] uptime 51.09 0.02 I0406 19:08:25.266619 29345 init_comm.go:44] [console] I0406 19:08:26.266834 29345 init_comm.go:44] [console] create directory /dev/pts I0406 19:08:27.266972 29345 init_comm.go:44] [console] open hyper channel /dev/vport0p1 I0406 19:08:28.267105 29345 init_comm.go:44] [console] send ready message I0406 19:08:29.267391 29345 init_comm.go:44] [console] hyper send type 8, len 0 I0406 19:08:30.267475 29345 init_comm.go:44] [console] channel sh.hyper.channel.1, directory sh.hyper.channel.0 I0406 19:08:31.267612 29345 init_comm.go:44] [console] I0406 19:08:32.267896 29345 init_comm.go:44] [console] open hyper channel /dev/vport0p2 I0406 19:08:33.268309 29345 init_comm.go:44] [console] hyper_init_event hyper channel event 0x614580, ops 0x614380, fd 3 I0406 19:08:34.268487 29345 init_comm.go:44] [console] hyper_add_event add event fd 3, 0x614380 I0406 19:08:35.268619 29345 init_comm.go:44] [console] hyper_init_event hyper ttyfd event 0x614548, ops 0x614340, fd 4 I0406 19:08:36.268761 29345 init_comm.go:44] [console] hyper_add_event add event fd 4, 0x614340 I0406 19:06:07.256048 29345 init_comm.go:83] read 8/8 [length = 0] I0406 19:08:38.286252 29345 init_comm.go:87] data length is 8 I0406 19:08:39.286393 29345 init_comm.go:120] Get init ready message I0406 19:08:40.286551 29345 init_comm.go:164] got cmd:1 I0406 19:08:41.286730 29345 init_comm.go:245] send command 1 to init, payload: '{"hostname":"shell","containers":[],"shareDir":"share_dir"}'. I0406 19:08:42.286881 29345 init_comm.go:258] write 67 to init, payload: '\00\00\00\00\00\00C{"hostname":"shell","containers":[],"shareDir":"share_dir"}'. I0406 19:08:43.287019 29345 init_comm.go:263] message sent, set pong timer W0406 19:05:25.211686 29345 qmp_handler.go:282] Initializer Timeout. E0406 19:08:45.292385 29345 qmp_handler.go:368] QMP initialize timeout I0406 19:05:01.242258 29345 qmp_handler.go:103] got a message {"return": {}} I0406 19:08:47.315364 29345 qmp_handler.go:210] got for response I0406 19:08:48.315499 29345 qmp_handler.go:213] QMP connection initialized I0406 19:05:29.217795 29345 hypervisor.go:29] main event loop got message 3(EVENT_VM_TIMEOUT) E0406 19:08:50.318243 29345 vm_states.go:346] Shutting down because of an exception: Start POD timeout I0406 19:08:51.318381 29345 context.go:212] VM vm-EvCFIREQIF: state change from STARTING to 'TERMINATING' E0406 19:08:52.318518 29345 vm_states.go:629] Start POD timeout I0406 19:08:53.319523 29345 hypervisor.go:29] main event loop got message 5(EVENT_INIT_CONNECTED) W0406 19:08:54.319661 29345 vm_states.go:482] got unexpected event during terminating I0406 19:08:55.319797 29345 hypervisor.go:29] main event loop got message 41(ERROR_INIT_FAIL) W0406 19:08:56.319934 29345 vm_states.go:482] got unexpected event during terminating I0406 19:08:40.286582 29345 init_comm.go:72] trying to read 8 bytes I0406 19:08:58.338739 29345 init_comm.go:83] read 8/8 [length = 0] I0406 19:08:59.338912 29345 init_comm.go:87] data length is 12 I0406 19:09:00.339045 29345 init_comm.go:72] trying to read 4 bytes I0406 19:09:01.339187 29345 init_comm.go:83] read 12/12 [length = 12] I0406 19:09:02.339321 29345 init_comm.go:72] trying to read 8 bytes I0406 19:09:03.339466 29345 init_comm.go:83] read 8/8 [length = 0] I0406 19:09:04.339601 29345 init_comm.go:87] data length is 12 I0406 19:09:05.339733 29345 init_comm.go:72] trying to read 4 bytes I0406 19:09:06.339886 29345 init_comm.go:83] read 12/12 [length = 12] I0406 19:09:07.340023 29345 init_comm.go:72] trying to read 8 bytes I0406 19:09:08.340164 29345 init_comm.go:83] read 8/8 [length = 0] I0406 19:09:09.340294 29345 init_comm.go:87] data length is 8 I0406 19:09:10.340442 29345 init_comm.go:72] trying to read 8 bytes

laijs commented 8 years ago

it seems there is problem in glog, it needs 1s for every message. And it delays everything and cause timeout when runv starts the pod.

Does it start the container successfully without the "-v=3"?

abdasgupta commented 8 years ago

Yeah, it worked without "-v=3" . Thanks.