EctoWatch 0.11.0 doesn't work in test env

[paulsabou]

I have migrated from ecto watch 0.6.0 to 0.11.0. In 0.6.0 my tests run but in 0.11.0 not anymore. In dev everything runs ok.

I'm using Sandbox mode. In test_helper.exs I have

ExUnit.start()
Ecto.Adapters.SQL.Sandbox.mode(MyApp.Repo, {:shared, self()})

In my application.ex I have a watcher with extra columns. My application.ex

      {EctoWatch,
       repo: MyApp.Repo,
       pub_sub: MyApp.PubSub,
       watchers: [
         {CommunityOrganisation, :deleted, extra_columns: [:community_id, :organisation_id]}]

I get this error when running the tests (no test pass or fail but everything fails before any test are even run):

** (Mix) Could not start application burohelp: MyApp.Application.start(:normal, []) returned an error: shutdown: failed to start child: EctoWatch
    ** (EXIT) shutdown: failed to start child: EctoWatch.WatcherSupervisor
        ** (EXIT) shutdown: failed to start child: :ew_deleted_for_burohelp_db_organisations_teamworker
            ** (EXIT) an exception was raised:
                ** (DBConnection.ConnectionError) could not checkout the connection owned by #PID<0.1833.0>. When using the sandbox, connections are shared, so this may imply another process is using a connection. Reason: connection not available and request was dropped from queue after 10924ms. This means requests are coming in and your connection pool cannot serve them fast enough. You can address this by:

  1. Ensuring your database is available and that you can connect to it
  2. Tracking down slow queries and making sure they are running fast enough
  3. Increasing the pool_size (although this increases resource consumption)
  4. Allowing requests to wait longer by increasing :queue_target and :queue_interval

See DBConnection.start_link/2 for more information

                    (ecto_sql 3.11.3) lib/ecto/adapters/sql.ex:1054: Ecto.Adapters.SQL.raise_sql_call_error/1
                    (ecto_watch 0.8.1) lib/ecto_watch/watcher_server.ex:57: EctoWatch.WatcherServer.init/1
                    (stdlib 5.2.3) gen_server.erl:980: :gen_server.init_it/2
                    (stdlib 5.2.3) gen_server.erl:935: :gen_server.init_it/6
                    (stdlib 5.2.3) proc_lib.erl:241: :proc_lib.init_p_do_apply/3

Is there anything I should change in my test suite or anywhere else?

[cheerfulstoic]

Hey, thanks for reporting this!

So I'm not as familiar as I'd like to be with ecto sandboxes in tests, but I've been reading up on them to try to get my head around this. But some things I took note of first:

In your stacktrace I see it's reporting version 0.8.1 of ecto_watch. Upgrading probably won't fix this issue, but you could turn on the new debug? option (see the docs) to see the watcher server starting up and see it's PID. Make sure to checkout the Upgrading Versions guide in the docs as well.

I see the error says request was dropped from queue after 10924ms, so I guess that means that EctoWatch was trying to run it's query (creating a postgres function) and it waiting almost 11 seconds, which is definitely strange.. I see that you mentioned that this happened before any tests ran, so probably this isn't a comflict with another query, but I'm not sure what would cause that sort of timeout.

I'll try to see if I can re-create this in an app, especially with shared mode on.

[cheerfulstoic]

Reading the documentation I noted two things about shared mode:

"after checking out a connection in manual mode, you can change the mode to {:shared, pid}" - Not sure what exactly this means, but maybe you have to set :manual mode first?

"If successful, returns :ok (this is always successful for :auto and :manual modes)..." maybe add an :ok = on that last line in your test_helper.exs like this?

:ok = Ecto.Adapters.SQL.Sandbox.mode(MyApp.Repo, {:shared, self()})

...just so that it's obvious if something is failing there 🤷

[cheerfulstoic]

When I put :ok = Ecto.Adapters.SQL.Sandbox.mode(MyApp.Repo, {:shared, self()}) at the end of one of my repos I get an error because it's returning :not_found, so maybe setting the mode isn't actually doing anything for you? It doesn't seem to matter if I set :manual first.

Honestly I'm not sure what process the test_helper.exs runs inside of. I found this forum thread where they put {:shared, self()} inside of a setup block, which makes more sense to me... It's confusing, though, because this guide seems to heavily imply putting {:shared, self()} at the bottom of test_helper.exs, but maybe it's wrong?

Either way, it may or may not help with the EctoWatch issue, but it might be good to get that figured out first 😅

Also, I was reading the error again:

could not checkout the connection owned by #PID<0.1833.0>. When using the sandbox, connections are shared, so this may imply another process is using a connection. Reason: connection not available and request was dropped from queue after 10924ms. This means requests are coming in and your connection pool cannot serve them fast enough.

So it seems like it's not a query timeout but a checkout timeout, so it might be related because this sandbox stuff is all about processes owning connections that they've checked out from the pool, if I understand it correctly.

[paulsabou]

Thank you for looking into this. I will investigate further with different test setups and let you know what works.