Add logging out, add telemetry support

Author: zookzook

CHANGELOG.md

@@ -4,6 +4,12 @@ All notable changes to this project will be documented in this file.
 
 The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/),
 and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html).
+
+## 0.8.5
+* Enhancements
+  * Add colored log output
+  * Add telemetry support for execution
+
 ## 0.8.4 (2022-03-09)
 * Bugfix
   * add missing excludes from dump function (collections)

README.md

@@ -274,6 +274,49 @@ Failing operations return a `{:error, error}` tuple where `error` is a
  }}
 ```
 
+### Logging
+
+You config the logging output by adding in your config file this line  
+
+```elixir
+config :mongodb_driver, log: true
+```
+
+The attribute `log` supports `true`, `false` or a log level like `:info`. The default value is `false`. If you turn 
+logging on, then you will see log output (command, collection, parameters):
+
+```
+[info] CMD find "my-collection" [filter: [name: "Helga"]] db=2.1ms
+```
+
+### Telemetry
+
+The driver uses the [:telemetry](https://github.com/beam-telemetry/telemetry) package to emit the execution duration
+for each command. The event name is `[:mongodb_driver, :execution]` and the driver uses the following meta data:
+
+```elixir
+metadata = %{
+type: :mongodb_driver,
+command: command,
+params: parameters,
+collection: collection,
+options: Keyword.get(opts, :telemetry_options, [])
+}
+
+:telemetry.execute([:mongodb_driver, :execution], %{duration: duration}, metadata)
+```
+
+In a Phoenix application with installed Phoenix Dashboard the metrics can be used by defining a metric in the Telemetry module:
+
+```elixr
+      summary("mongodb_driver.execution.duration",
+        tags: [:collection, :command],
+        unit: {:microsecond, :millisecond}
+      ),
+```
+
+Then you see for each collection the execution time for each different command in the Dashboard metric page.
+
 ### Connection Pooling
 
 The driver supports pooling by DBConnection (2.x). By default `mongodb_driver` will start a single

config/config.exs

@@ -14,6 +14,9 @@ config :logger, :console,
   format: "$time [$level] $message ($metadata)\n\n",
   metadata: [:module, :function, :line]
 
+config :mongodb_driver,
+  log: true
+
 # Sample configuration:
 #
 #     config :logger, :console,

lib/mongo.ex

@@ -799,7 +799,7 @@ defmodule Mongo do
     with {:ok, conn, new_cmd} <- Session.bind_session(session, cmd),
          {:ok, _cmd, response} <- DBConnection.execute(conn, %Query{action: :command}, [new_cmd], defaults(opts)),
          :ok <- Session.update_session(session, response, opts),
-         {:ok, {_flags, doc}} <- check_for_error(response) do
+         {:ok, {_flags, doc}} <- check_for_error(response, cmd, opts) do
       {:ok, doc}
     else
       {:error, error} ->
@@ -812,20 +812,20 @@ defmodule Mongo do
           {:ok, BSON.document() | nil} | {:error, Mongo.Error.t()}
   def exec_command(conn, cmd, opts) do
     with {:ok, _cmd, response} <- DBConnection.execute(conn, %Query{action: :command}, [cmd], defaults(opts)) do
-      check_for_error(response)
+      check_for_error(response, cmd, opts)
     end
   end
 
   def exec_more_to_come(conn, opts) do
     with {:ok, _cmd, response} <- DBConnection.execute(conn, %Query{action: :command}, [:more_to_come], defaults(opts)) do
-      check_for_error(response)
+      check_for_error(response, [:more_to_come], opts)
     end
   end
 
   ##
   # Checks for an error and broadcast the event.
   ##
-  defp check_for_error({%{"ok" => ok} = response, %{request_id: request_id, operation_id: operation_id, connection_id: connection_id} = event, flags, duration}) when ok == 1 do
+  defp check_for_error({%{"ok" => ok} = response, %{request_id: request_id, operation_id: operation_id, connection_id: connection_id} = event, flags, duration}, cmd, opts) when ok == 1 do
     Events.notify(
       %CommandSucceededEvent{
         reply: response,
@@ -838,10 +838,12 @@ defmodule Mongo do
       :commands
     )
 
+    do_log(cmd, duration, opts)
+
     {:ok, {flags, response}}
   end
 
-  defp check_for_error({%{"ok" => ok} = response, event, flags, duration}) when ok == 1 do
+  defp check_for_error({%{"ok" => ok} = response, event, flags, duration}, cmd, opts) when ok == 1 do
     Events.notify(
       %CommandSucceededEvent{
         reply: response,
@@ -851,10 +853,12 @@ defmodule Mongo do
       :commands
     )
 
+    do_log(cmd, duration, opts)
+
     {:ok, {flags, response}}
   end
 
-  defp check_for_error({doc, %{request_id: request_id, operation_id: operation_id, connection_id: connection_id} = event, _flags, duration}) do
+  defp check_for_error({doc, %{request_id: request_id, operation_id: operation_id, connection_id: connection_id} = event, _flags, duration}, cmd, opts) do
     error = Mongo.Error.exception(doc)
 
     Events.notify(
@@ -869,10 +873,12 @@ defmodule Mongo do
       :commands
     )
 
+    do_log(cmd, duration, opts)
+
     {:error, error}
   end
 
-  defp check_for_error({doc, event, _flags, duration}) do
+  defp check_for_error({doc, event, _flags, duration}, cmd, opts) do
     error = Mongo.Error.exception(doc)
 
     Events.notify(
@@ -884,6 +890,8 @@ defmodule Mongo do
       :commands
     )
 
+    do_log(cmd, duration, opts)
+
     {:error, error}
   end
 
@@ -1521,4 +1529,103 @@ defmodule Mongo do
   defp defaults(opts) do
     Keyword.put_new(opts, :timeout, @timeout)
   end
+
+  ## support for logging like Ecto
+  defp do_log([:more_to_come], _duration, _opts) do
+    :ok
+  end
+
+  defp do_log(cmd, duration, opts) do
+    case Keyword.has_key?(cmd, :isMaster) || Keyword.has_key?(cmd, :more_to_come) do
+      true ->
+        :ok
+
+      false ->
+        command =
+          cmd
+          |> Keyword.keys()
+          |> Enum.at(0)
+
+        {_, params} = Keyword.pop_first(cmd, command)
+        collection = Keyword.get(cmd, command)
+        do_log(command, collection, params, duration, opts)
+    end
+  end
+
+  defp do_log(command, collection, params, duration, opts) do
+    metadata = %{
+      type: :mongodb_driver,
+      command: command,
+      params: params,
+      collection: collection,
+      options: Keyword.get(opts, :telemetry_options, [])
+    }
+
+    :telemetry.execute([:mongodb_driver, :execution], %{duration: duration}, metadata)
+
+    log = Application.get_env(:mongodb_driver, :log, false)
+
+    case Keyword.get(opts, :log, log) do
+      true ->
+        Logger.log(:info, fn -> log_iodata(command, collection, params, duration) end, ansi_color: command_color(command))
+
+      false ->
+        :ok
+
+      level ->
+        Logger.log(level, fn -> log_iodata(command, collection, params, duration) end, ansi_color: command_color(command))
+    end
+  end
+
+  defp log_iodata(command, collection, params, duration) do
+    us = duration
+    ms = div(us, 100) / 10
+
+    [
+      "CMD",
+      ?\s,
+      Atom.to_string(command),
+      ?\s,
+      to_iodata(collection),
+      ?\s,
+      to_iodata(params),
+      [?\s, "db", ?=, :io_lib_format.fwrite_g(ms), ?m, ?s]
+    ]
+  end
+
+  defp to_iodata(doc) do
+    opts = Inspect.Opts.new([])
+
+    doc =
+      doc
+      |> Inspect.Algebra.to_doc(opts)
+      |> Inspect.Algebra.group()
+
+    Inspect.Algebra.format(doc, opts.width)
+  end
+
+  defp command_color(:getMore), do: :cyan
+  defp command_color(:ping), do: :cyan
+  defp command_color(:aggregate), do: :cyan
+  defp command_color(:find), do: :cyan
+  defp command_color(:count), do: :cyan
+  defp command_color(:distinct), do: :cyan
+  defp command_color(:listIndexes), do: :cyan
+  defp command_color(:listCollections), do: :cyan
+  defp command_color(:insert), do: :green
+  defp command_color(:delete), do: :red
+  defp command_color(:dropIndexes), do: :red
+  defp command_color(:drop), do: :red
+  defp command_color(:dropDatabase), do: :red
+  defp command_color(:dropUser), do: :red
+  defp command_color(:abortTransaction), do: :red
+  defp command_color(:update), do: :yellow
+  defp command_color(:findAndModify), do: :yellow
+  defp command_color(:createUser), do: :magenta
+  defp command_color(:createIndexes), do: :magenta
+  defp command_color(:create), do: :magenta
+  defp command_color(:killCursors), do: :magenta
+  defp command_color(:commitTransaction), do: :magenta
+  defp command_color(:configureFailPoint), do: :blue
+  defp command_color(_), do: nil
 end

lib/mongo/topology_description.ex

@@ -67,7 +67,13 @@ defmodule Mongo.TopologyDescription do
   Updates the current measured round trip time for the specified server (address)
   """
   def update_rrt(topology, address, round_trip_time) do
-    put_in(topology.servers[address][:round_trip_time], round_trip_time)
+    case topology.servers[address] do
+      nil ->
+        topology
+
+      _other ->
+        put_in(topology.servers[address][:round_trip_time], round_trip_time)
+    end
   end
 
   @doc """

mix.exs

@@ -2,7 +2,7 @@ defmodule Mongodb.Mixfile do
   use Mix.Project
 
   @source_url "https://github.com/zookzook/elixir-mongodb-driver"
-  @version "0.8.4"
+  @version "0.8.5"
 
   def project() do
     [
@@ -35,6 +35,7 @@ defmodule Mongodb.Mixfile do
 
   defp deps do
     [
+      {:telemetry, "~> 1.0"},
       {:db_connection, "~> 2.4.1"},
       {:decimal, "~> 2.0"},
       {:jason, "~> 1.3", only: [:dev, :test]},