Ecto: Cannot run migrations with latest git

[xadhoom]

Environment

• Elixir version (elixir -v): 1.5.2
• Database and version : PostgreSQL 9.5
• Ecto version (mix deps): master at https://github.com/elixir-ecto/ecto/commit/39f23475983228585d463d4d2a90937fd9bc1407
• Database adapter and version: postgrex 0.13.3
• Operating system: Linux Fedora 26

Additional information

A very barebone app to test the issue: https://github.com/xadhoom/test_ecto

Current behavior

Migration fails with timeout even with SQL.Sandbox adapter.

With standard adapter:

mix do ecto.drop, ecto.create, ecto.migrate
The database for TestEcto.Repo has been dropped
The database for TestEcto.Repo has been created

11:38:51.778 [debug] QUERY OK source="schema_migrations" db=0.4ms
SELECT s0."version"::bigint FROM "schema_migrations" AS s0 FOR UPDATE []
** (exit) exited in: :gen_server.call(TestEcto.Repo.Pool, {:checkout, #Reference<0.1585673959.3863478274.2703>, true}, 5000)
    ** (EXIT) time out
    (stdlib) gen_server.erl:214: :gen_server.call/3
    (poolboy) /tmp/test_ecto/deps/poolboy/src/poolboy.erl:55: :poolboy.checkout/3
    (db_connection) lib/db_connection/poolboy.ex:41: DBConnection.Poolboy.checkout/2
    (db_connection) lib/db_connection.ex:920: DBConnection.checkout/2
    (db_connection) lib/db_connection.ex:742: DBConnection.run/3
    (db_connection) lib/db_connection.ex:790: DBConnection.transaction/3
    (ecto) lib/ecto/migrator.ex:147: Ecto.Migrator.do_run_maybe_in_transaction/3
    (elixir) lib/task/supervised.ex:85: Task.Supervised.do_apply/2

11:38:56.808 [error] GenServer #PID<0.153.0> terminating
** (stop) exited in: :gen_server.call(TestEcto.Repo.Pool, {:checkout, #Reference<0.1585673959.3863478274.2703>, true}, 5000)
    ** (EXIT) time out
Last message: {:EXIT, #PID<0.73.0>, {:timeout, {:gen_server, :call, [TestEcto.Repo.Pool, {:checkout, #Reference<0.1585673959.3863478274.2703>, true}, 5000]}}}
State: {:state, {#PID<0.153.0>, Supervisor.Default}, :simple_one_for_one, [{:child, :undefined, Task.Supervised, {Task.Supervised, :start_link, []}, :temporary, 5000, :worker, [Task.Supervised]}], {:set, {:set, 0, 16, 16, 8, 80, 48, {[], [], [], [], [], [], [], [], [], [], [], [], [], [], [], []}, {{[], [], [], [], [], [], [], [], [], [], [], [], [], [], [], []}}}}, 3, 5, [], 0, Supervisor.Default, {[%{id: Task.Supervised, restart: :temporary, shutdown: 5000, start: {Task.Supervised, :start_link, []}}], [strategy: :simple_one_for_one]}}

With Sandbox adapter:

mix do ecto.drop, ecto.create, ecto.migrate
Compiling 3 files (.ex)
Generated test_ecto app
The database for TestEcto.Repo has been dropped
The database for TestEcto.Repo has been created

11:41:49.025 [debug] QUERY OK source="schema_migrations" db=0.3ms
SELECT s0."version"::bigint FROM "schema_migrations" AS s0 FOR UPDATE []
** (DBConnection.ConnectionError) failed to checkout using DBConnection.Poolboy
    (db_connection) lib/db_connection.ex:926: DBConnection.checkout/2
    (db_connection) lib/db_connection.ex:742: DBConnection.run/3
    (db_connection) lib/db_connection.ex:790: DBConnection.transaction/3
    (ecto) lib/ecto/migrator.ex:147: Ecto.Migrator.do_run_maybe_in_transaction/3
    (elixir) lib/task/supervised.ex:85: Task.Supervised.do_apply/2
    (elixir) lib/task/supervised.ex:36: Task.Supervised.reply/5
    (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3

11:41:54.053 [error] GenServer #PID<0.246.0> terminating
** (stop) exited in: :gen_server.call(#PID<0.235.0>, {:checkout, #Reference<0.2550196222.4132175873.158658>, true}, 5000)
    ** (EXIT) time out
    (stdlib) gen_server.erl:214: :gen_server.call/3
    (poolboy) /tmp/test_ecto/deps/poolboy/src/poolboy.erl:55: :poolboy.checkout/3
    (db_connection) lib/db_connection/poolboy.ex:41: DBConnection.Poolboy.checkout/2
    (db_connection) lib/db_connection/ownership/proxy.ex:108: DBConnection.Ownership.Proxy.handle_call/3
    (stdlib) gen_server.erl:636: :gen_server.try_handle_call/4
    (stdlib) gen_server.erl:665: :gen_server.handle_msg/6
    (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3
Last message (from #PID<0.245.0>): {:init, 15000}
State: %{client: nil, conn_module: nil, conn_state: nil, owner_ref: #Reference<0.2550196222.4132175873.158656>, ownership_timer: nil, pool: #PID<0.235.0>, pool_mod: DBConnection.Poolboy, pool_opts: [timeout: :infinity, name: TestEcto.Repo.Pool, otp_app: :test_ecto, repo: TestEcto.Repo, pool_timeout: 5000, adapter: Ecto.Adapters.Postgres, username: "postgres", password: "postgres", database: "test_ecto_test", hostname: "localhost", pool: DBConnection.Ownership, pool_size: 1], pool_ref: nil, queue: {[], []}, timer: nil}
Client #PID<0.245.0> is alive
    (stdlib) gen.erl:169: :gen.do_call/4
    (elixir) lib/gen_server.ex:771: GenServer.call/3
    (db_connection) lib/db_connection/ownership/proxy.ex:15: DBConnection.Ownership.Proxy.init/2
    (db_connection) lib/db_connection/ownership.ex:124: DBConnection.Ownership.checkout/2
    (db_connection) lib/db_connection.ex:920: DBConnection.checkout/2
    (db_connection) lib/db_connection.ex:742: DBConnection.run/3
    (db_connection) lib/db_connection.ex:790: DBConnection.transaction/3
    (ecto) lib/ecto/migrator.ex:147: Ecto.Migrator.do_run_maybe_in_transaction/3


11:41:54.057 [error] GenServer #PID<0.203.0> terminating
** (DBConnection.ConnectionError) failed to checkout using DBConnection.Poolboy
    (db_connection) lib/db_connection.ex:926: DBConnection.checkout/2
    (db_connection) lib/db_connection.ex:742: DBConnection.run/3
    (db_connection) lib/db_connection.ex:790: DBConnection.transaction/3
    (ecto) lib/ecto/migrator.ex:147: Ecto.Migrator.do_run_maybe_in_transaction/3
    (elixir) lib/task/supervised.ex:85: Task.Supervised.do_apply/2
    (elixir) lib/task/supervised.ex:36: Task.Supervised.reply/5
    (stdlib) proc_lib.erl:247: :proc_lib.init_p_do_apply/3
Last message: {:EXIT, #PID<0.73.0>, {%DBConnection.ConnectionError{message: "failed to checkout using DBConnection.Poolboy"}, [{DBConnection, :checkout, 2, [file: 'lib/db_connection.ex', line: 926]}, {DBConnection, :run, 3, [file: 'lib/db_connection.ex', line: 742]}, {DBConnection, :transaction, 3, [file: 'lib/db_connection.ex', line: 790]}, {Ecto.Migrator, :do_run_maybe_in_transaction, 3, [file: 'lib/ecto/migrator.ex', line: 147]}, {Task.Supervised, :do_apply, 2, [file: 'lib/task/supervised.ex', line: 85]}, {Task.Supervised, :reply, 5, [file: 'lib/task/supervised.ex', line: 36]}, {:proc_lib, :init_p_do_apply, 3, [file: 'proc_lib.erl', line: 247]}]}}
State: {:state, {#PID<0.203.0>, Supervisor.Default}, :simple_one_for_one, [{:child, :undefined, Task.Supervised, {Task.Supervised, :start_link, []}, :temporary, 5000, :worker, [Task.Supervised]}], {:set, {:set, 0, 16, 16, 8, 80, 48, {[], [], [], [], [], [], [], [], [], [], [], [], [], [], [], []}, {{[], [], [], [], [], [], [], [], [], [], [], [], [], [], [], []}}}}, 3, 5, [], 0, Supervisor.Default, {[%{id: Task.Supervised, restart: :temporary, shutdown: 5000, start: {Task.Supervised, :start_link, []}}], [strategy: :simple_one_for_one]}}

This seems related to #2245

Expected behavior

Migration runs

[josevalim]

/cc @blatyo

[blatyo]

Thanks for the test repo @xadhoom. I've duplicated the issue with your repo. Very clearly not exhausting the connection pool and no special isolation level. I'll take a look tonight.

[blatyo]

My preliminary investigation, even though the database is setup with a pool size of 10, there is only one connection available in the pool. I'm investigating why that is, but the issue is pool exhaustion.

[blatyo]

@xadhoom I'm not sure if this is currently blocking you. If it is, doing mix ecto.migrate --pool-size=2 should get you past this issue.

[blatyo]

I've also create PR #2259 to make this situation less confusing

[xadhoom]

yep, it works thanks!