Telemetry

CHANGELOG.md

@@ -6,6 +6,8 @@
 
 * [`Mix.Tasks.Pow.Extension.Phoenix.Gen.Templates`] `mix pow.extension.phoenix.gen.templates` now dynamically loads template list from the extension base module
 * [`PowResetPassword.Plug`] `PowResetPassword.Plug.load_user_by_token/2` now sets a `:pow_reset_password_decoded_token` key in `conn.private` that will be used in `PowResetPassword.Plug.update_user_password/2`
+* [`Pow.Plug.Session] `:telemetry` events are now dispatched for session creation, renewal and destruction
+* [`PowPersistentSession.Plug.Cookie] `:telemetry` events are now dispatched for creation and destruction
 
 ## v1.0.19 (2020-03-13)
 

lib/extensions/persistent_session/plug/cookie.ex

@@ -71,6 +71,7 @@ defmodule PowPersistentSession.Plug.Cookie do
   alias Pow.{Config, Operations, Plug, UUID}
 
   @cookie_key "persistent_session"
+  @telemetry_event [:pow_persistent_session, :plug, :cookie]
 
   @doc """
   Sets a persistent session cookie with a randomly generated unique token.
@@ -92,31 +93,19 @@ defmodule PowPersistentSession.Plug.Cookie do
   """
   @spec create(Conn.t(), map(), Config.t()) :: Conn.t()
   def create(conn, user, config) do
+    metadata         = Map.get(conn.private, :pow_persistent_session_metadata, [])
+    token            = gen_token(config)
+    {user, metadata} = persistent_session_value(user, metadata, conn)
+
     conn
     |> delete(config)
-    |> before_send_create(user, config)
-  end
-
-  defp before_send_create(conn, user, config) do
-    {store, store_config} = store(config)
-    token                 = gen_token(config)
-    value                 = persistent_session_value(conn, user, config)
-
-    register_before_send(conn, fn conn ->
-      store.put(store_config, token, value)
-
-      client_store_put(conn, token, config)
-    end)
+    |> before_send_create(token, {user, metadata}, config)
   end
 
-  defp persistent_session_value(conn, user, config) do
-    clauses  = user_to_get_by_clauses!(user, config)
-    metadata =
-      conn.private
-      |> Map.get(:pow_persistent_session_metadata, [])
-      |> maybe_put_fingerprint_in_session_metadata(conn)
+  defp gen_token(config) do
+    uuid = UUID.generate()
 
-    {clauses, metadata}
+    Plug.prepend_with_namespace(config, uuid)
   end
 
   defp user_to_get_by_clauses!(user, config) do
@@ -126,6 +115,12 @@ defmodule PowPersistentSession.Plug.Cookie do
     end
   end
 
+  defp persistent_session_value(user, metadata, conn) do
+    metadata = maybe_put_fingerprint_in_session_metadata(metadata, conn)
+
+    {user, metadata}
+  end
+
   defp maybe_put_fingerprint_in_session_metadata(metadata, conn) do
     conn.private
     |> Map.get(:pow_session_metadata, [])
@@ -144,6 +139,27 @@ defmodule PowPersistentSession.Plug.Cookie do
     end
   end
 
