Permission check in bifrost can time out on large systems

Chef Server Version

Chef server latest 12.19.*, but probably affects most chef server versions.

Platform Details

This appears in hosted right now, as the largest single chef server instance. However there's no reason this can't bite elsewhere

Configuration

Hosted, but potentially other instances as well.

Scenario:

This was first discovered when investigating failures associate a user with an org.

erchef@127.0.0.1 method=PUT; path=/users/<USER_ID>/association_requests/<ASSOC_ID>; status=500; req_id=<req_id>; org_name=XOrg msg={add_usag_to_org_users_group_failed,{error,error_in_bifrost}}; req_time=4214; rdbms_time=4055; rdbms_count=10; authz_time=15; authz_count=1; user=pivotal; req_api_version=1;

Retry fails because the the first, failed attempt left behind a USAG that the creation code couldn't handle. See issue #310.

2019-01-24T21:01:08Z erchef@127.0.0.1 method=PUT; path=/users/XUser/association_requests/<ASSOC_ID>; status=500; req_id=<req_id>; org_name=XOrg; msg={usag_creation_failed,{conflict,<<"duplicate key value violates unique cons"...>>}}; req_time=166; rdbms_time=16; rdbms_count=7; authz_time=9; authz_count=1; user=pivotal; req_api_version=1;

Root cause of problem.

We're seeing good numbers of log entries with very large request times.

2019-01-28T23:01:41Z oc_bifrost@127.0.0.1 method=GET; path=/containers/<CONTAINER_GUID>/acl/read/actors/<PIVOTAL_AUTHZ_ID>; status=200; requestor_id=<PIVOTAL_AUTHZ_ID>; req_time=2925; rdbms.bifrost_db.has_permission_time=2923; rdbms.bifrost_db.has_permission_count=1; rdbms.bifrost_db.exists_time=1; rdbms.bifrost_db.exists_count=1;

Sometimes the db even times out in bifrost:

{error,{case_clause,{error,timeout}},[{bifrost_wm_base,forbidden,2,[{file,"/var/cache/omnibus/src/oc_bifrost/_build/default/lib/bifrost/src/bifrost_wm_base.erl"},{line,85}]},{webmachine_resource,resource_call,3,[{file,"/var/cache/omnibus/src/oc_bifrost/_build/default/lib/webmachine/src/webmachine_resource.erl"},{line,203}]},{webmachine_resource,do,3,[{file,"/var/cache/omnibus/src/oc_bifrost/_build/default/lib/webmachine/src/webmachine_resource.erl"},{line,148}]},{webmachine_decision_core,resource_call,1,[{file,"/var/cache/omnibus/src/oc_bifrost/_build/default/lib/webmachine/src/webmachine_decision_core.erl"},{line,47}]},{webmachine_decision_core,decision,1,[{file,"/var/cache/omnibus/src/oc_bifrost/_build/default/lib/webmachine/src/webmachine_decision_core.erl"},{line,222}]},{webmachine_decision_core,handle_request,2,[{file,"/var/cache/omnibus/src/oc_bifrost/_build/default/lib/webmachine/src/webmachine_decision_core.erl"},{line,32}]},{webmachine_mochiweb,loop,2,[{file,"/var/cache/omnibus/src/oc_bifrost/_build/default/lib/webmachine/src/webmachine_mochiweb.erl"},{line,106}]},{mochiweb_http,headers,6,[{file,"/var/cache/omnibus/src/oc_bifrost/_build/default/lib/mochiweb/src/mochiweb_http.erl"},{line,114}]}]}}

These long delays cause the erchef user association to timeout, and fail.

The slow call seems to be in the check_acl routine: https://github.com/chef/chef-server/blob/master/src/oc_bifrost/apps/bifrost/src/bifrost_wm_base.erl#L85

This doesn't happen on every ACL check for pivotal, just the ones where pivotal isn't directly in the ACL, but is indirectly from a group.

This leads us to suspect the group expansion code since it only fires if the actor isn't directly in the ACL. This (recursively) expands the groups the actor belongs in: https://github.com/chef/chef-server/blob/ac11df3d7c/src/oc_bifrost/schema/deploy/groups_for_actor.sql#L26

The working hypothesis is that pivotal is in too many groups, check via:

bifrost=> select count(parent) from group_actor_relations where child in (select id from auth_actor where authz_id ='<PIVOTAL_AUTHZ_ID>');

In hosted this number is large enough to give us trouble (>100k). Hosted chef server is the largest single installation we are aware of, so this most likely uncommon in the field unless a truly large number of organizations or groups are in play. However if postgres is under load we might see similar problems sooner.

Mitigations

• Delete excess organizations and groups. Look for orphaned groups missed by org deletion process
• Put pivotal in all ACLs, as this sidesteps group expansion. However we don't currently block users from removing it, and it doesn't address cases where we have other users (or the users in the server-admins group)
• Fix issue #310, and make user-org association more idempotent. Specifically, we should be able to handle dangling USAGs from previous attempts. It also might be worth doing the permissions check up front, and use the bifrost superuser for all operations.
• Consider increasing the timeouts in bifrost and erchef, to better tolerate long delays. However erlang has a default timeout of 5s in gen_server calls, and so the increased timeout might have ripple effects throughout the code.

Solutions

• The crux of the problem is that pivotal is in every single group in the server. We generate a temp table with every group we're recursively a member of, and when this gets large apparently things take a while. One approach to investigate to reverse the expansion process and recursively expand the group members of the group in the ACL, and then test if any contain the actor as a member. See https://github.com/chef/chef-server/blob/ac11df3d7c/src/oc_bifrost/schema/deploy/groups_for_actor.sql Users/actors are often global objects, while groups are less often so. Will require some benchmarking and testing to verify that it is both robust and actually faster.

Nonsolutions

• Retries inside of erchef or bifrost. These would need exponential fallback, and may trigger upstream timeouts and retries, and possibly load amplification. Nested retries are an antipattern to be avoided. It's better to push the failure up higher in the stack and retry there.
• Caching would have to happen inside the bifrost sql stored procedures to be effective, and that seems difficult to implement.

Start with bifrost_wm_base.erl around check_acl at line 85 and the recursive group expansion in schema/deploy/groups_for_actor.sql around line 26. Run the provided group_actor_relations query and inspect the permission path for actors inherited through groups. Done means a tested, benchmarked approach that remains robust and improves permission checks for very large group memberships without causing timeouts.