Add logging for executing queries (#134)

* Add logging for executing queries

Arguments are translated to Log::Metadata::Value via DB::Statement#arg_to_log method.

DB::Statement#before_query_or_exec & after_query_or_exec protected methods can be used to hook and run around the statement execution

* Move the metadata converter to a module

* Replace before/after with def_around_query_or_exec macro

* Update src/db/enumerable_concat.cr

Co-authored-by: Ary Borenszweig <asterite@gmail.com>

Co-authored-by: Ary Borenszweig <asterite@gmail.com>

spec/custom_drivers_types_spec.cr

@@ -48,11 +48,11 @@ class FooDriver < DB::Driver
   end
 
   class FooConnection < DB::Connection
-    def build_prepared_statement(query) : DB::Statement
+    def build_prepared_statement(command) : DB::Statement
-      FooStatement.new(self)
+      FooStatement.new(self, command)
     end
 
-    def build_unprepared_statement(query) : DB::Statement
+    def build_unprepared_statement(command) : DB::Statement
       raise "not implemented"
     end
   end
@@ -112,7 +112,7 @@ class BarDriver < DB::Driver
 
   class BarConnection < DB::Connection
     def build_prepared_statement(query) : DB::Statement
-      BarStatement.new(self)
+      BarStatement.new(self, query)
     end
 
     def build_unprepared_statement(query) : DB::Statement

spec/dummy_driver.cr

@@ -96,22 +96,22 @@ class DummyDriver < DB::Driver
   class DummyStatement < DB::Statement
     property params
 
-    def initialize(connection, @query : String, @prepared : Bool)
+    def initialize(connection, command : String, @prepared : Bool)
       @params = Hash(Int32 | String, DB::Any | Array(DB::Any)).new
-      super(connection)
+      super(connection, command)
-      raise DB::Error.new(query) if query == "syntax error"
+      raise DB::Error.new(command) if command == "syntax error"
     end
 
     protected def perform_query(args : Enumerable) : DB::ResultSet
       @connection.as(DummyConnection).check
       set_params args
-      DummyResultSet.new self, @query
+      DummyResultSet.new self, command
     end
 
     protected def perform_exec(args : Enumerable) : DB::ExecResult
       @connection.as(DummyConnection).check
       set_params args
-      raise DB::Error.new("forced exception due to query") if @query == "raise"
+      raise DB::Error.new("forced exception due to query") if command == "raise"
       DB::ExecResult.new 0i64, 0_i64
     end
 
@@ -149,9 +149,9 @@ class DummyDriver < DB::Driver
 
     @@last_result_set : self?
 
-    def initialize(statement, query)
+    def initialize(statement, command)
       super(statement)
-      @top_values = query.split.map { |r| r.split(',') }.to_a
+      @top_values = command.split.map { |r| r.split(',') }.to_a
       @column_count = @top_values.size > 0 ? @top_values[0].size : 2
 
       @@last_result_set = self

spec/statement_spec.cr

@@ -1,4 +1,5 @@
 require "./spec_helper"
+require "log/spec"
 
 describe DB::Statement do
   it "should build prepared statements" do
@@ -217,4 +218,40 @@ describe DB::Statement do
       end
     end
   end
+
+  describe "logging" do
+    it "exec with no arguments" do
+      Log.capture(DB::Log.source) do |logs|
+        with_dummy do |db|
+          db.exec "42"
+        end
+
+        entry = logs.check(:debug, /Executing query/i).entry
+        entry.data[:query].should eq("42")
+        entry.data[:args].as_a.should be_empty
+      end
+    end
+
+    it "query with arguments" do
+      Log.capture(DB::Log.source) do |logs|
+        with_dummy do |db|
+          db.exec "1, ?", args: ["a"]
+          db.exec "2, ?", "a"
+          db.exec "3, ?", ["a"]
+        end
+
+        entry = logs.check(:debug, /Executing query/i).entry
+        entry.data[:query].should eq("1, ?")
+        entry.data[:args][0].as_s.should eq("a")
+
+        entry = logs.check(:debug, /Executing query/i).entry
+        entry.data[:query].should eq("2, ?")
+        entry.data[:args][0].as_s.should eq("a")
+
+        entry = logs.check(:debug, /Executing query/i).entry
+        entry.data[:query].should eq("3, ?")
+        entry.data[:args][0][0].as_s.should eq("a")
+      end
+    end
+  end
 end

src/db.cr

@@ -1,4 +1,5 @@
 require "uri"
+require "log"
 
 # The DB module is a unified interface for database access.
 # Individual database systems are supported by specific database driver shards.
@@ -75,6 +76,8 @@ require "uri"
 # ```
 #
 module DB
+  Log = ::Log.for(self)
+
   # Types supported to interface with database driver.
   # These can be used in any `ResultSet#read` or any `Database#query` related
   # method to be used as query parameters
@@ -134,7 +137,7 @@ module DB
     build_connection(uri)
   end
 
-  # ditto
+  # :ditto:
   def self.connect(uri : URI | String, &block)
     cnn = build_connection(uri)
     begin

src/db/enumerable_concat.cr

@@ -20,7 +20,7 @@ module DB
     end
 
     # returns given `e1 : T` an `Enumerable(T')` and `e2 : U` an `Enumerable(U') | Nil`
-    # it retuns and `Enumerable(T' | U')` that enumerates the elements of `e1`
+    # it returns an `Enumerable(T' | U')` that enumerates the elements of `e1`
     # and, later, the elements of `e2`.
     def self.build(e1 : T, e2 : U)
       return e1 if e2.nil? || e2.empty?

src/db/statement.cr

@@ -51,7 +51,9 @@ module DB
     # :nodoc:
     getter connection
 
-    def initialize(@connection : Connection)
+    getter command : String
+
+    def initialize(@connection : Connection, @command : String)
     end
 
     def release_connection
@@ -79,13 +81,17 @@ module DB
     end
 
     private def perform_exec_and_release(args : Enumerable) : ExecResult
-      return perform_exec(args)
+      around_query_or_exec(args) do
+        perform_exec(args)
+      end
     ensure
       release_connection
     end
 
     private def perform_query_with_rescue(args : Enumerable) : ResultSet
-      return perform_query(args)
+      around_query_or_exec(args) do
+        perform_query(args)
+      end
     rescue e : Exception
       # Release connection only when an exception occurs during the query
       # execution since we need the connection open while the ResultSet is open
@@ -95,5 +101,90 @@ module DB
 
     protected abstract def perform_query(args : Enumerable) : ResultSet
     protected abstract def perform_exec(args : Enumerable) : ExecResult
+
+    # This method is called when executing the statement. Although it can be
+    # redefined, it is recommended to use the `def_around_query_or_exec` macro
+    # to be able to add new behaviors without loosing prior existing ones.
+    protected def around_query_or_exec(args : Enumerable)
+      yield
+    end
+
+    # This macro allows injecting code to be run before and after the execution
+    # of the request. It should return the yielded value. It must be called with 1
+    # block argument that will be used to pass the `args : Enumerable`.
+    #
+    # ```
+    # class DB::Statement
+    #   def_around_query_or_exec do |args|
+    #     # do something before query or exec
+    #     res = yield
+    #     # do something after query or exec
+    #     res
+    #   end
+    # end
+    # ```
+    macro def_around_query_or_exec(&block)
+      protected def around_query_or_exec(%args : Enumerable)
+        previous_def do
+          {% if block.args.size != 1 %}
+            {% raise "Wrong number of block arguments (given #{block.args.size}, expected: 1)" %}
+          {% end %}
+
+          {{ block.args.first.id }} = %args
+          {{ block.body }}
+        end
+      end
+    end
+
+    def_around_query_or_exec do |args|
+      emit_log(args)
+      yield
+    end
+
+    protected def emit_log(args : Enumerable)
+      Log.debug &.emit("Executing query", query: command, args: MetadataValueConverter.arg_to_log(args))
+    end
+  end
+
+  # This module converts DB supported values to `::Log::Metadata::Value`
+  #
+  # ### Note to implementors
+  #
+  # If the driver defines custom types to be used as arguments the default behavior
+  # will be converting the value via `#to_s`. Otherwise you can define overloads to
+  # change this behaviour.
+  #
+  # ```
+  # module DB::MetadataValueConverter
+  #   def self.arg_to_log(arg : PG::Geo::Point)
+  #     ::Log::Metadata::Value.new("(#{arg.x}, #{arg.y})::point")
+  #   end
+  # end
+  # ```
+  module MetadataValueConverter
+    # Returns *arg* encoded as a `::Log::Metadata::Value`.
+    def self.arg_to_log(arg) : ::Log::Metadata::Value
+      ::Log::Metadata::Value.new(arg.to_s)
+    end
+
+    # :ditto:
+    def self.arg_to_log(arg : Enumerable) : ::Log::Metadata::Value
+      ::Log::Metadata::Value.new(arg.to_a.map { |a| arg_to_log(a).as(::Log::Metadata::Value) })
+    end
+
+    # :ditto:
+    def self.arg_to_log(arg : Int) : ::Log::Metadata::Value
+      ::Log::Metadata::Value.new(arg.to_i64)
+    end
+
+    # :ditto:
+    def self.arg_to_log(arg : UInt64) : ::Log::Metadata::Value
+      ::Log::Metadata::Value.new(arg.to_s)
+    end
+
+    # :ditto:
+    def self.arg_to_log(arg : Nil | Bool | Int32 | Int64 | Float32 | Float64 | String | Time) : ::Log::Metadata::Value
+      ::Log::Metadata::Value.new(arg)
+    end
   end
 end