Preload fails to checkout connection from poolboy

[olivermt]

Environment

• Elixir version (elixir -v): 1.3.2
• Database and version (PostgreSQL 9.4, MongoDB 3.2, etc.): postgres 9.4
• Ecto version (mix deps): 2.0.0
• Database adapter and version (mix deps):
• Operating system: windows

Current behavior

Task that seeds test database fails.
It seems to crash on a subsequent Repo.get/preload, but I have not been able to reproduce in a fresh repo so I am not sure.

Chain of code that fails:

Excerpt from fixtures task:

Logger.info "Setting up some personal video addresses and provisioning clients"
    video_addresses = samples do
      :user_id | :username                   | :domain_id
      1        | "branded"                   | 1
      2        | "cmedude"                   | 2
      3        | "seeviadude"                | 1
      4        | "pexipbrander"              | 1
      6        | "vcsdude"                   | 3
    end

    Enum.each(video_addresses, fn va_params ->
      {:ok, _ } = Repo.get(User, va_params.user_id)
                   |> VideoAddressService.create_video_address(%{"username" => va_params.username, "domain_id" => va_params.domain_id})
      unless va_params.user_id == 1 do
        {:ok, _}  = ClientService.create_client(va_params.user_id)
        Logger.info "Created clients for user id #{inspect va_params.user_id}"
      end
    end)

The call to VideoAddressService does not fail, so not included.

The clientservice is very small and looks like so:

  def create_client(user_id) do
    Logger.debug "It fails here"
    Repo.get(User, user_id)
    |> Repo.preload([:video_address, :client]) #line that fails
    |> do_create_client
  end

Console output:
The select from the get, so that part seems to work:

11:54:34.046 [debug] QUERY OK db=0.0ms
SELECT u0."id", u0."company_id", u0."username", u0."password", u0."name", u0."phone_number", u0."activated", u0."seevia_id", u0."recovery_pin", u0."recovery_pin_timestamp", u0."recovery_hash", u0."first_time_password", u0."inserted_at", u0."updated_at" FROM "users" AS u0 WHERE (u0."id" = $1) [2]

Then it fails on the preload

