Merge pull request #31 from timberio/features/support-phoenix-instrumentation

Add Phoenix instrumentation

Author: DavidAntaramian

README.md

@@ -136,6 +136,35 @@ existing pipeline or pass multiple pipeliness to `Phoenix.Router.pipe_through/1`
 Note: If you use both, it's recommended that the `Timber.ContextPlug` be called
 first.
 
+### Phoenix Controllers & Templates
+
+Timber can also log additional information about Phoenix controllers and
+templates using the instrumentation tools built right into Phoenix. All you need
+to do is add `Timber.PhoenixInstrumenter` to the list of `:instrumenters` in
+your endpoint configuration:
+
+```elixir
+config :my_app, MyApp.Endpoint,
+  http: [port: 4001],
+  root: Path.dirname(__DIR__),
+  instrumenters: [Timber.PhoenixInstrumenter],
+  pubsub: [name: MyApp.PubSub,
+           adapter: Pheonix.PubSub.PG2]
+```
+
+You will need to recompile Phoenix using `mix deps.compile phoenix` for this
+change to take effect. If you see duplicate output, try turning off Phoenix's
+default logging by modifying the `controller` definition block in `MyApp.Web`
+to add the `log: false` option:
+
+```elixir
+def controller do
+  quote do
+    use Phoenix.Controller, log: false
+  end
+end
+```
+
 ### Ecto
 
 Timber can collect information about the queries Ecto runs if you declare

lib/timber/events/controller_call.ex

@@ -0,0 +1,25 @@
+defmodule Timber.Events.ControllerCall do
+  @moduledoc """
+  Represents a controller being called
+  """
+
+  @type t :: %__MODULE__{
+    action: String.t | nil,
+    controller: String.t | nil,
+    description: IO.chardata | nil
+  }
+
+  defstruct [
+    :action,
+    :controller,
+    :description
+  ]
+
+  @spec new(Keyword.t) :: t
+  def new(opts) do
+    event = struct(__MODULE__, opts)
+    description = ["Processing by ", event.controller, ?., event.action]
+
+    %__MODULE__{ event | description: description }
+  end
+end

lib/timber/events/template_render_event.ex

