https://www.ory.sh/ logo
Join Slack
Powered by
```{ "audience": "application", "error": {...
# talk-oathkeeper
b
Copy code
{
    "audience": "application",
    "error": {
        "message": "EOF",
        "trace": "\<http://ngithub.com/ory/oathkeeper/proxy.(*Proxy).RoundTrip\n\t/home/ory/proxy/proxy.go:94\nnet/http/httputil.(*ReverseProxy).ServeHTTP\n\t/usr/local/go/src/net/http/httputil/reverseproxy.go:288\ngithub.com/urfave/negroni.Wrap.func1\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:46\ngithub.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/ory/x/reqlog.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.163-1/reqlog/middleware.go:134\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/ory/oathkeeper/metrics.(*Middleware).ServeHTTP\n\t/home/ory/metrics/middleware.go:88\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/ory/x/metricsx.(*Service).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.163-1/metricsx/middleware.go:261\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.(*Negroni).ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:96\ngithub.com/rs/cors.(*Cors).Handler.func1\n\t/go/pkg/mod/github.com/rs/cors@v1.6.0/cors.go:207\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2069\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2887\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1952\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1371|ngithub.com/ory/oathkeeper/proxy.(*Proxy).RoundTrip\n\t/home/ory/proxy/proxy.go:94\nnet/http/httputil.(*ReverseProxy).ServeHTTP\n\t/usr/local/go/src/net/http/httputil/reverseproxy.go:288\ngithub.com/urfave/negroni.Wrap.func1\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:46\ngithub.com/urfave/negroni.HandlerFunc.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/ory/x/reqlog.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.163-1/reqlog/middleware.go:134\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/ory/oathkeeper/metrics.(*Middleware).ServeHTTP\n\t/home/ory/metrics/middleware.go:88\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/ory/x/metricsx.(*Service).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.163-1/metricsx/middleware.go:261\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/urfave/negroni.(*Negroni).ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:96\ngithub.com/rs/cors.(*Cors).Handler.func1\n\t/go/pkg/mod/github.com/rs/cors@v1.6.0/cors.go:207\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2069\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2887\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1952\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1371>"
    },
    "file": "/home/ory/proxy/proxy.go:97",
    "func": "<http://github.com/ory/oathkeeper/proxy.(*Proxy).RoundTrip|github.com/ory/oathkeeper/proxy.(*Proxy).RoundTrip>",
    "granted": false,
    "http_host": "<http://api.stagedelemental.com|api.stagedelemental.com>",
    "http_method": "POST",
    "http_url": "<http://kratos-direct.internal:4433/self-service/registration?flow=59a8bce2-00c7-454d-b0c4-fff046dc5f73>",
    "http_user_agent": "python-requests/2.25.1",
    "level": "warning",
    "msg": "Access request denied because roundtrip failed",
    "service_name": "ORY Oathkeeper",
    "service_version": "v0.38.15-beta.1",
    "subject": "",
    "time": "2022-03-25T13:40:41Z"
}
d
Hello. Could you share your access rules without any sensitive information?
Usually this behavior happens with network configuration mismatch or network connectivity issues
b
sure - ill go grab them. Definitely feels like a network problem, when we had it routed internally through an AWS load balancer the LB consistently reports getting 20s of response and then reports essentially that the target ( kratos ) errored in some way. The fact that its always the same time obviously is suspicious.
Copy code
- id: "ory:kratos:public"
  upstream:
    preserve_host: true
    url: "<http://kratos-direct.internal.stagedapp.com:4433>"
    strip_path: /.ory/kratos/public
  match:
    url: "<http://api.stagedapp.com/.ory/kratos/public/><**>"
    methods:
      - GET
      - POST
      - PUT
      - DELETE
      - PATCH
  authenticators:
    - handler: noop
  authorizer:
    handler: allow
  mutators:
    - handler: noop

- id: "app:api:anonymous"
  upstream:
    preserve_host: true
    url: "<http://api.internal.stagedapp.com>"
  match:
    url: "<http://api.stagedapp.com/><{healthcheck}{/,}>"
    methods:
      - GET
  authenticators:
    - handler: noop
  authorizer:
    handler: allow
  mutators:
    - handler: noop

- id: "app:api:protected"
  upstream:
    preserve_host: true
    url: "<http://api.internal.stagedapp.com>"
  match:                                                
    url: "<http://api.stagedapp.com/><*>/api/v1/<**>"
    methods:
      - GET
      - POST
      - PUT
      - DELETE
      - PATCH
  authenticators:
    - handler: cookie_session
    - handler: bearer_token
    - handler: anonymous
  authorizer:
   handler: allow
  mutators:
    - handler: id_token
to reiterate .. the GET request to initialize the flow has no problem getting to kratos and back. Its just the actual POST with the registration payload that gets to kratos, but not back
d
EOF
error can happen when backend closes connection prematurely
Could you please check your logs, because there can be panics for Kratos
I think that’s the only reason that can happen with your case because configuration of oathkeeper looks good
b
there isn't a panic in the log - kratos keeps running fine. the last relevant kratos entry is the one i posted .. it is indicating a successful registration
Copy code
"http_response": {
        "headers": {
            "cache-control": "private, no-cache, no-store, must-revalidate",
            "content-type": "application/json; charset=utf-8",
            "vary": "Cookie"
        },
        "size": 809,
        "status": 200,
        "text_status": "OK",
        "took": 20267234453
    },
    "level": "info",
    "msg": "completed handling request",
    "time": "2022-03-25T13:40:41Z"
there are log records for the various steps in the process .. "msg": "A new identity has registered using self-service registration.", "msg": "Running PostRegistrationPostPersistHooks.", "ExecutePostRegistrationPostPersistHook completed successfully." , Post registration execution hooks completed successfully.", "msg": "completed handling request"
d
Okay. I’ll check trace from oathkeeper
I assume something wrong with 
X-Forwarded-For
headers or with CORS settings
Could you share your CORS settings please in 
oathkeeper.yml
?
b
here's the current oathkeeper config .. will go check our ENV as well for overrides:
access_rules: matching_strategy: glob repositories: - file:///home/ory/access-rules.yml errors: fallback: - json handlers: redirect: enabled: true config: when: - error: - unauthorized - forbidden request: header: accept: - text/html json: enabled: true config: verbose: false log: level: debug format: json authenticators: bearer_token: enabled: true config: preserve_path: true extra_from: "@this" token_from: header: X-Session-Token anonymous: enabled: true config: subject: guest cookie_session: enabled: true config: preserve_path: true extra_from: "@this" subject_from: "identity.id" only: - ory_kratos_session noop: enabled: true authorizers: allow: enabled: true mutators: noop: enabled: true id_token: enabled: true config: jwks_url: file:///home/ory/id_token.jwks.json claims: '{ "id": "{{ .Extra.identity.id }}", "email": "{{ .Extra.identity.traits.email }}", "verified": "{{ (index .Extra.identity.verifiable_addresses 0).verified }}" }'
here are the ENV vars that actually set the CORS values:
Copy code
AUTHENTICATORS_BEARER_TOKEN_CONFIG_CHECK_SESSION_URL    <http://kratos.internal.stagedapp.com/sessions/whoami>
AUTHENTICATORS_COOKIE_SESSION_CONFIG_CHECK_SESSION_URL <http://kratos.internal.stagedapp.com/sessions/whoami>
ERRORS_HANDLERS_REDIRECT_CONFIG_TO <http://stagedapp.com/auth/login>
LOG_LEAK_SENSITIVE_VALUES  TRUE
LOG_LEVEL  trace
MUTATORS_ID_TOKEN_CONFIG_ISSUER_URL    <http://api.internal.stagedapp.com>
SERVE_PROXY_CORS_ALLOW_CREDENTIALS TRUE
SERVE_PROXY_CORS_ALLOWED_HEADERS   Authorization,Content-Type
SERVE_PROXY_CORS_ALLOWED_ORIGINS   <https://stagedapp.com>,https://*.<http://stagedapp.com|stagedapp.com>
SERVE_PROXY_CORS_ENABLED   TRUE
SERVE_PROXY_CORS_EXPOSED_HEADERS   Content-Type
SERVE_PROXY_TIMEOUT_IDLE   30s
SERVE_PROXY_TIMEOUT_READ   30s
SERVE_PROXY_TIMEOUT_WRITE  30s
d
What’s CORS settings for Kratos?
Copy code
SERVE_PROXY_CORS_ALLOWED_HEADERS   Authorization,Content-Type
SERVE_PROXY_CORS_EXPOSED_HEADERS   Content-Type
Could you try to run it without these headers?
b
so remove those env vars? yeah .. will try
also noticed i should turn on CORS debug at the oathkeeper level
kratos CORS env vars:
Copy code
LOG_LEAK_SENSITIVE_VALUES   TRUE
LOG_LEVEL  trace
SELFSERVICE_DEFAULT_BROWSER_RETURN_URL <https://www.stagedapp.com/>
SELFSERVICE_FLOWS_RECOVERY_AFTER_DEFAULT_BROWSER_RETURN_URL    <https://www.stagedapp.com/dashboard>
SELFSERVICE_FLOWS_REGISTRATION_UI_URL  <https://www.stagedapp.com/auth/registration>
SELFSERVICE_FLOWS_SETTINGS_AFTER_PASSWORD_DEFAULT_BROWSER_RETURN_URL   <https://www.stagedapp.com/dashboard>
SELFSERVICE_FLOWS_SETTINGS_UI_URL  <https://www.stagedapp.com/user-settings>
SELFSERVICE_FLOWS_VERIFICATION_AFTER_DEFAULT_BROWSER_RETURN_URL    <https://www.stagedapp.com/dashboard>
SELFSERVICE_WHITELISTED_RETURN_URLS    <https://stagedapp.com>,<https://www.stagedapp.com>,<https://api.stagedapp.com>
SERVE_PUBLIC_BASE_URL  <https://api.stagedapp.com/.ory/kratos/public>
SERVE_PUBLIC_CORS_ALLOW_CREDENTIALS    TRUE
SERVE_PUBLIC_CORS_ALLOWED_ORIGINS  <https://www.stagedapp.com>
SERVE_PUBLIC_CORS_ENABLED  FALSE
d
So.. basically according to the trace that you given your request fails because it can’t get 
X-Forwarded-For
header from Kratos on Post request. Oathkeeper uses negroni middleware and it uses rs. Somehow it fails on POST only
And I don’t know how to reproduce this error locally..
b
ill turn on the CORS error reporting in oathkeeper and see if that provides something useful.
nothing more reported with the CORS debug set to true in oathkeeper. Adjusting those env vars now
thanks for the assistance BTW 🙂 we are adjusting some configs so its all set in one place to make that change you asked for so it will be a few mins
ok - so i set up a direct connection to Kratos to take oathkeeper out of the equation, and its still the same problem. So at least thats progress
its behind the AWS LB at the moment so i can't investigate the raw output from kratos but I am working on that now - getting a direct connection
To wrap up this convo .. the problem was related to some thing in the AWS networking .. as if it was dropping packets on the larger payloads that resulted from an actual registration POST. Perhaps kratos error logging could show that if it was able to detect an incomplete communication with the requesting server , but it wasn't actually a kratos issue. Thanks for the assistance
🙌 1
4 Views
Open in Slack
PreviousNext
Powered by