ERROR: null value in column "authenticated_at" violates not-null constraint

codemandosch commented 2 years ago

Preflight checklist

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

Describe the bug

We have a staging and a production environment. When we try do a request to the oauth2/auth endpoint on the former. Everything works out and a row is created in the hydra_2_authentication_request table and our request is redirected as expected. When we do the exact same thing in the production environment, with the same settings, we get the following error:

message:ERROR: null value in column "authenticated_at" violates not-null constraint (SQLSTATE 23502)]

and looking at the table hydra_2_authentication_request, there is no row created (as there would be in a working environment). We suspect something goes wrong when creating the row in the DB but at the same time, it can still create clients and bearer tokens via client credentials the normal way.

Reproducing the bug

Running ory hydra in docker swarm with traefik load balancer, https is handled in traefik and then the request is relayed internally to hydra in the dockerswarm.

Relevant log output

time=2022-02-11T14:01:49Z level=info msg=started handling request http_request=map[headers:map[accept:text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9 accept-encoding:gzip, deflate, br accept-language:en-US,en;q=0.9 cookie:_hjAbsoluteSessionInProgress=1; _gcl_au=1.1.2012139111.1644584286; _ga=<ga_id>; _hjid=<hjid>; _hjSessionUser_2192549=<session_user>==; _hjSession_2192549=<session_user>==; intercom-session-n3um964n=<intercom_session_num>--ef6979d5bf737c8c3f4fbd70f349a2f4b37cd8df; _ga_TAG_ID=GS1.1.1644587050.2.0.1644587050.0 referer:<referer> sec-ch-ua:"Chromium";v="94", "Google Chrome";v="94", ";Not A Brand";v="99" sec-ch-ua-mobile:?0 sec-ch-ua-platform:"Linux" sec-fetch-dest:document sec-fetch-mode:navigate sec-fetch-site:cross-site sec-fetch-user:?1 upgrade-insecure-requests:1 user-agent:Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/94.0.4606.61 Safari/537.36 x-forwarded-for:188.151.251.173 x-forwarded-host:auth.app.website.com x-forwarded-port:443 x-forwarded-proto:https x-forwarded-server:85ccd53aa9db x-real-ip:188.151.251.173] host:auth.app.website.com method:GET path:/oauth2/auth query:client_id=<client_id>&state=1644588108.005293461774&redirect_uri=<redirect_uri>&response_type=code&scope=openid%20offline remote:10.0.1.116:53046 scheme:http]

time=2022-02-11T14:01:49Z level=debug msg=User logout skipped because cookie exists but session value is empty. audience=application http_request=map[headers:map[accept:text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9 accept-encoding:gzip, deflate, br accept-language:en-US,en;q=0.9 cookie:_hjAbsoluteSessionInProgress=1; _gcl_au=1.1.2012139111.1644584286; _ga=<ga_id>; _hjid=<hjid>; _hjSessionUser_2192549=<session_user>==; _hjSession_2192549=<session_user>==; intercom-session-n3um964n=<intercom_session_num>--ef6979d5bf737c8c3f4fbd70f349a2f4b37cd8df; _ga_TAG_ID=GS1.1.1644587050.2.0.1644587050.0 referer:<referer> sec-ch-ua:"Chromium";v="94", "Google Chrome";v="94", ";Not A Brand";v="99" sec-ch-ua-mobile:?0 sec-ch-ua-platform:"Linux" sec-fetch-dest:document sec-fetch-mode:navigate sec-fetch-site:cross-site sec-fetch-user:?1 upgrade-insecure-requests:1 user-agent:Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/94.0.4606.61 Safari/537.36 x-forwarded-for:188.151.251.173 x-forwarded-host:auth.app.website.com x-forwarded-port:443 x-forwarded-proto:https x-forwarded-server:85ccd53aa9db x-real-ip:188.151.251.173] host:auth.app.website.com method:GET path:/oauth2/auth query:client_id=<client_id>&state=1644588108.005293461774&redirect_uri=<redirect_uri>&response_type=code&scope=openid%20offline remote:10.0.1.116:53046 scheme:http] service_name=ORY Hydra service_version=v1.10.7

time=2022-02-11T14:01:49Z level=error msg=An error occurred audience=application error=map[message:ERROR: null value in column "authenticated_at" violates not-null constraint (SQLSTATE 23502)] http_request=map[headers:map[accept:text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9 accept-encoding:gzip, deflate, br accept-language:en-US,en;q=0.9 cookie:_hjAbsoluteSessionInProgress=1; _gcl_au=1.1.2012139111.1644584286; _ga=<ga_id>; _hjid=<hjid>; _hjSessionUser_2192549=<session_user>==; _hjSession_2192549=<session_user>==; intercom-session-n3um964n=<intercom_session_num>--ef6979d5bf737c8c3f4fbd70f349a2f4b37cd8df; _ga_TAG_ID=GS1.1.1644587050.2.0.1644587050.0 referer:<referer> sec-ch-ua:"Chromium";v="94", "Google Chrome";v="94", ";Not A Brand";v="99" sec-ch-ua-mobile:?0 sec-ch-ua-platform:"Linux" sec-fetch-dest:document sec-fetch-mode:navigate sec-fetch-site:cross-site sec-fetch-user:?1 upgrade-insecure-requests:1 user-agent:Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/94.0.4606.61 Safari/537.36 x-forwarded-for:188.151.251.173 x-forwarded-host:auth.app.website.com x-forwarded-port:443 x-forwarded-proto:https x-forwarded-server:85ccd53aa9db x-real-ip:188.151.251.173] host:auth.app.website.com method:GET path:/oauth2/auth query:client_id=<client_id>&state=1644588108.005293461774&redirect_uri=<redirect_uri>&response_type=code&scope=openid%20offline remote:10.0.1.116:53046 scheme:http] service_name=ORY Hydra service_version=v1.10.7

Relevant configuration

No response

Version

v1.10.7

On which operating system are you observing this issue?

Linux

In which environment are you deploying?

Docker Compose

Additional Context

No response

grantzvolsky commented 2 years ago

Thank you for your report @codemandosch. It would be very helpful if you could contribute a failing test case or comment a reproducible environment (e.g. a Dockerfile) with a script that triggers the issue.

aeneasr commented 2 years ago

It looks like you might be missing some SQL migrations in the system that fails. Did you run „hydra migrate sql“?

Nad as @grantzvolsky said a reproducible case would be very helpful!

codemandosch commented 2 years ago

This was indeed correct @grantzvolsky @aeneasr . It was somewhat strange that our two environments was on different migration versions. But now we have migrated production and it's working. Closing the issue. :pray:

ory / hydra