Nightly 6.0 - 2018-04-18 - 5-25-OPS-User-Grant: Cannot init ops-user permissions

[rogeliosanchez]

VIC version:
v1.5.0-dev-18481-023de08

5-25-OPS-User-Grant: granted ops-user perms work after upgrade
"vic-machine-linux create failed: Cannot init ops-user permissions, failure: ServerFaultCode: The operation is not supported on the object.. Exiting...\n" ' does not contain 'Installer completed successfully'

Apr 19 2018 03:33:07.724Z DEBUG op=13146.1: vm folder name: "VCH-0-5474"
Apr 19 2018 03:33:07.724Z DEBUG op=13146.1: vm inventory path: "/datacenter1/vm/VCH-0-5474"
Apr 19 2018 03:33:07.724Z DEBUG [BEGIN]  [vic/lib/install/management.(*Dispatcher).reconfigureApplianceSpec:710]
Apr 19 2018 03:33:07.724Z DEBUG [BEGIN]  [vic/lib/install/management.(*Dispatcher).configIso:404]
Apr 19 2018 03:33:07.756Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).configIso:404] [32.369771ms] 
Apr 19 2018 03:33:07.756Z DEBUG [BEGIN]  [vic/lib/install/management.(*Dispatcher).configLogging:430]
Apr 19 2018 03:33:09.135Z DEBUG [BEGIN] op=13146.1 [vic/pkg/vsphere/vm.(*VirtualMachine).Properties:519] VM(VirtualMachine:vm-40) Properties([config.files.vmPathName])
Apr 19 2018 03:33:09.135Z DEBUG op=13146.1: properties: [config.files.vmPathName summary.runtime.connectionState]
Apr 19 2018 03:33:09.166Z DEBUG [ END ] op=13146.1 [vic/pkg/vsphere/vm.(*VirtualMachine).Properties:519] [30.505299ms] VM(VirtualMachine:vm-40) Properties([config.files.vmPathName])
Apr 19 2018 03:33:09.166Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).configLogging:430] [1.409380358s] 
Apr 19 2018 03:33:09.166Z DEBUG op=13146.1: generating new config secret key
Apr 19 2018 03:33:09.168Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).reconfigureApplianceSpec:710] [1.44415763s] 
Apr 19 2018 03:33:09.696Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).createAppliance:487] [2.998625198s] 
Apr 19 2018 03:33:09.697Z DEBUG [BEGIN] op=13146.1 [vic/lib/install/management.(*Dispatcher).uploadImages:115]
Apr 19 2018 03:33:09.697Z INFO  op=13146.1: Uploading images for container
Apr 19 2018 03:33:09.697Z INFO  op=13146.1: 	"./vic/bootstrap.iso"
Apr 19 2018 03:33:09.697Z DEBUG [BEGIN]  [vic/pkg/retry.DoWithConfig:73]
Apr 19 2018 03:33:09.697Z INFO  op=13146.1: 	"./vic/appliance.iso"
Apr 19 2018 03:33:09.697Z DEBUG [BEGIN]  [vic/pkg/retry.DoWithConfig:73]
Apr 19 2018 03:33:21.489Z DEBUG [ END ]  [vic/pkg/retry.DoWithConfig:73] [11.791410955s] 
Apr 19 2018 03:33:23.142Z DEBUG [ END ]  [vic/pkg/retry.DoWithConfig:73] [13.444939587s] 
Apr 19 2018 03:33:23.142Z DEBUG [ END ] op=13146.1 [vic/lib/install/management.(*Dispatcher).uploadImages:115] [13.445790371s] 
Apr 19 2018 03:33:23.274Z DEBUG [ END ] op=13146.1 [vic/lib/install/management.(*Dispatcher).CreateVCH:42] [16.91484336s] VCH-0-5474
Apr 19 2018 03:33:23.274Z DEBUG [BEGIN]  [vic/lib/install/management.(*Dispatcher).CollectDiagnosticLogs:224]
Apr 19 2018 03:33:23.274Z INFO  op=13146.1: Collecting 129e7188-815a-4ae0-9b34-587fc0ed385f vpxd.log
Apr 19 2018 03:33:23.344Z DEBUG [ END ]  [vic/lib/install/management.(*Dispatcher).CollectDiagnosticLogs:224] [69.931827ms] 
Apr 19 2018 03:33:23.344Z ERROR op=13146.1: Cannot init ops-user permissions, failure: ServerFaultCode: The operation is not supported on the object.. Exiting...
Apr 19 2018 03:33:23.376Z ERROR op=13146.1: --------------------
Apr 19 2018 03:33:23.377Z ERROR op=13146.1: vic-machine-linux create failed: Cannot init ops-user permissions, failure: ServerFaultCode: The operation is not supported on the object.. Exiting...

