Add configurable logging for proxy lifecycle events

Introduce a :log_level config option (default :debug) that logs request
start, upstream status, completion, errors, and handler rejections.
Errors always log at :error level; log_level: false silences everything.
All messages use iolists with lazy evaluation.

Author: stuartc

lib/philter.ex

@@ -98,7 +98,8 @@ defmodule Philter do
           finch_name: atom(),
           receive_timeout: pos_integer(),
           max_payload_size: pos_integer(),
-          persistable_content_types: [String.t()]
+          persistable_content_types: [String.t()],
+          log_level: Logger.level() | false
         ]
 
   @doc """
@@ -152,6 +153,9 @@ defmodule Philter do
     * `:persistable_content_types` - Content types eligible for body accumulation.
       Supports wildcards like `"text/*"`. Default: JSON, XML, and text types.
 
+    * `:log_level` - Logger level for lifecycle events (`:debug`, `:info`, etc.)
+      or `false` to disable all logging. Default: `:debug`.
+
   ## Return Value
 
   Returns the `conn` with response sent. Observations are stored in:
@@ -178,6 +182,19 @@ defmodule Philter do
     upstream_url = build_upstream_url(upstream, path, conn.query_string)
     req_content_type = get_content_type(conn.req_headers)
     outbound_headers = build_outbound_headers(Keyword.get(opts, :headers), conn, upstream)
+    log_level = config.log_level
+
+    # Log #1: Request start
+    log(log_level, fn ->
+      [
+        "Philter ",
+        conn.method,
+        " ",
+        upstream_url,
+        " host=",
+        extract_host(upstream)
+      ]
+    end)
 
     # Notify handler of request start
     case notify_request_started(handler, %{
@@ -220,7 +237,9 @@ defmodule Philter do
           observer: observer,
           status: nil,
           started_at: started_at,
-          error: nil
+          error: nil,
+          log_level: log_level,
+          upstream_url: upstream_url
         }
 
         result =
@@ -235,6 +254,20 @@ defmodule Philter do
         case result do
           {:ok, acc} ->
             observations = Observer.finalize(observer)
+            duration_us = System.monotonic_time(:microsecond) - started_at
+
+            # Log #3: Success complete
+            log(log_level, fn ->
+              [
+                "Philter complete ",
+                Integer.to_string(acc.status),
+                " ",
+                Integer.to_string(observations.response.size),
+                "B ",
+                Integer.to_string(div(duration_us, 1000)),
+                "ms"
+              ]
+            end)
 
             handler_state = handler_state(acc)
 
@@ -248,7 +281,7 @@ defmodule Philter do
                 upstream_url: upstream_url,
                 method: acc.conn.method,
                 status: acc.conn.status,
-                duration_us: System.monotonic_time(:microsecond) - started_at
+                duration_us: duration_us
               },
               handler_state
             )
@@ -298,13 +331,27 @@ defmodule Philter do
         end
 
       {:reject, status, body, _handler_state} ->
+        # Log #5: Handler rejection
+        log(log_level, fn ->
+          [
+            "Philter rejected ",
+            conn.method,
+            " ",
+            upstream_url,
+            " status=",
+            Integer.to_string(status)
+          ]
+        end)
+
         conn |> send_resp(status, body) |> halt()
     end
   end
 
   # Stream message handlers (replaces ResponseStreamer)
 
   defp handle_stream_message({:status, status}, acc) do
+    # Log #2: Status from upstream
+    log(acc.log_level, fn -> ["Philter ", Integer.to_string(status), " from upstream"] end)
     {:cont, %{acc | status: status}}
   end
 
@@ -484,6 +531,20 @@ defmodule Philter do
   defp handler_state(_), do: nil
 
   defp handle_error(acc, handler, info) do
+    # Log #4: Error
+    if acc.log_level do
+      Logger.error(fn ->
+        [
+          "Philter error ",
+          Integer.to_string(info.status),
+          " ",
+          inspect(info.error),
+          " upstream=",
+          info.upstream_url
+        ]
+      end)
+    end
+
     observations = Observer.finalize(acc.observer)
     handler_state = handler_state(acc)
 
@@ -519,4 +580,7 @@ defmodule Philter do
   defp notify_response_finished({module, _args}, result, state) do
     module.handle_response_finished(result, state)
   end
+
+  defp log(false, _fun), do: :ok
+  defp log(level, fun), do: Logger.log(level, fun)
 end

lib/philter/config.ex

@@ -28,6 +28,7 @@ defmodule Philter.Config do
   - `:receive_timeout` - Timeout in ms for receiving response (default: 15_000)
   - `:max_payload_size` - Max size in bytes for full body accumulation (default: 1_048_576 / 1MB)
   - `:persistable_content_types` - Content types eligible for full body storage (default: see below)
+  - `:log_level` - Logger level for lifecycle events, or `false` to disable (default: `:debug`)
 
   ## Default Persistable Content Types
 
@@ -45,6 +46,7 @@ defmodule Philter.Config do
   @default_finch_name Philter.Finch
   @default_receive_timeout 15_000
   @default_max_payload_size 1_048_576
+  @default_log_level :debug
   @default_persistable_content_types [
     "application/json",
     "application/xml",
@@ -57,7 +59,8 @@ defmodule Philter.Config do
           finch_name: atom(),
           receive_timeout: pos_integer(),
           max_payload_size: pos_integer(),
-          persistable_content_types: [String.t()]
+          persistable_content_types: [String.t()],
+          log_level: Logger.level() | false
         }
 
   @doc """
