`Postgrex.SCRAM.LockedCache` is is not alive on `SIGTERM`

[jozuas]

Not entirely sure if this is a bug, nor if anything can be done about it. But pretty often we get some exceptions on systemctl restart of our Elixir app. It seems that the order of supervision tree shutdown is resulting in some race conditions? I understand that this is benign, but I wanted to highlight this in case anyone else is experiencing the same problem.

Elixir version

Elixir 1.19.0 (compiled with Erlang/OTP 28)

Database and Version

PostgreSQL 18

Postgrex Version

postgres (PostgreSQL) 18.0

Current behavior

journalctl log:

Feb 11 11:02:31 tp-web-2 systemd[1]: Stopping terrapin-app...
Feb 11 11:02:32 tp-web-2 terrapin-app[139595]: 11:02:32.342 pid=<0.4838.0>  [notice] SIGTERM received - shutting down
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: 11:02:34.304 pid=<0.301574.0> module=gen_statem function=error_info/7 line=4990  [error] :gen_statem #PID<0.301574.0> terminating
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: ** (stop) exited in: GenServer.call(Postgrex.SCRAM.LockedCache, {:lock, {<<3, 159, 112, 140, 60, 115, 220, 100, 155, 57, 217, 110, 87, 163, 48, 112, 175, 28, 181, 24, 75, 206, 165, 27, 184, 248, 161, 221, 103, 216, 169, 176>>, <<36, 132, 79, 226, 238, 231, 22, 67, 65, 206, 170, 133, 123, 128, 167, 168>>, 4096}}, :infinity)
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     ** (EXIT) no process: the process is not alive or there's no process currently associated with the given name, possibly because its application isn't started
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (elixir 1.19.0) lib/gen_server.ex:1135: GenServer.call/3
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/scram/locked_cache.ex:33: Postgrex.SCRAM.LockedCache.run/2
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/scram.ex:28: Postgrex.SCRAM.client_final/2
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/protocol.ex:912: Postgrex.Protocol.auth_cont/4
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/protocol.ex:749: Postgrex.Protocol.handshake/3
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/protocol.ex:229: Postgrex.Protocol.connect_endpoints/6
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (db_connection 2.8.1) lib/db_connection/connection.ex:79: DBConnection.Connection.handle_event/4
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (stdlib 7.1) gen_statem.erl:3750: :gen_statem.loop_state_callback/11
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: Process Label: "db_conn_8"
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: Queue: [internal: {:connect, :init}]
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: Postponed: []
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: 11:02:34.305 pid=<0.301575.0> module=gen_statem function=error_info/7 line=4990  [error] :gen_statem #PID<0.301575.0> terminating
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: ** (stop) exited in: GenServer.call(Postgrex.SCRAM.LockedCache, {:lock, {<<3, 159, 112, 140, 60, 115, 220, 100, 155, 57, 217, 110, 87, 163, 48, 112, 175, 28, 181, 24, 75, 206, 165, 27, 184, 248, 161, 221, 103, 216, 169, 176>>, <<36, 132, 79, 226, 238, 231, 22, 67, 65, 206, 170, 133, 123, 128, 167, 168>>, 4096}}, :infinity)
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     ** (EXIT) no process: the process is not alive or there's no process currently associated with the given name, possibly because its application isn't started
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (elixir 1.19.0) lib/gen_server.ex:1135: GenServer.call/3
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/scram/locked_cache.ex:33: Postgrex.SCRAM.LockedCache.run/2
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/scram.ex:28: Postgrex.SCRAM.client_final/2
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/protocol.ex:912: Postgrex.Protocol.auth_cont/4
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/protocol.ex:749: Postgrex.Protocol.handshake/3
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/protocol.ex:229: Postgrex.Protocol.connect_endpoints/6
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (db_connection 2.8.1) lib/db_connection/connection.ex:79: DBConnection.Connection.handle_event/4
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (stdlib 7.1) gen_statem.erl:3750: :gen_statem.loop_state_callback/11
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: Process Label: "db_conn_4"
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: Queue: [internal: {:connect, :init}]
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: Postponed: []
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: 11:02:34.308 pid=<0.301576.0> module=gen_statem function=error_info/7 line=4990  [error] :gen_statem #PID<0.301576.0> terminating
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: ** (stop) exited in: GenServer.call(Postgrex.SCRAM.LockedCache, {:lock, {<<3, 159, 112, 140, 60, 115, 220, 100, 155, 57, 217, 110, 87, 163, 48, 112, 175, 28, 181, 24, 75, 206, 165, 27, 184, 248, 161, 221, 103, 216, 169, 176>>, <<36, 132, 79, 226, 238, 231, 22, 67, 65, 206, 170, 133, 123, 128, 167, 168>>, 4096}}, :infinity)
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     ** (EXIT) no process: the process is not alive or there's no process currently associated with the given name, possibly because its application isn't started
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (elixir 1.19.0) lib/gen_server.ex:1135: GenServer.call/3
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/scram/locked_cache.ex:33: Postgrex.SCRAM.LockedCache.run/2
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/scram.ex:28: Postgrex.SCRAM.client_final/2
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/protocol.ex:912: Postgrex.Protocol.auth_cont/4
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/protocol.ex:749: Postgrex.Protocol.handshake/3
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/protocol.ex:229: Postgrex.Protocol.connect_endpoints/6
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (db_connection 2.8.1) lib/db_connection/connection.ex:79: DBConnection.Connection.handle_event/4
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (stdlib 7.1) gen_statem.erl:3750: :gen_statem.loop_state_callback/11
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: Process Label: "db_conn_17"
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: Queue: [internal: {:connect, :init}]
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: Postponed: []
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: 11:02:34.349 pid=<0.301577.0> module=gen_statem function=error_info/7 line=4990  [error] :gen_statem #PID<0.301577.0> terminating
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: ** (stop) exited in: GenServer.call(Postgrex.SCRAM.LockedCache, {:lock, {<<3, 159, 112, 140, 60, 115, 220, 100, 155, 57, 217, 110, 87, 163, 48, 112, 175, 28, 181, 24, 75, 206, 165, 27, 184, 248, 161, 221, 103, 216, 169, 176>>, <<36, 132, 79, 226, 238, 231, 22, 67, 65, 206, 170, 133, 123, 128, 167, 168>>, 4096}}, :infinity)
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     ** (EXIT) no process: the process is not alive or there's no process currently associated with the given name, possibly because its application isn't started
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (elixir 1.19.0) lib/gen_server.ex:1135: GenServer.call/3
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/scram/locked_cache.ex:33: Postgrex.SCRAM.LockedCache.run/2
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/scram.ex:28: Postgrex.SCRAM.client_final/2
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/protocol.ex:912: Postgrex.Protocol.auth_cont/4
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/protocol.ex:749: Postgrex.Protocol.handshake/3
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/protocol.ex:229: Postgrex.Protocol.connect_endpoints/6
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (db_connection 2.8.1) lib/db_connection/connection.ex:79: DBConnection.Connection.handle_event/4
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (stdlib 7.1) gen_statem.erl:3750: :gen_statem.loop_state_callback/11
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: Process Label: "db_conn_2"
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: Queue: [internal: {:connect, :init}]
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: Postponed: []
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: 11:02:34.351 pid=<0.301578.0> module=gen_statem function=error_info/7 line=4990  [error] :gen_statem #PID<0.301578.0> terminating
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: ** (stop) exited in: GenServer.call(Postgrex.SCRAM.LockedCache, {:lock, {<<3, 159, 112, 140, 60, 115, 220, 100, 155, 57, 217, 110, 87, 163, 48, 112, 175, 28, 181, 24, 75, 206, 165, 27, 184, 248, 161, 221, 103, 216, 169, 176>>, <<36, 132, 79, 226, 238, 231, 22, 67, 65, 206, 170, 133, 123, 128, 167, 168>>, 4096}}, :infinity)
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     ** (EXIT) no process: the process is not alive or there's no process currently associated with the given name, possibly because its application isn't started
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (elixir 1.19.0) lib/gen_server.ex:1135: GenServer.call/3
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/scram/locked_cache.ex:33: Postgrex.SCRAM.LockedCache.run/2
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/scram.ex:28: Postgrex.SCRAM.client_final/2
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/protocol.ex:912: Postgrex.Protocol.auth_cont/4
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/protocol.ex:749: Postgrex.Protocol.handshake/3
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/protocol.ex:229: Postgrex.Protocol.connect_endpoints/6
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (db_connection 2.8.1) lib/db_connection/connection.ex:79: DBConnection.Connection.handle_event/4
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (stdlib 7.1) gen_statem.erl:3750: :gen_statem.loop_state_callback/11
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: Process Label: "db_conn_6"
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: Queue: [internal: {:connect, :init}]
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: Postponed: []
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: 11:02:34.353 pid=<0.301579.0> module=gen_statem function=error_info/7 line=4990  [error] :gen_statem #PID<0.301579.0> terminating
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: ** (stop) exited in: GenServer.call(Postgrex.SCRAM.LockedCache, {:lock, {<<3, 159, 112, 140, 60, 115, 220, 100, 155, 57, 217, 110, 87, 163, 48, 112, 175, 28, 181, 24, 75, 206, 165, 27, 184, 248, 161, 221, 103, 216, 169, 176>>, <<36, 132, 79, 226, 238, 231, 22, 67, 65, 206, 170, 133, 123, 128, 167, 168>>, 4096}}, :infinity)
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     ** (EXIT) no process: the process is not alive or there's no process currently associated with the given name, possibly because its application isn't started
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (elixir 1.19.0) lib/gen_server.ex:1135: GenServer.call/3
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/scram/locked_cache.ex:33: Postgrex.SCRAM.LockedCache.run/2
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/scram.ex:28: Postgrex.SCRAM.client_final/2
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/protocol.ex:912: Postgrex.Protocol.auth_cont/4
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/protocol.ex:749: Postgrex.Protocol.handshake/3
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (postgrex 0.21.1) lib/postgrex/protocol.ex:229: Postgrex.Protocol.connect_endpoints/6
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (db_connection 2.8.1) lib/db_connection/connection.ex:79: DBConnection.Connection.handle_event/4
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]:     (stdlib 7.1) gen_statem.erl:3750: :gen_statem.loop_state_callback/11
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: Process Label: "db_conn_7"
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: Queue: [internal: {:connect, :init}]
Feb 11 11:02:34 tp-web-2 terrapin-app[139595]: Postponed: []
Feb 11 11:02:38 tp-web-2 systemd[1]: terrapin-app.service: Deactivated successfully.
Feb 11 11:02:38 tp-web-2 systemd[1]: Stopped terrapin-app.

