Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Print authentication error stack-trace in INFO level #2080

Closed
orenbm opened this issue Mar 24, 2021 · 1 comment · Fixed by #2070
Closed

Print authentication error stack-trace in INFO level #2080

orenbm opened this issue Mar 24, 2021 · 1 comment · Fixed by #2070
Labels
component/conjur kind/enhancement

Comments

@orenbm
Copy link
Member

orenbm commented Mar 24, 2021

We have a lot of cases where the customer has an authentication error
and the log level is set to INFO. In such cases, the log will show the
following:

  INFO 2021/03/17 13:22:21 +0000 [pid=512] [origin=127.0.0.1] [request_id=8752fd9f-b800-46c6-9716-41a8d4dc587a] [tid=523] Started POST "/authn-oidc/keycloak/cucumber/authenticate" for 127.0.0.1 at 2021-03-17 13:22:21 +0000
 INFO 2021/03/17 13:22:21 +0000 [pid=512] [origin=127.0.0.1] [request_id=8752fd9f-b800-46c6-9716-41a8d4dc587a] [tid=523] Processing by AuthenticateController#authenticate_oidc as */*
 INFO 2021/03/17 13:22:21 +0000 [pid=512] [origin=127.0.0.1] [request_id=8752fd9f-b800-46c6-9716-41a8d4dc587a] [tid=523]   Parameters: {:controller=>"authenticate", :action=>"authenticate_oidc", :service_id=>"keycloak", :account=>"cucumber"}
 INFO 2021/03/17 13:22:22 +0000 [pid=512] [origin=127.0.0.1] [request_id=8752fd9f-b800-46c6-9716-41a8d4dc587a] [tid=523] CONJ00048I Authentication Error: #<Errors::Authentication::Security::RoleNotFound: CONJ00007E 'not_in_conjur' not found>
 INFO 2021/03/17 13:22:22 +0000 [pid=512] [origin=127.0.0.1] [request_id=8752fd9f-b800-46c6-9716-41a8d4dc587a] [tid=523] Completed 401 Unauthorized in 118ms

Although we print the actual error, it sometimes doesn't help enough and we want to view the
stack trace. This requires the customer to set the log level to DEBUG and re-run the request.
Also - sometimes it adds another cycle in which we ask for debug logs.

