Request logging for 4xx HTTP status as error

sawadashota commented 2 years ago

Preflight checklist

[X] I could not find a solution in the existing issues, docs, nor discussions.
[X] I agree to follow this project's Code of Conduct.
[X] I have read and am following this repository's Contribution Guidelines.
[X] This issue affects my Ory Cloud project.
[X] I have joined the Ory Community Slack.
[ ] I am signed up to the Ory Security Patch Newsletter.

Describe the bug

Request error logging for 4xx HTTP status (ex. 404 Not Found) logs as error. Handlers in oathkeeper writes logs this as warning but herodot writes logs as error. If we consider error log is action required, it would be warn level when 4xx HTTP status. https://github.com/ory/herodot/blob/4f8e0125bb42446c328ac4bcec941f70ce538c3d/error_reporter.go?_pjax=%23js-repo-pjax-container%3Afirst-of-type%2C%20div%5Bitemtype%3D%22http%3A%2F%2Fschema.org%2FSoftwareSourceCode%22%5D%20main%3Afirst-of-type%2C%20%5Bdata-pjax-container%5D%3Afirst-of-type#L24

Reproducing the bug

Run docker-compose up
Access to http://localhost:4455/
4 lines of log are appeared for a request. One of them is level=error although 404 Not Found status.

Relevant log output

oathkeeper_1  | time=2022-01-04T08:30:06Z level=info msg=started handling request http_request=map[headers:map[accept:text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9 accept-encoding:gzip, deflate, br accept-language:en-US,en;q=0.9,ja;q=0.8 cookie:Value is sensitive and has been redacted. To see the value set config key "log.leak_sensitive_values = true" or environment variable "LOG_LEAK_SENSITIVE_VALUES=true". user-agent:Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.110 Safari/537.36] host:localhost:4455 method:GET path:/ query:<nil> remote:172.22.0.1:63468 scheme:http]
oathkeeper_1  | time=2022-01-04T08:30:06Z level=warning msg=Access request denied audience=application error=map[debug: message:Requested url does not match any rules reason: status:Not Found status_code:404] granted=false http_host=localhost:4455 http_method=GET http_url=http://localhost:4455/ http_user_agent=Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.110 Safari/537.36 service_name=ORY Oathkeeper service_version=master
oathkeeper_1  | time=2022-01-04T08:30:06Z level=error msg=An error occurred while handling a request code=404 debug= details=map[] error=Requested url does not match any rules reason= request-id= status=404 writer=JSON
oathkeeper_1  | time=2022-01-04T08:30:06Z level=info msg=completed handling request http_request=map[headers:map[accept:text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9 accept-encoding:gzip, deflate, br accept-language:en-US,en;q=0.9,ja;q=0.8 cookie:Value is sensitive and has been redacted. To see the value set config key "log.leak_sensitive_values = true" or environment variable "LOG_LEAK_SENSITIVE_VALUES=true". user-agent:Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.110 Safari/537.36] host:localhost:4455 method:GET path:/ query:<nil> remote:172.22.0.1:63468 scheme:http] http_response=map[status:404 text_status:Not Found took:7.2236ms]

Relevant configuration

https://github.com/ory/oathkeeper/blob/master/.docker_compose/config.yaml

Version

master

On which operating system are you observing this issue?

macOS

In which environment are you deploying?

Docker

Additional Context

No response

aeneasr commented 2 years ago

I even think that we could log these as level info?

sawadashota commented 2 years ago

Or level warning is reasonable I think. Another line for this request logged as warning.

oathkeeper_1  | time=2022-01-04T08:30:06Z level=warning msg=Access request denied audience=application error=map[debug: message:Requested url does not match any rules reason: status:Not Found status_code:404] granted=false http_host=localhost:4455 http_method=GET http_url=http://localhost:4455/ http_user_agent=Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.110 Safari/537.36 service_name=ORY Oathkeeper service_version=master