dav: log a body so it reads back byte for byte
The log chomped each CR, and the final newline went too;
no blank line split the head from the body it ran into.
Now it's laid out like HTTP, the body split on newlines alone,
so read_request gets back the bytes the client sent, every one.
Assisted-by: Claude Opus 5 via Claude Code
diff --git a/lib/pro_tacts/exchange_log.rb b/lib/pro_tacts/exchange_log.rb
index e9111aa..bb9253c 100644
--- a/lib/pro_tacts/exchange_log.rb
+++ b/lib/pro_tacts/exchange_log.rb
@@ -63,6 +63,28 @@ module ProTacts
end
end
+ # Reads one exchange's request back out of the log at path or a
+ # rotation of it: the request line and headers as logged, and the
+ # body byte for byte. nil when none of them holds the id.
+ #: (String id, String | Pathname path) -> [Array[String], String]?
+ def self.read_request(id, path)
+ marker = "#{id} >> ".b
+ # Logger's rotations, newest first (Logger::LogDevice#shift_log_age).
+ [path.to_s, *(0...ROTATIONS).map { "#{path}.#{it}" }].each do |log|
+ next unless File.exist?(log)
+
+ lines = File.binread(log).split("\n").filter_map do |line|
+ _stamp, _, rest = line.partition(" ")
+ rest.delete_prefix(marker) if rest.start_with?(marker)
+ end
+ next if lines.empty?
+
+ blank = lines.index("") or raise ArgumentError, "exchange #{id} in #{log} has no blank line after its head"
+ return [lines.take(blank), lines.drop(blank + 1).join("\n")]
+ end
+ nil
+ end
+
# everything logs every DAV exchange rather than the ones that went
# wrong (Config#debug?).
#: (Rack::_App app, path: String | Pathname, everything: bool) -> void
@@ -131,24 +153,33 @@ module ProTacts
#: (Rack::env env) -> Array[String]
def request(env)
- lines = ["#{env.fetch('REQUEST_METHOD')} #{full_path(env)} #{env.fetch('SERVER_PROTOCOL')}"]
+ head = ["#{env.fetch('REQUEST_METHOD')} #{full_path(env)} #{env.fetch('SERVER_PROTOCOL')}"]
env.each do |key, value|
case key
- when /\AHTTP_(.+)\z/ then lines << "#{header_name(key.delete_prefix('HTTP_'))}: #{value}"
- when "CONTENT_TYPE" then lines << "Content-Type: #{value}"
- when "CONTENT_LENGTH" then lines << "Content-Length: #{value}"
+ when /\AHTTP_(.+)\z/ then head << "#{header_name(key.delete_prefix('HTTP_'))}: #{value}"
+ when "CONTENT_TYPE" then head << "Content-Type: #{value}"
+ when "CONTENT_LENGTH" then head << "Content-Length: #{value}"
end
end
- lines.flat_map { prefixed(">>", it) } + prefixed(">>", request_body(env))
+ message(">>", head, request_body(env))
end
#: (Integer status, Rack::headers headers, String body) -> Array[String]
def response(status, headers, body)
- lines = ["#{status}#{reason(status)}"]
+ head = ["#{status}#{reason(status)}"]
headers.each do |name, value|
- Array(value).each { lines << "#{name}: #{it}" }
+ Array(value).each { head << "#{name}: #{it}" }
end
- lines.flat_map { prefixed("<<", it) } + prefixed("<<", body)
+ message("<<", head, body)
+ end
+
+ # Laid out as HTTP lays out a message, so that read_request can take
+ # it apart: the head, a blank line, then the body split on "\n"
+ # alone, which keeps each CR and leaves a final newline as an empty
+ # last line.
+ #: (String prefix, Array[String] head, String body) -> Array[String]
+ def message(prefix, head, body)
+ (head + [""] + body.b.split("\n", -1)).map { "#{prefix} #{it}".b }
end
#: (Rack::env env) -> String
@@ -182,8 +213,8 @@ module ProTacts
phrase ? " #{phrase}" : ""
end
- # Binary throughout, so a request body that is not UTF-8 and a
- # response body that is can share one message.
+ # Binary, like message's lines, so an exception message that is not
+ # UTF-8 still joins them.
#: (String prefix, String text) -> Array[String]
def prefixed(prefix, text)
text.b.lines(chomp: true).map { "#{prefix} #{it}".b }
diff --git a/test/pro_tacts/test_exchange_log.rb b/test/pro_tacts/test_exchange_log.rb
index 2a0c2c5..e8a44d8 100644
--- a/test/pro_tacts/test_exchange_log.rb
+++ b/test/pro_tacts/test_exchange_log.rb
@@ -49,6 +49,12 @@ class ExchangeLogTest < Minitest::Test
path.exist? ? path.readlines.reject { it.start_with?("#") }.join : ""
end
+ # The last request's head and body, read back out of the log.
+ def read_back
+ id = last_request.env.fetch(ProTacts::ExchangeLog::ENV_KEY)
+ ProTacts::ExchangeLog.read_request(id, @directory / "exchange.log")
+ end
+
def test_a_successful_exchange_is_not_logged
request "/dav/addressbook/", method: "PROPFIND"
@@ -168,6 +174,47 @@ class ExchangeLogTest < Minitest::Test
assert_includes logged, "<< 200 OK"
end
+ def test_a_logged_request_reads_back_byte_for_byte
+ @stub.status = 412
+ card = "BEGIN:VCARD\r\nNOTE:Zoë\r\n\r\nEND:VCARD\r\n"
+
+ put "/dav/addressbook/new.vcf", card, "CONTENT_TYPE" => "text/vcard", "HTTP_IF_MATCH" => '"abc"'
+
+ head, body = read_back
+ assert_match %r{\APUT /dav/addressbook/new\.vcf HTTP/1\.\d\z}, head.first
+ assert_includes head, "Content-Type: text/vcard"
+ assert_includes head, 'If-Match: "abc"'
+ assert_equal card.b, body
+ end
+
+ def test_a_body_without_a_final_newline_reads_back_without_one
+ @stub.status = 412
+
+ put "/dav/addressbook/new.vcf", "BEGIN:VCARD"
+
+ assert_equal "BEGIN:VCARD", read_back.last
+ end
+
+ def test_a_request_with_no_body_reads_back_with_an_empty_one
+ @stub.status = 404
+
+ delete "/dav/addressbook/nope.vcf"
+
+ assert_equal "", read_back.last
+ end
+
+ def test_a_request_reads_back_from_a_rotated_log
+ @stub.status = 404
+ request "/dav/addressbook/", method: "PROPFIND"
+ (@directory / "exchange.log").rename(@directory / "exchange.log.0")
+
+ assert_match %r{\APROPFIND /dav/addressbook/ }, read_back.first.first
+ end
+
+ def test_an_id_no_log_holds_reads_back_as_nil
+ assert_nil ProTacts::ExchangeLog.read_request("0123456789ab", @directory / "exchange.log")
+ end
+
def test_a_body_that_is_not_utf_8_logs_beside_one_that_is
@stub.status = 412
app