Furthermore, the stack trace that is written in DEBUG logs is quite hard to read:

 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] Started POST "/authn-oidc/keycloak/cucumber/authenticate" for 127.0.0.1 at 2021-03-17 13:16:55 +0000
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] Processing by AuthenticateController#authenticate_oidc as */*
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303]   Parameters: {:controller=>"authenticate", :action=>"authenticate_oidc", :service_id=>"keycloak", :account=>"cucumber"}
DEBUG 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303]   Sequel::Postgres::Database (0.5ms)  BEGIN
DEBUG 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303]   Sequel::Postgres::Database (0.4ms)  SELECT * FROM "roles" WHERE "role_id" = 'cucumber:user:admin'
DEBUG 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303]   Sequel::Postgres::Database (0.4ms)  SELECT * FROM "resources" WHERE "resource_id" = 'cucumber:variable:conjur/authn-oidc/keycloak/provider-uri'
DEBUG 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303]   Sequel::Postgres::Database (0.4ms)  SELECT * FROM "resources" WHERE "resource_id" = 'cucumber:variable:conjur/authn-oidc/keycloak/id-token-user-property'
DEBUG 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303]   Sequel::Postgres::Database (0.7ms)  SELECT * FROM "secrets" WHERE ("secrets"."resource_id" = 'cucumber:variable:conjur/authn-oidc/keycloak/provider-uri') ORDER BY "version" DESC LIMIT 1
DEBUG 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303]   Sequel::Postgres::Database (0.9ms)  SELECT * FROM "secrets" WHERE ("secrets"."resource_id" = 'cucumber:variable:conjur/authn-oidc/keycloak/id-token-user-property') ORDER BY "version" DESC LIMIT 1
DEBUG 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] CONJ00023D Concurrency limited cache concurrent requests updated to '1'
DEBUG 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] CONJ00007D Working with Identity Provider https://keycloak:8443/auth/realms/master
DEBUG 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] CONJ00008D Identity Provider discovery succeeded
DEBUG 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] CONJ00009D Fetched Identity Provider keys from provider successfully
DEBUG 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] CONJ00016D Rate limited cache updated successfully
DEBUG 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] CONJ00021D Concurrency limited cache updated successfully
DEBUG 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] CONJ00023D Concurrency limited cache concurrent requests updated to '0'
DEBUG 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] CONJ00017D Fetched Identity Provider keys from cache successfully
DEBUG 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] CONJ00005D Token decoded successfully
DEBUG 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] CONJ00004D Extracted username 'not_in_conjur' from ID token claim 'preferred_username'
DEBUG 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303]   Sequel::Postgres::Database (0.5ms)  SELECT * FROM "roles" WHERE "role_id" = 'cucumber:user:admin'
DEBUG 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303]   Sequel::Postgres::Database (0.5ms)  SELECT * FROM "roles" WHERE "role_id" = 'cucumber:user:admin'
DEBUG 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303]   Sequel::Postgres::Database (0.3ms)  SELECT * FROM "roles" WHERE "role_id" = 'cucumber:user:not_in_conjur'
DEBUG 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303]   Sequel::Postgres::Database (0.6ms)  SELECT * FROM "roles" WHERE ("role_id" = 'cucumber:user:not_in_conjur') LIMIT 1
DEBUG 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303]   Sequel::Postgres::Database (0.5ms)  SELECT * FROM "roles" WHERE ("role_id" = 'cucumber:user:not_in_conjur') LIMIT 1
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] CONJ00048I Authentication Error: #<Errors::Authentication::Security::RoleNotFound: CONJ00007E 'not_in_conjur' not found>
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /src/conjur-server/app/domain/authentication/security/validate_role_can_access_webservice.rb:52:in `validate_role_is_defined'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /src/conjur-server/app/domain/authentication/security/validate_role_can_access_webservice.rb:22:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] (eval):7:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /src/conjur-server/app/domain/authentication/authenticate.rb:60:in `validate_user_has_access_to_webservice'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /src/conjur-server/app/domain/authentication/authenticate.rb:27:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] (eval):7:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /src/conjur-server/app/controllers/authenticate_controller.rb:69:in `authenticate'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /src/conjur-server/app/controllers/authenticate_controller.rb:95:in `authenticate_oidc'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/abstract_controller/base.rb:194:in `process_action'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/rendering.rb:30:in `process_action'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/callbacks.rb:109:in `block in run_callbacks'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /src/conjur-server/app/controllers/application_controller.rb:78:in `block in run_with_transaction'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/sequel-4.49.0/lib/sequel/database/transactions.rb:224:in `_transaction'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/sequel-4.49.0/lib/sequel/database/transactions.rb:199:in `block in transaction'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/sequel-4.49.0/lib/sequel/database/connecting.rb:301:in `block in synchronize'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/sequel-4.49.0/lib/sequel/connection_pool/threaded.rb:107:in `hold'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/sequel-4.49.0/lib/sequel/database/connecting.rb:301:in `synchronize'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/sequel-4.49.0/lib/sequel/database/transactions.rb:165:in `transaction'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /src/conjur-server/app/controllers/application_controller.rb:77:in `run_with_transaction'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/callbacks.rb:136:in `run_callbacks'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/abstract_controller/callbacks.rb:41:in `process_action'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/rescue.rb:22:in `process_action'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/notifications.rb:168:in `block in instrument'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/notifications.rb:168:in `instrument'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/abstract_controller/base.rb:134:in `process'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionview-5.2.4.5/lib/action_view/rendering.rb:32:in `process'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_controller/metal.rb:191:in `dispatch'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_controller/metal.rb:252:in `dispatch'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/routing/route_set.rb:34:in `serve'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/journey/router.rb:52:in `block in serve'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/journey/router.rb:35:in `each'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/journey/router.rb:35:in `serve'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/routing/route_set.rb:840:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/conjur-rack-4.2.0/lib/conjur/rack/authenticator.rb:89:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/tempfile_reaper.rb:15:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/etag.rb:27:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/conditional_get.rb:40:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/head.rb:12:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:266:in `context'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:260:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/cookies.rb:670:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/callbacks.rb:98:in `run_callbacks'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/railties-5.2.4.5/lib/rails/rack/logger.rb:38:in `call_app'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/railties-5.2.4.5/lib/rails/rack/logger.rb:26:in `block in call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/tagged_logging.rb:71:in `block in tagged'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/tagged_logging.rb:28:in `tagged'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/tagged_logging.rb:71:in `tagged'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/railties-5.2.4.5/lib/rails/rack/logger.rb:26:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/request_id.rb:27:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/method_override.rb:24:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/runtime.rb:22:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/executor.rb:14:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/static.rb:127:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/sendfile.rb:110:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/conjur-rack-heartbeat-2.2.0/lib/rack/heartbeat.rb:20:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /src/conjur-server/lib/rack/remove_request_parameters.rb:26:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /src/conjur-server/lib/rack/default_content_type.rb:68:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/railties-5.2.4.5/lib/rails/engine.rb:524:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/puma-3.12.6/lib/puma/configuration.rb:227:in `call'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/puma-3.12.6/lib/puma/server.rb:706:in `handle_request'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/puma-3.12.6/lib/puma/server.rb:476:in `process_client'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/puma-3.12.6/lib/puma/server.rb:334:in `block in run'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/puma-3.12.6/lib/puma/thread_pool.rb:135:in `block in spawn_thread'
DEBUG 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303]   Sequel::Postgres::Database (0.6ms)  ROLLBACK
DEBUG 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] ApplicationController::Unauthorized
/src/conjur-server/app/controllers/authenticate_controller.rb:171:in `handle_authentication_error'
/src/conjur-server/app/controllers/authenticate_controller.rb:83:in `rescue in authenticate'
/src/conjur-server/app/controllers/authenticate_controller.rb:68:in `authenticate'
/src/conjur-server/app/controllers/authenticate_controller.rb:95:in `authenticate_oidc'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/abstract_controller/base.rb:194:in `process_action'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/rendering.rb:30:in `process_action'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/callbacks.rb:109:in `block in run_callbacks'
/src/conjur-server/app/controllers/application_controller.rb:78:in `block in run_with_transaction'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/sequel-4.49.0/lib/sequel/database/transactions.rb:224:in `_transaction'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/sequel-4.49.0/lib/sequel/database/transactions.rb:199:in `block in transaction'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/sequel-4.49.0/lib/sequel/database/connecting.rb:301:in `block in synchronize'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/sequel-4.49.0/lib/sequel/connection_pool/threaded.rb:107:in `hold'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/sequel-4.49.0/lib/sequel/database/connecting.rb:301:in `synchronize'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/sequel-4.49.0/lib/sequel/database/transactions.rb:165:in `transaction'
/src/conjur-server/app/controllers/application_controller.rb:77:in `run_with_transaction'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/callbacks.rb:136:in `run_callbacks'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/abstract_controller/callbacks.rb:41:in `process_action'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/rescue.rb:22:in `process_action'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/notifications.rb:168:in `block in instrument'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/notifications.rb:168:in `instrument'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/abstract_controller/base.rb:134:in `process'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionview-5.2.4.5/lib/action_view/rendering.rb:32:in `process'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_controller/metal.rb:191:in `dispatch'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_controller/metal.rb:252:in `dispatch'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/routing/route_set.rb:34:in `serve'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/journey/router.rb:52:in `block in serve'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/journey/router.rb:35:in `each'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/journey/router.rb:35:in `serve'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/routing/route_set.rb:840:in `call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/conjur-rack-4.2.0/lib/conjur/rack/authenticator.rb:89:in `call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/tempfile_reaper.rb:15:in `call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/etag.rb:27:in `call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/conditional_get.rb:40:in `call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/head.rb:12:in `call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:266:in `context'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:260:in `call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/cookies.rb:670:in `call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/callbacks.rb:98:in `run_callbacks'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/railties-5.2.4.5/lib/rails/rack/logger.rb:38:in `call_app'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/railties-5.2.4.5/lib/rails/rack/logger.rb:26:in `block in call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/tagged_logging.rb:71:in `block in tagged'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/tagged_logging.rb:28:in `tagged'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/tagged_logging.rb:71:in `tagged'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/railties-5.2.4.5/lib/rails/rack/logger.rb:26:in `call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/request_id.rb:27:in `call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/method_override.rb:24:in `call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/runtime.rb:22:in `call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/executor.rb:14:in `call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/static.rb:127:in `call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/sendfile.rb:110:in `call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/conjur-rack-heartbeat-2.2.0/lib/rack/heartbeat.rb:20:in `call'
/src/conjur-server/lib/rack/remove_request_parameters.rb:26:in `call'
/src/conjur-server/lib/rack/default_content_type.rb:68:in `call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/railties-5.2.4.5/lib/rails/engine.rb:524:in `call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/puma-3.12.6/lib/puma/configuration.rb:227:in `call'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/puma-3.12.6/lib/puma/server.rb:706:in `handle_request'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/puma-3.12.6/lib/puma/server.rb:476:in `process_client'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/puma-3.12.6/lib/puma/server.rb:334:in `block in run'
/var/lib/ruby/lib/ruby/gems/2.5.0/gems/puma-3.12.6/lib/puma/thread_pool.rb:135:in `block in spawn_thread'
 INFO 2021/03/17 13:16:55 +0000 [pid=298] [origin=127.0.0.1] [request_id=14d4edf2-5f96-4628-99dd-c9647539064e] [tid=303] Completed 401 Unauthorized in 307ms

