Experimenting with Ecto Queries

Readers, thank you all for your patience as I haven’t posted for several weeks.

Last time I wrote about setting up Ecto from scratch and I promised to continue with this topic. However, this post will be another topice though it is Ecto related. I’m going to go through a series of troubleshooting experiments in order to learn more about a problem I’ve run into in one of my private projects.

In this post I’m using

Elixir 1.2.0
Ecto 1.1.1
timex 1.0.0
timex_ecto 0.7.0

The Models

In my private project I have a Phoenix application with a model that represents an object that is available during specific date/time ranges. We’ll call this Object for now. There is a second model, AvailableDateRange which represents a single range of dates. An Object has many AvailableDateRanges.

I’m using Timex to describe the date/times.

Here’s a stripped down version of these structures:

defmodule Project.Object do
  use Project.Web, :model
  require Logger

  schema "object" do
    field :title, :string
    field :description, :string
    belongs_to :user, User

    has_many :available_date_ranges, Project.AvailableDateRange, on_replace: :delete

    timestamps
  end
end

defmodule Project.AvailableDateRange do
  use Project.Web, :model
  use Timex.Ecto.Timestamps

  schema "available_date_ranges" do
    field :start, Timex.Ecto.DateTimeWithTimezone
    field :end, Timex.Ecto.DateTimeWithTimezone
    belongs_to :object, Project.Object

    timestamps
  end
end

The Query

In my project I have a query that looks like this:

def available_for(query \\ Project.Object, s, e) do
  s = parse_date(s)
  e = parse_date(e)

  from object in query, join: a in assoc(object, :available_date_ranges), where: a.start > ^s
end

defp parse_date(date) do
  {:ok, timex} = Timex.DateFormat.parse(date, "{M}/{D}/{YYYY}")
  timex
end

The function available_for/3 is a composable query. I can pass any query that returns Object records int available_for/3 and it builds a new query that limits the original query to those Object records that are available for a specific date. The function is unfinished. It checks only the starting date and not the ending date. I haven’t finished this because it isn’t working.

The Problem

When I try to use this query I get this error:

** (exit) an exception was raised:
    ** (FunctionClauseError) no function clause matching in :lists.zip/2
        (stdlib) lists.erl:386: :lists.zip([{ {2016, 1, 5}, {0, 0, 0, 0}}, "UTC"], [])
        (postgrex) lib/postgrex/extensions/binary.ex:297: Postgrex.Extensions.Binary.encode_record/3
        (postgrex) lib/postgrex/protocol.ex:299: anonymous fn/2 in Postgrex.Protocol.encode_params/1
        (elixir) lib/enum.ex:1043: anonymous fn/3 in Enum.map/2
        (elixir) lib/enum.ex:1387: Enum."-reduce/3-lists^foldl/2-0-"/3
        (elixir) lib/enum.ex:1043: Enum.map/2
        (postgrex) lib/postgrex/protocol.ex:294: Postgrex.Protocol.encode_params/1
        (postgrex) lib/postgrex/protocol.ex:264: Postgrex.Protocol.send_params/2
        (postgrex) lib/postgrex/protocol.ex:136: Postgrex.Protocol.message/3
        (postgrex) lib/postgrex/connection.ex:417: Postgrex.Connection.new_data/2
        (postgrex) lib/postgrex/connection.ex:292: Postgrex.Connection.handle_info/2
        (stdlib) gen_server.erl:615: :gen_server.try_dispatch/4
        (stdlib) gen_server.erl:681: :gen_server.handle_msg/5
        (stdlib) proc_lib.erl:240: :proc_lib.init_p_do_apply/3

This error happens deep inside Postgrex, the Postgres adapter for Ecto. I can understand that the zip function doesn’t match on lists of different sizes but I don’t know why this happening. In the rest of the post we will investigate what is going wrong and how we can make this work.

Experiments

I will approach this investigation as a series of experiments, each experiment building on the previous. I’ll start with a very simple Ecto program and will build up toward something like the example from my private project until I can reproduce this same error.

The goals of these are experiments are to

Build up an understanding of what’s going on with my query.
Build a minimal reproduction case that I can debug or send off to the Ecto developers for further investigation.

Experiment 1 - Setup a basic Ecto application

