Arvados-cwl-runner raises container permission denied error when submitting

When trying to submit a workflow to arvados I keep getting this error using the below commandline parameters.

CLI

arvados-cwl-runner /data/Tools/Test.cwl /data/Workflows/Inputs/Test.yaml
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/arvados_cwl/arvcontainer.py", line 308, in run
    ).execute(num_retries=self.arvrunner.num_retries)
  File "/usr/local/lib/python3.7/site-packages/googleapiclient/_helpers.py", line 130, in positional_wrapper
    return wrapped(*args, **kwargs)
  File "/usr/local/lib/python3.7/site-packages/googleapiclient/http.py", line 840, in execute
    raise HttpError(resp, content, uri=self.uri)
arvados.errors.ApiError: <

Server Error

/var/www/arvados-api/current/app/models/container.rb:511:in `validate_change'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:382:in `block in make_lambda'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:169:in `block (2 levels) in halting'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:547:in `block (2 levels) in default_terminator'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:546:in `catch'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:546:in `block in default_terminator'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:170:in `block in halting'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:454:in `block in call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:454:in `each'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:454:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:101:in `__run_callbacks__'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:750:in `_run_validate_callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activemodel-5.0.7.2/lib/active_model/validations.rb:408:in `run_validations!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activemodel-5.0.7.2/lib/active_model/validations/callbacks.rb:113:in `block in run_validations!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:126:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:506:in `block (2 levels) in compile'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:455:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:101:in `__run_callbacks__'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:750:in `_run_validation_callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activemodel-5.0.7.2/lib/active_model/validations/callbacks.rb:113:in `run_validations!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activemodel-5.0.7.2/lib/active_model/validations.rb:338:in `valid?'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/validations.rb:65:in `valid?'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/validations.rb:82:in `perform_validations'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/validations.rb:50:in `save!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/attribute_methods/dirty.rb:30:in `save!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:324:in `block in save!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:395:in `block in with_transaction_returning_status'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/connection_adapters/abstract/database_statements.rb:230:in `transaction'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:211:in `transaction'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:392:in `with_transaction_returning_status'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:324:in `save!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/suppressor.rb:45:in `save!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/persistence.rb:51:in `create!'
/var/www/arvados-api/current/app/models/container.rb:194:in `block in resolve'
/var/www/arvados-api/current/lib/current_api_client.rb:129:in `block in act_as_system_user'
/var/www/arvados-api/current/lib/current_api_client.rb:140:in `act_as_user'
/var/www/arvados-api/current/lib/current_api_client.rb:128:in `act_as_system_user'
/var/www/arvados-api/current/app/models/container.rb:190:in `resolve'
/var/www/arvados-api/current/app/models/container_request.rb:265:in `set_container'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:382:in `block in make_lambda'

Can you collect more API logs leading up to the failed request? What is weird here is that the error is an invalid state change in the container object.

Is there a container request or container uuid associated with the error? Can you query those records as well?

