Ecto.Adapters.SQL.Sandbox times out in CI (GH Actions/Semaphore)

[lessless]

Hi,

Initially, I opened a topic on the elixir form, but on the second thought, this might be a better place, because the aforementioned plug's behaviour varies depending on the environment, whilst ideally it should be indiscriminate to that.

I’m looking for advice on setting up E2E testing with Cypress as a part of the CI/CD pipeline. The suite works perfectly fine, but it’s a total trainwreck with Github Actions and Semaphore.

The whole approach is a somewhat low-key solution:

• clone the e2e suite alongside the main app
• start phx.server in the background
• run e2e tests

As I wrote, the problem is that Phoenix is starting to drop DB connections.

Depending on the debug settings I can get one of these

1:32:32.325 [error] #PID<0.912.0> running MimisbrunnrWeb.Endpoint (connection #PID<0.805.0>, stream id 3
) terminated
Server: localhost:1080 (http)
Request: DELETE /sandbox
** (exit) an exception was raised:
    ** (File.Error) could not stream "apps/mimisbrunnr_web/lib/mimisbrunnr_web/endpoint.ex": no such file
 or directory
        (elixir 1.13.4) lib/file/stream.ex:83: anonymous fn/3 in Enumerable.File.Stream.reduce/3
        (elixir 1.13.4) lib/stream.ex:1517: anonymous fn/5 in Stream.resource/3
        (elixir 1.13.4) lib/stream.ex:1719: Enumerable.Stream.do_each/4
        (elixir 1.13.4) lib/enum.ex:4144: Enum.split/2
        (plug 1.13.6) lib/plug/debugger.ex:472: Plug.Debugger.get_snippet/2
        (plug 1.13.6) lib/plug/debugger.ex:328: Plug.Debugger.each_frame/4
        (elixir 1.13.4) lib/enum.ex:1715: Enum."-map_reduce/3-lists^mapfoldl/2-0-"/3
        (elixir 1.13.4) lib/enum.ex:1715: Enum."-map_reduce/3-lists^mapfoldl/2-0-"/3

Error:  GenServer #PID<0.627.0> terminating

** (MatchError) no match of right hand side value: :not_found

    (phoenix_ecto 4.4.0) lib/phoenix_ecto/sql/sandbox_session.ex:22: Phoenix.Ecto.SQL.SandboxSession.handle_call/3

Error:  GenServer #PID<0.627.0> terminating
** (MatchError) no match of right hand side value: :not_found
    (phoenix_ecto 4.4.0) lib/phoenix_ecto/sql/sandbox_session.ex:22: Phoenix.Ecto.SQL.SandboxSession.handle_call/3
##[debug]Dropping file value '/home/runner/work/mimisbrunnr/mimisbrunnr/    (phoenix_ecto 4.4.0) lib/phoenix_ecto/sql/sandbox_session.ex'. Path does not exist
Warning:     (stdlib 3.16.1) gen_server.erl:721: :gen_server.try_handle_call/4
    (stdlib 3.16.1) gen_server.erl:750: :gen_server.handle_msg/6