+  defp before_send_create(conn, token, {user, metadata}, config) do
+    {store, store_config} = store(config)
+    session_fingerprint   = get_session_fingerprint(conn)
+    clauses               = user_to_get_by_clauses!(user, config)
+
+    register_before_send(conn, fn conn ->
+      store.put(store_config, token, {clauses, metadata})
+
+      trigger_telemetry_event(config, :create, %{
+        conn: conn,
+        session_fingerprint: session_fingerprint,
+        user: user})
+
+      client_store_put(conn, token, config)
+    end)
+  end
+
+  defp trigger_telemetry_event(config, action, %{conn: _conn, session_fingerprint: _session_fingerprint, user: _user} = metadata) do
+    Pow.telemetry_event(config, @telemetry_event, action, metadata)
+  end
+
   @doc """
   Expires the persistent session.
 
@@ -155,6 +171,9 @@ defmodule PowPersistentSession.Plug.Cookie do
   def delete(conn, config), do: before_send_delete(conn, config)
 
   defp before_send_delete(conn, config) do
+    session_fingerprint = get_session_fingerprint(conn)
+    user                = Plug.current_user(conn)
+
     register_before_send(conn, fn conn ->
       case client_store_fetch(conn, config) do
         {nil, conn} ->
@@ -163,11 +182,22 @@ defmodule PowPersistentSession.Plug.Cookie do
         {token, conn} ->
           expire_token_in_store(token, config)
 
+          trigger_telemetry_event(config, :delete, %{
+            conn: conn,
+            session_fingerprint: session_fingerprint,
+            user: user})
+
           client_store_delete(conn, config)
       end
     end)
   end
 
+  defp get_session_fingerprint(conn) do
+    conn.private
+    |> Map.get(:pow_session_metadata, [])
+    |> Keyword.get(:fingerprint)
+  end
+
   defp expire_token_in_store(token, config) do
     {store, store_config} = store(config)
 
@@ -309,12 +339,6 @@ defmodule PowPersistentSession.Plug.Cookie do
     end
   end
 
-  defp gen_token(config) do
-    uuid = UUID.generate()
-
-    Plug.prepend_with_namespace(config, uuid)
-  end
-
   defp client_store_fetch(conn, config) do
     conn = Conn.fetch_cookies(conn)
 

lib/pow.ex

@@ -1,6 +1,8 @@
 defmodule Pow do
   @moduledoc false
 
+  alias Pow.Config
+
   @doc """
   Checks for version requirement in dependencies.
   """
@@ -16,4 +18,53 @@ defmodule Pow do
         false
     end
   end
+
+  @doc """
+  Dispatches a telemetry event.
+
+  This will dispatch an event with `:telemetry`, if `:telemetry` is available.
+
+  You can attach to these event in Pow. Here's a common example of attaching
+  to the telemetry events of session lifecycle to log them:
+
+      defmodule MyAppWeb.Pow.TelemetryListener do
+        require Logger
+
+        def install do
+          events = [
+            [:pow, :plug, :session, :create],
+            [:pow, :plug, :session, :delete],
+            [:pow, :plug, :session, :renew]
+          }]
+
+          :ok = :telemetry.attach_many("my-app-log-handler", events, &handle_event/4, :ok)
+        end
+
+        def handle_event([:pow, :plug, :sesssion, :create], _measurements, metadata, _config) do
+          Logger.info("[Pow.Plug.Session] Session \#{metadata.session_fingerprint} initiated for user \#{metadata.user.id}")
+        end
+        def handle_event([:pow, :plug, :sesssion, :delete], _measurements, metadata, _config) do
+          Logger.info("[Pow.Plug.Session] Session \#{metadata.session_fingerprint} has been deleted")
+        end
+        def handle_event([:pow, :plug, :sesssion, :renew], _measurements, metadata, _config) do
+          Logger.info("[Pow.Plug.Session] Session \#{metadaa.session_fingerprint} has renewed")
+        end
+      end
+
+  Now you can set call `MyAppWeb.Pow.TelemetryListener.install()`.
+  """
+  @spec telemetry_event(Config.t(), [atom()], atom(), map(), map()) :: :ok
+  def telemetry_event(config, event, action, metadata, measurements \\ %{}) do
+    loaded = Code.ensure_loaded?(:telemetry)
+    log?   = Config.get(config, :log_telemetry?, true)
+    event  = event ++ [action]
+
+    case loaded and log? do
+      true ->
+        :telemetry.execute(event, measurements, metadata)
+
+      false ->
+        :error
+    end
+  end
 end

lib/pow/plug/session.ex

@@ -17,6 +17,9 @@ defmodule Pow.Plug.Session do
   The session id used in the client is signed using `Pow.Plug.sign_token/4` to
   prevent timing attacks.
 
+  Telemetry events are dispatched for the lifecycle of the sessions. See
+  `Pow.telemetry_event/5` for more.
+
   ## Example
 
       @pow_config [
@@ -112,6 +115,7 @@ defmodule Pow.Plug.Session do
 
   @session_key "auth"
   @session_ttl_renewal :timer.minutes(15)
+  @telemetry_event [:pow, :plug, :session]
 
   @doc """
   Fetches session from credentials cache.
@@ -171,12 +175,13 @@ defmodule Pow.Plug.Session do
   @spec create(Conn.t(), map(), Config.t()) :: {Conn.t(), map()}
   def create(conn, user, config) do
     metadata         = Map.get(conn.private, :pow_session_metadata, [])
