Skip to content

Comments

Query page#5

Closed
nathanl wants to merge 1 commit intoftes:mainfrom
nathanl:query_page
Closed

Query page#5
nathanl wants to merge 1 commit intoftes:mainfrom
nathanl:query_page

Conversation

@nathanl
Copy link
Contributor

@nathanl nathanl commented Nov 10, 2025

Builds on #4

Adds a demo page for Better sandbox lifecycle management.

Instructions:

  • Run mix test test/features as usual - should pass
  • Run QUERY_DELAY=100 mix test test/features - the test passes because it doesn't try to verify the results of the delayed async operation, but errors appear in the log when that operation attempts to use the sandbox after its owner (the test process) has shut down
  • Point mix.exs at the branch in Better sandbox lifecycle management phoenix_test_playwright#95, mix deps.update, and add @tag sandbox_shutdown_delay: 200 above the test. The error logs do not appear because the sandbox shutdown is delayed long enough for queries to finish.

@ftes
Copy link
Owner

ftes commented Nov 11, 2025

Interesting: In step 2, I only see the errors if @tag trace: :open is present.

I can confirm that in step 3, the error disappears.
But regardless of whether I add @tag sandbox_shutdown_delay: 200 or not.

@nathanl
Copy link
Contributor Author

nathanl commented Nov 11, 2025

Interesting. Yeah, if I run CI=true QUERY_DELAY=200 mix test test/features (based on seeing if !System.get_env("CI"), do: @tag(trace: :open)) I don't see the error logs, but if I add IO.inspect/1 calls I can see that the SELECT random() never runs in that case. My guess is that this is because not only the test but the entire test suite is finished, so the test server is shut down before the query happens. That wouldn't be the case in a test suite where more tests still have to run.

If I run CI=true QUERY_DELAY=2 mix test test/features I sometimes see the error log. In that case I guess it's a race between the query and the test server shutting down.

@nathanl
Copy link
Contributor Author

nathanl commented Nov 11, 2025

I'll rebase this PR

@ftes
Copy link
Owner

ftes commented Nov 11, 2025

With these

changes to this PR Diff below contains: - your step 3 - with multiple async browser test suites - but without `@tag sandbox_shutdown_delay: 200`
diff --git a/mix.exs b/mix.exs
index d5ce0f1..06b0dd3 100644
--- a/mix.exs
+++ b/mix.exs
@@ -67,7 +67,11 @@ defmodule MyApp.MixProject do
       {:dns_cluster, "~> 0.2.0"},
       {:bandit, "~> 1.5"},
       {:phoenix_test, "~> 0.7", only: :test, runtime: false},
-      {:phoenix_test_playwright, "~> 0.9", only: :test, runtime: false}
+      {:phoenix_test_playwright,
+       github: "nathanl/phoenix_test_playwright",
+       ref: "sandbox_owner",
+       only: :test,
+       runtime: false}
     ]
   end
 
diff --git a/mix.lock b/mix.lock
index 03247e2..c3a181d 100644
--- a/mix.lock
+++ b/mix.lock
@@ -35,7 +35,7 @@
   "phoenix_pubsub": {:hex, :phoenix_pubsub, "2.2.0", "ff3a5616e1bed6804de7773b92cbccfc0b0f473faf1f63d7daf1206c7aeaaa6f", [:mix], [], "hexpm", "adc313a5bf7136039f63cfd9668fde73bba0765e0614cba80c06ac9460ff3e96"},
   "phoenix_template": {:hex, :phoenix_template, "1.0.4", "e2092c132f3b5e5b2d49c96695342eb36d0ed514c5b252a77048d5969330d639", [:mix], [{:phoenix_html, "~> 2.14.2 or ~> 3.0 or ~> 4.0", [hex: :phoenix_html, repo: "hexpm", optional: true]}], "hexpm", "2c0c81f0e5c6753faf5cca2f229c9709919aba34fab866d3bc05060c9c444206"},
   "phoenix_test": {:hex, :phoenix_test, "0.9.0", "0349496d868e53f2c776abe59204b09b2484475f97e3be7e9c9dcdd26f343551", [:mix], [{:jason, "~> 1.4", [hex: :jason, repo: "hexpm", optional: false]}, {:lazy_html, "~> 0.1.7", [hex: :lazy_html, repo: "hexpm", optional: false]}, {:mime, ">= 1.0.0", [hex: :mime, repo: "hexpm", optional: true]}, {:phoenix, ">= 1.7.10", [hex: :phoenix, repo: "hexpm", optional: false]}, {:phoenix_live_view, "~> 1.0", [hex: :phoenix_live_view, repo: "hexpm", optional: false]}], "hexpm", "c214433a6c14746a0b58985653a72cdf1f19084c60f1ea2c8b8c4e0c809ec9f2"},