##[debug]Dropping file value '/home/runner/work/mimisbrunnr/mimisbrunnr/    (stdlib 3.16.1) gen_server.erl'. Path does not exist
Warning:     (stdlib 3.16.1) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
Last message (from #PID<0.701.0>): :checkin
State: %{client: #PID<0.626.0>, repo: Mimisbrunnr.Repo, sandbox: Ecto.Adapters.SQL.Sandbox}
Client #PID<0.701.0> is alive

    (stdlib 3.16.1) gen.erl:233: :gen.do_call/4
##[debug]Dropping file value '/home/runner/work/mimisbrunnr/mimisbrunnr/    (stdlib 3.16.1) gen.erl'. Path does not exist
Warning:     (elixir 1.12.3) lib/gen_server.ex:1021: GenServer.call/3
    (phoenix_ecto 4.4.0) lib/phoenix_ecto/sql/sandbox.ex:200: Phoenix.Ecto.SQL.Sandbox.call/2
##[debug]Dropping file value '/home/runner/work/mimisbrunnr/mimisbrunnr/    (phoenix_ecto 4.4.0) lib/phoenix_ecto/sql/sandbox.ex'. Path does not exist
Warning:     (mimisbrunnr_web 0.1.0) lib/mimisbrunnr_web/endpoint.ex:1: MimisbrunnrWeb.Endpoint.plug_builder_call/2
    (mimisbrunnr_web 0.1.0) lib/plug/debugger.ex:136: MimisbrunnrWeb.Endpoint."call (overridable 3)"/2
##[debug]Dropping file value '/home/runner/work/mimisbrunnr/mimisbrunnr/    (mimisbrunnr_web 0.1.0) lib/plug/debugger.ex'. Path does not exist
Warning:     (mimisbrunnr_web 0.1.0) lib/mimisbrunnr_web/endpoint.ex:1: MimisbrunnrWeb.Endpoint.call/2
    (phoenix 1.6.7) lib/phoenix/endpoint/cowboy2_handler.ex:54: Phoenix.Endpoint.Cowboy2Handler.init/4
##[debug]Dropping file value '/home/runner/work/mimisbrunnr/mimisbrunnr/    (phoenix 1.6.7) lib/phoenix/endpoint/cowboy2_handler.ex'. Path does not exist
Warning:     (cowboy 2.9.0) /__w/mimisbrunnr/mimisbrunnr/main/deps/cowboy/src/cowboy_handler.erl:37: :cowboy_handler.execute/2
Error:  #PID<0.701.0> running MimisbrunnrWeb.Endpoint (connection #PID<0.680.0>, stream id 2) terminated

To isloate tests I followed guide from Dockyard https://dockyard.com/blog/2017/11/15/how-to-add-concurrent-transactional-end-to-end-tests-in-a-phoenix-powered-ember-app.

config/acceptance_tests.exs

import Config

config :mimisbrunnr, sql_sandbox: true

config :mimisbrunnr, Mimisbrunnr.Repo,
  pool: Ecto.Adapters.SQL.Sandbox,
  pool_size: 10

endpoint.ex:

  if Application.compile_env(:mimisbrunnr, :sql_sandbox) do
    plug Phoenix.Ecto.SQL.Sandbox,
      at: "/sandbox",
      header: "x-user-agent",
      repo: Mimisbrunnr.Repo,
      timeout: 30_000 # default
  end

If I bump timeout to 150_000 I’m getting

[error] GenServer #PID<0.1276.0> terminating
** (MatchError) no match of right hand side value: :not_found
    (phoenix_ecto 4.4.0) lib/phoenix_ecto/sql/sandbox_session.ex:27: Phoenix.Ecto.SQL.SandboxSession.handle_info/2
    (stdlib 3.17.2) gen_server.erl:695: :gen_server.try_dispatch/4
    (stdlib 3.17.2) gen_server.erl:771: :gen_server.handle_msg/6
    (stdlib 3.17.2) proc_lib.erl:226: :proc_lib.init_p_do_apply/3
Last message: :timeout
State: %{client: #PID<0.1275.0>, repo: Mimisbrunnr.Repo, sandbox: Ecto.Adapters.SQL.Sandbox}
[error] Postgrex.Protocol (#PID<0.476.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.1416.0> exited
[error] Postgrex.Protocol (#PID<0.474.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.1415.0> exited
[error] Postgrex.Protocol (#PID<0.473.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.1418.0> exited
[error] Postgrex.Protocol (#PID<0.481.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.1419.0> exited
[error] Postgrex.Protocol (#PID<0.479.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.1442.0> exited
[error] Postgrex.Protocol (#PID<0.478.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.1445.0> exited

If the app doesn’t checkout session, then everything is fine. That is I comment out those two blocks in Cypress:

Before(async () => {
  await cy.request('POST', sandboxUrl).then((response) => {
    context.sandboxSessionId = response.body;
    return context;
  });
});

After(() => {
  cy.request({
    method: 'DELETE',
    url: sandboxUrl,
    headers: { 'x-user-agent': context.sandboxSessionId },
    retryOnStatusCodeFailure: false,
    failOnStatusCode: false,
  });
});

[josevalim]

From the looks of it, it seems not related to Ecto. You are most likely running out of file descriptors in the OS, and that’s causing reading file, opening sockets, and similar to fail. Bump or set the limit to infinity and you should be good.

[lessless]

File descriptors limit is already set to max

$ ulimit -a
core file size          (blocks, -c) 0
data seg size           (kbytes, -d) unlimited
scheduling priority             (-e) 0
file size               (blocks, -f) unlimited
pending signals                 (-i) 31538
max locked memory       (kbytes, -l) 65536
max memory size         (kbytes, -m) unlimited
open files                      (-n) 1024000
pipe size            (512 bytes, -p) 8
POSIX message queues     (bytes, -q) 819200
real-time priority              (-r) 0
stack size              (kbytes, -s) 8192
cpu time               (seconds, -t) unlimited
max user processes              (-u) 10240
virtual memory          (kbytes, -v) unlimited
file locks                      (-x) unlimited

[josevalim]

Hrm, this is weird because it shows the classical symptoms of running out of file descriptors. Both tools (Elixir and the thing logging file dropped) are reporting the same.

So given two tools report the same and it works on other environments, I am inclined to think the issue is elsewhere, unless you can further isolate/pin point it.