UnicodeConversionError

[Valian]

Hi @fuelen, thanks for a very useful library!

I encountered a bug that causes an exception when logging a query. This is what appears in the console.

[error]  Handler "ecto.dev_logger" has failed and has been detached. Class=:error
Reason=%UnicodeConversionError{
 encoded: "\e[38;5;31m'Q}vG",
 message: "invalid encoding starting at <<246, 229, 61, 115, 2, 108, 128, 33, 102, 144, 102, 55, 125, 237, 142, 40, 217, 225, 234, 79, 134, 83, 85, 94, 218, 15, 55, 38, 39>>"
}
Stacktrace=[
{List, :to_string, 1, [file: 'lib/list.ex', line: 997]},
{Ecto.DevLogger, :"-telemetry_handler/4-fun-0-", 4,
 [file: 'lib/ecto/dev_logger.ex', line: 54]},
{Enum, :"-reduce/3-lists^foldl/2-0-", 3, [file: 'lib/enum.ex', line: 2396]},
{Ecto.DevLogger, :telemetry_handler, 4,
 [file: 'lib/ecto/dev_logger.ex', line: 52]}
...
]

I added additional check to get params forwarded to telemetry_handler. Here they are:

measurements = [decode_time: 3368, idle_time: 1060439273, query_time: 13933908, queue_time: 3607902, total_time: 17545178]
metadata = [
  options: [], 
  params: [
    <<81, 125, 118, 71, 246, 229, 61, 115, 2, 108, 128, 33, 102, 144, 102, 55, 125, 237, 142, 40, 217, 225, 234, 79, 134, 83, 85, 94, 218, 15, 55, 38>>, 
    "session", 
    ~U[2022-04-19 08:53:55.503683Z]
  ], 
  query: "SELECT u1.\"id\", u1.\"email\", u1.\"first_name\", u1.\"last_name\", u1.\"hashed_password\", u1.\"confirmed_at\", u1.\"inserted_at\", u1.\"updated_at\" FROM \"users_tokens\" AS u0 INNER JOIN \"public\".\"users\" AS u1 ON u1.\"id\" = u0.\"user_id\" WHERE ((u0.\"token\" = $1) AND (u0.\"context\" = $2)) AND (u0.\"inserted_at\" > $3::timestamp + (-(60)::numeric * interval '1 day'))", 
  repo: MyApp.Repo, 
  result: {:ok, %Postgrex.Result{columns: ["id", "email", "first_name", "last_name", "hashed_password", "confirmed_at", "inserted_at", "updated_at"], command: :select, connection_id: 145, messages: [], num_rows: 1, rows: [[1, "jakubskalecki@test.test", "Jakub", "Skalecki", "$2b$12$.kvB0H60EvpkDQG3kAbIBOblbcnL7x9ObaGrF2t6eaXWVF5/nWqke", ~N[2022-03-31 09:43:15.157988], ~N[2022-03-31 09:43:15.158022], ~N[2022-03-31 09:43:15.158022]]]}}, 
  source: "users_tokens", 
  type: :ecto_sql_query
]

Do you have an idea why it happens? Currently, this makes it impossible to use the library for me.

[fuelen]

Hi @Valian What is the type of "token" column?

In order to print invalid strings, we may try to encode them to base64 and decode in SQL, so the logged snippet will look like

u0."token" = DECODE('9uU9cwJsgCFmkGY3fe2OKNnh6k+GU1Ve2g83Jic=', 'BASE64')

[Valian]

@fuelen it's :binary, and in PostgreSQL bytea. It's a standard token schema generated by mix phx.gen.auth, and token itself is generated by :crypto.strong_rand_bytes. Displaying it in base64 sounds like a good, copy-pastable idea.

[dougw-bc]

I have noticed the same issue with a Cloak encrypted :binary field

[fuelen]

I have a working draft, will publish a fix today later

[fuelen]

@dougw-bc @Valian fixed in v0.1.4

[Valian]

:heart: :green_heart: :yellow_heart: :orange_heart: