From b30a2e98cc22ad38dfede4d4354e88b7df0cebfd Mon Sep 17 00:00:00 2001 From: Dan Schultzer Date: Fri, 7 Jun 2019 08:26:00 -0700 Subject: [PATCH 1/2] Add session telemetry events --- CHANGELOG.md | 1 + lib/pow.ex | 51 +++++++++++++++++++++++++ lib/pow/plug/session.ex | 48 ++++++++++++++++++++---- mix.exs | 1 + test/pow/plug/session_test.exs | 68 ++++++++++++++++++++++++++++++++++ 5 files changed, 162 insertions(+), 7 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index a9e39441..607c6ffd 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,6 +6,7 @@ * [`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 ## v1.0.19 (2020-03-13) diff --git a/lib/pow.ex b/lib/pow.ex index b8e6462c..0c1a4f49 100644 --- a/lib/pow.ex +++ b/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 diff --git a/lib/pow/plug/session.ex b/lib/pow/plug/session.ex index 365d1f29..ee8946f3 100644 --- a/lib/pow/plug/session.ex +++ b/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 diff --git a/mix.exs b/mix.exs index 45a86425..ef0416fd 100644 --- a/mix.exs +++ b/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]}, diff --git a/test/pow/plug/session_test.exs b/test/pow/plug/session_test.exs index d0b89cea..24b402d9 100644 --- a/test/pow/plug/session_test.exs +++ b/test/pow/plug/session_test.exs @@ -367,6 +367,74 @@ defmodule Pow.Plug.SessionTest do assert is_nil(Plug.current_user(conn)) end + describe "with telemetry logging" do + setup do + pid = self() + events = [ + [:pow, :plug, :session, :create], + [:pow, :plug, :session, :delete], + [:pow, :plug, :session, :renew] + ] + + :telemetry.attach_many("event-handler-#{inspect pid}", events, fn event, measurements, metadata, send_to: pid -> + send(pid, {:event, event, measurements, metadata}) + end, send_to: pid) + end + + test "logs create and delete", %{conn: new_conn} do + conn = + new_conn + |> init_plug() + |> run_do_create(@user) + + assert session_id = get_session_id(conn) + + assert_receive {:event, [:pow, :plug, :session, :create], _measurements, metadata} + assert metadata[:conn] + assert session_fingerprint = metadata[:session_fingerprint] + assert metadata[:user] == @user + assert {@user, session_metadata} = get_from_cache(session_id) + assert session_metadata[:fingerprint] == session_fingerprint + + conn + |> recycle_session_conn() + |> init_plug() + |> run_do_delete() + + assert_receive {:event, [:pow, :plug, :session, :delete], _measurements, metadata} + assert metadata[:conn] + assert metadata[:session_fingerprint] == session_fingerprint + assert metadata[:user] == @user + assert get_from_cache(session_id) == :not_found + end + + test "logs renewal", %{conn: conn} do + ttl = 100 + config = Keyword.merge(@default_opts, session_ttl_renewal: ttl) + stale_timestamp = :os.system_time(:millisecond) - ttl - 1 + session_id = sign_token("token") + + @store_config + |> Keyword.put(:namespace, "credentials") + |> EtsCacheMock.put({"token", {@user, inserted_at: stale_timestamp, fingerprint: "fingerprint"}}) + + conn + |> Conn.fetch_session() + |> Conn.put_session(config[:session_key], session_id) + |> run_plug(config) + + assert get_session_id(conn) != session_id + + assert_receive {:event, [:pow, :plug, :session, :renew], _measurements, metadata} + assert metadata[:conn] + assert metadata[:session_fingerprint] == "fingerprint" + assert metadata[:user] == @user + + refute_receive {:event, [:pow, :plug, :session, :delete], _measurements, _metadata} + refute_receive {:event, [:pow, :plug, :session, :create], _measurements, _metadata} + end + end + describe "with EtsCache backend" do setup do start_supervised!({EtsCache, []}) From 07c53a4b8bbddbadf9f5f68987807344995c9bd9 Mon Sep 17 00:00:00 2001 From: Dan Schultzer Date: Sun, 26 Apr 2020 17:14:20 -0700 Subject: [PATCH 2/2] Add persistent session telemetry events --- CHANGELOG.md | 1 + .../persistent_session/plug/cookie.ex | 76 ++++++++++++------- .../persistent_session/plug/cookie_test.exs | 54 ++++++++++++- 3 files changed, 102 insertions(+), 29 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 607c6ffd..4f76361e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,7 @@ * [`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) diff --git a/lib/extensions/persistent_session/plug/cookie.ex b/lib/extensions/persistent_session/plug/cookie.ex index da0818e7..b5efcdf6 100644 --- a/lib/extensions/persistent_session/plug/cookie.ex +++ b/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) diff --git a/test/extensions/persistent_session/plug/cookie_test.exs b/test/extensions/persistent_session/plug/cookie_test.exs index 8b22ec10..88c17c64 100644 --- a/test/extensions/persistent_session/plug/cookie_test.exs +++ b/test/extensions/persistent_session/plug/cookie_test.exs @@ -349,13 +349,61 @@ defmodule PowPersistentSession.Plug.CookieTest do assert get_from_cache(conn, id, backend: ets) == :not_found end - defp conn_with_session_plug(config) do - :get - |> Test.conn("/") + describe "with telemetry logging" do + setup do + pid = self() + events = [ + [:pow_persistent_session, :plug, :cookie, :create], + [:pow_persistent_session, :plug, :cookie, :delete] + ] + + :telemetry.attach_many("event-handler-#{inspect pid}", events, fn event, measurements, metadata, send_to: pid -> + send(pid, {:event, event, measurements, metadata}) + end, send_to: pid) + end + + test "logs create and delete", %{conn: conn, config: config} do + user = %User{id: 1} + + conn = + conn + |> init_plug(config) + |> Session.do_create(user, config) + |> run_create(user, config) + + assert_receive {:event, [:pow_persistent_session, :plug, :cookie, :create], _measurements, metadata} + assert metadata[:conn] + assert metadata[:user] == user + assert metadata[:session_fingerprint] + + conn + |> recycle_session_conn(config) + |> init_plug(config) + |> run_delete(config) + + assert_receive {:event, [:pow_persistent_session, :plug, :cookie, :delete], _measurements, metadata} + assert metadata[:conn] + assert metadata[:user] == user + assert metadata[:session_fingerprint] + end + end + + defp conn_with_session_plug(config, conn \\ nil) do + conn + |> Kernel.||(Test.conn(:get, "/")) |> PlugSession.call(PlugSession.init(store: ProcessStore, key: "foobar")) |> Session.call(Session.init(config)) end + defp recycle_session_conn(old_conn, config) do + conn = + :get + |> Test.conn("/") + |> Test.recycle_cookies(old_conn) + + conn_with_session_plug(config, conn) + end + defp persistent_cookie(conn, cookie_key, id) do cookies = Map.new([{cookie_key, id}]) %{conn | cookies: cookies}