Error after upgrading to Ecto 3.0.0-rc.0

[mtarnovan]

Hi,

I'm seeing this error when running tests after upgrading to Ecto 3.0.0-rc.0:

12:45:14.873 [error]  an exception was raised logging %DBConnection.LogEntry{call: :prepare_execute, connection_time: 1031000, decode_time: 5000, params: ["123", 1, ~N[2018-10-28 10:45:14], ~N[2018-10-28 10:45:14]], pool_time: 77000, query: %Postgrex.Query{cache: :statement, columns: nil, name: "ecto_insert_api_keys", param_formats: nil, param_oids: nil, param_types: nil, ref: nil, result_formats: nil, result_oids: nil, result_types: nil, statement: "INSERT INTO \"api_keys\" (\"key\",\"user_id\",\"created_at\",\"updated_at\") VALUES ($1,$2,$3,$4) RETURNING \"id\"", types: nil}, result: {:ok, %Postgrex.Query{cache: :statement, columns: ["id"], name: "ecto_insert_api_keys", param_formats: [:binary, :binary, :binary, :binary], param_oids: [1043, 23, 1114, 1114], param_types: [Postgrex.Extensions.Raw, Postgrex.Extensions.Int4, Postgrex.Extensions.Timestamp, Postgrex.Extensions.Timestamp], ref: #Reference<0.596339587.3623092225.170903>, result_formats: [:binary], result_oids: [23], result_types: [Postgrex.Extensions.Int4], statement: "INSERT INTO \"api_keys\" (\"key\",\"user_id\",\"created_at\",\"updated_at\") VALUES ($1,$2,$3,$4) RETURNING \"id\"", types: {Postgrex.DefaultTypes, #Reference<0.596339587.3623223297.169392>}}, %Postgrex.Result{columns: ["id"], command: :insert, connection_id: 56733, messages: [], num_rows: 1, rows: [[1]]}}}: ** (ArgumentError) argument error
    (stdlib) :ets.lookup(Telemetry.HandlerTable, [:openapi_rest, :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:754: Ecto.Adapters.SQL.log/4
    (db_connection) lib/db_connection.ex:1303: DBConnection.log/5
    (postgrex) lib/postgrex.ex:167: Postgrex.query/4
    lib/ecto/adapters/sql.ex:627: Ecto.Adapters.SQL.struct/10
    (ecto) lib/ecto/repo/schema.ex:600: Ecto.Repo.Schema.apply/4
    (ecto) lib/ecto/repo/schema.ex:226: anonymous fn/15 in Ecto.Repo.Schema.do_insert/3
    (ecto) lib/ecto/repo/schema.ex:128: Ecto.Repo.Schema.insert!/3
    test/test_helper.exs:32: OpenapiRest.TestHelper.setup_conn/1
    test/controllers/company_controller_test.exs:2: OpenapiRest.CompanyControllerTest.__ex_unit__/2
    (ex_unit) lib/ex_unit/runner.ex:299: ExUnit.Runner.exec_test_setup/2
    (ex_unit) lib/ex_unit/runner.ex:246: anonymous fn/2 in ExUnit.Runner.spawn_test/3
    (stdlib) timer.erl:166: :timer.tc/1
    (ex_unit) lib/ex_unit/runner.ex:245: anonymous fn/4 in ExUnit.Runner.spawn_test/3

Seems to be originating from the new telemetry lib:

iex(1)> Telemetry.list_handlers [:openapi_rest, :repo, :query]
** (ArgumentError) argument error
    (stdlib) :ets.match_object(Telemetry.HandlerTable, {:_, [:openapi_rest, :repo, :query | :_], :_, :_, :_})
    lib/telemetry/handler_table.ex:68: Telemetry.HandlerTable.list_by_prefix/1

[josevalim]

Can you please paste your mix.exs file? I am assuming this is because you have a :applications list and you have listed :ecto_sql in there.

[mtarnovan]

I don't think I have. Here it is:

defmodule OpenapiRest.Mixfile do
  use Mix.Project

  defp umbrella_application do
    case Mix.Project.umbrella? do
      true -> [
        build_path: "../../_build",
        config_path: "../../config/config.exs",
        deps_path: "../../deps",
        lockfile: "../../mix.lock"
        ]
        _ -> []
    end
  end

  def project do
    [app: :openapi_rest,
     version: "0.0.1",
     elixir: "~> 1.0",
     elixirc_paths: elixirc_paths(Mix.env),
     compilers: [:phoenix, :gettext] ++ Mix.compilers,
     build_embedded: Mix.env == :prod,
     start_permanent: Mix.env == :prod,
     aliases: aliases(),
     deps: deps(),
     test_coverage: [tool: ExCoveralls],
     preferred_cli_env: ["coveralls": :test, "coveralls.detail": :test, "coveralls.post": :test, "coveralls.html": :test]
    ] ++ umbrella_application()
  end

  # Configuration for the OTP application.
  #
  # Type `mix help compile.app` for more information.
  def application do
    [mod: {OpenapiRest.Application, []},
     applications: [:phoenix, :phoenix_html, :cowboy, :logger, :gettext,
                    :phoenix_ecto, :postgrex, :exq, :timex,
                    :prometheus_ex, :prometheus_ecto, :prometheus_phoenix,
                    :prometheus_plugs, :prometheus_process_collector]]
  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
    [
      {:absinthe, "~> 1.4"},
      {:absinthe_ecto, "~> 0.1.3", override: true},
      {:absinthe_phoenix, "~> 1.4"},
      {:cors_plug, "~> 1.1"},
      {:cowboy, "~> 1.0"},
      {:credo, "~> 0.10.0", only: [:dev, :test], runtime: false},
      # {:ecto, "~> 2.1"},
      {:ecto_sql, "3.0.0-rc.0"},
      {:ecto, "3.0.0-rc.0", override: true},
      {:excoveralls, "~> 0.10", only: :test},
      {:exq, "~> 0.9.1"},
      {:redix, "~> 0.7.1"}, # needs to be locked at this version fo exq
      {:gettext, "~> 0.13.1"},
      {:jason, "~> 1.1"},
      {:kerosene, "~> 0.7.0"},
      {:oaex, git: "https://github.com/openapi-ro/oaex.git", tag: "v0.2.2"},
      {:phoenix_ecto, "~> 3.5"},
      {:phoenix_html, "~> 2.6"},
      {:phoenix_live_reload, "~> 1.0", only: :dev},
      {:phoenix_pubsub, "~> 1.0"},
      {:phoenix, "~> 1.3.3"},
      {:plug_require_header, "~> 0.8"},
      {:plug, "~> 1.3.0"},
      {:poison, "~> 2.0"},
      {:postgrex, "0.14.0-rc.1"},
      {:prometheus_ecto, "~> 1.0"},
      {:prometheus_ex, "~> 1.0"},
      {:prometheus_phoenix, "~> 1.0"},
      {:prometheus_plugs, "~> 1.0"},
      {:prometheus_process_collector, "~> 1.0"},
      {:remote_ip, "~> 0.1.0"},
      {:timex, "~> 3.1"},
      {:trailing_format_plug, "~> 0.0.7"},
      {:validators_ro, git: "https://github.com/mtarnovan/validators_ro.git"}
   ]
  end

  # Aliases are shortcut 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"]]
  end
end

[josevalim]

Right. You need to add :ecto_sql to the list but the easiest thing to do is to migrate to the :extra_applications mechanism that is part of Elixir v1.4+ --

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

[mtarnovan]

Thanks, José. Will do that.

[mtarnovan]

So basically it should look something like this, then?

  def application do
    [
      mod: {OpenapiRest.Application, []},
      extra_applications: [:logger, :runtime_tools]
    ]
  end

If I understood correctly, Elixir will pick up apps to be started from their OTP definition if available, so we don't need to list them manually anymore, but only add those than we want to start "manually" to extra_applications. Previously I was overriding this behaviour by providing an applications: list, which prevented Elixir to "autodetect" apps.

Anyway, after that change I have another error:

11:47:02.154 [error]  an exception was raised logging %DBConnection.LogEntry{call: :prepare_execute, connection_time: 28861000, decode_time: 3845000, params: [], pool_time: 12185000, 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: "TRUNCATE TABLE users RESTART IDENTITY CASCADE", types: nil}, result: {:ok, %Postgrex.Query{cache: :reference, columns: nil, name: "", param_formats: [], param_oids: [], param_types: [], ref: #Reference<0.1131348408.2763522049.255965>, result_formats: [], result_oids: nil, result_types: nil, statement: "TRUNCATE TABLE users RESTART IDENTITY CASCADE", types: {Postgrex.DefaultTypes, #Reference<0.1131348408.2763653121.254715>}}, %Postgrex.Result{columns: nil, command: :truncate_table, connection_id: 65179, messages: [%{code: "00000", file: "tablecmds.c", line: "1283", message: "truncate cascades to table \"subscription_requests\"", routine: "ExecuteTruncate", severity: "NOTICE", unknown: "NOTICE"}, %{code: "00000", file: "tablecmds.c", line: "1283", message: "truncate cascades to table \"quota_warn_logs\"", routine: "ExecuteTruncate", severity: "NOTICE", unknown: "NOTICE"}, %{code: "00000", file: "tablecmds.c", line: "1283", message: "truncate cascades to table \"api_keys\"", routine: "ExecuteTruncate", severity: "NOTICE", unknown: "NOTICE"}], num_rows: 0, rows: nil}}}: ** (UndefinedFunctionError) function Ecto.LogEntry.log/3 is undefined or private. Did you mean one of:

      * log/2

    (ecto) Ecto.LogEntry.log(%{caller_pid: #PID<0.811.0>, decode_time: 3845000, params: [], query: "TRUNCATE TABLE users RESTART IDENTITY CASCADE", query_time: 28861000, queue_time: 12185000, result: {:ok, %Postgrex.Result{columns: nil, command: :truncate_table, connection_id: 65179, messages: [%{code: "00000", file: "tablecmds.c", line: "1283", message: "truncate cascades to table \"subscription_requests\"", routine: "ExecuteTruncate", severity: "NOTICE", unknown: "NOTICE"}, %{code: "00000", file: "tablecmds.c", line: "1283", message: "truncate cascades to table \"quota_warn_logs\"", routine: "ExecuteTruncate", severity: "NOTICE", unknown: "NOTICE"}, %{code: "00000", file: "tablecmds.c", line: "1283", message: "truncate cascades to table \"api_keys\"", routine: "ExecuteTruncate", severity: "NOTICE", unknown: "NOTICE"}], num_rows: 0, rows: nil}}, source: nil}, :debug, [ansi_color: nil])
    (ecto_sql) lib/ecto/adapters/sql.ex:759: 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
    test/test_helper.exs:16: OpenapiRest.TestHelper.setup_conn/1
    test/controllers/jsonp_controller_test.exs:1: OpenapiRest.JSONPControllerTest.__ex_unit__/2
    (ex_unit) lib/ex_unit/runner.ex:299: ExUnit.Runner.exec_test_setup/2
    (ex_unit) lib/ex_unit/runner.ex:246: anonymous fn/2 in ExUnit.Runner.spawn_test/3
    (stdlib) timer.erl:166: :timer.tc/1

I've looked at the source for dbconnection and ecto, but I'm not sure what's going on.

Thanks.

[wojtekmach]

function Ecto.LogEntry.log/3 is undefined or private

this error is weird, could you rm -rf _build and re-run the app?

[wojtekmach]

Also, please make sure you're at the latest ecto RC.

[mtarnovan]

@wojtekmach Thanks, but that didn't help. (I did previously try mix deps.clean --all). I'm using the latest from hex (3.0.0-rc0). I'll try with master and 3.0.0-rc1

[wojtekmach]

Yeah, please make sure to mix deps.update ecto and mix deps.update ecto_sql.

[mtarnovan]

Thanks @wojtekmach. It works with both ecto and ecto_sql from master!