Postgress timeout error in iex

Here’s the error:

[error] Postgrex.Protocol (#PID<0.291.0>) disconnected: ** (DBConnection.ConnectionError) owner #PID<0.317.0> timed out because it owned the connection for longer than 60000ms (set via the :ownership_timeout option)

I’ve read about similar errors and the solution is to change the timeout config–but I don’t know how to do that.

postgres 2.1.4 (43)

~/phoenix_apps/foo$ iex -S mix
Erlang/OTP 20 [erts-9.3] [source] [64-bit] [smp:4:4] [ds:4:4:10] [async-threads:10] [hipe] [kernel-poll:false]

Interactive Elixir (1.8.2) - press Ctrl+C to exit (type h() ENTER for help)

mix.exs:

defmodule Foo.MixProject do
  use Mix.Project

  def project do
    [
      app: :foo,
      version: "0.1.0",
      elixir: "~> 1.5",
      elixirc_paths: elixirc_paths(Mix.env()),
      compilers: [:phoenix, :gettext] ++ Mix.compilers(),
      start_permanent: Mix.env() == :prod,
      aliases: aliases(),
      deps: deps()
    ]
  end

  # Configuration for the OTP application.
  #
  # Type `mix help compile.app` for more information.
  def application do
    [
      mod: {Foo.Application, []},
      extra_applications: [:logger, :runtime_tools]
    ]
  end

  # Specifies which paths to compile per environment.
  defp elixirc_paths(:test), do: ["lib", "test/support"]
  defp elixirc_paths(_), do: ["lib"]

  # Specifies your project dependencies.
  #
  # Type `mix help deps` for examples and options.
  defp deps do
    [
      {:phoenix, "~> 1.4.0"},
      {:phoenix_pubsub, "~> 1.1"},

      {:phoenix_ecto, "~> 4.0"},
      {:ecto_sql, "~> 3.0"},
      {:postgrex, ">= 0.0.0"},

      {:phoenix_html, "~> 2.11"},
      {:phoenix_live_reload, "~> 1.2", only: :dev},
      {:gettext, "~> 0.11"},
      {:jason, "~> 1.0"},
      {:plug_cowboy, "~> 2.0"}
    ]
  end

  # Aliases are shortcuts or tasks specific to the current project.
  # For example, to create, migrate and run the seeds file at once:
  #
  #     $ mix ecto.setup
  #
  # See the documentation for `Mix` for more info on aliases.
  defp aliases do
    [
      "ecto.setup": ["ecto.create", "ecto.migrate", "run priv/repo/seeds.exs"],
      "ecto.reset": ["ecto.drop", "ecto.setup"],
      test: ["ecto.create --quiet", "ecto.migrate", "test"]
    ]
  end
end

config.ex:

# This file is responsible for configuring your application
# and its dependencies with the aid of the Mix.Config module.
#
# This configuration file is loaded before any dependency and
# is restricted to this project.

# General application configuration
use Mix.Config

config :foo, 
  ecto_repos: [Foo.Repo]

config :foo, Foo.Repo,
  datbase: "foo",
  username: "7stud",
  password: "",
  hostname: "localhost",
  port: "5432",
  pool: Ecto.Adapters.SQL.Sandbox

# Configures the endpoint
config :foo, FooWeb.Endpoint,
  url: [host: "localhost"],
  secret_key_base: "N6K81h2nEY56l+GjbUMMjkUILbxGSZeSLbBNqxI1eksHIeWxoSe9M86YnixpAn32",
  render_errors: [view: FooWeb.ErrorView, accepts: ~w(html json)],
  pubsub: [name: Foo.PubSub, adapter: Phoenix.PubSub.PG2]

# Configures Elixir's Logger
config :logger, :console,
  format: "$time $metadata[$level] $message\n",
  metadata: [:request_id]

# Use Jason for JSON parsing in Phoenix
config :phoenix, :json_library, Jason

# Import environment specific config. This must remain at the bottom
# of this file so it overrides the configuration defined above.
import_config "#{Mix.env()}.exs"

How have you checked out the connection?

I’m running Postgres.app on localhost. I stopped and restarted Postgres.app, and the error persists.

What do you do to make this error happen?

Is just startingiex -S mix and waiting enough? Or do you need to call functions to trigger it? If so, which?

Also, the sandbox pool is only for testing AFAIK.

I tried doing iex -S mix and letting it sit there for 5 minutes, and I did not get a timeout error. I have to make some function calls to get the error:

iex(1)> Foo.go                
[debug] QUERY OK db=11.2ms decode=3.4ms queue=6.9ms
INSERT INTO "items" ("AM01","inserted_at","updated_at") VALUES ($1,$2,$3) RETURNING "id" [%{"AM" => "01", "D9" => ""}, ~N[2019-07-06 20:29:33], ~N[2019-07-06 20:29:33]]
[debug] QUERY OK db=1.6ms queue=0.4ms
INSERT INTO "items" ("AM02","inserted_at","updated_at") VALUES ($1,$2,$3) RETURNING "id" [%{"AM" => "02", "D8" => ""}, ~N[2019-07-06 20:29:33], ~N[2019-07-06 20:29:33]]
:ok
iex(2)> items = Foo.list_items
[debug] QUERY OK source="items" db=8.3ms queue=0.5ms
SELECT i0."id", i0."title", i0."AM01", i0."AM02", i0."inserted_at", i0."updated_at" FROM "items" AS i0 []
[
  %Foo.Item{
    AM01: %{"AM" => "01", "D9" => ""},
    AM02: nil,
    __meta__: #Ecto.Schema.Metadata<:loaded, "items">,
    id: 77,
    inserted_at: ~N[2019-07-06 19:44:20],
    title: nil,
    updated_at: ~N[2019-07-06 19:44:20]
  },
  %Foo.Item{
    AM01: nil,
    AM02: %{"AM" => "02", "D8" => ""},
    __meta__: #Ecto.Schema.Metadata<:loaded, "items">,
    id: 78,
    inserted_at: ~N[2019-07-06 19:44:20],
    title: nil,
    updated_at: ~N[2019-07-06 19:44:20]
  },
  %Foo.Item{
    AM01: %{"AM" => "01", "D9" => ""},
    AM02: nil,
    __meta__: #Ecto.Schema.Metadata<:loaded, "items">,
    id: 79,
    inserted_at: ~N[2019-07-06 20:29:33],
    title: nil,
    updated_at: ~N[2019-07-06 20:29:33]
  },
  %Foo.Item{
    AM01: nil,
    AM02: %{"AM" => "02", "D8" => ""},
    __meta__: #Ecto.Schema.Metadata<:loaded, "items">,
    id: 80,
    inserted_at: ~N[2019-07-06 20:29:33],
    title: nil,
    updated_at: ~N[2019-07-06 20:29:33]
  }
]
iex(3)> for item <- items, do: Foo.delete_item(item)
[debug] QUERY OK db=1.8ms queue=0.6ms
DELETE FROM "items" WHERE "id" = $1 [77]
[debug] QUERY OK db=1.4ms queue=0.1ms
DELETE FROM "items" WHERE "id" = $1 [78]
[debug] QUERY OK db=1.7ms
DELETE FROM "items" WHERE "id" = $1 [79]
[debug] QUERY OK db=1.4ms
DELETE FROM "items" WHERE "id" = $1 [80]
[
  ok: %Foo.Item{
    AM01: %{"AM" => "01", "D9" => ""},
    AM02: nil,
    __meta__: #Ecto.Schema.Metadata<:deleted, "items">,
    id: 77,
    inserted_at: ~N[2019-07-06 19:44:20],
    title: nil,
    updated_at: ~N[2019-07-06 19:44:20]
  },
  ok: %Foo.Item{
    AM01: nil,
    AM02: %{"AM" => "02", "D8" => ""},
    __meta__: #Ecto.Schema.Metadata<:deleted, "items">,
    id: 78,
    inserted_at: ~N[2019-07-06 19:44:20],
    title: nil,
    updated_at: ~N[2019-07-06 19:44:20]
  },
  ok: %Foo.Item{
    AM01: %{"AM" => "01", "D9" => ""},
    AM02: nil,
    __meta__: #Ecto.Schema.Metadata<:deleted, "items">,
    id: 79,
    inserted_at: ~N[2019-07-06 20:29:33],
    title: nil,
    updated_at: ~N[2019-07-06 20:29:33]
  },
  ok: %Foo.Item{
    AM01: nil,
    AM02: %{"AM" => "02", "D8" => ""},
    __meta__: #Ecto.Schema.Metadata<:deleted, "items">,
    id: 80,
    inserted_at: ~N[2019-07-06 20:29:33],
    title: nil,
    updated_at: ~N[2019-07-06 20:29:33]
  }
]
iex(4)> [error] Postgrex.Protocol (#PID<0.281.0>) disconnected: ** (DBConnection.ConnectionError) owner #PID<0.308.0> timed out because it owned the connection for longer than 60000ms (set via the :ownership_timeout option)

Have you tried removing the pool: Ecto.Adapters.SQL.Sandbox from your config, as I suggested earlier? Does the problem persist then?

2 Likes

That seems to have gotten rid of the error. Thanks!