Nightly-6.0-vMotion-13-1-vMotion-VCH-Appliance-VCH failed to install

[rajanashok]

https://storage.cloud.google.com/vic-ci-logs/vic_nightly_logs_2018-04-11-20-32-56.zip?authuser=1

vic-machine-linux create failed: Creating VCH exceeded time limit of 15m0s. Please increase the timeout using --timeout to accommodate for a busy vSphere target\n" ' does not contain 'Installer completed successfully'

Apr 12 2018 02:51:37.478Z ERROR op=290.70: vic/pkg/trace.(*Operation).Err: shutdown error: context deadline exceeded
vic/lib/portlayer/exec.(*containerBase).shutdown:365 shutdown

time="2018-04-12T02:23:31Z" level=debug msg="Version v1.4.0-dev-0-6acfebf" 
time="2018-04-12T02:23:31Z" level=warning msg="Using administrative user for VCH operation - use --ops-user to improve security (see -x for advanced help)" 
time="2018-04-12T02:23:31Z" level=debug msg="client network: IP {<nil> <nil>} gateway <nil> dest: []" 
time="2018-04-12T02:23:31Z" level=debug msg="public network: IP {<nil> <nil>} gateway <nil> dest: []" 
time="2018-04-12T02:23:31Z" level=debug msg="management network: IP {<nil> <nil>} gateway <nil> dest: []" 
time="2018-04-12T02:23:31Z" level=debug msg="VCH DNS servers: []" 
time="2018-04-12T02:23:31Z" level=debug msg="Unable to locate existing server certificate in cert path" 
time="2018-04-12T02:23:31Z" level=info msg="Generating CA certificate/key pair - private key in VCH-0-8783/ca-key.pem" 
time="2018-04-12T02:23:32Z" level=info msg="Generating server certificate/key pair - private key in VCH-0-8783/server-key.pem" 
time="2018-04-12T02:23:33Z" level=info msg="Generating client certificate/key pair - private key in VCH-0-8783/key.pem" 
time="2018-04-12T02:23:33Z" level=info msg="Generated browser friendly PFX ...
    [ Message content over the limit has been removed. ]
time="2018-04-12T02:39:51Z" level=info msg="    \"port-layer\": \"<nil>\"" 
time="2018-04-12T02:39:51Z" level=info msg="    \"vicadmin\": \"<nil>\"" 
time="2018-04-12T02:39:51Z" level=info msg="Collecting e5c45e3f-84ad-4c49-b5c2-0b7a062b07c2 vpxd.log" 
time="2018-04-12T02:39:51Z" level=info msg="\tAPI may be slow to start - try to connect to API after a few minutes:" 
time="2018-04-12T02:39:51Z" level=info msg="\t\tRun vic-machine-linux inspect to find API connection command and run the command if ip address is ready" 
time="2018-04-12T02:39:51Z" level=info msg="\t\tIf command succeeds, VCH is started. If command fails, VCH failed to install - see documentation for troubleshooting." 
time="2018-04-12T02:39:51Z" level=error msg="vic/cmd/vic-machine/create.(*Create).Run.func3: Create error: context deadline exceeded\nvic/cmd/vic-machine/create.(*Create).Run:744 Create\nvic/cmd/vic-machine/common.NewOperation:27 vic-machine-linux" 
time="2018-04-12T02:39:51Z" level=error msg=-------------------- 
time="2018-04-12T02:39:51Z" level=error msg="vic-machine-linux create failed: Creating VCH exceeded time limit of 15m0s. Please increase the timeout using --timeout to accommodate for a busy vSphere target\n" ' does not contain 'Installer completed successfully'

Appliance Log:

