search

vmware / vic

vSphere Integrated Containers Engine is a container runtime for vSphere.
http://vmware.github.io/vic
Other
640 stars 173 forks source link

docker start: unable to wait for process due to deadline context exceeded on propertycollector #3315

Closed anchal-agrawal closed 7 years ago

anchal-agrawal commented 7 years ago

Seen in CI during docker start:

Error response from daemon: Server error from portlayer: unable to wait for process launch status: context deadline exceeded
Error: failed to start containers: <container>

https://ci.vmware.run/vmware/vic/7252

==============================================================================
Test-Cases.Group1-Docker-Commands.1-19-Docker-Volume-Create :: Test 1-19 - ...
==============================================================================
Simple docker volume create                                           | FAIL |
125 != 0
------------------------------------------------------------------------------

https://ci.vmware.run/vmware/vic/7255

==============================================================================
Test-Cases.Group1-Docker-Commands.1-04-Docker-Create :: Test 1-04 - Docker ...
==============================================================================
Create linked containers that can ping                                | FAIL |
1 != 0
------------------------------------------------------------------------------

Logs:

PL log snippet

time="2016-11-27T23:24:25Z" level=error msg="Property collector error: context deadline exceeded" 
time="2016-11-27T23:24:25Z" level=error msg="Unable to wait for extra config property guestinfo.vice..sessions|ed127adf6141da6ced6427218092314848330d4655ae487373563b80f9ea6406.started: context deadline exceeded" 
time="2016-11-27T23:24:25Z" level=debug msg="Setting container ed127adf6141da6ced6427218092314848330d4655ae487373563b80f9ea6406 state: Starting" 
time=2016-11-27T23:24:25.254927717Z level=debug msg=[ END ] [github.com/vmware/vic/lib/portlayer/exec.(*Container).start:308] [3m0.835699349s] ed127adf6141da6ced6427218092314848330d4655ae487373563b80f9ea6406 
time=2016-11-27T23:24:25.254941955Z level=debug msg=[BEGIN] [github.com/vmware/vic/lib/portlayer/exec.(*Container).RefreshFromHandle:291] 20030f839c28752cea16062a4d63757c 
time="2016-11-27T23:24:25Z" level=debug msg="container refreshed - ChangeVersion: 2016-11-27T23:21:24.992438Z" 
time=2016-11-27T23:24:25.254955773Z level=debug msg=[ END ] [github.com/vmware/vic/lib/portlayer/exec.(*Container).RefreshFromHandle:291] [13.5µs] 20030f839c28752cea16062a4d63757c 
time=2016-11-27T23:24:25.254992941Z level=debug msg=[ END ] [github.com/vmware/vic/lib/portlayer/exec.Commit:35] [3m0.966211744s] ed127adf6141da6ced6427218092314848330d4655ae487373563b80f9ea6406 
time="2016-11-27T23:24:25Z" level=error msg="CommitHandler error on handle(20030f839c28752cea16062a4d63757c) for ed127adf6141da6ced6427218092314848330d4655ae487373563b80f9ea6406: &errors.errorString{s:\"unable to wait for process launch status: context deadline exceeded\"}"

Test-Cases.Group1-Docker-Commands.1-19-Docker-Volume-Create-VCH-7252-2440-container-logs.zip Test-Cases.Group1-Docker-Commands.1-04-Docker-Create-VCH-7255-5311-container-logs.zip

hickeng commented 7 years ago

This is odd - in a successful boot we see the following from the containerVM vmware.log:

2016-11-25T17:24:14.094Z| vcpu-1| I120: PVSCSI: ReqRing: 256 entries, eSz=128, 8 pages
2016-11-25T17:24:14.094Z| vcpu-1| I120: PVSCSI: CmpRing: 1024 entries, eSz=32, 8 pages
2016-11-25T17:24:14.095Z| vcpu-1| I120: PVSCSI: MsgRing: 32 entries, eSz=128, 1 pages
2016-11-25T17:24:14.095Z| vcpu-1| I120: PVSCSI: scsi0: init reqCallThresholdCapable 1
2016-11-25T17:24:14.444Z| vcpu-0| I120: Ethernet0 MAC Address: 00:0c:29:26:bf:ee
2016-11-25T17:24:14.504Z| svga| I120: SVGA hiding SVGA
2016-11-25T17:24:14.510Z| svga| I120: SVGA enabling SVGA
2016-11-25T17:24:14.569Z| svga| A115: ConfigDB: Setting svga.guestBackedPrimaryAware = "TRUE"
2016-11-25T17:24:14.827Z| vcpu-0| I120: CDROM ide0:0: CMD 0x52 (*UNKNOWN (0x52)*) FAILED (key 0x5 asc 0x20 ascq 0)
2016-11-25T17:24:14.835Z| vcpu-0| I120: CDROM: Emulate GET CONFIGURATION RT 0 starting feature 0
2016-11-25T17:24:14.835Z| vcpu-0| I120: CDROM: Emulate GET CONFIGURATION RT 0 starting feature 0
2016-11-25T17:24:14.841Z| vcpu-0| I120: CDROM: Emulate GET CONFIGURATION RT 0 starting feature 0
2016-11-25T17:24:15.242Z| vcpu-0| I120: CDROM: Emulate GET CONFIGURATION RT 0 starting feature 0
2016-11-25T17:24:15.242Z| vcpu-0| I120: CDROM: Emulate GET CONFIGURATION RT 0 starting feature 0
2016-11-25T17:24:15.248Z| vcpu-0| I120: CDROM: Emulate GET CONFIGURATION RT 0 starting feature 0
2016-11-25T17:24:15.349Z| vcpu-0| I120: HBACommon: First write on scsi0:0.fileName='/vmfs/volumes/57ebe8e5-b912ca38-0fd0-0050569c054c/unitContainer-64c5e09b715f0c7ea6e475ef5fbc711a86324db26db754787ee5e6c084c32e75/64c5e09b715f0c7ea6e475ef5fbc711a86324db26db754787ee5e6c084c32e75.vmdk'
2016-11-25T17:24:15.349Z| vcpu-0| I120: DDB: "longContentID" = "5681cc024bb8dfb6868140bf4c6d46e6" (was "ee259b121c585247850f686b75d766b9")
2016-11-25T17:24:15.822Z| vcpu-0| I120: DISKLIB-CHAIN : DiskChainUpdateContentID: old=0x75d766b9, new=0x4c6d46e6 (5681cc024bb8dfb6868140bf4c6d46e6)

yet from these failed containers there's no indication of CD initialization:

2016-11-25T17:17:48.633Z| vcpu-1| I120: PVSCSI: ReqRing: 256 entries, eSz=128, 8 pages
2016-11-25T17:17:48.633Z| vcpu-1| I120: PVSCSI: CmpRing: 1024 entries, eSz=32, 8 pages
2016-11-25T17:17:48.633Z| vcpu-1| I120: PVSCSI: MsgRing: 32 entries, eSz=128, 1 pages
2016-11-25T17:17:48.634Z| vcpu-1| I120: PVSCSI: scsi0: init reqCallThresholdCapable 1
2016-11-25T17:17:49.021Z| vcpu-1| I120: Ethernet0 MAC Address: 00:0c:29:74:98:f1
2016-11-25T17:17:49.211Z| svga| I120: SVGA hiding SVGA
2016-11-25T17:17:49.218Z| svga| I120: SVGA enabling SVGA
2016-11-25T17:17:49.248Z| svga| A115: ConfigDB: Setting svga.guestBackedPrimaryAware = "TRUE"
2016-11-25T17:17:50.183Z| vcpu-0| I120: HBACommon: First write on scsi0:0.fileName='/vmfs/volumes/57ebe8e5-b912ca38-0fd0-0050569c054c/unnamedSpecVolC-5d8736066f9aca53608d42b2db05420d6572870a23fed7037c8c0eb706bd2e23/5d8736066f9aca53608d42b2db05420d6572870a23fed7037c8c0eb706bd2e23.vmdk'
2016-11-25T17:17:50.183Z| vcpu-0| I120: DDB: "longContentID" = "af8cb14d8474187860729afb22418ce2" (was "ee259b121c585247850f686b75d766b9")
2016-11-25T17:17:50.849Z| vcpu-0| I120: DISKLIB-CHAIN : DiskChainUpdateContentID: old=0x75d766b9, new=0x22418ce2 (af8cb14d8474187860729afb22418ce2)

