Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Cannot run migrations with latest git #2256

Closed
xadhoom opened this issue Oct 2, 2017 · 6 comments · Fixed by #2258
Closed

Cannot run migrations with latest git #2256

xadhoom opened this issue Oct 2, 2017 · 6 comments · Fixed by #2258
Labels
Milestone

Comments

@xadhoom
Copy link
Contributor

xadhoom commented Oct 2, 2017

Environment

  • Elixir version (elixir -v): 1.5.2
  • Database and version : PostgreSQL 9.5
  • Ecto version (mix deps): master at 39f2347
  • 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
Copy link
Member

/cc @blatyo

@josevalim josevalim added this to the v3.0 milestone Oct 2, 2017
@blatyo
Copy link
Contributor

blatyo commented Oct 2, 2017

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
Copy link
Contributor

blatyo commented Oct 3, 2017

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
Copy link
Contributor

blatyo commented Oct 3, 2017

@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
Copy link
Contributor

blatyo commented Oct 3, 2017

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

@xadhoom
Copy link
Contributor Author

xadhoom commented Oct 3, 2017

yep, it works thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants