ocis server startup error

[phil-davis]

Describe the bug

https://drone.owncloud.com/owncloud/ocis/12206/39/3

+ ocis/bin/ocis server
{"level":"error","service":"proxy","error":"{\"id\":\"go.micro.client\",\"code\":500,\"detail\":\"service com.owncloud.api.settings: not found\",\"status\":\"Internal Server Error\"}","time":"2022-06-01T03:55:43Z","message":"Could not load roles"}

Is this a "normal" startup error message?

https://drone.owncloud.com/owncloud/ocis/12206/39/6

    Given user "Alice" has been created with default attributes and without skeleton files # FeatureContext::userHasBeenCreatedWithDefaultAttributesAndWithoutSkeletonFiles()
      GraphContext::throwHttpException
      Could not create user Alice
      HTTP status code: 401
      Error code: accessDenied
      Message: Unauthorized (Exception)

"something happens" (tm) sometimes on ocis startup, and admin cannot create users. So the whole CI pipeline obviously gets lots of unexpected failures.

Steps to reproduce

Run lots of CI pipelines and see one fail.

Expected behavior

ocis starts cleanly every time.

Actual behavior

ocis sometimes has an error on startup

Setup

current ocis master branch in CI

[micbar]

I had this problem locally when i was running out of file descriptors. But that should not be the case in CI.

could not load roles is a critical message during startup and brings ocis down.

[micbar]

Setting it to p2 because startup errors like these should not happen.

[rhafer]

+ ocis/bin/ocis server
{"level":"error","service":"proxy","error":"{\"id\":\"go.micro.client\",\"code\":500,\"detail\":\"service com.owncloud.api.settings: not found\",\"status\":\"Internal Server Error\"}","time":"2022-06-01T03:55:43Z","message":"Could not load roles"}

Is this a "normal" startup error message?

I wouldn't say normal, but it can happen when there a request issued against ocis before all services are fully up. I think this message is issue during the wait-for-ocis-server check (https://github.com/owncloud/ocis/blob/master/.drone.star#L1591). Unfortunately that check succeeds (as most of the other service are already up) and a failure to load the user's roles are not considered fatal here: https://github.com/owncloud/ocis/blob/master/extensions/proxy/pkg/user/backend/cs3.go#L79

It looks to me as if the settings service is just needing an awful long time to come up. Though I don't think that this is the root cause for the failing test afterwards. If it were, we'd see more error messages like the above in the logs (caused by the failing user creating during the tests). But as said this is just guessing for more detailed analysis we'd need more logging.

[rhafer]

I think we found a possible race condition in the proxy that might be causing the kind of bug experienced here.

From GetUserByClaims() (https://github.com/owncloud/ocis/blob/master/extensions/proxy/pkg/user/backend/cs3.go#L52):

	if user.Id.Type != cs3.UserType_USER_TYPE_LIGHTWEIGHT {
		roleIDs, err = loadRolesIDs(ctx, user.Id.OpaqueId, c.settingsRoleService)
		if err != nil {
			c.logger.Error().Err(err).Msgf("Could not load roles")
		}
	}

If the settings service is not fully up at this point. roleIDs is empty. (And the error returned by loadRoleIDs is ignored. Now we're trying to add a default role to the user and if the settings service becomes available before doing that the code below will overwrite the role-assignment of the user. (If this was an admin user, it will loose the privilege to create users ...)

	// if roles are empty, assume we haven't seen the user before and assign a
	// default user role. At least until proper roles are provided. See
	// https://github.com/owncloud/ocis/v2/issues/1825 for more context.
	if len(roleIDs) == 0 {
		if user.Id.Type == cs3.UserType_USER_TYPE_PRIMARY {
			c.logger.Info().Str("userid", user.Id.OpaqueId).Msg("user has no role assigned, assigning default user role")
			_, err := c.settingsRoleService.AssignRoleToUser(ctx, &settingssvc.AssignRoleToUserRequest{
				AccountUuid: user.Id.OpaqueId,
				RoleId:      settingsService.BundleUUIDRoleUser,
			})
			if err != nil {
				c.logger.Warn().Err(err).Msg("Could not add default role")
			}
			roleIDs = append(roleIDs, settingsService.BundleUUIDRoleUser)
		}
	}