bikebrigade / dispatch

Bike Brigade's dispatching software! 🚴
https://bikebrigade.ca
Apache License 2.0
72 stars 9 forks source link

Broken Test: Presence issue #319

Open teesloane opened 3 months ago

teesloane commented 3 months ago

Every time I run tests this spews:

12:05:04.757 [error] Task #PID<0.1496.0> started from BikeBrigade.Presence_shard0 terminating
** (stop) exited in: DBConnection.Holder.checkout(#PID<0.1484.0>, [log: #Function<13.13581932/1 in Ecto.Adapters.SQL.with_log/3>, source: "users", cast_params: [[]], repo: BikeBrigade.Repo, timeout: 15000, pool_size: 10, pool: DBConnection.Ownership])
    ** (EXIT) shutdown: "owner #PID<0.1483.0> exited"
    (db_connection 2.6.0) lib/db_connection/holder.ex:97: DBConnection.Holder.checkout/3
    (db_connection 2.6.0) lib/db_connection/holder.ex:78: DBConnection.Holder.checkout/3
    (db_connection 2.6.0) lib/db_connection.ex:1280: DBConnection.checkout/3
    (db_connection 2.6.0) lib/db_connection.ex:1605: DBConnection.run/6
    (db_connection 2.6.0) lib/db_connection.ex:800: DBConnection.execute/4
    (ecto_sql 3.11.1) lib/ecto/adapters/postgres/connection.ex:133: Ecto.Adapters.Postgres.Connection.execute/4
    (ecto_sql 3.11.1) lib/ecto/adapters/sql.ex:996: Ecto.Adapters.SQL.execute!/5
    (ecto_sql 3.11.1) lib/ecto/adapters/sql.ex:952: Ecto.Adapters.SQL.execute/6
    (ecto 3.11.1) lib/ecto/repo/queryable.ex:232: Ecto.Repo.Queryable.execute/4
    (ecto 3.11.1) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
    (bike_brigade 0.1.0) lib/bike_brigade/presence.ex:12: BikeBrigade.Presence.fetch/2
    (phoenix 1.7.10) lib/phoenix/presence.ex:609: anonymous fn/2 in Phoenix.Presence.async_merge/2
    (elixir 1.16.2) lib/enum.ex:1708: anonymous fn/3 in Enum.map/2
    (stdlib 5.2.2) maps.erl:416: :maps.fold_1/4
    (elixir 1.16.2) lib/enum.ex:2540: Enum.map/2
    (phoenix 1.7.10) lib/phoenix/presence.ex:608: anonymous fn/3 in Phoenix.Presence.async_merge/2
    (elixir 1.16.2) lib/task/supervised.ex:101: Task.Supervised.invoke_mfa/2
    (elixir 1.16.2) lib/task/supervised.ex:36: Task.Supervised.reply/4
Function: #Function<0.36326264/0 in Phoenix.Presence.async_merge/2>
    Args: []
12:05:04.760 [error] GenServer BikeBrigade.Presence_shard0 terminating
** (FunctionClauseError) no function clause matching in Phoenix.Presence.handle_info/2
    (phoenix 1.7.10) lib/phoenix/presence.ex:504: Phoenix.Presence.handle_info({:DOWN, #Reference<0.0.65027.3534340900.612433922.211812>, :process, #PID<0.1496.0>, {{:shutdown, "owner #PID<0.1483.0> exited"}, {DBConnection.Holder, :checkout, [#PID<0.1484.0>, [log: #Function<13.13581932/1 in Ecto.Adapters.SQL.with_log/3>, source: "users", cast_params: [[]], repo: BikeBrigade.Repo, timeout: 15000, pool_size: 10, pool: DBConnection.Ownership]]}}}, %{module: BikeBrigade.Presence, pubsub_server: BikeBrigade.PubSub, task_supervisor: BikeBrigade.Presence.TaskSupervisor, current_task: {#Reference<0.3534340900.612368386.211808>, %Task{mfa: {:erlang, :apply, 2}, owner: #PID<0.508.0>, pid: #PID<0.1496.0>, ref: #Reference<0.0.65027.3534340900.612433922.211812>}}, tasks: {[], []}, client_state: nil, topics: %{}})
    (phoenix_pubsub 2.1.3) lib/phoenix/tracker/shard.ex:223: Phoenix.Tracker.Shard.handle_info/2
    (stdlib 5.2.2) gen_server.erl:1095: :gen_server.try_handle_info/3
    (stdlib 5.2.2) gen_server.erl:1183: :gen_server.handle_msg/6
    (stdlib 5.2.2) proc_lib.erl:241: :proc_lib.init_p_do_apply/3
Last message: {:DOWN, #Reference<0.0.65027.3534340900.612433922.211812>, :process, #PID<0.1496.0>, {{:shutdown, "owner #PID<0.1483.0> exited"}, {DBConnection.Holder, :checkout, [#PID<0.1484.0>, [log: #Function<13.13581932/1 in Ecto.Adapters.SQL.with_log/3>, source: "users", cast_params: [[]], repo: BikeBrigade.Repo, timeout: 15000, pool_size: 10, pool: DBConnection.Ownership]]}}}

And I have just ignored it forever because it's a skipped test.

Let's fix it!

teesloane commented 1 month ago

I took a look at this, but didn't make great progress. Here's what I've learned so far:

first off, I'm not seeing the Presence issue. Hooray! But we are seeing this issue now:

18:06:16.499 [error] Postgrex.Protocol (#PID<0.482.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.1256.0> exited

I looked into the error and found a suggestion on the elixir forum.

When running mix test with --trace` and a slowdown on exit, we can see where the postgrex timeout's are showing up.

CleanShot 2024-06-13 at 18 09 59@2x

Here are the culprits, as text:

BikeBrigadeWeb.CampaignLiveTest [test/bike_brigade_web/live/campaign_live_test.exs]

  * test Show with riders Can assign a rider to a task [L#199]18:06:02.780 [error] Postgrex.Protocol (#PID<0.479.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.961.0> exited
  * test Show with riders Can unassign a rider from a task [L#224]18:06:03.868 [error] Postgrex.Protocol (#PID<0.488.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.981.0> exited

BikeBrigadeWeb.CampaignSignupLiveTest [test/bike_brigade_web/live/campaign_signup_live_test.exs]

  * test Show Rider can signup for a task [L#175]18:06:16.499 [error] Postgrex.Protocol (#PID<0.482.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.1256.0> exited

I think I'll come back to this a bit later, as it doesn't really constitute a failing test and I think is low priority.