Internal call from oathkeeper to hydra introspect url timeout

[stanleyyuenyiu]

Describe the bug

we deploy the oathkeeper as api gateway and hydra as oauth into kubernetes ENV,

we use oauth2_introspection as the authenticators

then we setup the introspection_url to internal URL of kubernetes
(e.g http://hydra-admin.uat:4445/oauth2/introspect

we tested inside the pod of oathkeeper, and it is able to ping or curl to http://hydra-admin.uat:4445/oauth2/introspect (yes, we knew that it is require to add header X-Forwarded-Proto: https)

we setup the access rules for a single api to use the authenticators handler oauth2_introspection

and we also setup the TLS Termination of hydra to allow it from 0.0.0.0/0 (anywhere)

while we call the api gateway from public network and it said timeout becoz of http://hydra-admin.uat:4445/oauth2/introspect

we change to the introspection_url to the public url of the hydra admin, and it success without timeout

Expected: internal URL can be used in introspection_url
Actual: internal URL cant be used in introspection_url

Reproducing the bug

Steps to reproduce the behavior:

1. Make API Request to with Postman curl https://apigateway.uat.mydomain.com/mono-service/myapipath -H 'Authorization: bearer 47TCCYLjK1tCGRyrqVW3tnVNkm_QglJ7h2dpZD-3-0s.09wj-tAwqnhKsBSzxCHF7cp18ebKRyW0aVlBuxCSIy0'
2. Request fails with response: { "error": { "code": 500, "request": "0d145068519d20b64082fac0292bc2b0", "message": "Post http://hydra-admin.uat:4445/oauth2/introspect: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)" } }

Server logs

time="2019-08-27T02:08:07Z" level=warning msg="The authentication handler encountered an error" access_url="http://apigateway.uat.mydomain.com/mono-service/myapipath" 
authentication_handler=oauth2_introspection error="Post http://hydra-admin.uat:4445/oauth2/introspect: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)" granted=false reason_id=authentication_handler_error

time="2019-08-27T02:08:07Z" level=warning msg="Access request denied" access_url="http://apigateway.uat.mydomain.com/mono-service/myapipath" error="Post http://hydra-admin.uat:4445/oauth2/introspect: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)" granted=false

time="2019-08-27T02:08:07Z" level=error msg="An error occurred while handling a request" code=500 debug= details="map[]" error="Post http://hydra-admin.uat:4445/oauth2/introspect: net/http: request canceled while waiting for connection (Client.Timeout exceeded while awaiting headers)" reason= request-id=8924ee421377a913ff3fa60bd1f24aea status=500 trace="Stack trace: \ngithub.com/ory/oathkeeper/pipeline/authn.(*AuthenticatorOAuth2Introspection).Authenticate\n\t/go/src/github.com/ory/oathkeeper/pipeline/authn/authenticator_oauth2_introspection.go:87\ngithub.com/ory/oathkeeper/proxy.(*RequestHandler).HandleRequest\n\t/go/src/github.com/ory/oathkeeper/proxy/request_handler.go:91\ngithub.com/ory/oathkeeper/proxy.(*Proxy).Director\n\t/go/src/github.com/ory/oathkeeper/proxy/proxy.go:116\nnet/http/httputil.(*ReverseProxy).ServeHTTP\n\t/usr/local/go/src/net/http/httputil/reverseproxy.go:216\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/meatballhat/negroni-logrus.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/meatballhat/negroni-logrus@v0.0.0-20170801195057-31067281800f/middleware.go:136\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.66/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\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2774\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1878\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1337" writer=JSON

time="2019-08-27T02:08:07Z" level=info msg="completed handling request" measure#oathkeeper-proxy.latency=1024359913 method=GET remote=127.0.0.1 request=/mono-service/myapipath request_id=8924ee421377a913ff3fa60bd1f24aea status=500 text_status="Internal Server Error" took=1.024359913s

Expected behavior

Expected: internal URL can be used in introspection_url

Environment

kubernetes :
Server Version: version.Info {Major:"1", Minor:"9", GitVersion:"v1.9.3", GitCommit:"d2835416544f298c919e2ead3be3d0864b52323b", GitTreeState:"clean", BuildDate:"2018-02-07T11:55:20Z", GoVersion:"go1.9.2", Compiler:"gc", Platform:"linux/amd64"}

Ingress controller:
quay.io/kubernetes-ingress-controller/nginx-ingress-controller:0.24.1

oathkeeper
oryd/oathkeeper:v0.17.0-beta.1

hydra
oryd/hydra:v1.0.0

[stanleyyuenyiu]

From the source file authenticator_oauth2_introspection.go

i dont see the there is any header added while try to call the introspection_url (X-Forwarded-Proto: https), is it one of the reason?

line 84 of authenticator_oauth2_introspection.go

body := url.Values{"token": {token}, "scope": {strings.Join(cf.Scopes, " ")}} resp, err := a.client.Post(a.c.AuthenticatorOAuth2TokenIntrospectionIntrospectionURL().String(), "application/x-www-form-urlencoded", strings.NewReader(body.Encode())) if err != nil { return nil, errors.WithStack(err) }

[aeneasr]

Thank you for this very detailed bug report! I think indeed that this could be caused by the missing forward header. Are you calling hydra directly, or through a proxy?

[stanleyyuenyiu]

@aeneasr
i call the apigateway(oathkeeper) by using postman,

and since i setup the introspection_url in oathkeeper with internal service endpoint (e.g http://hydra-admin.uat:4445/oauth2/introspect)

i assume oathkeeper will check my token by using http.Client.post http://hydra-admin.uat:4445/oauth2/introspect

and i resulted an timeout error, but if i change introspection_url to public endpoint of hydra, it work fine

in the last hour, i create a golang application by using net/http to call the internal service endpoint and deploy to my kubenetes, it work too

so i believe it is not related to forward header or something

here is my simple code

package main

import (
    "encoding/json"
    "net/http"
    "net/url"
    "strings"
    "log"
    "time"
)

type RetryPolicy func(*http.Response, error) (retry bool)

type ResilientRoundTripper struct {
        // RoundTripper the wrapped RoundTripper.
        http.RoundTripper

        // ShouldRetry defines a strategy for retries.
        ShouldRetry RetryPolicy
        MaxInterval    time.Duration
        MaxElapsedTime time.Duration
}
var _ http.RoundTripper = new(ResilientRoundTripper)

type AuthenticatorOAuth2IntrospectionResult struct {
    Active    bool                   `json:"active"`
    Extra     map[string]interface{} `json:"ext"`
    Subject   string                 `json:"sub,omitempty"`
    Username  string                 `json:"username"`
    Audience  []string               `json:"aud"`
    TokenType string                 `json:"token_type"`
    Issuer    string                 `json:"iss"`
    ClientID  string                 `json:"client_id,omitempty"`
    Scope     string                 `json:"scope,omitempty"`
}

func defaultShouldRetry(res *http.Response, err error) bool {
        if err != nil || res.StatusCode == 0 || res.StatusCode >= 500 {
                return true
        }
        return false
}

func NewDefaultResilientRoundTripper(
        backOffMaxInterval time.Duration,
        backOffDieAfter time.Duration,
) *ResilientRoundTripper {
        return &ResilientRoundTripper{
                RoundTripper:   http.DefaultTransport,
                ShouldRetry:    defaultShouldRetry,
                MaxInterval:    backOffMaxInterval,
                MaxElapsedTime: backOffDieAfter,
        }
}

func NewResilientRoundTripper(
    roundTripper http.RoundTripper,
    backOffMaxInterval time.Duration,
    backOffDieAfter time.Duration,
) *ResilientRoundTripper {
    return &ResilientRoundTripper{
        RoundTripper:   roundTripper,
        ShouldRetry:    defaultShouldRetry,
        MaxInterval:    backOffMaxInterval,
        MaxElapsedTime: backOffDieAfter,
    }
}

func NewResilientClientLatencyToleranceSmall(rt http.RoundTripper) *http.Client {
    transport := NewDefaultResilientRoundTripper(time.Millisecond*50, time.Second)
    if rt != nil {
        transport = NewResilientRoundTripper(rt, time.Millisecond*50, time.Second)
    }

    return &http.Client{
        Timeout:   time.Millisecond * 500,
        Transport: transport,
    }
}

func main() {       
        var rt http.RoundTripper
        
        client := NewResilientClientLatencyToleranceSmall(rt)

        body := url.Values{"token": {"1234"}, "scope": {"none"}}                                           
                                                                                                                                                                                                                                                                                                                             
        var i AuthenticatorOAuth2IntrospectionResult                                                                                                                 
                                                                                                                                                                     
        resp, err := client.Post("http://release-name-hydra-admin.uat:4445/oauth2/introspect", "application/x-www-form-urlencoded", strings.NewReader(body.Encode()))
        if err != nil {                                              
            log.Print( err)                                          
        }                                                            
                                                                     
        defer resp.Body.Close()                                      
                                                                     
        if err := json.NewDecoder(resp.Body).Decode(&i); err != nil {
             log.Print( err)                                     
        }                                                    
        log.Print(i)                                                       
                                                                       
}  

and here is the docker file for you to build this code

FROM golang:1.11.2-alpine

WORKDIR /mytesting

ADD ./mytesting /mytesting

RUN cd /mytesting && go build

EXPOSE 1234

ENTRYPOINT ./mytesting

[stanleyyuenyiu]

Thank you for this very detailed bug report! I think indeed that this could be caused by the missing forward header. Are you calling hydra directly, or through a proxy?

Any Idea?

[stanleyyuenyiu]

i just double check the log from Hydra, turnout it is the timeout message from oathkeeper confuse me

it really like what you said, it missing the header Forwarded-Proto, but im not sure how to make it work?

as i already set the hydra "tls.allow_termination_from" to

• 127.0.0.1/32
• 0.0.0.0/0

so 0.0.0.0/0 wouldnt work at all?

time="2019-08-29T05:36:28Z" level=info msg="started handling request" method=POST remote="100.96.30.75:59388" request=/oauth2/introspect
time="2019-08-29T05:36:28Z" level=warning msg="Could not serve http connection" error="X-Forwarded-Proto header is missing"
time="2019-08-29T05:36:28Z" level=error msg="An error occurred while handling a request" code=502 debug= details="map[]" error="can not serve request over insecure http" reason= request-id= status= trace="Stack trace: \ngithub.com/ory/hydra/x.RejectInsecureRequests.func1\n\t/go/src/github.com/ory/hydra/x/tls_termination.go:75\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/metricsx.(*Service).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.64/metricsx/middleware.go:260\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/ory/hydra/metrics/prometheus.(*MetricsManager).ServeHTTP\n\t/go/src/github.com/ory/hydra/metrics/prometheus/middleware.go:26\ngithub.com/urfave/negroni.middleware.ServeHTTP\n\t/go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38\ngithub.com/meatballhat/negroni-logrus.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/meatballhat/negroni-logrus@v0.0.0-20170801195057-31067281800f/middleware.go:136\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:1995\nnet/http.serverHandler.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2774\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1878\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1337" writer=JSON
time="2019-08-29T05:36:28Z" level=info msg="completed handling request" measure#hydra/admin: https://oauth-uat.lkkhpgdi.com/.latency=638983 method=POST remote="100.96.30.75:59388" request=/oauth2/introspect status=502 text_status="Bad Gateway" took="638.983µs"

[aeneasr]

We simply need to add the ability to set X-Fowarded-Proto header, then it should be ok. See #95

[stanleyyuenyiu]

please also make it on pre_authentication too

[aeneasr]

I am closing this issue as it has not received any engagement from the community or maintainers in a long time. That does not imply that the issue has no merit. If you feel strongly about this issue

• open a PR referencing and resolving the issue;
• leave a comment on it and discuss ideas how you could contribute towards resolving it;
• open a new issue with updated details and a plan on resolving the issue.

We are cleaning up issues every now and then, primarily to keep the 4000+ issues in our backlog in check and to prevent maintainer burnout. Burnout in open source maintainership is a widespread and serious issue. It can lead to severe personal and health issues as well as enabling catastrophic attack vectors.

Thank you to anyone who participated in the issue! 🙏✌️