First I need a basic Elixir application with Ecto. I covered exactly this in the last post so I won’t go over it in detail here. But here are the commands I’m running so you can follow along.

First, create a new supervised mix project. EE is “Ecto Experiments”

$ mix new --sup ee

Next, I put everything under source control.

Install ecto with postgrex and start the Ecto application. I can do this in mix.exs.

@@ -14,7 +14,7 @@ defmodule EE.Mixfile do
   #
   # Type "mix help compile.app" for more information
   def application do
-    [applications: [:logger]]
+    [applications: [:logger, :postgrex, :ecto]]
   end

   # Dependencies can be Hex packages:
@@ -27,6 +27,9 @@ defmodule EE.Mixfile do
   #
   # Type "mix help deps" for more examples and options
   defp deps do
-    []
+    [
+      {:postgrex, ">= 0.0.0"},
+      {:ecto, "~> 1.0"},
+    ]
   end
 end

I then configured the database by adding the following to config/config.exs:

config :ee, Ee.Repo,
  adapter: Ecto.Adapters.Postgres,
  database: "ecto_experiments",
  username: "postgres",
  password: "postgres"

Then, I created a Repo in lib/ee/repo.ex:

defmodule Ee.Repo do
  use Ecto.Repo,
  otp_app: :ee
end

Then I added the Repo as a worker in my child specification:

index ae71ede..7524c78 100644
--- a/lib/ee.ex
+++ b/lib/ee.ex
@@ -8,7 +8,7 @@ defmodule Ee do

     children = [
       # Define workers and child supervisors to be supervised
-      # worker(Ee.Worker, [arg1, arg2, arg3]),
+      worker(Ee.Repo, [])
     ]

     # See http://elixir-lang.org/docs/stable/elixir/Supervisor.html

and tested the whole thing with

$ mix ecto.create
The database for Ee.Repo has been created.

I committed all the changes. The next step is to build a model. We’ll start with this as lib/ee/object.ex:

defmodule EE.Object do
  use Ecto.Schema

  schema "object" do
    field :title, :string
    field :description, :string

    # has_many :available_date_ranges, Project.AvailableDateRange, on_replace: :delete

    timestamps
  end
end

I’ve stripped this down slightly from the example I showed from my private project.

I’ve removed Project.Web since we are not using Phoenix. Instead we use Ecto.Schema.
I’ve removed logger.
I’ve removed belongs_to :user, User since we haven’t built a User model.
I’ve commented out the has_many relationship. We’ll add it back when we add AvailableDateRange.

Here’s the associated migration:

defmodule EE.Repo.Migrations.AddObject do
  use Ecto.Migration

  def change do
    create table(:object) do
      add :title, :string
      add :description, :string

      timestamps
    end
  end
end

and I can run it like this:

$ mix ecto.migrate

14:53:37.623 [info]  == Running Ee.Repo.Migrations.AddObject.change/0 forward

14:53:37.623 [info]  create table object

14:53:37.628 [info]  == Migrated in 0.0s

We now have a basic setup so I committed everything. And I added a git tag called experiment/setup to mark this point for later reference.

Experiment 2 - Tests

Next, let’s write a test and any additional required code to create an object and insert it into the database.

In the last experiment we configured the database for the dev environment. We’ll need to add a configuration for the test environment. We’ll also have to set things up so that we can maintain separate dev and test configs.

Mix generated support for this but commented out. In config/config.exs we have:

# It is also possible to import configuration files, relative to this
# directory. For example, you can emulate configuration per environment
# by uncommenting the line below and defining dev.exs, test.exs and such.
# Configuration from the imported file will override the ones defined
# here (which is why it is important to import them last).
#
#     import_config "#{Mix.env}.exs"

We’ll uncomment this import and move our existing config to config/dev.exs:

# config/dev.exs
use Mix.Config

config :ee, EE.Repo,
  adapter: Ecto.Adapters.Postgres,
  database: "ecto_experiments",
  username: "postgres",
  password: "postgres"

Then we create a new file config/test.exs:

# config/test.exs
use Mix.Config

config :ee, EE.Repo,
  adapter: Ecto.Adapters.Postgres,
  database: "ecto_experiments_test",
  username: "postgres",
  password: "postgres",
  pool: Ecto.Adapters.SQL.Sandbox