+    session_id       = gen_session_id(config)
     {user, metadata} = session_value(user, metadata)
 
     conn =
       conn
       |> delete(config)
-      |> before_send_create({user, metadata}, config)
+      |> before_send_create(session_id, {user, metadata}, config)
       |> Conn.put_private(:pow_session_metadata, metadata)
 
     {conn, user}
@@ -193,17 +198,26 @@ defmodule Pow.Plug.Session do
 
   defp gen_fingerprint(), do: UUID.generate()
 
-  defp before_send_create(conn, value, config) do
+  defp before_send_create(conn, session_id, {user, metadata}, config) do
     {store, store_config} = store(config)
-    session_id            = gen_session_id(config)
+    session_fingerprint   = Keyword.get(metadata, :fingerprint)
 
     register_before_send(conn, fn conn ->
-      store.put(store_config, session_id, value)
+      store.put(store_config, session_id, {user, metadata})
+
+      trigger_telemetry_event(config, :create, %{
+        conn: conn,
+        session_fingerprint: session_fingerprint,
+        user: user})
 
       client_store_put(conn, session_id, config)
     end)
   end
 
+  defp trigger_telemetry_event(config, action, %{conn: _conn, session_fingerprint: _session_fingerprint, user: _user} = metadata) do
+    Pow.telemetry_event(config, @telemetry_event, action, metadata)
+  end
+
   @doc """
   Delete an existing session in the credentials cache.
 
@@ -219,6 +233,8 @@ defmodule Pow.Plug.Session do
 
   defp before_send_delete(conn, config) do
     {store, store_config} = store(config)
+    session_fingerprint   = get_session_fingerprint(conn)
+    user                  = Plug.current_user(conn)
 
     register_before_send(conn, fn conn ->
       case client_store_fetch(conn, config) do
@@ -228,11 +244,22 @@ defmodule Pow.Plug.Session do
         {session_id, conn} ->
           store.delete(store_config, session_id)
 
+          trigger_telemetry_event(config, :delete, %{
+            conn: conn,
+            session_fingerprint: session_fingerprint,
+            user: user})
+
           client_store_delete(conn, config)
       end
     end)
   end
 
+  defp get_session_fingerprint(conn) do
+    conn.private
+    |> Map.get(:pow_session_metadata, [])
+    |> Keyword.get(:fingerprint)
+  end
+
   # TODO: Remove by 1.1.0
   defp convert_old_session_value({session_id, {user, timestamp}}) when is_number(timestamp), do: {session_id, {user, inserted_at: timestamp}}
   defp convert_old_session_value(any), do: any
@@ -249,20 +276,27 @@ defmodule Pow.Plug.Session do
     |> Keyword.get(:inserted_at)
     |> session_stale?(config)
     |> case do
-      true  -> lock_create(conn, session_id, user, config)
+      true  -> lock_renew_stale_session(conn, session_id, user, config)
       false -> {conn, user}
     end
   end
 
-  defp lock_create(conn, session_id, user, config) do
+  defp lock_renew_stale_session(conn, session_id, user, config) do
     id    = {[__MODULE__, session_id], self()}
     nodes = Node.list() ++ [node()]
 
     case :global.set_lock(id, nodes, 0) do
       true ->
-        {conn, user} = create(conn, user, config)
+        {conn, user} = create(conn, user, Config.put(config, :log_telemetry?, false))
 
         conn = register_before_send(conn, fn conn ->
+          session_fingerprint = get_session_fingerprint(conn)
+
+          trigger_telemetry_event(config, :renew, %{
+            conn: conn,
+            session_fingerprint: session_fingerprint,
+            user: user})
+
           :global.del_lock(id, nodes)
 
           conn

mix.exs

@@ -39,6 +39,7 @@ defmodule Pow.MixProject do
       {:phoenix, "~> 1.3.0 or ~> 1.4.0"},
       {:phoenix_html, ">= 2.0.0 and <= 3.0.0"},
       {:plug, ">= 1.5.0 and < 2.0.0", optional: true},
+      {:telemetry, "~> 0.4", optional: true},
 
       {:phoenix_ecto, "~> 4.1.0", only: [:dev, :test]},
       {:credo, "~> 1.2.0", only: [:dev, :test]},