From c7d913231fa89d6854b1dee4e24d56fd07cf25bd Mon Sep 17 00:00:00 2001 From: v0idpwn Date: Thu, 27 Mar 2025 14:24:59 -0300 Subject: [PATCH 01/20] Allow configuring stacktrace depth for logging A lot of times, more stack items can be helpful in identifying the source of a query. This commit demonstrates how we can support it. But the API has problems: 1. the `:stacktrace` option is used not only by logging but also for general telemetry events. Making it an integer doesn't make sense for telemetry (as the full stacktrace is published there anyway). 2. the `:stacktrace` option is overriden Ecto-side, so Ecto.SQL can't accept integers on a per-query basis, only on global configuration. --- integration_test/sql/logging.exs | 12 +++++++ lib/ecto/adapters/sql.ex | 62 +++++++++++++++++--------------- 2 files changed, 45 insertions(+), 29 deletions(-) diff --git a/integration_test/sql/logging.exs b/integration_test/sql/logging.exs index be1a64752..5c6e9e830 100644 --- a/integration_test/sql/logging.exs +++ b/integration_test/sql/logging.exs @@ -137,6 +137,18 @@ defmodule Ecto.Integration.LoggingTest do :ok end) =~ stacktrace_entry(__ENV__.line) + + # Bigger stacktrace size + # This fails because we don't receive per-query :stacktrace ecto-sql side, + # only the global config from adapter_meta + out = capture_log(fn -> + TestRepo.all(Post, Keyword.put(@stacktrace_opts, :stacktrace, 2)) + + :ok + end) + + assert out =~ stacktrace_entry(__ENV__.line - 2) + assert out =~ ~r/ ↳ ExUnit.CaptureLog.with_log\/2, at: lib\/ex_unit\/capture_log.ex:113/ end test "with custom log level" do diff --git a/lib/ecto/adapters/sql.ex b/lib/ecto/adapters/sql.ex index ab43205c2..dead02777 100644 --- a/lib/ecto/adapters/sql.ex +++ b/lib/ecto/adapters/sql.ex @@ -658,10 +658,11 @@ defmodule Ecto.Adapters.SQL do sql_call(adapter_meta, :query_many, [sql], params, opts) end + defp sql_call(adapter_meta, callback, args, params, opts) do - %{pid: pool, telemetry: telemetry, sql: sql, opts: default_opts} = adapter_meta + %{pid: pool, telemetry: telemetry, sql: sql, opts: default_opts, stacktrace: stacktrace_config} = adapter_meta conn = get_conn_or_pool(pool, adapter_meta) - opts = with_log(telemetry, params, opts ++ default_opts) + opts = with_log(telemetry, stacktrace_config, params, opts ++ default_opts) args = args ++ [params, opts] apply(sql, callback, [conn | args]) end @@ -872,7 +873,7 @@ defmodule Ecto.Adapters.SQL do """ end - stacktrace = Keyword.get(config, :stacktrace, nil) + stacktrace = Keyword.get(config, :stacktrace) telemetry_prefix = Keyword.fetch!(config, :telemetry_prefix) telemetry = {config[:repo], log, telemetry_prefix ++ [:query]} @@ -1097,8 +1098,8 @@ defmodule Ecto.Adapters.SQL do @doc false def reduce(adapter_meta, statement, params, opts, acc, fun) do - %{pid: pool, telemetry: telemetry, sql: sql, opts: default_opts} = adapter_meta - opts = with_log(telemetry, params, opts ++ default_opts) + %{pid: pool, telemetry: telemetry, sql: sql, stacktrace: stacktrace_config, opts: default_opts} = adapter_meta + opts = with_log(telemetry, stacktrace_config, params, opts ++ default_opts) case get_conn(pool) do %DBConnection{conn_mode: :transaction} = conn -> @@ -1113,8 +1114,8 @@ defmodule Ecto.Adapters.SQL do @doc false def into(adapter_meta, statement, params, opts) do - %{pid: pool, telemetry: telemetry, sql: sql, opts: default_opts} = adapter_meta - opts = with_log(telemetry, params, opts ++ default_opts) + %{pid: pool, telemetry: telemetry, sql: sql, opts: default_opts, stacktrace: stacktrace_config} = adapter_meta + opts = with_log(telemetry, stacktrace_config, params, opts ++ default_opts) case get_conn(pool) do %DBConnection{conn_mode: :transaction} = conn -> @@ -1231,11 +1232,11 @@ defmodule Ecto.Adapters.SQL do ## Log - defp with_log(telemetry, params, opts) do - [log: &log(telemetry, params, &1, opts)] ++ opts + defp with_log(telemetry, stacktrace_config, params, opts) do + [log: &log(telemetry, stacktrace_config, params, &1, opts)] ++ opts end - defp log({repo, log, event_name}, params, entry, opts) do + defp log({repo, log, event_name}, stacktrace_config, params, entry, opts) do %{ connection_time: query_time, decode_time: decode_time, @@ -1286,14 +1287,14 @@ defmodule Ecto.Adapters.SQL do {true, level} -> Logger.log( level, - fn -> log_iodata(measurements, repo, source, query, log_params, result, stacktrace) end, + fn -> log_iodata(measurements, repo, source, query, log_params, result, stacktrace, stacktrace_size(stacktrace_config)) end, ansi_color: sql_color(query) ) {opts_level, args_level} -> Logger.log( opts_level || args_level, - fn -> log_iodata(measurements, repo, source, query, log_params, result, stacktrace) end, + fn -> log_iodata(measurements, repo, source, query, log_params, result, stacktrace, stacktrace_size(stacktrace_config)) end, ansi_color: sql_color(query) ) end @@ -1301,6 +1302,9 @@ defmodule Ecto.Adapters.SQL do :ok end + defp stacktrace_size(val) when is_integer(val), do: val + defp stacktrace_size(_), do: 1 + defp log_measurements([{_, nil} | rest], total, acc), do: log_measurements(rest, total, acc) @@ -1310,7 +1314,7 @@ defmodule Ecto.Adapters.SQL do defp log_measurements([], total, acc), do: Map.new([total_time: total] ++ acc) - defp log_iodata(measurements, repo, source, query, params, result, stacktrace) do + defp log_iodata(measurements, repo, source, query, params, result, stacktrace, stacktrace_size) do [ "QUERY", ?\s, @@ -1324,7 +1328,7 @@ defmodule Ecto.Adapters.SQL do query, ?\s, inspect(params, charlists: false), - log_stacktrace(stacktrace, repo) + log_stacktrace(stacktrace, repo, stacktrace_size) ] end @@ -1351,19 +1355,19 @@ defmodule Ecto.Adapters.SQL do end end - defp log_stacktrace(stacktrace, repo) do - with [_ | _] <- stacktrace, - {module, function, arity, info} <- last_non_ecto(Enum.reverse(stacktrace), repo, nil) do + defp log_stacktrace([], _, _), do: [] + + defp log_stacktrace(stacktrace, repo, size) do + for {{module, function, arity, info}, idx} <- Enum.with_index(last_non_ecto(Enum.reverse(stacktrace), repo, size)) do [ ?\n, IO.ANSI.light_black(), + List.duplicate(?\s, 2 * idx), "↳ ", Exception.format_mfa(module, function, arity), log_stacktrace_info(info), IO.ANSI.reset() ] - else - _ -> [] end end @@ -1377,21 +1381,21 @@ defmodule Ecto.Adapters.SQL do @repo_modules [Ecto.Repo.Queryable, Ecto.Repo.Schema, Ecto.Repo.Transaction] - defp last_non_ecto([{mod, _, _, _} | _stacktrace], repo, last) - when mod == repo or mod in @repo_modules, - do: last - - defp last_non_ecto([last | stacktrace], repo, _last), - do: last_non_ecto(stacktrace, repo, last) + defp last_non_ecto(stacktrace, repo, size) do + stacktrace + |> last_non_ecto_entries(repo, []) + |> Enum.take(size) + end - defp last_non_ecto([], _repo, last), - do: last + defp last_non_ecto_entries([{mod, _, _, _} | _], repo, acc) when mod == repo or mod in @repo_modules, do: acc + defp last_non_ecto_entries([entry | rest], repo, acc), do: last_non_ecto_entries(rest, repo, [entry | acc]) + defp last_non_ecto_entries([], _, acc), do: acc ## Connection helpers defp checkout_or_transaction(fun, adapter_meta, opts, callback) do - %{pid: pool, telemetry: telemetry, opts: default_opts} = adapter_meta - opts = with_log(telemetry, [], opts ++ default_opts) + %{pid: pool, telemetry: telemetry, opts: default_opts, stacktrace: stacktrace_config} = adapter_meta + opts = with_log(telemetry, stacktrace_config, [], opts ++ default_opts) callback = fn conn -> previous_conn = put_conn(pool, conn) From 56943fb9ef061546dc6a7157b0b6bff483fadcd5 Mon Sep 17 00:00:00 2001 From: v0idpwn Date: Thu, 27 Mar 2025 15:08:15 -0300 Subject: [PATCH 02/20] Bugfix --- integration_test/sql/logging.exs | 2 ++ lib/ecto/adapters/sql.ex | 6 +++--- 2 files changed, 5 insertions(+), 3 deletions(-) diff --git a/integration_test/sql/logging.exs b/integration_test/sql/logging.exs index 5c6e9e830..b6f135475 100644 --- a/integration_test/sql/logging.exs +++ b/integration_test/sql/logging.exs @@ -201,6 +201,8 @@ defmodule Ecto.Integration.LoggingTest do TestRepo.insert_all(Logging, source_query, log: :info) end) + IO.inspect(log, label: :log) + param_regex = ~r/\[(?.+), \"(?.+)\"\]/ param_logs = Regex.named_captures(param_regex, log) diff --git a/lib/ecto/adapters/sql.ex b/lib/ecto/adapters/sql.ex index dead02777..0960c8b99 100644 --- a/lib/ecto/adapters/sql.ex +++ b/lib/ecto/adapters/sql.ex @@ -1355,9 +1355,7 @@ defmodule Ecto.Adapters.SQL do end end - defp log_stacktrace([], _, _), do: [] - - defp log_stacktrace(stacktrace, repo, size) do + defp log_stacktrace([_ | _] = stacktrace, repo, size) do for {{module, function, arity, info}, idx} <- Enum.with_index(last_non_ecto(Enum.reverse(stacktrace), repo, size)) do [ ?\n, @@ -1371,6 +1369,8 @@ defmodule Ecto.Adapters.SQL do end end + defp log_stacktrace(_, _, _), do: [] + defp log_stacktrace_info([file: file, line: line] ++ _) do [", at: ", file, ?:, Integer.to_string(line)] end From ee79088d4aec11652dc7befe0a957b0d2263aed1 Mon Sep 17 00:00:00 2001 From: v0idpwn Date: Fri, 28 Mar 2025 09:56:08 -0300 Subject: [PATCH 03/20] Support MFA for stacktrace Left the alternative `last_non_ecto` implementation taking a parameter for length. Goal is to make it easier to just increase the length without needing to implement a new function or use a 3rd party package. --- integration_test/sql/logging.exs | 8 ++------ lib/ecto/adapters/sql.ex | 26 +++++++++++++++++++------- 2 files changed, 21 insertions(+), 13 deletions(-) diff --git a/integration_test/sql/logging.exs b/integration_test/sql/logging.exs index b6f135475..dee5d1a55 100644 --- a/integration_test/sql/logging.exs +++ b/integration_test/sql/logging.exs @@ -138,11 +138,9 @@ defmodule Ecto.Integration.LoggingTest do :ok end) =~ stacktrace_entry(__ENV__.line) - # Bigger stacktrace size - # This fails because we don't receive per-query :stacktrace ecto-sql side, - # only the global config from adapter_meta + # Requires upstream change in Ecto to pass out = capture_log(fn -> - TestRepo.all(Post, Keyword.put(@stacktrace_opts, :stacktrace, 2)) + TestRepo.all(Post, Keyword.put(@stacktrace_opts, :stacktrace, {Ecto.Adapters.SQL, :last_non_ecto, [2]})) :ok end) @@ -201,8 +199,6 @@ defmodule Ecto.Integration.LoggingTest do TestRepo.insert_all(Logging, source_query, log: :info) end) - IO.inspect(log, label: :log) - param_regex = ~r/\[(?.+), \"(?.+)\"\]/ param_logs = Regex.named_captures(param_regex, log) diff --git a/lib/ecto/adapters/sql.ex b/lib/ecto/adapters/sql.ex index 0960c8b99..373fdcfa1 100644 --- a/lib/ecto/adapters/sql.ex +++ b/lib/ecto/adapters/sql.ex @@ -1287,14 +1287,14 @@ defmodule Ecto.Adapters.SQL do {true, level} -> Logger.log( level, - fn -> log_iodata(measurements, repo, source, query, log_params, result, stacktrace, stacktrace_size(stacktrace_config)) end, + fn -> log_iodata(measurements, repo, source, query, log_params, result, stacktrace, stacktrace_mfa(stacktrace_config, opts)) end, ansi_color: sql_color(query) ) {opts_level, args_level} -> Logger.log( opts_level || args_level, - fn -> log_iodata(measurements, repo, source, query, log_params, result, stacktrace, stacktrace_size(stacktrace_config)) end, + fn -> log_iodata(measurements, repo, source, query, log_params, result, stacktrace, stacktrace_mfa(stacktrace_config, opts)) end, ansi_color: sql_color(query) ) end @@ -1302,8 +1302,18 @@ defmodule Ecto.Adapters.SQL do :ok end - defp stacktrace_size(val) when is_integer(val), do: val - defp stacktrace_size(_), do: 1 + defp stacktrace_mfa(stacktrace_config, opts) do + case Keyword.get(opts, :log_stacktrace_mfa) do + {_, _, _} = mfa -> + mfa + + _ -> + case stacktrace_config do + {_, _, _} = mfa -> mfa + _ -> {__MODULE__, :last_non_ecto, [1]} + end + end + end defp log_measurements([{_, nil} | rest], total, acc), do: log_measurements(rest, total, acc) @@ -1355,8 +1365,10 @@ defmodule Ecto.Adapters.SQL do end end - defp log_stacktrace([_ | _] = stacktrace, repo, size) do - for {{module, function, arity, info}, idx} <- Enum.with_index(last_non_ecto(Enum.reverse(stacktrace), repo, size)) do + defp log_stacktrace([_ | _] = stacktrace, repo, {module, function, args}) do + entries = apply(module, function, args ++ [Enum.reverse(stacktrace), repo]) + + for {{module, function, arity, info}, idx} <- Enum.with_index(entries) do [ ?\n, IO.ANSI.light_black(), @@ -1381,7 +1393,7 @@ defmodule Ecto.Adapters.SQL do @repo_modules [Ecto.Repo.Queryable, Ecto.Repo.Schema, Ecto.Repo.Transaction] - defp last_non_ecto(stacktrace, repo, size) do + def last_non_ecto(size, stacktrace, repo) do stacktrace |> last_non_ecto_entries(repo, []) |> Enum.take(size) From cfb655f6597ba52ffdc884c21c6d4968e08dfb65 Mon Sep 17 00:00:00 2001 From: v0idpwn Date: Fri, 28 Mar 2025 18:59:59 -0300 Subject: [PATCH 04/20] Accept on config as well --- integration_test/sql/logging.exs | 2 +- lib/ecto/adapters/sql.ex | 35 ++++++++++++++++---------------- 2 files changed, 18 insertions(+), 19 deletions(-) diff --git a/integration_test/sql/logging.exs b/integration_test/sql/logging.exs index dee5d1a55..66ea7f0ab 100644 --- a/integration_test/sql/logging.exs +++ b/integration_test/sql/logging.exs @@ -140,7 +140,7 @@ defmodule Ecto.Integration.LoggingTest do # Requires upstream change in Ecto to pass out = capture_log(fn -> - TestRepo.all(Post, Keyword.put(@stacktrace_opts, :stacktrace, {Ecto.Adapters.SQL, :last_non_ecto, [2]})) + TestRepo.all(Post, Keyword.put(@stacktrace_opts, :log_stacktrace_mfa, {Ecto.Adapters.SQL, :last_non_ecto, [2]})) :ok end) diff --git a/lib/ecto/adapters/sql.ex b/lib/ecto/adapters/sql.ex index 373fdcfa1..e66b23d51 100644 --- a/lib/ecto/adapters/sql.ex +++ b/lib/ecto/adapters/sql.ex @@ -660,9 +660,9 @@ defmodule Ecto.Adapters.SQL do defp sql_call(adapter_meta, callback, args, params, opts) do - %{pid: pool, telemetry: telemetry, sql: sql, opts: default_opts, stacktrace: stacktrace_config} = adapter_meta + %{pid: pool, telemetry: telemetry, sql: sql, opts: default_opts, log_stacktrace_mfa: log_stacktrace_mfa} = adapter_meta conn = get_conn_or_pool(pool, adapter_meta) - opts = with_log(telemetry, stacktrace_config, params, opts ++ default_opts) + opts = with_log(telemetry, log_stacktrace_mfa, params, opts ++ default_opts) args = args ++ [params, opts] apply(sql, callback, [conn | args]) end @@ -861,6 +861,7 @@ defmodule Ecto.Adapters.SQL do end log = Keyword.get(config, :log, :debug) + log_stacktrace_mfa = Keyword.get(config, :log_stacktrace_mfa, {__MODULE__, :last_non_ecto, [1]}) if log not in @valid_log_levels do raise """ @@ -886,6 +887,7 @@ defmodule Ecto.Adapters.SQL do telemetry: telemetry, sql: connection, stacktrace: stacktrace, + log_stacktrace_mfa: log_stacktrace_mfa, opts: Keyword.take(config, @pool_opts) } @@ -1098,8 +1100,8 @@ defmodule Ecto.Adapters.SQL do @doc false def reduce(adapter_meta, statement, params, opts, acc, fun) do - %{pid: pool, telemetry: telemetry, sql: sql, stacktrace: stacktrace_config, opts: default_opts} = adapter_meta - opts = with_log(telemetry, stacktrace_config, params, opts ++ default_opts) + %{pid: pool, telemetry: telemetry, sql: sql, log_stacktrace_mfa: log_stacktrace_mfa, opts: default_opts} = adapter_meta + opts = with_log(telemetry, log_stacktrace_mfa, params, opts ++ default_opts) case get_conn(pool) do %DBConnection{conn_mode: :transaction} = conn -> @@ -1114,8 +1116,8 @@ defmodule Ecto.Adapters.SQL do @doc false def into(adapter_meta, statement, params, opts) do - %{pid: pool, telemetry: telemetry, sql: sql, opts: default_opts, stacktrace: stacktrace_config} = adapter_meta - opts = with_log(telemetry, stacktrace_config, params, opts ++ default_opts) + %{pid: pool, telemetry: telemetry, sql: sql, opts: default_opts, log_stacktrace_mfa: log_stacktrace_mfa} = adapter_meta + opts = with_log(telemetry, log_stacktrace_mfa, params, opts ++ default_opts) case get_conn(pool) do %DBConnection{conn_mode: :transaction} = conn -> @@ -1232,11 +1234,11 @@ defmodule Ecto.Adapters.SQL do ## Log - defp with_log(telemetry, stacktrace_config, params, opts) do - [log: &log(telemetry, stacktrace_config, params, &1, opts)] ++ opts + defp with_log(telemetry, log_stacktrace_mfa, params, opts) do + [log: &log(telemetry, log_stacktrace_mfa, params, &1, opts)] ++ opts end - defp log({repo, log, event_name}, stacktrace_config, params, entry, opts) do + defp log({repo, log, event_name}, log_stacktrace_mfa, params, entry, opts) do %{ connection_time: query_time, decode_time: decode_time, @@ -1287,14 +1289,14 @@ defmodule Ecto.Adapters.SQL do {true, level} -> Logger.log( level, - fn -> log_iodata(measurements, repo, source, query, log_params, result, stacktrace, stacktrace_mfa(stacktrace_config, opts)) end, + fn -> log_iodata(measurements, repo, source, query, log_params, result, stacktrace, stacktrace_mfa(log_stacktrace_mfa, opts)) end, ansi_color: sql_color(query) ) {opts_level, args_level} -> Logger.log( opts_level || args_level, - fn -> log_iodata(measurements, repo, source, query, log_params, result, stacktrace, stacktrace_mfa(stacktrace_config, opts)) end, + fn -> log_iodata(measurements, repo, source, query, log_params, result, stacktrace, stacktrace_mfa(log_stacktrace_mfa, opts)) end, ansi_color: sql_color(query) ) end @@ -1302,16 +1304,13 @@ defmodule Ecto.Adapters.SQL do :ok end - defp stacktrace_mfa(stacktrace_config, opts) do + defp stacktrace_mfa(log_stacktrace_mfa, opts) do case Keyword.get(opts, :log_stacktrace_mfa) do {_, _, _} = mfa -> mfa _ -> - case stacktrace_config do - {_, _, _} = mfa -> mfa - _ -> {__MODULE__, :last_non_ecto, [1]} - end + log_stacktrace_mfa end end @@ -1406,8 +1405,8 @@ defmodule Ecto.Adapters.SQL do ## Connection helpers defp checkout_or_transaction(fun, adapter_meta, opts, callback) do - %{pid: pool, telemetry: telemetry, opts: default_opts, stacktrace: stacktrace_config} = adapter_meta - opts = with_log(telemetry, stacktrace_config, [], opts ++ default_opts) + %{pid: pool, telemetry: telemetry, opts: default_opts, log_stacktrace_mfa: log_stacktrace_mfa} = adapter_meta + opts = with_log(telemetry, log_stacktrace_mfa, [], opts ++ default_opts) callback = fn conn -> previous_conn = put_conn(pool, conn) From 80e5eb8501e10f2e9294f0193453e5acf0922795 Mon Sep 17 00:00:00 2001 From: v0idpwn Date: Fri, 28 Mar 2025 19:12:57 -0300 Subject: [PATCH 05/20] Rename function --- integration_test/sql/logging.exs | 2 +- lib/ecto/adapters/sql.ex | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/integration_test/sql/logging.exs b/integration_test/sql/logging.exs index 66ea7f0ab..1b533da68 100644 --- a/integration_test/sql/logging.exs +++ b/integration_test/sql/logging.exs @@ -140,7 +140,7 @@ defmodule Ecto.Integration.LoggingTest do # Requires upstream change in Ecto to pass out = capture_log(fn -> - TestRepo.all(Post, Keyword.put(@stacktrace_opts, :log_stacktrace_mfa, {Ecto.Adapters.SQL, :last_non_ecto, [2]})) + TestRepo.all(Post, Keyword.put(@stacktrace_opts, :log_stacktrace_mfa, {Ecto.Adapters.SQL, :last_non_ecto_stacktrace, [2]})) :ok end) diff --git a/lib/ecto/adapters/sql.ex b/lib/ecto/adapters/sql.ex index e66b23d51..797be1c51 100644 --- a/lib/ecto/adapters/sql.ex +++ b/lib/ecto/adapters/sql.ex @@ -861,7 +861,7 @@ defmodule Ecto.Adapters.SQL do end log = Keyword.get(config, :log, :debug) - log_stacktrace_mfa = Keyword.get(config, :log_stacktrace_mfa, {__MODULE__, :last_non_ecto, [1]}) + log_stacktrace_mfa = Keyword.get(config, :log_stacktrace_mfa, {__MODULE__, :last_non_ecto_stacktrace, [1]}) if log not in @valid_log_levels do raise """ @@ -1392,7 +1392,7 @@ defmodule Ecto.Adapters.SQL do @repo_modules [Ecto.Repo.Queryable, Ecto.Repo.Schema, Ecto.Repo.Transaction] - def last_non_ecto(size, stacktrace, repo) do + def last_non_ecto_stacktrace(size, stacktrace, repo) do stacktrace |> last_non_ecto_entries(repo, []) |> Enum.take(size) From 8c7a04f35ce26cb330de4c3e949bb0f52840a73d Mon Sep 17 00:00:00 2001 From: v0idpwn Date: Fri, 28 Mar 2025 19:17:58 -0300 Subject: [PATCH 06/20] format --- lib/ecto/adapters/sql.ex | 71 ++++++++++++++++++++++++++++++++++------ 1 file changed, 61 insertions(+), 10 deletions(-) diff --git a/lib/ecto/adapters/sql.ex b/lib/ecto/adapters/sql.ex index 797be1c51..810d86fb7 100644 --- a/lib/ecto/adapters/sql.ex +++ b/lib/ecto/adapters/sql.ex @@ -658,9 +658,15 @@ defmodule Ecto.Adapters.SQL do sql_call(adapter_meta, :query_many, [sql], params, opts) end - defp sql_call(adapter_meta, callback, args, params, opts) do - %{pid: pool, telemetry: telemetry, sql: sql, opts: default_opts, log_stacktrace_mfa: log_stacktrace_mfa} = adapter_meta + %{ + pid: pool, + telemetry: telemetry, + sql: sql, + opts: default_opts, + log_stacktrace_mfa: log_stacktrace_mfa + } = adapter_meta + conn = get_conn_or_pool(pool, adapter_meta) opts = with_log(telemetry, log_stacktrace_mfa, params, opts ++ default_opts) args = args ++ [params, opts] @@ -861,7 +867,9 @@ defmodule Ecto.Adapters.SQL do end log = Keyword.get(config, :log, :debug) - log_stacktrace_mfa = Keyword.get(config, :log_stacktrace_mfa, {__MODULE__, :last_non_ecto_stacktrace, [1]}) + + log_stacktrace_mfa = + Keyword.get(config, :log_stacktrace_mfa, {__MODULE__, :last_non_ecto_stacktrace, [1]}) if log not in @valid_log_levels do raise """ @@ -1100,7 +1108,14 @@ defmodule Ecto.Adapters.SQL do @doc false def reduce(adapter_meta, statement, params, opts, acc, fun) do - %{pid: pool, telemetry: telemetry, sql: sql, log_stacktrace_mfa: log_stacktrace_mfa, opts: default_opts} = adapter_meta + %{ + pid: pool, + telemetry: telemetry, + sql: sql, + log_stacktrace_mfa: log_stacktrace_mfa, + opts: default_opts + } = adapter_meta + opts = with_log(telemetry, log_stacktrace_mfa, params, opts ++ default_opts) case get_conn(pool) do @@ -1116,7 +1131,14 @@ defmodule Ecto.Adapters.SQL do @doc false def into(adapter_meta, statement, params, opts) do - %{pid: pool, telemetry: telemetry, sql: sql, opts: default_opts, log_stacktrace_mfa: log_stacktrace_mfa} = adapter_meta + %{ + pid: pool, + telemetry: telemetry, + sql: sql, + opts: default_opts, + log_stacktrace_mfa: log_stacktrace_mfa + } = adapter_meta + opts = with_log(telemetry, log_stacktrace_mfa, params, opts ++ default_opts) case get_conn(pool) do @@ -1289,14 +1311,36 @@ defmodule Ecto.Adapters.SQL do {true, level} -> Logger.log( level, - fn -> log_iodata(measurements, repo, source, query, log_params, result, stacktrace, stacktrace_mfa(log_stacktrace_mfa, opts)) end, + fn -> + log_iodata( + measurements, + repo, + source, + query, + log_params, + result, + stacktrace, + stacktrace_mfa(log_stacktrace_mfa, opts) + ) + end, ansi_color: sql_color(query) ) {opts_level, args_level} -> Logger.log( opts_level || args_level, - fn -> log_iodata(measurements, repo, source, query, log_params, result, stacktrace, stacktrace_mfa(log_stacktrace_mfa, opts)) end, + fn -> + log_iodata( + measurements, + repo, + source, + query, + log_params, + result, + stacktrace, + stacktrace_mfa(log_stacktrace_mfa, opts) + ) + end, ansi_color: sql_color(query) ) end @@ -1398,14 +1442,21 @@ defmodule Ecto.Adapters.SQL do |> Enum.take(size) end - defp last_non_ecto_entries([{mod, _, _, _} | _], repo, acc) when mod == repo or mod in @repo_modules, do: acc - defp last_non_ecto_entries([entry | rest], repo, acc), do: last_non_ecto_entries(rest, repo, [entry | acc]) + defp last_non_ecto_entries([{mod, _, _, _} | _], repo, acc) + when mod == repo or mod in @repo_modules, + do: acc + + defp last_non_ecto_entries([entry | rest], repo, acc), + do: last_non_ecto_entries(rest, repo, [entry | acc]) + defp last_non_ecto_entries([], _, acc), do: acc ## Connection helpers defp checkout_or_transaction(fun, adapter_meta, opts, callback) do - %{pid: pool, telemetry: telemetry, opts: default_opts, log_stacktrace_mfa: log_stacktrace_mfa} = adapter_meta + %{pid: pool, telemetry: telemetry, opts: default_opts, log_stacktrace_mfa: log_stacktrace_mfa} = + adapter_meta + opts = with_log(telemetry, log_stacktrace_mfa, [], opts ++ default_opts) callback = fn conn -> From e0d2c48d5a1a8c4bb3742f064cd150e0e364c7ef Mon Sep 17 00:00:00 2001 From: v0idpwn Date: Fri, 28 Mar 2025 19:23:42 -0300 Subject: [PATCH 07/20] Refactoring --- lib/ecto/adapters/sql.ex | 14 ++------------ 1 file changed, 2 insertions(+), 12 deletions(-) diff --git a/lib/ecto/adapters/sql.ex b/lib/ecto/adapters/sql.ex index 810d86fb7..8388abb84 100644 --- a/lib/ecto/adapters/sql.ex +++ b/lib/ecto/adapters/sql.ex @@ -1320,7 +1320,7 @@ defmodule Ecto.Adapters.SQL do log_params, result, stacktrace, - stacktrace_mfa(log_stacktrace_mfa, opts) + opts[:log_stacktrace_mfa] || log_stacktrace_mfa ) end, ansi_color: sql_color(query) @@ -1338,7 +1338,7 @@ defmodule Ecto.Adapters.SQL do log_params, result, stacktrace, - stacktrace_mfa(log_stacktrace_mfa, opts) + opts[:log_stacktrace_mfa] || log_stacktrace_mfa ) end, ansi_color: sql_color(query) @@ -1348,16 +1348,6 @@ defmodule Ecto.Adapters.SQL do :ok end - defp stacktrace_mfa(log_stacktrace_mfa, opts) do - case Keyword.get(opts, :log_stacktrace_mfa) do - {_, _, _} = mfa -> - mfa - - _ -> - log_stacktrace_mfa - end - end - defp log_measurements([{_, nil} | rest], total, acc), do: log_measurements(rest, total, acc) From 392983b73e85593a2a9dfdad60b5ed8f0a70d9b8 Mon Sep 17 00:00:00 2001 From: felipe stival <14948182+v0idpwn@users.noreply.github.com> Date: Fri, 28 Mar 2025 19:24:31 -0300 Subject: [PATCH 08/20] Remove dead comment --- integration_test/sql/logging.exs | 1 - 1 file changed, 1 deletion(-) diff --git a/integration_test/sql/logging.exs b/integration_test/sql/logging.exs index 1b533da68..c2ff0f570 100644 --- a/integration_test/sql/logging.exs +++ b/integration_test/sql/logging.exs @@ -138,7 +138,6 @@ defmodule Ecto.Integration.LoggingTest do :ok end) =~ stacktrace_entry(__ENV__.line) - # Requires upstream change in Ecto to pass out = capture_log(fn -> TestRepo.all(Post, Keyword.put(@stacktrace_opts, :log_stacktrace_mfa, {Ecto.Adapters.SQL, :last_non_ecto_stacktrace, [2]})) From 76df110e4b386f83ac6dcd5d9edad81836591f64 Mon Sep 17 00:00:00 2001 From: v0idpwn Date: Fri, 28 Mar 2025 19:30:45 -0300 Subject: [PATCH 09/20] Make test less strict about elixir internals --- integration_test/sql/logging.exs | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/integration_test/sql/logging.exs b/integration_test/sql/logging.exs index c2ff0f570..c1777852e 100644 --- a/integration_test/sql/logging.exs +++ b/integration_test/sql/logging.exs @@ -145,7 +145,9 @@ defmodule Ecto.Integration.LoggingTest do end) assert out =~ stacktrace_entry(__ENV__.line - 2) - assert out =~ ~r/ ↳ ExUnit.CaptureLog.with_log\/2, at: lib\/ex_unit\/capture_log.ex:113/ + + # We are a bit liberal with what we expect as we don't want to tie to internal ExUnit code + assert out =~ ~r/ ↳ ExUnit.CaptureLog.*/ end test "with custom log level" do From 3ef99bcd7fe9badc2c0f7dc66ac23ec4641d8502 Mon Sep 17 00:00:00 2001 From: v0idpwn Date: Sat, 29 Mar 2025 13:11:20 -0300 Subject: [PATCH 10/20] Address review comments --- integration_test/sql/logging.exs | 2 +- lib/ecto/adapters/sql.ex | 11 ++++++----- 2 files changed, 7 insertions(+), 6 deletions(-) diff --git a/integration_test/sql/logging.exs b/integration_test/sql/logging.exs index c1777852e..e22380495 100644 --- a/integration_test/sql/logging.exs +++ b/integration_test/sql/logging.exs @@ -139,7 +139,7 @@ defmodule Ecto.Integration.LoggingTest do end) =~ stacktrace_entry(__ENV__.line) out = capture_log(fn -> - TestRepo.all(Post, Keyword.put(@stacktrace_opts, :log_stacktrace_mfa, {Ecto.Adapters.SQL, :last_non_ecto_stacktrace, [2]})) + TestRepo.all(Post, Keyword.put(@stacktrace_opts, :log_stacktrace_mfa, {Ecto.Adapters.SQL, :first_non_ecto_stacktrace, [2]})) :ok end) diff --git a/lib/ecto/adapters/sql.ex b/lib/ecto/adapters/sql.ex index 8388abb84..a7f576ab2 100644 --- a/lib/ecto/adapters/sql.ex +++ b/lib/ecto/adapters/sql.ex @@ -869,7 +869,7 @@ defmodule Ecto.Adapters.SQL do log = Keyword.get(config, :log, :debug) log_stacktrace_mfa = - Keyword.get(config, :log_stacktrace_mfa, {__MODULE__, :last_non_ecto_stacktrace, [1]}) + Keyword.get(config, :log_stacktrace_mfa, {__MODULE__, :first_non_ecto_stacktrace, [1]}) if log not in @valid_log_levels do raise """ @@ -1399,9 +1399,9 @@ defmodule Ecto.Adapters.SQL do end defp log_stacktrace([_ | _] = stacktrace, repo, {module, function, args}) do - entries = apply(module, function, args ++ [Enum.reverse(stacktrace), repo]) + entries = apply(module, function, [stacktrace, repo | args]) - for {{module, function, arity, info}, idx} <- Enum.with_index(entries) do + Enum.with_index(entries, fn {module, function, arity, info}, idx -> [ ?\n, IO.ANSI.light_black(), @@ -1411,7 +1411,7 @@ defmodule Ecto.Adapters.SQL do log_stacktrace_info(info), IO.ANSI.reset() ] - end + end) end defp log_stacktrace(_, _, _), do: [] @@ -1426,8 +1426,9 @@ defmodule Ecto.Adapters.SQL do @repo_modules [Ecto.Repo.Queryable, Ecto.Repo.Schema, Ecto.Repo.Transaction] - def last_non_ecto_stacktrace(size, stacktrace, repo) do + def first_non_ecto_stacktrace(stacktrace, repo, size) do stacktrace + |> Enum.reverse() |> last_non_ecto_entries(repo, []) |> Enum.take(size) end From 8013fc1ab7236914bb0035272108c89ad8cd7f57 Mon Sep 17 00:00:00 2001 From: felipe stival <14948182+v0idpwn@users.noreply.github.com> Date: Sat, 29 Mar 2025 13:32:07 -0300 Subject: [PATCH 11/20] No staircase MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: José Valim --- lib/ecto/adapters/sql.ex | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/lib/ecto/adapters/sql.ex b/lib/ecto/adapters/sql.ex index a7f576ab2..f605c470b 100644 --- a/lib/ecto/adapters/sql.ex +++ b/lib/ecto/adapters/sql.ex @@ -1405,8 +1405,7 @@ defmodule Ecto.Adapters.SQL do [ ?\n, IO.ANSI.light_black(), - List.duplicate(?\s, 2 * idx), - "↳ ", + if(idx == 0, do: "↳ ", else: " "), Exception.format_mfa(module, function, arity), log_stacktrace_info(info), IO.ANSI.reset() From bc55c5ba19a68a962c75ad6844a11a0ef65085bb Mon Sep 17 00:00:00 2001 From: v0idpwn Date: Sat, 29 Mar 2025 13:36:01 -0300 Subject: [PATCH 12/20] Fix test (no staircase) --- integration_test/sql/logging.exs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/integration_test/sql/logging.exs b/integration_test/sql/logging.exs index e22380495..0f92e9a7f 100644 --- a/integration_test/sql/logging.exs +++ b/integration_test/sql/logging.exs @@ -147,7 +147,7 @@ defmodule Ecto.Integration.LoggingTest do assert out =~ stacktrace_entry(__ENV__.line - 2) # We are a bit liberal with what we expect as we don't want to tie to internal ExUnit code - assert out =~ ~r/ ↳ ExUnit.CaptureLog.*/ + assert out =~ ~r/ ExUnit.CaptureLog.*/ end test "with custom log level" do From f833e9a1ea5379413e6420abc6226eb99e7c526a Mon Sep 17 00:00:00 2001 From: v0idpwn Date: Sat, 29 Mar 2025 13:54:55 -0300 Subject: [PATCH 13/20] Try bumping integration suite to run on elixir 1.14 --- .github/workflows/ci.yml | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 49315f477..ed42f476a 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -52,7 +52,7 @@ jobs: fail-fast: false matrix: elixirbase: - - "1.11.4-erlang-23.3.4.9-alpine-3.16.9" + - "1.14.5-erlang-23.3.4.9-alpine-3.16.9" postgres: - "16.2-alpine" - "11.11-alpine" @@ -61,7 +61,7 @@ jobs: pool_count: - "1" include: - - elixirbase: "1.11.4-erlang-23.3.4.9-alpine-3.16.9" + - elixirbase: "1.14.5-erlang-23.3.4.9-alpine-3.16.9" postgres: "16.2-alpine" pool_count: "4" steps: @@ -79,7 +79,7 @@ jobs: fail-fast: false matrix: elixirbase: - - "1.11.4-erlang-23.3.4.9-alpine-3.16.9" + - "1.14.5-erlang-23.3.4.9-alpine-3.16.9" mysql: - "5.7" - "8.0" @@ -96,7 +96,7 @@ jobs: fail-fast: false matrix: elixirbase: - - "1.11.4-erlang-23.3.4.9-alpine-3.16.9" + - "1.14.5-erlang-23.3.4.9-alpine-3.16.9" mssql: - "2017" - "2019" From 5dea66b26cc8603ca29bc5b3f1fc8a6b03091d39 Mon Sep 17 00:00:00 2001 From: v0idpwn Date: Sat, 29 Mar 2025 14:04:11 -0300 Subject: [PATCH 14/20] Fix misnamed variable --- lib/ecto/adapters/sql.ex | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/lib/ecto/adapters/sql.ex b/lib/ecto/adapters/sql.ex index f605c470b..e93f8d219 100644 --- a/lib/ecto/adapters/sql.ex +++ b/lib/ecto/adapters/sql.ex @@ -1357,7 +1357,7 @@ defmodule Ecto.Adapters.SQL do defp log_measurements([], total, acc), do: Map.new([total_time: total] ++ acc) - defp log_iodata(measurements, repo, source, query, params, result, stacktrace, stacktrace_size) do + defp log_iodata(measurements, repo, source, query, params, result, stacktrace, stacktrace_mfa) do [ "QUERY", ?\s, @@ -1371,7 +1371,7 @@ defmodule Ecto.Adapters.SQL do query, ?\s, inspect(params, charlists: false), - log_stacktrace(stacktrace, repo, stacktrace_size) + log_stacktrace(stacktrace, repo, stacktrace_mfa) ] end From dc24a9a43daed30c3db8920e4006470ef505002f Mon Sep 17 00:00:00 2001 From: v0idpwn Date: Sat, 29 Mar 2025 14:52:31 -0300 Subject: [PATCH 15/20] Bump required elixir version Ecto already requires ~> 1.14 --- mix.exs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/mix.exs b/mix.exs index f7847df93..59b79ffdd 100644 --- a/mix.exs +++ b/mix.exs @@ -9,7 +9,7 @@ defmodule EctoSQL.MixProject do [ app: :ecto_sql, version: @version, - elixir: "~> 1.11", + elixir: "~> 1.14", deps: deps(), test_paths: test_paths(System.get_env("ECTO_ADAPTER")), xref: [ From da99c79f25c2487ed0e6ba89356fd8ddb35ab451 Mon Sep 17 00:00:00 2001 From: v0idpwn Date: Sun, 30 Mar 2025 13:53:48 -0300 Subject: [PATCH 16/20] Draft documentation --- lib/ecto/adapters/sql.ex | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/lib/ecto/adapters/sql.ex b/lib/ecto/adapters/sql.ex index e93f8d219..8852ff87f 100644 --- a/lib/ecto/adapters/sql.ex +++ b/lib/ecto/adapters/sql.ex @@ -1425,6 +1425,14 @@ defmodule Ecto.Adapters.SQL do @repo_modules [Ecto.Repo.Queryable, Ecto.Repo.Schema, Ecto.Repo.Transaction] + @doc """ + Receives a stacktrace, and return the first N items before Ecto entries + + This function is used by default in the `:log_stacktrace_info` config, with + a size of 1. + """ + @spec first_non_ecto_stacktrace(Exception.stacktrace(), Ecto.Repo.t(), non_neg_integer()) :: + Exception.stacktrace() def first_non_ecto_stacktrace(stacktrace, repo, size) do stacktrace |> Enum.reverse() From 2a0b542c1e08d4936588217ba5ab4df7925d9d1f Mon Sep 17 00:00:00 2001 From: felipe stival <14948182+v0idpwn@users.noreply.github.com> Date: Mon, 31 Mar 2025 15:59:44 -0300 Subject: [PATCH 17/20] Fix mistake in docs Co-authored-by: Greg Rychlewski --- lib/ecto/adapters/sql.ex | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/ecto/adapters/sql.ex b/lib/ecto/adapters/sql.ex index 8852ff87f..7e7dd4f1c 100644 --- a/lib/ecto/adapters/sql.ex +++ b/lib/ecto/adapters/sql.ex @@ -1428,7 +1428,7 @@ defmodule Ecto.Adapters.SQL do @doc """ Receives a stacktrace, and return the first N items before Ecto entries - This function is used by default in the `:log_stacktrace_info` config, with + This function is used by default in the `:log_stacktrace_mfa` config, with a size of 1. """ @spec first_non_ecto_stacktrace(Exception.stacktrace(), Ecto.Repo.t(), non_neg_integer()) :: From 8c16861f11ce2952f858c587dbd7dacd8134ec18 Mon Sep 17 00:00:00 2001 From: v0idpwn Date: Tue, 1 Apr 2025 16:20:51 -0300 Subject: [PATCH 18/20] Pass repo on a map --- lib/ecto/adapters/sql.ex | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/lib/ecto/adapters/sql.ex b/lib/ecto/adapters/sql.ex index 7e7dd4f1c..e77ede0a6 100644 --- a/lib/ecto/adapters/sql.ex +++ b/lib/ecto/adapters/sql.ex @@ -1399,7 +1399,7 @@ defmodule Ecto.Adapters.SQL do end defp log_stacktrace([_ | _] = stacktrace, repo, {module, function, args}) do - entries = apply(module, function, [stacktrace, repo | args]) + entries = apply(module, function, [stacktrace, %{repo: repo} | args]) Enum.with_index(entries, fn {module, function, arity, info}, idx -> [ @@ -1431,9 +1431,12 @@ defmodule Ecto.Adapters.SQL do This function is used by default in the `:log_stacktrace_mfa` config, with a size of 1. """ - @spec first_non_ecto_stacktrace(Exception.stacktrace(), Ecto.Repo.t(), non_neg_integer()) :: - Exception.stacktrace() - def first_non_ecto_stacktrace(stacktrace, repo, size) do + @spec first_non_ecto_stacktrace( + Exception.stacktrace(), + %{repo: Ecto.Repo.t()}, + non_neg_integer() + ) :: Exception.stacktrace() + def first_non_ecto_stacktrace(stacktrace, %{repo: repo}, size) do stacktrace |> Enum.reverse() |> last_non_ecto_entries(repo, []) From 67f47685feb13ad349ac822b258507d2db5d6aa1 Mon Sep 17 00:00:00 2001 From: v0idpwn Date: Tue, 1 Apr 2025 16:52:29 -0300 Subject: [PATCH 19/20] Alternative stacktrace filtering implementation --- lib/ecto/adapters/sql.ex | 16 +++++++++------- 1 file changed, 9 insertions(+), 7 deletions(-) diff --git a/lib/ecto/adapters/sql.ex b/lib/ecto/adapters/sql.ex index e77ede0a6..c5d67a00f 100644 --- a/lib/ecto/adapters/sql.ex +++ b/lib/ecto/adapters/sql.ex @@ -1438,19 +1438,21 @@ defmodule Ecto.Adapters.SQL do ) :: Exception.stacktrace() def first_non_ecto_stacktrace(stacktrace, %{repo: repo}, size) do stacktrace + |> first_non_ecto_entries(repo, size, size, []) |> Enum.reverse() - |> last_non_ecto_entries(repo, []) - |> Enum.take(size) end - defp last_non_ecto_entries([{mod, _, _, _} | _], repo, acc) + defp first_non_ecto_entries([{mod, _, _, _} | rest], repo, size, _, _) when mod == repo or mod in @repo_modules, - do: acc + do: first_non_ecto_entries(rest, repo, size, size, []) - defp last_non_ecto_entries([entry | rest], repo, acc), - do: last_non_ecto_entries(rest, repo, [entry | acc]) + defp first_non_ecto_entries([_ | rest], repo, size, 0, acc), + do: first_non_ecto_entries(rest, repo, size, 0, acc) - defp last_non_ecto_entries([], _, acc), do: acc + defp first_non_ecto_entries([], _, _, _, acc), do: acc + + defp first_non_ecto_entries([entry | rest], repo, size, pending, acc), + do: first_non_ecto_entries(rest, repo, size, pending - 1, [entry | acc]) ## Connection helpers From 9fdd763eef9d366e94479a3f2a4ad45ae50a8b0a Mon Sep 17 00:00:00 2001 From: v0idpwn Date: Tue, 1 Apr 2025 19:05:43 -0300 Subject: [PATCH 20/20] Revert "Alternative stacktrace filtering implementation" This reverts commit 67f47685feb13ad349ac822b258507d2db5d6aa1. --- lib/ecto/adapters/sql.ex | 16 +++++++--------- 1 file changed, 7 insertions(+), 9 deletions(-) diff --git a/lib/ecto/adapters/sql.ex b/lib/ecto/adapters/sql.ex index c5d67a00f..e77ede0a6 100644 --- a/lib/ecto/adapters/sql.ex +++ b/lib/ecto/adapters/sql.ex @@ -1438,21 +1438,19 @@ defmodule Ecto.Adapters.SQL do ) :: Exception.stacktrace() def first_non_ecto_stacktrace(stacktrace, %{repo: repo}, size) do stacktrace - |> first_non_ecto_entries(repo, size, size, []) |> Enum.reverse() + |> last_non_ecto_entries(repo, []) + |> Enum.take(size) end - defp first_non_ecto_entries([{mod, _, _, _} | rest], repo, size, _, _) + defp last_non_ecto_entries([{mod, _, _, _} | _], repo, acc) when mod == repo or mod in @repo_modules, - do: first_non_ecto_entries(rest, repo, size, size, []) + do: acc - defp first_non_ecto_entries([_ | rest], repo, size, 0, acc), - do: first_non_ecto_entries(rest, repo, size, 0, acc) + defp last_non_ecto_entries([entry | rest], repo, acc), + do: last_non_ecto_entries(rest, repo, [entry | acc]) - defp first_non_ecto_entries([], _, _, _, acc), do: acc - - defp first_non_ecto_entries([entry | rest], repo, size, pending, acc), - do: first_non_ecto_entries(rest, repo, size, pending - 1, [entry | acc]) + defp last_non_ecto_entries([], _, acc), do: acc ## Connection helpers