Expected behavior

Feb 11 11:02:31 tp-web-2 systemd[1]: Stopping terrapin-app...
Feb 11 11:02:32 tp-web-2 terrapin-app[139595]: 11:02:32.342 pid=<0.4838.0>  [notice] SIGTERM received - shutting down
Feb 11 11:02:38 tp-web-2 systemd[1]: terrapin-app.service: Deactivated successfully.
Feb 11 11:02:38 tp-web-2 systemd[1]: Stopped terrapin-app.

[josevalim]

I don't think this is a Postgrex bug. If your application depends on Postgrex, then your application should shutdown all of its processes first, which would include its connection pool, then it will proceed to shutdown other applications, including Postgrex.

This can only happen if you are starting processes and repositories outside of the supervision tree, so they are not getting cleaned up. Or if there is a bug somewhere. Can you by any chance reproduce this in an application that you can share?

Thank you.

[jozuas]

Oh, that makes a lot of sense, I did not think about that! I can see that in our codebase the employees are using unsupervised tasks that do DB operations in quite a few places. Let me remove those instances and report back after some days of observation. Thanks a lot!

[jozuas]

I moved all unsupervised tasks/processes that do DB operations to supervised tasks that are supposed to get shut down before Ecto repos are shutdown, and the incidence of this exception has decreased, but is still occurring. Looking into it further.

[josevalim]

Please let me know if you have any updates!

[jozuas]

Thanks for the reminder, I had a reminder set for looking at this again, but I somehow lost it. We are still routinely getting these after having removed all unsupervised tasks and processes. Claude insists it's a bug in Postgrex ad nauseam (when provided source code to postgrex), I will try to see what I can do to create an isolated example for replicating this.