In hostd.log everything looks the same as a successful VM boot until (yet I cannot see why this would inhibit the VM from booting correctly):

2016-11-25T17:17:40.442Z info hostd[781C8B70] [Originator@6876 sub=SysCommandPosix] ForkExec(/sbin/backup.sh)  7086553
2016-11-25T17:17:42.371Z info hostd[781C8B70] [Originator@6876 sub=Hostsvc.HostConfigSyncManagerImpl] /sbin/backup.sh succeeded
2016-11-25T17:17:53.874Z info hostd[78A40B70] [Originator@6876 sub=Vimsvc.ha-eventmgr] Event 308537 : User root@192.168.31.202 logged out (login time: Friday, 25 November, 2016 16:47:40, number of API invocations: 0, user agent: vic-admin/0.8.0-rc2)
2016-11-25T17:17:56.997Z error hostd[78F40B70] [Originator@6876 sub=SoapAdapter.HTTPService] Failed to read request; stream: <io_obj p:0x769c9974, h:-1, <TCP '0.0.0.0:0'>, <TCP '0.0.0.0:0'>>, error: N7Vmacore16TimeoutExceptionE(Operation timed out)
2016-11-25T17:18:00.770Z info hostd[78FC1B70] [Originator@6876 sub=Vimsvc.ha-eventmgr] Event 308538 : User root@192.168.31.202 logged out (login time: Friday, 25 November, 2016 16:45:32, number of API invocations: 0, user agent: vic-engine/0.8.0-rc2)
2016-11-25T17:18:06.052Z info hostd[781C8B70] [Originator@6876 sub=Vimsvc.ha-eventmgr] Event 308539 : User root@192.168.31.213 logged out (login time: Friday, 25 November, 2016 16:47:54, number of API invocations: 0, user agent: vic-machine/0.8.0-rc2)
[LikewiseGetDomainJoinInfo:355] QueryInformation(): ERROR_FILE_NOT_FOUND (2/0):
2016-11-25T17:18:42.611Z info hostd[78FC1B70] [Originator@6876 sub=Vimsvc.ha-eventmgr] Event 308540 : User root@192.168.31.213 logged out (login time: Friday, 25 November, 2016 16:48:14, number of API invocations: 0, user agent: vic-machine/0.8.0-rc2)
2016-11-25T17:18:52.015Z error hostd[781C8B70] [Originator@6876 sub=SoapAdapter.HTTPService] Failed to read request; stream: <io_obj p:0x77a36d8c, h:-1, <TCP '0.0.0.0:0'>, <TCP '0.0.0.0:0'>>, error: N7Vmacore16TimeoutExceptionE(Operation timed out)
2016-11-25T17:19:17.021Z error hostd[78A40B70] [Originator@6876 sub=SoapAdapter.HTTPService] Failed to read request; stream: <io_obj p:0x7564bbc4, h:-1, <TCP '0.0.0.0:0'>, <TCP '0.0.0.0:0'>>, error: N7Vmacore16TimeoutExceptionE(Operation timed out)
[LikewiseGetDomainJoinInfo:355] QueryInformation(): ERROR_FILE_NOT_FOUND (2/0):
2016-11-25T17:20:37.817Z info hostd[767C5B70] [Originator@6876 sub=Solo.Vmomi opID=e9a860c2 user=root] Activation [N5Vmomi10ActivationE:0x76982c48] : Invoke done [waitForUpdatesEx] on [vmodl.query.PropertyCollector:session[525f5d79-e4e0-59ab-38d0-48e21a488b30]523786c6-2b4c-4d1a-2f6f-f4ad437b16d7]
2016-11-25T17:20:37.817Z verbose hostd[767C5B70] [Originator@6876 sub=Solo.Vmomi opID=e9a860c2 user=root] Arg version:
--> "2"
2016-11-25T17:20:37.817Z verbose hostd[767C5B70] [Originator@6876 sub=Solo.Vmomi opID=e9a860c2 user=root] Arg options:
--> (null)
2016-11-25T17:20:37.818Z info hostd[767C5B70] [Originator@6876 sub=Solo.Vmomi opID=e9a860c2 user=root] Throw vmodl.fault.RequestCanceled
2016-11-25T17:20:37.818Z info hostd[767C5B70] [Originator@6876 sub=Solo.Vmomi opID=e9a860c2 user=root] Result:
--> (vmodl.fault.RequestCanceled) {
-->    faultCause = (vmodl.MethodFault) null,
-->    msg = ""
--> }
2016-11-25T17:20:37.818Z error hostd[76681B70] [Originator@6876 sub=SoapAdapter.HTTPService.HttpConnection] Failed to read header on stream <io_obj p:0x77506854, h:34, <TCP '0.0.0.0:0'>, <TCP '0.0.0.0:0'>>: N7Vmacore15SystemExceptionE(Connection reset by peer)