Apr 12 2018 02:51:17.602Z DEBUG [ END ] op=290.70 [vic/lib/portlayer/exec.(*containerBase).startGuestProgram:243] [134.165136ms] ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708:kill
Apr 12 2018 02:51:17.602Z INFO  op=290.70: waiting 10s for ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708 to power off
Apr 12 2018 02:51:17.904Z DEBUG [0xc42041afc0] write "Apr 12 2018 02:51:17.602Z DEBUG [ END ] op=290.70 [vic/lib/portlayer/exec.(*containerBase).startGuestProgram:243] [134.165136ms] ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708:kill\nApr 12 2018 02:51:17.602Z INFO  op=290.70: waiting 10s for ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708 to power off\n" to 2 writers (err: <nil>)
Apr 12 2018 02:51:27.468Z ERROR op=290.70: vic/pkg/trace.(*Operation).Err: shutdown error: context deadline exceeded
vic/lib/portlayer/exec.(*containerBase).shutdown:365 shutdown
vic/lib/apiservers/portlayer/restapi/handlers.(*ContainersHandlersImpl).CommitHandler:211 commit handle(fbcebf0f74b9bebb62799835de5bd583)
Apr 12 2018 02:51:27.478Z DEBUG [0xc42041afc0] write "Apr 12 2018 02:51:27.468Z ERROR op=290.70: vic/pkg/trace.(*Operation).Err: shutdown error: context deadline exceeded\nvic/lib/portlayer/exec.(*containerBase).shutdown:365 shutdown\nvic/lib/apiservers/portlayer/restapi/handlers.(*ContainersHandlersImpl).CommitHandler:211 commit handle(fbcebf0f74b9bebb62799835de5bd583)\n" to 2 writers (err: <nil>)
Apr 12 2018 02:51:27.478Z ERROR op=290.70: vic/lib/portlayer/exec.(*containerBase).shutdown: shutdown error: context deadline exceeded
vic/lib/portlayer/exec.(*containerBase).shutdown:365 shutdown
vic/lib/apiservers/portlayer/restapi/handlers.(*ContainersHandlersImpl).CommitHandler:211 commit handle(fbcebf0f74b9bebb62799835de5bd583)
Apr 12 2018 02:51:27.478Z WARN  op=290.70: timeout (10s) waiting for ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708 to power off via SIGTERM
Apr 12 2018 02:51:27.478Z INFO  op=290.70: sending kill -KILL ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708
Apr 12 2018 02:51:27.478Z DEBUG [BEGIN] op=290.70 [vic/lib/portlayer/exec.(*containerBase).startGuestProgram:243] ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708:kill
Apr 12 2018 02:51:27.508Z DEBUG [0xc42041afc0] write "Apr 12 2018 02:51:27.478Z ERROR op=290.70: vic/lib/portlayer/exec.(*containerBase).shutdown: shutdown error: context deadline exceeded\nvic/lib/portlayer/exec.(*containerBase).shutdown:365 shutdown\nvic/lib/apiservers/portlayer/restapi/handlers.(*ContainersHandlersImpl).CommitHandler:211 commit handle(fbcebf0f74b9bebb62799835de5bd583)\nApr 12 2018 02:51:27.478Z WARN  op=290.70: timeout (10s) waiting for ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708 to power off via SIGTERM\nApr 12 2018 02:51:27.478Z INFO  op=290.70: sending kill -KILL ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708\nApr 12 2018 02:51:27.478Z DEBUG [BEGIN] op=290.70 [vic/lib/portlayer/exec.(*containerBase).startGuestProgram:243] ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708:kill\n" to 2 writers (err: <nil>)
Apr 12 2018 02:51:27.530Z DEBUG [ END ] op=290.70 [vic/lib/portlayer/exec.(*containerBase).startGuestProgram:243] [51.989128ms] ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708:kill
Apr 12 2018 02:51:27.530Z WARN  op=290.70: sending kill -KILL ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708: ServerFaultCode: The attempted operation cannot be performed in the current state (Powered off).
Apr 12 2018 02:51:27.530Z INFO  op=290.70: waiting 10s for ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708 to power off
Apr 12 2018 02:51:27.544Z DEBUG [0xc42041afc0] write "Apr 12 2018 02:51:27.530Z DEBUG [ END ] op=290.70 [vic/lib/portlayer/exec.(*containerBase).startGuestProgram:243] [51.989128ms] ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708:kill\nApr 12 2018 02:51:27.530Z WARN  op=290.70: sending kill -KILL ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708: ServerFaultCode: The attempted operation cannot be performed in the current state (Powered off).\nApr 12 2018 02:51:27.530Z INFO  op=290.70: waiting 10s for ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708 to power off\n" to 2 writers (err: <nil>)
Apr 12 2018 02:51:29.692Z DEBUG error looking up client interface by name: Link client not found
Apr 12 2018 02:51:37.478Z ERROR op=290.70: vic/pkg/trace.(*Operation).Err: shutdown error: context deadline exceeded
vic/lib/portlayer/exec.(*containerBase).shutdown:365 shutdown
vic/lib/apiservers/portlayer/restapi/handlers.(*ContainersHandlersImpl).CommitHandler:211 commit handle(fbcebf0f74b9bebb62799835de5bd583)
Apr 12 2018 02:51:37.487Z DEBUG [0xc42041afc0] write "Apr 12 2018 02:51:37.478Z ERROR op=290.70: vic/pkg/trace.(*Operation).Err: shutdown error: context deadline exceeded\nvic/lib/portlayer/exec.(*containerBase).shutdown:365 shutdown\nvic/lib/apiservers/portlayer/restapi/handlers.(*ContainersHandlersImpl).CommitHandler:211 commit handle(fbcebf0f74b9bebb62799835de5bd583)\n" to 2 writers (err: <nil>)
Apr 12 2018 02:51:37.487Z ERROR op=290.70: vic/lib/portlayer/exec.(*containerBase).shutdown: shutdown error: context deadline exceeded
vic/lib/portlayer/exec.(*containerBase).shutdown:365 shutdown
vic/lib/apiservers/portlayer/restapi/handlers.(*ContainersHandlersImpl).CommitHandler:211 commit handle(fbcebf0f74b9bebb62799835de5bd583)
Apr 12 2018 02:51:37.487Z WARN  op=290.70: timeout (10s) waiting for ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708 to power off via SIGKILL
Apr 12 2018 02:51:37.487Z DEBUG op=290.70: Set container ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708 state: Stopping->Stopped
Apr 12 2018 02:51:37.487Z DEBUG Container(ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708) closing 0 log followers
Apr 12 2018 02:51:37.487Z DEBUG [ END ] op=290.70 [vic/lib/portlayer/exec.(*Container).stop:438] [20.018558686s] ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708
Apr 12 2018 02:51:37.487Z DEBUG [BEGIN] op=290.70 [vic/lib/portlayer/exec.(*containerBase).updates:119] ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708
Apr 12 2018 02:51:37.487Z DEBUG op=290.70: Update: for ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708, refreshing from change version 2018-04-12T02:49:05.891063Z
Apr 12 2018 02:51:37.487Z DEBUG [BEGIN] op=290.70 [vic/pkg/vsphere/vm.(*VirtualMachine).Properties:568] VM(VirtualMachine:vm-63) Properties([config runtime])
Apr 12 2018 02:51:37.487Z DEBUG op=290.70: properties: [config runtime summary.runtime.connectionState]
Apr 12 2018 02:51:37.541Z DEBUG [0xc42041afc0] write "Apr 12 2018 02:51:37.487Z ERROR op=290.70: vic/lib/portlayer/exec.(*containerBase).shutdown: shutdown error: context deadline exceeded\nvic/lib/portlayer/exec.(*containerBase).shutdown:365 shutdown\nvic/lib/apiservers/portlayer/restapi/handlers.(*ContainersHandlersImpl).CommitHandler:211 commit handle(fbcebf0f74b9bebb62799835de5bd583)\nApr 12 2018 02:51:37.487Z WARN  op=290.70: timeout (10s) waiting for ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708 to power off via SIGKILL\nApr 12 2018 02:51:37.487Z DEBUG op=290.70: Set container ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708 state: Stopping->Stopped\nApr 12 2018 02:51:37.487Z DEBUG Container(ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708) closing 0 log followers\nApr 12 2018 02:51:37.487Z DEBUG [ END ] op=290.70 [vic/lib/portlayer/exec.(*Container).stop:438] [20.018558686s] ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708\nApr 12 2018 02:51:37.487Z DEBUG [BEGIN] op=290.70 [vic/lib/portlayer/exec.(*containerBase).updates:119] ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708\nApr 12 2018 02:51:37.487Z DEBUG op=290.70: Update: for ad393e4cb5cf0005514df54c4b414d669c7813c7a3fa281a1e5271f9f9a4a708, refreshing from change version 2018-04-12T02:49:05.891063Z\nApr 12 2018 02:51:37.487Z DEBUG [BEGIN] op=290.70 [vic/pkg/vsphere/vm.(*VirtualMachine).Properties:568] VM(VirtualMachine:vm-63) Properties([config runtime])\nApr 12 2018 02:51:37.487Z DEBUG op=290.70

[rogeliosanchez]