{"method":"POST","path":"/arvados/v1/container_requests","format":"json","controller":"Arvados::V1::ContainerRequestsController","action":"create","status":403,"duration":49.65,"view":0.34,"db":28.03,"request_id":"req-5ajprkrbfhqem3ek9qii","client_ipaddr":"10.20.151.204","client_auth":"t4b0m-gj3su-6t6rmbdqg0q5tt9","exception":"#\u003cArvadosModel::PermissionDeniedError: ArvadosModel::PermissionDeniedError\u003e","exception_backtrace":"/var/www/arvados-api/current/app/models/container.rb:511:in `validate_change'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:382:in `block in make_lambda'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:169:in `block (2 levels) in halting'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:547:in `block (2 levels) in default_terminator'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:546:in `catch'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:546:in `block in default_terminator'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:170:in `block in halting'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:454:in `block in call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:454:in `each'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:454:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:101:in `__run_callbacks__'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:750:in `_run_validate_callbacks'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activemodel-5.0.7.2/lib/active_model/validations.rb:408:in `run_validations!'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activemodel-5.0.7.2/lib/active_model/validations/callbacks.rb:113:in `block in run_validations!'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:126:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:506:in `block (2 levels) in compile'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:455:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:101:in `__run_callbacks__'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:750:in `_run_validation_callbacks'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activemodel-5.0.7.2/lib/active_model/validations/callbacks.rb:113:in `run_validations!'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activemodel-5.0.7.2/lib/active_model/validations.rb:338:in `valid?'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/validations.rb:65:in `valid?'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/validations.rb:82:in `perform_validations'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/validations.rb:50:in `save!'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/attribute_methods/dirty.rb:30:in `save!'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:324:in `block in save!'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:395:in `block in with_transaction_returning_status'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/connection_adapters/abstract/database_statements.rb:230:in `transaction'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:211:in `transaction'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:392:in `with_transaction_returning_status'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:324:in `save!'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/suppressor.rb:45:in `save!'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/persistence.rb:51:in `create!'\n/var/www/arvados-api/current/app/models/container.rb:194:in `block in resolve'\n/var/www/arvados-api/current/lib/current_api_client.rb:129:in `block in act_as_system_user'\n/var/www/arvados-api/current/lib/current_api_client.rb:140:in `act_as_user'\n/var/www/arvados-api/current/lib/current_api_client.rb:128:in `act_as_system_user'\n/var/www/arvados-api/current/app/models/container.rb:190:in `resolve'\n/var/www/arvados-api/current/app/models/container_request.rb:265:in `set_container'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:382:in `block in make_lambda'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:169:in `block (2 levels) in halting'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:770:in `block (2 levels) in deprecated_false_terminator'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:769:in `catch'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:769:in `block in deprecated_false_terminator'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:170:in `block in halting'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:454:in `block in call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:454:in `each'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:454:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:101:in `__run_callbacks__'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:750:in `_run_validation_callbacks'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activemodel-5.0.7.2/lib/active_model/validations/callbacks.rb:113:in `run_validations!'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activemodel-5.0.7.2/lib/active_model/validations.rb:338:in `valid?'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/validations.rb:65:in `valid?'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/validations.rb:82:in `perform_validations'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/validations.rb:50:in `save!'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/attribute_methods/dirty.rb:30:in `save!'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:324:in `block in save!'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:395:in `block in with_transaction_returning_status'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/connection_adapters/abstract/database_statements.rb:232:in `block in transaction'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/connection_adapters/abstract/transaction.rb:189:in `within_new_transaction'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/connection_adapters/abstract/database_statements.rb:232:in `transaction'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:211:in `transaction'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:392:in `with_transaction_returning_status'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:324:in `save!'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/suppressor.rb:45:in `save!'\n/var/www/arvados-api/current/app/controllers/application_controller.rb:112:in `create'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_controller/metal/basic_implicit_render.rb:4:in `send_action'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/abstract_controller/base.rb:188:in `process_action'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_controller/metal/rendering.rb:30:in `process_action'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/abstract_controller/callbacks.rb:20:in `block in process_action'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:126:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:506:in `block (2 levels) in compile'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:455:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:448:in `block (2 levels) in around'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:286:in `block (2 levels) in halting'\n/var/www/arvados-api/current/app/controllers/application_controller.rb:431:in `block in set_current_request_id'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/tagged_logging.rb:69:in `block in tagged'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/tagged_logging.rb:26:in `tagged'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/tagged_logging.rb:69:in `tagged'\n/var/www/arvados-api/current/app/controllers/application_controller.rb:430:in `set_current_request_id'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:382:in `block in make_lambda'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:285:in `block in halting'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:447:in `block in around'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:455:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:101:in `__run_callbacks__'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:750:in `_run_process_action_callbacks'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:90:in `run_callbacks'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/abstract_controller/callbacks.rb:19:in `process_action'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_controller/metal/rescue.rb:20:in `process_action'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_controller/metal/instrumentation.rb:32:in `block in process_action'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/notifications.rb:164:in `block in instrument'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/notifications/instrumenter.rb:21:in `instrument'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/notifications.rb:164:in `instrument'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_controller/metal/instrumentation.rb:30:in `process_action'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_controller/metal/params_wrapper.rb:248:in `process_action'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/railties/controller_runtime.rb:18:in `process_action'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/abstract_controller/base.rb:126:in `process'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionview-5.0.7.2/lib/action_view/rendering.rb:30:in `process'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_controller/metal.rb:190:in `dispatch'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_controller/metal.rb:262:in `dispatch'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/routing/route_set.rb:50:in `dispatch'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/routing/route_set.rb:32:in `serve'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/journey/router.rb:39:in `block in serve'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/journey/router.rb:26:in `each'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/journey/router.rb:26:in `serve'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/routing/route_set.rb:727:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/omniauth-1.4.3/lib/omniauth/strategy.rb:186:in `call!'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/omniauth-1.4.3/lib/omniauth/strategy.rb:164:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/omniauth-1.4.3/lib/omniauth/builder.rb:63:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/rack-2.2.2/lib/rack/etag.rb:27:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/rack-2.2.2/lib/rack/conditional_get.rb:40:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/rack-2.2.2/lib/rack/head.rb:12:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/rack-2.2.2/lib/rack/session/abstract/id.rb:266:in `context'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/rack-2.2.2/lib/rack/session/abstract/id.rb:260:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/middleware/cookies.rb:613:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/middleware/callbacks.rb:38:in `block in call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:97:in `__run_callbacks__'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:750:in `_run_call_callbacks'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:90:in `run_callbacks'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/middleware/callbacks.rb:36:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/middleware/debug_exceptions.rb:49:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/lograge-0.10.0/lib/lograge/rails_ext/rack/logger.rb:15:in `call_app'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/railties-5.0.7.2/lib/rails/rack/logger.rb:24:in `block in call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/tagged_logging.rb:69:in `block in tagged'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/tagged_logging.rb:26:in `tagged'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/tagged_logging.rb:69:in `tagged'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/railties-5.0.7.2/lib/rails/rack/logger.rb:24:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/request_store-1.4.1/lib/request_store/middleware.rb:19:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/middleware/request_id.rb:24:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/rack-2.2.2/lib/rack/method_override.rb:24:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/rack-2.2.2/lib/rack/runtime.rb:22:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/middleware/executor.rb:12:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/rack-2.2.2/lib/rack/sendfile.rb:110:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/middleware/ssl.rb:84:in `call'\n/var/www/arvados-api/current/app/middlewares/arvados_api_token.rb:66:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/railties-5.0.7.2/lib/rails/engine.rb:522:in `call'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/railties-5.0.7.2/lib/rails/railtie.rb:193:in `public_send'\n/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/railties-5.0.7.2/lib/rails/railtie.rb:193:in `method_missing'\n/usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:107:in `process_request'\n/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:157:in `accept_and_process_next_request'\n/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:110:in `main_loop'\n/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler.rb:415:in `block (3 levels) in start_threads'\n/usr/lib/ruby/vendor_ruby/phusion_passenger/utils.rb:113:in `block in create_thread_and_abort_on_exception'\n","params":{"command":["cat","/keep/0acb15c9ad05a3249715831f2f3f31c9+52:/test.dat"],"name":"Test.cwl","output_path":"/var/spool/cwl","cwd":"/var/spool/cwl","priority":500,"state":"Committed","properties":{},"environment":{"TMPDIR":"/tmp","HOME":"/var/spool/cwl"},"container_image":"a99435b182c720edf05d9cad15fbce44+132","output_name":"Output for step Test.cwl","output_ttl":0,"mounts":{"/var/spool/cwl":{"kind":"tmp","capacity":1073741824},"/tmp":{"kind":"tmp","capacity":1073741824},"/keep/0acb15c9ad05a3249715831f2f3f31c9+52:":{"kind":"collection","portable_data_hash":"0acb15c9ad05a3249715831f2f3f31c9+52:"},"stdout":{"kind":"file","path":"/var/spool/cwl/out.dat"}},"secret_mounts":{},"runtime_constraints":{"vcpus":1,"ram":1073741824,"API":true},"scheduling_parameters":{},"use_existing":true,"alt":"json","container_request":{"name":"Test.cwl","properties":{},"state":"Committed","mounts":{"/var/spool/cwl":{"kind":"tmp","capacity":1073741824},"/tmp":{"kind":"tmp","capacity":1073741824},"/keep/0acb15c9ad05a3249715831f2f3f31c9+52:":{"kind":"collection","portable_data_hash":"0acb15c9ad05a3249715831f2f3f31c9+52:"},"stdout":{"kind":"file","path":"/var/spool/cwl/out.dat"}},"runtime_constraints":{"vcpus":1,"ram":1073741824,"API":true},"container_image":"a99435b182c720edf05d9cad15fbce44+132","environment":{"TMPDIR":"/tmp","HOME":"/var/spool/cwl"},"cwd":"/var/spool/cwl","command":["cat","/keep/0acb15c9ad05a3249715831f2f3f31c9+52:/test.dat"],"output_path":"/var/spool/cwl","priority":500,"use_existing":true,"scheduling_parameters":{},"output_name":"Output for step Test.cwl","output_ttl":0}},"@timestamp":"2020-09-28T13:44:21.550353500Z","@version":"1","message":"[403] POST /arvados/v1/container_requests (Arvados::V1::ContainerRequestsController#create)"}