The difference between the dev and test configs are:

database: We have separate databases for each config.
pool: For test we use Ecto.Adapters.SQL.Sandbox. This uses a special Sandbox pool that allows us to use test transactions.

For Ecto testing we want to run each test in its own database transaction. We can do this by adding the following to test/test_helper.exs:

Mix.Task.run "ecto.create", ["--quiet"]
Mix.Task.run "ecto.migrate", ["--quiet"]
Ecto.Adapters.SQL.begin_test_transaction(Ee.Repo)

At this point the initial test runs which means our config is good:

$ mix test

14:58:37.285 [debug] BEGIN [] OK query=0.3ms

14:58:37.286 [debug] SAVEPOINT ecto_sandbox [] OK query=0.3ms
.

Finished in 0.1 seconds (0.1s on load, 0.00s on tests)
1 test, 0 failures

Randomized with seed 323271

Now that we have Ecto setup for our tests we can write a real test.

test "we can create and insert object records" do
  Ee.Repo.insert! %Ee.Object{
    title: "Test Object",
    description: "And object for the test"
  }
end

And this simple test passes.

I’ll commit and add a tag called experiment/simple_test.

Experiment 3 - Simple Query

In this experiment we’ll add a simple query and wrap it in a function. I’ll start by writing a test that defines the interface I want:

test "we can insert object records and query them back" do
  title = "Queryable title"

  object = Ee.Repo.insert! %Ee.Object{
    title: title,
    description: "And object for the test"
  }

  found = Ee.Object.find_by_title(title)
  |> Ee.Repo.all

  assert Enum.count(found) == 1
  assert List.first(found).id == object.id
end

This test

Inserts an object with a special title
Uses Ee.Object.find_by_title/1 to query the same object.
Asserts that it got the object it expected.

To make this test pass we just need to implement find_by_title/1. The query is simply:

def find_by_title(title) do
  from object in Ee.Object, where: object.title == ^title
end

We query from all Ee.Object records and select those where the title matches our specified title. With this implementation the test passes.

There are no surprises here but we’re building slowly toward our goal.

I’ll commit and add a tag experiment/simple_query.

Experiment 4 - DateTime Query

Let’s take another step toward our goal and introduce a DateTime field and query. We’ll continue to take things slow and will test out using a DateTime field in Object before trying an association.

To add the field we’ll need a new migration:

defmodule Ee.Repo.Migrations.AddDateTimeToObject do
  use Ecto.Migration

  def change do
    alter table(:object) do
      add :date, :datetime
    end
  end
end

and to update the Object struct:

--- a/lib/ee/object.ex
+++ b/lib/ee/object.ex
@@ -5,6 +5,7 @@ defmodule Ee.Object do
   schema "object" do
     field :title, :string
     field :description, :string
+    field :date, Ecto.DateTime

     # has_many :available_date_ranges, Project.AvailableDateRange, on_replace: :delete

With this let’s try inserting an object with a filled in date.

test "we can create and insert object records with the date field" do
  Ee.Repo.insert! %Ee.Object{
    title: "Test Object",
    description: "And object for the test",
    date: Ecto.DateTime.from_erl({ {2016, 1, 6}, {3, 59, 5}})
  }
end

And this test passes.

Now, let’s try to query the object by date. Here’s the test:

test "we can insert object records and query them back by date" do
  date = { {2016, 1, 6}, {8, 0, 0}}

  object = Ee.Repo.insert! %Ee.Object{
    title: "Test Object",
    description: "And object for the test",
    date: Ecto.DateTime.from_erl(date)
  }

  found = Ee.Object.find_by_date(date)
  |> Ee.Repo.all

  assert Enum.count(found) == 1
  assert List.first(found).id == object.id
end

And here’s a working implementation of find_by_date:

def find_by_date(date) do
  from object in Ee.Object, where: object.date == ^date
end

This test passes and the experiment is a success. I commit and add a tag experiment/date-query.

Experiment 4 - Timex Query

Now, I don’t actually want to use Ecto.DateTime to store dates. I want to use the timex and timex_ecto libraries for their improved handling of timezones.