Seen again in 2018-04-15-20-32-56 nightly, 13-1-vMotion-VCH-Appliance.
"Creating VCH exceeded time limit of 15m0s"

From vic-machine.log

Apr 16 2018 02:28:40.955Z ERROR op=2777.2: Failed to obtain IP address for client interface
Apr 16 2018 02:28:40.955Z INFO  op=2777.2: Use vic-machine inspect to see if VCH has received an IP address at a later time
Apr 16 2018 02:28:40.955Z INFO  op=2777.2:   State of all interfaces:
Apr 16 2018 02:28:40.956Z INFO  op=2777.2:     "client" IP: "waiting for IP"
Apr 16 2018 02:28:40.956Z INFO  op=2777.2:     "management" IP: "waiting for IP"
Apr 16 2018 02:28:40.956Z INFO  op=2777.2:     "bridge" IP: "waiting for IP"
Apr 16 2018 02:28:40.956Z INFO  op=2777.2:     "public" IP: "waiting for IP"
Apr 16 2018 02:28:40.956Z INFO  op=2777.2:   State of components:
Apr 16 2018 02:28:40.956Z INFO  op=2777.2:     "vicadmin": "<nil>"
Apr 16 2018 02:28:40.956Z INFO  op=2777.2:     "docker-personality": "<nil>"
Apr 16 2018 02:28:40.956Z INFO  op=2777.2:     "port-layer": "<nil>"
Apr 16 2018 02:28:40.956Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).ensureApplianceInitializes:1067] [15m0.389630416s] 
Apr 16 2018 02:28:40.956Z DEBUG [BEGIN]  [vic/lib/install/management.(*Dispatcher).CollectDiagnosticLogs:224]
Apr 16 2018 02:28:40.956Z INFO  op=2777.1: Collecting 100b0718-bf60-437b-bac4-edb2e54663d9 vpxd.log
Apr 16 2018 02:28:41.151Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).CollectDiagnosticLogs:224] [194.65496ms] 
Apr 16 2018 02:28:41.151Z INFO  op=2777.1: 	API may be slow to start - try to connect to API after a few minutes:
Apr 16 2018 02:28:41.151Z INFO  op=2777.1: 		Run vic-machine-linux inspect to find API connection command and run the command if ip address is ready
Apr 16 2018 02:28:41.151Z INFO  op=2777.1: 		If command succeeds, VCH is started. If command fails, VCH failed to install - see documentation for troubleshooting.
Apr 16 2018 02:28:41.151Z ERROR op=2777.1: vic/cmd/vic-machine/create.(*Create).Run.func3: Create error: context deadline exceeded
vic/cmd/vic-machine/create.(*Create).Run:744 Create
vic/cmd/vic-machine/common.NewOperation:27 vic-machine-linux
Apr 16 2018 02:28:41.192Z ERROR op=2777.1: --------------------
Apr 16 2018 02:28:41.193Z ERROR op=2777.1: vic-machine-linux create failed: Creating VCH exceeded time limit of 15m0s. Please increase the timeout using --timeout to accommodate for a busy vSphere target

Report
60.zip
VCH logs
vch-0-6709.zip
Vic-machine log
vic-machine.log

[AngieCris]

Looks similar to #6701

[rogeliosanchez]

VIC version:
v1.4.0-dev-0-b6c0988

Deployment details:
Nightly 6.5

5-25-OPS-User-Grant