Vic-machine
vic-machine.log

Nightly Summary
60.zip

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

[zjs]

During the 2018-04-19-05-47-22 run, this was the only test in 5-25-OPS-User-Grant to fail.

time="2018-04-19T13:26:22Z" level=info msg="### Upgrading VCH ####" 
time="2018-04-19T13:26:22Z" level=debug msg="Accepting host \"10.192.121.134\" thumbprint 8A:2D:8E:A5:AD:E3:3B:FF:34:90:AC:C0:61:C8:A2:A1:74:C0:C9:AC" 
time="2018-04-19T13:26:22Z" level=debug msg="Creating VMOMI session with thumbprint 8A:2D:8E:A5:AD:E3:3B:FF:34:90:AC:C0:61:C8:A2:A1:74:C0:C9:AC" 
time="2018-04-19T13:26:22Z" level=debug msg="Session Environment Info: " API Type=VirtualCenter API Version=6.7 Build=8126527 Name="VMware vCenter Server" OS Type=linux-x64 Product ID=vpx UUID=e7fe75e4-7ce3-41e2-b838-866f8e7943eb Vendor="VMware, Inc." Version=6.7.0 
time="2018-04-19T13:26:22Z" level=debug msg="vSphere resource cache populating..." 
time="2018-04-19T13:26:23Z" level=debug msg="Cached dc: datacenter1" 
time="2018-04-19T13:26:23Z" level=debug msg="Cached cluster: cls1" 
time="2018-04-19T13:26:23Z" level=debug msg="Cached pool: " 
time="2018-04-19T13:26:23Z" level=debug msg="Cached folders: datacenter1" 
time="2018-04-19T13:26:23Z" level=debug msg="Error count populating vSphere cache: (1)" 
time="2018-04-19T13:26:23Z" level=debug msg="new validator Session.Populate: Failure finding ds (): default datastore resolves to multiple instances, please specify" 
time="2018-04-19T13:26:23Z" level=info msg="Validating target" 
time="2018-04-19T13:26:24Z" level=debug msg="properties: [config.extraConfig summary.runtime.connectionState]" 
time="2018-04-19T13:26:24Z" level=debug msg="Cannot find image stores from configuration; attempting to find from vm datastore" 
time="2018-04-19T13:26:24Z" level=debug msg="properties: [datastore summary.runtime.connectionState]" 
time="2018-04-19T13:26:24Z" level=info 
time="2018-04-19T13:26:24Z" level=info msg="VCH ID: VirtualMachine:vm-40" 
time="2018-04-19T13:26:24Z" level=debug msg="properties: [config.extraConfig summary.runtime.connectionState]" 
time="2018-04-19T13:26:25Z" level=debug msg="properties: [config.extraConfig summary.runtime.connectionState]" 
time="2018-04-19T13:26:25Z" level=debug msg="No need to migrate configuration for \"VirtualMachine:vm-40\"" 
time="2018-04-19T13:26:25Z" level=debug msg="Cannot find image stores from configuration; attempting to find from vm datastore" 
time="2018-04-19T13:26:25Z" level=debug msg="properties: [datastore summary.runtime.connectionState]" 
time="2018-04-19T13:26:25Z" level=debug msg="properties: [config.files.vmPathName summary.runtime.connectionState]" 
time="2018-04-19T13:26:25Z" level=info msg="Creating directory [datastore1] VCH-0-9565" 
time="2018-04-19T13:26:25Z" level=info msg="Datastore path is [datastore1] VCH-0-9565" 
time="2018-04-19T13:26:25Z" level=debug msg="Datacenter: \"datacenter1\", Cluster: \"ClusterComputeResource:domain-c7\", Resource Pool: \"/datacenter1/host/cls1/Resources\"" 
time="2018-04-19T13:26:25Z" level=debug msg="properties: [config.files.vmPathName summary.runtime.connectionState]" 
time="2018-04-19T13:26:25Z" level=info msg="Uploading images for container" 
time="2018-04-19T13:26:25Z" level=debug msg="Checking if file already exists: VCH-0-9565/V1.5.0-DEV-18535-634E0A5-appliance.iso" 
time="2018-04-19T13:26:26Z" level=debug msg="File not found. Nothing to do." 
time="2018-04-19T13:26:26Z" level=info msg="Uploading appliance.iso as V1.5.0-DEV-18535-634E0A5-appliance.iso" 
time="2018-04-19T13:26:32Z" level=debug msg="Checking if file already exists: VCH-0-9565/V1.5.0-DEV-18535-634E0A5-bootstrap.iso" 
time="2018-04-19T13:26:33Z" level=debug msg="File not found. Nothing to do." 
time="2018-04-19T13:26:33Z" level=info msg="Uploading bootstrap.iso as V1.5.0-DEV-18535-634E0A5-bootstrap.iso" 
time="2018-04-19T13:26:35Z" level=debug msg="VCH resource settings are not changed" 
time="2018-04-19T13:26:35Z" level=debug msg="properties: [snapshot summary.runtime.connectionState]" 
time="2018-04-19T13:26:36Z" level=info msg="Switching appliance iso to [datastore1] VCH-0-9565/V1.5.0-DEV-18535-634E0A5-appliance.iso" 
time="2018-04-19T13:26:36Z" level=debug msg="generating new config secret key" 
time="2018-04-19T13:26:36Z" level=debug msg="properties: [config.extraConfig summary.runtime.connectionState]" 
time="2018-04-19T13:26:37Z" level=info msg="Setting VM configuration" 
time="2018-04-19T13:26:38Z" level=debug msg="vm compute resource: " 
time="2018-04-19T13:26:38Z" level=debug msg="VirtualMachine:vm-40 resides in a multi-host cluster: true" 
time="2018-04-19T13:26:38Z" level=debug msg="DRS enabled: true" 
time="2018-04-19T13:26:39Z" level=info msg="Waiting for IP information" 
time="2018-04-19T13:26:39Z" level=info msg="Waiting for major appliance components to launch" 
time="2018-04-19T13:26:57Z" level=debug msg="properties: [config.extraConfig summary.runtime.connectionState]" 
time="2018-04-19T13:26:57Z" level=debug msg="  State of components:" 
time="2018-04-19T13:26:57Z" level=debug msg="    \"docker-personality\": \"started successfully\"" 
time="2018-04-19T13:26:57Z" level=debug msg="    \"port-layer\": \"started successfully\"" 
time="2018-04-19T13:26:57Z" level=debug msg="    \"vicadmin\": \"started successfully\"" 
time="2018-04-19T13:26:57Z" level=info msg="Obtained IP address for client interface: \"10.161.82.116\"" 
time="2018-04-19T13:26:57Z" level=info msg="Checking VCH connectivity with vSphere target" 
time="2018-04-19T13:26:57Z" level=info msg="vSphere API Test: <a href="https://10.192.121.134">https://10.192.121.134</a> vSphere API target responds as expected" 
time="2018-04-19T13:26:57Z" level=debug msg="Docker API endpoint: <a href="https://10.161.82.116:2376/info">https://10.161.82.116:2376/info</a>" 
time="2018-04-19T13:26:58Z" level=debug msg="Portlayer has established volume stores (default)" 
time="2018-04-19T13:26:58Z" level=debug msg="Confirmed port layer is operational" 
time="2018-04-19T13:27:00Z" level=error msg="Failed to upgrade: Failed to grant permissions to ops-user, failure: Ops-User: RBACManager, Unable to set permissions on Folder:group-v3, error: ServerFaultCode: A specified parameter was not correct: entity" 
time="2018-04-19T13:27:00Z" level=info msg="Rolling back upgrade" 
time="2018-04-19T13:27:00Z" level=info msg="Reverting to snapshot reconfigure for 18535" 
time="2018-04-19T13:27:02Z" level=debug msg="vm compute resource: " 
time="2018-04-19T13:27:02Z" level=debug msg="VirtualMachine:vm-40 resides in a multi-host cluster: true" 
time="2018-04-19T13:27:02Z" level=debug msg="DRS enabled: true" 
time="2018-04-19T13:27:02Z" level=info msg="Waiting for IP information" 
time="2018-04-19T13:27:17Z" level=info msg="Waiting for major appliance components to launch" 
time="2018-04-19T13:27:17Z" level=debug msg="properties: [config.extraConfig summary.runtime.connectionState]" 
time="2018-04-19T13:27:17Z" level=debug msg="  State of components:" 
time="2018-04-19T13:27:17Z" level=debug msg="    \"docker-personality\": \"started successfully\"" 
time="2018-04-19T13:27:17Z" level=debug msg="    \"port-layer\": \"started successfully\"" 
time="2018-04-19T13:27:17Z" level=debug msg="    \"vicadmin\": \"started successfully\"" 
time="2018-04-19T13:27:17Z" level=info msg="Obtained IP address for client interface: \"10.161.82.116\"" 
time="2018-04-19T13:27:17Z" level=info msg="Checking VCH connectivity with vSphere target" 
time="2018-04-19T13:27:18Z" level=info msg="vSphere API Test: <a href="https://10.192.121.134">https://10.192.121.134</a> vSphere API target responds as expected" 
time="2018-04-19T13:27:18Z" level=debug msg="Docker API endpoint: <a href="https://10.161.82.116:2376/info">https://10.161.82.116:2376/info</a>" 
time="2018-04-19T13:27:18Z" level=debug msg="connection refused" 
time="2018-04-19T13:27:19Z" level=debug msg="Components not yet initialized, retrying" 
time="2018-04-19T13:27:19Z" level=debug msg="connection refused" 
time="2018-04-19T13:27:20Z" level=debug msg="Components not yet initialized, retrying" 
time="2018-04-19T13:27:20Z" level=debug msg="connection refused" 
time="2018-04-19T13:27:21Z" level=debug msg="Components not yet initialized, retrying" 
time="2018-04-19T13:27:22Z" level=debug msg="Portlayer has established volume stores (default)" 
time="2018-04-19T13:27:22Z" level=debug msg="Confirmed port layer is operational" 
time="2018-04-19T13:27:22Z" level=info msg="Appliance is rolled back to old version" 
time="2018-04-19T13:27:22Z" level=info msg="Deleting upgrade images" ' does not contain 'Completed successfully

