Get the first non-ecto entry for stacktraces

Author: josevalim

integration_test/sql/logging.exs

@@ -5,70 +5,131 @@ defmodule Ecto.Integration.LoggingTest do
   alias Ecto.Integration.PoolRepo
   alias Ecto.Integration.Post
 
-  test "log entry is sent to telemetry" do
-    log = fn event_name, measurements, metadata ->
-      assert Enum.at(event_name, -1) == :query
-      assert %{result: {:ok, _res}} = metadata
-      assert measurements.total_time == measurements.query_time + measurements.decode_time + measurements.queue_time
-      assert measurements.idle_time
-      send(self(), :logged)
+  import ExUnit.CaptureLog
+
+  describe "telemetry" do
+    test "dispatches event" do
+      log = fn event_name, measurements, metadata ->
+        assert Enum.at(event_name, -1) == :query
+        assert %{result: {:ok, _res}} = metadata
+
+        assert measurements.total_time ==
+                 measurements.query_time + measurements.decode_time + measurements.queue_time
+
+        assert measurements.idle_time
+        send(self(), :logged)
+      end
+
+      Process.put(:telemetry, log)
+      _ = PoolRepo.all(Post)
+      assert_received :logged
     end
 
-    Process.put(:telemetry, log)
-    _ = PoolRepo.all(Post)
-    assert_received :logged
-  end
+    test "dispatches event with stacktrace" do
+      log = fn _event_name, _measurements, metadata ->
+        assert %{stacktrace: [_ | _]} = metadata
+        send(self(), :logged)
+      end
 
-  test "log entry is sent to telemetry with custom options" do
-    log = fn event_name, _measurements, metadata ->
-      assert Enum.at(event_name, -1) == :query
-      assert metadata.options == [:custom_metadata]
-      send(self(), :logged)
+      Process.put(:telemetry, log)
+      _ = PoolRepo.all(Post, stacktrace: true)
+      assert_received :logged
     end
 
-    Process.put(:telemetry, log)
-    _ = PoolRepo.all(Post, telemetry_options: [:custom_metadata])
-    assert_received :logged
-  end
+    test "dispatches event with custom options" do
+      log = fn event_name, _measurements, metadata ->
+        assert Enum.at(event_name, -1) == :query
+        assert metadata.options == [:custom_metadata]
+        send(self(), :logged)
+      end
 
-  test "log entry sent under another event name" do
-    log = fn [:custom], measurements, metadata ->
-      assert %{result: {:ok, _res}} = metadata
-      assert measurements.total_time == measurements.query_time + measurements.decode_time + measurements.queue_time
-      assert measurements.idle_time
-      send(self(), :logged)
+      Process.put(:telemetry, log)
+      _ = PoolRepo.all(Post, telemetry_options: [:custom_metadata])
+      assert_received :logged
     end
 
-    Process.put(:telemetry, log)
-    _ = PoolRepo.all(Post, telemetry_event: [:custom])
-    assert_received :logged
-  end
+    test "dispatches under another event name" do
+      log = fn [:custom], measurements, metadata ->
+        assert %{result: {:ok, _res}} = metadata
 
-  test "log entry is not sent to telemetry under nil event name" do
-    Process.put(:telemetry, fn _, _ -> raise "never called" end)
-    _ = TestRepo.all(Post, telemetry_event: nil)
-    refute_received :logged
-  end
+        assert measurements.total_time ==
+                 measurements.query_time + measurements.decode_time + measurements.queue_time
+
+        assert measurements.idle_time
+        send(self(), :logged)
+      end
+
+      Process.put(:telemetry, log)
+      _ = PoolRepo.all(Post, telemetry_event: [:custom])
+      assert_received :logged
+    end
 
-  test "log entry when some measurements are nil" do
-    assert ExUnit.CaptureLog.capture_log(fn ->
-             TestRepo.query("BEG", [], log: :error)
-           end) =~ "[error]"
+    test "is not dispatched with no event name" do
+      Process.put(:telemetry, fn _, _ -> raise "never called" end)
+      _ = TestRepo.all(Post, telemetry_event: nil)
+      refute_received :logged
+    end
   end
 
-  test "log entry with custom log level" do
-    assert ExUnit.CaptureLog.capture_log(fn ->
-             TestRepo.insert!(%Post{title: "1"}, [log: :error])
-           end) =~ "[error]"
+  describe "logs" do
+    @stacktrace_opts [stacktrace: true, log: :error]
 
-    # We cannot assert on the result because it depends on the suite log level
-    ExUnit.CaptureLog.capture_log(fn ->
-      TestRepo.insert!(%Post{title: "1"}, [log: true])
-    end)
+    defp stacktrace_entry(line) do
+      "↳ anonymous fn/0 in Ecto.Integration.LoggingTest.\"test logs includes stacktraces\"/1, " <>
+        "at: integration_test/sql/logging.exs##{line - 3}"
+    end
 
-    # But this assertion is always true
-    assert ExUnit.CaptureLog.capture_log(fn ->
-      TestRepo.insert!(%Post{title: "1"}, [log: false])
-    end) == ""
+    test "when some measurements are nil" do
+      assert capture_log(fn -> TestRepo.query("BEG", [], log: :error) end) =~
+               "[error]"
+    end
+
+    test "includes stacktraces" do
+      assert capture_log(fn ->
+               TestRepo.all(Post, @stacktrace_opts)
+
+               :ok
+             end) =~ stacktrace_entry(__ENV__.line)
+
+      assert capture_log(fn ->
+               TestRepo.insert(%Post{}, @stacktrace_opts)
+
+               :ok
+             end) =~ stacktrace_entry(__ENV__.line)
+
+      assert capture_log(fn ->
+               # Test cascading options
+               Ecto.Multi.new()
+               |> Ecto.Multi.insert(:post, %Post{})
+               |> TestRepo.transaction(@stacktrace_opts)
+
+               :ok
+             end) =~ stacktrace_entry(__ENV__.line)
+
+      assert capture_log(fn ->
+               # In theory we should point to the call _inside_ run
+               # but all multi calls point to the transaction starting point.
+               Ecto.Multi.new()
+               |> Ecto.Multi.run(:all, fn _, _ -> {:ok, TestRepo.all(Post, @stacktrace_opts)} end)
+               |> TestRepo.transaction()
+
+               :ok
+             end) =~ stacktrace_entry(__ENV__.line)
+    end
+
+    test "with custom log level" do
+      assert capture_log(fn -> TestRepo.insert!(%Post{title: "1"}, log: :error) end) =~
+               "[error]"
+
+      # We cannot assert on the result because it depends on the suite log level
+      capture_log(fn ->
+        TestRepo.insert!(%Post{title: "1"}, log: true)
+      end)
+
+      # But this assertion is always true
+      assert capture_log(fn ->
+               TestRepo.insert!(%Post{title: "1"}, log: false)
+             end) == ""
+    end
   end
 end

lib/ecto/adapters/sql.ex

@@ -1063,7 +1063,9 @@ defmodule Ecto.Adapters.SQL do
     } = entry
 
     source = Keyword.get(opts, :source)
-    query_string = String.Chars.to_string(query)
+    query = String.Chars.to_string(query)
+    result = with {:ok, _query, res} <- result, do: {:ok, res}
+    stacktrace = Keyword.get(opts, :stacktrace)
 
     params =
       Enum.map(params, fn
@@ -1084,12 +1086,12 @@ defmodule Ecto.Adapters.SQL do
     metadata = %{
       type: :ecto_sql_query,
       repo: repo,
-      result: log_result(result),
+      result: result,
       params: params,
-      query: query_string,
+      query: query,
       source: source,
-      options: Keyword.get(opts, :telemetry_options, []),
-      stacktrace: Keyword.get(opts, :stacktrace)
+      stacktrace: stacktrace,
+      options: Keyword.get(opts, :telemetry_options, [])
     }
 
     if event_name = Keyword.get(opts, :telemetry_event, event_name) do
@@ -1100,8 +1102,8 @@ defmodule Ecto.Adapters.SQL do
       true ->
         Logger.log(
           log,
-          fn -> log_iodata(measurements, metadata) end,
-          ansi_color: sql_color(query_string)
+          fn -> log_iodata(measurements, repo, source, query, params, result, stacktrace) end,
+          ansi_color: sql_color(query)
         )
 
       false ->
@@ -1110,8 +1112,8 @@ defmodule Ecto.Adapters.SQL do
       level ->
         Logger.log(
           level,
-          fn -> log_iodata(measurements, metadata) end,
-          ansi_color: sql_color(query_string)
+          fn -> log_iodata(measurements, repo, source, query, params, result, stacktrace) end,
+          ansi_color: sql_color(query)
         )
     end
 
@@ -1127,17 +1129,7 @@ defmodule Ecto.Adapters.SQL do
   defp log_measurements([], total, acc),
     do: Map.new([total_time: total] ++ acc)
 
-  defp log_result({:ok, _query, res}), do: {:ok, res}
-  defp log_result(other), do: other
-
-  defp log_iodata(measurements, metadata) do
-    %{
-      params: params,
-      query: query,
-      result: result,
-      source: source
-    } = metadata
-
+  defp log_iodata(measurements, repo, source, query, params, result, stacktrace) do
     [
       "QUERY",
       ?\s,
@@ -1151,43 +1143,10 @@ defmodule Ecto.Adapters.SQL do
       query,
       ?\s,
       inspect(params, charlists: false),
-      log_stacktrace(metadata.stacktrace)
+      log_stacktrace(stacktrace, repo)
     ]
   end
 
-  defp log_stacktrace(stacktrace) do 
-    with [_ | _] <- stacktrace,
-         {module, function, arity, metadata} <- first_non_ecto(stacktrace, nil) do
-      [
-        ?\n,
-        "↳ ",
-        Exception.format_mfa(module, function, arity),
-        ", at: ",
-        inspect(metadata)
-      ]
-    else
-      _ -> []
-    end
-  end
-
-  defp first_non_ecto([last_item], first_non_ecto) do
-    if is_ecto?(last_item), do: nil, else: first_non_ecto
-  end
-
-  defp first_non_ecto([head | tail], first_non_ecto) do
-    if is_ecto?(head) do
-      first_non_ecto(tail, nil)
-    else
-      first_non_ecto(tail, first_non_ecto || head)
-    end
-  end
-
-  defp is_ecto?({module, _f, _a, _m}) do
-    module
-    |> Atom.to_string()
-    |> String.starts_with?("Elixir.Ecto.")
-  end
-
   defp log_ok_error({:ok, _res}), do: "OK"
   defp log_ok_error({:error, _err}), do: "ERROR"
 
@@ -1211,6 +1170,40 @@ 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
+      [
+        ?\n,
+        "↳ ",
+        Exception.format_mfa(module, function, arity),
+        log_stacktrace_info(info)
+      ]
+    else
+      _ -> []
+    end
+  end
+
+  defp log_stacktrace_info([file: file, line: line] ++ _) do
+    [", at: ", file, ?#, Integer.to_string(line)]
+  end
+
+  defp log_stacktrace_info(_) do
+    []
+  end
+
+  @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([], _repo, last),
+    do: last
+
   ## Connection helpers
 
   defp checkout_or_transaction(fun, adapter_meta, opts, callback) do