16 2018 13:19:43.854Z ERROR op=15204.1: vic/pkg/trace.(*Operation).Err: Create error: context deadline exceeded
vic/cmd/vic-machine/create.(*Create).Run:744 Create
vic/cmd/vic-machine/common.NewOperation:27 vic-machine-linux
Apr 16 2018 13:19:43.972Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).waitForKey:769] [30m0.117746649s] guestinfo.vice..init.networks|client.assigned.IP
Apr 16 2018 13:19:43.973Z ERROR op=15204.1: vic/lib/install/management.(*Dispatcher).ensureApplianceInitializes: Create error: context deadline exceeded
vic/cmd/vic-machine/create.(*Create).Run:744 Create
vic/cmd/vic-machine/common.NewOperation:27 vic-machine-linux
Apr 16 2018 13:19:43.973Z DEBUG [BEGIN]  [vic/lib/install/management.(*Dispatcher).applianceConfiguration:756]
Apr 16 2018 13:19:43.973Z DEBUG [BEGIN] op=15204.1 [vic/pkg/vsphere/vm.(*VirtualMachine).Properties:593] VM(VirtualMachine:vm-30) Properties([config.extraConfig])
Apr 16 2018 13:19:43.973Z DEBUG op=15204.1: properties: [config.extraConfig summary.runtime.connectionState]
Apr 16 2018 13:19:43.973Z ERROR op=15204.1: vic/pkg/trace.(*Operation).Err: Create error: context deadline exceeded
vic/cmd/vic-machine/create.(*Create).Run:744 Create
vic/cmd/vic-machine/common.NewOperation:27 vic-machine-linux
Apr 16 2018 13:19:43.973Z DEBUG [ END ] op=15204.1 [vic/pkg/vsphere/vm.(*VirtualMachine).Properties:593] [592.5µs] VM(VirtualMachine:vm-30) Properties([config.extraConfig])
Apr 16 2018 13:19:43.973Z ERROR op=15204.1: Unable to get vm config: Post https://10.160.46.26/sdk: context deadline exceeded
Apr 16 2018 13:19:43.973Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).applianceConfiguration:756] [781.575µs] 
Apr 16 2018 13:19:43.973Z DEBUG op=15204.1:   State of components:
Apr 16 2018 13:19:43.973Z DEBUG op=15204.1:     "vicadmin": "waiting to launch"
Apr 16 2018 13:19:43.973Z DEBUG op=15204.1:     "docker-personality": "waiting to launch"
Apr 16 2018 13:19:43.974Z DEBUG op=15204.1:     "port-layer": "waiting to launch"
Apr 16 2018 13:19:43.974Z ERROR op=15204.1: vic/lib/install/management.(*Dispatcher).ensureApplianceInitializes: Create error: context deadline exceeded
vic/cmd/vic-machine/create.(*Create).Run:744 Create
vic/cmd/vic-machine/common.NewOperation:27 vic-machine-linux
Apr 16 2018 13:19:43.974Z DEBUG op=15204.2: [NewOperation] op=15204.2 [vic/pkg/trace.NewOperationWithLoggerFrom:243]
Apr 16 2018 13:19:43.974Z DEBUG [BEGIN]  [vic/lib/install/management.(*Dispatcher).applianceConfiguration:756]
Apr 16 2018 13:19:43.974Z DEBUG [BEGIN] op=15204.2 [vic/pkg/vsphere/vm.(*VirtualMachine).Properties:593] VM(VirtualMachine:vm-30) Properties([config.extraConfig])
Apr 16 2018 13:19:43.974Z DEBUG op=15204.2: properties: [config.extraConfig summary.runtime.connectionState]
Apr 16 2018 13:19:44.168Z DEBUG [ END ] op=15204.2 [vic/pkg/vsphere/vm.(*VirtualMachine).Properties:593] [194.058249ms] VM(VirtualMachine:vm-30) Properties([config.extraConfig])
Apr 16 2018 13:19:44.171Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).applianceConfiguration:756] [197.052277ms] 
Apr 16 2018 13:19:44.171Z INFO  op=15204.2: 
Apr 16 2018 13:19:44.171Z ERROR op=15204.2: Failed to obtain IP address for client interface
Apr 16 2018 13:19:44.171Z INFO  op=15204.2: Use vic-machine inspect to see if VCH has received an IP address at a later time
Apr 16 2018 13:19:44.171Z INFO  op=15204.2:   State of all interfaces:
Apr 16 2018 13:19:44.171Z INFO  op=15204.2:     "public" IP: "waiting for IP"
Apr 16 2018 13:19:44.171Z INFO  op=15204.2:     "client" IP: "waiting for IP"
Apr 16 2018 13:19:44.171Z INFO  op=15204.2:     "management" IP: "waiting for IP"
Apr 16 2018 13:19:44.171Z INFO  op=15204.2:     "bridge" IP: "waiting for IP"
Apr 16 2018 13:19:44.171Z INFO  op=15204.2:   State of components:
Apr 16 2018 13:19:44.171Z INFO  op=15204.2:     "vicadmin": "<nil>"
Apr 16 2018 13:19:44.171Z INFO  op=15204.2:     "docker-personality": "<nil>"
Apr 16 2018 13:19:44.172Z INFO  op=15204.2:     "port-layer": "<nil>"
Apr 16 2018 13:19:44.172Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).ensureApplianceInitializes:1067] [30m0.317464304s] 
Apr 16 2018 13:19:44.172Z DEBUG [BEGIN]  [vic/lib/install/management.(*Dispatcher).CollectDiagnosticLogs:224]
Apr 16 2018 13:19:44.172Z INFO  op=15204.1: Collecting 2508e1e9-0a52-403c-b934-d2a521599e09 vpxd.log
Apr 16 2018 13:19:44.248Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).CollectDiagnosticLogs:224] [76.41595ms] 
Apr 16 2018 13:19:44.248Z INFO  op=15204.1: 	API may be slow to start - try to connect to API after a few minutes:
Apr 16 2018 13:19:44.248Z INFO  op=15204.1: 		Run vic-machine-linux inspect to find API connection command and run the command if ip address is ready
Apr 16 2018 13:19:44.248Z INFO  op=15204.1: 		If command succeeds, VCH is started. If command fails, VCH failed to install - see documentation for troubleshooting.
Apr 16 2018 13:19:44.248Z ERROR op=15204.1: vic/cmd/vic-machine/create.(*Create).Run.func3: Create error: context deadline exceeded
vic/cmd/vic-machine/create.(*Create).Run:744 Create
vic/cmd/vic-machine/common.NewOperation:27 vic-machine-linux
Apr 16 2018 13:19:44.281Z ERROR op=15204.1: --------------------
Apr 16 2018 13:19:44.281Z ERROR op=15204.1: vic-machine-linux create failed: Creating VCH exceeded time limit of 30m0s. Please increase the timeout using --timeout to accommodate for a busy vSphere target

Vic-machine
vic-machine.log

VCH logs
vch-0-5437.zip

Nightly Summary
65.zip

Link to logs:
https://storage.cloud.google.com/vic-ci-logs/vic_nightly_logs_2018-04-16-03-54-06.zip?authuser=1

[rogeliosanchez]

VIC Version
v1.4.0-dev-0-b6c0988

Deployment Details
Nightly 6.7 - 2018-04-16

23-1-Future-ESXi-Install --> Install VIC appliance

