Add a debug logging mode for full request/response dumps
Debugging macOS discovery needs the PROPFIND body, which the normal one-line log cannot show. The debug middleware is off by default and switched on with PRO_TACTS_DEBUG.
Assisted-by: GLM 5.2 via pi
diff --git a/lib/pro_tacts.rb b/lib/pro_tacts.rb
new file mode 100644
index 0000000..b6f7e50
--- /dev/null
+++ b/lib/pro_tacts.rb
@@ -0,0 +1,11 @@
+# frozen_string_literal: true
+
+module ProTacts
+ # Whether debug logging is on. When true, every request and response is
+ # dumped in full — headers and bodies on both sides. Off by default because
+ # it logs contact data; see ProTacts::DebugLogger.
+ def self.debug_logging?
+ value = ENV["PRO_TACTS_DEBUG"]
+ !value.nil? && value.match?(/\A(1|true|yes)\z/i)
+ end
+end
diff --git a/lib/pro_tacts/debug_logger.rb b/lib/pro_tacts/debug_logger.rb
new file mode 100644
index 0000000..881d43f
--- /dev/null
+++ b/lib/pro_tacts/debug_logger.rb
@@ -0,0 +1,84 @@
+# frozen_string_literal: true
+
+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.
+ #
+ # 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)
+ @app = app
+ @io = io
+ end
+
+ def call(env)
+ log_request(env)
+ status, headers, body = @app.call(env)
+ parts = log_response(status, headers, body)
+ [status, headers, parts]
+ end
+
+ private
+
+ def log_request(env)
+ write(">>", "#{env['REQUEST_METHOD']} #{full_path(env)} #{env['SERVER_PROTOCOL']}")
+ each_header(env) { |name, value| write(">>", "#{name}: #{value}") }
+ body = read_request_body(env)
+ write(">>", body) unless body.empty?
+ end
+
+ def log_response(status, headers, body)
+ write("<<", "#{status}#{reason(status)}")
+ headers.each { |name, value| write("<<", "#{name}: #{value}") }
+ parts = []
+ body.each { |part| parts << part }
+ body.close if body.respond_to?(:close)
+ write("<<", parts.join) unless parts.join.empty?
+ parts
+ end
+
+ def full_path(env)
+ path = env["PATH_INFO"].to_s
+ query = env["QUERY_STRING"].to_s
+ query.empty? ? path : "#{path}?#{query}"
+ end
+
+ def each_header(env)
+ env.each do |key, value|
+ case key
+ when /\AHTTP_(.+)\z/
+ yield header_name(Regexp.last_match(1)), value
+ when "CONTENT_TYPE"
+ yield "Content-Type", value
+ when "CONTENT_LENGTH"
+ yield "Content-Length", value
+ end
+ end
+ end
+
+ def header_name(name)
+ name.split("_").map(&:capitalize).join("-")
+ end
+
+ def read_request_body(env)
+ input = env["rack.input"]
+ return "" if input.nil?
+ body = input.read
+ input.rewind
+ body
+ end
+
+ def reason(status)
+ phrase = Rack::Utils::HTTP_STATUS_CODES[status]
+ phrase ? " #{phrase}" : ""
+ end
+
+ def write(prefix, text)
+ text.to_s.each_line(chomp: true) { |line| @io.puts("#{prefix} #{line}") }
+ end
+ end
+end
diff --git a/lib/pro_tacts/web.rb b/lib/pro_tacts/web.rb
index ca6f23a..fed393e 100644
--- a/lib/pro_tacts/web.rb
+++ b/lib/pro_tacts/web.rb
@@ -20,6 +20,8 @@ end
require "rack/rewindable_input"
require "roda"
+require "pro_tacts"
+require "pro_tacts/debug_logger"
require "roda/plugins/dav_verbs"
module ProTacts
@@ -28,6 +30,7 @@ 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.debug_logging?
plugin :all_verbs
plugin :dav_verbs
diff --git a/test/pro_tacts/test_debug_logger.rb b/test/pro_tacts/test_debug_logger.rb
new file mode 100644
index 0000000..377977e
--- /dev/null
+++ b/test/pro_tacts/test_debug_logger.rb
@@ -0,0 +1,115 @@
+# frozen_string_literal: true
+
+require "minitest/autorun"
+require "stringio"
+
+require "pro_tacts"
+require "pro_tacts/debug_logger"
+
+class DebugLoggerTest < Minitest::Test
+ def setup
+ @io = StringIO.new
+ @app = ProTacts::DebugLogger.new(echo_app, io: @io)
+ end
+
+ # Echoes a fixed response so assertions can target what the logger adds.
+ def echo_app
+ body = ["<multistatus/>"]
+ ->(_env) { [207, { "Content-Type" => "text/xml", "ETag" => %("abc") }, body] }
+ end
+
+ def env(body: "", **headers)
+ {
+ "REQUEST_METHOD" => "PROPFIND",
+ "PATH_INFO" => "/dav/addressbook/",
+ "QUERY_STRING" => "",
+ "SERVER_PROTOCOL" => "HTTP/1.1",
+ "rack.input" => StringIO.new(body)
+ }.merge(headers.transform_keys { |k| "HTTP_#{k.to_s.upcase.tr('-', '_')}" })
+ end
+
+ def test_dumps_request_line_with_method_path_and_protocol
+ @app.call(env)
+
+ assert_includes @io.string, ">> PROPFIND /dav/addressbook/ HTTP/1.1"
+ end
+
+ def test_dumps_request_headers
+ @app.call(env(Depth: "1"))
+
+ assert_includes @io.string, ">> Depth: 1"
+ end
+
+ def test_dumps_request_body_with_every_line_prefixed
+ @app.call(env(body: "<propfind>\n <prop/>\n</propfind>"))
+
+ assert_includes @io.string, ">> <propfind>"
+ assert_includes @io.string, ">> <prop/>"
+ assert_includes @io.string, ">> </propfind>"
+ end
+
+ def test_request_body_is_still_readable_by_the_app
+ read = nil
+ app = ProTacts::DebugLogger.new(
+ ->(e) { read = e["rack.input"].read; [200, {}, [""]] },
+ io: StringIO.new
+ )
+
+ app.call(env(body: "<x/>"))
+
+ assert_equal "<x/>", read
+ end
+
+ def test_omits_request_body_line_when_there_is_no_body
+ @app.call(env)
+
+ refute_includes @io.string, ">> \n"
+ end
+
+ def test_dumps_response_status_headers_and_body
+ @app.call(env)
+
+ assert_includes @io.string, "<< 207 Multi-Status"
+ assert_includes @io.string, "<< Content-Type: text/xml"
+ assert_includes @io.string, "<< ETag: \"abc\""
+ assert_includes @io.string, "<< <multistatus/>"
+ end
+
+ def test_returns_the_response_intact
+ status, headers, body = @app.call(env)
+
+ assert_equal 207, status
+ assert_equal "text/xml", headers["Content-Type"]
+ assert_equal ["<multistatus/>"], body
+ end
+
+ class ToggleTest < Minitest::Test
+ def test_defaults_off_when_unset
+ with_env("PRO_TACTS_DEBUG" => nil) do
+ refute ProTacts.debug_logging?
+ end
+ end
+
+ def test_turns_on_with_truthy_values
+ with_env("PRO_TACTS_DEBUG" => "1") do
+ assert ProTacts.debug_logging?
+ end
+ end
+
+ def test_ignores_other_values
+ with_env("PRO_TACTS_DEBUG" => "no") do
+ refute ProTacts.debug_logging?
+ end
+ end
+
+ private
+
+ def with_env(vars)
+ saved = vars.keys.to_h { |k| [k, ENV[k]] }
+ vars.each { |k, v| v.nil? ? ENV.delete(k) : ENV[k] = v }
+ yield
+ ensure
+ saved.each { |k, v| v.nil? ? ENV.delete(k) : ENV[k] = v }
+ end
+ end
+end