Protocol.UndefinedError

[maxsalven]

ecto_dev_logger is occasionally crashing. The Stripe.Subscription struct is one from https://github.com/beam-community/stripity-stripe.

[error] graphql_operation=CreateStripeSubscription Handler [:ecto_dev_logger, :wod_up, :repo] has failed and has been detached. Class=:error
Reason=%Protocol.UndefinedError{
  protocol: Ecto.DevLogger.PrintableParameter,
  value: %Stripe.Subscription{
    id: "sub_REDACTED",
    object: "subscription",
    ...
  },
  description: ""
}
Stacktrace=[
  {Ecto.DevLogger.PrintableParameter, :impl_for!, 1,
   [file: ~c"lib/ecto/dev_logger/printable_parameter.ex", line: 1]},
  {Ecto.DevLogger.PrintableParameter, :to_expression, 1,
   [file: ~c"lib/ecto/dev_logger/printable_parameter.ex", line: 31]},
  {Ecto.DevLogger, :"-inline_params/4-fun-1-", 3,
   [file: ~c"lib/ecto/dev_logger.ex", line: 121]},
  {Regex, :apply_list, 5, [file: ~c"lib/regex.ex", line: 757]},
  {Regex, :apply_list, 5, [file: ~c"lib/regex.ex", line: 752]},
  {Regex, :replace, 4, [file: ~c"lib/regex.ex", line: 687]},
  {Ecto.DevLogger, :"-telemetry_handler/4-fun-0-", 6,
   [file: ~c"lib/ecto/dev_logger.ex", line: 94]},
  {Logger, :__do_log__, 4, [file: ~c"lib/logger.ex", line: 881]},
  {:telemetry, :"-execute/3-fun-0-", 4,
   [
     file: ~c"/Volumes/Development/github/wodup-api/deps/telemetry/src/telemetry.erl",
     line: 160
   ]},
  {:lists, :foreach_1, 2, [file: ~c"lists.erl", line: 1686]},
  {Ecto.Adapters.SQL, :log, 4, [file: ~c"lib/ecto/adapters/sql.ex", line: 1079]},
  {DBConnection, :log, 5, [file: ~c"lib/db_connection.ex", line: 1578]},
  {Postgrex, :query, 4, [file: ~c"lib/postgrex.ex", line: 340]},
  {Ecto.Adapters.SQL, :struct, 10,
   [file: ~c"lib/ecto/adapters/sql.ex", line: 955]},
  {Ecto.Repo.Schema, :apply, 4, [file: ~c"lib/ecto/repo/schema.ex", line: 764]},
  {Ecto.Repo.Schema, :"-do_insert/4-fun-3-", 15,
   [file: ~c"lib/ecto/repo/schema.ex", line: 377]},
  ...
]

[fuelen]

@maxsalven what version of ecto do you use?

[maxsalven]

ecto 3.10.3 ecto_sql 3.10.1

[fuelen]

:thinking: ecto should've converted this struct to JSON or something like that, as I understand. This error is possible if Stripe.Subscription is a custom type on a postgrex level. In this case custom implementation of the protocol is needed. But I assume this is not the case.. Could you provide steps to reproduce? it would be great to have an exs script

[maxsalven]

Mix.install(
  [
    {:ecto_sql, "~> 3.10"},
    {:postgrex, ">= 0.0.0"},
    {:jason, "~> 1.4"},
    {:ecto_dev_logger, "~> 0.9"}
  ],
  consolidate_protocols: false
)

Application.put_env(:example, Repo, database: "example", log: false)

defmodule Repo do
  use Ecto.Repo,
    adapter: Ecto.Adapters.Postgres,
    otp_app: :example
end

defmodule Migration0 do
  use Ecto.Migration

  def change do
    create table("posts") do
      add(:data, :jsonb)
    end
  end
end

defmodule Post do
  use Ecto.Schema

  schema "posts" do
    field(:data, :map)
  end
end

defmodule PostData do
  @derive Jason.Encoder
  defstruct foo: true
end

defmodule Main do
  import Ecto.Query, warn: false

  def main do
    children = [Repo]

    Ecto.DevLogger.install(Repo)

    _ = Repo.__adapter__().storage_down(Repo.config())
    :ok = Repo.__adapter__().storage_up(Repo.config())

    {:ok, _} = Supervisor.start_link(children, strategy: :one_for_one)

    Ecto.Migrator.run(Repo, [{0, Migration0}], :up, all: true, log_migrations_sql: :debug)

    Repo.insert!(%Post{data: %PostData{foo: true}})
  end
end

Main.main()

❯ elixir test.exs