Let’s start by setting up Timex in our application. I’ll follow the README.

First I’ll update mix.exs to include the timex and timex_ecto dependencies and start the tzdata app:

--- a/mix.exs
+++ b/mix.exs
@@ -14,7 +14,7 @@ defmodule Ee.Mixfile do
   #
   # Type "mix help compile.app" for more information
   def application do
-    [applications: [:logger, :postgrex, :ecto],
+    [applications: [:logger, :postgrex, :ecto, :tzdata, :timex],
      mod: {Ee, []}]
   end

@@ -31,6 +31,8 @@ defmodule Ee.Mixfile do
     [
       {:postgrex, ">= 0.0.0"},
       {:ecto, "~> 1.0"},
+      {:timex, "~> 1.0"},
+      {:timex_ecto, "~> 0.7"}
     ]
   end
 end

I want to use the Timex.Ecto.DateTimeWithTimezone type which is only supported with Postgres and requires some extra setup. We have to run some custom SQL which we can do in a migration like this:

defmodule Ee.Repo.Migrations.AddTimexDatetimetz do
  use Ecto.Migration

  def up do
    execute """
    CREATE TYPE datetimetz AS (
        dt timestamptz,
        tz varchar
    );
    """
  end

  def down do
    execute "DROP TYPE IF EXISTS datetimetz;"
  end
end

When bringing up this migration we execute custom SQL to create a new type called “datetimetz”. This SQL comes from the timex_ecto documentation.

Now that timex is setup we can add a field to Object. I’ve simply done this:

--- a/lib/ee/object.ex
+++ b/lib/ee/object.ex
@@ -6,6 +6,7 @@ defmodule Ee.Object do
     field :title, :string
     field :description, :string
     field :date, Ecto.DateTime
+    field :timex, Timex.Ecto.DateTimeWithTimezone

     # has_many :available_date_ranges, Project.AvailableDateRange, on_replace: :delete

I’ve named the field timex so that it is clear which kind of date field it is in these examples.

And of course to add this field we need another migration:

defmodule Ee.Repo.Migrations.AddTimexToObject do
  use Ecto.Migration

  def change do
    alter table(:object) do
      add :timex, :datetimetz
    end
  end
end

At this point my tests start to fail.

$ mix test

11:04:58.985 [debug] BEGIN [] OK query=0.2ms

11:04:58.985 [debug] SAVEPOINT ecto_sandbox [] OK query=0.2ms
.
11:04:59.063 [debug] INSERT INTO "object" ("inserted_at", "updated_at", "date", "description", "timex", "title") VALUES ($1, $2, $3, $4, $5, $6) RETURNING "id" [{ {2016, 1, 6}, {19, 4, 59, 0}}, { {2016, 1, 6}, {19, 4, 59, 0}}, { {2016, 1, 6}, {8, 0, 0, 0}}, "And object for the test", nil, "Test Object"] OK query=0.9ms

11:04:59.074 [debug] INSERT INTO "object" ("inserted_at", "updated_at", "date", "description", "timex", "title") VALUES ($1, $2, $3, $4, $5, $6) RETURNING "id" [{ {2016, 1, 6}, {19, 4, 59, 0}}, { {2016, 1, 6}, {19, 4, 59, 0}}, { {2016, 1, 6}, {3, 59, 5, 0}}, "And object for the test", nil, "Test Object"] OK query=5.0ms

11:04:59.076 [debug] INSERT INTO "object" ("inserted_at", "updated_at", "date", "description", "timex", "title") VALUES ($1, $2, $3, $4, $5, $6) RETURNING "id" [{ {2016, 1, 6}, {19, 4, 59, 0}}, { {2016, 1, 6}, {19, 4, 59, 0}}, nil, "And object for the test", nil, "Queryable title"] OK query=1.0ms


  1) test we can insert object records and query them back by date (EeTest)
     test/ee_test.exs:39
     ** (CaseClauseError) no case clause matching: {:ok, {:error, %ArgumentError{message: "no extension found for oid `131165`"}, [{Postgrex.Types, :fetch!, 2, [file: 'lib/postgrex/types.ex', line: 296]}, {Postgrex.Types, :decoder, 2, [file: 'lib/postgrex/types.ex', line: 220]}, {Enum, :"-map/2-lists^map/1-0-", 2, [file: 'lib/enum.ex', line: 1088]}, {Enum, :"-map/2-lists^map/1-0-", 2, [file: 'lib/enum.ex', line: 1088]}, {Postgrex.Protocol, :decoders, 2, [file: 'lib/postgrex/protocol.ex', line: 545]}, {Postgrex.Protocol, :describe_fields, 4, [file: 'lib/postgrex/protocol.ex', line: 368]}, {Postgrex.Protocol, :query, 4, [file: 'lib/postgrex/protocol.ex', line: 80]}, {Postgrex.Connection, :query, 6, [file: 'lib/postgrex/connection.ex', line: 315]}, {Postgrex.Connection, :query, 4, [file: 'lib/postgrex/connection.ex', line: 101]}, {Ecto.Adapters.Postgres.Connection, :query, 4, [file: 'lib/ecto/adapters/postgres/connection.ex', line: 31]}, {:timer, :tc, 3, [file: 'timer.erl', line: 197]}, {Ecto.Adapters.SQL, :query, 7, [file: 'lib/ecto/adapters/sql.ex', line: 262]}, {Ecto.Pool, :do_run, 4, [file: 'lib/ecto/pool.ex', line: 159]}, {Ecto.Adapters.SQL, :query, 6, [file: 'lib/ecto/adapters/sql.ex', line: 247]}, {Ecto.Adapters.SQL, :query, 5, [file: 'lib/ecto/adapters/sql.ex', line: 225]}, {Ecto.Adapters.SQL, :query!, 5, [file: 'lib/ecto/adapters/sql.ex', line: 183]}, {Ecto.Adapters.SQL, :execute, 6, [file: 'lib/ecto/adapters/sql.ex', line: 481]}, {Ecto.Repo.Queryable, :execute, 5, [file: 'lib/ecto/repo/queryable.ex', line: 95]}, {Ecto.Repo.Queryable, :all, 4, [file: 'lib/ecto/repo/queryable.ex', line: 15]}, {EeTest, :"test we can insert object records and query them back by date", 1, [file: 'test/ee_test.exs', line: 49]}]}, %{}, [], ""}
     stacktrace:
       (postgrex) lib/postgrex/protocol.ex:80: Postgrex.Protocol.query/4
       (postgrex) lib/postgrex/connection.ex:315: Postgrex.Connection.query/6
       (postgrex) lib/postgrex/connection.ex:101: Postgrex.Connection.query/4
       (ecto) lib/ecto/adapters/postgres/connection.ex:31: Ecto.Adapters.Postgres.Connection.query/4
       (stdlib) timer.erl:197: :timer.tc/3
       (ecto) lib/ecto/adapters/sql.ex:262: Ecto.Adapters.SQL.query/7
       (ecto) lib/ecto/pool.ex:159: Ecto.Pool.do_run/4
       (ecto) lib/ecto/adapters/sql.ex:247: Ecto.Adapters.SQL.query/6
       (ecto) lib/ecto/adapters/sql.ex:225: Ecto.Adapters.SQL.query/5
       (ecto) lib/ecto/adapters/sql.ex:183: Ecto.Adapters.SQL.query!/5
       (ecto) lib/ecto/adapters/sql.ex:481: Ecto.Adapters.SQL.execute/6
       (ecto) lib/ecto/repo/queryable.ex:95: Ecto.Repo.Queryable.execute/5
       (ecto) lib/ecto/repo/queryable.ex:15: Ecto.Repo.Queryable.all/4
       test/ee_test.exs:49

