elixir-ecto / db_connection

Database connection behaviour
http://hexdocs.pm/db_connection/DBConnection.html
306 stars 113 forks source link

Wrong DBConnection.LogEntry for transaction begin #187

Closed wojtekmach closed 5 years ago

wojtekmach commented 5 years ago
iex> self = self(); {:ok, pid} = Postgrex.start_link(database: "wojtek");
iex> Postgrex.transaction(pid, fn _conn -> :ok end, log: &send(self, &1))
iex> flush()
%DBConnection.LogEntry{
  call: :begin,
  connection_time: 18437000,
  decode_time: nil,
  params: nil,
  pool_time: 30531000,
  query: :begin,
  result: {:ok,
   %DBConnection{
     conn_mode: nil,
     conn_ref: #Reference<0.937492216.375128065.139515>,
     pool_ref: {:pool_ref, #PID<0.203.0>,
      #Reference<0.937492216.375259137.139407>,
      #Reference<0.937492216.375128065.139514>,
      #Reference<0.937492216.375259137.139513>,
      #Reference<0.937492216.375128065.139438>}
   },
   %Postgrex.Result{
     columns: nil,
     command: :commit,
     connection_id: 89085,
     messages: [],
     num_rows: nil,
     rows: nil
   }}
}
%DBConnection.LogEntry{
  call: :commit,
  connection_time: 252000,
  decode_time: nil,
  params: nil,
  pool_time: nil,
  query: :commit,
  result: {:ok,
   %Postgrex.Result{
     columns: nil,
     command: :commit,
     connection_id: 89085,
     messages: [],
     num_rows: nil,
     rows: nil
   }}
}

Starting from last, for commit we have correct log entry: {:ok, %{command: :commit}} = log_entry.result

For first entry, however, we have {:ok, %DBConnection{}, %{command: :commit}} = log_entry.result. I'd expect the same shape of result, {:ok, result} where result corresponds to begin query.

This isn't Postgrex specific and I'm seeing the same thing on MyXQL.

wojtekmach commented 5 years ago

So Postgrex returning {:ok, %DBConnection{}, %{command: :commit}} for begin made me think there's something wrong, but maybe it's a Postgrex bug (that it sets command to commit) or just how it works.

Come to think of it, there's nothing wrong with logging {:ok, %DBConnection{}, result} as opposed to {:ok, result} that I was proposing above, and in fact it might be desirable to log the connection we got from the pool. So I think it's fine to keep it as is, but let me know otherwise!

fishcakez commented 5 years ago

The reason begin has a 3 tuple is that we always log data structures that we create, this was intentionally added to support lower level functions, like begin, commit, rollback. We rolled back the public API but kept logs so they could become public.