Refresh token flow breaks up during db server downtime #1928

struhtanov · 2020-06-25T10:29:58Z

Describe the bug

Sometimes I start receiving "The refresh token has not been found: : not_found" during refresh token flow. After that I no more can refresh the token, end user has to pass oauth flow again.

Reproducing the bug

I didn't spent enough time to reproduce it on local setup. First attempts fails. Even on production setup it's not reproduced every time. So I'll describe steps on production setup instead.

1.) I have client, that infinitely refreshes oauth token. Here is NodeJs code snippet of express app, that handles oauth flow and then starts infinite token refresh:

const args = require("./args");
const express = require("express");
const ClientOAuth2 = require("client-oauth2");

const fiberyTheAuth = new ClientOAuth2({
  clientId: args.authClientId,
  clientSecret: args.authClientSecret,
  accessTokenUri: `${args.authUrl}/oauth2/token`,
  authorizationUri: `${args.authUrl}/oauth2/auth`,
  redirectUri: args.redirectUri,
  scopes: ["openid", "offline"],
  state: "asdfasfdsafd",
});

const fiberyAuth = fiberyTheAuth;

const app = express();

app.get("/", function (req, res, next) {
  var uri = fiberyAuth.code.getUri();
  res.redirect(uri)
});

const refresh = async (token) => {
  const oldToken = fiberyAuth.createToken(token.data.access_token, token.data.refresh_token);
  const time = Date.now();
  try {
    const refreshed = await oldToken.refresh();
    logger.info(`Token refreshed.`, {elapsedTime: Date.now() - time});
    return refreshed;
  } catch(e) {
    sendToSlack(`Token was not refreshed`, getErrorMeta(e))
    logger.error("Token was not refreshed", {...getErrorMeta(e), oldToken: oldToken.accessToken});
    return oldToken;
  }
};

const repeatRefresh = async (token) => {
  const newToken = await refresh(token);
  setTimeout(() => repeatRefresh(newToken), args.refreshInterval);
}

app.get("/callback", async function (req, res, next) {
  try {
    const token = await fiberyAuth.code.getToken(args.redirectUri.includes("localhost") ? req.originalUrl : `/api/authCheck${req.originalUrl}`);
    logger.info(token);
    repeatRefresh(token);

    res.sendStatus(200);
  } catch(e){
    res.sendStatus(401);
    logger.info("Failed to get token", getErrorMeta(e));
  }
});

module.exports = {app};

2.) In my kubernetes cluster I have v1.4.5-alpine hydra version. I use helm chart of this version. But I believe it is not important. I have replicaCount set to 3, and use postgres as database.

3.) At some point of time of the day my postgres db experience downtime, which is related to current cloud provider.

4.) After that sometimes my client cannot refresh token any more. Here are part of hydra logs:

{"debug":"failed to connect to `host=stolon-proxy-service.postgres.svc.cluster.local user=hydra database=hydra`: dial error (dial tcp 100.75.226.174:5432: operation was canceled)","description":"Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)","error":"invalid_client","level":"error","msg":"An error occurred","time":"2020-06-25T09:04:36Z"}
{"debug":"failed to connect to `host=stolon-proxy-service.postgres.svc.cluster.local user=hydra database=hydra`: dial error (dial tcp 100.75.226.174:5432: operation was canceled)","description":"Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)","error":"invalid_client","level":"error","msg":"An error occurred","time":"2020-06-25T09:04:40Z"}
{"error":"context canceled","level":"error","msg":"An error occurred","time":"2020-06-25T09:08:54Z"}
{"debug":"The refresh token has not been found: : not_found","description":"The provided authorization grant (e.g., authorization code, resource owner credentials) or refresh token is invalid, expired, revoked, does not match the redirection URI used in the authorization request, or was issued to another client","error":"invalid_grant","level":"error","msg":"An error occurred","time":"2020-06-25T09:08:54Z"}

I removed log records with similar content to keep posted logs short.
After 09:08:54 every attempt to refresh token gets same not_found error.

Server configuration

# Number of ORY Hydra members
replicaCount: 3

image:
  # ORY Hydra image
  repository: oryd/hydra
  # ORY Hydra version
  tag: v1.4.5-alpine
  # Image pull policy
  pullPolicy: IfNotPresent

# Image pull secrets
imagePullSecrets: []
# Chart name override
nameOverride: ""
# Full chart name override
fullnameOverride: ""

# Configures the Kubernetes service
service:
  # Configures the Kubernetes service for the proxy port.
  public:
    # En-/disable the service
    enabled: true
    # The service type
    type: ClusterIP
    # The service port
    port: 4444
    # If you do want to specify annotations, uncomment the following
    # lines, adjust them as necessary, and remove the curly braces after 'annotations:'.
    annotations:
      kong/request-host: ""
      kong/request-path: "/"
      kong/preserve-host: "true"
      kong/strip-request-path: "true"

    # kubernetes.io/ingress.class: nginx
    # kubernetes.io/tls-acme: "true"
  # Configures the Kubernetes service for the api port.
  admin:
    # En-/disable the service
    enabled: true
    # The service type
    type: ClusterIP
    # The service port
    port: 4445
    # If you do want to specify annotations, uncomment the following
    # lines, adjust them as necessary, and remove the curly braces after 'annotations:'.
    annotations: {}
    # kubernetes.io/ingress.class: nginx
    # kubernetes.io/tls-acme: "true"

# Configure ingress
ingress:
  # Configure ingress for the proxy port.
  public:
    # En-/Disable the proxy ingress.
    enabled: false

  admin:
    # En-/Disable the api ingress.
    enabled: false

# Configure ORY Hydra itself
hydra:
  # The ORY Hydra configuration. For a full list of available settings, check:
  #   https://github.com/ory/hydra/blob/master/docs/config.yaml
  config:
    dsn: "postgres://{{ .Secrets.HydraPgUser }}:{{ .Secrets.HydraPgPassword }}@{{ .Secrets.PgHostname }}:5432/{{ .Secrets.HydraPgDatabase }}?sslmode=disable"
    log:
      level: "error"
      format: "json"
    serve:
      public:
        port: 4444
      admin:
        port: 4445
      tls:
        allow_termination_from:
          - 0.0.0.0/0
    secrets:
      system: "{{ .Secrets.HydraSystemSecret }}"
      cookie: ""
    urls:
      self:
        issuer: "https://auth.fibery.io"
      login: "https://fibery.io/oauth-login"
      consent: "https://fibery.io/oauth-consent"
    ttl:
      access_token: 1h
    strategies:
      access_token: "jwt"

  autoMigrate: true
  dangerousForceHttp: true
  dangerousAllowInsecureRedirectUrls: false

deployment:
  resources:
  #  We usually recommend not to specify default resources and to leave this as a conscious
  #  choice for the user. This also increases chances charts run on environments with little
  #  resources, such as Minikube. If you do want to specify resources, uncomment the following
  #  lines, adjust them as necessary, and remove the curly braces after 'resources:'.
    limits:
      cpu: 500m
      memory: 128Mi
    requests:
      cpu: 100m
      memory: 128Mi

  labels: {}


  annotations: {}


  # Node labels for pod assignment.
  nodeSelector: {}


  # Configure node tolerations.
  tolerations: []

# Configure node affinity
affinity: {}

# Configures controller setup
maester:
  enabled: false

Expected behavior

Refresh flow does not break up

Environment

I believe it is described in helm chart.

Additional context

I was able to reproduce the issue on older version of hydra locally, but didn't find precise steps. What I tried was to turn on\off db, restart hydra container. At the same time I executed infinite token refresh. After upgrading to the latest hydra version I was not able to reproduce the issue, and hoped everything would go well, but it didn't.

I for sure understand that described details are not precise and may be not enough. Probably I would try to find exact steps. My only alternative is to move to some other oauth server which is of course time consuming.
Maybe someone can suggest any workaround of this issue. At the moment I have several client apps, like Zapier and Slack integrations. And clients are not happy with accidentally losing auth info.

The text was updated successfully, but these errors were encountered:

aeneasr · 2020-06-29T09:01:36Z

Refresh Tokens are TOTPs, meaning that they can be used only once. It's possible that there is a bug in the application which refreshes a token but does not update it properly in your storage. Another possibility is that there is a slow request that times out, causing the token to never get to your application in the first place.

Unless you have problems with the database, it would be quite unlikely for the cause to be there. I'm pretty sure it's one of the above issues.

Regarding your flow, your application needs to be able to deal with this! A flow like this can happen at any time (e.g. because the user removed consent) and should be accounted for :) I don't dispute that such a bug is annoying though!

itsuryev · 2020-07-07T08:35:30Z

Thank you very much for looking into this case, much appreciated!

It's possible that there is a bug in the application which refreshes a token but does not update it properly in your storage. Another possibility is that there is a slow request that times out, causing the token to never get to your application in the first place.

I was able to reproduce this issue using the sample app. You mention possible options (bug in application or timed out request) so somehow we need to rule them out.
In this case I am using sample app which simply refreshes token in 500ms interval, it doesn't store it, simply logs if request was successful or not. Also all requests indexed, so we see both request and response

Unless you have problems with the database

This is exactly what happens in our production from time to time and what I tried to replicate locally. To make this issue stand out following script was running in background:

while true
do
    docker-compose stop postgres
    sleep 1
    docker-compose start postgres
    sleep 1
done

Normally hydra survives such conditions quite well, if DB is up token is successfully refreshed and we see errors if DB is down. Once it is up again everything is back to normal:

#18090, 2020-07-07T07:45:58.584Z: Refreshing token…
#18090, 2020-07-07T07:45:58.740Z: Token refreshed
#18091, 2020-07-07T07:45:59.244Z: Refreshing token…
#18091, 2020-07-07T07:45:59.247Z: Token NOT refreshed; error: "Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)."
#18092, 2020-07-07T07:45:59.751Z: Refreshing token…
#18092, 2020-07-07T07:45:59.756Z: Token NOT refreshed; error: "Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)."
#18093, 2020-07-07T07:46:00.261Z: Refreshing token…
#18093, 2020-07-07T07:46:00.268Z: Token NOT refreshed; error: "Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)."
#18094, 2020-07-07T07:46:00.772Z: Refreshing token…
#18094, 2020-07-07T07:46:00.779Z: Token NOT refreshed; error: "Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)."
#18095, 2020-07-07T07:46:01.284Z: Refreshing token…
#18095, 2020-07-07T07:46:01.292Z: Token NOT refreshed; error: "Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)."
#18096, 2020-07-07T07:46:01.794Z: Refreshing token…
#18096, 2020-07-07T07:46:01.801Z: Token NOT refreshed; error: "Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)."
#18097, 2020-07-07T07:46:02.305Z: Refreshing token…
#18097, 2020-07-07T07:46:02.489Z: Token refreshed <--- once DB is up again everything is back to normal

The problem is that sometimes this flow breaks:

#18297, 2020-07-07T07:48:17.950Z: Refreshing token…
#18297, 2020-07-07T07:48:18.102Z: Token refreshed
#18298, 2020-07-07T07:48:18.607Z: Refreshing token…
#18298, 2020-07-07T07:48:18.732Z: Token NOT refreshed; error: "The error is unrecognizable."
#18299, 2020-07-07T07:48:19.242Z: Refreshing token…
#18299, 2020-07-07T07:48:19.249Z: Token NOT refreshed; error: "Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)."
#18300, 2020-07-07T07:48:19.757Z: Refreshing token…
#18300, 2020-07-07T07:48:19.766Z: Token NOT refreshed; error: "Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)."
#18301, 2020-07-07T07:48:20.275Z: Refreshing token…
#18301, 2020-07-07T07:48:20.284Z: Token NOT refreshed; error: "Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)."
#18302, 2020-07-07T07:48:20.791Z: Refreshing token…
#18302, 2020-07-07T07:48:21.822Z: Token NOT refreshed; error: "Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)."
#18303, 2020-07-07T07:48:22.330Z: Refreshing token…
#18303, 2020-07-07T07:48:22.405Z: Token NOT refreshed; error: "The provided authorization grant (e.g., authorization code, resource owner credentials) or refresh token is invalid, expired, revoked, does not match the redirection URI used in the authorization request, or was issued to another client." <--- refresh token is wasted