I noticed the logs were poorly formatted, below are them cleaned up

#\u003cArvadosModel::PermissionDeniedError: ArvadosModel::PermissionDeniedError\u003e","exception_backtrace":"/var/www/arvados-api/current/app/models/container.rb:511:in `validate_change'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:382:in `block in make_lambda'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:169:in `block (2 levels) in halting'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:547:in `block (2 levels) in default_terminator'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:546:in `catch'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:546:in `block in default_terminator'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:170:in `block in halting'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:454:in `block in call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:454:in `each'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:454:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:101:in `__run_callbacks__'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:750:in `_run_validate_callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activemodel-5.0.7.2/lib/active_model/validations.rb:408:in `run_validations!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activemodel-5.0.7.2/lib/active_model/validations/callbacks.rb:113:in `block in run_validations!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:126:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:506:in `block (2 levels) in compile'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:455:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:101:in `__run_callbacks__'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:750:in `_run_validation_callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activemodel-5.0.7.2/lib/active_model/validations/callbacks.rb:113:in `run_validations!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activemodel-5.0.7.2/lib/active_model/validations.rb:338:in `valid?'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/validations.rb:65:in `valid?'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/validations.rb:82:in `perform_validations'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/validations.rb:50:in `save!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/attribute_methods/dirty.rb:30:in `save!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:324:in `block in save!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:395:in `block in with_transaction_returning_status'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/connection_adapters/abstract/database_statements.rb:230:in `transaction'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:211:in `transaction'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:392:in `with_transaction_returning_status'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:324:in `save!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/suppressor.rb:45:in `save!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/persistence.rb:51:in `create!'
/var/www/arvados-api/current/app/models/container.rb:194:in `block in resolve'
/var/www/arvados-api/current/lib/current_api_client.rb:129:in `block in act_as_system_user'
/var/www/arvados-api/current/lib/current_api_client.rb:140:in `act_as_user'
/var/www/arvados-api/current/lib/current_api_client.rb:128:in `act_as_system_user'
/var/www/arvados-api/current/app/models/container.rb:190:in `resolve'
/var/www/arvados-api/current/app/models/container_request.rb:265:in `set_container'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:382:in `block in make_lambda'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:169:in `block (2 levels) in halting'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:770:in `block (2 levels) in deprecated_false_terminator'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:769:in `catch'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:769:in `block in deprecated_false_terminator'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:170:in `block in halting'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:454:in `block in call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:454:in `each'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:454:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:101:in `__run_callbacks__'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:750:in `_run_validation_callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activemodel-5.0.7.2/lib/active_model/validations/callbacks.rb:113:in `run_validations!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activemodel-5.0.7.2/lib/active_model/validations.rb:338:in `valid?'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/validations.rb:65:in `valid?'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/validations.rb:82:in `perform_validations'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/validations.rb:50:in `save!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/attribute_methods/dirty.rb:30:in `save!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:324:in `block in save!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:395:in `block in with_transaction_returning_status'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/connection_adapters/abstract/database_statements.rb:232:in `block in transaction'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/connection_adapters/abstract/transaction.rb:189:in `within_new_transaction'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/connection_adapters/abstract/database_statements.rb:232:in `transaction'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:211:in `transaction'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:392:in `with_transaction_returning_status'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/transactions.rb:324:in `save!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/suppressor.rb:45:in `save!'
/var/www/arvados-api/current/app/controllers/application_controller.rb:112:in `create'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_controller/metal/basic_implicit_render.rb:4:in `send_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/abstract_controller/base.rb:188:in `process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_controller/metal/rendering.rb:30:in `process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/abstract_controller/callbacks.rb:20:in `block in process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:126:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:506:in `block (2 levels) in compile'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:455:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:448:in `block (2 levels) in around'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:286:in `block (2 levels) in halting'
/var/www/arvados-api/current/app/controllers/application_controller.rb:431:in `block in set_current_request_id'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/tagged_logging.rb:69:in `block in tagged'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/tagged_logging.rb:26:in `tagged'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/tagged_logging.rb:69:in `tagged'
/var/www/arvados-api/current/app/controllers/application_controller.rb:430:in `set_current_request_id'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:382:in `block in make_lambda'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:285:in `block in halting'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:447:in `block in around'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:455:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:101:in `__run_callbacks__'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:750:in `_run_process_action_callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:90:in `run_callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/abstract_controller/callbacks.rb:19:in `process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_controller/metal/rescue.rb:20:in `process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_controller/metal/instrumentation.rb:32:in `block in process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/notifications.rb:164:in `block in instrument'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/notifications.rb:164:in `instrument'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_controller/metal/params_wrapper.rb:248:in `process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activerecord-5.0.7.2/lib/active_record/railties/controller_runtime.rb:18:in `process_action'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/abstract_controller/base.rb:126:in `process'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionview-5.0.7.2/lib/action_view/rendering.rb:30:in `process'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_controller/metal.rb:190:in `dispatch'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_controller/metal.rb:262:in `dispatch'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/routing/route_set.rb:50:in `dispatch'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/routing/route_set.rb:32:in `serve'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/journey/router.rb:39:in `block in serve'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/journey/router.rb:26:in `each'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/journey/router.rb:26:in `serve'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/routing/route_set.rb:727:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/omniauth-1.4.3/lib/omniauth/strategy.rb:186:in `call!'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/omniauth-1.4.3/lib/omniauth/strategy.rb:164:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/omniauth-1.4.3/lib/omniauth/builder.rb:63:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/rack-2.2.2/lib/rack/etag.rb:27:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/rack-2.2.2/lib/rack/conditional_get.rb:40:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/rack-2.2.2/lib/rack/head.rb:12:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/rack-2.2.2/lib/rack/session/abstract/id.rb:266:in `context'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/rack-2.2.2/lib/rack/session/abstract/id.rb:260:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/middleware/cookies.rb:613:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/middleware/callbacks.rb:38:in `block in call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:97:in `__run_callbacks__'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:750:in `_run_call_callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/callbacks.rb:90:in `run_callbacks'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/middleware/callbacks.rb:36:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/middleware/debug_exceptions.rb:49:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/lograge-0.10.0/lib/lograge/rails_ext/rack/logger.rb:15:in `call_app'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/railties-5.0.7.2/lib/rails/rack/logger.rb:24:in `block in call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/tagged_logging.rb:69:in `block in tagged'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/tagged_logging.rb:26:in `tagged'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/tagged_logging.rb:69:in `tagged'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/railties-5.0.7.2/lib/rails/rack/logger.rb:24:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/request_store-1.4.1/lib/request_store/middleware.rb:19:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/middleware/request_id.rb:24:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/rack-2.2.2/lib/rack/method_override.rb:24:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/rack-2.2.2/lib/rack/runtime.rb:22:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/activesupport-5.0.7.2/lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/middleware/executor.rb:12:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/rack-2.2.2/lib/rack/sendfile.rb:110:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/actionpack-5.0.7.2/lib/action_dispatch/middleware/ssl.rb:84:in `call'
/var/www/arvados-api/current/app/middlewares/arvados_api_token.rb:66:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/railties-5.0.7.2/lib/rails/engine.rb:522:in `call'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/railties-5.0.7.2/lib/rails/railtie.rb:193:in `public_send'
/var/www/arvados-api/shared/vendor_bundle/ruby/2.3.0/gems/railties-5.0.7.2/lib/rails/railtie.rb:193:in `method_missing'
/usr/lib/ruby/vendor_ruby/phusion_passenger/rack/thread_handler_extension.rb:107:in `process_request'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:157:in `accept_and_process_next_request'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler/thread_handler.rb:110:in `main_loop'
/usr/lib/ruby/vendor_ruby/phusion_passenger/request_handler.rb:415:in `block (3 levels) in start_threads'
/usr/lib/ruby/vendor_ruby/phusion_passenger/utils.rb:113:in `bloc