Looks broken for Ecto 3.0

[gen1321]

I'm having exceptions with Ecto 3.0 and phoenix 1.4

[error] an exception was raised logging %DBConnection.LogEntry{call: :execute, connection_time: 4374000, decode_time: 10000, params: [], pool_time: 27000, query: %Postgrex.Query{cache: :reference, columns: ["id", "redirect_to_url", "token", "user_uid", "deleted", "inserted_at", "updated_at"], name: "ecto_4548", param_formats: [], param_oids: [], param_types: [], ref: #Reference<0.801667392.3987996675.142681>, result_formats: [:binary, :binary, :binary, :binary, :binary, :binary, :binary], result_oids: [20, 1043, 1043, 1043, 16, 1114, 1114], result_types: [Postgrex.Extensions.Int8, Postgrex.Extensions.Raw, Postgrex.Extensions.Raw, Postgrex.Extensions.Raw, Postgrex.Extensions.Bool, Postgrex.Extensions.Timestamp, Postgrex.Extensions.Timestamp], statement: "SELECT s0.\"id\", s0.\"redirect_to_url\", s0.\"token\", s0.\"user_uid\", s0.\"deleted\", s0.\"inserted_at\", s0.\"updated_at\" FROM \"shortners\" AS s0 WHERE (s0.\"deleted\" = FALSE)", types: {Postgrex.DefaultTypes, #Reference<0.801667392.3988127747.140455>}}, result: {:ok, %Postgrex.Query{cache: :reference, columns: ["id", "redirect_to_url", "token", "user_uid", "deleted", "inserted_at", "updated_at"], name: "ecto_4548", param_formats: [], param_oids: [], param_types: [], ref: #Reference<0.801667392.3987996675.142681>, result_formats: [:binary, :binary, :binary, :binary, :binary, :binary, :binary], result_oids: [20, 1043, 1043, 1043, 16, 1114, 1114], result_types: [Postgrex.Extensions.Int8, Postgrex.Extensions.Raw, Postgrex.Extensions.Raw, Postgrex.Extensions.Raw, Postgrex.Extensions.Bool, Postgrex.Extensions.Timestamp, Postgrex.Extensions.Timestamp], statement: "SELECT s0.\"id\", s0.\"redirect_to_url\", s0.\"token\", s0.\"user_uid\", s0.\"deleted\", s0.\"inserted_at\", s0.\"updated_at\" FROM \"shortners\" AS s0 WHERE (s0.\"deleted\" = FALSE)", types: {Postgrex.DefaultTypes, #Reference<0.801667392.3988127747.140455>}}, %Postgrex.Result{columns: ["id", "redirect_to_url", "token", "user_uid", "deleted", "inserted_at", "updated_at"], command: :select, connection_id: 6283, messages: [], num_rows: 1, rows: [[1, "https://twitter.com/gen1321", "CP9VKx", "1321", false, ~N[2018-11-01 22:40:13.000000], ~N[2018-11-01 22:40:13.000000]]]}}}: ** (UndefinedFunctionError) function Ecto.LogEntry.log/1 is undefined or private
    (ecto) Ecto.LogEntry.log(%{caller_pid: #PID<0.676.0>, decode_time: 10000, params: [], query: "SELECT s0.\"id\", s0.\"redirect_to_url\", s0.\"token\", s0.\"user_uid\", s0.\"deleted\", s0.\"inserted_at\", s0.\"updated_at\" FROM \"shortners\" AS s0 WHERE (s0.\"deleted\" = FALSE)", query_time: 4374000, queue_time: 27000, result: {:ok, %Postgrex.Result{columns: ["id", "redirect_to_url", "token", "user_uid", "deleted", "inserted_at", "updated_at"], command: :select, connection_id: 6283, messages: [], num_rows: 1, rows: [[1, "https://twitter.com/gen1321", "CP9VKx", "1321", false, ~N[2018-11-01 22:40:13.000000], ~N[2018-11-01 22:40:13.000000]]]}}, source: "shortners"})
    (elixir) lib/enum.ex:1925: Enum."-reduce/3-lists^foldl/2-0-"/3
    (db_connection) lib/db_connection.ex:1303: DBConnection.log/5
    (ecto_sql) lib/ecto/adapters/postgres/connection.ex:80: Ecto.Adapters.Postgres.Connection.execute/4
    (ecto_sql) lib/ecto/adapters/sql.ex:541: Ecto.Adapters.SQL.execute!/4
    (ecto_sql) lib/ecto/adapters/sql.ex:523: Ecto.Adapters.SQL.execute/5
    (ecto) lib/ecto/repo/queryable.ex:147: Ecto.Repo.Queryable.execute/4
    (ecto) lib/ecto/repo/queryable.ex:18: Ecto.Repo.Queryable.all/3
    (shortcut) lib/shortcut_web/controllers/shortners_controller.ex:46: ShortcutWeb.ShortnersController.index/2
    (shortcut) lib/shortcut_web/controllers/shortners_controller.ex:1: ShortcutWeb.ShortnersController.action/2
    (shortcut) lib/shortcut_web/controllers/shortners_controller.ex:1: ShortcutWeb.ShortnersController.phoenix_controller_pipeline/2
    (shortcut) lib/shortcut_web/endpoint.ex:1: ShortcutWeb.Endpoint.instrument/4
    (phoenix) lib/phoenix/router.ex:275: Phoenix.Router.__call__/1
    (shortcut) lib/shortcut_web/endpoint.ex:1: ShortcutWeb.Endpoint.plug_builder_call/2
    (shortcut) lib/plug/debugger.ex:122: ShortcutWeb.Endpoint."call (overridable 3)"/2
    (shortcut) lib/shortcut_web/endpoint.ex:1: ShortcutWeb.Endpoint.call/2
    (phoenix) lib/phoenix/endpoint/cowboy2_handler.ex:34: Phoenix.Endpoint.Cowboy2Handler.init/2
    (cowboy) /app/deps/cowboy/src/cowboy_handler.erl:41: :cowboy_handler.execute/2
    (cowboy) /app/deps/cowboy/src/cowboy_stream_h.erl:293: :cowboy_stream_h.execute/3
    (cowboy) /app/deps/cowboy/src/cowboy_stream_h.erl:271: :cowboy_stream_h.request_process/3

[cschneid]

Thank you for the report - I'll take a look ASAP.

[gen1321]

Thanks @cschneid ! by the way this approach is depricated for ecto 3

config :your_app, YourApp.Repo,
  loggers: [{Ecto.LogEntry, :log, []},
            {ScoutApm.Instruments.EctoLogger, :log, []}]

I guess we should take a look at Telemetry and implement it :)

[cschneid]

From what I understand, Telemetry baked into the Phoenix stack isn't released yet? Is Ecto and its adapters ahead of the curve on that?

[gen1321]

Yes, it inside phoenix stack but it released standalone package https://hex.pm/packages/telemetry. You can check implementation from AppSignal on theirs Elixir Client. here is sample code

Telemetry.attach(
  "appsignal-ecto",
  [:my_app, :repo, :query],
  Appsignal.Ecto,
  :handle_event,
  nil
)

[cschneid]

@gen1321 - Thank you for the great report - I've handed this off to our elixir expert who will get Ecto 3 up and running.