search

ory / kratos

The most scalable and customizable identity server on the market. Replace your Homegrown, Auth0, Okta, Firebase with better UX and DX. Has all the tablestakes: Passkeys, Social Sign In, Multi-Factor Auth, SMS, SAML, TOTP, and more. Written in Go, cloud native, headless, API-first. Available as a service on Ory Network and for self-hosters.
https://www.ory.sh/?utm_source=github&utm_medium=banner&utm_campaign=kratos
Apache License 2.0
11.2k stars 959 forks source link

Internal Server Error: Unable to increment the message's "send_count" field #4058

Closed micheljung closed 1 month ago

micheljung commented 1 month ago

Preflight checklist

Ory Network Project

No response

Describe the bug

I'm running stress tests against Kratos. With only a few users (~10), the "login with code" step fails fairly often. It looks like a concurrency issue.

Reproducing the bug

It's too much effort to build a reproducer to share, so please ask me if you can't spot the problem without one.

Relevant log output

time=2024-08-25T21:30:14Z level=info msg=completed handling request func=github.com/ory/x/reqlog.(*Middleware).ServeHTTP file=/go/pkg/mod/github.com/ory/x@v0.0.623/reqlog/middleware.go:146 http_request=map[headers:map[accept:*/*] host:kratos.dev1.example.com:4433 method:GET path:/self-service/login/api query:<nil> remote:192.168.80.1:58648 scheme:http] http_response=map[headers:map[cache-control:private, no-cache, no-store, must-revalidate content-type:application/json vary:Origin] size:116 status:500 text_status:Internal Server Error took:5.027972357s]
2024-08-25T21:30:14.140310593Z time=2024-08-25T21:30:14Z level=error msg=Unable to increment the message's "send_count" field func=github.com/ory/kratos/courier.(*courier).DispatchMessage file=/project/courier/courier_dispatcher.go:23 audience=application error=map[message:database is locked stack_trace:
2024-08-25T21:30:14.140392902Z github.com/ory/x/sqlcon.handleSqlite
2024-08-25T21:30:14.140401304Z  /go/pkg/mod/github.com/ory/x@v0.0.623/sqlcon/error_sqlite.go:36
2024-08-25T21:30:14.140405500Z github.com/ory/x/sqlcon.HandleError
2024-08-25T21:30:14.140407832Z  /go/pkg/mod/github.com/ory/x@v0.0.623/sqlcon/error.go:92
2024-08-25T21:30:14.140410028Z github.com/ory/kratos/persistence/sql.(*Persister).IncrementMessageSendCount
2024-08-25T21:30:14.140412777Z  /project/persistence/sql/persister_courier.go:167
2024-08-25T21:30:14.140415034Z github.com/ory/kratos/courier.(*courier).DispatchMessage
2024-08-25T21:30:14.140417361Z  /project/courier/courier_dispatcher.go:20
2024-08-25T21:30:14.140419521Z github.com/ory/kratos/courier.(*courier).DispatchQueue
2024-08-25T21:30:14.140421693Z  /project/courier/courier_dispatcher.go:82
2024-08-25T21:30:14.140423769Z github.com/ory/kratos/courier.(*courier).watchMessages.func1
2024-08-25T21:30:14.140425884Z  /project/courier/courier.go:119
2024-08-25T21:30:14.140427989Z github.com/cenkalti/backoff.RetryNotify
2024-08-25T21:30:14.140430144Z  /go/pkg/mod/github.com/cenkalti/backoff@v2.2.1+incompatible/retry.go:37
2024-08-25T21:30:14.140432387Z github.com/cenkalti/backoff.Retry
2024-08-25T21:30:14.140434590Z  /go/pkg/mod/github.com/cenkalti/backoff@v2.2.1+incompatible/retry.go:24
2024-08-25T21:30:14.140436799Z github.com/ory/kratos/courier.(*courier).watchMessages
2024-08-25T21:30:14.140438970Z  /project/courier/courier.go:118
2024-08-25T21:30:14.140441159Z runtime.goexit
2024-08-25T21:30:14.140444786Z  /usr/local/go/src/runtime/asm_amd64.s:1695] message_id=e9a07cf0-a06e-4f85-903c-cb7cc173a16e message_nid=b80bd973-557b-4c65-9d37-72c0ef292439 message_subject=Login to your account message_template_type=login_code_valid message_type=email service_name=Ory Kratos service_version=v1.2.0
2024-08-25T21:30:14.152759045Z time=2024-08-25T21:30:14Z level=info msg=Encountered self-service login error. func=github.com/ory/kratos/selfservice/flow/login.(*ErrorHandler).WriteFlowError file=/project/selfservice/flow/login/error.go:86 audience=audit error=map[message:I[#/] S[] the provided code is invalid or has already been used stack_trace:
2024-08-25T21:30:14.153552413Z github.com/ory/kratos/schema.NewLoginCodeInvalid
2024-08-25T21:30:14.153563776Z  /project/schema/errors.go:344
2024-08-25T21:30:14.153567569Z github.com/ory/kratos/selfservice/strategy/code.(*Strategy).loginVerifyCode
2024-08-25T21:30:14.153569943Z  /project/selfservice/strategy/code/strategy_login.go:324
2024-08-25T21:30:14.153572025Z github.com/ory/kratos/selfservice/strategy/code.(*Strategy).Login
2024-08-25T21:30:14.153574018Z  /project/selfservice/strategy/code/strategy_login.go:198
2024-08-25T21:30:14.153575963Z github.com/ory/kratos/selfservice/flow/login.(*Handler).updateLoginFlow
2024-08-25T21:30:14.153590980Z  /project/selfservice/flow/login/handler.go:797
2024-08-25T21:30:14.153593813Z github.com/ory/kratos/x.(*RouterPublic).POST.NoCacheHandle.func1
2024-08-25T21:30:14.153595871Z  /project/x/nocache.go:21
2024-08-25T21:30:14.153597710Z github.com/ory/kratos/x.(*RouterPublic).Handle.NoCacheHandle.func1
2024-08-25T21:30:14.153599665Z  /project/x/nocache.go:21
2024-08-25T21:30:14.153601494Z github.com/julienschmidt/httprouter.(*Router).ServeHTTP
2024-08-25T21:30:14.153603350Z  /go/pkg/mod/github.com/julienschmidt/httprouter@v1.3.0/router.go:387
2024-08-25T21:30:14.153605367Z github.com/ory/nosurf.(*CSRFHandler).handleSuccess
2024-08-25T21:30:14.153607192Z  /go/pkg/mod/github.com/ory/nosurf@v1.2.7/handler.go:234
2024-08-25T21:30:14.153609147Z github.com/ory/nosurf.(*CSRFHandler).ServeHTTP
2024-08-25T21:30:14.153611154Z  /go/pkg/mod/github.com/ory/nosurf@v1.2.7/handler.go:185
2024-08-25T21:30:14.153613253Z github.com/ory/kratos/cmd/daemon.servePublic.MaxBytesHandler.func4
2024-08-25T21:30:14.153615273Z  /usr/local/go/src/net/http/server.go:3841
2024-08-25T21:30:14.153617389Z net/http.HandlerFunc.ServeHTTP
2024-08-25T21:30:14.153619691Z  /usr/local/go/src/net/http/server.go:2166
2024-08-25T21:30:14.153621683Z github.com/urfave/negroni.(*Negroni).UseHandler.Wrap.func1
2024-08-25T21:30:14.153623666Z  /go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:46
2024-08-25T21:30:14.153625660Z github.com/urfave/negroni.HandlerFunc.ServeHTTP
2024-08-25T21:30:14.153627626Z  /go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29
2024-08-25T21:30:14.153629612Z github.com/urfave/negroni.middleware.ServeHTTP
2024-08-25T21:30:14.153631564Z  /go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38
2024-08-25T21:30:14.153633513Z github.com/ory/kratos/x.init.func1
2024-08-25T21:30:14.153638749Z  /project/x/clean_url.go:15
2024-08-25T21:30:14.153640791Z github.com/urfave/negroni.HandlerFunc.ServeHTTP
2024-08-25T21:30:14.153642755Z  /go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29
2024-08-25T21:30:14.153644732Z github.com/urfave/negroni.middleware.ServeHTTP
2024-08-25T21:30:14.153648906Z  /go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38
2024-08-25T21:30:14.153651212Z github.com/rs/cors.(*Cors).ServeHTTP
2024-08-25T21:30:14.153653249Z  /go/pkg/mod/github.com/rs/cors@v1.8.2/cors.go:266
2024-08-25T21:30:14.153657614Z github.com/ory/kratos/cmd/daemon.servePublic.func1
2024-08-25T21:30:14.153662310Z  /project/cmd/daemon/serve.go:114
2024-08-25T21:30:14.153664311Z github.com/urfave/negroni.HandlerFunc.ServeHTTP
2024-08-25T21:30:14.153666339Z  /go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29
2024-08-25T21:30:14.153673556Z github.com/urfave/negroni.middleware.ServeHTTP
2024-08-25T21:30:14.153675895Z  /go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38
2024-08-25T21:30:14.153677999Z net/http.HandlerFunc.ServeHTTP
2024-08-25T21:30:14.153680003Z  /usr/local/go/src/net/http/server.go:2166
2024-08-25T21:30:14.153682072Z github.com/prometheus/client_golang/prometheus/promhttp.InstrumentHandlerResponseSize.func1
2024-08-25T21:30:14.153684320Z  /go/pkg/mod/github.com/prometheus/client_golang@v1.13.0/prometheus/promhttp/instrument_server.go:284
2024-08-25T21:30:14.153686515Z net/http.HandlerFunc.ServeHTTP
2024-08-25T21:30:14.153690781Z  /usr/local/go/src/net/http/server.go:2166
2024-08-25T21:30:14.153692902Z github.com/prometheus/client_golang/prometheus/promhttp.InstrumentHandlerCounter.func1
2024-08-25T21:30:14.153695115Z  /go/pkg/mod/github.com/prometheus/client_golang@v1.13.0/prometheus/promhttp/instrument_server.go:142
2024-08-25T21:30:14.153697594Z net/http.HandlerFunc.ServeHTTP
2024-08-25T21:30:14.153699659Z  /usr/local/go/src/net/http/server.go:2166
2024-08-25T21:30:14.153702089Z github.com/prometheus/client_golang/prometheus/promhttp.InstrumentHandlerDuration.func1
2024-08-25T21:30:14.153704203Z  /go/pkg/mod/github.com/prometheus/client_golang@v1.13.0/prometheus/promhttp/instrument_server.go:92
2024-08-25T21:30:14.153706261Z net/http.HandlerFunc.ServeHTTP
2024-08-25T21:30:14.153708033Z  /usr/local/go/src/net/http/server.go:2166
2024-08-25T21:30:14.153709984Z github.com/prometheus/client_golang/prometheus/promhttp.InstrumentHandlerDuration.func2
2024-08-25T21:30:14.153712082Z  /go/pkg/mod/github.com/prometheus/client_golang@v1.13.0/prometheus/promhttp/instrument_server.go:104
2024-08-25T21:30:14.153714367Z net/http.HandlerFunc.ServeHTTP
2024-08-25T21:30:14.153716735Z  /usr/local/go/src/net/http/server.go:2166
2024-08-25T21:30:14.153720321Z github.com/prometheus/client_golang/prometheus/promhttp.InstrumentHandlerRequestSize.func1
2024-08-25T21:30:14.153722527Z  /go/pkg/mod/github.com/prometheus/client_golang@v1.13.0/prometheus/promhttp/instrument_server.go:234
2024-08-25T21:30:14.153724539Z net/http.HandlerFunc.ServeHTTP
2024-08-25T21:30:14.153727140Z  /usr/local/go/src/net/http/server.go:2166] http_request=map[headers:map[accept:application/json content-length:74 content-type:application/json] host:kratos.dev1.skill-duel.com:4433 method:POST path:/self-service/login query:flow=2d053c28-6a63-4c1a-91a6-22498b2d5fdc remote:192.168.80.1:58644 scheme:http] login_flow=&{2d053c28-6a63-4c1a-91a6-22498b2d5fdc b80bd973-557b-4c65-9d37-72c0ef292439 {00000000-0000-0000-0000-000000000000 false}  <nil> api 2024-08-25 21:40:08.893846027 +0000 UTC 2024-08-25 21:30:08.893846027 +0000 UTC [123 125] http://kratos.dev1.skill-duel.com:4433/self-service/login/api  code 0xc001af9360 2024-08-25 21:30:08.904248 +0000 UTC 2024-08-25 21:30:08.904248 +0000 UTC  false aal1  sent_email   [123 125] [] } service_name=Ory Kratos service_version=v1.2.0
2024-08-25T21:30:14.170373130Z

Relevant configuration

No response

Version

1.2.0

On which operating system are you observing this issue?

Linux

In which environment are you deploying?

Docker Compose

Additional Context

Another exception that appears often:

time=2024-08-25T21:26:48Z level=info msg=Encountered self-service login error. func=github.com/ory/kratos/selfservice/flow/login.(*ErrorHandler).WriteFlowError file=/project/selfservice/flow/login/error.go:86 audience=audit error=map[message:I[#/] S[] could not find a strategy to login with stack_trace:
2024-08-25T21:26:48.541542970Z github.com/ory/kratos/selfservice/flow/login.(*Handler).updateLoginFlow
2024-08-25T21:26:48.541578755Z  /project/selfservice/flow/login/handler.go:821
2024-08-25T21:26:48.541584892Z github.com/ory/kratos/x.(*RouterPublic).POST.NoCacheHandle.func1
2024-08-25T21:26:48.541588647Z  /project/x/nocache.go:21
2024-08-25T21:26:48.541592445Z github.com/ory/kratos/x.(*RouterPublic).Handle.NoCacheHandle.func1
2024-08-25T21:26:48.541595914Z  /project/x/nocache.go:21
2024-08-25T21:26:48.541599183Z github.com/julienschmidt/httprouter.(*Router).ServeHTTP
2024-08-25T21:26:48.541602523Z  /go/pkg/mod/github.com/julienschmidt/httprouter@v1.3.0/router.go:387
2024-08-25T21:26:48.541605966Z github.com/ory/nosurf.(*CSRFHandler).handleSuccess
2024-08-25T21:26:48.541609219Z  /go/pkg/mod/github.com/ory/nosurf@v1.2.7/handler.go:234
2024-08-25T21:26:48.541612587Z github.com/ory/nosurf.(*CSRFHandler).ServeHTTP
2024-08-25T21:26:48.541615878Z  /go/pkg/mod/github.com/ory/nosurf@v1.2.7/handler.go:185
2024-08-25T21:26:48.541619378Z github.com/ory/kratos/cmd/daemon.servePublic.MaxBytesHandler.func4
2024-08-25T21:26:48.541622692Z  /usr/local/go/src/net/http/server.go:3841
2024-08-25T21:26:48.541626007Z net/http.HandlerFunc.ServeHTTP
2024-08-25T21:26:48.541629231Z  /usr/local/go/src/net/http/server.go:2166
2024-08-25T21:26:48.541632845Z github.com/urfave/negroni.(*Negroni).UseHandler.Wrap.func1
2024-08-25T21:26:48.541636543Z  /go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:46
2024-08-25T21:26:48.541640485Z github.com/urfave/negroni.HandlerFunc.ServeHTTP
2024-08-25T21:26:48.541644867Z  /go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29
2024-08-25T21:26:48.541649468Z github.com/urfave/negroni.middleware.ServeHTTP
2024-08-25T21:26:48.541653180Z  /go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38
2024-08-25T21:26:48.541656871Z github.com/ory/kratos/x.init.func1
2024-08-25T21:26:48.541660173Z  /project/x/clean_url.go:15
2024-08-25T21:26:48.541663569Z github.com/urfave/negroni.HandlerFunc.ServeHTTP
2024-08-25T21:26:48.541666919Z  /go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29
2024-08-25T21:26:48.541670331Z github.com/urfave/negroni.middleware.ServeHTTP
2024-08-25T21:26:48.541673767Z  /go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38
2024-08-25T21:26:48.541677244Z github.com/rs/cors.(*Cors).ServeHTTP
2024-08-25T21:26:48.541680920Z  /go/pkg/mod/github.com/rs/cors@v1.8.2/cors.go:266
2024-08-25T21:26:48.541684552Z github.com/ory/kratos/cmd/daemon.servePublic.func1
2024-08-25T21:26:48.541688044Z  /project/cmd/daemon/serve.go:114
2024-08-25T21:26:48.541691507Z github.com/urfave/negroni.HandlerFunc.ServeHTTP
2024-08-25T21:26:48.541695906Z  /go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:29
2024-08-25T21:26:48.541713112Z github.com/urfave/negroni.middleware.ServeHTTP
2024-08-25T21:26:48.541717665Z  /go/pkg/mod/github.com/urfave/negroni@v1.0.0/negroni.go:38
2024-08-25T21:26:48.541721662Z net/http.HandlerFunc.ServeHTTP
2024-08-25T21:26:48.541725208Z  /usr/local/go/src/net/http/server.go:2166
2024-08-25T21:26:48.541728695Z github.com/prometheus/client_golang/prometheus/promhttp.InstrumentHandlerResponseSize.func1
2024-08-25T21:26:48.541732937Z  /go/pkg/mod/github.com/prometheus/client_golang@v1.13.0/prometheus/promhttp/instrument_server.go:284
2024-08-25T21:26:48.541737287Z net/http.HandlerFunc.ServeHTTP
2024-08-25T21:26:48.541740689Z  /usr/local/go/src/net/http/server.go:2166
2024-08-25T21:26:48.541744314Z github.com/prometheus/client_golang/prometheus/promhttp.InstrumentHandlerCounter.func1
2024-08-25T21:26:48.541747920Z  /go/pkg/mod/github.com/prometheus/client_golang@v1.13.0/prometheus/promhttp/instrument_server.go:142
2024-08-25T21:26:48.541752122Z net/http.HandlerFunc.ServeHTTP
2024-08-25T21:26:48.541755724Z  /usr/local/go/src/net/http/server.go:2166
2024-08-25T21:26:48.541759837Z github.com/prometheus/client_golang/prometheus/promhttp.InstrumentHandlerDuration.func1
2024-08-25T21:26:48.541764106Z  /go/pkg/mod/github.com/prometheus/client_golang@v1.13.0/prometheus/promhttp/instrument_server.go:92
2024-08-25T21:26:48.541767744Z net/http.HandlerFunc.ServeHTTP
2024-08-25T21:26:48.541771559Z  /usr/local/go/src/net/http/server.go:2166
2024-08-25T21:26:48.541775009Z github.com/prometheus/client_golang/prometheus/promhttp.InstrumentHandlerDuration.func2
2024-08-25T21:26:48.541779054Z  /go/pkg/mod/github.com/prometheus/client_golang@v1.13.0/prometheus/promhttp/instrument_server.go:104
2024-08-25T21:26:48.541782874Z net/http.HandlerFunc.ServeHTTP
2024-08-25T21:26:48.541786620Z  /usr/local/go/src/net/http/server.go:2166
2024-08-25T21:26:48.541791564Z github.com/prometheus/client_golang/prometheus/promhttp.InstrumentHandlerRequestSize.func1
2024-08-25T21:26:48.541795249Z  /go/pkg/mod/github.com/prometheus/client_golang@v1.13.0/prometheus/promhttp/instrument_server.go:234
2024-08-25T21:26:48.541799032Z net/http.HandlerFunc.ServeHTTP
2024-08-25T21:26:48.541802894Z  /usr/local/go/src/net/http/server.go:2166
2024-08-25T21:26:48.541806318Z github.com/ory/x/prometheusx.Metrics.Instrument.Metrics.instrumentHandlerStatusBucket.func1
2024-08-25T21:26:48.541809879Z  /go/pkg/mod/github.com/ory/x@v0.0.623/prometheusx/metrics.go:115
2024-08-25T21:26:48.541813662Z net/http.HandlerFunc.ServeHTTP
2024-08-25T21:26:48.541817774Z  /usr/local/go/src/net/http/server.go:2166
2024-08-25T21:26:48.541821207Z github.com/ory/x/prometheusx.(*MetricsManager).ServeHTTP
2024-08-25T21:26:48.541826451Z  /go/pkg/mod/github.com/ory/x@v0.0.623/prometheusx/middleware.go:41] http_request=map[headers:map[accept:application/json content-length:77 content-type:application/json] host:kratos.dev1.example.com:4433 method:POST path:/self-service/login query:flow=4e7af34a-a282-473b-82d1-f9b959aec524 remote:192.168.80.1:60016 scheme:http] login_flow=&{4e7af34a-a282-473b-82d1-f9b959aec524 b80bd973-557b-4c65-9d37-72c0ef292439 {00000000-0000-0000-0000-000000000000 false}  <nil> api 2024-08-25 21:36:48.23496466 +0000 UTC 2024-08-25 21:26:48.23496466 +0000 UTC [123 125] http://kratos.dev1.example.com:4433/self-service/login/api  code 0xc00350f950 2024-08-25 21:26:48.264187 +0000 UTC 2024-08-25 21:26:48.264187 +0000 UTC  false aal1  sent_email   [123 125] [] } service_name=Ory Kratos service_version=v1.2.0
micheljung commented 1 month ago

Oh, wait, only now I see database is locked stack_trace and handleSqlite. I'm testing locally, using SQL Lite. Which, of course, is not expected to be stable.