At this point all subsequent requests to refresh token would fail. Please note that app received all responses, no timeouts, nothing of this sort.

aeneasr · 2020-07-07T09:41:26Z

Thank you for providing a detailed response here! It appears to me that there is an additional error happening:

#18298, 2020-07-07T07:48:18.732Z: Token NOT refreshed; error: "The error is unrecognizable."

It's hard to say what the error is exactly (maybe you could check the Hydra logs with LOG_LEVEL=trace) but I'm pretty sure it has to do with some transactional error. If you are able to find the error log and post it here that would be of big help.

By the way, the reproduction you did - what Hydra version are you using there?

itsuryev · 2020-07-07T10:10:01Z

I am using oryd/hydra:v1.4.5-alpine

Here is the Hydra log with info level:

# works fine
{"level":"info","method":"POST","msg":"started handling request","remote":"172.18.0.1:38996","request":"/oauth2/token","time":"2020-07-07T07:48:17Z"}
{"level":"info","measure#hydra/public: http://hydra:4444/.latency":149163100,"method":"POST","msg":"completed handling request","remote":"172.18.0.1:38996","request":"/oauth2/token","status":200,"text_status":"OK","time":"2020-07-07T07:48:18Z","took":149163100}

# problem, which lead to token consumption
{"level":"info","method":"POST","msg":"started handling request","remote":"172.18.0.1:38996","request":"/oauth2/token","time":"2020-07-07T07:48:18Z"}
{"error":"read tcp 172.18.0.37:34894-172.18.0.2:5432: read: connection reset by peer","level":"error","msg":"An error occurred","time":"2020-07-07T07:48:18Z"}
{"level":"info","measure#hydra/public: http://hydra:4444/.latency":122226000,"method":"POST","msg":"completed handling request","remote":"172.18.0.1:38996","request":"/oauth2/token","status":500,"text_status":"Internal Server Error","time":"2020-07-07T07:48:18Z","took":122226000}

# usual errors
{"level":"info","method":"POST","msg":"started handling request","remote":"172.18.0.8:49036","request":"/oauth2/token","time":"2020-07-07T07:48:18Z"}
{"debug":"unexpected EOF","description":"Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)","error":"invalid_client","level":"error","msg":"An error occurred","time":"2020-07-07T07:48:18Z"}
{"level":"info","measure#hydra/public: http://hydra:4444/.latency":1555300,"method":"POST","msg":"completed handling request","remote":"172.18.0.8:49036","request":"/oauth2/token","status":401,"text_status":"Unauthorized","time":"2020-07-07T07:48:18Z","took":1555300}
{"level":"info","method":"POST","msg":"started handling request","remote":"172.18.0.18:48974","request":"/oauth2/token","time":"2020-07-07T07:48:19Z"}
{"debug":"failed to connect to `host=postgres user=postgres database=hydra`: dial error (dial tcp 127.0.0.1:5432: connect: connection refused)","description":"Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)","error":"invalid_client","level":"error","msg":"An error occurred","time":"2020-07-07T07:48:19Z"}
{"level":"info","measure#hydra/public: http://hydra:4444/.latency":4280600,"method":"POST","msg":"completed handling request","remote":"172.18.0.18:48974","request":"/oauth2/token","status":401,"text_status":"Unauthorized","time":"2020-07-07T07:48:19Z","took":4280600}

aeneasr · 2020-07-07T11:03:37Z

Please set the log level to trace!

itsuryev · 2020-07-09T09:07:54Z

I've reproduced this issue again, in this case logs before failure from the app standpoint looked like this:

#49305, 2020-07-08T21:04:02.917Z: Refreshing token…
#49305, 2020-07-08T21:04:04.100Z: Token refreshed
#49306, 2020-07-08T21:04:04.611Z: Refreshing token…
#49306, 2020-07-08T21:04:05.357Z: Token NOT refreshed; error: "The authorization server encountered an unexpected condition that prevented it from fulfilling the request. (This error code is needed because a 500 Internal Server Error HTTP status code cannot be returned to the client via an HTTP redirect.)"
#49307, 2020-07-08T21:04:05.866Z: Refreshing token…
#49307, 2020-07-08T21:04:05.883Z: Token NOT refreshed; error: "Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)."
#49308, 2020-07-08T21:04:06.385Z: Refreshing token…
#49308, 2020-07-08T21:04:06.421Z: Token NOT refreshed; error: "Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)."
#49309, 2020-07-08T21:04:06.927Z: Refreshing token…
#49309, 2020-07-08T21:04:06.998Z: Token NOT refreshed; error: "Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)."
#49310, 2020-07-08T21:04:07.505Z: Refreshing token…
#49310, 2020-07-08T21:04:07.537Z: Token NOT refreshed; error: "Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)."
#49311, 2020-07-08T21:04:08.037Z: Refreshing token…
#49311, 2020-07-08T21:04:08.074Z: Token NOT refreshed; error: "Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)."
#49312, 2020-07-08T21:04:08.577Z: Refreshing token…
#49312, 2020-07-08T21:04:08.613Z: Token NOT refreshed; error: "Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)."
#49313, 2020-07-08T21:04:09.114Z: Refreshing token…
#49313, 2020-07-08T21:04:09.154Z: Token NOT refreshed; error: "Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)."
#49314, 2020-07-08T21:04:09.662Z: Refreshing token…
#49314, 2020-07-08T21:04:09.696Z: Token NOT refreshed; error: "Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)."
#49315, 2020-07-08T21:04:10.203Z: Refreshing token…
#49315, 2020-07-08T21:04:10.235Z: Token NOT refreshed; error: "Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)."
#49316, 2020-07-08T21:04:10.741Z: Refreshing token…
#49316, 2020-07-08T21:04:55.788Z: Token NOT refreshed; error: "The provided authorization grant (e.g., authorization code, resource owner credentials) or refresh token is invalid, expired, revoked, does not match the redirection URI used in the authorization request, or was issued to another client."

And Hydra logs with trace log level:

{"level":"info","method":"POST","msg":"started handling request","remote":"172.18.0.1:32982","request":"/oauth2/token","time":"2020-07-08T21:03:22Z"}
{"level":"debug","msg":"Got an empty session in toRequest","time":"2020-07-08T21:03:22Z"}
{"level":"info","measure#hydra/public: http://hydra:4444/.latency":1164618700,"method":"POST","msg":"completed handling request","remote":"172.18.0.1:32982","request":"/oauth2/token","status":200,"text_status":"OK","time":"2020-07-08T21:03:23Z","took":1164618700}
{"level":"info","method":"GET","msg":"started handling request","remote":"172.18.0.34:51194","request":"/health/alive","time":"2020-07-08T21:03:23Z"}
{"level":"info","measure#hydra/public: http://hydra:4444/.latency":1235100,"method":"GET","msg":"completed handling request","remote":"172.18.0.34:51194","request":"/health/alive","status":200,"text_status":"OK","time":"2020-07-08T21:03:23Z","took":1235100}
{"level":"info","method":"POST","msg":"started handling request","remote":"172.18.0.1:32982","request":"/oauth2/token","time":"2020-07-08T21:03:23Z"}
{"level":"debug","msg":"Got an empty session in toRequest","time":"2020-07-08T21:03:24Z"}
{"debug":"unexpected EOF","description":"The authorization server encountered an unexpected condition that prevented it from fulfilling the request","error":"server_error","level":"error","msg":"An error occurred","time":"2020-07-08T21:03:24Z"}
{"level":"debug","msg":"Stack trace: \ngithub.com/ory/fosite/handler/oauth2.handleRefreshTokenEndpointResponseStorageError\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/handler/oauth2/flow_refresh.go:193\ngithub.com/ory/fosite/handler/oauth2.(*RefreshTokenGrantHandler).PopulateTokenEndpointResponse\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/handler/oauth2/flow_refresh.go:166\ngithub.com/ory/fosite.(*Fosite).NewAccessResponse\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/access_response_writer.go:36\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler\n\t/home/ory/oauth2/handler.go:586\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/julienschmidt/httprouter.(*Router).Handler.func1\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/params_go17.go:26\ngithub.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/router.go:334\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\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/ory/hydra/x.RejectInsecureRequests.func1\n\t/home/ory/x/tls_termination.go:55\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.111/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/ory/hydra/metrics/prometheus.(*MetricsManager).ServeHTTP\n\t/home/ory/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/ory/x/reqlog.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.111/reqlog/middleware.go:140\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:2807\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1895\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1373","time":"2020-07-08T21:03:24Z"}
{"level":"info","measure#hydra/public: http://hydra:4444/.latency":736745100,"method":"POST","msg":"completed handling request","remote":"172.18.0.1:32982","request":"/oauth2/token","status":500,"text_status":"Internal Server Error","time":"2020-07-08T21:03:24Z","took":736745100}
{"level":"info","method":"POST","msg":"started handling request","remote":"172.18.0.1:32982","request":"/oauth2/token","time":"2020-07-08T21:03:24Z"}
{"debug":"unexpected EOF","description":"Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)","error":"invalid_client","level":"error","msg":"An error occurred","time":"2020-07-08T21:03:24Z"}
{"level":"debug","msg":"Stack trace: \ngithub.com/ory/fosite.(*Fosite).AuthenticateClient\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/client_authentication.go:209\ngithub.com/ory/fosite.(*Fosite).NewAccessRequest\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/access_request_handler.go:81\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler\n\t/home/ory/oauth2/handler.go:549\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/julienschmidt/httprouter.(*Router).Handler.func1\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/params_go17.go:26\ngithub.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/router.go:334\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\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/ory/hydra/x.RejectInsecureRequests.func1\n\t/home/ory/x/tls_termination.go:55\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.111/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/ory/hydra/metrics/prometheus.(*MetricsManager).ServeHTTP\n\t/home/ory/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/ory/x/reqlog.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.111/reqlog/middleware.go:140\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:2807\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1895\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1373","time":"2020-07-08T21:03:24Z"}
{"level":"info","measure#hydra/public: http://hydra:4444/.latency":3491400,"method":"POST","msg":"completed handling request","remote":"172.18.0.1:32982","request":"/oauth2/token","status":401,"text_status":"Unauthorized","time":"2020-07-08T21:03:24Z","took":3491400}
{"level":"info","method":"POST","msg":"started handling request","remote":"172.18.0.32:50298","request":"/oauth2/token","time":"2020-07-08T21:03:25Z"}
{"debug":"failed to connect to `host=postgres user=postgres database=hydra`: dial error (dial tcp 127.0.0.1:5432: connect: connection refused)","description":"Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)","error":"invalid_client","level":"error","msg":"An error occurred","time":"2020-07-08T21:03:25Z"}
{"level":"debug","msg":"Stack trace: \ngithub.com/ory/fosite.(*Fosite).AuthenticateClient\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/client_authentication.go:209\ngithub.com/ory/fosite.(*Fosite).NewAccessRequest\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/access_request_handler.go:81\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler\n\t/home/ory/oauth2/handler.go:549\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/julienschmidt/httprouter.(*Router).Handler.func1\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/params_go17.go:26\ngithub.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/router.go:334\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\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/ory/hydra/x.RejectInsecureRequests.func1\n\t/home/ory/x/tls_termination.go:55\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.111/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/ory/hydra/metrics/prometheus.(*MetricsManager).ServeHTTP\n\t/home/ory/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/ory/x/reqlog.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.111/reqlog/middleware.go:140\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:2807\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1895\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1373","time":"2020-07-08T21:03:25Z"}
{"level":"info","method":"POST","msg":"started handling request","remote":"172.18.0.1:32982","request":"/oauth2/token","time":"2020-07-08T21:03:25Z"}
{"level":"info","measure#hydra/public: http://hydra:4444/.latency":29537100,"method":"POST","msg":"completed handling request","remote":"172.18.0.32:50298","request":"/oauth2/token","status":401,"text_status":"Unauthorized","time":"2020-07-08T21:03:25Z","took":29537100}
{"debug":"failed to connect to `host=postgres user=postgres database=hydra`: dial error (dial tcp 127.0.0.1:5432: connect: connection refused)","description":"Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)","error":"invalid_client","level":"error","msg":"An error occurred","time":"2020-07-08T21:03:25Z"}
{"level":"debug","msg":"Stack trace: \ngithub.com/ory/fosite.(*Fosite).AuthenticateClient\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/client_authentication.go:209\ngithub.com/ory/fosite.(*Fosite).NewAccessRequest\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/access_request_handler.go:81\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler\n\t/home/ory/oauth2/handler.go:549\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/julienschmidt/httprouter.(*Router).Handler.func1\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/params_go17.go:26\ngithub.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/router.go:334\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\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/ory/hydra/x.RejectInsecureRequests.func1\n\t/home/ory/x/tls_termination.go:55\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.111/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/ory/hydra/metrics/prometheus.(*MetricsManager).ServeHTTP\n\t/home/ory/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/ory/x/reqlog.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.111/reqlog/middleware.go:140\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:2807\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1895\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1373","time":"2020-07-08T21:03:25Z"}
{"level":"info","measure#hydra/public: http://hydra:4444/.latency":20542200,"method":"POST","msg":"completed handling request","remote":"172.18.0.1:32982","request":"/oauth2/token","status":401,"text_status":"Unauthorized","time":"2020-07-08T21:03:25Z","took":20542200}
{"level":"info","method":"GET","msg":"started handling request","remote":"172.18.0.34:51226","request":"/health/alive","time":"2020-07-08T21:03:25Z"}
{"level":"info","measure#hydra/public: http://hydra:4444/.latency":1319300,"method":"GET","msg":"completed handling request","remote":"172.18.0.34:51226","request":"/health/alive","status":200,"text_status":"OK","time":"2020-07-08T21:03:25Z","took":1319300}
{"level":"info","method":"POST","msg":"started handling request","remote":"172.18.0.1:32982","request":"/oauth2/token","time":"2020-07-08T21:03:26Z"}
{"debug":"failed to connect to `host=postgres user=postgres database=hydra`: dial error (dial tcp 127.0.0.1:5432: connect: connection refused)","description":"Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)","error":"invalid_client","level":"error","msg":"An error occurred","time":"2020-07-08T21:03:26Z"}
{"level":"debug","msg":"Stack trace: \ngithub.com/ory/fosite.(*Fosite).AuthenticateClient\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/client_authentication.go:209\ngithub.com/ory/fosite.(*Fosite).NewAccessRequest\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/access_request_handler.go:81\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler\n\t/home/ory/oauth2/handler.go:549\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/julienschmidt/httprouter.(*Router).Handler.func1\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/params_go17.go:26\ngithub.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/router.go:334\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\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/ory/hydra/x.RejectInsecureRequests.func1\n\t/home/ory/x/tls_termination.go:55\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.111/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/ory/hydra/metrics/prometheus.(*MetricsManager).ServeHTTP\n\t/home/ory/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/ory/x/reqlog.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.111/reqlog/middleware.go:140\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:2807\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1895\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1373","time":"2020-07-08T21:03:26Z"}
{"level":"info","measure#hydra/public: http://hydra:4444/.latency":55838800,"method":"POST","msg":"completed handling request","remote":"172.18.0.1:32982","request":"/oauth2/token","status":401,"text_status":"Unauthorized","time":"2020-07-08T21:03:26Z","took":55838800}
{"level":"info","method":"POST","msg":"started handling request","remote":"172.18.0.1:32982","request":"/oauth2/token","time":"2020-07-08T21:03:26Z"}
{"debug":"failed to connect to `host=postgres user=postgres database=hydra`: dial error (dial tcp 127.0.0.1:5432: connect: connection refused)","description":"Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)","error":"invalid_client","level":"error","msg":"An error occurred","time":"2020-07-08T21:03:26Z"}
{"level":"debug","msg":"Stack trace: \ngithub.com/ory/fosite.(*Fosite).AuthenticateClient\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/client_authentication.go:209\ngithub.com/ory/fosite.(*Fosite).NewAccessRequest\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/access_request_handler.go:81\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler\n\t/home/ory/oauth2/handler.go:549\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/julienschmidt/httprouter.(*Router).Handler.func1\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/params_go17.go:26\ngithub.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/router.go:334\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\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/ory/hydra/x.RejectInsecureRequests.func1\n\t/home/ory/x/tls_termination.go:55\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.111/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/ory/hydra/metrics/prometheus.(*MetricsManager).ServeHTTP\n\t/home/ory/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/ory/x/reqlog.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.111/reqlog/middleware.go:140\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:2807\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1895\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1373","time":"2020-07-08T21:03:26Z"}
{"level":"info","measure#hydra/public: http://hydra:4444/.latency":20716100,"method":"POST","msg":"completed handling request","remote":"172.18.0.1:32982","request":"/oauth2/token","status":401,"text_status":"Unauthorized","time":"2020-07-08T21:03:26Z","took":20716100}
{"level":"info","method":"POST","msg":"started handling request","remote":"172.18.0.1:32982","request":"/oauth2/token","time":"2020-07-08T21:03:27Z"}
{"debug":"failed to connect to `host=postgres user=postgres database=hydra`: dial error (dial tcp 127.0.0.1:5432: connect: connection refused)","description":"Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)","error":"invalid_client","level":"error","msg":"An error occurred","time":"2020-07-08T21:03:27Z"}
{"level":"debug","msg":"Stack trace: \ngithub.com/ory/fosite.(*Fosite).AuthenticateClient\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/client_authentication.go:209\ngithub.com/ory/fosite.(*Fosite).NewAccessRequest\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/access_request_handler.go:81\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler\n\t/home/ory/oauth2/handler.go:549\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/julienschmidt/httprouter.(*Router).Handler.func1\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/params_go17.go:26\ngithub.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/router.go:334\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\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/ory/hydra/x.RejectInsecureRequests.func1\n\t/home/ory/x/tls_termination.go:55\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.111/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/ory/hydra/metrics/prometheus.(*MetricsManager).ServeHTTP\n\t/home/ory/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/ory/x/reqlog.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.111/reqlog/middleware.go:140\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:2807\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1895\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1373","time":"2020-07-08T21:03:27Z"}
{"level":"info","measure#hydra/public: http://hydra:4444/.latency":23133300,"method":"POST","msg":"completed handling request","remote":"172.18.0.1:32982","request":"/oauth2/token","status":401,"text_status":"Unauthorized","time":"2020-07-08T21:03:27Z","took":23133300}
{"level":"info","method":"POST","msg":"started handling request","remote":"172.18.0.1:32982","request":"/oauth2/token","time":"2020-07-08T21:03:27Z"}
{"debug":"failed to connect to `host=postgres user=postgres database=hydra`: dial error (dial tcp 127.0.0.1:5432: connect: connection refused)","description":"Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)","error":"invalid_client","level":"error","msg":"An error occurred","time":"2020-07-08T21:03:27Z"}
{"level":"debug","msg":"Stack trace: \ngithub.com/ory/fosite.(*Fosite).AuthenticateClient\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/client_authentication.go:209\ngithub.com/ory/fosite.(*Fosite).NewAccessRequest\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/access_request_handler.go:81\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler\n\t/home/ory/oauth2/handler.go:549\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/julienschmidt/httprouter.(*Router).Handler.func1\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/params_go17.go:26\ngithub.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/router.go:334\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\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/ory/hydra/x.RejectInsecureRequests.func1\n\t/home/ory/x/tls_termination.go:55\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.111/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/ory/hydra/metrics/prometheus.(*MetricsManager).ServeHTTP\n\t/home/ory/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/ory/x/reqlog.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.111/reqlog/middleware.go:140\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:2807\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1895\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1373","time":"2020-07-08T21:03:27Z"}
{"level":"info","measure#hydra/public: http://hydra:4444/.latency":22435000,"method":"POST","msg":"completed handling request","remote":"172.18.0.1:32982","request":"/oauth2/token","status":401,"text_status":"Unauthorized","time":"2020-07-08T21:03:27Z","took":22435000}
{"level":"info","method":"POST","msg":"started handling request","remote":"172.18.0.1:32982","request":"/oauth2/token","time":"2020-07-08T21:03:28Z"}
{"debug":"failed to connect to `host=postgres user=postgres database=hydra`: dial error (dial tcp 127.0.0.1:5432: connect: connection refused)","description":"Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)","error":"invalid_client","level":"error","msg":"An error occurred","time":"2020-07-08T21:03:28Z"}
{"level":"debug","msg":"Stack trace: \ngithub.com/ory/fosite.(*Fosite).AuthenticateClient\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/client_authentication.go:209\ngithub.com/ory/fosite.(*Fosite).NewAccessRequest\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/access_request_handler.go:81\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler\n\t/home/ory/oauth2/handler.go:549\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/julienschmidt/httprouter.(*Router).Handler.func1\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/params_go17.go:26\ngithub.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/router.go:334\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\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/ory/hydra/x.RejectInsecureRequests.func1\n\t/home/ory/x/tls_termination.go:55\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.111/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/ory/hydra/metrics/prometheus.(*MetricsManager).ServeHTTP\n\t/home/ory/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/ory/x/reqlog.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.111/reqlog/middleware.go:140\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:2807\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1895\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1373","time":"2020-07-08T21:03:28Z"}
{"level":"info","measure#hydra/public: http://hydra:4444/.latency":25970500,"method":"POST","msg":"completed handling request","remote":"172.18.0.1:32982","request":"/oauth2/token","status":401,"text_status":"Unauthorized","time":"2020-07-08T21:03:28Z","took":25970500}
{"level":"info","method":"GET","msg":"started handling request","remote":"172.18.0.34:51260","request":"/health/alive","time":"2020-07-08T21:03:28Z"}
{"level":"info","measure#hydra/public: http://hydra:4444/.latency":1005400,"method":"GET","msg":"completed handling request","remote":"172.18.0.34:51260","request":"/health/alive","status":200,"text_status":"OK","time":"2020-07-08T21:03:28Z","took":1005400}
{"level":"info","method":"POST","msg":"started handling request","remote":"172.18.0.1:32982","request":"/oauth2/token","time":"2020-07-08T21:03:28Z"}
{"debug":"failed to connect to `host=postgres user=postgres database=hydra`: dial error (dial tcp 127.0.0.1:5432: connect: connection refused)","description":"Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)","error":"invalid_client","level":"error","msg":"An error occurred","time":"2020-07-08T21:03:28Z"}
{"level":"debug","msg":"Stack trace: \ngithub.com/ory/fosite.(*Fosite).AuthenticateClient\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/client_authentication.go:209\ngithub.com/ory/fosite.(*Fosite).NewAccessRequest\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/access_request_handler.go:81\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler\n\t/home/ory/oauth2/handler.go:549\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/julienschmidt/httprouter.(*Router).Handler.func1\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/params_go17.go:26\ngithub.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/router.go:334\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\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/ory/hydra/x.RejectInsecureRequests.func1\n\t/home/ory/x/tls_termination.go:55\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.111/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/ory/hydra/metrics/prometheus.(*MetricsManager).ServeHTTP\n\t/home/ory/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/ory/x/reqlog.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.111/reqlog/middleware.go:140\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:2807\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1895\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1373","time":"2020-07-08T21:03:28Z"}
{"level":"info","measure#hydra/public: http://hydra:4444/.latency":18429900,"method":"POST","msg":"completed handling request","remote":"172.18.0.1:32982","request":"/oauth2/token","status":401,"text_status":"Unauthorized","time":"2020-07-08T21:03:28Z","took":18429900}
{"level":"info","method":"POST","msg":"started handling request","remote":"172.18.0.1:32982","request":"/oauth2/token","time":"2020-07-08T21:04:10Z"}
{"debug":"failed to connect to `host=postgres user=postgres database=hydra`: dial error (dial tcp 127.0.0.1:5432: connect: connection refused)","description":"Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)","error":"invalid_client","level":"error","msg":"An error occurred","time":"2020-07-08T21:04:10Z"}
{"level":"debug","msg":"Stack trace: \ngithub.com/ory/fosite.(*Fosite).AuthenticateClient\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/client_authentication.go:209\ngithub.com/ory/fosite.(*Fosite).NewAccessRequest\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/access_request_handler.go:81\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler\n\t/home/ory/oauth2/handler.go:549\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/julienschmidt/httprouter.(*Router).Handler.func1\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/params_go17.go:26\ngithub.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/router.go:334\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\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/ory/hydra/x.RejectInsecureRequests.func1\n\t/home/ory/x/tls_termination.go:55\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.111/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/ory/hydra/metrics/prometheus.(*MetricsManager).ServeHTTP\n\t/home/ory/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/ory/x/reqlog.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.111/reqlog/middleware.go:140\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:2807\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1895\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1373","time":"2020-07-08T21:04:10Z"}
{"level":"info","measure#hydra/public: http://hydra:4444/.latency":20414900,"method":"POST","msg":"completed handling request","remote":"172.18.0.1:32982","request":"/oauth2/token","status":401,"text_status":"Unauthorized","time":"2020-07-08T21:04:10Z","took":20414900}
{"level":"info","method":"POST","msg":"started handling request","remote":"172.18.0.1:32982","request":"/oauth2/token","time":"2020-07-08T21:04:10Z"}
{"level":"info","method":"POST","msg":"started handling request","remote":"172.18.0.32:50702","request":"/oauth2/token","time":"2020-07-08T21:04:12Z"}
{"level":"info","method":"GET","msg":"started handling request","remote":"172.18.0.34:51302","request":"/health/alive","time":"2020-07-08T21:04:12Z"}
{"level":"info","measure#hydra/public: http://hydra:4444/.latency":366900,"method":"GET","msg":"completed handling request","remote":"172.18.0.34:51302","request":"/health/alive","status":200,"text_status":"OK","time":"2020-07-08T21:04:12Z","took":366900}
{"debug":"failed to connect to `host=postgres user=postgres database=hydra`: server error (FATAL: the database system is starting up (SQLSTATE 57P03))","description":"Client authentication failed (e.g., unknown client, no client authentication included, or unsupported authentication method)","error":"invalid_client","level":"error","msg":"An error occurred","time":"2020-07-08T21:04:13Z"}
{"level":"debug","msg":"Stack trace: \ngithub.com/ory/fosite.(*Fosite).AuthenticateClient\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/client_authentication.go:209\ngithub.com/ory/fosite.(*Fosite).NewAccessRequest\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/access_request_handler.go:81\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler\n\t/home/ory/oauth2/handler.go:549\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/julienschmidt/httprouter.(*Router).Handler.func1\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/params_go17.go:26\ngithub.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/router.go:334\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\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/ory/hydra/x.RejectInsecureRequests.func1\n\t/home/ory/x/tls_termination.go:55\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.111/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/ory/hydra/metrics/prometheus.(*MetricsManager).ServeHTTP\n\t/home/ory/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/ory/x/reqlog.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.111/reqlog/middleware.go:140\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:2807\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1895\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1373","time":"2020-07-08T21:04:13Z"}
{"level":"info","measure#hydra/public: http://hydra:4444/.latency":1010015000,"method":"POST","msg":"completed handling request","remote":"172.18.0.32:50702","request":"/oauth2/token","status":401,"text_status":"Unauthorized","time":"2020-07-08T21:04:13Z","took":1010015000}
{"debug":"The refresh token has not been found: : not_found","description":"The provided authorization grant (e.g., authorization code, resource owner credentials) or refresh token is invalid, expired, revoked, does not match the redirection URI used in the authorization request, or was issued to another client","error":"invalid_grant","level":"error","msg":"An error occurred","time":"2020-07-08T21:04:14Z"}
{"level":"debug","msg":"Stack trace: \ngithub.com/ory/fosite/handler/oauth2.(*RefreshTokenGrantHandler).HandleTokenEndpointRequest\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/handler/oauth2/flow_refresh.go:68\ngithub.com/ory/fosite.(*Fosite).NewAccessRequest\n\t/go/pkg/mod/github.com/ory/fosite@v0.31.2/access_request_handler.go:89\ngithub.com/ory/hydra/oauth2.(*Handler).TokenHandler\n\t/home/ory/oauth2/handler.go:549\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/julienschmidt/httprouter.(*Router).Handler.func1\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/params_go17.go:26\ngithub.com/julienschmidt/httprouter.(*Router).ServeHTTP\n\t/go/pkg/mod/github.com/julienschmidt/httprouter@v1.2.0/router.go:334\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\nnet/http.HandlerFunc.ServeHTTP\n\t/usr/local/go/src/net/http/server.go:2012\ngithub.com/ory/hydra/x.RejectInsecureRequests.func1\n\t/home/ory/x/tls_termination.go:55\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.111/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/ory/hydra/metrics/prometheus.(*MetricsManager).ServeHTTP\n\t/home/ory/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/ory/x/reqlog.(*Middleware).ServeHTTP\n\t/go/pkg/mod/github.com/ory/x@v0.0.111/reqlog/middleware.go:140\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:2807\nnet/http.(*conn).serve\n\t/usr/local/go/src/net/http/server.go:1895\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_amd64.s:1373","time":"2020-07-08T21:04:14Z"}
{"level":"info","measure#hydra/public: http://hydra:4444/.latency":3989930700,"method":"POST","msg":"completed handling request","remote":"172.18.0.1:32982","request":"/oauth2/token","status":400,"text_status":"Bad Request","time":"2020-07-08T21:04:14Z","took":3989930700}