.

  2) test we can insert object records and query them back (EeTest)
     test/ee_test.exs:16
     ** (CaseClauseError) no case clause matching: {:ok, {:error, %ArgumentError{message: "no extension found for oid `131165`"}, [{Postgrex.Types, :fetch!, 2, [file: 'lib/postgrex/types.ex', line: 296]}, {Postgrex.Types, :decoder, 2, [file: 'lib/postgrex/types.ex', line: 220]}, {Enum, :"-map/2-lists^map/1-0-", 2, [file: 'lib/enum.ex', line: 1088]}, {Enum, :"-map/2-lists^map/1-0-", 2, [file: 'lib/enum.ex', line: 1088]}, {Postgrex.Protocol, :decoders, 2, [file: 'lib/postgrex/protocol.ex', line: 545]}, {Postgrex.Protocol, :describe_fields, 4, [file: 'lib/postgrex/protocol.ex', line: 368]}, {Postgrex.Protocol, :query, 4, [file: 'lib/postgrex/protocol.ex', line: 80]}, {Postgrex.Connection, :query, 6, [file: 'lib/postgrex/connection.ex', line: 315]}, {Postgrex.Connection, :query, 4, [file: 'lib/postgrex/connection.ex', line: 101]}, {Ecto.Adapters.Postgres.Connection, :query, 4, [file: 'lib/ecto/adapters/postgres/connection.ex', line: 31]}, {:timer, :tc, 3, [file: 'timer.erl', line: 197]}, {Ecto.Adapters.SQL, :query, 7, [file: 'lib/ecto/adapters/sql.ex', line: 262]}, {Ecto.Pool, :do_run, 4, [file: 'lib/ecto/pool.ex', line: 159]}, {Ecto.Adapters.SQL, :query, 6, [file: 'lib/ecto/adapters/sql.ex', line: 247]}, {Ecto.Adapters.SQL, :query, 5, [file: 'lib/ecto/adapters/sql.ex', line: 225]}, {Ecto.Adapters.SQL, :query!, 5, [file: 'lib/ecto/adapters/sql.ex', line: 183]}, {Ecto.Adapters.SQL, :execute, 6, [file: 'lib/ecto/adapters/sql.ex', line: 481]}, {Ecto.Repo.Queryable, :execute, 5, [file: 'lib/ecto/repo/queryable.ex', line: 95]}, {Ecto.Repo.Queryable, :all, 4, [file: 'lib/ecto/repo/queryable.ex', line: 15]}, {EeTest, :"test we can insert object records and query them back", 1, [file: 'test/ee_test.exs', line: 25]}]}, %{}, [], ""}
     stacktrace:
       (postgrex) lib/postgrex/protocol.ex:80: Postgrex.Protocol.query/4
       (postgrex) lib/postgrex/connection.ex:315: Postgrex.Connection.query/6
       (postgrex) lib/postgrex/connection.ex:101: Postgrex.Connection.query/4
       (ecto) lib/ecto/adapters/postgres/connection.ex:31: Ecto.Adapters.Postgres.Connection.query/4
       (stdlib) timer.erl:197: :timer.tc/3
       (ecto) lib/ecto/adapters/sql.ex:262: Ecto.Adapters.SQL.query/7
       (ecto) lib/ecto/pool.ex:159: Ecto.Pool.do_run/4
       (ecto) lib/ecto/adapters/sql.ex:247: Ecto.Adapters.SQL.query/6
       (ecto) lib/ecto/adapters/sql.ex:225: Ecto.Adapters.SQL.query/5
       (ecto) lib/ecto/adapters/sql.ex:183: Ecto.Adapters.SQL.query!/5
       (ecto) lib/ecto/adapters/sql.ex:481: Ecto.Adapters.SQL.execute/6
       (ecto) lib/ecto/repo/queryable.ex:95: Ecto.Repo.Queryable.execute/5
       (ecto) lib/ecto/repo/queryable.ex:15: Ecto.Repo.Queryable.all/4
       test/ee_test.exs:25



  3) test we can create and insert object records (EeTest)
     test/ee_test.exs:9
     ** (ArgumentError) repo Ee.Repo is not started, please ensure it is part of your supervision tree
     stacktrace:
       (ecto) lib/ecto/adapters/sql.ex:253: Ecto.Adapters.SQL.query/6
       (ecto) lib/ecto/adapters/sql.ex:225: Ecto.Adapters.SQL.query/5
       (ecto) lib/ecto/adapters/sql.ex:487: Ecto.Adapters.SQL.model/6
       (ecto) lib/ecto/repo/schema.ex:297: Ecto.Repo.Schema.apply/5
       (ecto) lib/ecto/repo/schema.ex:81: anonymous fn/11 in Ecto.Repo.Schema.do_insert/4
       (ecto) lib/ecto/repo/schema.ex:14: Ecto.Repo.Schema.insert!/4
       test/ee_test.exs:10



