Clean up logging in case of invalid credentials

[catper]

Is your feature request related to a problem? Please describe.

When a request gets denied due to invalid credentials (and perhaps in other cases too but this is the only one that's bothering me atm) a lot of logs are produced and the information within them tends to overlap. I also think that the log level for some of them isn't really motivated. When something like this happens during load/soak tests, output really goes through the roof.

Describe the solution you'd like

It would be nice if the logs could be cleaned up a bit and the levels at which logs are emitted were re-evaluated.

Additional context
Example output:

2020-08-26T13:23:35.836628111Z time="2020-08-26T13:23:35Z" level=warning msg="The authentication handler encountered an error" authentication_handler=oauth2_introspection error="Access credentials are invalid" granted=false http_host=test.istio-ingress.com http_method=GET http_url="http://test.istio-ingress.com/v1/greetings" http_user_agent= reason_id=authentication_handler_error rule_id=authenticate
2020-08-26T13:23:35.836636521Z time="2020-08-26T13:23:35Z" level=warning msg="Access request denied" error="Access credentials are invalid" granted=false http_host=test.istio-ingress.com http_method=GET http_url="http://test.istio-ingress.com/v1/greetings" http_user_agent=
2020-08-26T13:23:35.836674487Z time="2020-08-26T13:23:35Z" level=error msg="An error occurred while handling a request" code=401 debug= details="map[]" error="The request could not be authorized" reason= request-id=b62bdf80-a6bc-4c9a-a8dc-9c47ccde8fd4 status=401 writer=JSON
2020-08-26T13:23:35.836709377Z time="2020-08-26T13:23:35Z" level=info msg="completed handling request" measure#oathkeeper-api.latency=5958530 method=GET remote="127.0.0.1:41592" request=/decisions/v1/greetings request_id=b62bdf80-a6bc-4c9a-a8dc-9c47ccde8fd4 status=401 text_status=Unauthorized took=5.95853ms

The first two messages, in my opinion, basically say the same thing and could be condensed into one. I also think they belong on info level, not warning as they don't actually indicate a problem with the application, just with the request.

I feel the same way about the third message, which is on error level. Perhaps we have differing views of how logging is best applied but invalid credentials in no way indicates an issue with the application so why is this considered important enough to warrant a message on error level? On a side note, the reason and details fields are empty in this particular message so there isn't really even any insight to be gained from it. On its own this message seems to add no value?

What is the motivation for these particular messages and their corresponding log level and how would you feel about changing things?

[aeneasr]

Yes, this is on the roadmap (see the pinned issue) with the idea of adding an audit logger responsible for these things! Sorry for the late reply btw :)

[catper]

i'm guessing adding an audit logger is a fairly big change, is there an eta for this? if this is something that is likely to take a while, how about just changing these warnings/errors to infos with the regular logger in the meantime?

[aeneasr]

Yeah, we can do that!