search

hyperhq / runv

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

Problem running runv on Ubuntu 14.04 #290

Closed Ddnirvana closed 7 years ago

Ddnirvana commented 7 years ago

Hi, I am trying to run runv on Ubuntu 14.04,but it just failed. I run the flowing commands:


mkdir /mycontainer
cd /mycontainer
mkdir rootfs
docker export $(docker create busybox) | tar -C rootfs -xvf -
runv spec
#kernel and hyper-initrd.img are moved from hyperstart/build
runv --debug --kernel kernel --initrd hyper-initrd.img --driver=qemu start -b /mycontainer/ test

And I get the following warnings(the container ended without execution)


error rpc error: code = 11 desc = EOF

Some logs from runv-namespaced.INFO:


I0717 11:01:44.010278    7328 init_comm.go:68] [console] enter hyper_loop
I0717 11:01:44.010947    7328 init_comm.go:68] [console] hyper_init_event hyper channel event 0x615580, ops 0x6153a0, fd 3
I0717 11:01:44.011421    7328 init_comm.go:68] [console] hyper_add_event add event fd 3, 0x6153a0
I0717 11:01:44.012050    7328 init_comm.go:68] [console] hyper_init_event hyper ttyfd event 0x615548, ops 0x615360, fd 4
I0717 11:01:44.012555    7328 init_comm.go:68] [console] hyper_add_event add event fd 4, 0x615360
I0717 11:01:44.012864    7328 init_comm.go:68] [console] hyper_loop epoll_wait 1
I0717 11:01:44.013502    7328 init_comm.go:68] [console] hyper_handle_event get event 1, de 0x615580, fd 3. ops 0x6153a0
I0717 11:01:44.014100    7328 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, de 0x615580, fd 3, 0x6153a0
I0717 11:01:44.014362    7328 init_comm.go:68] [console] hyper_event_read
I0717 11:01:44.014682    7328 init_comm.go:68] [console] already read 8 bytes data
I0717 11:01:44.015007    7328 init_comm.go:68] [console] hyper send type 14, len 4
I0717 11:01:44.015092    7328 init_comm.go:106] read 8/8 [length = 0]
I0717 11:01:44.015102    7328 init_comm.go:110] data length is 12
I0717 11:01:44.015108    7328 init_comm.go:96] trying to read 4 bytes
I0717 11:01:44.015119    7328 init_comm.go:106] read 12/12 [length = 12]
I0717 11:01:44.015129    7328 init_comm.go:96] trying to read 8 bytes
I0717 11:01:44.015159    7328 init_comm.go:190] got cmd:14
I0717 11:01:44.015165    7328 init_comm.go:253] get command NEXT
I0717 11:01:44.015169    7328 init_comm.go:256] send 67, receive 8
I0717 11:01:44.015268    7328 init_comm.go:68] [console] get length 67
I0717 11:01:44.015666    7328 init_comm.go:68] [console] read 59 bytes data, total data 67
I0717 11:01:44.016037    7328 init_comm.go:68] [console] hyper send type 14, len 4
I0717 11:01:44.016117    7328 init_comm.go:106] read 8/8 [length = 0]
I0717 11:01:44.016124    7328 init_comm.go:110] data length is 12
I0717 11:01:44.016127    7328 init_comm.go:96] trying to read 4 bytes
I0717 11:01:44.016133    7328 init_comm.go:106] read 12/12 [length = 12]
I0717 11:01:44.016141    7328 init_comm.go:96] trying to read 8 bytes
I0717 11:01:44.016155    7328 init_comm.go:190] got cmd:14
I0717 11:01:44.016163    7328 init_comm.go:253] get command NEXT
I0717 11:01:44.016168    7328 init_comm.go:256] send 67, receive 67
I0717 11:01:44.017801    7328 init_comm.go:68] [console] 0 0 0 1 0 0 0 43 7b 22 68 6f 73 74 6e 61 6d 65 22 3a 22 73 68 65 6c 6c 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 
I0717 11:01:44.018226    7328 init_comm.go:68] [console]  hyper_channel_handle, type 1, len 67
I0717 11:01:44.019103    7328 init_comm.go:68] [console] call hyper_start_pod, json {"hostname":"shell","containers":[],"shareDir":"share_dir"}., len 59
I0717 11:01:44.020202    7328 init_comm.go:68] [console] call hyper_start_pod, json {"hostname":"shell","containers":[],"shareDir":"share_dir"}., len 59
I0717 11:01:44.020549    7328 init_comm.go:68] [console] jsmn parse successed, n is 7
I0717 11:01:44.020892    7328 init_comm.go:68] [console] token 0, type is 1, size is 3
I0717 11:01:44.021249    7328 init_comm.go:68] [console] token 1, type is 3, size is 1
I0717 11:01:44.021520    7328 init_comm.go:68] [console] hostname is shell
I0717 11:01:44.021863    7328 init_comm.go:68] [console] token 3, type is 3, size is 1
I0717 11:01:44.022129    7328 init_comm.go:68] [console] container count 0
I0717 11:01:44.023074    7328 init_comm.go:68] [console] random: busybox urandom read with 8 bits of entropy available
I0717 11:01:44.023446    7328 init_comm.go:68] [console] token 5, type is 3, size is 1
I0717 11:01:44.023739    7328 init_comm.go:68] [console] share tag is share_dir
I0717 11:01:44.024040    7328 init_comm.go:68] [console] create directory /tmp
I0717 11:01:44.024396    7328 init_comm.go:68] [console] create directory /tmp/hyper
I0717 11:01:44.024892    7328 init_comm.go:68] [console] create directory /tmp/hyper/proc
I0717 11:01:44.025383    7328 init_comm.go:68] [console] finish rescan
I0717 11:01:44.025902    7328 init_comm.go:68] [console] create directory /tmp/hyper/shared
I0717 11:01:44.026706    7328 init_comm.go:68] [console] pod init pid 325
I0717 11:01:44.027073    7328 init_comm.go:68] [console] hyper send type 8, len 0
I0717 11:01:44.027397    7328 init_comm.go:68] [console] in hyper_start_containers
I0717 11:01:44.027712    7328 init_comm.go:68] [console] out hyper_start_containers
I0717 11:01:44.027953    7328 init_comm.go:68] [console] uptime 0.34 0.02
I0717 11:01:44.028062    7328 init_comm.go:68] [console] 
I0717 11:01:44.028492    7328 init_comm.go:68] [console] hyper_channel_handle: STARTPOD finished
I0717 11:01:44.028838    7328 init_comm.go:68] [console] hyper send type 9, len 0
I0717 11:01:44.028919    7328 init_comm.go:106] read 8/8 [length = 0]
I0717 11:01:44.028926    7328 init_comm.go:110] data length is 8
I0717 11:01:44.028935    7328 init_comm.go:96] trying to read 8 bytes
I0717 11:01:44.028957    7328 init_comm.go:190] got cmd:9
I0717 11:01:44.028966    7328 init_comm.go:209] ack got, clear pong timer
I0717 11:01:44.028981    7328 hypervisor.go:29] vm vm-OewSSuQoQx: main event loop got message 31(COMMAND_ACK)
I0717 11:01:44.028988    7328 vm_states.go:499] [starting] got init ack to &{1 859531633408  [] 859533394400}
I0717 11:01:44.029241    7328 init_comm.go:68] [console] sigchld in hyper_init_sigchld
I0717 11:01:44.029498    7328 context.go:211] VM vm-OewSSuQoQx: state change from STARTING to 'RUNNING'
I0717 11:01:44.029507    7328 vm_states.go:515] pod start success 
I0717 11:01:44.029520    7328 vm.go:260] Get the response from VM, VM id is vm-OewSSuQoQx!
I0717 11:01:44.029535    7328 hyperpod.go:296] result: code 0 Start POD success
I0717 11:01:44.029541    7328 hyperpod.go:162] get exec path /usr/local/bin/runv
I0717 11:01:44.030054    7328 init_comm.go:68] [console] pid 324 exit normally, status 0
I0717 11:01:44.030090    7328 init_comm.go:68] [console] can not find exec whose pid is 324
I0717 11:01:44.030242    7328 init_comm.go:68] [console] hyper_loop epoll_wait -1
I0717 11:01:44.030536    7328 init_comm.go:68] [console] epoll: n=-1 errno==EINTR
I0717 11:01:44.030862    7328 init_comm.go:68] [console] pod init enter infinite loop
I0717 11:01:44.048861    7328 hypervisor.go:29] vm vm-OewSSuQoQx: main event loop got message 24(COMMAND_SHUTDOWN)
I0717 11:01:44.048873    7328 vm_states.go:327] got shutdown command, shutting down
I0717 11:01:44.048887    7328 context.go:211] VM vm-OewSSuQoQx: state change from RUNNING to 'TERMINATING'
I0717 11:01:44.048900    7328 init_comm.go:190] got cmd:4
I0717 11:01:44.048911    7328 init_comm.go:281] send command 4 to init, payload: 'null'.
I0717 11:01:44.048928    7328 init_comm.go:294] write 12 to init, payload: '\00\00\00\00\00\00null'.
I0717 11:01:44.048936    7328 init_comm.go:299] message sent, set pong timer
I0717 11:01:44.049362    7328 init_comm.go:68] [console] hyper_loop epoll_wait 1
I0717 11:01:44.049907    7328 init_comm.go:68] [console] hyper_handle_event get event 1, de 0x615580, fd 3. ops 0x6153a0
I0717 11:01:44.050442    7328 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, de 0x615580, fd 3, 0x6153a0
I0717 11:01:44.050648    7328 init_comm.go:68] [console] hyper_event_read
I0717 11:01:44.050940    7328 init_comm.go:68] [console] already read 8 bytes data
I0717 11:01:44.051227    7328 init_comm.go:68] [console] hyper send type 14, len 4
I0717 11:01:44.051319    7328 init_comm.go:106] read 8/8 [length = 0]
I0717 11:01:44.051339    7328 init_comm.go:110] data length is 12
I0717 11:01:44.051345    7328 init_comm.go:96] trying to read 4 bytes
I0717 11:01:44.051355    7328 init_comm.go:106] read 12/12 [length = 12]
I0717 11:01:44.051378    7328 init_comm.go:96] trying to read 8 bytes
I0717 11:01:44.051389    7328 init_comm.go:190] got cmd:14
I0717 11:01:44.051393    7328 init_comm.go:253] get command NEXT
I0717 11:01:44.051397    7328 init_comm.go:256] send 12, receive 8
I0717 11:01:44.051557    7328 init_comm.go:68] [console] get length 12
I0717 11:01:44.051886    7328 init_comm.go:68] [console] read 4 bytes data, total data 12
I0717 11:01:44.052176    7328 init_comm.go:68] [console] hyper send type 14, len 4
I0717 11:01:44.052248    7328 init_comm.go:106] read 8/8 [length = 0]
I0717 11:01:44.052256    7328 init_comm.go:110] data length is 12
I0717 11:01:44.052259    7328 init_comm.go:96] trying to read 4 bytes
I0717 11:01:44.052265    7328 init_comm.go:106] read 12/12 [length = 12]
I0717 11:01:44.052274    7328 init_comm.go:96] trying to read 8 bytes
I0717 11:01:44.052286    7328 init_comm.go:190] got cmd:14
I0717 11:01:44.052291    7328 init_comm.go:253] get command NEXT
I0717 11:01:44.052294    7328 init_comm.go:256] send 12, receive 12
I0717 11:01:44.052575    7328 init_comm.go:68] [console] 0 0 0 4 0 0 0 c 6e 75 6c 6c 
I0717 11:01:44.052945    7328 init_comm.go:68] [console]  hyper_channel_handle, type 4, len 12
I0717 11:01:44.053221    7328 init_comm.go:68] [console] get DESTROYPOD message
I0717 11:01:44.053675    7328 init_comm.go:68] [console] Sending SIGTERM
I0717 11:01:44.053893    7328 init_comm.go:68] [console] kill process 325
I0717 11:01:44.054118    7328 init_comm.go:68] [console] kill process 323
I0717 11:01:44.054346    7328 init_comm.go:68] [console] kill process 322
I0717 11:01:44.054546    7328 init_comm.go:68] [console] kill process 65
I0717 11:01:44.054749    7328 init_comm.go:68] [console] kill process 64
I0717 11:01:44.054951    7328 init_comm.go:68] [console] kill process 63
I0717 11:01:44.055169    7328 init_comm.go:68] [console] kill process 62
I0717 11:01:44.055371    7328 init_comm.go:68] [console] kill process 61
I0717 11:01:44.055581    7328 init_comm.go:68] [console] kill process 60
I0717 11:01:44.055850    7328 init_comm.go:68] [console] kill process 59
I0717 11:01:44.056061    7328 init_comm.go:68] [console] kill process 58
I0717 11:01:44.056277    7328 init_comm.go:68] [console] kill process 57
I0717 11:01:44.056478    7328 init_comm.go:68] [console] kill process 56
I0717 11:01:44.056693    7328 init_comm.go:68] [console] kill process 55
I0717 11:01:44.056894    7328 init_comm.go:68] [console] kill process 54
I0717 11:01:44.057104    7328 init_comm.go:68] [console] kill process 53
I0717 11:01:44.057316    7328 init_comm.go:68] [console] kill process 52
I0717 11:01:44.057522    7328 init_comm.go:68] [console] kill process 51
I0717 11:01:44.057722    7328 init_comm.go:68] [console] kill process 50
I0717 11:01:44.057929    7328 init_comm.go:68] [console] kill process 49
I0717 11:01:44.058130    7328 init_comm.go:68] [console] kill process 48
I0717 11:01:44.058339    7328 init_comm.go:68] [console] kill process 47
I0717 11:01:44.058542    7328 init_comm.go:68] [console] kill process 37
I0717 11:01:44.058747    7328 init_comm.go:68] [console] kill process 23
I0717 11:01:44.058950    7328 init_comm.go:68] [console] kill process 22
I0717 11:01:44.059169    7328 init_comm.go:68] [console] kill process 21
I0717 11:01:44.059376    7328 init_comm.go:68] [console] kill process 20
I0717 11:01:44.059584    7328 init_comm.go:68] [console] kill process 19
I0717 11:01:44.059789    7328 init_comm.go:68] [console] kill process 18
I0717 11:01:44.059995    7328 init_comm.go:68] [console] kill process 17
I0717 11:01:44.060207    7328 init_comm.go:68] [console] kill process 16
I0717 11:01:44.060410    7328 init_comm.go:68] [console] kill process 15
I0717 11:01:44.060626    7328 init_comm.go:68] [console] kill process 14
I0717 11:01:44.060811    7328 init_comm.go:68] [console] kill process 13
I0717 11:01:44.060992    7328 init_comm.go:68] [console] kill process 12
I0717 11:01:44.061185    7328 init_comm.go:68] [console] kill process 11
I0717 11:01:44.061367    7328 init_comm.go:68] [console] kill process 10
I0717 11:01:44.061549    7328 init_comm.go:68] [console] kill process 9
I0717 11:01:44.061730    7328 init_comm.go:68] [console] kill process 8
I0717 11:01:44.061905    7328 init_comm.go:68] [console] kill process 7
I0717 11:01:44.062083    7328 init_comm.go:68] [console] kill process 6
I0717 11:01:44.062271    7328 init_comm.go:68] [console] kill process 5
I0717 11:01:44.062453    7328 init_comm.go:68] [console] kill process 4
I0717 11:01:44.062634    7328 init_comm.go:68] [console] kill process 3
I0717 11:01:44.062814    7328 init_comm.go:68] [console] kill process 2
I0717 11:01:44.801100    7328 init_comm.go:68] [console] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x2f75b1eac7a, max_idle_ns: 440795210882 ns
I0717 11:01:54.049105    7328 hypervisor.go:29] vm vm-OewSSuQoQx: main event loop got message 3(EVENT_VM_TIMEOUT)
W0717 11:01:54.049131    7328 vm_states.go:650] VM did not exit in time, try to stop it
E0717 11:01:54.049366    7328 vm_states.go:293] Shutting down because of an exception: vm terminating timeout
I0717 11:01:54.049508    7328 qmp_handler.go:296] got new session
I0717 11:01:54.049537    7328 qmp_handler.go:225] Begin process command session
I0717 11:01:54.049560    7328 qmp_handler.go:243] sending command (1) {"execute":"quit"}
I0717 11:01:54.049594    7328 vm.go:298] Got response: 7: vm terminating timeout
I0717 11:01:54.050074    7328 qmp_handler.go:103] got a message {"return": {}}
I0717 11:01:54.050137    7328 qmp_handler.go:103] got a message {"timestamp": {"seconds": 1468724514, "microseconds": 50001}, "event": "SHUTDOWN"}
I0717 11:01:54.050159    7328 qmp_handler.go:107] got event: SHUTDOWN
I0717 11:01:54.050168    7328 qmp_handler.go:152] Shutdown, quit QMP receiver
I0717 11:01:54.050186    7328 qmp_handler.go:323] got QMP event SHUTDOWN
I0717 11:01:54.050195    7328 qmp_handler.go:325] got QMP shutdown event, quit...
I0717 11:01:54.050208    7328 hypervisor.go:29] vm vm-OewSSuQoQx: main event loop got message 1(EVENT_VM_EXIT)
I0717 11:01:54.050216    7328 vm_states.go:622] Got VM shutdown event while terminating, go to cleaning up
I0717 11:01:54.050222    7328 vm_states.go:36] VM has exit...
I0717 11:01:54.050233    7328 devicemap.go:93] All resource being released, someone is waiting for us...
I0717 11:01:54.050237    7328 context.go:198] no more device to release/remove/umount, quit
I0717 11:01:54.050270    7328 qemu_process.go:19] quit watch dog.
I0717 11:01:54.050289    7328 vm.go:298] Got response: 2: VM shut down
I0717 11:01:54.050300    7328 hyperpod.go:319] StopPod fail: QEMU response data is nil
I0717 11:01:54.050306    7328 hyperpod.go:309] start ns listener fail: EOF
I0717 11:01:54.050314    7328 supervisor.go:168] createHyperPod() returns
E0717 11:01:54.055261    7328 init_comm.go:99] read init data failed
E0717 11:01:54.055272    7328 tty.go:90] read tty data failed
I0717 11:01:54.055290    7328 tty.go:151] tty socket closed, quit the reading goroutine EOF
I0717 11:01:54.055305    7328 tty.go:428] Input byte chan closed, close the output string chan
I0717 11:01:54.055324    7328 init_comm.go:70] console output end
I0717 11:01:54.055329    7328 tty.go:118] tty chan closed, quit sent goroutine
I0717 11:02:14.029117    7328 init_comm.go:216] Send ping message to init
I0717 11:02:14.029156    7328 init_comm.go:190] got cmd:12
I0717 11:02:14.029220    7328 init_comm.go:281] send command 12 to init, payload: 'null'.
I0717 11:02:14.029262    7328 init_comm.go:294] write 0 to init, payload: '\00\00\00\00\00\00null'.