Finished in 0.5 seconds (0.4s on load, 0.02s on tests)
5 tests, 3 failures

Randomized with seed 53554

And they fail intermittently. Actually, I discovered that they fail the first time I run them and then they don’t fail again until I drop the database with:

$ MIX_ENV=test mix ecto.drop

I can make my results more consistent by making this change to the test helper:

--- a/test/test_helper.exs
+++ b/test/test_helper.exs
@@ -1,5 +1,6 @@
 ExUnit.start()

+Mix.Task.run "ecto.drop", ["--quiet"]
 Mix.Task.run "ecto.create", ["--quiet"]
 Mix.Task.run "ecto.migrate", ["--quiet"]
 Ecto.Adapters.SQL.begin_test_transaction(Ee.Repo)

This gives me a failure every time I run the tests but the number of failures varies. To try to understand what’s going wrong I comment out all of the tests except the initial test:

test "the truth" do
  assert 1 + 1 == 2
end

This passes every time I run it. Continuing with baby steps, I uncomment this test:

test "we can create and insert object records" do

The two uncommented tests pass every time I run them. Next, I uncomment another insertion test:

test "we can create and insert object records with the date field" do

The three tests pass every time I run them. Next, I uncomment the first query test:

test "we can insert object records and query them back" do

And this fails. So there is some problem with query?

