[Bug]: Errors on mix test related to spring auth

[jauggy]

Describe the Bug

Red errors when I run mix test for spring_auth_test.exs

Reproduce the bug

mix test pathto/spring/spring_auth_test.exs

Screenshots

No response

Additional context

...2024-07-21 22:53:49.096 [error] Postgrex.Protocol (#PID<0.691.0>) disconnected: ** (DBConnection.ConnectionError) owner #PID<0.1598.0> exited

Client #PID<0.1602.0> is still using a connection from owner at location:

    (erts 13.1.5) :prim_inet.recv0/3
    (postgrex 0.17.1) lib/postgrex/protocol.ex:3188: Postgrex.Protocol.msg_recv/4
    (postgrex 0.17.1) lib/postgrex/protocol.ex:2213: Postgrex.Protocol.recv_bind/3
    (postgrex 0.17.1) lib/postgrex/protocol.ex:2193: Postgrex.Protocol.rebind_execute/4
    (ecto_sql 3.10.1) lib/ecto/adapters/sql/sandbox.ex:375: Ecto.Adapters.SQL.Sandbox.Connection.proxy/3
    (db_connection 2.5.0) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
    (db_connection 2.5.0) lib/db_connection.ex:1432: DBConnection.run_execute/5
    (db_connection 2.5.0) lib/db_connection.ex:1527: DBConnection.run/6
    (db_connection 2.5.0) lib/db_connection.ex:656: DBConnection.parsed_prepare_execute/5
    (db_connection 2.5.0) lib/db_connection.ex:648: DBConnection.prepare_execute/4
    (postgrex 0.17.1) lib/postgrex.ex:340: Postgrex.query/4
    (ecto_sql 3.10.1) lib/ecto/adapters/sql.ex:955: Ecto.Adapters.SQL.struct/10
    (ecto 3.10.3) lib/ecto/repo/schema.ex:764: Ecto.Repo.Schema.apply/4
    (ecto 3.10.3) lib/ecto/repo/schema.ex:377: anonymous fn/15 in Ecto.Repo.Schema.do_insert/4
    (teiserver 0.1.0) lib/teiserver/telemetry/libs/simple_server_event_lib.ex:22: Teiserver.Telemetry.SimpleServerEventLib.log_simple_server_event/2
    (teiserver 0.1.0) lib/teiserver/data/client.ex:275: Teiserver.Client.do_disconnect/3
    (teiserver 0.1.0) lib/teiserver/tcp/spring/spring_tcp_server.ex:718: Teiserver.SpringTcpServer.handle_info/2
    (stdlib 4.2) gen_server.erl:1123: :gen_server.try_dispatch/4
    (stdlib 4.2) gen_server.erl:1200: :gen_server.handle_msg/6
    (stdlib 4.2) proc_lib.erl:240: :proc_lib.init_p_do_apply/3

The connection itself was checked out by #PID<0.1602.0> at location:

    (postgrex 0.17.1) lib/postgrex.ex:340: Postgrex.query/4
    (ecto_sql 3.10.1) lib/ecto/adapters/sql.ex:955: Ecto.Adapters.SQL.struct/10
    (ecto 3.10.3) lib/ecto/repo/schema.ex:764: Ecto.Repo.Schema.apply/4
    (ecto 3.10.3) lib/ecto/repo/schema.ex:377: anonymous fn/15 in Ecto.Repo.Schema.do_insert/4
    (teiserver 0.1.0) lib/teiserver/telemetry/libs/simple_server_event_lib.ex:22: Teiserver.Telemetry.SimpleServerEventLib.log_simple_server_event/2
    (teiserver 0.1.0) lib/teiserver/data/client.ex:275: Teiserver.Client.do_disconnect/3
    (teiserver 0.1.0) lib/teiserver/tcp/spring/spring_tcp_server.ex:718: Teiserver.SpringTcpServer.handle_info/2
    (stdlib 4.2) gen_server.erl:1123: :gen_server.try_dispatch/4
    (stdlib 4.2) gen_server.erl:1200: :gen_server.handle_msg/6
    (stdlib 4.2) proc_lib.erl:240: :proc_lib.init_p_do_apply/3


2024-07-21 22:53:49.121 request_id=SpringTcpServer#3841 [error] GenServer #PID<0.1600.0> terminating
** (stop) exited in: DBConnection.Holder.checkout(#PID<0.1599.0>, [log: #Function<13.1785099/1 in Ecto.Adapters.SQL.with_log/3>, cache_statement: "ecto_insert_telemetry_simple_server_events_0", cast_params: [668, ~U[2024-07-21 12:53:49Z], 3841], repo: Teiserver.Repo, queue_target: 5000, queue_interval: 100000, pool: DBConnection.Ownership, pool_size: 50, timeout: 300000])
    ** (EXIT) shutdown: %DBConnection.ConnectionError{message: "owner #PID<0.1598.0> exited\n\nClient #PID<0.1602.0> is still using a connection from owner at location:\n\n    (erts 13.1.5) :prim_inet.recv0/3\n    (postgrex 0.17.1) lib/postgrex/protocol.ex:3188: Postgrex.Protocol.msg_recv/4\n    (postgrex 0.17.1) lib/postgrex/protocol.ex:2213: Postgrex.Protocol.recv_bind/3\n    (postgrex 0.17.1) lib/postgrex/protocol.ex:2193: Postgrex.Protocol.rebind_execute/4\n    (ecto_sql 3.10.1) lib/ecto/adapters/sql/sandbox.ex:375: Ecto.Adapters.SQL.Sandbox.Connection.proxy/3\n    (db_connection 2.5.0) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4\n    (db_connection 2.5.0) lib/db_connection.ex:1432: DBConnection.run_execute/5\n    (db_connection 2.5.0) lib/db_connection.ex:1527: DBConnection.run/6\n    (db_connection 2.5.0) lib/db_connection.ex:656: DBConnection.parsed_prepare_execute/5\n    (db_connection 2.5.0) lib/db_connection.ex:648: DBConnection.prepare_execute/4\n    (postgrex 0.17.1) lib/postgrex.ex:340: Postgrex.query/4\n    (ecto_sql 3.10.1) lib/ecto/adapters/sql.ex:955: Ecto.Adapters.SQL.struct/10\n    (ecto 3.10.3) lib/ecto/repo/schema.ex:764: Ecto.Repo.Schema.apply/4\n    (ecto 3.10.3) lib/ecto/repo/schema.ex:377: anonymous fn/15 in Ecto.Repo.Schema.do_insert/4\n    (teiserver 0.1.0) lib/teiserver/telemetry/libs/simple_server_event_lib.ex:22: Teiserver.Telemetry.SimpleServerEventLib.log_simple_server_event/2\n    (teiserver 0.1.0) lib/teiserver/data/client.ex:275: Teiserver.Client.do_disconnect/3\n    (teiserver 0.1.0) lib/teiserver/tcp/spring/spring_tcp_server.ex:718: Teiserver.SpringTcpServer.handle_info/2\n    (stdlib 4.2) gen_server.erl:1123: :gen_server.try_dispatch/4\n    (stdlib 4.2) gen_server.erl:1200: :gen_server.handle_msg/6\n    (stdlib 4.2) proc_lib.erl:240: :proc_lib.init_p_do_apply/3\n\nThe connection itself was checked out by #PID<0.1602.0> at location:\n\n    (postgrex 0.17.1) lib/postgrex.ex:340: Postgrex.query/4\n    (ecto_sql 3.10.1) lib/ecto/adapters/sql.ex:955: Ecto.Adapters.SQL.struct/10\n    (ecto 3.10.3) lib/ecto/repo/schema.ex:764: Ecto.Repo.Schema.apply/4\n    (ecto 3.10.3) lib/ecto/repo/schema.ex:377: anonymous fn/15 in Ecto.Repo.Schema.do_insert/4\n    (teiserver 0.1.0) lib/teiserver/telemetry/libs/simple_server_event_lib.ex:22: Teiserver.Telemetry.SimpleServerEventLib.log_simple_server_event/2\n    (teiserver 0.1.0) lib/teiserver/data/client.ex:275: Teiserver.Client.do_disconnect/3\n    (teiserver 0.1.0) lib/teiserver/tcp/spring/spring_tcp_server.ex:718: Teiserver.SpringTcpServer.handle_info/2\n    (stdlib 4.2) gen_server.erl:1123: :gen_server.try_dispatch/4\n    (stdlib 4.2) gen_server.erl:1200: :gen_server.handle_msg/6\n    (stdlib 4.2) proc_lib.erl:240: :proc_lib.init_p_do_apply/3\n\n", severity: :error, reason: :error}
    (db_connection 2.5.0) lib/db_connection/holder.ex:97: DBConnection.Holder.checkout/3
    (db_connection 2.5.0) lib/db_connection/holder.ex:78: DBConnection.Holder.checkout/3
    (db_connection 2.5.0) lib/db_connection.ex:1200: DBConnection.checkout/3
    (db_connection 2.5.0) lib/db_connection.ex:1525: DBConnection.run/6
    (db_connection 2.5.0) lib/db_connection.ex:656: DBConnection.parsed_prepare_execute/5
    (db_connection 2.5.0) lib/db_connection.ex:648: DBConnection.prepare_execute/4
    (postgrex 0.17.1) lib/postgrex.ex:340: Postgrex.query/4
    (ecto_sql 3.10.1) lib/ecto/adapters/sql.ex:955: Ecto.Adapters.SQL.struct/10
    (ecto 3.10.3) lib/ecto/repo/schema.ex:764: Ecto.Repo.Schema.apply/4
    (ecto 3.10.3) lib/ecto/repo/schema.ex:377: anonymous fn/15 in Ecto.Repo.Schema.do_insert/4
    (teiserver 0.1.0) lib/teiserver/telemetry/libs/simple_server_event_lib.ex:22: Teiserver.Telemetry.SimpleServerEventLib.log_simple_server_event/2
    (teiserver 0.1.0) lib/teiserver/data/client.ex:275: Teiserver.Client.do_disconnect/3
    (teiserver 0.1.0) lib/teiserver/tcp/spring/spring_tcp_server.ex:718: Teiserver.SpringTcpServer.handle_info/2
    (stdlib 4.2) gen_server.erl:1123: :gen_server.try_dispatch/4
    (stdlib 4.2) gen_server.erl:1200: :gen_server.handle_msg/6
    (stdlib 4.2) proc_lib.erl:240: :proc_lib.init_p_do_apply/3
Last message: {:tcp_closed, #Port<0.81>}
2024-07-21 22:53:49.128 [error] Ranch listener #Reference<0.2806914703.4199284737.179243> had connection process started with Teiserver.SpringTcpServer:start_link/4 at #PID<0.1600.0> exit with reason: {{:shutdown, %DBConnection.ConnectionError{message: "owner #PID<0.1598.0> exited\n\nClient #PID<0.1602.0> is still using a connection from owner at location:\n\n    (erts 13.1.5) :prim_inet.recv0/3\n    (postgrex 0.17.1) lib/postgrex/protocol.ex:3188: Postgrex.Protocol.msg_recv/4\n    (postgrex 0.17.1) lib/postgrex/protocol.ex:2213: Postgrex.Protocol.recv_bind/3\n    (postgrex 0.17.1) lib/postgrex/protocol.ex:2193: Postgrex.Protocol.rebind_execute/4\n    (ecto_sql 3.10.1) lib/ecto/adapters/sql/sandbox.ex:375: Ecto.Adapters.SQL.Sandbox.Connection.proxy/3\n    (db_connection 2.5.0) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4\n    (db_connection 2.5.0) lib/db_connection.ex:1432: DBConnection.run_execute/5\n    (db_connection 2.5.0) lib/db_connection.ex:1527: DBConnection.run/6\n    (db_connection 2.5.0) lib/db_connection.ex:656: DBConnection.parsed_prepare_execute/5\n    (db_connection 2.5.0) lib/db_connection.ex:648: DBConnection.prepare_execute/4\n    (postgrex 0.17.1) lib/postgrex.ex:340: Postgrex.query/4\n    (ecto_sql 3.10.1) lib/ecto/adapters/sql.ex:955: Ecto.Adapters.SQL.struct/10\n    (ecto 3.10.3) lib/ecto/repo/schema.ex:764: Ecto.Repo.Schema.apply/4\n    (ecto 3.10.3) lib/ecto/repo/schema.ex:377: anonymous fn/15 in Ecto.Repo.Schema.do_insert/4\n    (teiserver 0.1.0) lib/teiserver/telemetry/libs/simple_server_event_lib.ex:22: Teiserver.Telemetry.SimpleServerEventLib.log_simple_server_event/2\n    (teiserver 0.1.0) lib/teiserver/data/client.ex:275: Teiserver.Client.do_disconnect/3\n    (teiserver 0.1.0) lib/teiserver/tcp/spring/spring_tcp_server.ex:718: Teiserver.SpringTcpServer.handle_info/2\n    (stdlib 4.2) gen_server.erl:1123: :gen_server.try_dispatch/4\n    (stdlib 4.2) gen_server.erl:1200: :gen_server.handle_msg/6\n    (stdlib 4.2) proc_lib.erl:240: :proc_lib.init_p_do_apply/3\n\nThe connection itself was checked out by #PID<0.1602.0> at location:\n\n    (postgrex 0.17.1) lib/postgrex.ex:340: Postgrex.query/4\n    (ecto_sql 3.10.1) lib/ecto/adapters/sql.ex:955: Ecto.Adapters.SQL.struct/10\n    (ecto 3.10.3) lib/ecto/repo/schema.ex:764: Ecto.Repo.Schema.apply/4\n    (ecto 3.10.3) lib/ecto/repo/schema.ex:377: anonymous fn/15 in Ecto.Repo.Schema.do_insert/4\n    (teiserver 0.1.0) lib/teiserver/telemetry/libs/simple_server_event_lib.ex:22: Teiserver.Telemetry.SimpleServerEventLib.log_simple_server_event/2\n    (teiserver 0.1.0) lib/teiserver/data/client.ex:275: Teiserver.Client.do_disconnect/3\n    (teiserver 0.1.0) lib/teiserver/tcp/spring/spring_tcp_server.ex:718: Teiserver.SpringTcpServer.handle_info/2\n    (stdlib 4.2) gen_server.erl:1123: :gen_server.try_dispatch/4\n    (stdlib 4.2) gen_server.erl:1200: :gen_server.handle_msg/6\n    (stdlib 4.2) proc_lib.erl:240: :proc_lib.init_p_do_apply/3\n\n", severity: :error, reason: :error}}, {DBConnection.Holder, :checkout, [#PID<0.1599.0>, [log: #Function<13.1785099/1 in Ecto.Adapters.SQL.with_log/3>, cache_statement: "ecto_insert_telemetry_simple_server_events_0", cast_params: [668, ~U[2024-07-21 12:53:49Z], 3841], repo: Teiserver.Repo, queue_target: 5000, queue_interval: 100000, pool: DBConnection.Ownership, pool_size: 50, timeout: 300000]]}}

[jauggy]

Even though I get a bunch of red errors all the tests pass. @geekingfrog is this expected? Do I have some setup wrong?

[NortySpock]

Out of curiosity, I gave it a go and got a test failure on my machine:

ran
mix test --seed 0 test/teiserver/protocols/spring/spring_auth_test.exs:448

output

Excluding tags: [:test]
Including tags: [location: {"test/teiserver/protocols/spring/spring_auth_test.exs", 448}]



  1) test RENAMEACCOUNT (Teiserver.SpringAuthTest)
     test/teiserver/protocols/spring/spring_auth_test.exs:448
     Assertion with == failed
     code:  assert accepted == "DENIED Flood protection - Please wait 20 seconds and try again"
     left:  "DENIED No user found for 'test_user_rename'"
     right: "DENIED Flood protection - Please wait 20 seconds and try again"
     stacktrace:
       test/teiserver/protocols/spring/spring_auth_test.exs:507: (test)


(...snip...)

Finished in 6.2 seconds (0.00s async, 6.2s sync)
17 tests, 1 failure, 16 excluded

So, reading line 507, it expected to hit flood protection, but actually could not find the user 'test_user_rename' , even after I bumped the timer.sleep(3000) (3000 milliseconds, I assume) on line 482

5000 milliseconds (5 seconds) worked, however. Maybe my machine is just slow as dirt?

I'm a novice to Elixir, but instead of just sleeping and hoping the timing works out, is there a flush / sync / fsync command we could set in the test to wait for the user rename step to commit properly before proceeding? (feel free to tell me I'm attacking the test from the wrong angle -- maybe protocol tests shouldn't have internal hooks to check to see if the database succeeded -- but then, perhaps instead we can have this be an in-memory database test so it can complete without having to actually flush to disk?)

[geekingfrog]

oooh yeah, that's a skipped test. Noticed the attribute :needs_attention, we skip these to at least have a green CI that allow us to catch new bugs.

If you want to observe something external, like a rename, you can poll. I have a utility function like that (nothing to do with tachyon, I just don't know of a better place to put it yet).

I haven't looked too much into that test tbh. If you want to have a go you're welcome, it's a good way to start understanding the current code.

There are many tests that are pretty cursed because there are global caches that are not isolated by tests, and sometimes also the code tested drifted away since for a long time there was no CI.

[NortySpock]

Yeah, I'll see if I can get the test to behave. Thanks for the utility function, I'll see if I can pull in the function in and get the test working.

I do notice the test is covering multiple things (ability to rename, plus flood-protection tracking a user through renames)... Might mean it would be better for me to split the test so as to focus each test on a single test case.