15:05:50.090 [debug] QUERY OK db=0.1ms
begin

15:05:50.092 [info] == Running 0 Migration0.change/0 forward

15:05:50.092 [info] create table posts

15:05:50.095 [debug] QUERY OK db=2.1ms
CREATE TABLE "posts" ("id" bigserial, "data" jsonb, PRIMARY KEY ("id"))

15:05:50.095 [debug] QUERY OK db=2.1ms
CREATE TABLE "posts" ("id" bigserial, "data" jsonb, PRIMARY KEY ("id")) []

15:05:50.096 [info] == Migrated 0 in 0.0s

15:05:50.109 [debug] QUERY OK db=0.5ms
commit

15:05:50.112 [error] Handler [:ecto_dev_logger, :repo] has failed and has been detached. Class=:error
Reason=%Protocol.UndefinedError{
  protocol: Ecto.DevLogger.PrintableParameter,
  value: %PostData{foo: true},
  description: ""
}
Stacktrace=[
  {Ecto.DevLogger.PrintableParameter, :impl_for!, 1,
   [file: ~c"lib/ecto/dev_logger/printable_parameter.ex", line: 1]},
  {Ecto.DevLogger.PrintableParameter, :to_expression, 1,
   [file: ~c"lib/ecto/dev_logger/printable_parameter.ex", line: 31]},
  {Ecto.DevLogger, :"-inline_params/4-fun-1-", 3,
   [file: ~c"lib/ecto/dev_logger.ex", line: 121]},
  {Regex, :apply_list, 5, [file: ~c"lib/regex.ex", line: 757]},
  {Regex, :apply_list, 5, [file: ~c"lib/regex.ex", line: 752]},
  {Regex, :replace, 4, [file: ~c"lib/regex.ex", line: 687]},
  {Ecto.DevLogger, :"-telemetry_handler/4-fun-0-", 6,
   [file: ~c"lib/ecto/dev_logger.ex", line: 94]},
  {Logger, :__do_log__, 4, [file: ~c"lib/logger.ex", line: 881]}
]

If I remove log: false

❯ elixir test.exs

15:06:06.900 [info] == Running 0 Migration0.change/0 forward

15:06:06.901 [info] create table posts

15:06:06.905 [debug] QUERY OK db=2.6ms
CREATE TABLE "posts" ("id" bigserial, "data" jsonb, PRIMARY KEY ("id")) []

15:06:06.906 [info] == Migrated 0 in 0.0s

15:06:06.921 [debug] QUERY OK db=1.3ms queue=0.3ms idle=30.8ms
INSERT INTO "posts" ("data") VALUES ($1) RETURNING "id" [%PostData{foo: true}]

[fuelen]

I see, ecto keeps the data as is. I'd suggest having the following fix:

defimpl Ecto.DevLogger.PrintableParameter, for: PostData do
  def to_expression(struct), do: struct |> Map.from_struct() |> Ecto.DevLogger.PrintableParameter.to_expression()
  def to_string_literal(struct), do: struct |> Map.from_struct() |> Ecto.DevLogger.PrintableParameter.to_string_literal()
end

A proper way of fixing this would be to request more metadata in telemetry from ecto (extend ecto functionality), so it sends this data as well:

param_types: [Postgrex.Extensions.JSONB]

[maxsalven]

Thanks.

I use around 30 different structs that get saved as JSON in ecto schemas. Is there a way to batch define them all at once with your first method? It's also fairly brittle in that I need to remember to take that extra step each time I use a new one.

Alternatively, is there a way to prevent the dev logger from crashing completely? E.g. it would be nicer to print an error message (~"could not log this sql statement, see issue #26") and then continue logging vs detaching completely until the server is restarted.

[fuelen]

Is there a way to batch define them all at once with your first method?

the simplest one is to use for:

for module <- [PostData] do
  defimpl Ecto.DevLogger.PrintableParameter, for: module do
    def to_expression(struct),
      do: struct |> Map.from_struct() |> Ecto.DevLogger.PrintableParameter.to_expression()

    def to_string_literal(struct),
      do: struct |> Map.from_struct() |> Ecto.DevLogger.PrintableParameter.to_string_literal()
  end
end

Alternatively, is there a way to prevent the dev logger from crashing completely?

yes, this is doable

BTW, embedded schemas don't have this issue

[fuelen]

Here is a link to the discussion of related proposal to Ecto https://groups.google.com/g/elixir-ecto/c/5AwUoaEuq4E/m/J9Kbr9FOBAAJ TL;DR: Ecto can't provider more details, so we can only guess types. Use the solution mentioned above