The output above actually includes 2 stack traces - one of the original error, and one of the error that we raise
in the authenticate_controller and is printed in the application_controller. We can improve our supportability by
printing the original stack trace in info level:

 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] Started POST "/authn-oidc/keycloak/cucumber/authenticate" for 127.0.0.1 at 2021-03-17 13:32:05 +0000
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] Processing by AuthenticateController#authenticate_oidc as */*
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589]   Parameters: {:controller=>"authenticate", :action=>"authenticate_oidc", :service_id=>"keycloak", :account=>"cucumber"}
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] CONJ00048I Authentication Error: #<Errors::Authentication::Security::RoleNotFound: CONJ00007E 'not_in_conjur' not found>
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /src/conjur-server/app/domain/authentication/security/validate_role_can_access_webservice.rb:52:in `validate_role_is_defined'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /src/conjur-server/app/domain/authentication/security/validate_role_can_access_webservice.rb:22:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] (eval):7:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /src/conjur-server/app/domain/authentication/authenticate.rb:60:in `validate_user_has_access_to_webservice'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /src/conjur-server/app/domain/authentication/authenticate.rb:27:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] (eval):7:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /src/conjur-server/app/controllers/authenticate_controller.rb:69:in `authenticate'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /src/conjur-server/app/controllers/authenticate_controller.rb:95:in `authenticate_oidc'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/abstract_controller/base.rb:194:in `process_action'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/rendering.rb:30:in `process_action'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/callbacks.rb:109:in `block in run_callbacks'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /src/conjur-server/app/controllers/application_controller.rb:78:in `block in run_with_transaction'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/sequel-4.49.0/lib/sequel/database/transactions.rb:224:in `_transaction'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/sequel-4.49.0/lib/sequel/database/transactions.rb:199:in `block in transaction'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/sequel-4.49.0/lib/sequel/database/connecting.rb:301:in `block in synchronize'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/sequel-4.49.0/lib/sequel/connection_pool/threaded.rb:107:in `hold'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/sequel-4.49.0/lib/sequel/database/connecting.rb:301:in `synchronize'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/sequel-4.49.0/lib/sequel/database/transactions.rb:165:in `transaction'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /src/conjur-server/app/controllers/application_controller.rb:77:in `run_with_transaction'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/callbacks.rb:136:in `run_callbacks'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/abstract_controller/callbacks.rb:41:in `process_action'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/rescue.rb:22:in `process_action'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/instrumentation.rb:34:in `block in process_action'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/notifications.rb:168:in `block in instrument'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/notifications.rb:168:in `instrument'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_controller/metal/params_wrapper.rb:256:in `process_action'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/abstract_controller/base.rb:134:in `process'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionview-5.2.4.5/lib/action_view/rendering.rb:32:in `process'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_controller/metal.rb:191:in `dispatch'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_controller/metal.rb:252:in `dispatch'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/routing/route_set.rb:52:in `dispatch'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/routing/route_set.rb:34:in `serve'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/journey/router.rb:52:in `block in serve'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/journey/router.rb:35:in `each'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/journey/router.rb:35:in `serve'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/routing/route_set.rb:840:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/conjur-rack-4.2.0/lib/conjur/rack/authenticator.rb:89:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/tempfile_reaper.rb:15:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/etag.rb:27:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/conditional_get.rb:40:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/head.rb:12:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:266:in `context'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/session/abstract/id.rb:260:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/cookies.rb:670:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/callbacks.rb:98:in `run_callbacks'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/debug_exceptions.rb:61:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/railties-5.2.4.5/lib/rails/rack/logger.rb:38:in `call_app'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/railties-5.2.4.5/lib/rails/rack/logger.rb:26:in `block in call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/tagged_logging.rb:71:in `block in tagged'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/tagged_logging.rb:28:in `tagged'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/tagged_logging.rb:71:in `tagged'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/railties-5.2.4.5/lib/rails/rack/logger.rb:26:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/request_id.rb:27:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/method_override.rb:24:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/runtime.rb:22:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/activesupport-5.2.4.5/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/executor.rb:14:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/actionpack-5.2.4.5/lib/action_dispatch/middleware/static.rb:127:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/rack-2.2.3/lib/rack/sendfile.rb:110:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/conjur-rack-heartbeat-2.2.0/lib/rack/heartbeat.rb:20:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /src/conjur-server/lib/rack/remove_request_parameters.rb:26:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /src/conjur-server/lib/rack/default_content_type.rb:68:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/railties-5.2.4.5/lib/rails/engine.rb:524:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/puma-3.12.6/lib/puma/configuration.rb:227:in `call'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/puma-3.12.6/lib/puma/server.rb:706:in `handle_request'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/puma-3.12.6/lib/puma/server.rb:476:in `process_client'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/puma-3.12.6/lib/puma/server.rb:334:in `block in run'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] /var/lib/ruby/lib/ruby/gems/2.5.0/gems/puma-3.12.6/lib/puma/thread_pool.rb:135:in `block in spawn_thread'
 INFO 2021/03/17 13:32:05 +0000 [pid=582] [origin=127.0.0.1] [request_id=cd55db99-e766-47dc-b025-11382e187098] [tid=589] Completed 401 Unauthorized in 235ms