From the log, I find something weird is that


I0717 11:01:44.029507    7328 vm_states.go:515] pod start success 
I0717 11:01:44.029520    7328 vm.go:260] Get the response from VM, VM id is vm-OewSSuQoQx!
I0717 11:01:44.029535    7328 hyperpod.go:296] result: code 0 Start POD success
I0717 11:01:44.029541    7328 hyperpod.go:162] get exec path /usr/local/bin/runv
I0717 11:01:44.030054    7328 init_comm.go:68] [console] pid 324 exit normally, status 0
I0717 11:01:44.030090    7328 init_comm.go:68] [console] can not find exec whose pid is 324
I0717 11:01:44.030242    7328 init_comm.go:68] [console] hyper_loop epoll_wait -1
I0717 11:01:44.030536    7328 init_comm.go:68] [console] epoll: n=-1 errno==EINTR
I0717 11:01:44.030862    7328 init_comm.go:68] [console] pod init enter infinite loop
I0717 11:01:44.048861    7328 hypervisor.go:29] vm vm-OewSSuQoQx: main event loop got message 24(COMMAND_SHUTDOWN)

after getting the log info "pod start success",we also get the log info "main event loop got message 24(COMMAND_SHUTDOWN)" I think maybe the problem is because of this SHUTDOWN COMMAND. I have tried many efforts on running runv :( Any ideas to fix this ? Looking forward to any help!~

gnawux commented 7 years ago

Hi @Ddnirvana , what's the version of runV and hyperstart are you working on?

Ddnirvana commented 7 years ago

Hi @gnawux ，thanks for your replying! They are both 0.6.0 version.

gao-feng commented 7 years ago

Hello, Do you modify hyperstart or kernel yourself? Some outputs in logs are not consist with codes, such as

I0717 11:01:44.029241    7328 init_comm.go:68] [console] sigchld in hyper_init_sigchld

I0717 11:01:44.030862    7328 init_comm.go:68] [console] pod init enter infinite loop
Ddnirvana commented 7 years ago

@gao-feng sorry forget mention that, as I said I tried many efforts to fix this problem by myself. So to better understanding the codes I added some log print code in the hyperstart and runv. But I am very sure the results and other log Infos are totally the same as previous unmodified one.

Ddnirvana commented 7 years ago

@gao-feng I re-run the command runv --debug --kernel kernel --initrd hyper-initrd.img --driver=qemu start -b /mycontainer/ test using unmodified version 0.6.0 hyperstart and runv and the log infos are:


I0718 10:02:38.195179   20539 vm.go:260] Get the response from VM, VM id is vm-jSdTQgbOCv!
I0718 10:02:38.195605   20539 init_comm.go:68] [console] channel sh.hyper.channel.1, directory sh.hyper.channel.0
I0718 10:02:38.195687   20539 init_comm.go:68] [console] 
I0718 10:02:38.196077   20539 init_comm.go:68] [console] open hyper channel /dev/vport0p2
I0718 10:02:38.196217   20539 qmp_handler.go:103] got a message {"timestamp": {"seconds": 1468807358, "microseconds": 196142}, "event": "VSERPORT_CHANGE", "data": {"open": true, "id": "channel1"}}
I0718 10:02:38.196235   20539 qmp_handler.go:107] got event: VSERPORT_CHANGE
I0718 10:02:38.196252   20539 qmp_handler.go:323] got QMP event VSERPORT_CHANGE
I0718 10:02:38.196824   20539 init_comm.go:68] [console] hyper_init_event hyper channel event 0x615580, ops 0x6153a0, fd 3
I0718 10:02:38.197231   20539 init_comm.go:68] [console] hyper_add_event add event fd 3, 0x6153a0
I0718 10:02:38.197801   20539 init_comm.go:68] [console] hyper_init_event hyper ttyfd event 0x615548, ops 0x615360, fd 4
I0718 10:02:38.198208   20539 init_comm.go:68] [console] hyper_add_event add event fd 4, 0x615360
I0718 10:02:38.198497   20539 init_comm.go:68] [console] hyper_loop epoll_wait 1
I0718 10:02:38.199065   20539 init_comm.go:68] [console] hyper_handle_event get event 1, de 0x615580, fd 3. ops 0x6153a0
I0718 10:02:38.199626   20539 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, de 0x615580, fd 3, 0x6153a0
I0718 10:02:38.199841   20539 init_comm.go:68] [console] hyper_event_read
I0718 10:02:38.200128   20539 init_comm.go:68] [console] already read 8 bytes data
I0718 10:02:38.200426   20539 init_comm.go:68] [console] hyper send type 14, len 4
I0718 10:02:38.200494   20539 init_comm.go:106] read 8/8 [length = 0]
I0718 10:02:38.200506   20539 init_comm.go:110] data length is 12
I0718 10:02:38.200509   20539 init_comm.go:96] trying to read 4 bytes
I0718 10:02:38.200515   20539 init_comm.go:106] read 12/12 [length = 12]
I0718 10:02:38.200522   20539 init_comm.go:96] trying to read 8 bytes
I0718 10:02:38.200531   20539 init_comm.go:190] got cmd:14
I0718 10:02:38.200535   20539 init_comm.go:253] get command NEXT
I0718 10:02:38.200539   20539 init_comm.go:256] send 67, receive 8
I0718 10:02:38.200662   20539 init_comm.go:68] [console] get length 67
I0718 10:02:38.201013   20539 init_comm.go:68] [console] read 59 bytes data, total data 67
I0718 10:02:38.201294   20539 init_comm.go:68] [console] hyper send type 14, len 4
I0718 10:02:38.201363   20539 init_comm.go:106] read 8/8 [length = 0]
I0718 10:02:38.201367   20539 init_comm.go:110] data length is 12
I0718 10:02:38.201370   20539 init_comm.go:96] trying to read 4 bytes
I0718 10:02:38.201374   20539 init_comm.go:106] read 12/12 [length = 12]
I0718 10:02:38.201380   20539 init_comm.go:96] trying to read 8 bytes
I0718 10:02:38.201387   20539 init_comm.go:190] got cmd:14
I0718 10:02:38.201391   20539 init_comm.go:253] get command NEXT
I0718 10:02:38.201394   20539 init_comm.go:256] send 67, receive 67
I0718 10:02:38.202938   20539 init_comm.go:68] [console] 0 0 0 1 0 0 0 43 7b 22 68 6f 73 74 6e 61 6d 65 22 3a 22 73 68 65 6c 6c 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 
I0718 10:02:38.203347   20539 init_comm.go:68] [console]  hyper_channel_handle, type 1, len 67
I0718 10:02:38.204260   20539 init_comm.go:68] [console] call hyper_start_pod, json {"hostname":"shell","containers":[],"shareDir":"share_dir"}., len 59
I0718 10:02:38.205288   20539 init_comm.go:68] [console] call hyper_start_pod, json {"hostname":"shell","containers":[],"shareDir":"share_dir"}., len 59
I0718 10:02:38.205637   20539 init_comm.go:68] [console] jsmn parse successed, n is 7
I0718 10:02:38.205958   20539 init_comm.go:68] [console] token 0, type is 1, size is 3
I0718 10:02:38.206282   20539 init_comm.go:68] [console] token 1, type is 3, size is 1
I0718 10:02:38.206533   20539 init_comm.go:68] [console] hostname is shell
I0718 10:02:38.206863   20539 init_comm.go:68] [console] token 3, type is 3, size is 1
I0718 10:02:38.207093   20539 init_comm.go:68] [console] container count 0
I0718 10:02:38.207421   20539 init_comm.go:68] [console] token 5, type is 3, size is 1
I0718 10:02:38.208269   20539 init_comm.go:68] [console] random: busybox urandom read with 8 bits of entropy available
I0718 10:02:38.208639   20539 init_comm.go:68] [console] share tag is share_dir
I0718 10:02:38.208905   20539 init_comm.go:68] [console] create directory /tmp
I0718 10:02:38.209226   20539 init_comm.go:68] [console] create directory /tmp/hyper
I0718 10:02:38.209574   20539 init_comm.go:68] [console] create directory /tmp/hyper/proc
I0718 10:02:38.210055   20539 init_comm.go:68] [console] finish rescan
I0718 10:02:38.210543   20539 init_comm.go:68] [console] create directory /tmp/hyper/shared
I0718 10:02:38.213417   20539 init_comm.go:68] [console] pod init pid 325
I0718 10:02:38.213746   20539 init_comm.go:68] [console] hyper send type 8, len 0
I0718 10:02:38.213977   20539 init_comm.go:68] [console] uptime 0.33 0.02
I0718 10:02:38.214078   20539 init_comm.go:68] [console] 
I0718 10:02:38.214345   20539 init_comm.go:68] [console] hyper send type 9, len 0
I0718 10:02:38.214462   20539 init_comm.go:106] read 8/8 [length = 0]
I0718 10:02:38.214470   20539 init_comm.go:110] data length is 8
I0718 10:02:38.214479   20539 init_comm.go:96] trying to read 8 bytes
I0718 10:02:38.214495   20539 init_comm.go:190] got cmd:9
I0718 10:02:38.214505   20539 init_comm.go:209] ack got, clear pong timer
I0718 10:02:38.214517   20539 hypervisor.go:29] vm vm-jSdTQgbOCv: main event loop got message 31(COMMAND_ACK)
I0718 10:02:38.214533   20539 vm_states.go:499] [starting] got init ack to &{1 859531731840  [] 859533565952}
I0718 10:02:38.214766   20539 init_comm.go:68] [console] pid 324 exit normally, status 0
I0718 10:02:38.214962   20539 context.go:211] VM vm-jSdTQgbOCv: state change from STARTING to 'RUNNING'
I0718 10:02:38.214969   20539 vm_states.go:515] pod start success 
I0718 10:02:38.214982   20539 vm.go:260] Get the response from VM, VM id is vm-jSdTQgbOCv!
I0718 10:02:38.214992   20539 hyperpod.go:296] result: code 0 Start POD success
I0718 10:02:38.214997   20539 hyperpod.go:162] get exec path /usr/local/bin/runv
I0718 10:02:38.215424   20539 init_comm.go:68] [console] can not find exec whose pid is 324
I0718 10:02:38.215450   20539 init_comm.go:68] [console] hyper_loop epoll_wait -1
I0718 10:02:38.232033   20539 hypervisor.go:29] vm vm-jSdTQgbOCv: main event loop got message 24(COMMAND_SHUTDOWN)
I0718 10:02:38.232045   20539 vm_states.go:327] got shutdown command, shutting down
I0718 10:02:38.232057   20539 context.go:211] VM vm-jSdTQgbOCv: state change from RUNNING to 'TERMINATING'
I0718 10:02:38.232065   20539 init_comm.go:190] got cmd:4
I0718 10:02:38.232074   20539 init_comm.go:281] send command 4 to init, payload: 'null'.
I0718 10:02:38.232098   20539 init_comm.go:294] write 12 to init, payload: '\00\00\00\00\00\00null'.
I0718 10:02:38.232104   20539 init_comm.go:299] message sent, set pong timer
I0718 10:02:38.232654   20539 init_comm.go:68] [console] hyper_loop epoll_wait 1
I0718 10:02:38.233604   20539 init_comm.go:68] [console] hyper_handle_event get event 1, de 0x615580, fd 3. ops 0x6153a0
I0718 10:02:38.234530   20539 init_comm.go:68] [console] hyper_handle_event event EPOLLIN, de 0x615580, fd 3, 0x6153a0
I0718 10:02:38.234855   20539 init_comm.go:68] [console] hyper_event_read
I0718 10:02:38.235298   20539 init_comm.go:68] [console] already read 8 bytes data
I0718 10:02:38.235731   20539 init_comm.go:68] [console] hyper send type 14, len 4
I0718 10:02:38.235838   20539 init_comm.go:106] read 8/8 [length = 0]
I0718 10:02:38.235848   20539 init_comm.go:110] data length is 12
I0718 10:02:38.235857   20539 init_comm.go:96] trying to read 4 bytes
I0718 10:02:38.235874   20539 init_comm.go:106] read 12/12 [length = 12]
I0718 10:02:38.235901   20539 init_comm.go:96] trying to read 8 bytes
I0718 10:02:38.235923   20539 init_comm.go:190] got cmd:14
I0718 10:02:38.235930   20539 init_comm.go:253] get command NEXT
I0718 10:02:38.235937   20539 init_comm.go:256] send 12, receive 8
I0718 10:02:38.236113   20539 init_comm.go:68] [console] get length 12
I0718 10:02:38.236542   20539 init_comm.go:68] [console] read 4 bytes data, total data 12
I0718 10:02:38.236987   20539 init_comm.go:68] [console] hyper send type 14, len 4
I0718 10:02:38.237059   20539 init_comm.go:106] read 8/8 [length = 0]
I0718 10:02:38.237065   20539 init_comm.go:110] data length is 12
I0718 10:02:38.237070   20539 init_comm.go:96] trying to read 4 bytes
I0718 10:02:38.237079   20539 init_comm.go:106] read 12/12 [length = 12]
I0718 10:02:38.237086   20539 init_comm.go:96] trying to read 8 bytes
I0718 10:02:38.237098   20539 init_comm.go:190] got cmd:14
I0718 10:02:38.237105   20539 init_comm.go:253] get command NEXT
I0718 10:02:38.237111   20539 init_comm.go:256] send 12, receive 12
I0718 10:02:38.237518   20539 init_comm.go:68] [console] 0 0 0 4 0 0 0 c 6e 75 6c 6c 
I0718 10:02:38.237990   20539 init_comm.go:68] [console]  hyper_channel_handle, type 4, len 12
I0718 10:02:38.238389   20539 init_comm.go:68] [console] get DESTROYPOD message
I0718 10:02:38.238925   20539 init_comm.go:68] [console] Sending SIGTERM
I0718 10:02:38.239203   20539 init_comm.go:68] [console] kill process 325
I0718 10:02:38.239555   20539 init_comm.go:68] [console] kill process 323
I0718 10:02:38.239858   20539 init_comm.go:68] [console] kill process 322
I0718 10:02:38.240171   20539 init_comm.go:68] [console] kill process 65
I0718 10:02:38.240512   20539 init_comm.go:68] [console] kill process 64
I0718 10:02:38.240751   20539 init_comm.go:68] [console] kill process 63
I0718 10:02:38.241067   20539 init_comm.go:68] [console] kill process 62
I0718 10:02:38.241316   20539 init_comm.go:68] [console] kill process 61
I0718 10:02:38.241626   20539 init_comm.go:68] [console] kill process 60
I0718 10:02:38.241913   20539 init_comm.go:68] [console] kill process 59
I0718 10:02:38.242201   20539 init_comm.go:68] [console] kill process 58
I0718 10:02:38.242498   20539 init_comm.go:68] [console] kill process 57
I0718 10:02:38.242739   20539 init_comm.go:68] [console] kill process 56
I0718 10:02:38.243036   20539 init_comm.go:68] [console] kill process 55
I0718 10:02:38.243340   20539 init_comm.go:68] [console] kill process 54
I0718 10:02:38.243599   20539 init_comm.go:68] [console] kill process 53
I0718 10:02:38.243843   20539 init_comm.go:68] [console] kill process 52
I0718 10:02:38.244139   20539 init_comm.go:68] [console] kill process 51
I0718 10:02:38.244403   20539 init_comm.go:68] [console] kill process 50
I0718 10:02:38.244704   20539 init_comm.go:68] [console] kill process 49
I0718 10:02:38.244964   20539 init_comm.go:68] [console] kill process 48
I0718 10:02:38.245176   20539 init_comm.go:68] [console] kill process 47
I0718 10:02:38.245437   20539 init_comm.go:68] [console] kill process 37
I0718 10:02:38.245688   20539 init_comm.go:68] [console] kill process 23
I0718 10:02:38.245940   20539 init_comm.go:68] [console] kill process 22
I0718 10:02:38.246191   20539 init_comm.go:68] [console] kill process 21
I0718 10:02:38.246451   20539 init_comm.go:68] [console] kill process 20
I0718 10:02:38.246701   20539 init_comm.go:68] [console] kill process 19
I0718 10:02:38.246953   20539 init_comm.go:68] [console] kill process 18
I0718 10:02:38.247204   20539 init_comm.go:68] [console] kill process 17
I0718 10:02:38.247466   20539 init_comm.go:68] [console] kill process 16
I0718 10:02:38.247717   20539 init_comm.go:68] [console] kill process 15
I0718 10:02:38.247968   20539 init_comm.go:68] [console] kill process 14
I0718 10:02:38.248222   20539 init_comm.go:68] [console] kill process 13
I0718 10:02:38.248484   20539 init_comm.go:68] [console] kill process 12
I0718 10:02:38.248743   20539 init_comm.go:68] [console] kill process 11
I0718 10:02:38.248994   20539 init_comm.go:68] [console] kill process 10
I0718 10:02:38.249237   20539 init_comm.go:68] [console] kill process 9
I0718 10:02:38.249489   20539 init_comm.go:68] [console] kill process 8
I0718 10:02:38.249732   20539 init_comm.go:68] [console] kill process 7
I0718 10:02:38.249974   20539 init_comm.go:68] [console] kill process 6
I0718 10:02:38.250214   20539 init_comm.go:68] [console] kill process 5
I0718 10:02:38.250467   20539 init_comm.go:68] [console] kill process 4
I0718 10:02:38.250707   20539 init_comm.go:68] [console] kill process 3
I0718 10:02:38.250948   20539 init_comm.go:68] [console] kill process 2
I0718 10:02:38.993768   20539 init_comm.go:68] [console] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x2f75b1eac7a, max_idle_ns: 440795210882 ns
I0718 10:02:48.232263   20539 hypervisor.go:29] vm vm-jSdTQgbOCv: main event loop got message 3(EVENT_VM_TIMEOUT)
W0718 10:02:48.232299   20539 vm_states.go:650] VM did not exit in time, try to stop it
E0718 10:02:48.232566   20539 vm_states.go:293] Shutting down because of an exception: vm terminating timeout
I0718 10:02:48.232695   20539 qmp_handler.go:296] got new session
I0718 10:02:48.232735   20539 qmp_handler.go:225] Begin process command session
I0718 10:02:48.232755   20539 qmp_handler.go:243] sending command (1) {"execute":"quit"}
I0718 10:02:48.232816   20539 vm.go:298] Got response: 7: vm terminating timeout
I0718 10:02:48.233293   20539 qmp_handler.go:103] got a message {"return": {}}
I0718 10:02:48.233353   20539 qmp_handler.go:103] got a message {"timestamp": {"seconds": 1468807368, "microseconds": 233233}, "event": "SHUTDOWN"}
I0718 10:02:48.233374   20539 qmp_handler.go:107] got event: SHUTDOWN
I0718 10:02:48.233383   20539 qmp_handler.go:152] Shutdown, quit QMP receiver
I0718 10:02:48.233394   20539 qmp_handler.go:323] got QMP event SHUTDOWN
I0718 10:02:48.233401   20539 qmp_handler.go:325] got QMP shutdown event, quit...
I0718 10:02:48.233411   20539 hypervisor.go:29] vm vm-jSdTQgbOCv: main event loop got message 1(EVENT_VM_EXIT)
I0718 10:02:48.233419   20539 vm_states.go:622] Got VM shutdown event while terminating, go to cleaning up
I0718 10:02:48.233425   20539 vm_states.go:36] VM has exit...
I0718 10:02:48.233435   20539 devicemap.go:93] All resource being released, someone is waiting for us...
I0718 10:02:48.233440   20539 context.go:198] no more device to release/remove/umount, quit
I0718 10:02:48.233464   20539 qemu_process.go:19] quit watch dog.
I0718 10:02:48.233480   20539 vm.go:298] Got response: 2: VM shut down
I0718 10:02:48.233491   20539 hyperpod.go:319] StopPod fail: QEMU response data is nil
I0718 10:02:48.233497   20539 hyperpod.go:309] start ns listener fail: EOF
I0718 10:02:48.233504   20539 supervisor.go:168] createHyperPod() returns
E0718 10:02:48.238242   20539 init_comm.go:99] read init data failed
E0718 10:02:48.238244   20539 tty.go:90] read tty data failed
I0718 10:02:48.238272   20539 tty.go:151] tty socket closed, quit the reading goroutine EOF
I0718 10:02:48.238282   20539 tty.go:428] Input byte chan closed, close the output string chan
I0718 10:02:48.238300   20539 init_comm.go:70] console output end
I0718 10:02:48.238309   20539 tty.go:118] tty chan closed, quit sent goroutine
gao-feng commented 7 years ago