Thank you so much for looking into it!

aeneasr · 2020-07-10T10:55:17Z

Yeah it looks like PostgreSQL is shutting down / being disconnected while we're in the middle of a SQL Transaction which removes the old refresh token and inserts the new refresh token. Apparently this can lead to a condition where the refresh token is only removed, without storing the new refresh token. It's a bit surprising that the transaction is not properly rolled back, but it is possible that this is due to PostgreSQL shutting down - not sure to be honest.

The only solution here is probably to change the transaction isolation level - even though I'm not even sure if that would really help because we don't really know if the request made it through or not because the TCP ACK is just missing. Further increasing the isolation level would have (I believe) serious performance implications because we're already at a pretty high isolation level for this particular transaction.

I think this is one of the cases where we unfortunately have to tag this with a "wontfix" and where your application should be able to deal with this by re-running the flow - unless someone comes along with a great idea on how to resolve this. I guess this also needs some in-depth knowledge of how PostgreSQL works itself.

itsuryev · 2020-07-10T13:18:38Z

Thank you for getting back to me, Aeneas!

Apparently this can lead to a condition where the refresh token is only removed, without storing the new refresh token. It's a bit surprising that the transaction is not properly rolled back, but it is possible that this is due to PostgreSQL shutting down - not sure to be honest.

