Debug mode now writes through stdlib Logger to log/debug.log (overridable with PRO_TACTS_DEBUG_LOG; "stderr" restores the old destination). Timestamps make it possible to see where a CardDAV client stalled between requests.

Assisted-by: GLM 5.2 via pi

diff --git a/.gitignore b/.gitignore
index ff0886e..0e3001d 100644
--- a/.gitignore
+++ b/.gitignore
@@ -1 +1,2 @@
+/log
 /servers
diff --git a/lib/pro_tacts/config.rb b/lib/pro_tacts/config.rb
index 09909bb..fb123dd 100644
--- a/lib/pro_tacts/config.rb
+++ b/lib/pro_tacts/config.rb
@@ -22,5 +22,11 @@ module ProTacts
       value = @env.fetch("PRO_TACTS_DEBUG", nil)
       !value.nil? && value.match?(TRUTHY)
     end
+
+    # Where the debug logger writes. A path, overridable with
+    # PRO_TACTS_DEBUG_LOG; "stderr" keeps it on the process's stderr.
+    def debug_log_path
+      @env.fetch("PRO_TACTS_DEBUG_LOG", "log/debug.log")
+    end
   end
 end
diff --git a/lib/pro_tacts/debug_logger.rb b/lib/pro_tacts/debug_logger.rb
index 881d43f..def352d 100644
--- a/lib/pro_tacts/debug_logger.rb
+++ b/lib/pro_tacts/debug_logger.rb
@@ -1,18 +1,41 @@
 # frozen_string_literal: true
 
+require "fileutils"
+require "logger"
 require "rack"
 
 module ProTacts
   # Rack middleware that dumps the full request and response exchange to a
-  # log stream: method, path, every header, and the full body on both sides.
+  # Logger: method, path, every header, and the full body on both sides.
+  # Every line is prefixed ">>" (request) or "<<" (response) so multi-line
+  # XML/vCard bodies stay readable.
   #
   # Off by default because it logs contact data. The only card right now is
   # fictional, so the debug path stays verbose while the normal one-line path
   # (Roda's common_logger) can be narrowed later without losing this.
   class DebugLogger
-    def initialize(app, io: $stderr)
+    # Builds the Logger the middleware writes to: appended and unbuffered
+    # (Logger syncs its own device), one timestamped line per dump. path
+    # "stderr" writes to the process's stderr.
+    def self.open_log(path)
+      target = if path == "stderr"
+                 $stderr
+               else
+                 FileUtils.mkdir_p(File.dirname(path))
+                 path
+               end
+
+      Logger.new(target).tap do |logger|
+        logger.level = :debug
+        logger.formatter = proc do |_severity, datetime, _progname, msg|
+          "#{datetime.strftime('%Y-%m-%dT%H:%M:%S.%3N')} #{msg}\n"
+        end
+      end
+    end
+
+    def initialize(app, logger:)
       @app = app
-      @io = io
+      @logger = logger
     end
 
     def call(env)
@@ -78,7 +101,7 @@ module ProTacts
     end
 
     def write(prefix, text)
-      text.to_s.each_line(chomp: true) { |line| @io.puts("#{prefix} #{line}") }
+      text.to_s.each_line(chomp: true) { |line| @logger.debug("#{prefix} #{line}") }
     end
   end
 end
diff --git a/lib/pro_tacts/web.rb b/lib/pro_tacts/web.rb
index 445a180..30fdeae 100644
--- a/lib/pro_tacts/web.rb
+++ b/lib/pro_tacts/web.rb
@@ -29,7 +29,10 @@ module ProTacts
     # and then rewind it so the application can still access it.
     use Rack::RewindableInput::Middleware
     use Sentry::Rack::CaptureExceptions
-    use ProTacts::DebugLogger if ProTacts.config.debug?
+    if ProTacts.config.debug?
+      logger = ProTacts::DebugLogger.open_log(ProTacts.config.debug_log_path)
+      use ProTacts::DebugLogger, logger: logger
+    end
 
     plugin :all_verbs
     plugin :dav_verbs
diff --git a/test/pro_tacts/test_config.rb b/test/pro_tacts/test_config.rb
index 0faf130..1524d8f 100644
--- a/test/pro_tacts/test_config.rb
+++ b/test/pro_tacts/test_config.rb
@@ -28,4 +28,13 @@ class ConfigTest < Minitest::Test
     refute ProTacts::Config.new("PRO_TACTS_DEBUG" => "no").debug?
     refute ProTacts::Config.new("PRO_TACTS_DEBUG" => "0").debug?
   end
+
+  def test_debug_log_path_defaults_to_a_file
+    assert_equal "log/debug.log", ProTacts::Config.new({}).debug_log_path
+  end
+
+  def test_debug_log_path_is_overridable
+    assert_equal "/tmp/dav.log", ProTacts::Config.new("PRO_TACTS_DEBUG_LOG" => "/tmp/dav.log").debug_log_path
+    assert_equal "stderr", ProTacts::Config.new("PRO_TACTS_DEBUG_LOG" => "stderr").debug_log_path
+  end
 end
diff --git a/test/pro_tacts/test_debug_logger.rb b/test/pro_tacts/test_debug_logger.rb
index e253a0a..8ecd32f 100644
--- a/test/pro_tacts/test_debug_logger.rb
+++ b/test/pro_tacts/test_debug_logger.rb
@@ -1,6 +1,7 @@
 # frozen_string_literal: true
 
 require "minitest/autorun"
+require "logger"
 require "stringio"
 
 require "pro_tacts/debug_logger"
@@ -8,7 +9,8 @@ require "pro_tacts/debug_logger"
 class DebugLoggerTest < Minitest::Test
   def setup
     @io = StringIO.new
-    @app = ProTacts::DebugLogger.new(echo_app, io: @io)
+    @logger = Logger.new(@io)
+    @app = ProTacts::DebugLogger.new(echo_app, logger: @logger)
   end
 
   # Echoes a fixed response so assertions can target what the logger adds.
@@ -51,7 +53,7 @@ class DebugLoggerTest < Minitest::Test
     read = nil
     app = ProTacts::DebugLogger.new(
       ->(e) { read = e["rack.input"].read; [200, {}, [""]] },
-      io: StringIO.new
+      logger: Logger.new(StringIO.new)
     )
 
     app.call(env(body: "<x/>"))
@@ -81,4 +83,17 @@ class DebugLoggerTest < Minitest::Test
     assert_equal "text/xml", headers["Content-Type"]
     assert_equal ["<multistatus/>"], body
   end
+
+  class OpenLogTest < Minitest::Test
+    def test_appends_timestamped_lines_to_a_file_it_creates
+      require "tmpdir"
+      Dir.mktmpdir do |dir|
+        path = File.join(dir, "nested", "debug.log")
+        logger = ProTacts::DebugLogger.open_log(path)
+        logger.debug(">> PROPFIND / HTTP/1.1")
+
+        assert_match(/\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3} >> PROPFIND \/ HTTP\/1.1\n/, File.read(path))
+      end
+    end
+  end
 end