vic/cmd/vic-machine/create.(*Create).Run:744 Create
vic/cmd/vic-machine/common.NewOperation:27 vic-machine-linux
Apr 16 2018 14:59:32.775Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).waitForKey:769] [30m0.15496077s] guestinfo.vice..init.networks|client.assigned.IP
Apr 16 2018 14:59:32.775Z ERROR op=622.1: vic/lib/install/management.(*Dispatcher).ensureApplianceInitializes: Create error: context deadline exceeded
vic/cmd/vic-machine/create.(*Create).Run:744 Create
vic/cmd/vic-machine/common.NewOperation:27 vic-machine-linux
Apr 16 2018 14:59:32.775Z DEBUG [BEGIN]  [vic/lib/install/management.(*Dispatcher).applianceConfiguration:756]
Apr 16 2018 14:59:32.775Z DEBUG [BEGIN] op=622.1 [vic/pkg/vsphere/vm.(*VirtualMachine).Properties:593] VM(VirtualMachine:1) Properties([config.extraConfig])
Apr 16 2018 14:59:32.775Z DEBUG op=622.1: properties: [config.extraConfig summary.runtime.connectionState]
Apr 16 2018 14:59:32.775Z ERROR op=622.1: vic/pkg/trace.(*Operation).Err: Create error: context deadline exceeded
vic/cmd/vic-machine/create.(*Create).Run:744 Create
vic/cmd/vic-machine/common.NewOperation:27 vic-machine-linux
Apr 16 2018 14:59:32.775Z DEBUG [ END ] op=622.1 [vic/pkg/vsphere/vm.(*VirtualMachine).Properties:593] [459.937µs] VM(VirtualMachine:1) Properties([config.extraConfig])
Apr 16 2018 14:59:32.775Z ERROR op=622.1: Unable to get vm config: Post https://10.192.168.170/sdk: context deadline exceeded
Apr 16 2018 14:59:32.775Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).applianceConfiguration:756] [626.667µs] 
Apr 16 2018 14:59:32.775Z DEBUG op=622.1:   State of components:
Apr 16 2018 14:59:32.776Z DEBUG op=622.1:     "vicadmin": "waiting to launch"
Apr 16 2018 14:59:32.776Z DEBUG op=622.1:     "docker-personality": "waiting to launch"
Apr 16 2018 14:59:32.776Z DEBUG op=622.1:     "port-layer": "waiting to launch"
Apr 16 2018 14:59:32.776Z ERROR op=622.1: vic/lib/install/management.(*Dispatcher).ensureApplianceInitializes: Create error: context deadline exceeded
vic/cmd/vic-machine/create.(*Create).Run:744 Create
vic/cmd/vic-machine/common.NewOperation:27 vic-machine-linux
Apr 16 2018 14:59:32.776Z DEBUG op=622.2: [NewOperation] op=622.2 [vic/pkg/trace.NewOperationWithLoggerFrom:243]
Apr 16 2018 14:59:32.776Z DEBUG [BEGIN]  [vic/lib/install/management.(*Dispatcher).applianceConfiguration:756]
Apr 16 2018 14:59:32.776Z DEBUG [BEGIN] op=622.2 [vic/pkg/vsphere/vm.(*VirtualMachine).Properties:593] VM(VirtualMachine:1) Properties([config.extraConfig])
Apr 16 2018 14:59:32.776Z DEBUG op=622.2: properties: [config.extraConfig summary.runtime.connectionState]
Apr 16 2018 14:59:33.039Z DEBUG [ END ] op=622.2 [vic/pkg/vsphere/vm.(*VirtualMachine).Properties:593] [263.687915ms] VM(VirtualMachine:1) Properties([config.extraConfig])
Apr 16 2018 14:59:33.042Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).applianceConfiguration:756] [266.702448ms] 
Apr 16 2018 14:59:33.042Z INFO  op=622.2: 
Apr 16 2018 14:59:33.043Z ERROR op=622.2: Failed to obtain IP address for client interface
Apr 16 2018 14:59:33.043Z INFO  op=622.2: Use vic-machine inspect to see if VCH has received an IP address at a later time
Apr 16 2018 14:59:33.043Z INFO  op=622.2:   State of all interfaces:
Apr 16 2018 14:59:33.043Z INFO  op=622.2:     "public" IP: "waiting for IP"
Apr 16 2018 14:59:33.043Z INFO  op=622.2:     "client" IP: "waiting for IP"
Apr 16 2018 14:59:33.043Z INFO  op=622.2:     "management" IP: "waiting for IP"
Apr 16 2018 14:59:33.043Z INFO  op=622.2:     "bridge" IP: "waiting for IP"
Apr 16 2018 14:59:33.043Z INFO  op=622.2:   State of components:
Apr 16 2018 14:59:33.043Z INFO  op=622.2:     "docker-personality": "<nil>"
Apr 16 2018 14:59:33.043Z INFO  op=622.2:     "port-layer": "<nil>"
Apr 16 2018 14:59:33.043Z INFO  op=622.2:     "vicadmin": "<nil>"
Apr 16 2018 14:59:33.043Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).ensureApplianceInitializes:1067] [30m0.423665402s] 
Apr 16 2018 14:59:33.043Z DEBUG [BEGIN]  [vic/lib/install/management.(*Dispatcher).CollectDiagnosticLogs:224]
Apr 16 2018 14:59:33.043Z INFO  op=622.1: Collecting ha-host hostd.log
Apr 16 2018 14:59:33.143Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).CollectDiagnosticLogs:224] [99.686261ms] 
Apr 16 2018 14:59:33.143Z INFO  op=622.1: 	API may be slow to start - try to connect to API after a few minutes:
Apr 16 2018 14:59:33.143Z INFO  op=622.1: 		Run vic-machine-linux inspect to find API connection command and run the command if ip address is ready
Apr 16 2018 14:59:33.143Z INFO  op=622.1: 		If command succeeds, VCH is started. If command fails, VCH failed to install - see documentation for troubleshooting.
Apr 16 2018 14:59:33.143Z ERROR op=622.1: vic/cmd/vic-machine/create.(*Create).Run.func3: Create error: context deadline exceeded
vic/cmd/vic-machine/create.(*Create).Run:744 Create
vic/cmd/vic-machine/common.NewOperation:27 vic-machine-linux
Apr 16 2018 14:59:33.182Z ERROR op=622.1: --------------------
Apr 16 2018 14:59:33.182Z ERROR op=622.1: vic-machine-linux create failed: Creating VCH exceeded time limit of 30m0s. Please increase the timeout using --timeout to accommodate for a busy vSphere target

Vic Machine
vic-machine.log

VCH Logs
vch-0-9507.zip

Nightly Summary
67.zip

Link to logs
https://storage.cloud.google.com/vic-ci-logs/vic_nightly_logs_2018-04-16-09-16-12.zip?authuser=1

[rogeliosanchez]

Seen in Nightly 6.7 - 2018-04-17

VIC Version
v1.4.0-rc1-0-86968ff

5-21-Datastore-Path --> DS Scheme Specified in Volume Store; should contain "installer completed successfully"
"vic-machine-linux create failed: Creating VCH exceeded time limit of 3m0s. Please increase the timeout using --timeout to accommodate for a busy vSphere target" ' does not contain 'Installer completed successfully'

vic/cmd/vic-machine/create.(*Create).Run:744 Create
vic/cmd/vic-machine/common.NewOperation:27 vic-machine-linux
Apr 17 2018 14:58:34.104Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).waitForKey:769] [3m0.137724927s] guestinfo.vice..init.networks|client.assigned.IP
Apr 17 2018 14:58:34.104Z ERROR op=8515.1: vic/lib/install/management.(*Dispatcher).ensureApplianceInitializes: Create error: context deadline exceeded
vic/cmd/vic-machine/create.(*Create).Run:744 Create
vic/cmd/vic-machine/common.NewOperation:27 vic-machine-linux
Apr 17 2018 14:58:34.104Z DEBUG [BEGIN]  [vic/lib/install/management.(*Dispatcher).applianceConfiguration:756]
Apr 17 2018 14:58:34.104Z DEBUG [BEGIN] op=8515.1 [vic/pkg/vsphere/vm.(*VirtualMachine).Properties:601] VM(VirtualMachine:2) Properties([config.extraConfig])
Apr 17 2018 14:58:34.104Z DEBUG op=8515.1: properties: [config.extraConfig summary.runtime.connectionState]
Apr 17 2018 14:58:34.104Z ERROR op=8515.1: vic/pkg/trace.(*Operation).Err: Create error: context deadline exceeded
vic/cmd/vic-machine/create.(*Create).Run:744 Create
vic/cmd/vic-machine/common.NewOperation:27 vic-machine-linux
Apr 17 2018 14:58:34.105Z DEBUG [ END ] op=8515.1 [vic/pkg/vsphere/vm.(*VirtualMachine).Properties:601] [502.282µs] VM(VirtualMachine:2) Properties([config.extraConfig])
Apr 17 2018 14:58:34.105Z ERROR op=8515.1: Unable to get vm config: Post https://10.192.106.55/sdk: context deadline exceeded
Apr 17 2018 14:58:34.105Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).applianceConfiguration:756] [649.466µs] 
Apr 17 2018 14:58:34.105Z DEBUG op=8515.1:   State of components:
Apr 17 2018 14:58:34.105Z DEBUG op=8515.1:     "vicadmin": "waiting to launch"
Apr 17 2018 14:58:34.105Z DEBUG op=8515.1:     "docker-personality": "waiting to launch"
Apr 17 2018 14:58:34.105Z DEBUG op=8515.1:     "port-layer": "waiting to launch"
Apr 17 2018 14:58:34.105Z ERROR op=8515.1: vic/lib/install/management.(*Dispatcher).ensureApplianceInitializes: Create error: context deadline exceeded
vic/cmd/vic-machine/create.(*Create).Run:744 Create
vic/cmd/vic-machine/common.NewOperation:27 vic-machine-linux
Apr 17 2018 14:58:34.105Z DEBUG op=8515.2: [NewOperation] op=8515.2 [vic/pkg/trace.NewOperationWithLoggerFrom:243]
Apr 17 2018 14:58:34.105Z DEBUG [BEGIN]  [vic/lib/install/management.(*Dispatcher).applianceConfiguration:756]
Apr 17 2018 14:58:34.105Z DEBUG [BEGIN] op=8515.2 [vic/pkg/vsphere/vm.(*VirtualMachine).Properties:601] VM(VirtualMachine:2) Properties([config.extraConfig])
Apr 17 2018 14:58:34.105Z DEBUG op=8515.2: properties: [config.extraConfig summary.runtime.connectionState]
Apr 17 2018 14:58:34.371Z DEBUG [ END ] op=8515.2 [vic/pkg/vsphere/vm.(*VirtualMachine).Properties:601] [265.904608ms] VM(VirtualMachine:2) Properties([config.extraConfig])
Apr 17 2018 14:58:34.373Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).applianceConfiguration:756] [267.845136ms] 
Apr 17 2018 14:58:34.373Z INFO  op=8515.2: 
Apr 17 2018 14:58:34.373Z ERROR op=8515.2: Failed to obtain IP address for client interface
Apr 17 2018 14:58:34.373Z INFO  op=8515.2: Use vic-machine inspect to see if VCH has received an IP address at a later time
Apr 17 2018 14:58:34.373Z INFO  op=8515.2:   State of all interfaces:
Apr 17 2018 14:58:34.373Z INFO  op=8515.2:     "bridge" IP: "waiting for IP"
Apr 17 2018 14:58:34.373Z INFO  op=8515.2:     "public" IP: "waiting for IP"
Apr 17 2018 14:58:34.374Z INFO  op=8515.2:     "client" IP: "waiting for IP"
Apr 17 2018 14:58:34.374Z INFO  op=8515.2:     "management" IP: "waiting for IP"
Apr 17 2018 14:58:34.374Z INFO  op=8515.2:   State of components:
Apr 17 2018 14:58:34.374Z INFO  op=8515.2:     "docker-personality": "<nil>"
Apr 17 2018 14:58:34.374Z INFO  op=8515.2:     "port-layer": "<nil>"
Apr 17 2018 14:58:34.374Z INFO  op=8515.2:     "vicadmin": "<nil>"
Apr 17 2018 14:58:34.374Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).ensureApplianceInitializes:1067] [3m0.408097309s] 
Apr 17 2018 14:58:34.374Z DEBUG [BEGIN]  [vic/lib/install/management.(*Dispatcher).CollectDiagnosticLogs:224]
Apr 17 2018 14:58:34.374Z INFO  op=8515.1: Collecting ha-host hostd.log
Apr 17 2018 14:58:34.523Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).CollectDiagnosticLogs:224] [148.994625ms] 
Apr 17 2018 14:58:34.523Z INFO  op=8515.1: 	API may be slow to start - try to connect to API after a few minutes:
Apr 17 2018 14:58:34.523Z INFO  op=8515.1: 		Run vic-machine-linux inspect to find API connection command and run the command if ip address is ready
Apr 17 2018 14:58:34.523Z INFO  op=8515.1: 		If command succeeds, VCH is started. If command fails, VCH failed to install - see documentation for troubleshooting.
Apr 17 2018 14:58:34.523Z ERROR op=8515.1: vic/cmd/vic-machine/create.(*Create).Run.func3: Create error: context deadline exceeded
vic/cmd/vic-machine/create.(*Create).Run:744 Create
vic/cmd/vic-machine/common.NewOperation:27 vic-machine-linux
Apr 17 2018 14:58:34.559Z ERROR op=8515.1: --------------------
Apr 17 2018 14:58:34.559Z ERROR op=8515.1: vic-machine-linux create failed: Creating VCH exceeded time limit of 3m0s. Please increase the timeout using --timeout to accommodate for a busy vSphere target

Vic Machine
vic-machine.log

VCH logs
vch-0-2919.zip

Nightly Summary
67.zip

Link to logs
https://storage.cloud.google.com/vic-ci-logs/vic_nightly_logs_2018-04-17-08-04-42.zip?authuser=1

More logs
Suites.Group5-Functional-Tests.5-21-Datastore-Path-VCH-0-2919-container-logs.zip

[rogeliosanchez]

Seen in Nightly 6.5 - 2018-04-20

VIC Version
v1.5.0-dev-18481-023de08

5-10-Multiple-Datacenter
"vic-machine-linux create failed: Creating VCH exceeded time limit of 30m0s. Please increase the timeout using --timeout to accommodate for a busy vSphere target\n" ' does not contain 'Installer completed successfully'

