Database connection failure while running the tests

hi,

I have a project which has many test cases nearly 600 +. So while running the test cases some of the connection is getting failed with the database or I don’t exactly but this is what I thought. Can someone explain me about the errors and some way to improve the design so this kind of things doesn’t happen.

* test get_order_item/2 retuns nil if the variant is not part of the order17:30:18.690 [error] Postgrex.Protocol (#PID<0.648.0>) disconnected: ** (DBConnection.ConnectionError) owner #PID<0.1416.0> exited

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

    :prim_inet.send_recv_reply/2
    (postgrex 0.15.8) lib/postgrex/protocol.ex:2918: Postgrex.Protocol.do_send/3
    (postgrex 0.15.8) lib/postgrex/protocol.ex:1172: Postgrex.Protocol.close_parse_describe_flush/3
    (postgrex 0.15.8) lib/postgrex/protocol.ex:1708: Postgrex.Protocol.handle_prepare_execute/4
    (ecto_sql 3.5.4) lib/ecto/adapters/sql/sandbox.ex:370: Ecto.Adapters.SQL.Sandbox.Connection.proxy/3
    (db_connection 2.3.1) lib/db_connection/holder.ex:316: DBConnection.Holder.holder_apply/4
    (db_connection 2.3.1) lib/db_connection.ex:1272: DBConnection.run_execute/5
    (db_connection 2.3.1) lib/db_connection.ex:1359: DBConnection.run/6
    (db_connection 2.3.1) lib/db_connection.ex:613: DBConnection.execute/4
    (ecto_sql 3.5.4) lib/ecto/adapters/postgres/connection.ex:80: Ecto.Adapters.Postgres.Connection.execute/4
    (ecto_sql 3.5.4) lib/ecto/adapters/sql.ex:702: Ecto.Adapters.SQL.execute!/4
    (ecto_sql 3.5.4) lib/ecto/adapters/sql.ex:684: Ecto.Adapters.SQL.execute/5
    (ecto 3.5.6) lib/ecto/repo/queryable.ex:229: Ecto.Repo.Queryable.execute/4
    (ecto 3.5.6) lib/ecto/repo/queryable.ex:17: Ecto.Repo.Queryable.all/3
    (healthy_eats 0.1.0) lib/healthy_eats/item/item.ex:369: HealthyEats.Item.cache_products/0
    (elixir 1.10.3) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
    (stdlib 3.10) proc_lib.erl:249: :proc_lib.init_p_do_apply/3

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

    (ecto_sql 3.5.4) lib/ecto/adapters/postgres/connection.ex:80: Ecto.Adapters.Postgres.Connection.execute/4
    (ecto_sql 3.5.4) lib/ecto/adapters/sql.ex:702: Ecto.Adapters.SQL.execute!/4
    (ecto_sql 3.5.4) lib/ecto/adapters/sql.ex:684: Ecto.Adapters.SQL.execute/5
    (ecto 3.5.6) lib/ecto/repo/queryable.ex:229: Ecto.Repo.Queryable.execute/4
    (ecto 3.5.6) lib/ecto/repo/queryable.ex:17: Ecto.Repo.Queryable.all/3
    (healthy_eats 0.1.0) lib/healthy_eats/item/item.ex:369: HealthyEats.Item.cache_products/0
    (elixir 1.10.3) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
    (stdlib 3.10) proc_lib.erl:249: :proc_lib.init_p_do_apply/3


17:30:18.703 [error] Task #PID<0.1412.0> started from #PID<0.1414.0> terminating
** (stop) exited in: DBConnection.Holder.checkout(#PID<0.1413.0>, [log: #Function<15.35638488/1 in Ecto.Adapters.SQL.with_log/3>, source: "product", timeout: 15000, pool_size: 10, pool: DBConnection.Ownership])
    ** (EXIT) shutdown: "owner #PID<0.1412.0> exited"
    (db_connection 2.3.1) lib/db_connection/holder.ex:86: DBConnection.Holder.checkout/2
    (db_connection 2.3.1) lib/db_connection/holder.ex:67: DBConnection.Holder.checkout/2
    (db_connection 2.3.1) lib/db_connection.ex:1046: DBConnection.checkout/3
    (db_connection 2.3.1) lib/db_connection.ex:1357: DBConnection.run/6
    (db_connection 2.3.1) lib/db_connection.ex:613: DBConnection.execute/4
    (ecto_sql 3.5.4) lib/ecto/adapters/postgres/connection.ex:80: Ecto.Adapters.Postgres.Connection.execute/4
    (ecto_sql 3.5.4) lib/ecto/adapters/sql.ex:702: Ecto.Adapters.SQL.execute!/4
    (ecto_sql 3.5.4) lib/ecto/adapters/sql.ex:684: Ecto.Adapters.SQL.execute/5
    (ecto 3.5.6) lib/ecto/repo/queryable.ex:229: Ecto.Repo.Queryable.execute/4
    (ecto 3.5.6) lib/ecto/repo/queryable.ex:17: Ecto.Repo.Queryable.all/3
    (healthy_eats 0.1.0) lib/healthy_eats/item/item.ex:369: HealthyEats.Item.cache_products/0
    (elixir 1.10.3) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
    (stdlib 3.10) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Function: #Function<13.30307743/0 in HealthyEats.Item.delete_product/1>
    Args: []
17:30:18.709 [error] Task #PID<0.1416.0> started from #PID<0.1418.0> terminating
** (stop) exited in: DBConnection.Holder.checkout(#PID<0.1417.0>, [log: #Function<15.35638488/1 in Ecto.Adapters.SQL.with_log/3>, source: "product_image", timeout: 15000, pool_size: 10, pool: DBConnection.Ownership])
    ** (EXIT) shutdown: %DBConnection.ConnectionError{message: "owner #PID<0.1416.0> exited\n\nClient #PID<0.1418.0> is still using a connection from owner at location:\n\n    :prim_inet.send_recv_reply/2\n    (postgrex 0.15.8) lib/postgrex/protocol.ex:2918: Postgrex.Protocol.do_send/3\n    (postgrex 0.15.8) lib/postgrex/protocol.ex:1172: Postgrex.Protocol.close_parse_describe_flush/3\n    (postgrex 0.15.8) lib/postgrex/protocol.ex:1708: Postgrex.Protocol.handle_prepare_execute/4\n    (ecto_sql 3.5.4) lib/ecto/adapters/sql/sandbox.ex:370: Ecto.Adapters.SQL.Sandbox.Connection.proxy/3\n    (db_connection 2.3.1) lib/db_connection/holder.ex:316: DBConnection.Holder.holder_apply/4\n    (db_connection 2.3.1) lib/db_connection.ex:1272: DBConnection.run_execute/5\n    (db_connection 2.3.1) lib/db_connection.ex:1359: DBConnection.run/6\n    (db_connection 2.3.1) lib/db_connection.ex:613: DBConnection.execute/4\n    (ecto_sql 3.5.4) lib/ecto/adapters/postgres/connection.ex:80: Ecto.Adapters.Postgres.Connection.execute/4\n    (ecto_sql 3.5.4) lib/ecto/adapters/sql.ex:702: Ecto.Adapters.SQL.execute!/4\n    (ecto_sql 3.5.4) lib/ecto/adapters/sql.ex:684: Ecto.Adapters.SQL.execute/5\n    (ecto 3.5.6) lib/ecto/repo/queryable.ex:229: Ecto.Repo.Queryable.execute/4\n    (ecto 3.5.6) lib/ecto/repo/queryable.ex:17: Ecto.Repo.Queryable.all/3\n    (healthy_eats 0.1.0) lib/healthy_eats/item/item.ex:369: HealthyEats.Item.cache_products/0\n    (elixir 1.10.3) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2\n    (stdlib 3.10) proc_lib.erl:249: :proc_lib.init_p_do_apply/3\n\nThe connection itself was checked out by #PID<0.1418.0> at location:\n\n    (ecto_sql 3.5.4) lib/ecto/adapters/postgres/connection.ex:80: Ecto.Adapters.Postgres.Connection.execute/4\n    (ecto_sql 3.5.4) lib/ecto/adapters/sql.ex:702: Ecto.Adapters.SQL.execute!/4\n    (ecto_sql 3.5.4) lib/ecto/adapters/sql.ex:684: Ecto.Adapters.SQL.execute/5\n    (ecto 3.5.6) lib/ecto/repo/queryable.ex:229: Ecto.Repo.Queryable.execute/4\n    (ecto 3.5.6) lib/ecto/repo/queryable.ex:17: Ecto.Repo.Queryable.all/3\n    (healthy_eats 0.1.0) lib/healthy_eats/item/item.ex:369: HealthyEats.Item.cache_products/0\n    (elixir 1.10.3) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2\n    (stdlib 3.10) proc_lib.erl:249: :proc_lib.init_p_do_apply/3\n\n", reason: :error, severity: :error}
    (db_connection 2.3.1) lib/db_connection/holder.ex:86: DBConnection.Holder.checkout/2
    (db_connection 2.3.1) lib/db_connection/holder.ex:67: DBConnection.Holder.checkout/2
    (db_connection 2.3.1) lib/db_connection.ex:1046: DBConnection.checkout/3
    (db_connection 2.3.1) lib/db_connection.ex:1357: DBConnection.run/6
    (db_connection 2.3.1) lib/db_connection.ex:613: DBConnection.execute/4
    (ecto_sql 3.5.4) lib/ecto/adapters/postgres/connection.ex:80: Ecto.Adapters.Postgres.Connection.execute/4
    (ecto_sql 3.5.4) lib/ecto/adapters/sql.ex:702: Ecto.Adapters.SQL.execute!/4
    (ecto_sql 3.5.4) lib/ecto/adapters/sql.ex:684: Ecto.Adapters.SQL.execute/5
    (ecto 3.5.6) lib/ecto/repo/queryable.ex:229: Ecto.Repo.Queryable.execute/4
    (ecto 3.5.6) lib/ecto/repo/queryable.ex:17: Ecto.Repo.Queryable.all/3
    (ecto 3.5.6) lib/ecto/repo/preloader.ex:229: Ecto.Repo.Preloader.fetch_query/8
    (elixir 1.10.3) lib/enum.ex:1396: Enum."-map/2-lists^map/1-0-"/2
    (ecto 3.5.6) lib/ecto/repo/preloader.ex:71: Ecto.Repo.Preloader.preload_each/4
    (ecto 3.5.6) lib/ecto/repo/preloader.ex:51: Ecto.Repo.Preloader.normalize_and_preload_each/5
    (ecto 3.5.6) lib/ecto/repo/preloader.ex:20: Ecto.Repo.Preloader.query/6
    (ecto 3.5.6) lib/ecto/repo/queryable.ex:235: Ecto.Repo.Queryable.execute/4
    (ecto 3.5.6) lib/ecto/repo/queryable.ex:17: Ecto.Repo.Queryable.all/3
    (healthy_eats 0.1.0) lib/healthy_eats/item/item.ex:369: HealthyEats.Item.cache_products/0
    (elixir 1.10.3) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
    (stdlib 3.10) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Function: #Function<23.30307743/0 in HealthyEats.Item.update_product/2>
    Args: []
1 Like

This error message usually happens when you have a test process that starts other processes, which keep running even when the test process exits. For instance, this test produces that error pretty reliably:

defmodule YourApp.FooTest do
  use YourApp.DataCase

  setup do
    Task.start(fn ->
      Process.sleep(1000)
      YourApp.Repo.get(YourApp.SomeSchema, 1)
    end)

    :ok
  end

  test "does a thing" do
    assert Core.Repo.get(Core.User, 1)
  end

  test "waits around" do
    Process.sleep(1000)
    assert true
  end
  test "waits around 2" do
    Process.sleep(1000)
    assert true
  end
  test "waits around 3" do
    Process.sleep(1000)
    assert true
  end
  test "waits around 4" do
    Process.sleep(1000)
    assert true
  end
  test "waits around 5" do
    Process.sleep(1000)
    assert true
  end
  test "waits around 6" do
    Process.sleep(1000)
    assert true
  end
  test "waits around 7" do
    Process.sleep(1000)
    assert true
  end
end

It’s hard to say exactly how to remediate this issue in your application, but you’ll want to look into tools like Process.monitor to ensure things are shutting down together.

2 Likes

Is it like I have to monitor every process which is running by those test cases? Is it even possible in our phoenix application?

The processes you need to be concerned about are processes that are started within a particular test (unless you’re explicitly using Ecto.Adapters.SQL.Sandbox.allow to share the connection with other ones). Look for code that is starting Tasks or similar.

For instance, the stacktraces in your post show HealthyEats.Item.cache_products being called by Task.Supervised.invoke_mfa - start by looking at the code both in cache_products and the code that calls cache_products for process-launching.