diff --git a/integration_test/cases/after_connect_test.exs b/integration_test/cases/after_connect_test.exs index 28b584c..406f998 100644 --- a/integration_test/cases/after_connect_test.exs +++ b/integration_test/cases/after_connect_test.exs @@ -212,17 +212,18 @@ defmodule AfterConnectTest do assert_receive {:after_connect, after_pid} - prefix = - "client #{inspect(after_pid)} stopped: " <> - "** (DBConnection.ConnectionError) bad return value: :oops" - - len = byte_size(prefix) + pid_str = inspect(after_pid) assert_receive {:EXIT, ^conn, {%DBConnection.ConnectionError{ - message: <<^prefix::binary-size(len), _::binary>> + message: message }, [_ | _]}} + assert Regex.match?( + ~r/^client #{Regex.escape(pid_str)}(?\s*\([^)]+\))?\s+stopped: \*\* \(DBConnection\.ConnectionError\) bad return value: :oops/, + message + ) + assert [ {:connect, _}, {:handle_status, _}, @@ -266,14 +267,18 @@ defmodule AfterConnectTest do assert_receive {:hi, conn} assert_receive {:after_connect, after_pid} - prefix = "client #{inspect(after_pid)} stopped: ** (RuntimeError) oops" - len = byte_size(prefix) + pid_str = inspect(after_pid) assert_receive {:EXIT, ^conn, {%DBConnection.ConnectionError{ - message: <<^prefix::binary-size(len), _::binary>> + message: message }, [_ | _]}} + assert Regex.match?( + ~r/^client #{Regex.escape(pid_str)}(?\s*\([^)]+\))?\s+stopped: \*\* \(RuntimeError\) oops/, + message + ) + assert [ {:connect, _}, {:handle_status, _}, diff --git a/integration_test/cases/execute_test.exs b/integration_test/cases/execute_test.exs index 9f46a8f..bb86417 100644 --- a/integration_test/cases/execute_test.exs +++ b/integration_test/cases/execute_test.exs @@ -432,17 +432,18 @@ defmodule ExecuteTest do P.execute(pool, %Q{}, [:param]) end - prefix = - "client #{inspect(self())} stopped: " <> - "** (DBConnection.ConnectionError) bad return value: :oops" - - len = byte_size(prefix) + pid_str = inspect(self()) assert_receive {:EXIT, ^conn, {%DBConnection.ConnectionError{ - message: <<^prefix::binary-size(len), _::binary>> + message: message }, [_ | _]}} + assert Regex.match?( + ~r/^client #{Regex.escape(pid_str)}(?\s*\([^)]+\))?\s+stopped: \*\* \(DBConnection\.ConnectionError\) bad return value: :oops/, + message + ) + assert [ {:connect, _}, {:handle_execute, [%Q{}, [:param], _, :state]}, @@ -473,14 +474,18 @@ defmodule ExecuteTest do Process.flag(:trap_exit, true) assert_raise RuntimeError, "oops", fn -> P.execute(pool, %Q{}, [:param]) end - prefix = "client #{inspect(self())} stopped: ** (RuntimeError) oops" - len = byte_size(prefix) + pid_str = inspect(self()) assert_receive {:EXIT, ^conn, {%DBConnection.ConnectionError{ - message: <<^prefix::binary-size(len), _::binary>> + message: message }, [_ | _]}} + assert Regex.match?( + ~r/^client #{Regex.escape(pid_str)}(?\s*\([^)]+\))?\s+stopped: \*\* \(RuntimeError\) oops/, + message + ) + assert [ {:connect, _}, {:handle_execute, [%Q{}, [:param], _, :state]}, diff --git a/integration_test/cases/prepare_stream_test.exs b/integration_test/cases/prepare_stream_test.exs index dfcb409..32d7c8a 100644 --- a/integration_test/cases/prepare_stream_test.exs +++ b/integration_test/cases/prepare_stream_test.exs @@ -286,17 +286,18 @@ defmodule PrepareStreamTest do :hi end) == {:error, :rollback} - prefix = - "client #{inspect(self())} stopped: " <> - "** (DBConnection.ConnectionError) bad return value: :oops" - - len = byte_size(prefix) + pid_str = inspect(self()) assert_receive {:EXIT, ^conn, {%DBConnection.ConnectionError{ - message: <<^prefix::binary-size(len), _::binary>> + message: message }, [_ | _]}} + assert Regex.match?( + ~r/^client #{Regex.escape(pid_str)}(?\s*\([^)]+\))?\s+stopped: \*\* \(DBConnection\.ConnectionError\) bad return value: :oops/, + message + ) + assert [ {:connect, _}, {:handle_begin, [_, :state]}, @@ -336,14 +337,18 @@ defmodule PrepareStreamTest do :hi end) == {:error, :rollback} - prefix = "client #{inspect(self())} stopped: ** (RuntimeError) oops" - len = byte_size(prefix) + pid_str = inspect(self()) assert_receive {:EXIT, ^conn, {%DBConnection.ConnectionError{ - message: <<^prefix::binary-size(len), _::binary>> + message: message }, [_ | _]}} + assert Regex.match?( + ~r/^client #{Regex.escape(pid_str)}(?\s*\([^)]+\))?\s+stopped: \*\* \(RuntimeError\) oops/, + message + ) + assert [ {:connect, _}, {:handle_begin, [_, :state]}, diff --git a/integration_test/cases/stream_test.exs b/integration_test/cases/stream_test.exs index 2d90668..574b9bb 100644 --- a/integration_test/cases/stream_test.exs +++ b/integration_test/cases/stream_test.exs @@ -432,17 +432,18 @@ defmodule StreamTest do :hi end) == {:error, :rollback} - prefix = - "client #{inspect(self())} stopped: " <> - "** (DBConnection.ConnectionError) bad return value: :oops" - - len = byte_size(prefix) + pid_str = inspect(self()) assert_receive {:EXIT, ^conn, {%DBConnection.ConnectionError{ - message: <<^prefix::binary-size(len), _::binary>> + message: message }, [_ | _]}} + assert Regex.match?( + ~r/^client #{Regex.escape(pid_str)}(?\s*\([^)]+\))?\s+stopped: \*\* \(DBConnection\.ConnectionError\) bad return value: :oops/, + message + ) + assert [ {:connect, _}, {:handle_begin, [_, :state]}, @@ -481,14 +482,18 @@ defmodule StreamTest do :hi end) == {:error, :rollback} - prefix = "client #{inspect(self())} stopped: ** (RuntimeError) oops" - len = byte_size(prefix) + pid_str = inspect(self()) assert_receive {:EXIT, ^conn, {%DBConnection.ConnectionError{ - message: <<^prefix::binary-size(len), _::binary>> + message: message }, [_ | _]}} + assert Regex.match?( + ~r/^client #{Regex.escape(pid_str)}(?\s*\([^)]+\))?\s+stopped: \*\* \(RuntimeError\) oops/, + message + ) + assert [ {:connect, _}, {:handle_begin, [_, :state]}, @@ -567,17 +572,18 @@ defmodule StreamTest do :hi end) == {:error, :rollback} - prefix = - "client #{inspect(self())} stopped: " <> - "** (DBConnection.ConnectionError) bad return value: :oops" - - len = byte_size(prefix) + pid_str = inspect(self()) assert_receive {:EXIT, ^conn, {%DBConnection.ConnectionError{ - message: <<^prefix::binary-size(len), _::binary>> + message: message }, [_ | _]}} + assert Regex.match?( + ~r/^client #{Regex.escape(pid_str)}(?\s*\([^)]+\))?\s+stopped: \*\* \(DBConnection\.ConnectionError\) bad return value: :oops/, + message + ) + assert [ {:connect, _}, {:handle_begin, [_, :state]}, @@ -619,14 +625,18 @@ defmodule StreamTest do :hi end) == {:error, :rollback} - prefix = "client #{inspect(self())} stopped: ** (RuntimeError) oops" - len = byte_size(prefix) + pid_str = inspect(self()) assert_receive {:EXIT, ^conn, {%DBConnection.ConnectionError{ - message: <<^prefix::binary-size(len), _::binary>> + message: message }, [_ | _]}} + assert Regex.match?( + ~r/^client #{Regex.escape(pid_str)}(?\s*\([^)]+\))?\s+stopped: \*\* \(RuntimeError\) oops/, + message + ) + assert [ {:connect, _}, {:handle_begin, [_, :state]}, diff --git a/integration_test/cases/transaction_execute_test.exs b/integration_test/cases/transaction_execute_test.exs index 251dc8c..42e2cd2 100644 --- a/integration_test/cases/transaction_execute_test.exs +++ b/integration_test/cases/transaction_execute_test.exs @@ -213,17 +213,18 @@ defmodule TransactionExecuteTest do :closed end) == {:error, :rollback} - prefix = - "client #{inspect(self())} stopped: " <> - "** (DBConnection.ConnectionError) bad return value: :oops" - - len = byte_size(prefix) + pid_str = inspect(self()) assert_receive {:EXIT, ^conn, {%DBConnection.ConnectionError{ - message: <<^prefix::binary-size(len), _::binary>> + message: message }, [_ | _]}} + assert Regex.match?( + ~r/^client #{Regex.escape(pid_str)}(?\s*\([^)]+\))?\s+stopped: \*\* \(DBConnection\.ConnectionError\) bad return value: :oops/, + message + ) + assert [ {:connect, _}, {:handle_begin, [_, :state]}, @@ -267,14 +268,18 @@ defmodule TransactionExecuteTest do :closed end) == {:error, :rollback} - prefix = "client #{inspect(self())} stopped: ** (RuntimeError) oops" - len = byte_size(prefix) + pid_str = inspect(self()) assert_receive {:EXIT, ^conn, {%DBConnection.ConnectionError{ - message: <<^prefix::binary-size(len), _::binary>> + message: message }, [_ | _]}} + assert Regex.match?( + ~r/^client #{Regex.escape(pid_str)}(?\s*\([^)]+\))?\s+stopped: \*\* \(RuntimeError\) oops/, + message + ) + assert [ {:connect, _}, {:handle_begin, [_, :state]}, diff --git a/integration_test/cases/transaction_test.exs b/integration_test/cases/transaction_test.exs index 8963115..ab3adf1 100644 --- a/integration_test/cases/transaction_test.exs +++ b/integration_test/cases/transaction_test.exs @@ -523,17 +523,18 @@ defmodule TransactionTest do P.transaction(pool, fn _ -> flunk("transaction ran") end) end - prefix = - "client #{inspect(self())} stopped: " <> - "** (DBConnection.ConnectionError) bad return value: :oops" - - len = byte_size(prefix) + pid_str = inspect(self()) assert_receive {:EXIT, ^conn, {%DBConnection.ConnectionError{ - message: <<^prefix::binary-size(len), _::binary>> + message: message }, [_ | _]}} + assert Regex.match?( + ~r/^client #{Regex.escape(pid_str)}(?\s*\([^)]+\))?\s+stopped: \*\* \(DBConnection\.ConnectionError\) bad return value: :oops/, + message + ) + assert [ {:connect, _}, {:handle_begin, [_, :state]}, @@ -567,14 +568,18 @@ defmodule TransactionTest do P.transaction(pool, fn _ -> flunk("transaction ran") end) end - prefix = "client #{inspect(self())} stopped: ** (RuntimeError) oops" - len = byte_size(prefix) + pid_str = inspect(self()) assert_receive {:EXIT, ^conn, {%DBConnection.ConnectionError{ - message: <<^prefix::binary-size(len), _::binary>> + message: message }, [_ | _]}} + assert Regex.match?( + ~r/^client #{Regex.escape(pid_str)}(?\s*\([^)]+\))?\s+stopped: \*\* \(RuntimeError\) oops/, + message + ) + assert [ {:connect, _}, {:handle_begin, [_, :state]}, @@ -709,17 +714,18 @@ defmodule TransactionTest do P.transaction(pool, fn _ -> :result end) end - prefix = - "client #{inspect(self())} stopped: " <> - "** (DBConnection.ConnectionError) bad return value: :oops" - - len = byte_size(prefix) + pid_str = inspect(self()) assert_receive {:EXIT, ^conn, {%DBConnection.ConnectionError{ - message: <<^prefix::binary-size(len), _::binary>> + message: message }, [_ | _]}} + assert Regex.match?( + ~r/^client #{Regex.escape(pid_str)}(?\s*\([^)]+\))?\s+stopped: \*\* \(DBConnection\.ConnectionError\) bad return value: :oops/, + message + ) + assert [ {:connect, _}, {:handle_begin, [_, :state]}, @@ -752,14 +758,18 @@ defmodule TransactionTest do Process.flag(:trap_exit, true) assert_raise RuntimeError, "oops", fn -> P.transaction(pool, fn _ -> :result end) end - prefix = "client #{inspect(self())} stopped: ** (RuntimeError) oops" - len = byte_size(prefix) + pid_str = inspect(self()) assert_receive {:EXIT, ^conn, {%DBConnection.ConnectionError{ - message: <<^prefix::binary-size(len), _::binary>> + message: message }, [_ | _]}} + assert Regex.match?( + ~r/^client #{Regex.escape(pid_str)}(?\s*\([^)]+\))?\s+stopped: \*\* \(RuntimeError\) oops/, + message + ) + assert [ {:connect, _}, {:handle_begin, [_, :state]}, diff --git a/integration_test/ownership/manager_test.exs b/integration_test/ownership/manager_test.exs index b9eaf59..a34c73d 100644 --- a/integration_test/ownership/manager_test.exs +++ b/integration_test/ownership/manager_test.exs @@ -269,11 +269,19 @@ defmodule ManagerTest do :ok end) - assert capture_log(fn -> - assert_receive :checked_out - assert Ownership.ownership_mode(pool, :manual, []) == :ok - assert Ownership.ownership_checkout(pool, []) == :ok - end) =~ "#{inspect(self())} checked in the connection owned by #{inspect(task.pid)}" + log_output = + capture_log(fn -> + assert_receive :checked_out + assert Ownership.ownership_mode(pool, :manual, []) == :ok + assert Ownership.ownership_checkout(pool, []) == :ok + end) + + self_pid_str = inspect(self()) + task_pid_str = inspect(task.pid) + + # Check that the log contains both PIDs with optional process info + assert log_output =~ + ~r/#{Regex.escape(self_pid_str)}(?\s*\([^)]+\))?\s+checked in the connection owned by\s+#{Regex.escape(task_pid_str)}(?\s*\([^)]+\))?/ end test "uses ETS when the pool is named (with pid access)" do @@ -667,7 +675,9 @@ defmodule ManagerTest do assert_receive :reconnected end) - assert log =~ ~r"State machine #PID<\d+\.\d+\.\d+> terminating\n" + assert log =~ + ~r"State machine #PID<\d+\.\d+\.\d+>(?\s*\([^)]+\))?\s+terminating\n" + assert log =~ "** (RuntimeError) oops" end diff --git a/integration_test/ownership/owner_test.exs b/integration_test/ownership/owner_test.exs index 7f06153..ecce2dc 100644 --- a/integration_test/ownership/owner_test.exs +++ b/integration_test/ownership/owner_test.exs @@ -44,9 +44,13 @@ defmodule OwnerTest do end) == :ok end) - assert log =~ ~r"owner #PID<\d+\.\d+\.\d+> exited" - assert log =~ ~r"is still using a connection from owner at location" - assert log =~ ~r"The connection itself was checked out by #PID<\d+\.\d+\.\d+> at location" + assert log =~ ~r"owner #PID<\d+\.\d+\.\d+>(?\s*\([^)]+\))?\s+exited" + + assert log =~ + ~r"Client #PID<\d+\.\d+\.\d+>(?\s*\([^)]+\))?\s+is still using a connection from owner at location" + + assert log =~ + ~r"The connection itself was checked out by #PID<\d+\.\d+\.\d+>(?\s*\([^)]+\))?" assert [ {:connect, _}, diff --git a/lib/db_connection.ex b/lib/db_connection.ex index c97acfd..7b9d642 100644 --- a/lib/db_connection.ex +++ b/lib/db_connection.ex @@ -82,6 +82,7 @@ defmodule DBConnection do require Logger alias DBConnection.Holder + alias DBConnection.Util require Holder @@ -1357,7 +1358,7 @@ defmodule DBConnection do end defp stop(%DBConnection{pool_ref: pool_ref}, kind, reason, stack) do - msg = "client #{inspect(self())} stopped: " <> Exception.format(kind, reason, stack) + msg = "client #{Util.inspect_pid(self())} stopped: " <> Exception.format(kind, reason, stack) exception = DBConnection.ConnectionError.exception(msg) _ = Holder.stop(pool_ref, exception) :ok diff --git a/lib/db_connection/connection.ex b/lib/db_connection/connection.ex index 3d466ed..41f7318 100644 --- a/lib/db_connection/connection.ex +++ b/lib/db_connection/connection.ex @@ -100,7 +100,7 @@ defmodule DBConnection.Connection do [ inspect(mod), " (", - inspect(self()), + Util.inspect_pid(self()), ") failed to connect: " | Exception.format_banner(:error, err, []) ] end, @@ -116,7 +116,7 @@ defmodule DBConnection.Connection do inspect(mod), ?\s, ?(, - inspect(self()), + Util.inspect_pid(self()), ") failed to connect: " | Exception.format_banner(:error, err, []) ] @@ -142,7 +142,7 @@ defmodule DBConnection.Connection do inspect(mod), ?\s, ?(, - inspect(self()), + Util.inspect_pid(self()), ") disconnected: " | Exception.format_banner(:error, err, []) ] end) @@ -343,7 +343,7 @@ defmodule DBConnection.Connection do def handle_event(:info, msg, :no_state, %{mod: mod} = s) do Logger.info(fn -> - [inspect(mod), ?\s, ?(, inspect(self()), ") missed message: " | inspect(msg)] + [inspect(mod), ?\s, ?(, Util.inspect_pid(self()), ") missed message: " | inspect(msg)] end) handle_timeout(s) diff --git a/lib/db_connection/holder.ex b/lib/db_connection/holder.ex index 83f4be6..e8f399c 100644 --- a/lib/db_connection/holder.ex +++ b/lib/db_connection/holder.ex @@ -2,6 +2,8 @@ defmodule DBConnection.Holder do @moduledoc false require Record + alias DBConnection.Util + @queue true @timeout 15000 @time_unit 1000 @@ -84,7 +86,7 @@ defmodule DBConnection.Holder do %{ exception | message: - "could not checkout the connection owned by #{inspect(caller)}. " <> + "could not checkout the connection owned by #{Util.inspect_pid(caller)}. " <> "When using the sandbox, connections are shared, so this may imply " <> "another process is using a connection. Reason: #{message}" }} @@ -332,7 +334,7 @@ defmodule DBConnection.Holder do call_reason = if maybe_pid do - "Error happened when attempting to transfer to #{inspect(maybe_pid)} " <> + "Error happened when attempting to transfer to #{Util.inspect_pid(maybe_pid)} " <> "(alive: #{Process.alive?(maybe_pid)})" else "Error happened when looking up connection" @@ -342,7 +344,7 @@ defmodule DBConnection.Holder do #{inspect(__MODULE__)} #{inspect(holder)} #{reason}, pool inconsistent. #{call_reason}. - SELF: #{inspect(self())} + SELF: #{Util.inspect_pid(self())} ETS INFO: #{inspect(:ets.info(holder))} Please report at https://github.com/elixir-ecto/db_connection/issues" diff --git a/lib/db_connection/ownership/manager.ex b/lib/db_connection/ownership/manager.ex index e1575fe..482bc7b 100644 --- a/lib/db_connection/ownership/manager.ex +++ b/lib/db_connection/ownership/manager.ex @@ -262,11 +262,11 @@ defmodule DBConnection.Ownership.Manager do if log do Logger.log(log, fn -> [ - inspect(caller), + Util.inspect_pid(caller), " checked out connection in ", inspect(mode), " mode using proxy ", - inspect(proxy) + Util.inspect_pid(proxy) ] end) end @@ -306,7 +306,13 @@ defmodule DBConnection.Ownership.Manager do defp owner_allow(%{ets: ets, log: log} = state, caller, allow, ref, proxy) do if log do Logger.log(log, fn -> - [inspect(allow), " was allowed by ", inspect(caller), " on proxy ", inspect(proxy)] + [ + Util.inspect_pid(allow), + " was allowed by ", + Util.inspect_pid(caller), + " on proxy ", + Util.inspect_pid(proxy) + ] end) end @@ -324,7 +330,13 @@ defmodule DBConnection.Ownership.Manager do defp owner_unallow(%{ets: ets, log: log} = state, caller, unallow, ref, proxy) do if log do Logger.log(log, fn -> - [inspect(unallow), " was unallowed by ", inspect(caller), " on proxy ", inspect(proxy)] + [ + Util.inspect_pid(unallow), + " was unallowed by ", + Util.inspect_pid(caller), + " on proxy ", + Util.inspect_pid(proxy) + ] end) end @@ -348,9 +360,9 @@ defmodule DBConnection.Ownership.Manager do if log do Logger.log(log, fn -> [ - Enum.map_join(entries, ", ", &inspect/1), + Enum.map_join(entries, ", ", &Util.inspect_pid/1), " lost connection from proxy ", - inspect(proxy) + Util.inspect_pid(proxy) ] end) end diff --git a/lib/db_connection/ownership/proxy.ex b/lib/db_connection/ownership/proxy.ex index 805cea1..41ac7f3 100644 --- a/lib/db_connection/ownership/proxy.ex +++ b/lib/db_connection/ownership/proxy.ex @@ -156,7 +156,8 @@ defmodule DBConnection.Ownership.Proxy do @impl true def handle_cast({:stop, caller}, %{owner: {owner, _}} = state) do - message = "#{inspect(caller)} checked in the connection owned by #{inspect(owner)}" + message = + "#{Util.inspect_pid(caller)} checked in the connection owned by #{Util.inspect_pid(owner)}" message = case pruned_stacktrace(caller) do @@ -165,7 +166,7 @@ defmodule DBConnection.Ownership.Proxy do current_stack -> message <> - "\n\n#{inspect(caller)} triggered the checkin at location:\n\n" <> + "\n\n#{Util.inspect_pid(caller)} triggered the checkin at location:\n\n" <> Exception.format_stacktrace(current_stack) end @@ -235,10 +236,10 @@ defmodule DBConnection.Ownership.Proxy do current_stack -> reason <> """ - \n\nClient #{inspect(client)} is still using a connection from owner at location: + \n\nClient #{Util.inspect_pid(client)} is still using a connection from owner at location: #{Exception.format_stacktrace(current_stack)} - The connection itself was checked out by #{inspect(client)} at location: + The connection itself was checked out by #{Util.inspect_pid(client)} at location: #{Exception.format_stacktrace(checkout_stack)} """ diff --git a/lib/db_connection/util.ex b/lib/db_connection/util.ex index 817e820..59d4fb3 100644 --- a/lib/db_connection/util.ex +++ b/lib/db_connection/util.ex @@ -4,15 +4,18 @@ defmodule DBConnection.Util do @doc """ Inspect a pid, including the process label if possible. """ - def inspect_pid(pid) do + def inspect_pid(pid) when is_pid(pid) do with :undefined <- get_label(pid), - :undefined <- get_name(pid) do + :undefined <- get_name(pid), + :undefined <- get_initial_call(pid) do inspect(pid) else - label_or_name -> "#{inspect(pid)} (#{inspect(label_or_name)})" + label_or_name_or_call -> "#{inspect(pid)} (#{inspect(label_or_name_or_call)})" end end + def inspect_pid(other), do: inspect(other) + defp get_name(pid) do try do Process.info(pid, :registered_name) @@ -28,8 +31,8 @@ defmodule DBConnection.Util do Set a process label if `Process.set_label/1` is available. """ def set_label(label) do - if function_exported?(:proc_lib, :set_label, 1) do - :proc_lib.set_label(label) + if function_exported?(Process, :set_label, 1) do + Process.set_label(label) else :ok end @@ -49,4 +52,11 @@ defmodule DBConnection.Util do :undefined end end + + defp get_initial_call(pid) do + case Process.info(pid, :initial_call) do + {:initial_call, {mod, _, _}} -> mod + _ -> :undefined + end + end end