** (EXIT from #PID<0.45.0>) an exception was raised:
    ** (DBConnection.ConnectionError) failed to checkout using DBConnection.Poolboy
        (db_connection) lib/db_connection.ex:722: DBConnection.checkout/2
        (db_connection) lib/db_connection.ex:623: DBConnection.run/3
        (db_connection) lib/db_connection.ex:464: DBConnection.prepare_execute/4
        (ecto) lib/ecto/adapters/sql.ex:228: Ecto.Adapters.SQL.sql_call/6
        (ecto) lib/ecto/adapters/sql.ex:400: Ecto.Adapters.SQL.execute_and_cache/7
        (ecto) lib/ecto/repo/queryable.ex:127: Ecto.Repo.Queryable.execute/5
        (ecto) lib/ecto/repo/queryable.ex:40: Ecto.Repo.Queryable.all/4
        (ecto) lib/ecto/repo/preloader.ex:171: Ecto.Repo.Preloader.fetch_query/8

11:54:39.133 [error] GenServer #PID<0.205.0> terminating
** (stop) exited in: :gen_server.call(#PID<0.193.0>, {:checkout, #Reference<0.0.4.180>, true}, 5000)
    ** (EXIT) time out
    (stdlib) gen_server.erl:212: :gen_server.call/3
    (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:629: :gen_server.try_handle_call/4
    (stdlib) gen_server.erl:661: :gen_server.handle_msg/5
    (stdlib) proc_lib.erl:240: :proc_lib.init_p_do_apply/3
Last message: {:init, 15000}
State: %{client: nil, conn_module: nil, conn_state: nil, owner_ref: #Reference<0.0.6.413>, ownership_timer: nil, pool: #PID<0.193.0>, pool_mod: DBConnection.Poolboy, pool_opts: [timeout: :infinity, decode_mapper: #Function<2.44924915/1 in Ecto.Adapters.SQL.execute/6>, log: #Function<13.44924915/1 in Ecto.Adapters.SQL.with_log/3>, caller: #PID<0.45.0>, pool_timeout: 5000, adapter: Ecto.Adapters.Postgres, username: "olivermt", password: "", database: "core_test", pool: DBConnection.Ownership, size: 1], pool_ref: nil, queue: {[], []}, timer: nil}

11:54:39.133 [error] GenServer #PID<0.206.0> terminating
** (stop) exited in: :gen_server.call(#PID<0.193.0>, {:checkout, #Reference<0.0.6.419>, true}, 5000)
    ** (EXIT) time out
    (stdlib) gen_server.erl:212: :gen_server.call/3
    (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:629: :gen_server.try_handle_call/4
    (stdlib) gen_server.erl:661: :gen_server.handle_msg/5
    (stdlib) proc_lib.erl:240: :proc_lib.init_p_do_apply/3
Last message: {:init, 15000}
State: %{client: nil, conn_module: nil, conn_state: nil, owner_ref: #Reference<0.0.6.416>, ownership_timer: nil, pool: #PID<0.193.0>, pool_mod: DBConnection.Poolboy, pool_opts: [timeout: :infinity, decode_mapper: #Function<2.44924915/1 in Ecto.Adapters.SQL.execute/6>, log: #Function<13.44924915/1 in Ecto.Adapters.SQL.with_log/3>, caller: #PID<0.45.0>, pool_timeout: 5000, adapter: Ecto.Adapters.Postgres, username: "olivermt", password: "", database: "core_test", pool: DBConnection.Ownership, size: 1], pool_ref: nil, queue: {[], []}, timer: nil}

11:54:39.148 [error] Task #PID<0.203.0> started from #PID<0.45.0> terminating
** (DBConnection.ConnectionError) failed to checkout using DBConnection.Poolboy
    (db_connection) lib/db_connection.ex:722: DBConnection.checkout/2
    (db_connection) lib/db_connection.ex:623: DBConnection.run/3
    (db_connection) lib/db_connection.ex:464: DBConnection.prepare_execute/4
    (ecto) lib/ecto/adapters/sql.ex:228: Ecto.Adapters.SQL.sql_call/6
    (ecto) lib/ecto/adapters/sql.ex:400: Ecto.Adapters.SQL.execute_and_cache/7
    (ecto) lib/ecto/repo/queryable.ex:127: Ecto.Repo.Queryable.execute/5
    (ecto) lib/ecto/repo/queryable.ex:40: Ecto.Repo.Queryable.all/4
    (ecto) lib/ecto/repo/preloader.ex:171: Ecto.Repo.Preloader.fetch_query/8
Function: &:erlang.apply/2
    Args: [#Function<10.114827146/2 in Ecto.Repo.Preloader.preload_each/4>, [{{:assoc, %Ecto.Association.Has{cardinality: :one, defaults: [], field: :client, on_cast: nil, on_delete: :nothing, on_replace: :raise, owner: Core.User, owner_key: :id, queryable: Core.Client, related: Core.Client, related_key: :user_id, relationship: :child}, {0, :user_id}}, nil, nil, []}, [caller: #PID<0.45.0>]]]

11:54:39.159 [error] Task #PID<0.204.0> started from #PID<0.45.0> terminating
** (DBConnection.ConnectionError) failed to checkout using DBConnection.Poolboy
    (db_connection) lib/db_connection.ex:722: DBConnection.checkout/2
    (db_connection) lib/db_connection.ex:623: DBConnection.run/3
    (db_connection) lib/db_connection.ex:464: DBConnection.prepare_execute/4
    (ecto) lib/ecto/adapters/sql.ex:228: Ecto.Adapters.SQL.sql_call/6
    (ecto) lib/ecto/adapters/sql.ex:400: Ecto.Adapters.SQL.execute_and_cache/7
    (ecto) lib/ecto/repo/queryable.ex:127: Ecto.Repo.Queryable.execute/5
    (ecto) lib/ecto/repo/queryable.ex:40: Ecto.Repo.Queryable.all/4
    (ecto) lib/ecto/repo/preloader.ex:171: Ecto.Repo.Preloader.fetch_query/8
Function: &:erlang.apply/2
    Args: [#Function<10.114827146/2 in Ecto.Repo.Preloader.preload_each/4>, [{{:assoc, %Ecto.Association.Has{cardinality: :one, defaults: [], field: :video_address, on_cast: nil, on_delete: :nothing, on_replace: :raise, owner: Core.User, owner_key: :id, queryable: Core.VideoAddress, related: Core.VideoAddress, related_key: :user_id, relationship: :child}, {0, :user_id}}, nil, nil, []}, [caller: #PID<0.45.0>]]]

11:54:39.170 [error] GenServer Core.Repo terminating
** (DBConnection.ConnectionError) failed to checkout using DBConnection.Poolboy
    (db_connection) lib/db_connection.ex:722: DBConnection.checkout/2
    (db_connection) lib/db_connection.ex:623: DBConnection.run/3
    (db_connection) lib/db_connection.ex:464: DBConnection.prepare_execute/4
    (ecto) lib/ecto/adapters/sql.ex:228: Ecto.Adapters.SQL.sql_call/6
    (ecto) lib/ecto/adapters/sql.ex:400: Ecto.Adapters.SQL.execute_and_cache/7
    (ecto) lib/ecto/repo/queryable.ex:127: Ecto.Repo.Queryable.execute/5
    (ecto) lib/ecto/repo/queryable.ex:40: Ecto.Repo.Queryable.all/4
    (ecto) lib/ecto/repo/preloader.ex:171: Ecto.Repo.Preloader.fetch_query/8
Last message: {:EXIT, #PID<0.45.0>, {%DBConnection.ConnectionError{message: "failed to checkout using DBConnection.Poolboy"}, [{DBConnection, :checkout, 2, [file: 'lib/db_connection.ex', line: 722]}, {DBConnection, :run, 3, [file: 'lib/db_connection.ex', line: 623]}, {DBConnection, :prepare_execute, 4, [file: 'lib/db_connection.ex', line: 464]}, {Ecto.Adapters.SQL, :sql_call, 6, [file: 'lib/ecto/adapters/sql.ex', line: 228]}, {Ecto.Adapters.SQL, :execute_and_cache, 7, [file: 'lib/ecto/adapters/sql.ex', line: 400]}, {Ecto.Repo.Queryable, :execute, 5, [file: 'lib/ecto/repo/queryable.ex', line: 127]}, {Ecto.Repo.Queryable, :all, 4, [file: 'lib/ecto/repo/queryable.ex', line: 40]}, {Ecto.Repo.Preloader, :fetch_query, 8, [file: 'lib/ecto/repo/preloader.ex', line: 171]}]}}
State: {:state, {:local, Core.Repo}, :one_for_one, [{:child, #PID<0.190.0>, DBConnection.Ownership.Manager, {DBConnection.Ownership.Manager, :start_link, [Postgrex.Protocol, [types: true, hostname: "localhost", types: true, name: Core.Repo.Pool, otp_app: :core, repo: Core.Repo, adapter: Ecto.Adapters.Postgres, username: "olivermt", password: "", database: "core_test", size: 1, pool_size: 1, pool_timeout: 5000, timeout: 15000, adapter: Ecto.Adapters.Postgres, username: "olivermt", password: "", database: "core_test", pool: DBConnection.Ownership, size: 1, extensions: [{Ecto.Adapters.Postgres.DateTime, []}, {Postgrex.Extensions.JSON, [library: Poison]}], port: 5432]]}, :permanent, 5000, :worker, [DBConnection.Ownership.Manager]}], :undefined, 3, 5, [], Ecto.Repo.Supervisor, {Core.Repo, :core, Ecto.Adapters.Postgres, [otp_app: :core, repo: Core.Repo, adapter: Ecto.Adapters.Postgres, username: "olivermt", password: "", database: "core_test", pool: Ecto.Adapters.SQL.Sandbox, size: 1, pool_size: 1]}}

[josevalim]

How are you running the seeds file? Most likely we will need a way to reproduce this, otherwise it will be very hard for us to fix it.

[olivermt]

This task:

defmodule Mix.Tasks.Fixtures do
  use Mix.Task
  import Mix.Ecto
  require Logger
  alias Core.Repo

  def run(_) do
    {:ok, pid, _} = ensure_started(Repo, [])
    Core.Test.Fixtures.seed_database

    pid && Repo.stop(pid)
  end

end```

[josevalim]

@olivermt Mix.Ecto is private API: https://github.com/elixir-ecto/ecto/blob/master/lib/mix/ecto.ex#L3. Please, please don't rely on private APIs. Can you try the following:

  def run(_) do
    Mix.Task.run "app.start"
    Core.Test.Fixtures.seed_database
  end

[olivermt]

Works like a charm!

I got the ensure_started stuff from ericmj like 10-11 months ago and just carried it over into newer versions.

Didnt know about app.start task.

Thank you for prompt and effective feedback :)