Apr 20 2018 07:46:47.166Z ERROR op=5113.1: vic/pkg/trace.(*Operation).Err: Create error: context deadline exceeded
vic/cmd/vic-machine/create.(*Create).Run:744 Create
vic/cmd/vic-machine/common.NewOperation:27 vic-machine-linux
Apr 20 2018 07:46:47.302Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).waitForKey:769] [30m0.135272398s] guestinfo.vice..init.networks|client.assigned.IP
Apr 20 2018 07:46:47.302Z ERROR op=5113.1: vic/lib/install/management.(*Dispatcher).ensureApplianceInitializes: Create error: context deadline exceeded
vic/cmd/vic-machine/create.(*Create).Run:744 Create
vic/cmd/vic-machine/common.NewOperation:27 vic-machine-linux
Apr 20 2018 07:46:47.302Z DEBUG [BEGIN]  [vic/lib/install/management.(*Dispatcher).applianceConfiguration:756]
Apr 20 2018 07:46:47.302Z DEBUG [BEGIN] op=5113.1 [vic/pkg/vsphere/vm.(*VirtualMachine).Properties:601] VM(VirtualMachine:vm-64) Properties([config.extraConfig])
Apr 20 2018 07:46:47.302Z DEBUG op=5113.1: properties: [config.extraConfig summary.runtime.connectionState]
Apr 20 2018 07:46:47.302Z ERROR op=5113.1: vic/pkg/trace.(*Operation).Err: Create error: context deadline exceeded
vic/cmd/vic-machine/create.(*Create).Run:744 Create
vic/cmd/vic-machine/common.NewOperation:27 vic-machine-linux
Apr 20 2018 07:46:47.303Z DEBUG [ END ] op=5113.1 [vic/pkg/vsphere/vm.(*VirtualMachine).Properties:601] [462.054µs] VM(VirtualMachine:vm-64) Properties([config.extraConfig])
Apr 20 2018 07:46:47.303Z ERROR op=5113.1: Unable to get vm config: Post https://10.160.127.75/sdk: context deadline exceeded
Apr 20 2018 07:46:47.303Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).applianceConfiguration:756] [628.285µs] 
Apr 20 2018 07:46:47.303Z DEBUG op=5113.1:   State of components:
Apr 20 2018 07:46:47.303Z DEBUG op=5113.1:     "vicadmin": "waiting to launch"
Apr 20 2018 07:46:47.303Z DEBUG op=5113.1:     "docker-personality": "waiting to launch"
Apr 20 2018 07:46:47.303Z DEBUG op=5113.1:     "port-layer": "waiting to launch"
Apr 20 2018 07:46:47.303Z ERROR op=5113.1: vic/lib/install/management.(*Dispatcher).ensureApplianceInitializes: Create error: context deadline exceeded
vic/cmd/vic-machine/create.(*Create).Run:744 Create
vic/cmd/vic-machine/common.NewOperation:27 vic-machine-linux
Apr 20 2018 07:46:47.303Z DEBUG op=5113.2: [NewOperation] op=5113.2 [vic/pkg/trace.NewOperationWithLoggerFrom:243]
Apr 20 2018 07:46:47.303Z DEBUG [BEGIN]  [vic/lib/install/management.(*Dispatcher).applianceConfiguration:756]
Apr 20 2018 07:46:47.303Z DEBUG [BEGIN] op=5113.2 [vic/pkg/vsphere/vm.(*VirtualMachine).Properties:601] VM(VirtualMachine:vm-64) Properties([config.extraConfig])
Apr 20 2018 07:46:47.303Z DEBUG op=5113.2: properties: [config.extraConfig summary.runtime.connectionState]
Apr 20 2018 07:46:47.485Z DEBUG [ END ] op=5113.2 [vic/pkg/vsphere/vm.(*VirtualMachine).Properties:601] [182.321011ms] VM(VirtualMachine:vm-64) Properties([config.extraConfig])
Apr 20 2018 07:46:47.488Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).applianceConfiguration:756] [184.769633ms] 
Apr 20 2018 07:46:47.488Z INFO  op=5113.2: 
Apr 20 2018 07:46:47.488Z ERROR op=5113.2: Failed to obtain IP address for client interface
Apr 20 2018 07:46:47.488Z INFO  op=5113.2: Use vic-machine inspect to see if VCH has received an IP address at a later time
Apr 20 2018 07:46:47.488Z INFO  op=5113.2:   State of all interfaces:
Apr 20 2018 07:46:47.488Z INFO  op=5113.2:     "public" IP: "waiting for IP"
Apr 20 2018 07:46:47.488Z INFO  op=5113.2:     "client" IP: "waiting for IP"
Apr 20 2018 07:46:47.488Z INFO  op=5113.2:     "management" IP: "waiting for IP"
Apr 20 2018 07:46:47.488Z INFO  op=5113.2:     "bridge" IP: "waiting for IP"
Apr 20 2018 07:46:47.488Z INFO  op=5113.2:   State of components:
Apr 20 2018 07:46:47.488Z INFO  op=5113.2:     "vicadmin": "<nil>"
Apr 20 2018 07:46:47.488Z INFO  op=5113.2:     "docker-personality": "<nil>"
Apr 20 2018 07:46:47.488Z INFO  op=5113.2:     "port-layer": "<nil>"
Apr 20 2018 07:46:47.488Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).ensureApplianceInitializes:1067] [30m0.322474372s] 
Apr 20 2018 07:46:47.489Z DEBUG [BEGIN]  [vic/lib/install/management.(*Dispatcher).CollectDiagnosticLogs:224]
Apr 20 2018 07:46:47.489Z INFO  op=5113.1: Collecting 10bd562d-6b6b-4695-a63d-7d3eb1cc26ae vpxd.log
Apr 20 2018 07:46:47.578Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).CollectDiagnosticLogs:224] [89.838972ms] 
Apr 20 2018 07:46:47.578Z INFO  op=5113.1: 	API may be slow to start - try to connect to API after a few minutes:
Apr 20 2018 07:46:47.579Z INFO  op=5113.1: 		Run vic-machine-linux inspect to find API connection command and run the command if ip address is ready
Apr 20 2018 07:46:47.579Z INFO  op=5113.1: 		If command succeeds, VCH is started. If command fails, VCH failed to install - see documentation for troubleshooting.
Apr 20 2018 07:46:47.579Z ERROR op=5113.1: vic/cmd/vic-machine/create.(*Create).Run.func3: Create error: context deadline exceeded
vic/cmd/vic-machine/create.(*Create).Run:744 Create
vic/cmd/vic-machine/common.NewOperation:27 vic-machine-linux
Apr 20 2018 07:46:47.610Z ERROR op=5113.1: --------------------
Apr 20 2018 07:46:47.611Z ERROR op=5113.1: vic-machine-linux create failed: Creating VCH exceeded time limit of 30m0s. Please increase the timeout using --timeout to accommodate for a busy vSphere target

Vic machine
vic-machine.log

Nightly summary
65.zip

Link to logs
https://storage.cloud.google.com/vic-ci-logs/vic_nightly_logs_2018-04-20-01-04-51.zip?authuser=1

[rogeliosanchez]

Seen in Nightly 6.5 - 2018-04-20

VIC Version
v1.5.0-dev-18481-023de08

5-21-Datastore-Path
Space in Path with Scheme
"vic-machine-linux create failed: Creating VCH exceeded time limit of 3m0s. Please increase the timeout using --timeout to accommodate for a busy vSphere target\n" ' does not contain 'Installer completed successfully'

Apr 20 2018 09:21:48.232Z INFO  op=11193.1: Waiting for major appliance components to launch
Apr 20 2018 09:21:48.233Z DEBUG [BEGIN]  [vic/lib/install/management.(*Dispatcher).waitForKey:769] guestinfo.vice..init.sessions|vicadmin.started
Apr 20 2018 09:21:48.548Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).waitForKey:769] [315.133687ms] guestinfo.vice..init.sessions|vicadmin.started
Apr 20 2018 09:21:48.548Z DEBUG [BEGIN]  [vic/lib/install/management.(*Dispatcher).waitForKey:769] guestinfo.vice..init.sessions|docker-personality.started
Apr 20 2018 09:21:48.922Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).waitForKey:769] [374.321706ms] guestinfo.vice..init.sessions|docker-personality.started
Apr 20 2018 09:21:48.922Z DEBUG [BEGIN]  [vic/lib/install/management.(*Dispatcher).waitForKey:769] guestinfo.vice..init.sessions|port-layer.started
Apr 20 2018 09:21:49.079Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).waitForKey:769] [156.120219ms] guestinfo.vice..init.sessions|port-layer.started
Apr 20 2018 09:21:49.079Z DEBUG [BEGIN]  [vic/lib/install/management.(*Dispatcher).applianceConfiguration:756]
Apr 20 2018 09:21:49.079Z DEBUG [BEGIN] op=11193.1 [vic/pkg/vsphere/vm.(*VirtualMachine).Properties:601] VM(VirtualMachine:4) Properties([config.extraConfig])
Apr 20 2018 09:21:49.079Z DEBUG op=11193.1: properties: [config.extraConfig summary.runtime.connectionState]
Apr 20 2018 09:21:49.130Z DEBUG [ END ] op=11193.1 [vic/pkg/vsphere/vm.(*VirtualMachine).Properties:601] [50.758985ms] VM(VirtualMachine:4) Properties([config.extraConfig])
Apr 20 2018 09:21:49.131Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).applianceConfiguration:756] [52.712907ms] 
Apr 20 2018 09:21:49.131Z DEBUG op=11193.1:   State of components:
Apr 20 2018 09:21:49.132Z DEBUG op=11193.1:     "vicadmin": "started successfully"
Apr 20 2018 09:21:49.132Z DEBUG op=11193.1:     "docker-personality": "started successfully"
Apr 20 2018 09:21:49.132Z DEBUG op=11193.1:     "port-layer": "started successfully"
Apr 20 2018 09:21:49.132Z INFO  op=11193.1: Obtained IP address for client interface: "10.161.22.70"
Apr 20 2018 09:21:49.132Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).ensureApplianceInitializes:1067] [20.286569876s] 
Apr 20 2018 09:21:49.132Z INFO  op=11193.1: Checking VCH connectivity with vSphere target
Apr 20 2018 09:21:49.690Z INFO  op=11193.1: vSphere API Test: https://10.161.4.223 vSphere API target responds as expected
Apr 20 2018 09:21:49.690Z DEBUG [BEGIN]  [vic/lib/install/management.(*Dispatcher).CheckDockerAPI:836]
Apr 20 2018 09:21:49.690Z DEBUG op=11193.1: Docker API endpoint: https://10.161.22.70:2376/info
Apr 20 2018 09:23:56.958Z DEBUG op=11193.1: Error was expected to be ECONNREFUSED: 0x6e
Apr 20 2018 09:23:56.958Z DEBUG op=11193.1: Components not yet initialized, retrying
Apr 20 2018 09:24:28.846Z ERROR op=11193.1: vic/pkg/trace.(*Operation).Err: Create error: context deadline exceeded
vic/cmd/vic-machine/create.(*Create).Run:744 Create
vic/cmd/vic-machine/common.NewOperation:27 vic-machine-linux
Apr 20 2018 09:24:28.846Z DEBUG op=11193.1: Unhandled net error type: context.deadlineExceededError{}
Apr 20 2018 09:24:28.846Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).CheckDockerAPI:836] [2m39.155778652s] 
Apr 20 2018 09:24:28.846Z INFO  op=11193.1: Docker API endpoint check failed: context deadline exceeded
Apr 20 2018 09:24:28.846Z DEBUG [BEGIN]  [vic/lib/install/management.(*Dispatcher).CollectDiagnosticLogs:224]
Apr 20 2018 09:24:28.846Z INFO  op=11193.1: Collecting ha-host hostd.log
Apr 20 2018 09:24:29.368Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).CollectDiagnosticLogs:224] [521.910341ms] 
Apr 20 2018 09:24:29.368Z INFO  op=11193.1: 	API may be slow to start - try to connect to API after a few minutes:
Apr 20 2018 09:24:29.368Z INFO  op=11193.1: 		Run command: docker -H 10.161.22.70:2376 --tls info
Apr 20 2018 09:24:29.368Z INFO  op=11193.1: 		If command succeeds, VCH is started. If command fails, VCH failed to install - see documentation for troubleshooting.
Apr 20 2018 09:24:29.368Z ERROR op=11193.1: vic/cmd/vic-machine/create.(*Create).Run.func3: Create error: context deadline exceeded
vic/cmd/vic-machine/create.(*Create).Run:744 Create
vic/cmd/vic-machine/common.NewOperation:27 vic-machine-linux
Apr 20 2018 09:24:29.403Z ERROR op=11193.1: --------------------
Apr 20 2018 09:24:29.403Z ERROR op=11193.1: vic-machine-linux create failed: Creating VCH exceeded time limit of 3m0s. Please increase the timeout using --timeout to accommodate for a busy vSphere target

Vic machine
vic-machine.log

Nightly Summary
65.zip

Link to logs
https://storage.cloud.google.com/vic-ci-logs/vic_nightly_logs_2018-04-20-01-04-51.zip?authuser=1