diff --git a/README.md b/README.md index 9cf1b76..cebd655 100644 --- a/README.md +++ b/README.md @@ -1,10 +1,13 @@ # Ecto.DevLogger +[![Hex.pm](https://img.shields.io/hexpm/v/ecto_dev_logger.svg)](https://hex.pm/packages/ecto_dev_logger) +[![Hex.pm Downloads](https://img.shields.io/hexpm/dt/ecto_dev_logger)](https://hex.pm/packages/ecto_dev_logger) + An alternative logger for Ecto queries. It inlines bindings into the query, so it is easy to copy-paste logged SQL and run it in any IDE for debugging without -manual transformation of common elixir terms to string representation (binary UUID, DateTime, Decimal, json, etc). -Also, it highlights db time to make slow queries noticeable. Source table and inlined bindings are highlighted as well. +manual transformation of common Elixir terms to string representations (binary UUID, DateTime, Decimal, JSON, etc.). +It also highlights DB time to make slow queries noticeable. The source table and inlined bindings are highlighted as well. ![before and after](./assets/screenshot.png) @@ -16,24 +19,176 @@ The package can be installed by adding `ecto_dev_logger` to your list of depende ```elixir def deps do [ - {:ecto_dev_logger, "~> 0.1"} + {:ecto_dev_logger, "~> 0.15"} ] end ``` -Then disable default logger for your repo in config file for dev mode: +Then disable the default logger for your repo in the config file for development: ```elixir if config_env() == :dev do config :my_app, MyApp.Repo, log: false end ``` -And install telemetry handler in `MyApp.Application`: +Then install the telemetry handler in `MyApp.Application`: ```elixir Ecto.DevLogger.install(MyApp.Repo) ``` -Telemetry handler will be installed only if `log` configuration value is set to `false`. +The telemetry handler will be installed only if the repo `:log` configuration is set to `false`. That's it. The docs can be found at [https://hexdocs.pm/ecto_dev_logger](https://hexdocs.pm/ecto_dev_logger). +### Development Only Installation + +If you turn off repo logging for any reason in production, you can configure `ecto_dev_logger` to *only* be available +in development. In your `mix.exs`, restrict the installation to `:dev`: + +```elixir +def deps do + [ + {:ecto_dev_logger, "~> 0.10", only: :dev} + ] +end +``` + +In `MyApp.Application`, an additional function is required: + +```elixir +defmodule MyApp.Application do + @moduledoc "..." + + def start(_type, _args) do + maybe_install_ecto_dev_logger() + + # ... + end + + if Code.ensure_loaded?(Ecto.DevLogger) do + defp maybe_install_ecto_dev_logger, do: Ecto.DevLogger.install(MyApp.Repo) + else + defp maybe_install_ecto_dev_logger, do: :ok + end + + # ... +end +``` + +### Ignore logging for a single `Repo` call + +If you want to suppress logging for a specific query or Repo operation, pass `log: false` via `telemetry_options`: + +```elixir +# Examples +Repo.query!("CREATE EXTENSION IF NOT EXISTS postgis", [], telemetry_options: [log: false]) +Repo.insert!(changeset, telemetry_options: [log: false]) +Repo.get!(User, user_id, telemetry_options: [log: false]) +``` + +This prevents `Ecto.DevLogger` from emitting a log for that telemetry event while still executing the operation normally. + +### How it works and limitations + +Ecto.DevLogger inlines query parameters by converting Elixir values into SQL expressions. It does this by calling the `Ecto.DevLogger.PrintableParameter` protocol for each bound value, producing a copy‑pastable literal or expression. + +Because it only sees Elixir values (not the database column types), it must guess the target database type. The mapping from Elixir types to database types is not one‑to‑one, so the output may not always match your schema exactly: + +- **Maps**: assumed to be JSON. If you store maps in other column types (for example, `hstore` when using `postgrex`), the rendered SQL will still be JSON. +- **Lists**: assumed to be array‑like columns; you might instead be storing lists as JSON. +- **Scalars**: integers, floats, booleans, and strings are logged as plain values. + +If you use custom database or driver‑level types, implement `Ecto.DevLogger.PrintableParameter` for the structs that appear in parameters to control how values are rendered and keep the logged SQL runnable. +Note that `Ecto.DevLogger` operates below `Ecto.Type` casting; multiple different `Ecto.Type`s can map to the same driver type. The logger sees the post‑cast value (for example, a `Postgrex.*` struct), not your `Ecto.Type`. + +Keep in mind that the logged SQL is meant for debugging; it aims to be helpful, but you may still need to add manual casts to match your schema precisely. + +### Rendering examples + +Below are examples of how common Elixir values are rendered in logged SQL: + +| Elixir value | Rendered SQL | Notes | +| --- | --- | --- | +| `nil` | `NULL` | | +| `true` / `false` | `true` / `false` | | +| `"hello"` | `'hello'` | Strings are single-quoted | +| `<<1, 2, 3>>` | `DECODE('AQID','BASE64')` | Non‑UTF‑8 binaries use a base64 decode function | +| `123` | `123` | Integers are unquoted | +| `12.34` | `12.34` | Floats are unquoted | +| `Decimal.new("12.34")` | `12.34` | Decimals are unquoted | +| `~D[2023-01-02]` | `'2023-01-02'` | Dates are quoted strings | +| `~U[2023-01-02 03:04:05Z]` | `'2023-01-02 03:04:05Z'` | DateTimes are quoted strings | +| `~N[2023-01-02 03:04:05]` | `'2023-01-02 03:04:05'` | NaiveDateTimes are quoted strings | +| `~T[03:04:05]` | `'03:04:05'` | Times are quoted strings | +| `%{"a" => 1}` | `'{"a":1}'` | Maps are rendered as JSON strings | +| `["Elixir", "Ecto"]` | `'{Elixir,Ecto}'` | Array string literal when all elements are string‑renderable | +| `["Elixir", <<153>>]` | `ARRAY['Elixir', DECODE('mQ==','BASE64')]` | Falls back to `ARRAY[...]` if mixed | +| `{"Elixir", "Ecto"}` | `'(Elixir,Ecto)'` | Composite string literal when all elements are string‑renderable | +| `{"Elixir", <<153>>}` | `ROW('Elixir', DECODE('mQ==','BASE64'))` | Falls back to `ROW(...)` if mixed | +| `%Postgrex.INET{address: {127,0,0,1}, netmask: 24}` | `'127.0.0.1/24'` | IP/netmask rendered as text | +| `%Postgrex.MACADDR{address: {8,1,43,5,7,9}}` | `'08:01:2B:05:07:09'` | MAC address rendered as text | +| `%Postgrex.Interval{months: 1, days: 2, secs: 34}` | `'1 mon 2 days 34:00:00'` | Interval rendered via `Postgrex.Interval.to_string/1` | +| `%Postgrex.Range{lower: 1, upper: 10, lower_inclusive: true, upper_inclusive: false}` | `'[1,10)'` | Range bounds and brackets | +| `%Postgrex.Range{lower: :empty}` | `'empty'` | Empty range | +| `%Postgrex.Multirange{ranges: [...]}` | `'{[1,3),(10,15]}'` | Multirange of ranges | +| `[%Postgrex.Lexeme{}, ...]` | `'word1:pos weight ...'` | Lists of lexemes are rendered as tsvector strings | + +Notes: +- “String‑renderable” means `PrintableParameter.to_string_literal/1` returns a string for the element. Otherwise, `to_expression/1` is used. +- Unknown structs (without a `PrintableParameter` implementation) fall back to `inspect/1` and may not form valid SQL. + +### Geo rendering examples (optional) + +Below are examples when the `geo` library is available: + +| Geo value | Rendered SQL | +| --- | --- | +| `%Geo.Point{coordinates: {1.0, 2.0}, srid: 4326}` | `'SRID=4326;POINT(1.0 2.0)'` | +| `%Geo.PointZ{coordinates: {1.0, 2.0, 3.0}}` | `'POINT Z(1.0 2.0 3.0)'` | +| `%Geo.PointM{coordinates: {1.0, 2.0, 4.0}}` | `'POINT M(1.0 2.0 4.0)'` | +| `%Geo.PointZM{coordinates: {1.0, 2.0, 3.0, 4.0}}` | `'POINT ZM(1.0 2.0 3.0 4.0)'` | +| `%Geo.LineString{coordinates: [{0.0, 0.0}, {1.0, 1.0}]}` | `'LINESTRING(0.0 0.0,1.0 1.0)'` | +| `%Geo.LineStringZ{coordinates: [{0.0, 0.0, 0.0}, {1.0, 1.0, 1.0}]}` | `'LINESTRINGZ(0.0 0.0 0.0,1.0 1.0 1.0)'` | +| `%Geo.LineStringZM{coordinates: [{0.0, 0.0, 0.0, 5.0}, {1.0, 1.0, 1.0, 6.0}]}` | `'LINESTRINGZM(0.0 0.0 0.0 5.0,1.0 1.0 1.0 6.0)'` | +| `%Geo.Polygon{coordinates: [[{0.0, 0.0}, {0.0, 1.0}, {1.0, 1.0}, {0.0, 0.0}]]}` | `'POLYGON((0.0 0.0,0.0 1.0,1.0 1.0,0.0 0.0))'` | +| `%Geo.PolygonZ{coordinates: [[{0.0, 0.0, 0.0}, {0.0, 1.0, 0.0}, {1.0, 1.0, 0.0}, {0.0, 0.0, 0.0}]]}` | `'POLYGON((0.0 0.0 0.0,0.0 1.0 0.0,1.0 1.0 0.0,0.0 0.0 0.0))'` | +| `%Geo.MultiPoint{coordinates: [{0.0, 0.0}, {1.0, 1.0}]}` | `'MULTIPOINT(0.0 0.0,1.0 1.0)'` | +| `%Geo.MultiPointZ{coordinates: [{0.0, 0.0, 0.0}, {1.0, 1.0, 1.0}]}` | `'MULTIPOINTZ(0.0 0.0 0.0,1.0 1.0 1.0)'` | +| `%Geo.MultiLineString{coordinates: [[{0.0, 0.0}, {1.0, 1.0}]]}` | `'MULTILINESTRING((0.0 0.0,1.0 1.0))'` | +| `%Geo.MultiLineStringZ{coordinates: [[{0.0, 0.0, 0.0}, {1.0, 1.0, 1.0}]]}` | `'MULTILINESTRINGZ((0.0 0.0 0.0,1.0 1.0 1.0))'` | +| `%Geo.MultiPolygon{coordinates: [[[{0.0, 0.0}, {0.0, 1.0}, {1.0, 1.0}, {0.0, 0.0}]]}]` | `'MULTIPOLYGON(((0.0 0.0,0.0 1.0,1.0 1.0,0.0 0.0)))'` | +| `%Geo.MultiPolygonZ{coordinates: [[[{0.0, 0.0, 0.0}, {0.0, 1.0, 0.0}, {1.0, 1.0, 0.0}, {0.0, 0.0, 0.0}]]}]` | `'MULTIPOLYGONZ(((0.0 0.0 0.0,0.0 1.0 0.0,1.0 1.0 0.0,0.0 0.0 0.0)))'` | +| `%Geo.GeometryCollection{geometries: [%Geo.Point{coordinates: {1.0, 2.0}}, %Geo.LineString{coordinates: [{0.0, 0.0}, {1.0, 1.0}]}]}` | `'GEOMETRYCOLLECTION(POINT(1.0 2.0),LINESTRING(0.0 0.0,1.0 1.0))'` | + +### Format queries + +It is possible to format queries using the `:before_inline_callback` option. +Here is an example setup using [pgFormatter](https://github.com/darold/pgFormatter) as an external utility: +```elixir +defmodule MyApp.Application do + def start(_type, _args) do + Ecto.DevLogger.install(MyApp.Repo, before_inline_callback: &__MODULE__.format_sql_query/1) + end + + def format_sql_query(query) do + case System.shell("echo $SQL_QUERY | pg_format -", env: [{"SQL_QUERY", query}], stderr_to_stdout: true) do + {formatted_query, 0} -> String.trim_trailing(formatted_query) + _ -> query + end + end +end +``` + +### Running tests + +You need to run a local PostgreSQL server for the tests to interact with. This is one way to do it: + +```console +$ docker run -p5432:5432 --rm --name ecto_dev_logger_postgres -e POSTGRES_PASSWORD=postgres -d postgres +``` + +If you want PostGIS enabled (for geometry types and extensions), run a PostGIS image instead: + +```console +$ docker run -p5432:5432 --rm --name ecto_dev_logger_postgis -e POSTGRES_PASSWORD=postgres -d postgis/postgis +``` diff --git a/assets/screenshot.png b/assets/screenshot.png index 8e25bb4..cdc85e7 100644 Binary files a/assets/screenshot.png and b/assets/screenshot.png differ diff --git a/lib/ecto/dev_logger.ex b/lib/ecto/dev_logger.ex index 439d7ae..9326161 100644 --- a/lib/ecto/dev_logger.ex +++ b/lib/ecto/dev_logger.ex @@ -3,92 +3,238 @@ defmodule Ecto.DevLogger do An alternative logger for Ecto queries. It inlines bindings into the query, so it is easy to copy-paste logged SQL and run it in any IDE for debugging without - manual transformation of common elixir terms to string representation (binary UUID, DateTime, Decimal, json, etc). - Also, it highlights db time to make slow queries noticeable. Source table and inlined bindings are highlighted as well. + manual transformation of common Elixir terms to string representations (binary UUID, DateTime, Decimal, JSON, etc.). + It also highlights DB time to make slow queries noticeable. The source table and inlined bindings are highlighted as well. """ require Logger + @type option :: {:log_repo_name, boolean()} | {:ignore_event, (metadata :: map() -> boolean())} + @doc """ - Attaches `telemetry_handler/4` to application. + Attaches `telemetry_handler/4` to the application. + + Returns the result from the call to `:telemetry.attach/4` or `:ok` if the repo has default logging enabled. + + ## Options + + * `:log_repo_name` - when truthy, adds the repo name to the log output. + * `:ignore_event` - a callback that allows skipping specific telemetry events, thus suppressing logs. + By default, the library ignores events from `Oban` and events related to migration queries. + These checks are not overridable by the `:ignore_event` callback and have priority over it. + * `:before_inline_callback` - a callback that allows modifying the query before inlining bindings. + You can use this option to format the query using an external utility, like `pgformatter`, etc. + + To ignore logging for a single Repo operation, pass `log: false` via `telemetry_options` to that call; for example: + + Repo.query!("SELECT 1", [], telemetry_options: [log: false]) + Repo.insert!(changeset, telemetry_options: [log: false]) """ - @spec install(repo_module :: module()) :: :ok - def install(repo_module) when is_atom(repo_module) do + @spec install(repo_module :: module(), opts :: [option()]) :: :ok | {:error, :already_exists} + def install(repo_module, opts \\ []) when is_atom(repo_module) do config = repo_module.config() if config[:log] == false do :telemetry.attach( - "ecto.dev_logger", + handler_id(repo_module), config[:telemetry_prefix] ++ [:query], &__MODULE__.telemetry_handler/4, - nil + opts ) + else + :ok end + end + + @doc """ + Detaches a previously attached handler for a given Repo. - :ok + Returns the result from the call to `:telemetry.detach/1` + """ + @spec uninstall(repo_module :: module()) :: :ok | {:error, :not_found} + def uninstall(repo_module) when is_atom(repo_module) do + :telemetry.detach(handler_id(repo_module)) + end + + @doc """ + Gets the handler_id for a given Repo. + """ + @spec handler_id(repo_module :: module()) :: list() + def handler_id(repo_module) do + config = repo_module.config() + [:ecto_dev_logger] ++ config[:telemetry_prefix] end defp oban_query?(metadata) do not is_nil(metadata[:options][:oban_conf]) end + defp schema_migration?(metadata) do + metadata[:options][:schema_migration] == true + end + + defp ignore_event?(config, metadata) do + metadata[:options][:log] == false or oban_query?(metadata) or schema_migration?(metadata) or + (config[:ignore_event] || (&always_false/1)).(metadata) + end + + defp always_false(_), do: false + @doc "Telemetry handler which logs queries." @spec telemetry_handler( :telemetry.event_name(), :telemetry.event_measurements(), :telemetry.event_metadata(), - :telemetry.handler_config() + [option()] ) :: :ok - def telemetry_handler(_event_name, measurements, metadata, _config) do - unless oban_query?(metadata) do - query_string = String.Chars.to_string(metadata.query) - color = sql_color(query_string) + def telemetry_handler(_event_name, measurements, metadata, config) do + if ignore_event?(config, metadata) do + :ok + else + query = String.Chars.to_string(metadata.query) + color = sql_color(query) repo_adapter = metadata[:repo].__adapter__() - - query_string = - metadata.params - |> Enum.with_index(1) - |> Enum.reverse() - |> Enum.reduce(query_string, fn {binding, index}, query -> - replacement = - to_string([ - IO.ANSI.color(0, 2, 3), - stringify_ecto_params(binding, :root), - apply(IO.ANSI, color, []) - ]) - - replace_params(repo_adapter, query, index, replacement) - end) + before_inline_callback = config[:before_inline_callback] || (&Function.identity/1) + params = preprocess_params(metadata) Logger.debug( - fn -> log_sql_iodata(query_string, measurements, metadata, color) end, + fn -> + query + |> before_inline_callback.() + |> inline_params(params, color, repo_adapter) + |> log_sql_iodata(measurements, metadata, color, config) + end, ansi_color: color ) end + end - :ok + @doc false + def inline_params(query, params, _return_to_color, _repo_adapter) when map_size(params) == 0 do + query end - defp log_sql_iodata(query, measurements, %{result: result, source: source}, color) do + def inline_params(query, params, return_to_color, repo_adapter) + when repo_adapter in [Ecto.Adapters.Postgres, Ecto.Adapters.Tds] do + params_by_index = + params + |> Enum.with_index(1) + |> Map.new(fn {value, index} -> {index, value} end) + + placeholder_with_number_regex = placeholder_with_number_regex(repo_adapter) + + String.replace(query, placeholder_with_number_regex, fn + <<_prefix::utf8, index::binary>> = replacement -> + case Map.fetch(params_by_index, String.to_integer(index)) do + {:ok, value} -> + try do + value + |> Ecto.DevLogger.PrintableParameter.to_expression() + |> colorize(IO.ANSI.color(0, 2, 3), apply(IO.ANSI, return_to_color, [])) + rescue + Protocol.UndefinedError -> + value + |> inspect() + |> colorize(IO.ANSI.color(5, 0, 0), apply(IO.ANSI, return_to_color, [])) + end + + :error -> + replacement + end + end) + end + + def inline_params(query, params, return_to_color, repo_adapter) + when repo_adapter in [Ecto.Adapters.MyXQL, Ecto.Adapters.SQLite3] do + params_by_index = + params + |> Enum.with_index() + |> Map.new(fn {value, index} -> {index, value} end) + + query + |> String.split(~r{\?(?!")}) + |> Enum.map_reduce(0, fn elem, index -> + formatted_value = + case Map.fetch(params_by_index, index) do + {:ok, value} -> + value + |> Ecto.DevLogger.PrintableParameter.to_expression() + |> colorize(IO.ANSI.color(0, 2, 3), apply(IO.ANSI, return_to_color, [])) + + :error -> + [] + end + + {[elem, formatted_value], index + 1} + end) + |> elem(0) + end + + defp preprocess_params(metadata) do + cast_params = Map.get(metadata, :cast_params) + + if is_list(cast_params) do + Enum.zip_with( + [metadata.params, cast_params], + fn + [[p | _] = integers, [c | _] = atoms] when is_integer(p) and is_atom(c) -> + Enum.zip_with([integers, atoms], fn [i, a] -> + %Ecto.DevLogger.NumericEnum{integer: i, atom: a} + end) + + [integer, atom] when is_integer(integer) and is_atom(atom) -> + %Ecto.DevLogger.NumericEnum{integer: integer, atom: atom} + + [[hex | _], [uuid | _] = uuids] when byte_size(hex) == 16 and byte_size(uuid) == 36 -> + uuids + + [hex, uuid] when byte_size(hex) == 16 and byte_size(uuid) == 36 -> + uuid + + [param, _] -> + param + end + ) + else + metadata.params + end + end + + defp placeholder_with_number_regex(Ecto.Adapters.Postgres), do: ~r/\$\d+/ + defp placeholder_with_number_regex(Ecto.Adapters.Tds), do: ~r/@\d+/ + + defp log_sql_iodata(query, measurements, metadata, color, config) do [ "QUERY", ?\s, - log_ok_error(result), - log_ok_source(source, color), + log_ok_error(metadata.result), + log_ok_source(metadata.source, color), + log_repo(metadata.repo, color, config), log_time("db", measurements, :query_time, true, color), log_time("decode", measurements, :decode_time, false, color), ?\n, - query + query, + log_stacktrace(metadata[:stacktrace], metadata.repo) ] end defp log_ok_error({:ok, _res}), do: "OK" defp log_ok_error({:error, _err}), do: "ERROR" + defp log_repo(nil, _color, _config), do: "" + + defp log_repo(repo, color, config) do + Keyword.get(config, :log_repo_name, false) + |> case do + true -> [" repo=", colorize(inspect(repo), IO.ANSI.blue(), apply(IO.ANSI, color, []))] + _ -> "" + end + end + defp log_ok_source(nil, _color), do: "" defp log_ok_source(source, color), - do: [" source=", IO.ANSI.blue(), inspect(source), apply(IO.ANSI, color, [])] + do: [" source=", colorize(inspect(source), IO.ANSI.blue(), apply(IO.ANSI, color, []))] defp log_time(label, measurements, key, force, color) do case measurements do @@ -101,7 +247,7 @@ defmodule Ecto.DevLogger do case duration_color(ms) do nil -> line - duration_color -> [duration_color, line, apply(IO.ANSI, color, [])] + duration_color -> colorize(line, duration_color, apply(IO.ANSI, color, [])) end else [] @@ -114,13 +260,15 @@ defmodule Ecto.DevLogger do @colorize_step 25 defp duration_color(duration) do - # don't colorize if duration < @colorize_step - duration = duration - @colorize_step - - if duration > 0 do - # then every @colorize_step ms apply color from RGB(5, 5, 0) to RGB(5, 0, 0) (simple gradient from yellow to red) - green = 5 - min(div(floor(duration), @colorize_step), 5) - IO.ANSI.color(5, green, 0) + if IO.ANSI.enabled?() do + # don't colorize if duration < @colorize_step + duration = duration - @colorize_step + + if duration > 0 do + # then every @colorize_step ms apply color from RGB(5, 5, 0) to RGB(5, 0, 0) (simple gradient from yellow to red) + green = 5 - min(div(floor(duration), @colorize_step), 5) + IO.ANSI.color(5, green, 0) + end end end @@ -134,98 +282,43 @@ defmodule Ecto.DevLogger do defp sql_color("commit" <> _), do: :magenta defp sql_color(_), do: :default_color - defp stringify_ecto_params(binding, _level) - when is_float(binding) or is_integer(binding) or is_atom(binding), - do: to_string(binding) - - defp stringify_ecto_params(%Decimal{} = binding, _level), do: to_string(binding) - - defp stringify_ecto_params(binding, level) when is_binary(binding) do - string = - with <<_::128>> <- binding, - {:ok, string} <- Ecto.UUID.load(binding) do - string - else - _ -> binding - end - - case level do - :root -> - if String.valid?(string) do - in_quotes(string) - else - "DECODE('#{Base.encode64(string)}', 'BASE64')" - end - - :child -> - string + defp colorize(term, color, return_to_color) do + if IO.ANSI.enabled?() do + [color, term, return_to_color] + else + term end end - defp stringify_ecto_params(binding, :root) when is_list(binding) do - in_quotes( - "{" <> - Enum.map_join(binding, ",", fn item -> - string = - item - |> stringify_ecto_params(:child) - |> String.replace("\"", "\\\"") - - if Enum.any?([",", "{", "}"], fn symbol -> String.contains?(string, symbol) end) do - "\"#{string}\"" - else - string - end - end) <> "}" - ) - end - - defp stringify_ecto_params(%module{} = date, :root) - when module in [Date, DateTime, NaiveDateTime] do - date |> stringify_ecto_params(:child) |> in_quotes() - end - - defp stringify_ecto_params(%{} = map, :root) when not is_struct(map) do - map |> stringify_ecto_params(:child) |> in_quotes() - end - - defp stringify_ecto_params(composite, level) when is_tuple(composite) do - values = - composite - |> Tuple.to_list() - |> Enum.map_join(",", &stringify_ecto_params(&1, :child)) - - case level do - :root -> in_quotes("(#{values})") - :child -> "(#{values})" + defp log_stacktrace(stacktrace, repo) do + with [_ | _] <- stacktrace, + {module, function, arity, info} <- last_non_ecto(Enum.reverse(stacktrace), repo, nil) do + [ + if(IO.ANSI.enabled?(), do: IO.ANSI.light_black(), else: ""), + ?\n, + "↳ ", + Exception.format_mfa(module, function, arity), + log_stacktrace_info(info) + ] + else + _ -> [] end end - defp stringify_ecto_params(%Date{} = date, :child) do - to_string(date) - end - - defp stringify_ecto_params(%NaiveDateTime{} = datetime, :child) do - NaiveDateTime.to_iso8601(datetime) - end - - defp stringify_ecto_params(%DateTime{} = datetime, :child) do - DateTime.to_iso8601(datetime) + defp log_stacktrace_info([file: file, line: line] ++ _) do + [", at: ", file, ?:, Integer.to_string(line)] end - defp stringify_ecto_params(%{} = map, :child) when not is_struct(map) do - Jason.encode!(map) + defp log_stacktrace_info(_) do + [] end - defp replace_params(Ecto.Adapters.Tds, query, index, replacement) do - String.replace(query, "@#{index}", replacement) - end + @repo_modules [Ecto.Repo.Queryable, Ecto.Repo.Schema, Ecto.Repo.Transaction] - defp replace_params(_adapter, query, index, replacement) do - String.replace(query, "$#{index}", replacement) - end + defp last_non_ecto([{mod, _, _, _} | _stacktrace], repo, last) + when mod == repo or mod in @repo_modules, + do: last - defp in_quotes(string) do - "'#{String.replace(string, "'", "''")}'" - end + defp last_non_ecto([last | stacktrace], repo, _last), do: last_non_ecto(stacktrace, repo, last) + defp last_non_ecto([], _repo, last), do: last end diff --git a/lib/ecto/dev_logger/numeric_enum.ex b/lib/ecto/dev_logger/numeric_enum.ex new file mode 100644 index 0000000..4c7c5d4 --- /dev/null +++ b/lib/ecto/dev_logger/numeric_enum.ex @@ -0,0 +1,4 @@ +defmodule Ecto.DevLogger.NumericEnum do + @moduledoc false + defstruct [:integer, :atom] +end diff --git a/lib/ecto/dev_logger/printable_parameter.ex b/lib/ecto/dev_logger/printable_parameter.ex new file mode 100644 index 0000000..b43e854 --- /dev/null +++ b/lib/ecto/dev_logger/printable_parameter.ex @@ -0,0 +1,452 @@ +defprotocol Ecto.DevLogger.PrintableParameter do + @moduledoc """ + A protocol for rendering values as valid, copy‑pastable SQL expressions. + + `Ecto.DevLogger` calls this protocol for every bound parameter when it inlines values + into the logged SQL. + + When should I implement this? + - When a value you pass as a query parameter is a struct or type that does not + have a built‑in implementation. + - This is common with driver‑level custom/extension types (for example, structs from database + driver libraries) or domain‑specific structs that ultimately become such driver types. + `Ecto.DevLogger` operates below `Ecto.Type` casting and only sees the post‑cast values. + + Without an implementation, the logger falls back to `inspect/1`, which may not be + valid SQL and therefore not directly runnable. + + How to implement + - If your value can be represented as a single string literal that your database accepts, + implement `to_string_literal/1` and have `to_expression/1` wrap it in single quotes. + - If it must be rendered as a structured SQL expression (e.g. `ROW(...)`, casts, or + constructor functions), implement `to_expression/1` directly and return `nil` from + `to_string_literal/1`. + + Example: PostgreSQL composite type represented by a struct + + defmodule MyApp.Money do + defstruct [:currency, :amount] + end + + defimpl Ecto.DevLogger.PrintableParameter, for: MyApp.Money do + def to_expression(%MyApp.Money{} = money) do + string = to_string_literal(money) + "'\#{String.replace(string, "'", "''")}'" + end + + def to_string_literal(%MyApp.Money{currency: cur, amount: amt}) do + "(\#{cur},\#{amt})" + end + end + + Arrays and tuples + - When all elements implement `to_string_literal/1`, lists and tuples are formatted as + PostgreSQL array and composite string literals (`'{...}'` and `'(...)'`). Otherwise, + they are rendered using `ARRAY[...]` and `ROW(...)`, with each element formatted via + `to_expression/1`. + + `to_expression/1` is the main function and `to_string_literal/1` is an optional helper for it. + """ + + @doc """ + Converts term to a valid SQL expression. + """ + @spec to_expression(any()) :: String.t() + def to_expression(term) + + @doc """ + Converts term to a string literal. + """ + @spec to_string_literal(any()) :: String.t() | nil + def to_string_literal(term) +end + +defmodule Ecto.DevLogger.Utils do + @moduledoc false + def in_string_quotes(string) do + "'#{String.replace(string, "'", "''")}'" + end + + def all_to_string_literal(list) do + result = + Enum.reduce_while(list, {:ok, []}, fn element, {:ok, acc} -> + case Ecto.DevLogger.PrintableParameter.to_string_literal(element) do + nil -> {:halt, :error} + string_literal -> {:cont, {:ok, [{element, string_literal} | acc]}} + end + end) + + with {:ok, list} <- result do + {:ok, Enum.reverse(list)} + end + end +end + +defimpl Ecto.DevLogger.PrintableParameter, for: Atom do + def to_expression(nil), do: "NULL" + def to_expression(true), do: "true" + def to_expression(false), do: "false" + def to_expression(atom), do: atom |> Atom.to_string() |> Ecto.DevLogger.Utils.in_string_quotes() + + def to_string_literal(nil), do: "NULL" + def to_string_literal(true), do: "true" + def to_string_literal(false), do: "false" + def to_string_literal(atom), do: Atom.to_string(atom) +end + +defimpl Ecto.DevLogger.PrintableParameter, for: Map do + def to_expression(map) do + map |> to_string_literal() |> Ecto.DevLogger.Utils.in_string_quotes() + end + + def to_string_literal(map), do: Jason.encode!(map) +end + +for geo_mod <- [ + Geo.Point, + Geo.PointZ, + Geo.PointM, + Geo.PointZM, + Geo.LineString, + Geo.LineStringZ, + Geo.LineStringZM, + Geo.Polygon, + Geo.PolygonZ, + Geo.MultiPoint, + Geo.MultiPointZ, + Geo.MultiLineString, + Geo.MultiLineStringZ, + Geo.MultiPolygon, + Geo.MultiPolygonZ, + Geo.GeometryCollection + ] do + if Code.ensure_loaded?(geo_mod) do + defimpl Ecto.DevLogger.PrintableParameter, for: geo_mod do + def to_expression(geometry) do + geometry |> to_string_literal() |> Ecto.DevLogger.Utils.in_string_quotes() + end + + def to_string_literal(geometry), do: to_string(geometry) + end + end +end + +defimpl Ecto.DevLogger.PrintableParameter, for: Tuple do + def to_expression(tuple) do + case to_string_literal(tuple) do + nil -> + "ROW(" <> + Enum.map_join( + Tuple.to_list(tuple), + ",", + &Ecto.DevLogger.PrintableParameter.to_expression/1 + ) <> ")" + + value -> + Ecto.DevLogger.Utils.in_string_quotes(value) + end + end + + def to_string_literal(tuple) do + case Ecto.DevLogger.Utils.all_to_string_literal(Tuple.to_list(tuple)) do + :error -> + nil + + {:ok, list} -> + body = + Enum.map_join(list, ",", fn {element, string_literal} -> + case element do + nil -> + "" + + "" -> + ~s|""| + + _ -> + string = String.replace(string_literal, "\"", "\\\"") + + if String.contains?(string, [",", "(", ")"]) do + ~s|"#{string}"| + else + string + end + end + end) + + "(" <> body <> ")" + end + end +end + +defimpl Ecto.DevLogger.PrintableParameter, for: Decimal do + def to_expression(decimal), do: to_string_literal(decimal) + def to_string_literal(decimal), do: Decimal.to_string(decimal) +end + +defimpl Ecto.DevLogger.PrintableParameter, for: Integer do + def to_expression(integer), do: to_string_literal(integer) + def to_string_literal(integer), do: Integer.to_string(integer) +end + +defimpl Ecto.DevLogger.PrintableParameter, for: Float do + def to_expression(float), do: to_string_literal(float) + def to_string_literal(float), do: Float.to_string(float) +end + +defimpl Ecto.DevLogger.PrintableParameter, for: Date do + def to_expression(date) do + date + |> to_string_literal() + |> Ecto.DevLogger.Utils.in_string_quotes() + end + + def to_string_literal(date), do: Date.to_string(date) +end + +defimpl Ecto.DevLogger.PrintableParameter, for: DateTime do + def to_expression(date_time) do + date_time + |> to_string_literal() + |> Ecto.DevLogger.Utils.in_string_quotes() + end + + def to_string_literal(date_time), do: DateTime.to_string(date_time) +end + +defimpl Ecto.DevLogger.PrintableParameter, for: NaiveDateTime do + def to_expression(naive_date_time) do + naive_date_time + |> to_string_literal() + |> Ecto.DevLogger.Utils.in_string_quotes() + end + + def to_string_literal(naive_date_time), do: NaiveDateTime.to_string(naive_date_time) +end + +defimpl Ecto.DevLogger.PrintableParameter, for: Time do + def to_expression(time) do + time + |> to_string_literal() + |> Ecto.DevLogger.Utils.in_string_quotes() + end + + def to_string_literal(time), do: Time.to_string(time) +end + +defimpl Ecto.DevLogger.PrintableParameter, for: BitString do + def to_expression(binary) do + if String.valid?(binary) do + Ecto.DevLogger.Utils.in_string_quotes(binary) + else + "DECODE('#{Base.encode64(binary)}','BASE64')" + end + end + + def to_string_literal(binary) do + if String.valid?(binary) do + binary + end + end +end + +defimpl Ecto.DevLogger.PrintableParameter, for: List do + def to_expression(list) do + case to_string_literal(list) do + nil -> + "ARRAY[" <> + Enum.map_join(list, ",", &Ecto.DevLogger.PrintableParameter.to_expression/1) <> "]" + + value -> + Ecto.DevLogger.Utils.in_string_quotes(value) + end + end + + def to_string_literal(list) do + case Ecto.DevLogger.Utils.all_to_string_literal(list) do + :error -> + nil + + {:ok, elements_with_string_literals} -> + if tsvector?(list) do + Enum.map_join(elements_with_string_literals, " ", fn {_element, string_literal} -> + string_literal + end) + else + body = + Enum.map_join(elements_with_string_literals, ",", fn {element, string_literal} -> + cond do + is_list(element) or is_nil(element) -> + string_literal + + element == "" -> + ~s|""| + + true -> + string = String.replace(string_literal, "\"", "\\\"") + + if String.downcase(string) == "null" or + String.contains?(string, [",", "{", "}"]) do + ~s|"#{string}"| + else + string + end + end + end) + + "{" <> body <> "}" + end + end + end + + # tsvector is a list of lexemes. + # By checking only the first element we assume that the others are also lexemes. + defp tsvector?([%{__struct__: Postgrex.Lexeme} | _]) do + true + end + + defp tsvector?(_list) do + false + end +end + +if Code.ensure_loaded?(Postgrex.MACADDR) do + defimpl Ecto.DevLogger.PrintableParameter, for: Postgrex.MACADDR do + def to_expression(macaddr) do + macaddr + |> to_string_literal() + |> Ecto.DevLogger.Utils.in_string_quotes() + end + + def to_string_literal(macaddr) do + macaddr.address + |> Tuple.to_list() + |> Enum.map_join(":", fn value -> + value + |> Integer.to_string(16) + |> String.pad_leading(2, "0") + end) + end + end +end + +if Code.ensure_loaded?(Postgrex.Range) do + defimpl Ecto.DevLogger.PrintableParameter, for: Postgrex.Range do + def to_expression(range) do + range + |> to_string_literal() + |> Ecto.DevLogger.Utils.in_string_quotes() + end + + def to_string_literal(%Postgrex.Range{lower: :empty}), do: "empty" + def to_string_literal(%Postgrex.Range{upper: :empty}), do: "empty" + + def to_string_literal(%Postgrex.Range{} = range) do + left_bracket = if range.lower_inclusive, do: "[", else: "(" + right_bracket = if range.upper_inclusive, do: "]", else: ")" + + lower = + case range.lower do + :unbound -> "" + value -> Ecto.DevLogger.PrintableParameter.to_string_literal(value) + end + + upper = + case range.upper do + :unbound -> "" + value -> Ecto.DevLogger.PrintableParameter.to_string_literal(value) + end + + left_bracket <> lower <> "," <> upper <> right_bracket + end + end +end + +if Code.ensure_loaded?(Postgrex.Multirange) do + defimpl Ecto.DevLogger.PrintableParameter, for: Postgrex.Multirange do + def to_expression(%Postgrex.Multirange{} = multirange) do + multirange + |> to_string_literal() + |> Ecto.DevLogger.Utils.in_string_quotes() + end + + def to_string_literal(%Postgrex.Multirange{ranges: ranges}) do + ranges = ranges || [] + + body = + Enum.map_join(ranges, ",", fn %Postgrex.Range{} = range -> + Ecto.DevLogger.PrintableParameter.to_string_literal(range) + end) + + "{" <> body <> "}" + end + end +end + +if Code.ensure_loaded?(Postgrex.Interval) do + defimpl Ecto.DevLogger.PrintableParameter, for: Postgrex.Interval do + def to_expression(struct), + do: Postgrex.Interval.to_string(struct) |> Ecto.DevLogger.Utils.in_string_quotes() + + def to_string_literal(struct), + do: Postgrex.Interval.to_string(struct) + end +end + +if Code.ensure_loaded?(Postgrex.INET) do + defimpl Ecto.DevLogger.PrintableParameter, for: Postgrex.INET do + def to_expression(inet) do + inet + |> to_string_literal() + |> Ecto.DevLogger.Utils.in_string_quotes() + end + + def to_string_literal(inet) do + netmask = + case inet.netmask do + nil -> "" + netmask -> "/#{netmask}" + end + + "#{:inet.ntoa(inet.address)}#{netmask}" + end + end +end + +if Code.ensure_loaded?(Postgrex.Lexeme) do + defimpl Ecto.DevLogger.PrintableParameter, for: Postgrex.Lexeme do + def to_expression(lexeme) do + raise "Invalid parameter: #{lexeme} must be inside a list" + end + + def to_string_literal(lexeme) do + word = + if String.contains?(lexeme.word, [",", "'", " ", ":"]) do + Ecto.DevLogger.Utils.in_string_quotes(lexeme.word) + else + lexeme.word + end + + case lexeme.positions do + [] -> + word + + positions -> + positions = + Enum.map_join(positions, ",", fn {position, weight} -> + if weight in [nil, :D] do + Integer.to_string(position) + else + [Integer.to_string(position), Atom.to_string(weight)] + end + end) + + "#{word}:#{positions}" + end + end + end +end + +defimpl Ecto.DevLogger.PrintableParameter, for: Ecto.DevLogger.NumericEnum do + def to_expression(enum), do: "#{enum.integer}/*#{enum.atom}*/" + def to_string_literal(_numeric_enum), do: nil +end diff --git a/mix.exs b/mix.exs index 45100fd..26b492f 100644 --- a/mix.exs +++ b/mix.exs @@ -1,6 +1,6 @@ defmodule Ecto.DevLogger.MixProject do use Mix.Project - @version "0.1.4" + @version "0.15.0" @source_url "https://github.com/fuelen/ecto_dev_logger" def project do @@ -18,7 +18,7 @@ defmodule Ecto.DevLogger.MixProject do extras: ["README.md": [title: "README"]], source_url: @source_url, source_ref: "v#{@version}", - assets: "assets" + assets: %{"assets" => "assets"} ] ] end @@ -41,10 +41,12 @@ defmodule Ecto.DevLogger.MixProject do defp deps do [ {:ecto, "~> 3.7"}, - {:ecto_sql, "~> 3.7", only: :test}, - {:postgrex, "~> 0.16", only: :test}, {:jason, "~> 1.0"}, - {:ex_doc, "~> 0.28", only: :dev, runtime: false} + {:ex_doc, "~> 0.28", only: :dev, runtime: false}, + {:ecto_sql, "~> 3.7", only: :test}, + {:geo_postgis, "~> 3.5", only: :test}, + {:postgrex, "~> 0.17", optional: true}, + {:geo, "~> 3.5 or ~> 4.0", optional: true} ] end end diff --git a/mix.lock b/mix.lock index c28c75f..0897ce9 100644 --- a/mix.lock +++ b/mix.lock @@ -1,16 +1,17 @@ %{ - "connection": {:hex, :connection, "1.1.0", "ff2a49c4b75b6fb3e674bfc5536451607270aac754ffd1bdfe175abe4a6d7a68", [:mix], [], "hexpm", "722c1eb0a418fbe91ba7bd59a47e28008a189d47e37e0e7bb85585a016b2869c"}, - "db_connection": {:hex, :db_connection, "2.4.2", "f92e79aff2375299a16bcb069a14ee8615c3414863a6fef93156aee8e86c2ff3", [:mix], [{:connection, "~> 1.0", [hex: :connection, repo: "hexpm", optional: false]}, {:telemetry, "~> 0.4 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "4fe53ca91b99f55ea249693a0229356a08f4d1a7931d8ffa79289b145fe83668"}, - "decimal": {:hex, :decimal, "2.0.0", "a78296e617b0f5dd4c6caf57c714431347912ffb1d0842e998e9792b5642d697", [:mix], [], "hexpm", "34666e9c55dea81013e77d9d87370fe6cb6291d1ef32f46a1600230b1d44f577"}, - "earmark_parser": {:hex, :earmark_parser, "1.4.20", "89970db71b11b6b89759ce16807e857df154f8df3e807b2920a8c39834a9e5cf", [:mix], [], "hexpm", "1eb0d2dabeeeff200e0d17dc3048a6045aab271f73ebb82e416464832eb57bdd"}, - "ecto": {:hex, :ecto, "3.7.1", "a20598862351b29f80f285b21ec5297da1181c0442687f9b8329f0445d228892", [:mix], [{:decimal, "~> 1.6 or ~> 2.0", [hex: :decimal, repo: "hexpm", optional: false]}, {:jason, "~> 1.0", [hex: :jason, repo: "hexpm", optional: true]}, {:telemetry, "~> 0.4 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "d36e5b39fc479e654cffd4dbe1865d9716e4a9b6311faff799b6f90ab81b8638"}, - "ecto_sql": {:hex, :ecto_sql, "3.7.2", "55c60aa3a06168912abf145c6df38b0295c34118c3624cf7a6977cd6ce043081", [:mix], [{:db_connection, "~> 2.2", [hex: :db_connection, repo: "hexpm", optional: false]}, {:ecto, "~> 3.7.0", [hex: :ecto, repo: "hexpm", optional: false]}, {:myxql, "~> 0.4.0 or ~> 0.5.0 or ~> 0.6.0", [hex: :myxql, repo: "hexpm", optional: true]}, {:postgrex, "~> 0.15.0 or ~> 0.16.0 or ~> 1.0", [hex: :postgrex, repo: "hexpm", optional: true]}, {:tds, "~> 2.1.1 or ~> 2.2", [hex: :tds, repo: "hexpm", optional: true]}, {:telemetry, "~> 0.4.0 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "3c218ea62f305dcaef0b915fb56583195e7b91c91dcfb006ba1f669bfacbff2a"}, - "ex_doc": {:hex, :ex_doc, "0.28.2", "e031c7d1a9fc40959da7bf89e2dc269ddc5de631f9bd0e326cbddf7d8085a9da", [:mix], [{:earmark_parser, "~> 1.4.19", [hex: :earmark_parser, repo: "hexpm", optional: false]}, {:makeup_elixir, "~> 0.14", [hex: :makeup_elixir, repo: "hexpm", optional: false]}, {:makeup_erlang, "~> 0.1", [hex: :makeup_erlang, repo: "hexpm", optional: false]}], "hexpm", "51ee866993ffbd0e41c084a7677c570d0fc50cb85c6b5e76f8d936d9587fa719"}, - "jason": {:hex, :jason, "1.3.0", "fa6b82a934feb176263ad2df0dbd91bf633d4a46ebfdffea0c8ae82953714946", [:mix], [{:decimal, "~> 1.0 or ~> 2.0", [hex: :decimal, repo: "hexpm", optional: true]}], "hexpm", "53fc1f51255390e0ec7e50f9cb41e751c260d065dcba2bf0d08dc51a4002c2ac"}, - "makeup": {:hex, :makeup, "1.1.0", "6b67c8bc2882a6b6a445859952a602afc1a41c2e08379ca057c0f525366fc3ca", [:mix], [{:nimble_parsec, "~> 1.2.2 or ~> 1.3", [hex: :nimble_parsec, repo: "hexpm", optional: false]}], "hexpm", "0a45ed501f4a8897f580eabf99a2e5234ea3e75a4373c8a52824f6e873be57a6"}, - "makeup_elixir": {:hex, :makeup_elixir, "0.15.2", "dc72dfe17eb240552857465cc00cce390960d9a0c055c4ccd38b70629227e97c", [:mix], [{:makeup, "~> 1.0", [hex: :makeup, repo: "hexpm", optional: false]}, {:nimble_parsec, "~> 1.1", [hex: :nimble_parsec, repo: "hexpm", optional: false]}], "hexpm", "fd23ae48d09b32eff49d4ced2b43c9f086d402ee4fd4fcb2d7fad97fa8823e75"}, - "makeup_erlang": {:hex, :makeup_erlang, "0.1.1", "3fcb7f09eb9d98dc4d208f49cc955a34218fc41ff6b84df7c75b3e6e533cc65f", [:mix], [{:makeup, "~> 1.0", [hex: :makeup, repo: "hexpm", optional: false]}], "hexpm", "174d0809e98a4ef0b3309256cbf97101c6ec01c4ab0b23e926a9e17df2077cbb"}, - "nimble_parsec": {:hex, :nimble_parsec, "1.2.3", "244836e6e3f1200c7f30cb56733fd808744eca61fd182f731eac4af635cc6d0b", [:mix], [], "hexpm", "c8d789e39b9131acf7b99291e93dae60ab48ef14a7ee9d58c6964f59efb570b0"}, - "postgrex": {:hex, :postgrex, "0.16.2", "0f83198d0e73a36e8d716b90f45f3bde75b5eebf4ade4f43fa1f88c90a812f74", [:mix], [{:connection, "~> 1.1", [hex: :connection, repo: "hexpm", optional: false]}, {:db_connection, "~> 2.1", [hex: :db_connection, repo: "hexpm", optional: false]}, {:decimal, "~> 1.5 or ~> 2.0", [hex: :decimal, repo: "hexpm", optional: false]}, {:jason, "~> 1.0", [hex: :jason, repo: "hexpm", optional: true]}], "hexpm", "a9ea589754d9d4d076121090662b7afe155b374897a6550eb288f11d755acfa0"}, - "telemetry": {:hex, :telemetry, "1.0.0", "0f453a102cdf13d506b7c0ab158324c337c41f1cc7548f0bc0e130bbf0ae9452", [:rebar3], [], "hexpm", "73bc09fa59b4a0284efb4624335583c528e07ec9ae76aca96ea0673850aec57a"}, + "db_connection": {:hex, :db_connection, "2.8.1", "9abdc1e68c34c6163f6fb96a96532272d13ad7ca45262156ae8b7ec6d9dc4bec", [:mix], [{:telemetry, "~> 0.4 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "a61a3d489b239d76f326e03b98794fb8e45168396c925ef25feb405ed09da8fd"}, + "decimal": {:hex, :decimal, "2.3.0", "3ad6255aa77b4a3c4f818171b12d237500e63525c2fd056699967a3e7ea20f62", [:mix], [], "hexpm", "a4d66355cb29cb47c3cf30e71329e58361cfcb37c34235ef3bf1d7bf3773aeac"}, + "earmark_parser": {:hex, :earmark_parser, "1.4.44", "f20830dd6b5c77afe2b063777ddbbff09f9759396500cdbe7523efd58d7a339c", [:mix], [], "hexpm", "4778ac752b4701a5599215f7030989c989ffdc4f6df457c5f36938cc2d2a2750"}, + "ecto": {:hex, :ecto, "3.13.2", "7d0c0863f3fc8d71d17fc3ad3b9424beae13f02712ad84191a826c7169484f01", [:mix], [{:decimal, "~> 2.0", [hex: :decimal, repo: "hexpm", optional: false]}, {:jason, "~> 1.0", [hex: :jason, repo: "hexpm", optional: true]}, {:telemetry, "~> 0.4 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "669d9291370513ff56e7b7e7081b7af3283d02e046cf3d403053c557894a0b3e"}, + "ecto_sql": {:hex, :ecto_sql, "3.13.2", "a07d2461d84107b3d037097c822ffdd36ed69d1cf7c0f70e12a3d1decf04e2e1", [:mix], [{:db_connection, "~> 2.4.1 or ~> 2.5", [hex: :db_connection, repo: "hexpm", optional: false]}, {:ecto, "~> 3.13.0", [hex: :ecto, repo: "hexpm", optional: false]}, {:myxql, "~> 0.7", [hex: :myxql, repo: "hexpm", optional: true]}, {:postgrex, "~> 0.19 or ~> 1.0", [hex: :postgrex, repo: "hexpm", optional: true]}, {:tds, "~> 2.1.1 or ~> 2.2", [hex: :tds, repo: "hexpm", optional: true]}, {:telemetry, "~> 0.4.0 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "539274ab0ecf1a0078a6a72ef3465629e4d6018a3028095dc90f60a19c371717"}, + "ex_doc": {:hex, :ex_doc, "0.38.4", "ab48dff7a8af84226bf23baddcdda329f467255d924380a0cf0cee97bb9a9ede", [:mix], [{:earmark_parser, "~> 1.4.44", [hex: :earmark_parser, repo: "hexpm", optional: false]}, {:makeup_c, ">= 0.1.0", [hex: :makeup_c, repo: "hexpm", optional: true]}, {:makeup_elixir, "~> 0.14 or ~> 1.0", [hex: :makeup_elixir, repo: "hexpm", optional: false]}, {:makeup_erlang, "~> 0.1 or ~> 1.0", [hex: :makeup_erlang, repo: "hexpm", optional: false]}, {:makeup_html, ">= 0.1.0", [hex: :makeup_html, repo: "hexpm", optional: true]}], "hexpm", "f7b62346408a83911c2580154e35613eb314e0278aeea72ed7fedef9c1f165b2"}, + "geo": {:hex, :geo, "4.1.0", "64ba89a64cc400b5b16dd2f5bd644cb141776eb8c2ac5a983332c8d944936c12", [:mix], [{:jason, "~> 1.4", [hex: :jason, repo: "hexpm", optional: true]}], "hexpm", "19edb2b3398ca9f701b573b1fb11bc90951ebd64f18b06bd1bf35abe509a2934"}, + "geo_postgis": {:hex, :geo_postgis, "3.7.1", "614f25b42334a615bd54bb09c22030b1aac7bac8f829bd823ab1faccf093a324", [:mix], [{:ecto, "~> 3.0", [hex: :ecto, repo: "hexpm", optional: true]}, {:geo, "~> 3.6 or ~> 4.0", [hex: :geo, repo: "hexpm", optional: false]}, {:jason, "~> 1.2", [hex: :jason, repo: "hexpm", optional: true]}, {:poison, "~> 2.2 or ~> 3.0 or ~> 4.0 or ~> 5.0 or ~> 6.0", [hex: :poison, repo: "hexpm", optional: true]}, {:postgrex, ">= 0.0.0", [hex: :postgrex, repo: "hexpm", optional: false]}], "hexpm", "c20d823c600d35b7fe9ddd5be03052bb7136c57d6f1775dbd46871545e405280"}, + "jason": {:hex, :jason, "1.4.4", "b9226785a9aa77b6857ca22832cffa5d5011a667207eb2a0ad56adb5db443b8a", [:mix], [{:decimal, "~> 1.0 or ~> 2.0", [hex: :decimal, repo: "hexpm", optional: true]}], "hexpm", "c5eb0cab91f094599f94d55bc63409236a8ec69a21a67814529e8d5f6cc90b3b"}, + "makeup": {:hex, :makeup, "1.2.1", "e90ac1c65589ef354378def3ba19d401e739ee7ee06fb47f94c687016e3713d1", [:mix], [{:nimble_parsec, "~> 1.4", [hex: :nimble_parsec, repo: "hexpm", optional: false]}], "hexpm", "d36484867b0bae0fea568d10131197a4c2e47056a6fbe84922bf6ba71c8d17ce"}, + "makeup_elixir": {:hex, :makeup_elixir, "1.0.1", "e928a4f984e795e41e3abd27bfc09f51db16ab8ba1aebdba2b3a575437efafc2", [:mix], [{:makeup, "~> 1.0", [hex: :makeup, repo: "hexpm", optional: false]}, {:nimble_parsec, "~> 1.2.3 or ~> 1.3", [hex: :nimble_parsec, repo: "hexpm", optional: false]}], "hexpm", "7284900d412a3e5cfd97fdaed4f5ed389b8f2b4cb49efc0eb3bd10e2febf9507"}, + "makeup_erlang": {:hex, :makeup_erlang, "1.0.2", "03e1804074b3aa64d5fad7aa64601ed0fb395337b982d9bcf04029d68d51b6a7", [:mix], [{:makeup, "~> 1.0", [hex: :makeup, repo: "hexpm", optional: false]}], "hexpm", "af33ff7ef368d5893e4a267933e7744e46ce3cf1f61e2dccf53a111ed3aa3727"}, + "nimble_parsec": {:hex, :nimble_parsec, "1.4.2", "8efba0122db06df95bfaa78f791344a89352ba04baedd3849593bfce4d0dc1c6", [:mix], [], "hexpm", "4b21398942dda052b403bbe1da991ccd03a053668d147d53fb8c4e0efe09c973"}, + "postgrex": {:hex, :postgrex, "0.21.1", "2c5cc830ec11e7a0067dd4d623c049b3ef807e9507a424985b8dcf921224cd88", [:mix], [{:db_connection, "~> 2.1", [hex: :db_connection, repo: "hexpm", optional: false]}, {:decimal, "~> 1.5 or ~> 2.0", [hex: :decimal, repo: "hexpm", optional: false]}, {:jason, "~> 1.0", [hex: :jason, repo: "hexpm", optional: true]}, {:table, "~> 0.1.0", [hex: :table, repo: "hexpm", optional: true]}], "hexpm", "27d8d21c103c3cc68851b533ff99eef353e6a0ff98dc444ea751de43eb48bdac"}, + "telemetry": {:hex, :telemetry, "1.3.0", "fedebbae410d715cf8e7062c96a1ef32ec22e764197f70cda73d82778d61e7a2", [:rebar3], [], "hexpm", "7015fc8919dbe63764f4b4b87a95b7c0996bd539e0d499be6ec9d7f3875b79e6"}, } diff --git a/test/ecto/dev_logger/printable_parameter_test.exs b/test/ecto/dev_logger/printable_parameter_test.exs new file mode 100644 index 0000000..4fd79e3 --- /dev/null +++ b/test/ecto/dev_logger/printable_parameter_test.exs @@ -0,0 +1,323 @@ +defmodule Ecto.DevLogger.PrintableParameterTest do + use ExUnit.Case, async: true + doctest Ecto.DevLogger.PrintableParameter + import Ecto.DevLogger.PrintableParameter + + test "to_expression/1" do + # NULL + assert to_expression(nil) == "NULL" + + # Boolean + assert to_expression(true) == "true" + assert to_expression(false) == "false" + + # Atom + assert to_expression(:hey) == "'hey'" + assert to_expression(:hey@hey) == "'hey@hey'" + + # Integer + assert to_expression(-123) == "-123" + assert to_expression(123) == "123" + + # Float + assert to_expression(123.12) == "123.12" + assert to_expression(-123.12) == "-123.12" + + # Decimal + assert to_expression(Decimal.from_float(-123.12)) == "-123.12" + assert to_expression(Decimal.from_float(123.12)) == "123.12" + + # String + assert to_expression("string with single quote: '") == ~s|'string with single quote: '''| + assert to_expression("string with double quote: \"") == ~s|'string with double quote: "'| + assert to_expression("") == ~s|''| + + # Binary + assert to_expression(<<95, 131, 49, 101, 176, 212, 77, 86>>) == + "DECODE('X4MxZbDUTVY=','BASE64')" + + # Map + assert to_expression(%{ + "string" => "string", + "boolean" => true, + "integer" => 1, + "array" => [1, 2, 3] + }) == ~s|'{"array":[1,2,3],"boolean":true,"integer":1,"string":"string"}'| + + # UUID-like binary + assert to_expression("dc2ec804-6ee2-4689-a8f1-be59aa80771f") == + "'dc2ec804-6ee2-4689-a8f1-be59aa80771f'" + + # Date and Time + assert to_expression(~D[2022-11-04]) == "'2022-11-04'" + assert to_expression(~U[2022-11-04 10:40:11.362181Z]) == "'2022-11-04 10:40:11.362181Z'" + assert to_expression(~N[2022-11-04 10:40:01.256931]) == "'2022-11-04 10:40:01.256931'" + assert to_expression(~T[10:40:17.657300]) == "'10:40:17.657300'" + + # Postgrex types + assert to_expression(%Postgrex.INET{address: {127, 0, 0, 1}, netmask: 24}) == "'127.0.0.1/24'" + assert to_expression(%Postgrex.INET{address: {127, 0, 0, 1}, netmask: nil}) == "'127.0.0.1'" + assert to_expression(%Postgrex.MACADDR{address: {8, 1, 43, 5, 7, 9}}) == "'08:01:2B:05:07:09'" + + assert to_expression(%Postgrex.Interval{months: 1, days: 2, secs: 34}) == + "'1 month, 2 days, 34 seconds'" + + # List + assert to_expression([]) == "'{}'" + assert to_expression([1, 2, 3]) == "'{1,2,3}'" + assert to_expression([1, 2, 3, nil]) == ~s|'{1,2,3,NULL}'| + assert to_expression([1.2, 2.3, 3.4]) == "'{1.2,2.3,3.4}'" + assert to_expression(["abc", "DFG", "NULL", ""]) == ~s|'{abc,DFG,"NULL",""}'| + assert to_expression([:hello, :world]) == ~s|'{hello,world}'| + assert to_expression(["single quote:'"]) == "'{single quote:''}'" + assert to_expression(["double quote:\""]) == ~s|'{double quote:\\"}'| + assert to_expression(["{", "}", ","]) == ~s|'{"{","}",","}'| + assert to_expression([[1, 2, 3], [3, 4, 5]]) == "'{{1,2,3},{3,4,5}}'" + assert to_expression([["a", "b", "c"], ["d", "f", "e"]]) == "'{{a,b,c},{d,f,e}}'" + assert to_expression([~D[2022-11-04], ~D[2022-11-03]]) == "'{2022-11-04,2022-11-03}'" + + assert to_expression([~U[2022-11-04 10:40:11.362181Z], ~U[2022-11-03 10:40:11.362181Z]]) == + "'{2022-11-04 10:40:11.362181Z,2022-11-03 10:40:11.362181Z}'" + + assert to_expression([~N[2022-11-04 10:40:01.256931], ~N[2022-11-03 10:40:01.256931]]) == + "'{2022-11-04 10:40:01.256931,2022-11-03 10:40:01.256931}'" + + assert to_expression([~T[10:40:17.657300], ~T[09:40:17.657300]]) == + "'{10:40:17.657300,09:40:17.657300}'" + + assert to_expression([ + %Postgrex.INET{address: {127, 0, 0, 1}, netmask: 24}, + %Postgrex.INET{address: {127, 0, 0, 1}, netmask: nil} + ]) == "'{127.0.0.1/24,127.0.0.1}'" + + assert to_expression([ + %Geo.Point{coordinates: {44.21587, -87.5947}, srid: 4326, properties: %{}} + ]) == "'{SRID=4326;POINT(44.21587 -87.5947)}'" + + assert to_expression([ + %Geo.Polygon{ + coordinates: [ + [{2.20, 41.41}, {2.13, 41.41}, {2.13, 41.35}, {2.20, 41.35}, {2.20, 41.41}] + ], + srid: nil, + properties: %{} + } + ]) == "'{\"POLYGON((2.2 41.41,2.13 41.41,2.13 41.35,2.2 41.35,2.2 41.41))\"}'" + + assert to_expression([%Postgrex.MACADDR{address: {8, 1, 43, 5, 7, 9}}]) == + "'{08:01:2B:05:07:09}'" + + # List of lexemes is considered as tsvector + assert to_expression([ + %Postgrex.Lexeme{word: "Joe's", positions: [{5, :D}]}, + %Postgrex.Lexeme{word: "foo", positions: [{1, :A}, {3, :B}, {2, nil}]}, + %Postgrex.Lexeme{word: "bar", positions: []} + ]) == "'''Joe''''s'':5 foo:1A,3B,2 bar'" + + assert to_expression([%{}, %{}]) == ~s|'{"{}","{}"}'| + assert to_expression([{1, "USD"}, {2, "USD"}]) == ~s|'{"(1,USD)","(2,USD)"}'| + + assert to_expression([[<<95, 131, 49, 101>>, <<101, 176, 212, 77, 86>>, nil]]) == + "ARRAY[ARRAY[DECODE('X4MxZQ==','BASE64'),DECODE('ZbDUTVY=','BASE64'),NULL]]" + + # Tuple (composite types) + assert to_expression({1, 1.2, "string", "", nil}) == ~s|'(1,1.2,string,"",)'| + + assert to_expression({"'", ~s|"|, ")", "(", ",", "multiple words"}) == + ~s|'('',\\",")","(",",",multiple words)'| + + assert to_expression({{<<101, 49, 95, 131>>, "hello", nil}, {nil, [1, 2, 3]}}) == + ~s|ROW(ROW(DECODE('ZTFfgw==','BASE64'),'hello',NULL),'(,"{1,2,3}")')| + + assert to_expression(%Ecto.DevLogger.NumericEnum{ + integer: 1, + atom: :one + }) == + "1/*one*/" + + # Ranges (Postgrex.Range) + assert to_expression(%Postgrex.Range{ + lower: 1, + upper: 5, + lower_inclusive: true, + upper_inclusive: false + }) == "'[1,5)'" + + assert to_expression(%Postgrex.Range{ + lower: :unbound, + upper: 5, + lower_inclusive: true, + upper_inclusive: false + }) == "'[,5)'" + + assert to_expression(%Postgrex.Range{ + lower: 1, + upper: :unbound, + lower_inclusive: true, + upper_inclusive: false + }) == "'[1,)'" + + assert to_expression(%Postgrex.Range{ + lower: Decimal.new("0.12"), + upper: Decimal.new("10.5"), + lower_inclusive: false, + upper_inclusive: true + }) == "'(0.12,10.5]'" + + assert to_expression(%Postgrex.Range{lower: :empty}) == "'empty'" + + # Ranges with other element types + # int8range-like (large integers) + assert to_expression(%Postgrex.Range{ + lower: 10_000_000_000, + upper: 10_000_000_010, + lower_inclusive: true, + upper_inclusive: false + }) == "'[10000000000,10000000010)'" + + # tsrange (NaiveDateTime) + assert to_expression(%Postgrex.Range{ + lower: ~N[2022-06-25 14:30:16.643949], + upper: ~N[2022-06-25 15:30:16.643949], + lower_inclusive: true, + upper_inclusive: false + }) == "'[2022-06-25 14:30:16.643949,2022-06-25 15:30:16.643949)'" + + # tstzrange (DateTime) + assert to_expression(%Postgrex.Range{ + lower: ~U[2022-06-25 14:30:16.639767Z], + upper: ~U[2022-06-25 15:30:16.643949Z], + lower_inclusive: false, + upper_inclusive: true + }) == "'(2022-06-25 14:30:16.639767Z,2022-06-25 15:30:16.643949Z]'" + + # daterange (Date) + assert to_expression(%Postgrex.Range{ + lower: ~D[2022-11-04], + upper: ~D[2022-11-10], + lower_inclusive: true, + upper_inclusive: false + }) == "'[2022-11-04,2022-11-10)'" + + # Multirange + mr = %Postgrex.Multirange{ + ranges: [ + %Postgrex.Range{lower: 1, upper: 3, lower_inclusive: true, upper_inclusive: false}, + %Postgrex.Range{lower: 10, upper: 15, lower_inclusive: false, upper_inclusive: true} + ] + } + + assert to_expression(mr) == "'{[1,3),(10,15]}'" + end + + test "to_expression/1 for all Geo geometry types" do + assert to_expression(%Geo.Point{coordinates: {1.0, 2.0}, srid: 4326, properties: %{}}) == + "'SRID=4326;POINT(1.0 2.0)'" + + assert to_expression(%Geo.PointZ{coordinates: {1.0, 2.0, 3.0}, srid: nil, properties: %{}}) == + "'POINT Z(1.0 2.0 3.0)'" + + assert to_expression(%Geo.PointM{coordinates: {1.0, 2.0, 4.0}, srid: 3857, properties: %{}}) == + "'SRID=3857;POINT M(1.0 2.0 4.0)'" + + assert to_expression(%Geo.PointZM{ + coordinates: {1.0, 2.0, 3.0, 4.0}, + srid: nil, + properties: %{} + }) == + "'POINT ZM(1.0 2.0 3.0 4.0)'" + + assert to_expression(%Geo.LineString{ + coordinates: [{0.0, 0.0}, {1.0, 1.0}], + srid: nil, + properties: %{} + }) == + "'LINESTRING(0.0 0.0,1.0 1.0)'" + + assert to_expression(%Geo.LineStringZ{ + coordinates: [{0.0, 0.0, 0.0}, {1.0, 1.0, 1.0}], + srid: nil, + properties: %{} + }) == + "'LINESTRINGZ(0.0 0.0 0.0,1.0 1.0 1.0)'" + + assert to_expression(%Geo.LineStringZM{ + coordinates: [{0.0, 0.0, 0.0, 5.0}, {1.0, 1.0, 1.0, 6.0}], + srid: nil, + properties: %{} + }) == + "'LINESTRINGZM(0.0 0.0 0.0 5.0,1.0 1.0 1.0 6.0)'" + + assert to_expression(%Geo.Polygon{ + coordinates: [[{0.0, 0.0}, {0.0, 1.0}, {1.0, 1.0}, {0.0, 0.0}]], + srid: nil, + properties: %{} + }) == + "'POLYGON((0.0 0.0,0.0 1.0,1.0 1.0,0.0 0.0))'" + + assert to_expression(%Geo.PolygonZ{ + coordinates: [[{0.0, 0.0, 0.0}, {0.0, 1.0, 0.0}, {1.0, 1.0, 0.0}, {0.0, 0.0, 0.0}]], + srid: nil, + properties: %{} + }) == + "'POLYGON((0.0 0.0 0.0,0.0 1.0 0.0,1.0 1.0 0.0,0.0 0.0 0.0))'" + + assert to_expression(%Geo.MultiPoint{ + coordinates: [{0.0, 0.0}, {1.0, 1.0}], + srid: nil, + properties: %{} + }) == + "'MULTIPOINT(0.0 0.0,1.0 1.0)'" + + assert to_expression(%Geo.MultiPointZ{ + coordinates: [{0.0, 0.0, 0.0}, {1.0, 1.0, 1.0}], + srid: nil, + properties: %{} + }) == + "'MULTIPOINTZ(0.0 0.0 0.0,1.0 1.0 1.0)'" + + assert to_expression(%Geo.MultiLineString{ + coordinates: [[{0.0, 0.0}, {1.0, 1.0}]], + srid: nil, + properties: %{} + }) == + "'MULTILINESTRING((0.0 0.0,1.0 1.0))'" + + assert to_expression(%Geo.MultiLineStringZ{ + coordinates: [[{0.0, 0.0, 0.0}, {1.0, 1.0, 1.0}]], + srid: nil, + properties: %{} + }) == + "'MULTILINESTRINGZ((0.0 0.0 0.0,1.0 1.0 1.0))'" + + assert to_expression(%Geo.MultiPolygon{ + coordinates: [[[{0.0, 0.0}, {0.0, 1.0}, {1.0, 1.0}, {0.0, 0.0}]]], + srid: nil, + properties: %{} + }) == + "'MULTIPOLYGON(((0.0 0.0,0.0 1.0,1.0 1.0,0.0 0.0)))'" + + assert to_expression(%Geo.MultiPolygonZ{ + coordinates: [ + [[{0.0, 0.0, 0.0}, {0.0, 1.0, 0.0}, {1.0, 1.0, 0.0}, {0.0, 0.0, 0.0}]] + ], + srid: nil, + properties: %{} + }) == + "'MULTIPOLYGONZ(((0.0 0.0 0.0,0.0 1.0 0.0,1.0 1.0 0.0,0.0 0.0 0.0)))'" + + assert to_expression(%Geo.GeometryCollection{ + geometries: [ + %Geo.Point{coordinates: {1.0, 2.0}, srid: nil, properties: %{}}, + %Geo.LineString{ + coordinates: [{0.0, 0.0}, {1.0, 1.0}], + srid: nil, + properties: %{} + } + ], + srid: nil, + properties: %{} + }) == + "'GEOMETRYCOLLECTION(POINT(1.0 2.0),LINESTRING(0.0 0.0,1.0 1.0))'" + end +end diff --git a/test/ecto/dev_logger_test.exs b/test/ecto/dev_logger_test.exs index 3e1c0ce..4feddbb 100644 --- a/test/ecto/dev_logger_test.exs +++ b/test/ecto/dev_logger_test.exs @@ -1,8 +1,54 @@ defmodule Ecto.DevLoggerTest do use ExUnit.Case + import ExUnit.CaptureLog + + Postgrex.Types.define( + Ecto.DevLoggerTest.PostgresTypes, + [Geo.PostGIS.Extension | Ecto.Adapters.Postgres.extensions()], + json: Jason + ) defmodule Repo do - use Ecto.Repo, adapter: Ecto.Adapters.Postgres, otp_app: :does_not_matter + use Ecto.Repo, adapter: Ecto.Adapters.Postgres, otp_app: :my_test_app + + def get_config() do + [ + telemetry_prefix: [:my_test_app, :repo], + otp_app: :my_test_app, + timeout: 15_000, + migration_timestamps: [type: :naive_datetime_usec], + database: "ecto_dev_logger_test", + hostname: "localhost", + username: "postgres", + password: "postgres", + port: 5432, + log: false, + stacktrace: true, + pool_size: 10, + types: Ecto.DevLoggerTest.PostgresTypes + ] + end + end + + defmodule Repo2 do + use Ecto.Repo, adapter: Ecto.Adapters.Postgres, otp_app: :my_test_app + + def get_config() do + [ + telemetry_prefix: [:my_test_app, :repo2], + otp_app: :my_test_app, + timeout: 15_000, + migration_timestamps: [type: :naive_datetime_usec], + database: "ecto_dev_logger_test2", + hostname: "localhost", + username: "postgres", + password: "postgres", + port: 5432, + log: false, + stacktrace: true, + pool_size: 10 + ] + end end defmodule Money do @@ -31,8 +77,81 @@ defmodule Ecto.DevLoggerTest do end end + defmodule MACADDRType do + use Ecto.Type + + def type, do: :inet + def cast(term), do: {:ok, term} + def dump(term), do: {:ok, term} + def load(term), do: {:ok, term} + end + + defmodule InetType do + use Ecto.Type + + def type, do: :inet + def cast(term), do: {:ok, term} + def dump(term), do: {:ok, term} + def load(term), do: {:ok, term} + end + + defmodule Int4RangeType do + use Ecto.Type + + def type, do: :int4range + def cast(term), do: {:ok, term} + def dump(term), do: {:ok, term} + def load(term), do: {:ok, term} + end + + defmodule NumRangeType do + use Ecto.Type + + def type, do: :numrange + def cast(term), do: {:ok, term} + def dump(term), do: {:ok, term} + def load(term), do: {:ok, term} + end + + defmodule Int8RangeType do + use Ecto.Type + + def type, do: :int8range + def cast(term), do: {:ok, term} + def dump(term), do: {:ok, term} + def load(term), do: {:ok, term} + end + + defmodule TsRangeType do + use Ecto.Type + + def type, do: :tsrange + def cast(term), do: {:ok, term} + def dump(term), do: {:ok, term} + def load(term), do: {:ok, term} + end + + defmodule TstzRangeType do + use Ecto.Type + + def type, do: :tstzrange + def cast(term), do: {:ok, term} + def dump(term), do: {:ok, term} + def load(term), do: {:ok, term} + end + + defmodule DateRangeType do + use Ecto.Type + + def type, do: :daterange + def cast(term), do: {:ok, term} + def dump(term), do: {:ok, term} + def load(term), do: {:ok, term} + end + defmodule Post do use Ecto.Schema + @enum [foo: 1, bar: 2, baz: 5] @primary_key {:id, :binary_id, read_after_writes: true} schema "posts" do @@ -42,94 +161,549 @@ defmodule Ecto.DevLoggerTest do field(:integer, :integer) field(:decimal, :decimal) field(:date, :date) + field(:time, :time) field(:array_of_strings, {:array, :string}) field(:money, Money.Ecto.Type) field(:multi_money, {:array, Money.Ecto.Type}) field(:datetime, :utc_datetime_usec) field(:naive_datetime, :naive_datetime_usec) + field(:password_digest, :string) + field(:ip, InetType) + field(:macaddr, MACADDRType) + field(:array_of_enums, {:array, Ecto.Enum}, values: @enum) + field(:enum, Ecto.Enum, values: @enum) + field(:int_range, Int4RangeType) + field(:num_range, NumRangeType) + field(:int8_range, Int8RangeType) + field(:ts_range, TsRangeType) + field(:tstz_range, TstzRangeType) + field(:date_range, DateRangeType) end end setup do - Repo.__adapter__().storage_down(config()) - Repo.__adapter__().storage_up(config()) - {:ok, _} = Repo.start_link(config()) - - Repo.query!("CREATE EXTENSION \"pgcrypto\";") - - Repo.query!(""" - CREATE TYPE money_type AS (currency char(3), value integer); - """) - - Repo.query!(""" - CREATE TABLE posts ( - id uuid PRIMARY KEY NOT NULL DEFAULT gen_random_uuid(), - string text, - "binary" bytea, - map jsonb, - integer integer, - decimal numeric, - date date, - array_of_strings text[], - money money_type, - multi_money money_type[], - datetime timestamp without time zone NOT NULL, - naive_datetime timestamp without time zone NOT NULL - ) - """) - - :telemetry.attach( - "ecto.dev_logger", - [:my_test_app, :repo, :query], - &Ecto.DevLogger.telemetry_handler/4, - nil - ) + setup_repo(Repo) + Ecto.DevLogger.install(Repo) on_exit(fn -> - Repo.__adapter__().storage_down(config()) + teardown_repo(Repo) end) end test "everything" do - %{id: post_id} = - Repo.insert!(%Post{ - string: "Post '1'", - binary: - <<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>>, - map: %{test: true, string: "\"'"}, - integer: 0, - decimal: Decimal.from_float(0.12), - date: Date.utc_today(), - array_of_strings: ["single_word", "hello, comma", "hey 'quotes'", "hey \"quotes\""], - money: %Money{currency: "USD", value: 390}, - multi_money: [%Money{currency: "USD", value: 230}, %Money{currency: "USD", value: 180}], - datetime: DateTime.utc_now(), - naive_datetime: NaiveDateTime.utc_now() - }) + datetime = ~U[2024-08-01 21:23:53.845311Z] + naive_datetime = ~N[2024-08-01 21:23:53.846380] + date = ~D[2024-08-01] + time = ~T[21:23:53] + + post = %Post{ + string: "Post '1'", + binary: + <<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>>, + map: %{test: true, string: "\"'"}, + integer: 0, + decimal: Decimal.from_float(0.12), + date: date, + time: time, + array_of_strings: ["single_word", "hello, comma", "hey 'quotes'", "hey \"quotes\""], + money: %Money{currency: "USD", value: 390}, + multi_money: [%Money{currency: "USD", value: 230}, %Money{currency: "USD", value: 180}], + datetime: datetime, + naive_datetime: naive_datetime, + password_digest: "$pbkdf2-sha512$160000$iFMKqXv32lHNL7GsUtajyA$Sa4ebMd", + ip: %Postgrex.INET{address: {127, 0, 0, 1}, netmask: 24}, + macaddr: %Postgrex.MACADDR{address: {8, 1, 43, 5, 7, 9}}, + array_of_enums: [:foo, :baz], + enum: :bar + } + + {%{id: post_id}, log} = with_log(fn -> Repo.insert!(post) end) + IO.puts(log) + + query = + "INSERT INTO \"posts\" (\"binary\",\"integer\",\"date\",\"time\",\"string\",\"map\",\"enum\",\"ip\",\"decimal\",\"array_of_strings\",\"money\",\"multi_money\",\"datetime\",\"naive_datetime\",\"password_digest\",\"macaddr\",\"array_of_enums\") VALUES (DECODE('9uU9cwJsgCFmkGY3fe2OKNnh6k+GU1Ve2g83Jic=','BASE64'),0,'2024-08-01','21:23:53','Post ''1''','{\"string\":\"\\\"''\",\"test\":true}',2/*bar*/,'127.0.0.1/24',0.12,'{single_word,\"hello, comma\",hey ''quotes'',hey \\\"quotes\\\"}','(USD,390)','{\"(USD,230)\",\"(USD,180)\"}','2024-08-01 21:23:53.845311Z','2024-08-01 21:23:53.846380','$pbkdf2-sha512$160000$iFMKqXv32lHNL7GsUtajyA$Sa4ebMd','08:01:2B:05:07:09',ARRAY[1/*foo*/,5/*baz*/]) RETURNING \"id\"" + + assert %Postgrex.Result{} = Ecto.Adapters.SQL.query!(Repo, query, []) + + # Coverage can reorder columns; assert presence of critical fragments instead + plain = strip_ansi(log) + assert plain =~ "INSERT INTO \"posts\" (" + assert plain =~ "'08:01:2B:05:07:09'" + assert plain =~ ~r/'\{single_word,"hello, comma",hey ''quotes'',hey \\"quotes\\"\}'/ post = Repo.get!(Post, post_id) - post = post |> Ecto.Changeset.change(string: "Post '2'") |> Repo.update!() + post = post |> Ecto.Changeset.change(string: nil) |> Repo.update!() Repo.delete!(post) + end + + describe "generates correct sql for structs" do + test "ip field" do + ip = %Postgrex.INET{address: {127, 0, 0, 1}, netmask: 24} + + log = capture_log(fn -> Repo.insert!(%Post{ip: ip}) end) + + assert strip_ansi(log) =~ + ~S|INSERT INTO "posts" ("ip") VALUES ('127.0.0.1/24') RETURNING "id"| + end + + test "macaddr field" do + macaddr = %Postgrex.MACADDR{address: {8, 1, 43, 5, 7, 9}} + + log = capture_log(fn -> Repo.insert!(%Post{macaddr: macaddr}) end) + + assert strip_ansi(log) =~ + ~S|INSERT INTO "posts" ("macaddr") VALUES ('08:01:2B:05:07:09') RETURNING "id"| + end + + test "array of enums field" do + log = capture_log(fn -> Repo.insert!(%Post{array_of_enums: [:foo, :baz]}) end) + + assert strip_ansi(log) =~ + ~S|INSERT INTO "posts" ("array_of_enums") VALUES (ARRAY[1/*foo*/,5/*baz*/]) RETURNING "id"| + end + + test "enum field" do + log = capture_log(fn -> Repo.insert!(%Post{enum: :bar}) end) + + assert strip_ansi(log) =~ + ~S|INSERT INTO "posts" ("enum") VALUES (2/*bar*/) RETURNING "id"| + end + + test "int4range field" do + range = %Postgrex.Range{lower: 1, upper: 10, lower_inclusive: true, upper_inclusive: false} + + log = capture_log(fn -> Repo.insert!(%Post{int_range: range}) end) + + assert strip_ansi(log) =~ + ~S|INSERT INTO "posts" ("int_range") VALUES ('[1,10)') RETURNING "id"| + end + + test "numrange field" do + range = %Postgrex.Range{ + lower: Decimal.new("0.5"), + upper: Decimal.new("10.5"), + lower_inclusive: false, + upper_inclusive: true + } + + log = capture_log(fn -> Repo.insert!(%Post{num_range: range}) end) + + assert strip_ansi(log) =~ + ~S|INSERT INTO "posts" ("num_range") VALUES ('(0.5,10.5]') RETURNING "id"| + end + + test "int8range field" do + range = %Postgrex.Range{ + lower: 10_000_000_000, + upper: 10_000_000_010, + lower_inclusive: true, + upper_inclusive: false + } + + log = capture_log(fn -> Repo.insert!(%Post{int8_range: range}) end) + + assert strip_ansi(log) =~ + ~S|INSERT INTO "posts" ("int8_range") VALUES ('[10000000000,10000000010)') RETURNING "id"| + end + + test "tsrange field" do + range = %Postgrex.Range{ + lower: ~N[2022-06-25 14:30:16.643949], + upper: ~N[2022-06-25 15:30:16.643949], + lower_inclusive: true, + upper_inclusive: false + } + + log = capture_log(fn -> Repo.insert!(%Post{ts_range: range}) end) + + assert strip_ansi(log) =~ + ~S|INSERT INTO "posts" ("ts_range") VALUES ('[2022-06-25 14:30:16.643949,2022-06-25 15:30:16.643949)') RETURNING "id"| + end + + test "tstzrange field" do + range = %Postgrex.Range{ + lower: ~U[2022-06-25 14:30:16.639767Z], + upper: ~U[2022-06-25 15:30:16.643949Z], + lower_inclusive: false, + upper_inclusive: true + } + + log = capture_log(fn -> Repo.insert!(%Post{tstz_range: range}) end) + + assert strip_ansi(log) =~ + ~S|INSERT INTO "posts" ("tstz_range") VALUES ('(2022-06-25 14:30:16.639767Z,2022-06-25 15:30:16.643949Z]') RETURNING "id"| + end + + test "daterange field" do + range = %Postgrex.Range{ + lower: ~D[2022-11-04], + upper: ~D[2022-11-10], + lower_inclusive: true, + upper_inclusive: false + } + + log = capture_log(fn -> Repo.insert!(%Post{date_range: range}) end) + + assert strip_ansi(log) =~ + ~S|INSERT INTO "posts" ("date_range") VALUES ('[2022-11-04,2022-11-10)') RETURNING "id"| + end + end + defmodule GeoPost do + use Ecto.Schema + @primary_key {:id, :binary_id, read_after_writes: true} + schema "geo_posts" do + field(:point, Geo.PostGIS.Geometry) + field(:polygon, Geo.PostGIS.Geometry) + field(:line_string, Geo.PostGIS.Geometry) + field(:multi_point, Geo.PostGIS.Geometry) + field(:multi_line_string, Geo.PostGIS.Geometry) + field(:multi_polygon, Geo.PostGIS.Geometry) + field(:geometry_collection, Geo.PostGIS.Geometry) + end + end + + test "logs with geo_postgis geometry fields and hits DB" do + Repo.query!("CREATE EXTENSION IF NOT EXISTS postgis", [], telemetry_options: [log: false]) + + Repo.query!( + """ + CREATE TABLE IF NOT EXISTS geo_posts ( + id uuid PRIMARY KEY NOT NULL DEFAULT gen_random_uuid(), + point geometry(Point, 4326), + polygon geometry(Polygon), + line_string geometry(LineString), + multi_point geometry(MultiPoint), + multi_line_string geometry(MultiLineString), + multi_polygon geometry(MultiPolygon), + geometry_collection geometry(GeometryCollection) + ) + """, + [], + telemetry_options: [log: false] + ) + + point = %Geo.Point{coordinates: {44.21587, -87.5947}, srid: 4326, properties: %{}} + + polygon = %Geo.Polygon{ + coordinates: [[{2.20, 41.41}, {2.13, 41.41}, {2.13, 41.35}, {2.20, 41.35}, {2.20, 41.41}]], + srid: nil, + properties: %{} + } + + line = %Geo.LineString{coordinates: [{0.0, 0.0}, {1.0, 1.0}], srid: nil, properties: %{}} + mpoint = %Geo.MultiPoint{coordinates: [{0.0, 0.0}, {1.0, 1.0}], srid: nil, properties: %{}} + + mline = %Geo.MultiLineString{ + coordinates: [[{0.0, 0.0}, {1.0, 1.0}]], + srid: nil, + properties: %{} + } + + mpoly = %Geo.MultiPolygon{ + coordinates: [[[{0.0, 0.0}, {0.0, 1.0}, {1.0, 1.0}, {0.0, 0.0}]]], + srid: nil, + properties: %{} + } + + gcoll = %Geo.GeometryCollection{geometries: [point, line], srid: nil, properties: %{}} + + log = + capture_log(fn -> + Repo.insert!(%GeoPost{ + point: point, + polygon: polygon, + line_string: line, + multi_point: mpoint, + multi_line_string: mline, + multi_polygon: mpoly, + geometry_collection: gcoll + }) + end) + + plain = strip_ansi(log) + # Extract the VALUES(...) section of the geo_posts INSERT in one regex run + [[values_section]] = + Regex.scan( + ~r/INSERT INTO \"geo_posts\" \([^)]*\) VALUES \(([\s\S]*?)\)\s+RETURNING \"id\"/, + plain, + capture: :all_but_first + ) + + # Extract all single-quoted values from VALUES(...) + values = Regex.scan(~r/'[^']*'/, values_section) |> Enum.map(&hd/1) + + expected_values = [ + "'SRID=4326;POINT(44.21587 -87.5947)'", + "'POLYGON((2.2 41.41,2.13 41.41,2.13 41.35,2.2 41.35,2.2 41.41))'", + "'LINESTRING(0.0 0.0,1.0 1.0)'", + "'MULTIPOINT(0.0 0.0,1.0 1.0)'", + "'MULTILINESTRING((0.0 0.0,1.0 1.0))'", + "'MULTIPOLYGON(((0.0 0.0,0.0 1.0,1.0 1.0,0.0 0.0)))'", + "'GEOMETRYCOLLECTION(POINT(44.21587 -87.5947),LINESTRING(0.0 0.0,1.0 1.0))'" + ] + + assert Enum.sort(values) == Enum.sort(expected_values) + end + + test "duration" do Enum.each([0.02, 0.025, 0.05, 0.075, 0.1, 0.125, 0.15], fn duration -> Ecto.Adapters.SQL.query!(Repo, "SELECT pg_sleep(#{duration})", []) end) end - defp config do - [ - telemetry_prefix: [:my_test_app, :repo], - otp_app: :my_test_app, - timeout: 15000, - migration_timestamps: [type: :naive_datetime_usec], - database: "ecto_dev_logger_test", - hostname: "localhost", - username: "postgres", - password: "postgres", - port: 5432, - log: false, - pool_size: 10 + describe "inline_params/4" do + @params [ + nil, + "5f833165-b0d4-4d56-b21f-500d29bd94ae", + [["test"]], + %Ecto.DevLogger.NumericEnum{integer: 1, atom: true} ] + @return_to_color :yellow + test "Postgres" do + assert to_string( + Ecto.DevLogger.inline_params( + "UPDATE \"posts\" SET \"string\" = $1 WHERE \"id\" = $2 AND \"array_of_array_of_string\" = $3 OR \"priority?\" = $4 RETURNING \"id\"", + @params, + @return_to_color, + Ecto.Adapters.Postgres + ) + ) == + "UPDATE \"posts\" SET \"string\" = \e[38;5;31mNULL\e[33m WHERE \"id\" = \e[38;5;31m'5f833165-b0d4-4d56-b21f-500d29bd94ae'\e[33m AND \"array_of_array_of_string\" = \e[38;5;31m'{{test}}'\e[33m OR \"priority?\" = \e[38;5;31m1/*true*/\e[33m RETURNING \"id\"" + end + + test "Tds" do + assert to_string( + Ecto.DevLogger.inline_params( + "UPDATE \"posts\" SET \"string\" = @1 WHERE \"id\" = @2 AND \"array_of_array_of_string\" = @3 OR \"priority?\" = @4 RETURNING \"id\"", + @params, + @return_to_color, + Ecto.Adapters.Tds + ) + ) == + "UPDATE \"posts\" SET \"string\" = \e[38;5;31mNULL\e[33m WHERE \"id\" = \e[38;5;31m'5f833165-b0d4-4d56-b21f-500d29bd94ae'\e[33m AND \"array_of_array_of_string\" = \e[38;5;31m'{{test}}'\e[33m OR \"priority?\" = \e[38;5;31m1/*true*/\e[33m RETURNING \"id\"" + end + + test "MySQL" do + assert to_string( + Ecto.DevLogger.inline_params( + "UPDATE \"posts\" SET \"string\" = ? WHERE \"id\" = ? AND \"array_of_array_of_string\" = ? OR \"priority?\" = ? RETURNING \"id\"", + @params, + @return_to_color, + Ecto.Adapters.MyXQL + ) + ) == + "UPDATE \"posts\" SET \"string\" = \e[38;5;31mNULL\e[33m WHERE \"id\" = \e[38;5;31m'5f833165-b0d4-4d56-b21f-500d29bd94ae'\e[33m AND \"array_of_array_of_string\" = \e[38;5;31m'{{test}}'\e[33m OR \"priority?\" = \e[38;5;31m1/*true*/\e[33m RETURNING \"id\"" + end + + test "SQLite3" do + assert to_string( + Ecto.DevLogger.inline_params( + "UPDATE \"posts\" SET \"string\" = ? WHERE \"id\" = ? AND \"array_of_array_of_string\" = ? OR \"priority?\" = ? RETURNING \"id\"", + @params, + @return_to_color, + Ecto.Adapters.SQLite3 + ) + ) == + "UPDATE \"posts\" SET \"string\" = \e[38;5;31mNULL\e[33m WHERE \"id\" = \e[38;5;31m'5f833165-b0d4-4d56-b21f-500d29bd94ae'\e[33m AND \"array_of_array_of_string\" = \e[38;5;31m'{{test}}'\e[33m OR \"priority?\" = \e[38;5;31m1/*true*/\e[33m RETURNING \"id\"" + end + end + + test "install returns error from failure to attach " do + assert {:error, :already_exists} = Ecto.DevLogger.install(Repo) + end + + test "handler_id\1" do + assert [:ecto_dev_logger, :my_test_app, :repo] = Ecto.DevLogger.handler_id(Repo) + end + + describe "multiple repos" do + setup do + setup_repo(Repo2) + + on_exit(fn -> + teardown_repo(Repo2) + end) + end + + test "install of second repo works" do + assert :ok = Ecto.DevLogger.install(Repo2) + repo1_prefix = Repo.config()[:telemetry_prefix] + [repo1_handler] = :telemetry.list_handlers(repo1_prefix) + repo2_prefix = Repo2.config()[:telemetry_prefix] + [repo2_handler] = :telemetry.list_handlers(repo2_prefix) + # Confirm that there is a distinct handler ID for each repo + assert repo1_handler.id != repo2_handler.id + end + + test "logging for two repos, with repo name" do + ## Use options to enable logging of repo name on second repo + assert :ok = Ecto.DevLogger.install(Repo2, log_repo_name: true) + + # Log some basic queries + repo1_log = + capture_log(fn -> + %{id: post_id} = + Repo.insert!(%Post{ + datetime: ~U[2022-06-25T14:30:16.639767Z], + naive_datetime: ~N[2022-06-25T14:30:16.643949] + }) + + Repo.get!(Post, post_id) + :ok + end) + + [ + repo1_insert_start, + repo1_insert_status, + repo1_insert_query, + repo1_insert_location, + repo1_select_start, + repo1_select_status, + repo1_select_query, + repo1_select_location, + _close + ] = String.split(repo1_log, "\n") + + ## Confirm that the original repo's logging is not changed by the addition of a second repo + assert repo1_insert_start == "\e[32m" + + assert repo1_insert_status =~ + ~r/\[debug\] QUERY OK source=\e\[34m\"posts\"\e\[32m db=\d+\.\d+ms/ + + assert repo1_insert_query == + "INSERT INTO \"posts\" (\"datetime\",\"naive_datetime\") VALUES (\e[38;5;31m'2022-06-25 14:30:16.639767Z'\e[32m,\e[38;5;31m'2022-06-25 14:30:16.643949'\e[32m) RETURNING \"id\"\e[90m" + + assert repo1_insert_location =~ + ~r/↳\ anonymous\ fn\/0\ in\ Ecto\.DevLoggerTest\."test\ multiple\ repos\ logging\ for\ two\ repos,\ with\ repo\ name"\/1,\ at:\ test\/ecto\/dev_logger_test\.exs:[0-9]+/ + + assert repo1_select_start == "\e[0m\e[36m" + + assert repo1_select_status =~ + ~r/\[debug\] QUERY OK source=\e\[34m\"posts\"\e\[36m db=\d+\.\d+ms/ + + select_query_regex = + ~r/SELECT\ p0\."id",.*FROM\ "posts"\ AS\ p0\ WHERE\ \(p0\."id"\ =\ \e\[38;5;31m'[-0-9a-fA-F]+'\e\[36m\)\e\[90m/ + + assert repo1_select_query =~ select_query_regex + + assert repo1_select_location =~ + ~r/↳\ anonymous\ fn\/0\ in\ Ecto\.DevLoggerTest\."test\ multiple\ repos\ logging\ for\ two\ repos,\ with\ repo\ name"\/1,\ at:\ test\/ecto\/dev_logger_test\.exs:[0-9]+/ + + repo2_log = + capture_log(fn -> + %{id: post_id} = + Repo2.insert!(%Post{ + datetime: ~U[2022-06-25T14:30:16.639767Z], + naive_datetime: ~N[2022-06-25T14:30:16.643949] + }) + + Repo2.get!(Post, post_id) + :ok + end) + + [ + repo2_insert_start, + repo2_insert_status, + repo2_insert_query, + repo2_insert_location, + repo2_select_start, + repo2_select_status, + repo2_select_query, + repo2_select_location, + _close + ] = String.split(repo2_log, "\n") + + ## Confirm that the logging remains the same apart from the addition of the repo name in the status line. + assert repo2_insert_start == repo1_insert_start + + assert repo2_insert_status =~ + ~r/\[debug\] QUERY OK source=\e\[34m\"posts\"\e\[32m repo=\e\[34mEcto.DevLoggerTest.Repo2\e\[32m db=\d+\.\d+ms/ + + assert repo2_insert_query == repo1_insert_query + + assert repo2_insert_location =~ + ~r/↳\ anonymous\ fn\/0\ in\ Ecto\.DevLoggerTest\."test\ multiple\ repos\ logging\ for\ two\ repos,\ with\ repo\ name"\/1,\ at:\ test\/ecto\/dev_logger_test\.exs:[0-9]+/ + + assert repo2_select_start == repo1_select_start + + assert repo2_select_status =~ + ~r/\[debug\] QUERY OK source=\e\[34m\"posts\"\e\[36m repo=\e\[34mEcto.DevLoggerTest.Repo2\e\[\d+m db=\d+\.\d+ms/ + + assert repo2_select_query =~ select_query_regex + + assert repo2_select_location =~ + ~r/↳\ anonymous\ fn\/0\ in\ Ecto\.DevLoggerTest\."test\ multiple\ repos\ logging\ for\ two\ repos,\ with\ repo\ name"\/1,\ at:\ test\/ecto\/dev_logger_test\.exs:[0-9]+/ + end + end + + defp setup_repo(repo_module) do + config = repo_module.get_config() + + Application.put_env(:my_test_app, repo_module, config) + repo_module.__adapter__().storage_down(config) + repo_module.__adapter__().storage_up(config) + repo_pid = start_supervised!(repo_module) + + repo_module.query!("CREATE EXTENSION IF NOT EXISTS \"pgcrypto\";", []) + + repo_module.query!( + """ + CREATE TYPE money_type AS (currency char(3), value integer); + """, + [] + ) + + repo_module.query!( + """ + CREATE TABLE posts ( + id uuid PRIMARY KEY NOT NULL DEFAULT gen_random_uuid(), + string text, + "binary" bytea, + map jsonb, + integer integer, + decimal numeric, + date date, + time time(0) without time zone, + array_of_strings text[], + money money_type, + multi_money money_type[], + password_digest text, + datetime timestamp without time zone, + naive_datetime timestamp without time zone, + ip INET, + macaddr MACADDR, + array_of_enums integer[], + enum integer, + int_range int4range, + num_range numrange, + int8_range int8range, + ts_range tsrange, + tstz_range tstzrange, + date_range daterange + ) + """, + [] + ) + + ## Swallow the reload warning after changing DB structure. + assert capture_log(fn -> + repo_module.query!("SELECT * FROM posts") + end) =~ + "forcing us to reload type information from the database. This is expected behaviour whenever you migrate your database." + + repo_pid + end + + defp teardown_repo(repo_module) do + Ecto.DevLogger.uninstall(repo_module) + + config = repo_module.get_config() + repo_module.__adapter__().storage_down(config) + end + + def strip_ansi(string) do + Regex.replace(~r/\e\[[0-9;]*[mGKH]/, string, "") end end diff --git a/test/test_helper.exs b/test/test_helper.exs index 869559e..cf36d96 100644 --- a/test/test_helper.exs +++ b/test/test_helper.exs @@ -1 +1,2 @@ +Application.put_env(:elixir, :ansi_enabled, true) ExUnit.start()