Is this an assumption or do you see it somehow from the logs? Because this sounds quite improbable, there is little to no doubts that Postgres have either completely applied or rolled back transaction.
I've looked into handler/oauth2/flow_refresh.go and everything seems in order there -- we open just one transaction, attempt to do things and roll back if something is wrong.

Which leads us to

    responder.SetExtra("refresh_token", refreshToken)

    if err := storage.MaybeCommitTx(ctx, c.TokenRevocationStorage); err != nil {
        return handleRefreshTokenEndpointResponseStorageError(ctx, false, c.TokenRevocationStorage, err)
    }

    return nil

Please bear with me here, I am not familiar with Go, if we get error during transaction commit do we still generated refresh token and other stuff or is everything replaced with error message itself?

I've found the following case in PostgreSQL 9 Administration Cookbook - Second Edition:

If the commit fails, it is possible that the server committed the transaction successfully but was unable to communicate that to the client, but we don't know for certain.
We can resolve that uncertainty by rechecking a unique aspect of the transaction, such as re-confirming the existence of an object identifier that was inserted.

If that's the case and my assumption about error message is correct then everything fits together. Transaction was commited but client received not token but error.

I think this is one of the cases where we unfortunately have to tag this with a "wontfix" and where your application should be able to deal with this by re-running the flow - unless someone comes along with a great idea on how to resolve this.

While application of course should somehow be able to handle everything thrown at it this part leaves me unsettled. If case above is not correct then Hydra under some conditions experiences data loss and that's a bummer. There could be different priorities but closing an actual issue with "wontfix" seems wrong.

Please tell if I could be of any help to narrow down this issue.

Thank you for involvement, cheers!

aeneasr · 2020-07-10T15:56:27Z

Is this an assumption or do you see it somehow from the logs? Because this sounds quite improbable, there is little to no doubts that Postgres have either completely applied or rolled back transaction.

Experience ;) I am not debating that PG has committed the transaction, the problem is that the TCP connection aborts while the transaction is running. The error returned by the broken transaction will then cause the Go code to try and roll back the transaction, which does not happen because the TCP connection is still offline! In the meanwhile, the actual transaction was successful at PG itself.

For the Go code, it is impossible to know if the transaction failed or succeeded, and it thus assumes an error, even if the transaction actually succeeded. This is not solvable from a code perspective in my experience and is just one of the things that can happen in distributed systems.

There's actually an issue for that in lib/pq: lib/pq#871

As we're moving to gobuffalo/pop we'll move also to jackc/pgx but that library also is not able to deal with these type of scenarios.

aeneasr · 2020-07-10T15:57:54Z

If you have lots of error messages and broken flows like these, I would recommend trying to reduce the flakyness of the network by either co-locating ORY Hydra with your SQL database or doing some other stuff that helps reduce error rates and latency between those two.