Experiment 5 - Query Tests

To isolate the problem, I comment out all the tests except “we can insert object records and query them back” and this single test fails every time I run it:

$ mix test

11:13:18.923 [debug] BEGIN [] OK query=0.2ms

11:13:18.924 [debug] SAVEPOINT ecto_sandbox [] OK query=0.4ms

11:13:18.984 [debug] INSERT INTO "object" ("inserted_at", "updated_at", "date", "description", "timex", "title") VALUES ($1, $2, $3, $4, $5, $6) RETURNING "id" [{ {2016, 1, 6}, {19, 13, 18, 0}}, { {2016, 1, 6}, {19, 13, 18, 0}}, nil, "And object for the test", nil, "Queryable title"] OK query=0.9ms


  1) test we can insert object records and query them back (EeTest)
     test/ee_test.exs:16
     ** (CaseClauseError) no case clause matching: {:ok, {:error, %ArgumentError{message: "no extension found for oid `131645`"}, [{Postgrex.Types, :fetch!, 2, [file: 'lib/postgrex/types.ex', line: 296]}, {Postgrex.Types, :decoder, 2, [file: 'lib/postgrex/types.ex', line: 220]}, {Enum, :"-map/2-lists^map/1-0-", 2, [file: 'lib/enum.ex', line: 1088]}, {Enum, :"-map/2-lists^map/1-0-", 2, [file: 'lib/enum.ex', line: 1088]}, {Postgrex.Protocol, :decoders, 2, [file: 'lib/postgrex/protocol.ex', line: 545]}, {Postgrex.Protocol, :describe_fields, 4, [file: 'lib/postgrex/protocol.ex', line: 368]}, {Postgrex.Protocol, :query, 4, [file: 'lib/postgrex/protocol.ex', line: 80]}, {Postgrex.Connection, :query, 6, [file: 'lib/postgrex/connection.ex', line: 315]}, {Postgrex.Connection, :query, 4, [file: 'lib/postgrex/connection.ex', line: 101]}, {Ecto.Adapters.Postgres.Connection, :query, 4, [file: 'lib/ecto/adapters/postgres/connection.ex', line: 31]}, {:timer, :tc, 3, [file: 'timer.erl', line: 197]}, {Ecto.Adapters.SQL, :query, 7, [file: 'lib/ecto/adapters/sql.ex', line: 262]}, {Ecto.Pool, :do_run, 4, [file: 'lib/ecto/pool.ex', line: 159]}, {Ecto.Adapters.SQL, :query, 6, [file: 'lib/ecto/adapters/sql.ex', line: 247]}, {Ecto.Adapters.SQL, :query, 5, [file: 'lib/ecto/adapters/sql.ex', line: 225]}, {Ecto.Adapters.SQL, :query!, 5, [file: 'lib/ecto/adapters/sql.ex', line: 183]}, {Ecto.Adapters.SQL, :execute, 6, [file: 'lib/ecto/adapters/sql.ex', line: 481]}, {Ecto.Repo.Queryable, :execute, 5, [file: 'lib/ecto/repo/queryable.ex', line: 95]}, {Ecto.Repo.Queryable, :all, 4, [file: 'lib/ecto/repo/queryable.ex', line: 15]}, {EeTest, :"test we can insert object records and query them back", 1, [file: 'test/ee_test.exs', line: 25]}]}, %{}, [], ""}
     stacktrace:
       (postgrex) lib/postgrex/protocol.ex:80: Postgrex.Protocol.query/4
       (postgrex) lib/postgrex/connection.ex:315: Postgrex.Connection.query/6
       (postgrex) lib/postgrex/connection.ex:101: Postgrex.Connection.query/4
       (ecto) lib/ecto/adapters/postgres/connection.ex:31: Ecto.Adapters.Postgres.Connection.query/4
       (stdlib) timer.erl:197: :timer.tc/3
       (ecto) lib/ecto/adapters/sql.ex:262: Ecto.Adapters.SQL.query/7
       (ecto) lib/ecto/pool.ex:159: Ecto.Pool.do_run/4
       (ecto) lib/ecto/adapters/sql.ex:247: Ecto.Adapters.SQL.query/6
       (ecto) lib/ecto/adapters/sql.ex:225: Ecto.Adapters.SQL.query/5
       (ecto) lib/ecto/adapters/sql.ex:183: Ecto.Adapters.SQL.query!/5
       (ecto) lib/ecto/adapters/sql.ex:481: Ecto.Adapters.SQL.execute/6
       (ecto) lib/ecto/repo/queryable.ex:95: Ecto.Repo.Queryable.execute/5
       (ecto) lib/ecto/repo/queryable.ex:15: Ecto.Repo.Queryable.all/4
       test/ee_test.exs:25

