Blog

Elixir: log de query SQL cortado

Elixir: log de query SQL cortado

En config.exs tenía configurado el logger así:

config :logger, :console,
  format:
    (System.get_env("EX_LOGGER_FORMAT") || "$date\T$time\Z [$level] $metadata$message") <>
      "\n",
  level: :debug,
  metadata: [:pid, :module],
  utc_log: true

Me daba una salida de SQL tal que así:

2023-09-13T15:54:35.390Z [debug] pid=<0.4255.0> module=Ecto.Adapters.SQL QUERY OK source="sources" db=2021.6ms idle=1884.3ms
SELECT s0."id", s1."id", s1."job_id", s1."type", s1."message", s1."inserted_at" FROM "sources" AS s0 INNER JOIN LATERAL (SELECT se0."id" AS "id", se0."job_id" AS "job_id", se0."type" AS "type", se0."message" AS "message", se0."inserted_at" AS "inserted_at" FROM "events" AS se0 INNER JOIN "jobs" AS sj1 ON se0."job_id" = sj1."id" WHERE (sj1."source_id" = s0."id") ORDER BY se0."id" DESC LIMIT $1) AS s1 ON TRUE WHERE (s0."id" = ANY($2)) [1, [168, 233, 195, 177, 225, 199, 152, 179, 213, 236, 174, 147, 178, 176, 188, 145, 196, 226, 202, 197, 144, 141, 235, 205, 194, 218, 215, 229, 181, 214, 187, 151, 201, 237, 234, 175, 220, 203, 139, 231, 185, 219, 130, 191, 190, 80, 159, 198, ...]]

Como se puede observar, la lista de parámetros está cortada con los puntos suspensivos. Intenté configurar Ecto.LogEntry pero descubrí que ya se había eliminado a partir de la  3.1.x. El código que realmente se está utilizando para el log es:

# deps/ecto_sql/lib/ecto/adapters/sql.ex
defmodule Ecto.Adapters.SQL do
 [...]
  defp log_iodata(measurements, repo, source, query, params, result, stacktrace) do
    [
      "QUERY",
      ?\s,
      log_ok_error(result),
      log_ok_source(source),
      log_time("db", measurements, :query_time, true),
      log_time("decode", measurements, :decode_time, false),
      log_time("queue", measurements, :queue_time, false),
      log_time("idle", measurements, :idle_time, true),
      ?\n,
      query,
      ?\s,
      inspect(params, charlists: false), # AQUÍ
      log_stacktrace(stacktrace, repo)
    ]
  end

Los parámetros se muestran con un inspect (Kernel.inspect, no IO.inspect). Para nuestra consola, podemos hacer:

IEx.configure(inspect: [limit: :infinity])

Sin embargo, esto no funcionaba para el código de mi proyecto compilado. Encontré la respuesta aquí:

previous_inspect = Inspect.Opts.default_inspect_fun()

Inspect.Opts.default_inspect_fun(fn term, opts ->
  previous_inspect.(term, %Inspect.Opts{opts | limit: :infinity})
end)

Puesto que arranco mi proyecto con iex -S mix phx.server, puse estas líneas y ya se me mostraba la query sin cortar:

2023-09-13T16:04:05.209Z [debug] pid=<0.1259.0> module=Ecto.Adapters.SQL QUERY OK source="sources" db=2080.6ms idle=36.0ms
SELECT s0."id", s1."id", s1."job_id", s1."type", s1."message", s1."inserted_at" FROM "sources" AS s0 INNER JOIN LATERAL (SELECT se0."id" AS "id", se0."job_id" AS "job_id", se0."type" AS "type", se0."message" AS "message", se0."inserted_at" AS "inserted_at" FROM "events" AS se0 INNER JOIN "jobs" AS sj1 ON se0."job_id" = sj1."id" WHERE (sj1."source_id" = s0."id") ORDER BY se0."id" DESC LIMIT $1) AS s1 ON TRUE WHERE (s0."id" = ANY($2)) [1, [153, 191, 188, 119, 214, 164, 213, 196, 231, 179, 197, 176, 162, 144, 159, 217, 202, 175, 131, 152, 235, 186, 201, 203, 234, 229, 178, 130, 219, 205, 226, 218, 199, 194, 225, 141, 177, 75, 182, 237, 236, 139, 174, 216, 168, 215, 151, 187, 124, 198, 190, 195, 220, 156, 181, 233, 185, 147, 228, 145, 80]]