[rogeliosanchez]

Seen in Nigthly 6.5 - 2018-04-19 as noted above

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

5-25-OPS-User-Grant
granted ops-user perms work after upgrade

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-19-00-26-56.zip?authuser=1

[zjs]

Investigation

The failure message is:

Failed to grant permissions to ops-user, failure: Ops-User: RBACManager, Unable to set permissions on Folder:group-v3, error: ServerFaultCode: A specified parameter was not correct: entity

It looks like this is coming from the code which grants operations user permissions, while re-granting operations permissions after the upgrade:

vic/lib/install/opsuser/opsuser.go

Lines 251 to 262 in a05eda2

	resourcePermissions := make([]rbac.ResourcePermission, 0, len(am.Config.Resources))
	// Apply permissions
	for _, desc := range resourceDescs {
	resourcePermission, err := am.AddPermission(ctx, desc.ref, desc.rType, false)
	if err != nil {
	return nil, errors.Errorf("Ops-User: RBACManager, Unable to set permissions on %s, error: %s",
	desc.ref.String(), err.Error())
	}
	if resourcePermission != nil {
	resourcePermissions = append(resourcePermissions, *resourcePermission)
	}
	}

The folder object was recently added to the set of resources on which permissions are granted:

vic/lib/install/opsuser/opsuser.go