What does this error mean? It sounds like some extension isn’t enabled in the database but which extension?

Debugging this head on hasn’t been fruitful. The oid 131645 doesn’t seem to have a specific meaning that I can find. It even seems to change every time I run the tests.

I’m going to try a less direct approach. First, I remove the mix ecto.drop call that I added to test_helper. Then I run the test again and see it pass. This suggests that there is some data being carried over in the database that is making the test pass! I should be able to look in the database to find it.

I”m using PG Commander to look at the database.

There are no objects left in the object table.
There is a datetimetz user defined type.

I’m sort of thinking that the datetimetz type isn’t getting setup when the tests are running.

Experiment 6 - Run commands from the shell

At this point we’re into real investigation and it’s time to get a little more scientific about these experiments. Based on my thoughts above, I have a hypothesis: Something isn’t working right with the Mix.Task.run calls. Perhaps they don’t finish by the time the test starts.

Based on this hypothesis I ran the following experiment.

First, I commented out all the Mix.Task calls from the test helper:

--- a/test/test_helper.exs
+++ b/test/test_helper.exs
@@ -1,6 +1,6 @@
 ExUnit.start()

-Mix.Task.run "ecto.drop", ["--quiet"]
-Mix.Task.run "ecto.create", ["--quiet"]
-Mix.Task.run "ecto.migrate", ["--quiet"]
+# Mix.Task.run "ecto.drop", ["--quiet"]
+# Mix.Task.run "ecto.create", ["--quiet"]
+# Mix.Task.run "ecto.migrate", ["--quiet"]
 Ecto.Adapters.SQL.begin_test_transaction(Ee.Repo)

Second, I ran this sequence of shell commands

$ mix ecto.drop --quiet ; mix ecto.create --quiet ; mix ecto.migrate --quiet ; mix test

This sequence of commands passes consistently. So I think this points to some problem with the commands running properly.

Next steps

Unfortunately, this post is getting a little too long so I am going to have to stop here and continue this investigation in a second post.

In this post we reviewed setting up Ecto and then worked through a system of experiments in order to driver and investigation of a problem that I’m having in another project. I hope you enjoyed exploring this system of problem isolation with me.

Next week I’ll continue in this line of investigation and will pick up where we just left off.

Joseph Kain