@@ -142,6 +145,30 @@ defmodule Philter.Config do
     end)
   end
 
+  @doc """
+  Returns the log level for lifecycle events.
+
+  Set to `false` to disable all logging. Defaults to `:debug`.
+
+  ## Examples
+
+      iex> Philter.Config.log_level()
+      :debug
+
+      iex> Philter.Config.log_level(log_level: :info)
+      :info
+
+      iex> Philter.Config.log_level(log_level: false)
+      false
+
+  """
+  @spec log_level(keyword()) :: Logger.level() | false
+  def log_level(opts \\ []) do
+    Keyword.get_lazy(opts, :log_level, fn ->
+      Application.get_env(:philter, :log_level, @default_log_level)
+    end)
+  end
+
   @doc """
   Returns all configuration as a map, with per-request overrides applied.
 
@@ -160,7 +187,8 @@ defmodule Philter.Config do
       finch_name: finch_name(opts),
       receive_timeout: receive_timeout(opts),
       max_payload_size: max_payload_size(opts),
-      persistable_content_types: persistable_content_types(opts)
+      persistable_content_types: persistable_content_types(opts),
+      log_level: log_level(opts)
     }
   end
 

test/philter_test.exs

@@ -1,5 +1,6 @@
 defmodule PhilterTest do
   use ExUnit.Case, async: true
+  import ExUnit.CaptureLog
   import Plug.Test
   import Plug.Conn
 
@@ -543,4 +544,106 @@ defmodule PhilterTest do
       assert conn.halted
     end
   end
+
+  describe "logging" do
+    test "default :debug level emits request start with method, URL, and host", %{
+      bypass: bypass,
+      upstream: upstream
+    } do
+      Bypass.expect(bypass, "GET", "/log-test", fn conn ->
+        send_resp(conn, 200, "ok")
+      end)
+
+      log =
+        capture_log([level: :debug], fn ->
+          conn(:get, "/log-test")
+          |> Philter.proxy(upstream: upstream, finch_name: Philter.TestFinch)
+        end)
+
+      assert log =~ "Philter GET"
+      assert log =~ "/log-test"
+      assert log =~ "host=localhost:#{bypass.port}"
+    end
+
+    test "log_level: false produces no log output", %{bypass: bypass, upstream: upstream} do
+      Bypass.expect(bypass, "GET", "/silent", fn conn ->
+        send_resp(conn, 200, "ok")
+      end)
+
+      log =
+        capture_log([level: :debug], fn ->
+          conn(:get, "/silent")
+          |> Philter.proxy(
+            upstream: upstream,
+            finch_name: Philter.TestFinch,
+            log_level: false
+          )
+        end)
+
+      assert log == ""
+    end
+
+    test "error paths log at :error level", %{upstream: _upstream} do
+      log =
+        capture_log([level: :error], fn ->
+          conn(:get, "/fail")
+          |> Philter.proxy(
+            upstream: "http://localhost:59999",
+            finch_name: Philter.TestFinch
+          )
+        end)
+
+      assert log =~ "Philter error 502"
+      assert log =~ "upstream=http://localhost:59999/fail"
+    end
+
+    test "response complete log includes status, size, and duration", %{
+      bypass: bypass,
+      upstream: upstream
+    } do
+      Bypass.expect(bypass, "GET", "/complete", fn conn ->
+        send_resp(conn, 200, "hello")
+      end)
+
+      log =
+        capture_log([level: :debug], fn ->
+          conn(:get, "/complete")
+          |> Philter.proxy(upstream: upstream, finch_name: Philter.TestFinch)
+        end)
+
+      assert log =~ "Philter complete 200"
+      assert log =~ "5B"
+      assert log =~ ~r/\d+ms/
+    end
+
+    test "rejection is logged with method, URL, and status", %{upstream: upstream} do
+      log =
+        capture_log([level: :debug], fn ->
+          conn(:get, "/rejected")
+          |> Philter.proxy(
+            upstream: upstream,
+            finch_name: Philter.TestFinch,
+            handler: {RejectingHandler, %{}}
+          )
+        end)
+
+      assert log =~ "Philter rejected GET"
+      assert log =~ "/rejected"
+      assert log =~ "status=413"
+    end
+
+    test "error log is suppressed when log_level: false" do
+      log =
+        capture_log([level: :error], fn ->
+          conn(:get, "/fail")
+          |> Philter.proxy(
+            upstream: "http://localhost:59999",
+            finch_name: Philter.TestFinch,
+            log_level: false
+          )
+        end)
+
+      assert log == ""
+    end
+  end
 end