Lines 241 to 249 in a05eda2

	// For vCenter, apply the endpoint role to the VCH inventory folder as well.
	if mgr.session.IsVC() {
	vchFolder := mgr.session.VCHFolder
	if vchFolder == nil {
	return nil, errors.Errorf("VCH folder not set, unable to set permissions")
	}
	resourceDescs = append(resourceDescs, resourceDesc{rbac.Endpoint, vchFolder.Reference()})
	}

This may be addressed by #7677, which should be merging soon. If that's delayed, we can disable this test.

[rogeliosanchez]

Seen in Nigthly 6.7 - 2018-04-19

VIC Version
v1.5.0-DEV-18535-634E0A5

5-25-OPS-User-Grant
granted ops-user perms work after upgrade
"Deleting upgrade images" ' does not contain 'Completed successfully'

Vic machine
vic-machine.log

Nightly Summary
67.zip

Link to logs
https://storage.cloud.google.com/vic-ci-logs/vic_nightly_logs_2018-04-19-05-47-22.zip?authuser=1

[rogeliosanchez]

Seen in Nigthly 6.0 - 2018-04-19

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

5-25-OPS-User-Grant
granted ops-user perms work after upgrade
"vic-machine-linux create failed: Cannot init ops-user permissions, failure: ServerFaultCode: The operation is not supported on the object.. Exiting...\n" ' does not contain 'Installer completed successfully'

Vic machine
vic-machine.log

Nightly Summary
60.zip

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

[rogeliosanchez]

Seen in Nigthly 6.5 - 2018-04-20

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

5-25-OPS-User-Grant
granted ops-user perms work after upgrade
"Deleting upgrade images" ' does not contain 'Completed successfully'

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 Nigthly 6.7 - 2018-04-20

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

5-25-OPS-User-Grant
granted ops-user perms work after upgrade
"Deleting upgrade images" ' does not contain 'Completed successfully'

Vic machine
vic-machine.log

Nightly summary
67.zip

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

[matthewavery]

Seen in nightlies for 6.0, 6.5, and 6.7 on 4/221/2018. same error with the same logs. I will not be posting additional logs on this failure as we have plenty at this point.

[zjs]

It seems like this will be fixed by #7777, as that will ensure that operations user permissions are re-granted at the right point during VCH upgrade. Assigning to @jzt for tracking.