@Ddnirvana Thanks! it seems like some wrong in containerd-nslistener, Can you apply the below patch to tell us what's wrong.

diff --git a/supervisor/hyperpod.go b/supervisor/hyperpod.go
index 9b92419..e504e9a 100644
--- a/supervisor/hyperpod.go
+++ b/supervisor/hyperpod.go
@@ -290,6 +290,7 @@ func (hp *HyperPod) startNsListener() (err error) {
        glog.Infof("get exec path %s", path)
        parentPipe, childPipe, err = newPipe()
        if err != nil {
+               glog.Errorf("create pipe for containerd-nslistener failed: %v", err)
                return err
        }

@@ -304,7 +305,7 @@ func (hp *HyperPod) startNsListener() (err error) {
        cmd.Args[0] = "containerd-nslistener"
        cmd.ExtraFiles = append(cmd.ExtraFiles, childPipe)
        if err = cmd.Start(); err != nil {
-               glog.Error(err)
+               glog.Errorf("start containerd-nslistener failed %v", err)
                return err
        }

@@ -328,6 +329,7 @@ func (hp *HyperPod) startNsListener() (err error) {
        /* Make sure nsListener create new netns */
        var ready string
        if err = dec.Decode(&ready); err != nil {
+               glog.Errorf("Get ready message from containerd-nslistener failed: %v", err)
                return err
        }
Ddnirvana commented 7 years ago

OMG......Firstly I find your patch is based on the codes in the git(which is the most recently version). Actually it's a bit different than the version 0.6.0 code in the release package(which version I am using now). So I just think maybe I should try pulling the latest code instead of downloading the release package. And I find it just works fine! @gao-feng I really really appreciate your help! But I still wonder why it failed when I use the code in the release packages......

gao-feng commented 7 years ago

@Ddnirvana Good news! I think it may be runv-0.6 doesn't support nslistener(https://github.com/hyperhq/runv/blob/v0.6.0/main.go#L51), the latest code adds the support.(https://github.com/hyperhq/runv/blob/master/main.go#L57)

I'm sorry that troubled you.