(we'd normally see a series of the following):

2016-11-27T23:20:39.069Z info hostd[27BC9B70] [Originator@6876 sub=SysCommandPosix] ForkExec(/sbin/backup.sh)  6482585
2016-11-27T23:20:40.430Z info hostd[27BC9B70] [Originator@6876 sub=Hostsvc.HostConfigSyncManagerImpl] /sbin/backup.sh succeeded
2016-11-27T23:20:44.081Z info hostd[254C2B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe523-69be456a-164b-0050569c6063/tender_wing-0a25a8f3898c2776dc32486cceef7727cce997916472d013ce8bf0a8fac9fd19/tender_wing-0a25a8f3898c2776dc32486cceef7727cce997916472d013ce8bf0a8fac9fd19.vmx] Send config update invoked
2016-11-27T23:20:44.231Z info hostd[254C2B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe523-69be456a-164b-0050569c6063/tender_wing-0a25a8f3898c2776dc32486cceef7727cce997916472d013ce8bf0a8fac9fd19/tender_wing-0a25a8f3898c2776dc32486cceef7727cce997916472d013ce8bf0a8fac9fd19.vmx] Tools manifest version status changed from guestToolsNotInstalled to guestToolsUnmanaged, on install is TRUE
2016-11-27T23:20:44.237Z info hostd[254C2B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe523-69be456a-164b-0050569c6063/tender_wing-0a25a8f3898c2776dc32486cceef7727cce997916472d013ce8bf0a8fac9fd19/tender_wing-0a25a8f3898c2776dc32486cceef7727cce997916472d013ce8bf0a8fac9fd19.vmx] Send config update invoked
emlin commented 7 years ago

https://ci.vmware.run/vmware/vic/7504

mhagen-vmware commented 7 years ago

marking this low priority, if we see it again it should be moved to medium.

chengwang86 commented 7 years ago

https://ci.vmware.run/vmware/vic/7923

1-23 Docker inspect container with multiple networks

From portlayer.log

Feb  8 2017 22:57:27.290Z DEBUG [BEGIN] [github.com/vmware/vic/lib/portlayer/exec.(*containerBase).start:152] 72f9699886cd4f6f4798c92e8c90e35f88b4711f383ff059317b006df86f9022
Feb  8 2017 22:57:28.325Z DEBUG Found 2 subscribers to vsphere.VMEvent: two-net-test-72f9699886cd4f6f4798c92e8c90e35f88b4711f383ff059317b006df86f9022 on  vic-esx-05.ci.drone.local in ha-datacenter is powered on
Feb  8 2017 22:57:28.334Z DEBUG Event manager calling back to exec
Feb  8 2017 22:57:28.334Z DEBUG Event manager calling back to logging
Feb  8 2017 22:57:28.334Z DEBUG [BEGIN] [github.com/vmware/vic/lib/portlayer/logging.eventCallback:50]
Feb  8 2017 22:57:28.334Z DEBUG [ END ] [github.com/vmware/vic/lib/portlayer/logging.eventCallback:50] [5.626µs] 
Feb  8 2017 23:00:28.369Z ERROR Property collector error: Post https://192.168.31.7/sdk: net/http: request canceled
Feb  8 2017 23:00:28.389Z ERROR Unable to wait for extra config property guestinfo.vice..sessions|72f9699886cd4f6f4798c92e8c90e35f88b4711f383ff059317b006df86f9022.started: Post https://192.168.31.7/sdk: net/http: request canceled
Feb  8 2017 23:00:28.389Z DEBUG [ END ] [github.com/vmware/vic/lib/portlayer/exec.(*containerBase).start:152] [3m1.098245374s] 72f9699886cd4f6f4798c92e8c90e35f88b4711f383ff059317b006df86f9022
anchal-agrawal commented 7 years ago

Also seen in #4212.

mhagen-vmware commented 7 years ago

See in longevity: container-logs.zip

anchal-agrawal commented 7 years ago

Also seen on https://ci.vmware.run/vmware/vic/9335 in test Group6-VIC-Machine/6-07-Create-Network:

docker run -d --net=vm-network --name p1 busybox /bin/top
${rc} = 125

Portlayer log snippet:

Mar 31 2017 17:25:16.914Z DEBUG Setting container 3e68223a29742e183c7fb0ceb0936c3e2923f0d202bc83356051a958db89580b state: Starting
Mar 31 2017 17:25:16.914Z DEBUG [BEGIN] [github.com/vmware/vic/lib/portlayer/exec.(*containerBase).start:181] 3e68223a29742e183c7fb0ceb0936c3e2923f0d202bc83356051a958db89580b
Mar 31 2017 17:25:17.529Z DEBUG Found 2 subscribers to vsphere.VMEvent: p1-3e68223a2974 on  ns539602.ip-144-217-72.net in ha-datacenter is powered on
Mar 31 2017 17:25:17.530Z DEBUG Event manager calling back to exec
Mar 31 2017 17:25:17.531Z DEBUG Event manager calling back to logging
Mar 31 2017 17:25:17.532Z DEBUG [BEGIN] [github.com/vmware/vic/lib/portlayer/logging.eventCallback:52]
Mar 31 2017 17:25:17.532Z DEBUG [ END ] [github.com/vmware/vic/lib/portlayer/logging.eventCallback:52] [17.899µs] 
Mar 31 2017 17:25:22.194Z DEBUG Found 2 subscribers to vsphere.VMEvent: p1-3e68223a2974 on  ns539602.ip-144-217-72.net in ha-datacenter is powered off
Mar 31 2017 17:25:22.195Z DEBUG Event manager calling back to exec
Mar 31 2017 17:25:22.196Z DEBUG Event manager calling back to logging
...
Mar 31 2017 17:25:22.221Z DEBUG Setting container 3e68223a29742e183c7fb0ceb0936c3e2923f0d202bc83356051a958db89580b state: Stopped
Mar 31 2017 17:25:22.221Z DEBUG Container(3e68223a29742e183c7fb0ceb0936c3e2923f0d202bc83356051a958db89580b) closing 0 log followers
Mar 31 2017 17:25:22.221Z DEBUG Container(3e68223a29742e183c7fb0ceb0936c3e2923f0d202bc83356051a958db89580b) state set to Stopped via event activity
Mar 31 2017 17:25:22.221Z DEBUG Found 2 subscribers to events.ContainerEvent: Container 3e68223a29742e183c7fb0ceb0936c3e2923f0d202bc83356051a958db89580b PoweredOff
Mar 31 2017 17:25:22.221Z DEBUG Event manager calling back to PLE-de029b71c86e6f41f2502efcffd5a605f2445ce8a5b01e03747720e9f5822165
Mar 31 2017 17:25:22.221Z DEBUG Event manager calling back to netCtx(0xc420165ce0)
...
Mar 31 2017 17:25:22.221Z DEBUG [BEGIN] [github.com/vmware/vic/lib/portlayer/exec.(*containerBase).updates:117] 3e68223a29742e183c7fb0ceb0936c3e2923f0d202bc83356051a958db89580b
Mar 31 2017 17:25:22.244Z DEBUG get vm properties [config runtime] of vm VirtualMachine:10212
Mar 31 2017 17:25:22.244Z DEBUG properties: [config runtime summary.runtime.connectionState]
Mar 31 2017 17:25:22.253Z ERROR Unable to wait for extra config property guestinfo.vice..sessions|3e68223a29742e183c7fb0ceb0936c3e2923f0d202bc83356051a958db89580b.started: summary.runtime.powerState=poweredOff
Mar 31 2017 17:25:22.253Z DEBUG [ END ] [github.com/vmware/vic/lib/portlayer/exec.(*containerBase).start:181] [5.339365353s] 3e68223a29742e183c7fb0ceb0936c3e2923f0d202bc83356051a958db89580b
Mar 31 2017 17:25:22.253Z DEBUG [ END ] [github.com/vmware/vic/lib/portlayer/exec.(*Container).start:336] [5.339401922s] 3e68223a29742e183c7fb0ceb0936c3e2923f0d202bc83356051a958db89580b
...
Mar 31 2017 17:25:22.269Z DEBUG [BEGIN] [github.com/vmware/vic/lib/portlayer/exec.Commit:35] 3e68223a29742e183c7fb0ceb0936c3e2923f0d202bc83356051a958db89580b
Mar 31 2017 17:25:22.269Z DEBUG ChangeVersion is 2017-03-31T17:25:17.523112Z
...
Mar 31 2017 17:25:22.269Z DEBUG [ END ] [github.com/vmware/vic/lib/portlayer/exec.Commit:35] [5.505227487s] 3e68223a29742e183c7fb0ceb0936c3e2923f0d202bc83356051a958db89580b
Mar 31 2017 17:25:22.269Z ERROR CommitHandler error on handle(7c9f3d3a39dd6f182785ced2f50d0da6) for 3e68223a29742e183c7fb0ceb0936c3e2923f0d202bc83356051a958db89580b: &errors.errorString{s:"unable to wait for process launch status: summary.runtime.powerState=poweredOff"}
Mar 31 2017 17:25:22.269Z DEBUG [ END ] [github.com/vmware/vic/lib/apiservers/portlayer/restapi/handlers.(*ContainersHandlersImpl).CommitHandler:213] [5.505511593s] handle(7c9f3d3a39dd6f182785ced2f50d0da6)

Log bundle: Test-Cases.Group6-VIC-Machine.6-07-Create-Network-VCH-9335-8157-container-logs.zip

andrewtchin commented 7 years ago

https://ci.vcna.io/vmware/vic/11121

Test-Cases.Group1-Docker-Commands.1-06-Docker-Run-VCH-11121-3941-container-logs.zip

chengwang86 commented 7 years ago

Also seen in nightly test 5-6-1-vSAN-Simple (vsphere 6.5) 5-6-1-VSAN-Simple.zip

chengwang86 commented 7 years ago

Seen in ci https://ci.vcna.io/vmware/vic/11599

Test-Cases.Group6-VIC-Machine.6-07-Create-Network.Connectivity Bridge to Public

Test-Cases.Group6-VIC-Machine.6-07-Create-Network-VCH-11599-6905-container-logs.zip

From portlayer.log

Jun 16 2017 16:03:11.220Z DEBUG [BEGIN] [github.com/vmware/vic/lib/portlayer/exec.(*containerBase).start:195] 1a466226955e1103fe02fef717ac1745db0f8f14cafe763f68b71cca5c51070e
Jun 16 2017 16:03:11.236Z DEBUG vSphere Event p1-1a466226955e on host ns539602.ip-144-217-72.net in ha-datacenter is starting for eventID(368040) ignored by the event collector
Jun 16 2017 16:03:11.752Z DEBUG [BEGIN] [github.com/vmware/vic/lib/portlayer/exec.(*containerBase).waitForSession:370] 1a466226955e1103fe02fef717ac1745db0f8f14cafe763f68b71cca5c51070e
Jun 16 2017 16:03:11.757Z DEBUG Found 2 subscribers to id: 368041 - vsphere.VMEvent: p1-1a466226955e on  ns539602.ip-144-217-72.net in ha-datacenter is powered on
Jun 16 2017 16:03:11.759Z DEBUG Event manager calling back to exec
Jun 16 2017 16:03:11.760Z DEBUG Event manager calling back to logging
Jun 16 2017 16:03:11.760Z DEBUG [BEGIN] [github.com/vmware/vic/lib/portlayer/logging.eventCallback:52]
Jun 16 2017 16:03:11.760Z DEBUG [ END ] [github.com/vmware/vic/lib/portlayer/logging.eventCallback:52] [7.055µs] 
Jun 16 2017 16:03:11.764Z DEBUG [BEGIN] [github.com/vmware/vic/lib/portlayer/exec.(*Container).OnEvent:615] event PoweredOn received for id: 368041
Jun 16 2017 16:03:11.764Z DEBUG [BEGIN] [github.com/vmware/vic/lib/portlayer/exec.eventedState:589] event PoweredOn received for id: 368041
Jun 16 2017 16:03:11.764Z DEBUG [ END ] [github.com/vmware/vic/lib/portlayer/exec.eventedState:589] [6.793µs] event PoweredOn received for id: 368041
Jun 16 2017 16:03:11.764Z DEBUG [ END ] [github.com/vmware/vic/lib/portlayer/exec.(*Container).OnEvent:615] [27.257µs] event PoweredOn received for id: 368041
Jun 16 2017 16:06:11.757Z ERROR Property collector error: Post https://192.168.31.39/sdk: context deadline exceeded
Jun 16 2017 16:06:11.757Z ERROR Unable to wait for extra config property guestinfo.vice..sessions|1a466226955e1103fe02fef717ac1745db0f8f14cafe763f68b71cca5c51070e.started: Post https://192.168.31.39/sdk: context deadline exceeded
Jun 16 2017 16:06:11.757Z DEBUG [ END ] [github.com/vmware/vic/lib/portlayer/exec.(*containerBase).waitForSession:370] [3m0.004537441s] 1a466226955e1103fe02fef717ac1745db0f8f14cafe763f68b71cca5c51070e
Jun 16 2017 16:06:11.757Z DEBUG [ END ] [github.com/vmware/vic/lib/portlayer/exec.(*containerBase).start:195] [3m0.536454593s] 1a466226955e1103fe02fef717ac1745db0f8f14cafe763f68b71cca5c51070e
Jun 16 2017 16:06:11.757Z DEBUG [ END ] [github.com/vmware/vic/lib/portlayer/exec.(*Container).start:345] [3m0.536488814s] 1a466226955e1103fe02fef717ac1745db0f8f14cafe763f68b71cca5c51070e
Jun 16 2017 16:06:11.757Z DEBUG [BEGIN] [github.com/vmware/vic/lib/portlayer/exec.(*Container).RefreshFromHandle:328] 262a9b00b79c82bc6b4dd9fcd0645797
Jun 16 2017 16:06:11.757Z DEBUG Current ChangeVersion: 2017-06-16T16:03:11.130233Z
Jun 16 2017 16:06:11.757Z DEBUG [ END ] [github.com/vmware/vic/lib/portlayer/exec.(*Container).RefreshFromHandle:328] [8.428µs] 262a9b00b79c82bc6b4dd9fcd0645797
Jun 16 2017 16:06:11.757Z DEBUG [ END ] [github.com/vmware/vic/lib/portlayer/exec.Commit:35] [3m0.646678099s] 1a466226955e1103fe02fef717ac1745db0f8f14cafe763f68b71cca5c51070e
Jun 16 2017 16:06:11.757Z ERROR CommitHandler error on handle(262a9b00b79c82bc6b4dd9fcd0645797) for 1a466226955e1103fe02fef717ac1745db0f8f14cafe763f68b71cca5c51070e: &errors.errorString{s:"unable to wait for process launch status: Post https://192.168.31.39/sdk: context deadline exceeded"}
hickeng commented 7 years ago

5479 would cause this in the portlayer logs, but not checked the log bundle to see whether the containerVM booted that far.

mhagen-vmware commented 7 years ago

https://ci.vcna.io/vmware/vic/12028

Test-Cases.Group1-Docker-Commands.1-37-Docker-USER-VCH-12028-9391-container-logs.zip

hickeng commented 7 years ago

@mhagen-vmware this is a completely different error. The detail of the error message in the 12028 build output is container VM has unexpectedly powered off. instead of context deadline exceeded

chengwang86 commented 7 years ago

@hickeng This is my fault. I found unable to wait for process launch status: summary.runtime.powerState=poweredOff in #4558 (closed) and this comment https://github.com/vmware/vic/issues/3315#issuecomment-290792180. So I thought the failure that @mhagen-vmware posted here might be related to this issue. I have created a new issue here https://github.com/vmware/vic/issues/5629

anchal-agrawal commented 7 years ago

https://ci.vcna.io/vmware/vic/12229

sgairo commented 7 years ago

Seen in nightlies 6.5 on 7/23/17 : 5-22-NFS-Volume.zip

sgairo commented 7 years ago

Seen in nightlies 6.5 on 7/27/17 report: 5-22-NFS-Volume.zip

sgairo commented 7 years ago

Seen in nightlies 6.5 on 7/30/17 report: 5-22-NFS-Volume.zip

Also on 6.0: 5-22-NFS-Volume.zip

sflxn commented 7 years ago

I'm not sure this really is an issue, or at least a high priority one. A lot of people are lumping in cannot start container issues into this bug. I've looked through most of these logs and only found 3 that actually pertains to the original issue, and the original issue has 2 of them. In other words, since the original issue, only one new issue, vsan-simple on June 8, has an issue that vaguely resembles the original issue. Please note, this issue only deals with CDE waiting on the property collector and not the big bucket of "cannot start container".

The one on June 8 was caused by the VM starting up and not finding an operating system. I have seen this issue in my own local environment. The original issue shows very few clues I can go on.

Run 7255's hostd file shows

2016-11-27T23:21:26.123Z info hostd[27902B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe523-69be456a-164b-0050569c6063/busy2-ed127adf6141da6ced6427218092314848330d4655ae487373563b80f9ea6406/busy2-ed127adf6141da6ced6427218092314848330d4655ae487373563b80f9ea6406.vmx] Send config update invoked
2016-11-27T23:21:26.257Z info hostd[27902B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe523-69be456a-164b-0050569c6063/busy2-ed127adf6141da6ced6427218092314848330d4655ae487373563b80f9ea6406/busy2-ed127adf6141da6ced6427218092314848330d4655ae487373563b80f9ea6406.vmx] Skip a duplicate transition to: VM_STATE_ON
2016-11-27T23:21:29.435Z info hostd[27902B70] [Originator@6876 sub=SysCommandPosix] ForkExec(/sbin/backup.sh)  6482927
2016-11-27T23:21:31.100Z info hostd[27902B70] [Originator@6876 sub=Hostsvc.HostConfigSyncManagerImpl] /sbin/backup.sh succeeded
2016-11-27T23:21:38.082Z info hostd[29342B70] [Originator@6876 sub=Vmsvc.vm:/vmfs/volumes/57ebe523-69be456a-164b-0050569c6063/busy1-4a1becd4be20c454b033e4a81c639f324ad12c73e52825151966d9e100adfe2f/busy1-4a1becd4be20c454b033e4a81c639f324ad12c73e52825151966d9e100adfe2f.vmx] Send config update invoked
[LikewiseGetDomainJoinInfo:355] QueryInformation(): ERROR_FILE_NOT_FOUND (2/0):
[LikewiseGetDomainJoinInfo:355] QueryInformation(): ERROR_FILE_NOT_FOUND (2/0):
[LikewiseGetDomainJoinInfo:355] QueryInformation(): ERROR_FILE_NOT_FOUND (2/0):

Since the original issue showed up last year and only one issue since then has the CDE on the property collector, maybe we should lower the priority of this one.

sflxn commented 7 years ago

After talking to @mdubya66, we're going to close this issue as Cannot Reproduce. If we see this issue again, we can reopen it.