Still, this has some clutter and we would not want the info log (which is the default one) to include so many
lines. However, we can achieve a better output by printing only the stack trace of our app, beginning in our
code. This can be done by printing the stack trace in INFO level while printing in DEBUG level once we hit the ruby gems level. Such a log will
look like this:

 INFO 2021/03/17 13:20:46 +0000 [pid=455] [origin=127.0.0.1] [request_id=c9e98ca5-317f-49ab-975b-13301ba28941] [tid=461] Started POST "/authn-oidc/keycloak/cucumber/authenticate" for 127.0.0.1 at 2021-03-17 13:20:46 +0000
INFO 2021/03/17 13:20:46 +0000 [pid=455] [origin=127.0.0.1] [request_id=c9e98ca5-317f-49ab-975b-13301ba28941] [tid=461] Processing by AuthenticateController#authenticate_oidc as */*
INFO 2021/03/17 13:20:46 +0000 [pid=455] [origin=127.0.0.1] [request_id=c9e98ca5-317f-49ab-975b-13301ba28941] [tid=461]   Parameters: {:controller=>"authenticate", :action=>"authenticate_oidc", :service_id=>"keycloak", :account=>"cucumber"}
INFO 2021/03/17 13:20:46 +0000 [pid=455] [origin=127.0.0.1] [request_id=c9e98ca5-317f-49ab-975b-13301ba28941] [tid=461] CONJ00048I Authentication Error: #<Errors::Authentication::Security::RoleNotFound: CONJ00007E 'not_in_conjur' not found>
INFO 2021/03/17 13:20:46 +0000 [pid=455] [origin=127.0.0.1] [request_id=c9e98ca5-317f-49ab-975b-13301ba28941] [tid=461] /src/conjur-server/app/domain/authentication/security/validate_role_can_access_webservice.rb:52:in `validate_role_is_defined'
INFO 2021/03/17 13:20:46 +0000 [pid=455] [origin=127.0.0.1] [request_id=c9e98ca5-317f-49ab-975b-13301ba28941] [tid=461] /src/conjur-server/app/domain/authentication/security/validate_role_can_access_webservice.rb:22:in `call'
INFO 2021/03/17 13:20:46 +0000 [pid=455] [origin=127.0.0.1] [request_id=c9e98ca5-317f-49ab-975b-13301ba28941] [tid=461] (eval):7:in `call'
INFO 2021/03/17 13:20:46 +0000 [pid=455] [origin=127.0.0.1] [request_id=c9e98ca5-317f-49ab-975b-13301ba28941] [tid=461] /src/conjur-server/app/domain/authentication/authenticate.rb:60:in `validate_user_has_access_to_webservice'
INFO 2021/03/17 13:20:46 +0000 [pid=455] [origin=127.0.0.1] [request_id=c9e98ca5-317f-49ab-975b-13301ba28941] [tid=461] /src/conjur-server/app/domain/authentication/authenticate.rb:27:in `call'
INFO 2021/03/17 13:20:46 +0000 [pid=455] [origin=127.0.0.1] [request_id=c9e98ca5-317f-49ab-975b-13301ba28941] [tid=461] (eval):7:in `call'
INFO 2021/03/17 13:20:46 +0000 [pid=455] [origin=127.0.0.1] [request_id=c9e98ca5-317f-49ab-975b-13301ba28941] [tid=461] /src/conjur-server/app/controllers/authenticate_controller.rb:69:in `authenticate'
INFO 2021/03/17 13:20:46 +0000 [pid=455] [origin=127.0.0.1] [request_id=c9e98ca5-317f-49ab-975b-13301ba28941] [tid=461] /src/conjur-server/app/controllers/authenticate_controller.rb:95:in `authenticate_oidc'
INFO 2021/03/17 13:20:46 +0000 [pid=455] [origin=127.0.0.1] [request_id=c9e98ca5-317f-49ab-975b-13301ba28941] [tid=461] Completed 401 Unauthorized in 123ms

The output above has the authentication error, it has a minimal stack trace that can help us (or the customer) understand the
issue easily, and it is not very long and thus doesn't add too much to the defaut INFO log.
@orenbm orenbm mentioned this issue Mar 24, 2021
Merged
4 tasks
@izgeri izgeri mentioned this issue Mar 30, 2021
Closed
@izgeri
Copy link
Contributor

izgeri commented Mar 31, 2021

Tried this out for fun. Now a healthy, functioning k8s authenticator log looks like:

[origin=10.244.0.14] [request_id=43c4d2c5-3687-4c8f-8423-31f1051bbad6] [tid=41] Started POST "/authn-k8s/my-authenticator-id/inject_client_cert" for 10.244.0.14 at 2021-03-31 19:17:45 +0000
[origin=10.244.0.14] [request_id=43c4d2c5-3687-4c8f-8423-31f1051bbad6] [tid=41] Processing by AuthenticateController#k8s_inject_client_cert as HTML
[origin=10.244.0.14] [request_id=43c4d2c5-3687-4c8f-8423-31f1051bbad6] [tid=41]   Parameters: {:controller=>"authenticate", :action=>"k8s_inject_client_cert", :service_id=>"my-authenticator-id"}
[origin=10.244.0.14] [request_id=43c4d2c5-3687-4c8f-8423-31f1051bbad6] [tid=41] myConjurAccount:host:conjur/authn-k8s/my-authenticator-id/apps/test-app-secretless successfully injected client certificate with authenticator authn-k8s service myConjurAccount:webservice:conjur/authn-k8s/my-authenticator-id
[origin=10.244.0.14] [request_id=43c4d2c5-3687-4c8f-8423-31f1051bbad6] [tid=41] Completed 202 Accepted in 1308ms

and the logs when there is an authn error look like this (in this flow, the authenticator service isn't enabled on the server, eg CONJUR_AUTHENTICATORS isn't set correctly):

[origin=10.244.0.13] [request_id=2ea6e163-2025-44ae-92b7-f40b33d7c481] [tid=39] Started POST "/authn-k8s/my-authenticator-id/inject_client_cert" for 10.244.0.13 at 2021-03-31 19:54:30 +0000
[origin=10.244.0.13] [request_id=2ea6e163-2025-44ae-92b7-f40b33d7c481] [tid=39] Processing by AuthenticateController#k8s_inject_client_cert as HTML
[origin=10.244.0.13] [request_id=2ea6e163-2025-44ae-92b7-f40b33d7c481] [tid=39]   Parameters: {:controller=>"authenticate", :action=>"k8s_inject_client_cert", :service_id=>"my-authenticator-id"}
[origin=10.244.0.13] [request_id=2ea6e163-2025-44ae-92b7-f40b33d7c481] [tid=39] myConjurAccount:host:conjur/authn-k8s/my-authenticator-id/apps/test-app-summon-sidecar failed to inject client certificate with authenticator authn-k8s service myConjurAccount:webservice:conjur/authn-k8s/my-authenticator-id: CONJ00004E 'authn-k8s/my-authenticator-id' is not enabled
[origin=10.244.0.13] [request_id=2ea6e163-2025-44ae-92b7-f40b33d7c481] [tid=39] CONJ00048I Authentication Error: #<Errors::Authentication::Security::AuthenticatorNotWhitelisted: CONJ00004E 'authn-k8s/my-authenticator-id' is not enabled>
[origin=10.244.0.13] [request_id=2ea6e163-2025-44ae-92b7-f40b33d7c481] [tid=39] /opt/conjur-server/app/domain/authentication/security/validate_webservice_is_whitelisted.rb:41:in `validate_webservice_is_whitelisted'
[origin=10.244.0.13] [request_id=2ea6e163-2025-44ae-92b7-f40b33d7c481] [tid=39] /opt/conjur-server/app/domain/authentication/security/validate_webservice_is_whitelisted.rb:23:in `call'
[origin=10.244.0.13] [request_id=2ea6e163-2025-44ae-92b7-f40b33d7c481] [tid=39] (eval):7:in `call'
[origin=10.244.0.13] [request_id=2ea6e163-2025-44ae-92b7-f40b33d7c481] [tid=39] /opt/conjur-server/app/domain/authentication/authn_k8s/validate_pod_request.rb:41:in `validate_webservice_is_whitelisted'
[origin=10.244.0.13] [request_id=2ea6e163-2025-44ae-92b7-f40b33d7c481] [tid=39] /opt/conjur-server/app/domain/authentication/authn_k8s/validate_pod_request.rb:31:in `call'
[origin=10.244.0.13] [request_id=2ea6e163-2025-44ae-92b7-f40b33d7c481] [tid=39] (eval):7:in `call'
[origin=10.244.0.13] [request_id=2ea6e163-2025-44ae-92b7-f40b33d7c481] [tid=39] /opt/conjur-server/app/domain/authentication/authn_k8s/inject_client_cert.rb:66:in `validate'
[origin=10.244.0.13] [request_id=2ea6e163-2025-44ae-92b7-f40b33d7c481] [tid=39] /opt/conjur-server/app/domain/authentication/authn_k8s/inject_client_cert.rb:24:in `call'
[origin=10.244.0.13] [request_id=2ea6e163-2025-44ae-92b7-f40b33d7c481] [tid=39] (eval):7:in `call'
[origin=10.244.0.13] [request_id=2ea6e163-2025-44ae-92b7-f40b33d7c481] [tid=39] /opt/conjur-server/app/controllers/authenticate_controller.rb:123:in `k8s_inject_client_cert'
[origin=10.244.0.13] [request_id=2ea6e163-2025-44ae-92b7-f40b33d7c481] [tid=39] /opt/conjur-server/app/controllers/application_controller.rb:79:in `block in run_with_transaction'
[origin=10.244.0.13] [request_id=2ea6e163-2025-44ae-92b7-f40b33d7c481] [tid=39] /opt/conjur-server/app/controllers/application_controller.rb:78:in `run_with_transaction'
[origin=10.244.0.13] [request_id=2ea6e163-2025-44ae-92b7-f40b33d7c481] [tid=39] /opt/conjur-server/lib/rack/remove_request_parameters.rb:26:in `call'
[origin=10.244.0.13] [request_id=2ea6e163-2025-44ae-92b7-f40b33d7c481] [tid=39] /opt/conjur-server/lib/rack/default_content_type.rb:68:in `call'
[origin=10.244.0.13] [request_id=2ea6e163-2025-44ae-92b7-f40b33d7c481] [tid=39] Completed 401 Unauthorized in 27ms

In particular, with the server running in info mode this is clearly visible in the logs:

Authentication Error: #<Errors::Authentication::Security::AuthenticatorNotWhitelisted: CONJ00004E 'authn-k8s/my-authenticator-id' is not enabled>

💥 🎉

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
component/conjur kind/enhancement
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Print authentication error stack-trace in INFO level cyberark/conjur
2 participants
@izgeri @orenbm