@@ -4,9 +4,23 @@ defmodule Timber.Events.TemplateRenderEvent do
   """
 
   @type t :: %__MODULE__{
-    name: String.t,
-    time_ms: float
+    name: String.t | nil,
+    description: IO.chardata | nil,
+    time_ms: float | nil,
   }
 
-  defstruct [:name, :time_ms]
+  defstruct [
+    :description,
+    :name,
+    :time_ms
+  ]
+
+  @spec new(Keyword.t) :: t
+  def new(opts) do
+    event = struct(__MODULE__, opts)
+    time = Float.to_string(event.time_ms)
+    description = ["Rendered ", ?", event.name, ?", " in ", time, "ms"]
+
+    %__MODULE__{ event | description: description }
+  end
 end

lib/timber/phoenix_instrumenter.ex

@@ -0,0 +1,135 @@
+defmodule Timber.PhoenixInstrumenter do
+  @moduledoc """
+  Handles instrumentation of `Phoenix.Endpoint`
+
+  This module is designed to log events when Phoenix calls a controller or
+  renders a template. It hooks into the instrumentation tools built into
+  Phoenix. Because of this, you will have to trigger a Phoenix recompile
+  in order for the instrumentation to take effect.
+
+  ## Adding Instrumentation
+
+  Phoenix instrumenetation is controlled through the configuration for your
+  Phoenix endpoint module, typically named along the lines of `MyApp.Endpoint`.
+  This module will be configured in `config/config.exs` similar to the following:
+
+  ```
+  config :my_app, MyApp.Endpoint,
+    http: [port: 4001],
+    root: Path.dirname(__DIR__),
+    pubsub: [name: MyApp.PubSub,
+              adapter: Phoenix.PubSub.PG2]
+  ```
+
+  You will need to add an `:instrumenters` key to this configuration with
+  a value of `[Timber.PhoenixInstrumenter]`. This would update the configuration
+  to something like the following:
+
+
+  ```
+  config :my_app, MyApp.Endpoint,
+    http: [port: 4001],
+    root: Path.dirname(__DIR__),
+    instrumenters: [Timber.PhoenixInstrumenter],
+    pubsub: [name: MyApp.PubSub,
+              adapter: Phoenix.PubSub.PG2]
+  ```
+
+  In order for this to take affect locally, you will need to recompile Phoenix using
+  the command `mix deps.compile phoenix`. By default, Timber will log calls to controllers
+  and template renders at the `:info` level. You can change this by adding an additional
+  configuration line:
+
+  ```
+  config :timber, :instrumentation_level, :debug
+  ```
+
+  If you're currently displaying logs at the `:debug` level, you will also see that
+  Phoenix has built-in logging already at this level. The Phoenix logger will not emit
+  Timber events, so you can turn it off to stop the duplicate output. The Phoenix logger
+  is controlled through the `MyApp.Web` module. Look for a definition block like the
+  following:
+
+  ```
+  def controller do
+    quote do
+      use Phoenix.Controller
+    end
+  end
+  ```
+
+  You will want to modify this to the following
+
+  ```
+  def controller do
+    quote do
+      use Phoenix.Controller, log: false
+    end
+  end
+  ```
+  """
+
+  require Logger
+  
+  alias Timber.Events.ControllerCall
+  alias Timber.Events.TemplateRenderEvent
+
+  @doc false
+  @spec phoenix_controller_call(:start | :stop, map | non_neg_integer, map | :ok) :: :ok
+  def phoenix_controller_call(:start, %{module: module}, %{conn: conn}) do
+    log_level = get_log_level(:info)
+
+    controller = inspect(module)
+    action_name =
+      conn
+      |> Phoenix.Controller.action_name()
+      |> Atom.to_string
+
+    # Phoenix actions are always 2 arity function
+    action = action_name <> "/2"
+
+    event = ControllerCall.new(
+      action: action,
+      controller: controller
+    )
+
+    Logger.log(log_level, event.description, timber_event: event)
+
+    :ok
+  end
+
+  def phoenix_controller_call(:stop, _time_diff, :ok) do
+    :ok
+  end
+
+  @doc false
+  @spec phoenix_controller_render(:start | :stop, map | non_neg_integer, map | :ok) :: :ok
+  def phoenix_controller_render(:start, _compile_metadata, %{template: template_name}) do
+    {:ok, template_name}
+  end
+
+  def phoenix_controller_render(:stop, time_diff, {:ok, template_name}) do
+    log_level = get_log_level(:info)
+
+    # This comes in as native time but is expected to be a float representing
+    # milliseconds
+    time_ms =
+      time_diff
+      |> System.convert_time_unit(:native, :milliseconds)
+      |> :erlang.float()
+
+    event = TemplateRenderEvent.new(
+      name: template_name,
+      time_ms: time_ms
+    )
+
+    Logger.log(log_level, event.description, timber_event: event)
+
+    :ok
+  end
+
+  @spec get_log_level(atom) :: atom
+  defp get_log_level(default) do
+    Application.get_env(:timber, :instrumentation_level, default)
+  end
+end

mix.exs

@@ -159,6 +159,7 @@ defmodule Timber.Mixfile do
       {:ex_doc, "~> 0.14", only: [:dev, :docs]},
       {:excoveralls, "~> 0.5", only: [:test]},
       {:plug, "~> 1.2", optional: true},
+      {:phoenix, "~> 1.2", optional: true},
       {:poison, "~> 2.2.0"},
     ]
   end

mix.lock

@@ -14,6 +14,8 @@
   "metrics": {:hex, :metrics, "1.0.1", "25f094dea2cda98213cecc3aeff09e940299d950904393b2a29d191c346a8486", [:rebar3], []},
   "mime": {:hex, :mime, "1.0.1", "05c393850524767d13a53627df71beeebb016205eb43bfbd92d14d24ec7a1b51", [:mix], []},
   "mimerl": {:hex, :mimerl, "1.0.2", "993f9b0e084083405ed8252b99460c4f0563e41729ab42d9074fd5e52439be88", [:rebar3], []},
+  "phoenix": {:hex, :phoenix, "1.2.1", "6dc592249ab73c67575769765b66ad164ad25d83defa3492dc6ae269bd2a68ab", [:mix], [{:cowboy, "~> 1.0", [hex: :cowboy, optional: true]}, {:phoenix_pubsub, "~> 1.0", [hex: :phoenix_pubsub, optional: false]}, {:plug, "~> 1.1", [hex: :plug, optional: false]}, {:poison, "~> 1.5 or ~> 2.0", [hex: :poison, optional: false]}]},
+  "phoenix_pubsub": {:hex, :phoenix_pubsub, "1.0.1", "c10ddf6237007c804bf2b8f3c4d5b99009b42eca3a0dfac04ea2d8001186056a", [:mix], []},
   "plug": {:hex, :plug, "1.2.2", "cfbda521b54c92ab8ddffb173fbaabed8d8fc94bec07cd9bb58a84c1c501b0bd", [:mix], [{:cowboy, "~> 1.0", [hex: :cowboy, optional: true]}, {:mime, "~> 1.0", [hex: :mime, optional: false]}]},
   "poison": {:hex, :poison, "2.2.0", "4763b69a8a77bd77d26f477d196428b741261a761257ff1cf92753a0d4d24a63", [:mix], []},
   "poolboy": {:hex, :poolboy, "1.5.1", "6b46163901cfd0a1b43d692657ed9d7e599853b3b21b95ae5ae0a777cf9b6ca8", [:rebar], []},