-  "phoenix_test_playwright": {:hex, :phoenix_test_playwright, "0.9.1", "deac9b101ab506cdc04cad3bedfb7ec99753418fbab68fd63214126dcf92bc5c", [:mix], [{:ecto_sql, "~> 3.10", [hex: :ecto_sql, repo: "hexpm", optional: true]}, {:nimble_options, "~> 1.1", [hex: :nimble_options, repo: "hexpm", optional: false]}, {:phoenix, "~> 1.7", [hex: :phoenix, repo: "hexpm", optional: false]}, {:phoenix_ecto, "~> 4.5", [hex: :phoenix_ecto, repo: "hexpm", optional: true]}, {:phoenix_live_view, "~> 1.0", [hex: :phoenix_live_view, repo: "hexpm", optional: false]}, {:phoenix_test, "~> 0.8", [hex: :phoenix_test, repo: "hexpm", optional: false]}], "hexpm", "82ebcb8cd8926a8d9054b9ff44c99991f0fa2247b4fc1434369f50f8e0913bfc"},
+  "phoenix_test_playwright": {:git, "https://github.com/nathanl/phoenix_test_playwright.git", "fe1da3095c26499d032b9111174a8c091966584c", [ref: "sandbox_owner"]},
   "plug": {:hex, :plug, "1.18.1", "5067f26f7745b7e31bc3368bc1a2b818b9779faa959b49c934c17730efc911cf", [:mix], [{:mime, "~> 1.0 or ~> 2.0", [hex: :mime, repo: "hexpm", optional: false]}, {:plug_crypto, "~> 1.1.1 or ~> 1.2 or ~> 2.0", [hex: :plug_crypto, repo: "hexpm", optional: false]}, {:telemetry, "~> 0.4.3 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "57a57db70df2b422b564437d2d33cf8d33cd16339c1edb190cd11b1a3a546cc2"},
   "plug_crypto": {:hex, :plug_crypto, "2.1.1", "19bda8184399cb24afa10be734f84a16ea0a2bc65054e23a62bb10f06bc89491", [:mix], [], "hexpm", "6470bce6ffe41c8bd497612ffde1a7e4af67f36a15eea5f921af71cf3e11247c"},
   "postgrex": {:hex, :postgrex, "0.21.1", "2c5cc830ec11e7a0067dd4d623c049b3ef807e9507a424985b8dcf921224cd88", [:mix], [{:db_connection, "~> 2.1", [hex: :db_connection, repo: "hexpm", optional: false]}, {:decimal, "~> 1.5 or ~> 2.0", [hex: :decimal, repo: "hexpm", optional: false]}, {:jason, "~> 1.0", [hex: :jason, repo: "hexpm", optional: true]}, {:table, "~> 0.1.0", [hex: :table, repo: "hexpm", optional: true]}], "hexpm", "27d8d21c103c3cc68851b533ff99eef353e6a0ff98dc444ea751de43eb48bdac"},
diff --git a/test/features/register_test.exs b/test/features/register_test.exs
index fd4e0e5..b697516 100644
--- a/test/features/register_test.exs
+++ b/test/features/register_test.exs
@@ -1,25 +1,28 @@
 defmodule Features.RegisterTest do
-  use PhoenixTest.Playwright.Case, async: true
+  use PhoenixTest.Playwright.Case, async: true, parameterize: Enum.map(1..10, &%{param: &1})
   use MyAppWeb, :verified_routes
 
-  if !System.get_env("CI"), do: @tag(trace: :open)
+  # if !System.get_env("CI"), do: @tag(trace: :open)
 
-  test "register", %{conn: conn} do
-    conn
-    |> visit(~p"/")
-    |> click_link("Register")
-    |> assert_has("body .phx-connected")
-    |> fill_in("Email", with: "f@ftes.de")
-    |> click_button("Create an account")
-    |> assert_has("#flash-info", text: "email was sent")
-    |> visit(~p"/dev/mailbox")
-    |> click_link("log-in")
-    |> click_button("Confirm and stay logged in")
-    |> assert_has("#flash-info", text: "User confirmed")
-    |> visit(~p"/users/settings")
-    |> assert_has(".phx-connected")
-    |> assert_has("h1", text: "Settings")
-    |> visit(~p"/queries")
-    |> assert_has("h1", text: "Database Queries")
+  for i <- 1..4 do
+    # @tag sandbox_shutdown_delay: 200
+    test "register #{i}", %{conn: conn} do
+      conn
+      |> visit(~p"/")
+      |> click_link("Register")
+      |> assert_has("body .phx-connected")
+      |> fill_in("Email", with: "f@ftes.de")
+      |> click_button("Create an account")
+      |> assert_has("#flash-info", text: "email was sent")
+      |> visit(~p"/dev/mailbox")
+      |> click_link("log-in")
+      |> click_button("Confirm and stay logged in")
+      |> assert_has("#flash-info", text: "User confirmed")
+      |> visit(~p"/users/settings")
+      |> assert_has(".phx-connected")
+      |> assert_has("h1", text: "Settings")
+      |> visit(~p"/queries")
+      |> assert_has("h1", text: "Database Queries")
+    end
   end
 end

I observe:

  • no errors when running QUERY_DELAY=100 mix test test/features --max-cases 2 (even without @tag sandbox_shutdown_delay: 200)
  • lots of errors when running QUERY_DELAY=100 mix test test/features --max-cases 4 (even with@tag sandbox_shutdown_delay: 200)

@nathanl
Copy link
Contributor Author

nathanl commented Nov 11, 2025

Thanks for the additional info. I need to do some more tinkering and thinking to understand that.

@ftes
Copy link
Owner

ftes commented Nov 12, 2025

Thanks for bearing with me Nathan. And for the effort you're putting into this.
Just to be clear: It's a very welcome addition, and I want to get it in asap.

I'm just trying to make sure we end up with a good solution. And ideally have a test bed (either manually via this example app, or better yet we can translate our findings here into automated integration tests in the library).

@nathanl
Copy link
Contributor Author

nathanl commented Nov 12, 2025

@ftes I don't fully understand those errors, but having locally added more labels and inspections, it seems to me that somehow they're coming from a db checkout that's done in the registration liveview, not one done by phoenix_test_playwright.

  7) test register 1 (Features.RegisterTest)
     Parameters: %{param: 6}
     test/features/register_test.exs:8
     Could not find element #flash-info [text: "email was sent"]
     code: |> assert_has("#flash-info", text: "email was sent")
     stacktrace:
       (phoenix_test_playwright 0.9.1) lib/phoenix_test/playwright.ex:671: PhoenixTest.Playwright.assert_has/3
       test/features/register_test.exs:15: (test)

13:37:43.581 [error] Postgrex.Protocol (#PID<0.381.0> ("db_conn_8")) disconnected: ** (DBConnection.ConnectionError) owner #PID<0.1315.0> exited

Client #PID<0.1325.0> ({Phoenix.LiveView, MyAppWeb.UserLive.Registration, "lv:phx-GHdWS4QvapuwHgPC"}) is still using a connection from owner at location:

    :prim_inet.recv0/3
    (postgrex 0.21.1) lib/postgrex/protocol.ex:3261: Postgrex.Protocol.msg_recv/4
    (postgrex 0.21.1) lib/postgrex/protocol.ex:2263: Postgrex.Protocol.recv_bind/3
    (postgrex 0.21.1) lib/postgrex/protocol.ex:2243: Postgrex.Protocol.rebind_execute/4
    (ecto_sql 3.13.2) lib/ecto/adapters/sql/sandbox.ex:407: Ecto.Adapters.SQL.Sandbox.Connection.proxy/3
    (db_connection 2.8.1) lib/db_connection/holder.ex:356: DBConnection.Holder.holder_apply/4
    (db_connection 2.8.1) lib/db_connection.ex:1539: DBConnection.run_execute/5
    (db_connection 2.8.1) lib/db_connection.ex:1587: DBConnection.run_with_retries/5
    (db_connection 2.8.1) lib/db_connection.ex:791: DBConnection.parsed_prepare_execute/5
    (db_connection 2.8.1) lib/db_connection.ex:783: DBConnection.prepare_execute/4
    (postgrex 0.21.1) lib/postgrex.ex:298: Postgrex.query/4
    (ecto_sql 3.13.2) lib/ecto/adapters/sql.ex:1166: Ecto.Adapters.SQL.struct/10
    (ecto 3.13.5) lib/ecto/repo/schema.ex:1000: Ecto.Repo.Schema.apply/4
    (ecto 3.13.5) lib/ecto/repo/schema.ex:500: anonymous fn/15 in Ecto.Repo.Schema.do_insert/4
    (my_app 0.1.0) lib/my_app_web/live/user_live/registration.ex:58: MyAppWeb.UserLive.Registration.handle_event/3
    (phoenix_live_view 1.1.17) lib/phoenix_live_view/channel.ex:530: anonymous fn/3 in Phoenix.LiveView.Channel.view_handle_event/3
    (telemetry 1.3.0) /Users/nlong/code/external/phoenix_test_playwright_example/deps/telemetry/src/telemetry.erl:324: :telemetry.span/3
    (phoenix_live_view 1.1.17) lib/phoenix_live_view/channel.ex:260: Phoenix.LiveView.Channel.handle_info/2
    (stdlib 7.1) gen_server.erl:2434: :gen_server.try_handle_info/3
    (stdlib 7.1) gen_server.erl:2420: :gen_server.handle_msg/3

The connection itself was checked out by #PID<0.1325.0> ({Phoenix.LiveView, MyAppWeb.UserLive.Registration, "lv:phx-GHdWS4QvapuwHgPC"}) at location:

    (postgrex 0.21.1) lib/postgrex.ex:298: Postgrex.query/4
    (ecto_sql 3.13.2) lib/ecto/adapters/sql.ex:1166: Ecto.Adapters.SQL.struct/10
    (ecto 3.13.5) lib/ecto/repo/schema.ex:1000: Ecto.Repo.Schema.apply/4
    (ecto 3.13.5) lib/ecto/repo/schema.ex:500: anonymous fn/15 in Ecto.Repo.Schema.do_insert/4
    (my_app 0.1.0) lib/my_app_web/live/user_live/registration.ex:58: MyAppWeb.UserLive.Registration.handle_event/3
    (phoenix_live_view 1.1.17) lib/phoenix_live_view/channel.ex:530: anonymous fn/3 in Phoenix.LiveView.Channel.view_handle_event/3
    (telemetry 1.3.0) /Users/nlong/code/external/phoenix_test_playwright_example/deps/telemetry/src/telemetry.erl:324: :telemetry.span/3
    (phoenix_live_view 1.1.17) lib/phoenix_live_view/channel.ex:260: Phoenix.LiveView.Channel.handle_info/2
    (stdlib 7.1) gen_server.erl:2434: :gen_server.try_handle_info/3
    (stdlib 7.1) gen_server.erl:2420: :gen_server.handle_msg/3
    (stdlib 7.1) proc_lib.erl:333: :proc_lib.init_p_do_apply/3


13:37:43.591 [error] GenServer #PID<0.1325.0> terminating
** (Postgrex.Error) ERROR 57014 (query_canceled) canceling statement due to user request
    (ecto_sql 3.13.2) lib/ecto/adapters/sql.ex:1098: Ecto.Adapters.SQL.raise_sql_call_error/1
    (ecto 3.13.5) lib/ecto/repo/schema.ex:1000: Ecto.Repo.Schema.apply/4
    (ecto 3.13.5) lib/ecto/repo/schema.ex:500: anonymous fn/15 in Ecto.Repo.Schema.do_insert/4
    (my_app 0.1.0) lib/my_app_web/live/user_live/registration.ex:58: MyAppWeb.UserLive.Registration.handle_event/3
    (phoenix_live_view 1.1.17) lib/phoenix_live_view/channel.ex:530: anonymous fn/3 in Phoenix.LiveView.Channel.view_handle_event/3
    (telemetry 1.3.0) /Users/nlong/code/external/phoenix_test_playwright_example/deps/telemetry/src/telemetry.erl:324: :telemetry.span/3
    (phoenix_live_view 1.1.17) lib/phoenix_live_view/channel.ex:260: Phoenix.LiveView.Channel.handle_info/2
    (stdlib 7.1) gen_server.erl:2434: :gen_server.try_handle_info/3
    (stdlib 7.1) gen_server.erl:2420: :gen_server.handle_msg/3
    (stdlib 7.1) proc_lib.erl:333: :proc_lib.init_p_do_apply/3
Process Label: {Phoenix.LiveView, MyAppWeb.UserLive.Registration, "lv:phx-GHdWS4QvapuwHgPC"}
Last message: %Phoenix.Socket.Message{topic: "lv:phx-GHdWS4QvapuwHgPC", event: "event", payload: %{"event" => "save", "meta" => %{}, "type" => "form", "value" => "user%5Bemail%5D=f%40ftes.de"}, ref: "13", join_ref: "4"}

Furthermore, if I switch back to using the released version of phoenix_test_playwright but run your parameterized test above, I still see those errors, plus ones that the sandbox_shutdown_delay apparently prevents, like

.13:44:49.292 [error] Postgrex.Protocol (#PID<0.1407.0> ("db_conn_14")) disconnected: ** (DBConnection.ConnectionError) owner #PID<0.1973.0> exited

Client #PID<0.2041.0> (MyAppWeb.QueriesLive) is still using a connection from owner at location:

    :prim_inet.recv0/3
    (postgrex 0.21.1) lib/postgrex/protocol.ex:3261: Postgrex.Protocol.msg_recv/4
    (postgrex 0.21.1) lib/postgrex/protocol.ex:2956: Postgrex.Protocol.recv_transaction/4
    (postgrex 0.21.1) lib/postgrex/protocol.ex:1410: Postgrex.Protocol.parse_describe_flush/4
    (ecto_sql 3.13.2) lib/ecto/adapters/sql/sandbox.ex:407: Ecto.Adapters.SQL.Sandbox.Connection.proxy/3
    (db_connection 2.8.1) lib/db_connection/holder.ex:356: DBConnection.Holder.holder_apply/4
    (db_connection 2.8.1) lib/db_connection.ex:1524: DBConnection.prepare/4
    (db_connection 2.8.1) lib/db_connection.ex:1517: DBConnection.run_prepare/4
    (db_connection 2.8.1) lib/db_connection.ex:1529: DBConnection.run_prepare_execute/5
    (db_connection 2.8.1) lib/db_connection.ex:1587: DBConnection.run_with_retries/5
    (db_connection 2.8.1) lib/db_connection.ex:791: DBConnection.parsed_prepare_execute/5
    (db_connection 2.8.1) lib/db_connection.ex:783: DBConnection.prepare_execute/4
    (postgrex 0.21.1) lib/postgrex.ex:319: Postgrex.query_prepare_execute/4
    (my_app 0.1.0) lib/my_app_web/live/queries_live.ex:43: MyAppWeb.QueriesLive.mount/3
    (phoenix_live_view 1.1.17) lib/phoenix_live_view/utils.ex:348: anonymous fn/6 in Phoenix.LiveView.Utils.maybe_call_live_view_mount!/5
    (telemetry 1.3.0) /Users/nlong/code/external/phoenix_test_playwright_example/deps/telemetry/src/telemetry.erl:324: :telemetry.span/3
    (phoenix_live_view 1.1.17) lib/phoenix_live_view/channel.ex:1238: Phoenix.LiveView.Channel.verified_mount/8
    (phoenix_live_view 1.1.17) lib/phoenix_live_view/channel.ex:84: Phoenix.LiveView.Channel.handle_info/2
    (stdlib 7.1) gen_server.erl:2434: :gen_server.try_handle_info/3
    (stdlib 7.1) gen_server.erl:2420: :gen_server.handle_msg/3

The connection itself was checked out by #PID<0.2041.0> (MyAppWeb.QueriesLive) at location:

    (postgrex 0.21.1) lib/postgrex.ex:319: Postgrex.query_prepare_execute/4
    (my_app 0.1.0) lib/my_app_web/live/queries_live.ex:43: MyAppWeb.QueriesLive.mount/3
    (phoenix_live_view 1.1.17) lib/phoenix_live_view/utils.ex:348: anonymous fn/6 in Phoenix.LiveView.Utils.maybe_call_live_view_mount!/5
    (telemetry 1.3.0) /Users/nlong/code/external/phoenix_test_playwright_example/deps/telemetry/src/telemetry.erl:324: :telemetry.span/3
    (phoenix_live_view 1.1.17) lib/phoenix_live_view/channel.ex:1238: Phoenix.LiveView.Channel.verified_mount/8
    (phoenix_live_view 1.1.17) lib/phoenix_live_view/channel.ex:84: Phoenix.LiveView.Channel.handle_info/2
    (stdlib 7.1) gen_server.erl:2434: :gen_server.try_handle_info/3
    (stdlib 7.1) gen_server.erl:2420: :gen_server.handle_msg/3
    (stdlib 7.1) proc_lib.erl:333: :proc_lib.init_p_do_apply/3

@nathanl
Copy link
Contributor Author

nathanl commented Nov 12, 2025

It seems to me that @tag trace: :open makes a difference only if it delays the end of on_exit/1, which it shouldn't, hence Don't block test exits when opening a trace

@nathanl
Copy link
Contributor Author

nathanl commented Nov 13, 2025

I'm not sure how to test this change better than the demo at the top. We want to see what does or doesn't get logged after the test completes, so inherently the test itself can't assert that.

I feel a bit stuck. These changes definitely improve the situation for the app I'm working on. I get why you want a more general proof and a way to prevent regression. But at the moment I'm not sure how to provide that better than this PR.

@ftes
Copy link
Owner

ftes commented Nov 14, 2025

Thanks for all the hard work Nathan.
Lets get this in, and I'll try to find some more beta testers on main branch.

@ftes
Copy link
Owner

ftes commented Nov 14, 2025

I've added some ecto based test to ftes/phoenix_test based on your examples here.
If you have time to look at them, that would be great.

Closing this.

@ftes ftes closed this Nov 14, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants