Repository: elixir-ecto/ecto (elixir)

Issue:
Cannot run migrations with latest git
### 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


Pull request:
Increase ecto pool size for running migrations
closes #2256

This will fix the immediate issue. In addition, Ecto should probably warn when the pool size is too small or capture the connection checkout error and suggest increasing the pool size.

Patch:
diff --git a/lib/mix/ecto.ex b/lib/mix/ecto.ex
index 76a49ca3..b092f42a 100644
--- a/lib/mix/ecto.ex
+++ b/lib/mix/ecto.ex
@@ -98,7 +98,7 @@ defmodule Mix.Ecto do
 
     {:ok, apps} = repo.__adapter__.ensure_all_started(repo, :temporary)
 
-    pool_size = Keyword.get(opts, :pool_size, 1)
+    pool_size = Keyword.get(opts, :pool_size, 2)
     case repo.start_link(pool_size: pool_size) do
       {:ok, pid} ->
         {:ok, pid, apps}


Test patch:
diff --git a/integration_test/sql/alter.exs b/integration_test/sql/alter.exs
index e88951fb..2534ceb4 100644
--- a/integration_test/sql/alter.exs
+++ b/integration_test/sql/alter.exs
@@ -36,15 +36,18 @@ defmodule Ecto.Integration.AlterTest do
   end
 
   import Ecto.Query, only: [from: 1, from: 2]
-  import Ecto.Migrator, only: [up: 4, down: 4]
+
+  defp run(direction, repo, module) do
+    Ecto.Migration.Runner.run(repo, module, :forward, direction, direction, log: false)
+  end
 
   test "reset cache on returning query after alter column type" do
     values = from v in "alter_col_type", select: v.value
 
-    assert :ok == up(PoolRepo, 20161112120000, AlterMigrationOne, log: false)
+    assert :ok == run(:up, PoolRepo, AlterMigrationOne)
     assert PoolRepo.all(values) == [1]
 
-    assert :ok == up(PoolRepo, 20161112130000, AlterMigrationTwo, log: false)
+    assert :ok == run(:up, PoolRepo, AlterMigrationTwo)
 
     # optionally fail once with ArgumentError when preparing query prepared on
     # another connection (and clear cache)
@@ -58,18 +61,35 @@ defmodule Ecto.Integration.AlterTest do
       result ->
         assert [%Decimal{}] = result
     end
+
+    PoolRepo.transaction(fn() ->
+      assert [%Decimal{}] = PoolRepo.all(values)
+
+      assert :ok == run(:down, PoolRepo, AlterMigrationTwo)
+
+      # optionally fail once with database error when already prepared on
+      # connection (and clear cache)
+      try do
+        PoolRepo.all(values, [mode: :savepoint])
+      catch
+        :error, _ ->
+          assert PoolRepo.all(values) == [1]
+      else
+        result ->
+          assert result == [1]
+      end
+    end)
   after
-    assert :ok == down(PoolRepo, 20161112130000, AlterMigrationTwo, log: false)
-    assert :ok == down(PoolRepo, 20161112120000, AlterMigrationOne, log: false)
+    assert :ok == run(:down, PoolRepo, AlterMigrationOne)
   end
 
   test "reset cache on paramterised query after alter column type" do
     values = from v in "alter_col_type"
 
-    assert :ok == up(PoolRepo, 20161112120000, AlterMigrationOne, log: false)
+    assert :ok == run(:up, PoolRepo, AlterMigrationOne)
     assert PoolRepo.update_all(values, [set: [value: 2]]) == {1, nil}
 
-    assert :ok == up(PoolRepo, 20161112130000, AlterMigrationTwo, log: false)
+    assert :ok == run(:up, PoolRepo, AlterMigrationTwo)
 
     # optionally fail once with ArgumentError when preparing query prepared on
     # another connection (and clear cache)
@@ -83,8 +103,15 @@ defmodule Ecto.Integration.AlterTest do
       result ->
         assert result == {1, nil}
     end
+
+    PoolRepo.transaction(fn() ->
+      assert PoolRepo.update_all(values, [set: [value: Decimal.new(5)]]) == {1, nil}
+
+      assert :ok == run(:down, PoolRepo, AlterMigrationTwo)
+
+      assert PoolRepo.update_all(values, [set: [value: 6]]) == {1, nil}
+    end)
   after
-    assert :ok == down(PoolRepo, 20161112130000, AlterMigrationTwo, log: false)
-    assert :ok == down(PoolRepo, 20161112120000, AlterMigrationOne, log: false)
+    assert :ok == run(:down, PoolRepo, AlterMigrationOne)
   end
 end
diff --git a/test/mix/ecto_test.exs b/test/mix/ecto_test.exs
index 99b555f2..b3c7d494 100644
--- a/test/mix/ecto_test.exs
+++ b/test/mix/ecto_test.exs
@@ -21,7 +21,7 @@ defmodule Mix.EctoTest do
 
   defmodule Repo do
     def start_link(opts) do
-      assert opts[:pool_size] == 1
+      assert opts[:pool_size] == 2
       Process.get(:start_link)
     end