An error occurred while handling a request

[lanphan]

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.
• [ ] 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

I checked log in oathkeeper and found logs like this:

{"code":401,"debug":"","details":{},"error":"Access credentials are invalid","level":"error","msg":"An error occurred while handling a request","reason":"","request-id":"","status":401,"time":"2021-12-20T02:09:00Z","writer":"JSON"}

Noted that in the time this log occurs, there is no error log / 401 logs from kratos. My question is, what is exactly error occurred in oathkeeper and which request oathkeeper handles at that time? I think the log doesn't contain enough information for debug (even I already set debug level = DEBUG)

My expectation for log should be similar like the log below:

{"audience":"application","error":{"debug":"","message":"Access credentials are invalid","reason":"","status":"Unauthorized","status_code":401},"granted":false,"http_host":"abc.com","http_method":"POST","http_url":"https://abc.com/xyz/api","http_user_agent":"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/96.0.4664.45 Safari/537.36","level":"info","msg":"Access request denied","service_name":"ORY Oathkeeper","service_version":"master","time":"2021-12-20T02:09:00Z"}

Reproducing the bug

It's not possible to reproduce this log

Relevant log output

none

Relevant configuration

No response

Version

v0.38.16-beta.1

On which operating system are you observing this issue?

Linux

In which environment are you deploying?

Kubernetes

Additional Context

No response

[lanphan]

Hi @aeneasr , Do you have any clue about why this bug happens? It's appreciated if I have your advice, then I can start digging deeper.

[lanphan]

just because I got so much that issue lately

[aeneasr]

Its possible that the upstream "https://abc.com/xyz/api" was too slow or returned that the credential is not valid

[hernangonzalez]

I've been playing with it locally and am seeing the same error. Also no logs from kratos.

rules

- 
  id: "httpbin:public"
  upstream:
    preserve_host: false
    url: "http://httpbin.org/anything"
  match:
    url: "http://<127.0.0.1|localhost>:4455/bin"
    methods:
      - GET
      - POST
      - PUT
      - DELETE
      - PATCH
  authenticators:
    -
      handler: cookie_session
  authorizer:
    handler: allow
  mutators:
    - handler: id_token

config

serve:
  proxy:
    port: 4455
  api:
    port: 4456

access_rules:
  repositories:
    - file://./keeper/rules.yaml

authenticators:
  noop:
    enabled: true
  cookie_session:
    enabled: true
    config:
      check_session_url: http://127.0.0.1:4433/sessions/whoami
      preserve_path: true
      extra_from: "@this"
      subject_from: "identity.id"

authorizers:
  allow:
    enabled: true

mutators:
  noop:
    enabled: true
  id_token:
    enabled: true
    config:
      issuer_url: http://127.0.0.1:4455/
      jwks_url: file://./keeper/jwks.json
      claims: |
        {
          "session": {{ .Extra | toJson }}
        }