axelson

axelson

Scenic Core Team

Strange DBConnection.ConnectionError with Ecto 3.0.6

I’m not sure how to interpret the following error. What is the relationship of PID 0.553.0 to 0.2195.0? It seems that 0.553.0 may be the test process in which case the error doesn’t make sense to me because (as I’m interpreting it) the client and the owner are the same process.

03:50:50.547 [error] Postgrex.Protocol (#PID<0.553.0>) disconnected: ** (DBConnection.ConnectionError) owner #PID<0.2195.0> checked in the connection

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

    :prim_inet.recv0/3
    (postgrex) lib/postgrex/protocol.ex:2701: Postgrex.Protocol.msg_recv/4
    (postgrex) lib/postgrex/protocol.ex:2454: Postgrex.Protocol.recv_close/3
    (postgrex) lib/postgrex/protocol.ex:1169: Postgrex.Protocol.close_parse_describe_flush/3
    (postgrex) lib/postgrex/protocol.ex:1587: Postgrex.Protocol.handle_prepare_execute/4
    (ecto_sql) lib/ecto/adapters/sql/sandbox.ex:375: Ecto.Adapters.SQL.Sandbox.Connection.proxy/3
    (db_connection) lib/db_connection/holder.ex:268: DBConnection.Holder.holder_apply/4
    (db_connection) lib/db_connection.ex:1189: DBConnection.run_execute/5
    (db_connection) lib/db_connection.ex:1276: DBConnection.run/6
    (db_connection) lib/db_connection.ex:550: DBConnection.execute/4
    (ecto_sql) lib/ecto/adapters/postgres/connection.ex:80: Ecto.Adapters.Postgres.Connection.execute/4
    (ecto_sql) lib/ecto/adapters/sql.ex:571: Ecto.Adapters.SQL.execute!/4
    (ecto_sql) lib/ecto/adapters/sql.ex:553: Ecto.Adapters.SQL.execute/5
    (ecto) lib/ecto/repo/queryable.ex:147: Ecto.Repo.Queryable.execute/4
    (ecto) lib/ecto/repo/queryable.ex:18: Ecto.Repo.Queryable.all/3
    test/hobnob_messages/queries/mentions_query_test.exs:101: HobnobMessages.Queries.MentionsQueryTest."test unread_in_threads_for_user/1 includes messages in threads when the user has no thread member"/1
    (ex_unit) lib/ex_unit/runner.ex:312: ExUnit.Runner.exec_test/1
    (stdlib) timer.erl:166: :timer.tc/1
    (ex_unit) lib/ex_unit/runner.ex:251: anonymous fn/4 in ExUnit.Runner.spawn_test/3

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

    (ecto_sql) lib/ecto/adapters/postgres/connection.ex:80: Ecto.Adapters.Postgres.Connection.execute/4
    (ecto_sql) lib/ecto/adapters/sql.ex:571: Ecto.Adapters.SQL.execute!/4
    (ecto_sql) lib/ecto/adapters/sql.ex:553: Ecto.Adapters.SQL.execute/5
    (ecto) lib/ecto/repo/queryable.ex:147: Ecto.Repo.Queryable.execute/4
    (ecto) lib/ecto/repo/queryable.ex:18: Ecto.Repo.Queryable.all/3
    test/hobnob_messages/queries/mentions_query_test.exs:101: HobnobMessages.Queries.MentionsQueryTest."test unread_in_threads_for_user/1 includes messages in threads when the user has no thread member"/1
    (ex_unit) lib/ex_unit/runner.ex:312: ExUnit.Runner.exec_test/1
    (stdlib) timer.erl:166: :timer.tc/1
    (ex_unit) lib/ex_unit/runner.ex:251: anonymous fn/4 in ExUnit.Runner.spawn_test/3

The failure is intermittent but happens quite often on a full test run. I don’t get the same error on Ecto 2.2.11.

Environment:

  • ecto: 3.0.6
  • ecto_sql: 3.0.4
  • postgrex: 0.14.1
  • Elixir: 1.7.4
  • Erlang: 21.0.4
  • Mac OS X: 10.13.6

Marked As Solved

josevalim

josevalim

Creator of Elixir

The only scenario I can see it happening is if you have your tests as async but you are changing the mode of the sandbox. Or you have another process changing the sandbox mode while this test runs. Can you please get all of the places you call Ecto.Adapters.SQL.Sandbox and put the code snippets here?

Also Liked

axelson

axelson

Scenic Core Team

Yes!! That was exactly it. Thanks for the tip. I had a 1.5 year-old test that looked like this:

    test "it sends a notification to the user channel if they are a member that is not present",
         %{user: user, room: room} do
      # This test uses another process
      Ecto.Adapters.SQL.Sandbox.mode(MyApp.Repo, {:shared, self()})
      
      # rest of the test
    end

I think my thinking was that I wanted just this test to use the shared mode of the sandbox and since every test runs in a separate process that Sandbox.mode would set the mode for that specific process (since you’re passing the pid in).

From the docs it seemed okay:

iex(3)> h Ecto.Adapters.SQL.Sandbox.mode

                              def mode(repo, mode)

Sets the mode for the repo pool.

The mode can be :auto, :manual or {:shared, <pid>}.

Although I guess I should have realized that the “repo pool” is a shared resource across multiple tests.

But for my understanding, this is what I think was happening:

  1. Multiple tests are running concurrently (since we’re using async: true)
  2. This test called Ecto.Adapters.SQL.Sandbox.mode(MyApp.Repo, {:shared, self()})
  3. When the DBConnection.Ownership.Manager GenServer received the mode change request it checked in all of the existing transaction checkouts, including for tests that were still running!
  4. The tests that were still running tried to continue to use their connection, but the Manager GenServer had already checked them in resulting in the warning at the top of this thread.
  5. The tests that were still running would then check out a new connection, and since this new connection was running in a new db transaction, any database entries inserted in the previous connection no longer exist which caused related test failures such as foreign key exceptions

I plan to create a doc PR to add some sort of warning to the Ecto.Adapters.SQL.Sandbox.mode function, unless this can be considered a true db_connection bug (I’m using db_connection 2.0.5). It would be nice if Ecto.Adapters.SQL.Sandbox.mode would eventually cause a warning if it forces the check-in of unrelated existing check-outs. Also this part of the original error message is not technically correct in this scenario:

(DBConnection.ConnectionError) owner #PID<0.2195.0> checked in the connection

Since #PID<0.2195.0> did not initiate the check-in (at least this is that is my current understanding). It looks like you’re in the process of adding an improvement for this case. That PR changes the error message to #PID<0.3100.0> checked in the connection owned by #PID<0.3096.0> which is a definite improvement since #PID<0.3100.0> was the process that was running the test that called Sandbox.mode.

Also due to the new $callers tracking in db_connection that test runs just fine in async mode without having to change the sandbox pool mode.

Thanks again for the help in tracking this down!

bnymn

bnymn

In my case, I had the following line in both test_helper.exs and setup block.

Ecto.Adapters.SQL.Sandbox.mode(Blog.Repo, {:shared, self()})

Removing the line from test_helper.exs solved the problem.

dimitarvp

dimitarvp

Or the async Task can just send a message to the parent process. That makes it both more stable and predictable in the original code and more testable as well. :slight_smile:

dimitarvp

dimitarvp

The error you’re seeing is an integral part of the db_connection package, which several DB packages step on (Postgres for Ecto included). I am not aware of a way to disable it though I haven’t looked at the source in detail either, I admit.

But, why being conservative about waiting for the tasks to finish? If Process.sleep(50) fixed the problem then I’d imagine that Task.await_many will finish in 50ms or less, making it an imperceptible lag.

To expand on this: this is a bandaid, and is done when you just give up and are like “no clue what needs this little extra timie to finish but I am not going to bother looking for it”.

Don’t do that. Be a good engineer, your future self and colleagues will thank you for it.

And yes I know it’s tests and people somehow drop (part of) their coding standards there, but IMO tests need love too!

amos-kibet

amos-kibet

I’ve read the comments and learnt a few things as well, especially on Process.sleep/1 and I assume :time.sleep/1 being a bandaid.
I learnt a few solutions, thanks to @almirsarajcic and @dimitarvp

  1. You could send a message to the parent (test) process from the async process. In my case I needed to mock the async code. This is what I had initially:
test "blah blah blah" do
    test_pid = self()
    ref = make_ref()

    expect(MyMock, :some_fn, fn -> 
        send(test_pid, {:done, ref})  
    end)

    # Just before `end` of the `test` block, I asserted that I received the message from the async process:
    assert_receive {:done, ^ref}
     
    # Here, you can assert on any side-effects of the async code, like DB changes, etc.
end

This way, we are guaranteed that the async process returns before the test exits.

  1. You can (and should always) use supervised tasks, which gives you the flexibility to start your Task Supervisor in the tests that need it. Here was my final setup:
    In MyApp.Application:
def start(type, args) do
    children = [MyAppWeb.Endpoint, # other children] ++ more_children()
      end

    # See https://hexdocs.pm/elixir/Supervisor.html
    # for other strategies and supported options
    opts = [strategy: :one_for_one, name: MyApp.Supervisor]
    Supervisor.start_link(children, opts)
  end

  defp more_children(env \\ Application.get_env(:my_app, :env))
  defp more_children(:test), do: []
  defp more_children(_env), do: [{Task.Supervisor, name: MyApp.TaskSupervisor}]

Then, in the function I am testing, I use a supervised Task:

def some_function do
  Task.Supervisor.async_nolink(MyApp.TaskSupervisor, fn -> 
    # do some work
  end)
  
  :ok
end

Finally, in my test, I start the task supervisor as part of my test setup:

describe "blah" do
  setup do
      start_supervised!({Task.Supervisor, name: MyApp.TaskSupervisor, strategy: :one_for_one})

      :ok
  end
  test "blah blah" do
      expect(MyMock, :some_function, fn -> 
         :ok
      end)
  end
end

I loved the second approach and it’s what I use, but I’m curious though. If I want to assert on DB change made by the async process, how else would I do that without adding a delay? I would still get the DB connection errors with this approach.

Where Next?

Popular in Questions Top

itssasanka
Hi all, Trying to get some more clarity over utc_datetime and naive_datetime for Ecto: https://hexdocs.pm/ecto/Ecto.Schema.html#module-...
New
_russellb
I want to try my hand at web scraping. What tools/libraries do I need to use. I’m hoping to turn this into something professional so don’...
New
New
lastday4you
I wanted to check elixir version in phoenix because i found that my elixir is 1.5 but when i use Enum.chunk_by it said the function is un...
New
rms.mrcs
Hi, I need to transform a list of numbers into a map where the keys are the indexes and the values are the original values of the list....
New
alice
Hey, Just curious what are the main benefits of Elixir compared to Clojure? When is Elixir more useful than Clojure and vice versa? Th...
New
johnnyicon
Hi all, I've just started learning Elixir and Phoenix Framework, so please pardon my n00bness at this stage. I'm trying to use Postg...
New
baxterw3b
Hi guys, i’m new in the Elixir world, and i have to say, that i love it! i’m having some problem to understand anonymous functions with ...
New
chrisalley
ExUnit now has describe blocks which is a welcome addition coming from RSpec. In the docs, it states that nested hierarchies of describe ...
New
jay1
Why is it that the mnesia database isn’t the most preferred database for use in Elixir/Phoenix?
New

Other popular topics Top

JDanielMartinez
Hi! May someone helps me, please! I have two apps into an umbrella project: the first one is Database, which manages queries, and the se...
New
yurko
Here are few pieces of (common) Linux knowledge that we use for reasonably small one server apps. We use Ubuntu but this should work for ...
New
Tee
can someone please explain to me how Enum.reduce works with maps
New
_russellb
I want to try my hand at web scraping. What tools/libraries do I need to use. I’m hoping to turn this into something professional so don’...
New
nsuchy
Hi. I’ve noticed that Windows Powershell has it’s own IEX command and you cannot access Elixir’s IEX due to the conflict. This isn’t a cr...
New
aadeshere1
I have a another noob question about loop. Since elixir is immutable, while loop is not directly possible. total = 10 while total != 0 ...
New
fayddelight
I tried installing elixir 1.11.2 erlang 23.3.4 via asdf in my zsh shell. Enabled the versions locally and globally. When I list them ...
New
msaraiva
Surface is an experimental library built on top of Phoenix LiveView and its new LiveComponent API that aims to provide a more declarative...
564 42633 214
New
AstonJ
by Lance Halvorsen Elixir and Phoenix are generating tremendous excitement as an unbeatable platform for building modern web application...
460 27162 124
New
magnetic
Hey :wave:t3: Elixir community, I’ve been learning Elixir, and working on some side projects. My editor of choice is VSCode, and althoug...
New

We're in Beta

About us Mission Statement