struhtanov · 2020-07-13T08:39:55Z

We already have DB collocated with Hydra. At the moment refresh token flow break appears when there are some problems on DB. We use Stolon in our postgres setup, maybe there are some peculiarities there.

While I understand all your concerns that described problem is unlikely, we experience it quite often during little db downtimes. Of course clients do support re-auth, but this breaks flow of an end user. For example for an automation system Zapier (for which we have integration), re-auth means that automation stops working, until user does some manual steps. Zapier does notify end user about broken flow by email, but who reads emails nowadays... Similar situation is for a Slackbots, etc.

The main problem is that there is no clear workaround. The only one I see is greatly increasing lifespan of access_token, which is of course insecure. Just to notice, there are already similar propositions in Hydra repo issues, like this one. This will definitely solve our issue. I've looked through other Oauth server, IdentityServer. It also supports similar feature.

aeneasr · 2020-08-21T08:37:47Z

Ok, thank you for the detailed response. Given that there is nothing really we can do here right now given the context to address the exact issue (PG related network problems) and that #1831 will solve this for you, I think it's ok to close this and have it as an additional use case / upvote for #1831 .

aeneasr added bug Something is not working. package/persistence/sql Affects a SQL statement, schema or component labels Aug 21, 2020

aeneasr added this to the unplanned milestone Aug 21, 2020

aeneasr closed this as completed Aug 21, 2020

aeneasr mentioned this issue Aug 21, 2020

Refresh tokens need a grace period to deal with network errors and similar issues #1831

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Refresh token flow breaks up during db server downtime #1928

Refresh token flow breaks up during db server downtime #1928

struhtanov commented Jun 25, 2020

aeneasr commented Jun 29, 2020

itsuryev commented Jul 7, 2020

aeneasr commented Jul 7, 2020

itsuryev commented Jul 7, 2020 •

edited

Loading

aeneasr commented Jul 7, 2020

itsuryev commented Jul 9, 2020 •

edited

Loading

aeneasr commented Jul 10, 2020 •

edited

Loading

itsuryev commented Jul 10, 2020

aeneasr commented Jul 10, 2020 •

edited

Loading

aeneasr commented Jul 10, 2020

struhtanov commented Jul 13, 2020

aeneasr commented Aug 21, 2020

Refresh token flow breaks up during db server downtime #1928

Refresh token flow breaks up during db server downtime #1928

Comments

struhtanov commented Jun 25, 2020

aeneasr commented Jun 29, 2020

itsuryev commented Jul 7, 2020

aeneasr commented Jul 7, 2020

itsuryev commented Jul 7, 2020 • edited Loading

aeneasr commented Jul 7, 2020

itsuryev commented Jul 9, 2020 • edited Loading

aeneasr commented Jul 10, 2020 • edited Loading

itsuryev commented Jul 10, 2020

aeneasr commented Jul 10, 2020 • edited Loading

aeneasr commented Jul 10, 2020

struhtanov commented Jul 13, 2020

aeneasr commented Aug 21, 2020

itsuryev commented Jul 7, 2020 •

edited

Loading

itsuryev commented Jul 9, 2020 •

edited

Loading

aeneasr commented Jul 10, 2020 •

edited

Loading

aeneasr commented Jul 10, 2020 •

edited

Loading