Intermittent issue regarding to Chef server 12 knife upload cookbook

Version

chef-server-core-12.0.5-1.el6.x86_64
chef-12.0.3-1.el6.x86_64

Environment

RHEL 6.6 x86_64

Summary

After I successfully installed and configured the new Chef server 12, I tried to upload cookbooks in batch to this Chef server, but got intermittent uploading issue.

# /opt/chef/bin/knife cookbook upload apache2 apt aws build-essential ceph chef_handler chef-sugar cpu database dmg erlang git haproxy homebrew
Uploading apache2      [3.0.0]
Uploading apt          [2.6.1]
Uploading aws          [1.0.0]
Uploading build-essential [1.4.2]
Uploading ceph         [0.8.0]
Uploading chef_handler [1.1.5]
Uploading chef-sugar   [2.5.0]
Uploading cpu          [0.2.0]
Uploading database     [4.0.2]
ERROR: You authenticated successfully to https://binbin-chef.localdomain:443/organizations/ibm as os-software-management but you are not authorized for this action
Response:  missing create permission

This is obviously an issue, because I have successfully uploaded several cookbooks. And also, this appears intermittently. Sometimes, you failed at the third cookbook, and sometimes, you failed at the last one. Retrying to upload several times, all the cookbooks can be uploaded successfully.

Details

I tried to dig into the log files, and noticed following:
In /var/log/opscode/nginx/access.log, at the failing time, it reported:

"POST /organizations/ppp/sandboxes HTTP/1.1" 403 "2.877" 39 "-" "Chef Knife/12.0.3 (ruby-2.1.4-p265; ohai-8.0.1; x86_64-linux; +http://opscode.com)" "127.0.0.1:8000" "403" "2.875" "12.0.3" "algorithm=sha1;version=1.0;" "os-software-management" "2015-04-09T03:21:07Z" "Z16jPrg9oK6vgxkDl+IPAREhbdY=" 1693

At the same time, in /var/log/opscode/opscode-erchef/current:

[error] {<<"method=POST; path=/organizations; status=500; ">>,{error,{case_clause,{error,server_error}},[{oc_chef_authz,create_entity_if_authorized,4,[{file,"src/oc_chef_authz.erl"},{line,139}]},{oc_chef_wm_base,do_create_in_container,4,[{file,"src/oc_chef_wm_base.erl"},{line,274}]},{webmachine_resource,resource_call,3,[{file,"src/webmachine_resource.erl"},{line,186}]},{webmachine_resource,do,3,[{file,"src/webmachine_resource.erl"},{line,142}]},{webmachine_decision_core,resource_call,1,[{file,"src/webmachine_decision_core.erl"},{line,48}]},{webmachine_decision_core,decision,1,[{file,"src/webmachine_decision_core.erl"},{line,225}]},{webmachine_decision_core,handle_request,2,[{file,"src/webmachine_decision_core.erl"},{line,33}]},{webmachine_mochiweb,loop,2,[{file,"src/webmachine_mochiweb.erl"},{line,72}]}]}}
[error] Unable to read ACL for newly created sandbox: <<"cccc636437f6b5eee1070628579486ad">>
[error] {<<"method=POST; path=/organizations/ppp/sandboxes; status=403; ">>,"Forbidden"}
[error] Error setting ACE {authz_ace,[<<"302d9d7b8965c2655c81ee7f2fb62599">>,<<"81abaf8f7ae0d80ff013a9c079854048">>],[<<"776b85b0df0c2066d5056df11b8c4d85">>]} for method update on object <<"cccc636437f6b5eee1070628579486ad">> for requestor <<"81abaf8f7ae0d80ff013a9c079854048">>: req_timedout
[error] Unable to read ACL for newly created sandbox: <<"cccc636437f6b5eee1070628579486ad">>

In the Error setting ACE ... log, the request actually timedout: req_timedout

By checking oc_bifrost log /var/log/opscode/oc_bifrost/requests.log.1 for ACL processing, an interesting log showed up:

oc_bifrost@127.0.0.1 method=PUT; path=/objects/cccc636437f6b5eee1070628579486ad/acl/read; status=200; requestor_id=81abaf8f7ae0d80ff013a9c079854048; req_time=9; rdbms.bifrost_db.has_permission_time=2; rdbms.bifrost_db.has_permission_count=1; rdbms.bifrost_db.exists_time=1; rdbms.bifrost_db.exists_count=1; rdbms.bifrost_db.update_acl_time=3; rdbms.bifrost_db.update_acl_count=1; 
oc_bifrost@127.0.0.1 method=PUT; path=/objects/cccc636437f6b5eee1070628579486ad/acl/update; status=200; requestor_id=81abaf8f7ae0d80ff013a9c079854048; req_time=2470; rdbms.bifrost_db.has_permission_time=1; rdbms.bifrost_db.has_permission_count=1; rdbms.bifrost_db.exists_time=0; rdbms.bifrost_db.exists_count=1; rdbms.bifrost_db.update_acl_time=2467; rdbms.bifrost_db.update_acl_count=1; 
oc_bifrost@127.0.0.1 method=GET; path=/containers/b02d710e4ecf1bf869dd573bc70a0e53/acl/read/actors/81abaf8f7ae0d80ff013a9c079854048; status=200; requestor_id=81abaf8f7ae0d80ff013a9c079854048; req_time=5; rdbms.bifrost_db.has_permission_time=2; rdbms.bifrost_db.has_permission_count=1; rdbms.bifrost_db.exists_time=1; rdbms.bifrost_db.exists_count=1; 

Please notice the req_time and rdbms.bifrost_db.update_acl_time in the second line of log, they are extremely longer than others (thousands of times). This probably caused this issue. DB operation is too long and the erchef thought it was timedout.

This issue does not happen on all the systems, not sure if it is related to environment configuration.

Start with src/oc_chef_authz.erl at line 139 and correlate the erchef errors with the oc_bifrost requests.log.1 entries for the sandbox ACL update, especially req_timedout and update_acl_time. Done means explaining the intermittent 403 and timeout behavior and verifying a reliable resolution against the reported Chef Server 12 environment.