Ory Hydra 1.10.2 apis sometimes takes too long.

[azajkhan]

I am using Ory hydra 1.10.2 , recently while checking logs we observered sometimes ory hydra apis takes more then 15 sec to serve the request.
its very intermittant , sometimes same api give response in milliseconds.
PFA hydra logs
time=2021-11-18T10:58:34+10:00 level=info msg=completed handling request http_request=map[headers:map[accept:application/json accept-encoding:gzip,deflate user-agent:Apache-HttpClient/4.5.7 (Java/1.8.0_281) x-forwarded-for:<MASKED_IP>:1730 x-forwarded-proto:https] host:popuatidp.mphrx.com method:POST path:/oauth2/revoke query: remote:<MASKED_IP>:16484 scheme:http] http_response=map[status:200 text_status:OK took:21.878337303s]

time="2021-09-01T22:48:23+10:00" level=info msg="started handling request" method=GET remote="" request="/oauth2/auth?acr=&client_id&login_verifier=&redirect_uri=&response_type=code&scope=openid+offline&state=
time="2021-09-01T22:48:23+10:00" level=info msg="completed handling request" measure#hydra/public: https:///.latency=23784353 method=GET remote=":18655" request="/oauth2/auth?acr=&client_id=&login_verifier=&redirect_uri=&response_type=code&scope=openid+offline&state=" status=302 text_status=Found took=23.784353ms

I have masked few details for obvious reasons.

Can someone help me understand , why hydra sometimes takes 15-20 (or more) sec to serve request, and immidiately next moment same apis responds instantly.

[aeneasr]

Make sure to configure BCrypt with a reasonable work factor or add more CPU, see: https://www.ory.sh/hydra/docs/benchmark/#bcrypt

[aeneasr]

Hm, that's strange - I really don't know what could cause this. But it does look like an issue with the DB? We have not observed this issue anywhere else. Is your dataset very large?

[rahulagrawal]

Thanks for the reply.

No the DB size is not that large. We also ran the janitor script It cleaned the request table but not the session table. We cleaned it manually.

Also may I request how do we enable TRACE level logs. We have done it via yml file but no luck. We see only debug logs.

Is there a way to change the timeout settings for the HTTP responses which HYDRA emits.

[vinckr]

Hey, just checking in if your problem still persists.
I will mark this as answered for now, but feel free to come back to the discussion any time.
Thanks a ton 🐝

[azajkhan]

Hi @vinckr @aeneasr Out of nowhere we started facing same issue again on one of Prod servers. Can you please help us narrow down the root cause
logs at the incident
time=2022-05-25T03:30:51-05:00 level=error msg=An error occurred audience=application error=map[message:sql: transaction has already been committed or rolled back] 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:Value is sensitive and has been redacted. To see the value set config key "log.leak_sensitive_values = true" or environment variable "LOG_LEAK_SENSITIVE_VALUES=true". user-agent:Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/99.0.4844.82 Safari/537.36 x-forwarded-for:49.42.68.164:46852 x-forwarded-proto:https] host:idp.patientportal.myhealthhome.com method:GET path:/oauth2/auth query:Value is sensitive and has been redacted. To see the value set config key "log.leak_sensitive_values = true" or environment variable "LOG_LEAK_SENSITIVE_VALUES=true". remote:10.15.12.68:41637 scheme:http] service_name=ORY Hydra service_version=v1.10.2
time=2022-05-25T03:30:51-05:00 level=info msg=completed 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:Value is sensitive and has been redacted. To see the value set config key "log.leak_sensitive_values = true" or environment variable "LOG_LEAK_SENSITIVE_VALUES=true". user-agent:Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/99.0.4844.82 Safari/537.36 x-forwarded-for:49.42.68.164:46852 x-forwarded-proto:https] host:idp.patientportal.myhealthhome.com method:GET path:/oauth2/auth query:Value is sensitive and has been redacted. To see the value set config key "log.leak_sensitive_values = true" or environment variable "LOG_LEAK_SENSITIVE_VALUES=true". remote:10.15.12.68:41637 scheme:http] http_response=map[status:302 text_status:Found took:1m0.650583406s]

Hydra version used : 1.10.2

Its happenning for all the request going to hydra via broweser for login verifier

https://<HYDRA_PUBLIC_URL>/oauth2/auth?client_id=3b2720ee-c75a-4902-8463-576fd761ae9f&login_verifier=eae37f5a268849b9a5b98570de0dbdc2&redirect_uri=&response_type=code&scope=openid+offline&state=MYLT47SACOJGHG8

[vinckr]

Hello,
Sorry you're having trouble.

Did you resolve the issue since you wrote us last in November? Did it not occur anymore and now suddenly happen again? Was there any change on your infra or to Hydra that could have caused this?
If you can share it:
Your setup, additional log files, your configuration and any other information that you think is helpful also helps us to solve your issue more quickly!