Ecto: Telemetry issue upgrading to ecto 3.0

[pyladune]

Environment

• Elixir version1.7.2
• Database and version (PostgreSQL 9.4, MongoDB 3.2, etc.): Postgres 9.6.4
• Ecto version (mix deps): 3.0.1
• Database adapter and version (mix deps): postgres 0.14
• Operating system: Fedora 29 / Debian stable

Current behavior

Moving from 2.2.8 to 3.0.1 generates issue when running below code. Strangely Migrating using mix runs well.

21:29:18.707 [error] an exception was raised logging %DBConnection.LogEntry{call: :prepare_execute, connection_time: 567898, decode_time: 3228640, params: [], pool_time: 94505565, query: %Postgrex.Query{cache: :reference, columns: nil, name: "", param_formats: nil, param_oids: nil, param_types: nil, ref: nil, result_formats: nil, result_oids: nil, result_types: nil, statement: ["CREATE TABLE ", "IF NOT EXISTS ", [34, "schema_migrations", 34], 32, 40, [[[], [[34, "version", 34], 32, "bigint", [[], []]], ", "], [34, "inserted_at", 34], 32, ["timestamp", "(0)"], [[], []]], [", ", "PRIMARY KEY (", [[], 34, "version", 34], ")"], 41, []], types: nil}, result: {:ok, %Postgrex.Query{cache: :reference, columns: nil, name: "", param_formats: [], param_oids: [], param_types: [], ref: #Reference<0.2217321960.3306160131.116157>, result_formats: [], result_oids: nil, result_types: nil, statement: ["CREATE TABLE ", "IF NOT EXISTS ", [34, "schema_migrations", 34], 32, 40, [[[], [[34, "version", 34], 32, "bigint", [[], []]], ", "], [34, "inserted_at", 34], 32, ["timestamp", "(0)"], [[], []]], [", ", "PRIMARY KEY (", [[], 34, "version", 34], ")"], 41, []], types: {Inilab.PostgresTypes, #Reference<0.2217321960.3306291202.135624>}}, %Postgrex.Result{columns: nil, command: :create_table, connection_id: 32246, messages: [%{code: "42P07", file: "parse_utilcmd.c", line: "193", message: "relation \"schema_migrations\" already exists, skipping", routine: "transformCreateStmt", severity: "NOTICE", unknown: "NOTICE"}], num_rows: 0, rows: nil}}}: ** (ArgumentError) argument error
(stdlib) :ets.lookup(Telemetry.HandlerTable, [:inilab, :repo, :query])
lib/telemetry/handler_table.ex:59: Telemetry.HandlerTable.list_for_event/1
lib/telemetry.ex:76: Telemetry.execute/3
lib/ecto/adapters/sql.ex:756: Ecto.Adapters.SQL.log/4
(db_connection) lib/db_connection.ex:1303: DBConnection.log/5
(postgrex) lib/postgrex.ex:188: Postgrex.query_prepare_execute/4
lib/ecto/adapters/sql.ex:288: Ecto.Adapters.SQL.query!/4
(elixir) lib/enum.ex:1314: Enum."-map/2-lists^map/1-0-"/2
lib/ecto/adapters/sql.ex:677: Ecto.Adapters.SQL.execute_ddl/4
lib/ecto/migrator.ex:470: Ecto.Migrator.verbose_schema_migration/3
lib/ecto/migrator.ex:254: Ecto.Migrator.run/4
(inilab) lib/mix/tasks/migrate.ex:11: Mix.Tasks.Migrate.run/1
(mix) lib/mix/task.ex:316: Mix.Task.run_task/3
(mix) lib/mix/cli.ex:79: Mix.CLI.run_task/2
(elixir) src/elixir_compiler.erl:71: :elixir_compiler.dispatch/4
(elixir) src/elixir_compiler.erl:68: :elixir_compiler.compile/3
(elixir) src/elixir_lexical.erl:17: :elixir_lexical.run/2
(elixir) src/elixir_compiler.erl:23: :elixir_compiler.quo

Expected behavior

Migration passes

[josevalim]

You need to add :ecto_sql as an application in the :applications list
inside your mix.exs file. Otherwise ecto_sql wont start which means

telemetry won’t run either.

José Valim
www.plataformatec.com.br
Skype: jv.ptec
Founder and Director of R&D

[pyladune]

yep, i tried that already but it did not solved the case

  def application do
    [mod: {Inilab.Application, []}, extra_applications: [:logger, :appsignal, :ecto_sql ]]
  end

[josevalim]

Can you please provide an applications that reproduces the error then? The

above is definitely supposed to work.

José Valimwww.plataformatec.com.br
http://www.plataformatec.com.br/Founder and Director of R&D

[josevalim]

In any case, I would double check if ecto_sql is really started. If you
look at your stacktrace, you can see that it is not showing the ecto_sql
application. We have this:

lib/ecto/adapters/sql.ex:288: Ecto.Adapters.SQL.query!/4

But it should be the following if ecto_sql was running:

> (ecto_sql) lib/ecto/adapters/sql.ex:288: Ecto.Adapters.SQL.query!/4

José Valimwww.plataformatec.com.br
http://www.plataformatec.com.br/Founder and Director of R&D

[pyladune]

Checked all, currently no idea why ecto_sql does not load but will investigate

[pyladune]

Found why ecto_sql did not load: seems it has to be referenced inside included_applications instead of extra_applications. However despite started, it still fails :-(

09:02:01.240 [error] an exception was raised logging %DBConnection.LogEntry{call: :prepare_execute, connection_time: 256429, decode_time: 2581140, params: [], pool_time: 53166816, query: %Postgrex.Query{cache: :reference, columns: nil, name: "", param_formats: nil, param_oids: nil, param_types: nil, ref: nil, result_formats: nil, result_oids: nil, result_types: nil, statement: ["CREATE TABLE ", "IF NOT EXISTS ", [34, "schema_migrations", 34], 32, 40, [[[], [[34, "version", 34], 32, "bigint", [[], []]], ", "], [34, "inserted_at", 34], 32, ["timestamp", "(0)"], [[], []]], [", ", "PRIMARY KEY (", [[], 34, "version", 34], ")"], 41, []], types: nil}, result: {:ok, %Postgrex.Query{cache: :reference, columns: nil, name: "", param_formats: [], param_oids: [], param_types: [], ref: #Reference<0.1410010727.3950247937.39370>, result_formats: [], result_oids: nil, result_types: nil, statement: ["CREATE TABLE ", "IF NOT EXISTS ", [34, "schema_migrations", 34], 32, 40, [[[], [[34, "version", 34], 32, "bigint", [[], []]], ", "], [34, "inserted_at", 34], 32, ["timestamp", "(0)"], [[], []]], [", ", "PRIMARY KEY (", [[], 34, "version", 34], ")"], 41, []], types: {Inilab.PostgresTypes, #Reference<0.1410010727.3950379010.23906>}}, %Postgrex.Result{columns: nil, command: :create_table, connection_id: 16571, messages: [%{code: "42P07", file: "parse_utilcmd.c", line: "193", message: "relation \"schema_migrations\" already exists, skipping", routine: "transformCreateStmt", severity: "NOTICE", unknown: "NOTICE"}], num_rows: 0, rows: nil}}}: ** (ArgumentError) argument error
    (stdlib) :ets.lookup(Telemetry.HandlerTable, [:inilab, :repo, :query])
    lib/telemetry/handler_table.ex:59: Telemetry.HandlerTable.list_for_event/1
    lib/telemetry.ex:76: Telemetry.execute/3
    (ecto_sql) lib/ecto/adapters/sql.ex:756: Ecto.Adapters.SQL.log/4
    (db_connection) lib/db_connection.ex:1303: DBConnection.log/5
    (postgrex) lib/postgrex.ex:188: Postgrex.query_prepare_execute/4
    (ecto_sql) lib/ecto/adapters/sql.ex:288: Ecto.Adapters.SQL.query!/4
    (elixir) lib/enum.ex:1314: Enum."-map/2-lists^map/1-0-"/2
    (ecto_sql) lib/ecto/adapters/sql.ex:677: Ecto.Adapters.SQL.execute_ddl/4
    (ecto_sql) lib/ecto/migrator.ex:470: Ecto.Migrator.verbose_schema_migration/3
    (ecto_sql) lib/ecto/migrator.ex:254: Ecto.Migrator.run/4
    (inilab) lib/mix/tasks/migrate.ex:11: Mix.Tasks.Migrate.run/1
    (mix) lib/mix/task.ex:316: Mix.Task.run_task/3
    (mix) lib/mix/cli.ex:79: Mix.CLI.run_task/2
    (elixir) src/elixir_compiler.erl:71: :elixir_compiler.dispatch/4
    (elixir) src/elixir_compiler.erl:68: :elixir_compiler.compile/3
    (elixir) src/elixir_lexical.erl:17: :elixir_lexical.run/2
    (elixir) src/elixir_compiler.erl:23: :elixir_compiler.quoted/2
    (elixir) lib/code.ex:767: Code.require_file/2
    (elixir) lib/kernel/cli.ex:503: Kernel.CLI.wrapper/1

[josevalim]

ecto_sql should not be inside included_applications. Without a way to

reproduce the issue, I am afraid there isn’t much we can do help though. :(

José Valimwww.plataformatec.com.br
http://www.plataformatec.com.br/Founder and Director of R&D

[pyladune]

fixed by adding simply {:ok, _} = Application.ensure_all_started(:ecto_sql)
Thanks a lot for your inputs

[noircir]

@pyladune : where did you insert {:ok, _} = Application.ensure_all_started(:ecto_sql) ?
I have an identical logging error, though {:ecto_sql, "~> 3.0-rc.1"}is added and the app runs OK otherwise.

[pyladune]

@noircir
defmodule Inilab.Release.Tasks do
# Called with ./bin/inilab command Elixir.Release.Tasks migrate
def migrate do
{:ok, _} = Application.ensure_all_started(:ecto)
{:ok, _} = Application.ensure_all_started(:postgrex)
{:ok, _} = Application.ensure_all_started(:ecto_sql)
Application.load(:inilab)
Inilab.Repo.start_link()

path = Application.app_dir(:inilab, "priv/repo/migrations")
Ecto.Migrator.run(Inilab.Repo, path, :up, all: true)

:init.stop()

end