dav: log failed exchanges under an id Sentry carries
Two captures fold into one, and it keeps the exchanges that fail;
each line leads with the id Sentry holds, so an alert points down the trail.
A 201 that warned is kept, a 401 is not;
PRO_TACTS_DEBUG logs every exchange, for the probes that need the lot.
Assisted-by: Claude Opus 5 via Claude Code
diff --git a/.dockerignore b/.dockerignore
index ecf73c9..d201826 100644
--- a/.dockerignore
+++ b/.dockerignore
@@ -6,8 +6,8 @@
.envrc
.quire
.ramekin
-# data/ is the real address book; log/ holds unhandled captures with
-# every header. Neither belongs in an image.
+# data/ is the real address book; log/ holds exchange logs with every
+# header and body. Neither belongs in an image.
data
log
tmp
diff --git a/AGENTS.md b/AGENTS.md
index 7513449..ef210c6 100644
--- a/AGENTS.md
+++ b/AGENTS.md
@@ -49,7 +49,8 @@ lib/pro_tacts/
├── vcard/parser.rb # One card's bytes into lines
├── config.rb # Every environment read in the app
├── profile.rb # carddav.mobileconfig generation
-└── debug_logger.rb # Full request/response dumps, off by default
+└── exchange_log.rb # Failed DAV exchanges, whole, under an id Sentry
+ # carries
lib/roda/plugins/dav_verbs.rb # PROPFIND and REPORT routing verbs
lib/sequel/extensions/sole.rb # `first`, minus the ambiguity
db/migrations/ # Sequel migrations, run on every store open
@@ -91,10 +92,12 @@ not a fixture; edit a `.vcf` to change what the replay serves.
refused until you pass both. The
security of that rests on the app being reachable only through
`tailscale serve` — never bind it to anything but localhost.
-- Unanswered requests (404s, app-level 403s, and 5xx) are written to
- `log/unhandled` in the fixture layout. When implementing something a
- client asked for, look there first — and strip the identifying headers
- before promoting a capture into `test/fixtures`.
+- DAV exchanges that went wrong (a status of 400 or more but 401, a
+ crash, or a report to Sentry) are written whole to `log/exchange.log`,
+ each line prefixed by the id Sentry carries as the `exchange` tag.
+ When implementing something a client asked for, look there first — and
+ strip the identifying headers before promoting an exchange into
+ `test/fixtures`.
- No request body reaches Sentry: `send_default_pii` is off in
`config.ru`, because card content never leaves the machine. The URL,
headers, exception messages, and `capture_message` text still do, so
@@ -116,8 +119,7 @@ not a fixture; edit a `.vcf` to change what the replay serves.
- `supported_http_methods` in `config/puma.rb` *replaces* Puma's default
method list rather than extending it. Any method the app answers must be
named there or Puma returns 501 from the HTTP parser, before Rack runs —
- so the request never reaches the app and `UnhandledRequests` cannot
- capture it. Adding a route is two files, not one.
+ so the request never reaches the app and `ExchangeLog` cannot log it. Adding a route is two files, not one.
- Application code reads configuration through `ProTacts.config` only; add
a method to `config.rb` rather than reaching for `ENV`. The Rakefile is
outside that rule and reads `PRO_TACTS_HOSTNAME` directly.
@@ -156,9 +158,9 @@ not a fixture; edit a `.vcf` to change what the replay serves.
the one being served — a fixture, a test, a task pointed elsewhere.
- `test/test_helper.rb` sets `ENV` before it requires the app, and the
requires cannot all move to the top because of it: the app reads
- configuration as it loads, since the unhandled-request middleware is
- given its directory at class-definition time. Set it afterwards and
- the 404 captures land in `log/` instead of `tmp/`.
+ configuration as it loads, since the exchange log is given its path at
+ class-definition time. Set it afterwards and the failed exchanges land
+ in `log/` instead of a tmpdir.
- Only three things in the database cannot be rebuilt: the cards, the
change log, and the birthdays — a partial date has no vCard 3.0
spelling, so it lives beside its card rather than in it (see
diff --git a/README.md b/README.md
index 3c768de..3492779 100644
--- a/README.md
+++ b/README.md
@@ -70,12 +70,13 @@ of the group `sync:*`, which everyone gets, and of `sync:<name>`, where
the name is the user's Tailscale display name. A card a client creates
joins its writer's group. See `docs/plans/2026-09-12-per-user-books.md`.
-Requests the server cannot answer — a 404, a refused report, or a crash —
-are kept under `log/unhandled`, one directory per distinct request, in the
-same layout as `test/fixtures/macos-exchange`. A client asking for
-something unimplemented therefore leaves behind enough to implement it, and
-the capture can be promoted to a fixture by copying it and stripping the
-identifying headers.
+DAV exchanges that go wrong — a status of 400 or more other than the 401
+above, a crash, or a request that reported to Sentry — are written whole
+to `log/exchange.log`, rotated by size. Each exchange has an id that
+Sentry carries as the `exchange` tag, so an alert names the exchange to
+read. A client asking for something unimplemented therefore leaves behind
+enough to implement it. `PRO_TACTS_DEBUG=1` logs every DAV exchange
+instead, for reading back a write that succeeded.
Sentry gets no request body at all, because `send_default_pii` is off, so
the cards themselves never leave the machine.
diff --git a/Rakefile b/Rakefile
index 5b0ea2e..419f592 100644
--- a/Rakefile
+++ b/Rakefile
@@ -23,11 +23,11 @@ task :dev do
# entr's watch list is fd's snapshot at launch: a file created
# after `rake dev` starts is never watched, and edits to it never
# reload the server — restart the task when work adds a file.
- # A dev session's debug exchanges go to their own log, truncated per
- # start, so reading a session back never means picking it out of older
- # ones — log/debug.log stays the deployment default. An exported
- # PRO_TACTS_DEBUG_LOG (e.g. stderr) wins over both.
- ENV["PRO_TACTS_DEBUG_LOG"] ||= "log/dev.log"
+ # A dev session's exchanges go to their own log, truncated per start,
+ # so reading a session back never means picking it out of older ones —
+ # log/exchange.log stays the deployment default. An exported
+ # PRO_TACTS_EXCHANGE_LOG (e.g. stderr) wins over both.
+ ENV["PRO_TACTS_EXCHANGE_LOG"] ||= "log/dev.log"
File.truncate("log/dev.log", 0) if File.exist?("log/dev.log")
Dir.mktmpdir("pro-tacts-dev") do |dir|
@@ -44,13 +44,13 @@ task :fixtures do
# Mirrors test/test_helper.rb, which cannot be required here without
# minitest/autorun running its at_exit hook inside rake. Its own
# tmpdir, so a fixture re-record cannot race a concurrent test run.
- # The debug log dies with that tmpdir too: the fixture files are the
+ # The exchange log dies with that tmpdir too: the fixture files are the
# durable record of a re-record, and a replay's exchanges must not
# append to a log a real client session also uses.
Dir.mktmpdir("pro-tacts-test") do |dir|
data_dir = Pathname.new(dir)
ENV["PRO_TACTS_DATA_DIR"] = data_dir.to_s
- ENV["PRO_TACTS_DEBUG_LOG"] ||= (data_dir / "debug.log").to_s
+ ENV["PRO_TACTS_EXCHANGE_LOG"] ||= (data_dir / "exchange.log").to_s
require "pro_tacts/web"
require_relative "test/fixture_data"
require_relative "test/pro_tacts/exchange_fixtures"
diff --git a/config.ru b/config.ru
index 44258b6..60172fd 100644
--- a/config.ru
+++ b/config.ru
@@ -40,12 +40,11 @@ Sentry.init do |sentry|
sentry.before_send = drop_identity
sentry.before_send_transaction = drop_identity
- # The debug log is a local-only record of full exchanges, bodies and
- # all. Sentry's sentry_logger hook would otherwise turn every one of
- # its lines into a breadcrumb, and send_default_pii has no say over
- # breadcrumbs. Keyed on the progname DebugLogger#write passes with
- # each line.
- sentry.exclude_loggers = [ProTacts::DebugLogger::PROGNAME]
+ # The exchange log is a local-only record of whole exchanges, bodies
+ # and all. Sentry's sentry_logger hook would otherwise turn it into
+ # breadcrumbs, and send_default_pii has no say over breadcrumbs. Keyed
+ # on the progname ExchangeLog#write passes with each exchange.
+ sentry.exclude_loggers = [ProTacts::ExchangeLog::PROGNAME]
sentry.traces_sample_rate = 1.0
end
diff --git a/config/puma.rb b/config/puma.rb
index 724ecab..70dab82 100644
--- a/config/puma.rb
+++ b/config/puma.rb
@@ -1,7 +1,7 @@
# Puma replaces its default method list with this one rather than adding to
# it, so every method the app answers has to be named here or Puma rejects
-# the request with a 501 before Rack sees it — and UnhandledRequests never
-# gets to capture it. The DAV verbs match the privileges advertised in
+# the request with a 501 before Rack sees it — and ExchangeLog never gets
+# to log it. The DAV verbs match the privileges advertised in
# current-user-privilege-set: DAV:write and DAV:bind imply PUT, DAV:unbind
# implies DELETE (RFC 3744 sections 3.2, 3.9, and 3.10). POST is the web
# UI's alone — the browser's create, no DAV meaning.
diff --git a/docs/plans/2026-09-13-failed-exchanges-only.md b/docs/plans/2026-09-13-failed-exchanges-only.md
new file mode 100644
index 0000000..ffd3941
--- /dev/null
+++ b/docs/plans/2026-09-13-failed-exchanges-only.md
@@ -0,0 +1,25 @@
+# Only failed DAV exchanges are logged
+
+2026-09-13. Amends "Every DAV exchange is logged locally" in
+`docs/plans/2026-09-13-dav-observability.md` before it shipped: the
+exchange log keeps the DAV exchanges that went wrong, not every one.
+
+An exchange went wrong when its status is 400 or more other than 401,
+when it raised, or when it reported to Sentry while it ran. The last
+case covers an arrival report on a PUT that succeeded, and it keeps the
+id honest: every `exchange` tag Sentry carries names an exchange the log
+holds. A 401 stays out because it is the identity gate refusing a
+request that names nobody, whose body came from outside the tailnet.
+
+The DAV routes are the paths under `/dav/` and `/.well-known/`, plus any
+verb the admin screens do not answer, wherever it lands. That catches
+the PROPFIND on `/`, and a DAV request to a path nothing routes.
+
+A successful write still has to be readable, for the probes in
+`tasks/probe.rake` and for a photo fixture. `PRO_TACTS_DEBUG`, which
+switched the old debug log on, now widens the exchange log to every DAV
+exchange, and the footer's `+debug` label stays with it.
+
+The rest of that section stands: one middleware, a size-rotated file
+under `log/`, the id on the request's Sentry scope, and a rake task to
+extract an exchange as a fixture.
diff --git a/lib/pro_tacts/admin/layout.rb b/lib/pro_tacts/admin/layout.rb
index 76df395..2907189 100644
--- a/lib/pro_tacts/admin/layout.rb
+++ b/lib/pro_tacts/admin/layout.rb
@@ -103,7 +103,7 @@ module ProTacts
# footer exists to end.
#
# Debug logging says so while it is on because it dumps
- # whole requests, contact data included (see DebugLogger),
+ # every sync whole, contact data included (see ExchangeLog),
# and a log left recording is the kind of thing found months
# later. Off, the label is absent: the footer states what is
# true, and the quiet case is the normal one. It reads as a
diff --git a/lib/pro_tacts/config.rb b/lib/pro_tacts/config.rb
index 8e8b07f..9b3c906 100644
--- a/lib/pro_tacts/config.rb
+++ b/lib/pro_tacts/config.rb
@@ -23,8 +23,10 @@ module ProTacts
@env.fetch("SENTRY_DSN", nil)
end
- # Whether to dump full request/response exchanges to the log. Off by
- # default because it logs contact data. See ProTacts::DebugLogger.
+ # Whether the exchange log keeps every DAV exchange rather than the
+ # ones that went wrong, so a write that succeeded can be read back
+ # (tasks/probe.rake). Off by default because it records every sync
+ # whole. See ProTacts::ExchangeLog.
#: () -> bool
def debug?
value = @env.fetch("PRO_TACTS_DEBUG", nil)
@@ -50,19 +52,13 @@ module ProTacts
path.nil? ? data_dir / "contacts.db" : Pathname.new(path)
end
- # Where requests the app could not answer are kept, one directory per
- # distinct request. Under log/ because it holds request data and is not
- # meant to be committed. See ProTacts::UnhandledRequests.
- #: () -> Pathname
- def unhandled_dir
- Pathname.new(@env.fetch("PRO_TACTS_UNHANDLED_DIR", "log/unhandled"))
- end
-
- # Where the debug logger writes. A path, overridable with
- # PRO_TACTS_DEBUG_LOG; "stderr" keeps it on the process's stderr.
+ # Where the exchange log writes. A path, overridable with
+ # PRO_TACTS_EXCHANGE_LOG; "stderr" keeps it on the process's stderr.
+ # Under log/ because it holds request data and is not meant to be
+ # committed. See ProTacts::ExchangeLog.
#: () -> String
- def debug_log_path
- @env.fetch("PRO_TACTS_DEBUG_LOG", "log/debug.log")
+ def exchange_log_path
+ @env.fetch("PRO_TACTS_EXCHANGE_LOG", "log/exchange.log")
end
# The CardDAV account's display name, PRO_TACTS_PROFILE_NAME — what
diff --git a/lib/pro_tacts/debug_logger.rb b/lib/pro_tacts/debug_logger.rb
deleted file mode 100644
index faefbcd..0000000
--- a/lib/pro_tacts/debug_logger.rb
+++ /dev/null
@@ -1,143 +0,0 @@
-
-require "fileutils"
-require "logger"
-require "pathname"
-require "rack"
-
-module ProTacts
- # Rack middleware that dumps the full request and response exchange to a
- # 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.
- class DebugLogger
- # @rbs @app: Rack::_App
- # @rbs @logger: Logger
-
- # Identifies this logger's lines to Sentry's sentry_logger
- # breadcrumb hook, which keys its exclude list on the progname
- # (see config.ru). Every line here is a local-only record of a
- # full exchange — bodies included — so none of it may ride to
- # Sentry as a breadcrumb, which send_default_pii does not govern.
- PROGNAME = "ProTacts::DebugLogger" #: String
-
- # 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.
- #: (String | Pathname path) -> Logger
- def self.open_log(path)
- target = if path.to_s == "stderr"
- $stderr
- else
- FileUtils.mkdir_p(Pathname.new(path).dirname)
- path.to_s
- 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
-
- #: (Rack::_App app, logger: Logger) -> void
- def initialize(app, logger:)
- @app = app
- @logger = logger
- end
-
- #: (Rack::env env) -> Rack::response
- def call(env)
- log_request(env)
- status, headers, body = @app.call(env)
- parts = log_response(status, headers, body)
- [status, headers, parts]
- end
-
- private
-
- #: (Rack::env env) -> void
- def log_request(env)
- write(">>", "#{env.fetch('REQUEST_METHOD')} #{full_path(env)} #{env.fetch('SERVER_PROTOCOL')}")
- each_header(env) do |name, value|
- write(">>", "#{name}: #{value}")
- end
- body = read_request_body(env)
- write(">>", body) unless body.empty?
- end
-
- # Returns the body parts it consumed, for the caller to send on in
- # place of the body it read.
- #: (Integer status, Rack::headers headers, Rack::_Body body) -> Array[String]
- def log_response(status, headers, body)
- write("<<", "#{status}#{reason(status)}")
- headers.each do |name, value|
- write("<<", "#{name}: #{value}")
- end
- parts = [] #: Array[String]
- body.each do |part|
- parts << part
- end
- # A body holding a resource closes it. No signature can say
- # "close if you have one", so the cast carries what respond_to?
- # has already established.
- (_ = body).close if body.respond_to?(:close)
- write("<<", parts.join) unless parts.join.empty?
- parts
- end
-
- #: (Rack::env env) -> String
- def full_path(env)
- path = env["PATH_INFO"].to_s
- query = env["QUERY_STRING"].to_s
- query.empty? ? path : "#{path}?#{query}"
- end
-
- #: (Rack::env env) { (String, untyped) -> void } -> void
- def each_header(env)
- env.each do |key, value|
- case key
- when /\AHTTP_(.+)\z/
- yield header_name(key.delete_prefix("HTTP_")), value
- when "CONTENT_TYPE"
- yield "Content-Type", value
- when "CONTENT_LENGTH"
- yield "Content-Length", value
- end
- end
- end
-
- #: (String name) -> String
- def header_name(name)
- name.split("_").map(&:capitalize).join("-")
- end
-
- #: (Rack::env env) -> String
- def read_request_body(env)
- input = env["rack.input"]
- return "" if input.nil?
- body = input.read
- input.rewind
- body
- end
-
- #: (Integer status) -> String
- def reason(status)
- phrase = Rack::Utils::HTTP_STATUS_CODES[status]
- phrase ? " #{phrase}" : ""
- end
-
- #: (String prefix, String text) -> void
- def write(prefix, text)
- text.to_s.lines(chomp: true).each do |line|
- # The progname form (block for the message) is what carries
- # PROGNAME to Logger#add, where Sentry's hook reads it; the
- # custom formatter ignores it, so the log's format is
- # unchanged.
- @logger.debug(PROGNAME) { "#{prefix} #{line}" }
- end
- end
- end
-end
diff --git a/lib/pro_tacts/exchange_log.rb b/lib/pro_tacts/exchange_log.rb
new file mode 100644
index 0000000..2b44836
--- /dev/null
+++ b/lib/pro_tacts/exchange_log.rb
@@ -0,0 +1,195 @@
+require "fileutils"
+require "logger"
+require "pathname"
+require "rack"
+require "securerandom"
+require "sentry-ruby"
+
+module ProTacts
+ # Rack middleware that writes the DAV exchanges that went wrong to a
+ # local log, whole: the request line, every header, and both bodies,
+ # photo bytes included. Sentry says that an exchange went wrong and
+ # this log says what it was; card content reaches only the second
+ # (docs/plans/2026-09-13-dav-observability.md, amended by
+ # docs/plans/2026-09-13-failed-exchanges-only.md).
+ #
+ # Each DAV exchange gets an id, set as the `exchange` tag on the
+ # request's Sentry scope and written at the head of each of its lines
+ # here, so an alert names the exchange to read.
+ class ExchangeLog
+ # @rbs @app: Rack::_App
+ # @rbs @logger: Logger
+ # @rbs @everything: bool
+
+ # Identifies this log's lines to Sentry's sentry_logger breadcrumb
+ # hook, which keys its exclude list on the progname (see config.ru):
+ # the lines carry card content, and send_default_pii has no say over
+ # breadcrumbs.
+ PROGNAME = "ProTacts::ExchangeLog" #: String
+
+ # A photo PUT is a megabyte of base64 on its own.
+ ROTATE_AT = 10 * 1024 * 1024 #: Integer
+ ROTATIONS = 5 #: Integer
+
+ # The paths the DAV half routes. The verbs the admin screens answer
+ # are the other test: any other verb is a DAV client's wherever it
+ # lands, which is what catches the PROPFIND on / and a DAV request
+ # to a path nothing routes.
+ DAV_PATH = %r{\A/(dav|\.well-known)(/|\z)} #: Regexp
+ WEB_VERBS = %w[GET HEAD POST].freeze #: Array[String]
+
+ # Builds the Logger the middleware writes to: appended, unbuffered
+ # (Logger syncs its own device), and rotated by size. path "stderr"
+ # writes to the process's stderr instead.
+ #: (String | Pathname path) -> Logger
+ def self.open_log(path)
+ target = if path.to_s == "stderr"
+ $stderr
+ else
+ FileUtils.mkdir_p(Pathname.new(path).dirname)
+ path.to_s
+ end
+
+ Logger.new(target, ROTATIONS, ROTATE_AT).tap do |logger|
+ logger.level = :info
+ logger.formatter = proc do |_severity, datetime, _progname, msg|
+ stamp = datetime.strftime("%Y-%m-%dT%H:%M:%S.%3N")
+ msg.to_s.lines.map { "#{stamp} #{it}" }.join
+ end
+ end
+ end
+
+ # everything logs every DAV exchange rather than the ones that went
+ # wrong (Config#debug?).
+ #: (Rack::_App app, path: String | Pathname, everything: bool) -> void
+ def initialize(app, path:, everything:)
+ @app = app
+ @logger = self.class.open_log(path)
+ @everything = everything
+ end
+
+ #: (Rack::env env) -> Rack::response
+ def call(env)
+ return @app.call(env) unless dav?(env)
+
+ id = SecureRandom.hex(6)
+ Sentry.set_tags(exchange: id)
+ # The hub's last event id moves only for an error event, so one
+ # that moved while the app ran is a report about this exchange.
+ reported = Sentry.last_event_id
+
+ status, headers, body = begin
+ @app.call(env)
+ rescue StandardError => e
+ # CaptureExceptions reports it once this re-raises, under the
+ # tag already set.
+ write(id, request(env) + prefixed("!!", "#{e.class}: #{e.message}"))
+ raise
+ end
+
+ unless @everything || failed?(status) || Sentry.last_event_id != reported
+ return [status, headers, body]
+ end
+
+ parts = drain(body)
+ write(id, request(env) + response(status, headers, parts.join))
+ [status, headers, parts]
+ end
+
+ private
+
+ #: (Rack::env env) -> bool
+ def dav?(env)
+ env["PATH_INFO"].to_s.match?(DAV_PATH) || !WEB_VERBS.include?(env["REQUEST_METHOD"])
+ end
+
+ # A 401 is the identity gate refusing a request that names nobody
+ # (Web#unauthorized): nothing went wrong, and unless everything is
+ # asked for, a body from outside the tailnet stays off disk.
+ #: (Integer status) -> bool
+ def failed?(status)
+ status >= 400 && status != 401
+ end
+
+ #: (Rack::_Body body) -> Array[String]
+ def drain(body)
+ parts = [] #: Array[String]
+ body.each do |part|
+ parts << part
+ end
+ # A body holding a resource closes it. No signature can say
+ # "close if you have one", so the cast carries what respond_to?
+ # has already established.
+ (_ = body).close if body.respond_to?(:close)
+ parts
+ end
+
+ #: (Rack::env env) -> Array[String]
+ def request(env)
+ lines = ["#{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}"
+ end
+ end
+ lines.flat_map { prefixed(">>", it) } + prefixed(">>", request_body(env))
+ end
+
+ #: (Integer status, Rack::headers headers, String body) -> Array[String]
+ def response(status, headers, body)
+ lines = ["#{status}#{reason(status)}"]
+ headers.each do |name, value|
+ Array(value).each { lines << "#{name}: #{it}" }
+ end
+ lines.flat_map { prefixed("<<", it) } + prefixed("<<", body)
+ end
+
+ #: (Rack::env env) -> String
+ def full_path(env)
+ path = env["PATH_INFO"].to_s
+ query = env["QUERY_STRING"].to_s
+ query.empty? ? path : "#{path}?#{query}"
+ end
+
+ #: (String name) -> String
+ def header_name(name)
+ name.split("_").map(&:capitalize).join("-")
+ end
+
+ # Read from the start whether or not the app read it first;
+ # Rack::RewindableInput is what makes the rewind possible.
+ #: (Rack::env env) -> String
+ def request_body(env)
+ input = env["rack.input"]
+ return "" if input.nil?
+
+ input.rewind
+ body = input.read.to_s
+ input.rewind
+ body
+ end
+
+ #: (Integer status) -> String
+ def reason(status)
+ phrase = Rack::Utils::HTTP_STATUS_CODES[status]
+ phrase ? " #{phrase}" : ""
+ end
+
+ # Binary throughout, so a request body that is not UTF-8 and a
+ # response body that is can share one message.
+ #: (String prefix, String text) -> Array[String]
+ def prefixed(prefix, text)
+ text.b.lines(chomp: true).map { "#{prefix} #{it}".b }
+ end
+
+ # One Logger call per exchange, so its lines land together however
+ # many requests are running; the progname is what Sentry's hook
+ # reads, and the formatter ignores it.
+ #: (String id, Array[String] lines) -> void
+ def write(id, lines)
+ @logger.add(Logger::INFO, lines.map { "#{id} ".b + it + "\n" }.join, PROGNAME)
+ end
+ end
+end
diff --git a/lib/pro_tacts/unhandled_requests.rb b/lib/pro_tacts/unhandled_requests.rb
deleted file mode 100644
index 91f0d84..0000000
--- a/lib/pro_tacts/unhandled_requests.rb
+++ /dev/null
@@ -1,143 +0,0 @@
-require "digest"
-require "fileutils"
-require "pathname"
-
-module ProTacts
- # Keeps a full copy of the requests the app could not answer, so a client
- # asking for something unimplemented leaves behind enough to implement it.
- #
- # Each capture is a directory holding "request" and "response", the same
- # layout and format as test/fixtures/macos-exchange, so promoting one to a
- # fixture is a copy. Strip the identifying headers when you do — captures
- # keep every header, fixtures do not.
- #
- # This is the local counterpart to the Sentry reporting in config.ru, which
- # no longer sends request bodies.
- class UnhandledRequests
- # @rbs @app: Rack::_App
- # @rbs @directory: Pathname
-
- # 404 is the missing-functionality signal: a client asked for something
- # this server does not route. 5xx is kept because Sentry now reports
- # those without a body, and a crash is hard to read without one. 403 is
- # the routed-but-unimplemented case, today an unsupported REPORT type.
- # An unauthenticated request is refused with a 401 (Web#unauthorized),
- # which is not kept, so no capture holds a body from outside the
- # tailnet.
- #: (Integer status) -> bool
- def self.capture?(status)
- status == 403 || status == 404 || status >= 500
- end
-
- #: (Rack::_App app, directory: Pathname | String) -> void
- def initialize(app, directory:)
- @app = app
- @directory = Pathname.new(directory)
- end
-
- #: (Rack::env env) -> Rack::response
- def call(env)
- status, headers, body = @app.call(env)
- return [status, headers, body] unless self.class.capture?(status)
-
- parts = [] #: Array[String]
- body.each do
- parts << it
- end
- # See DebugLogger#log_response: respond_to? cannot narrow an
- # interface, so the cast stands for the check beside it.
- (_ = body).close if body.respond_to?(:close)
-
- capture(env, status, headers, parts.join)
-
- [status, headers, parts]
- end
-
- private
-
- #: (Rack::env env, Integer status, Rack::headers headers, String body) -> void
- def capture(env, status, headers, body)
- target = @directory / name_for(env)
-
- # The directory name carries a digest of the request, so an already
- # captured request is one a client is repeating — recording it again
- # would just grow the directory without adding anything.
- return if target.exist?
-
- FileUtils.mkdir_p(target)
- (target / "request").write(render_request(env))
- (target / "response").write(render_response(status, headers, body))
- rescue SystemCallError => e
- # A failed capture must not turn a 404 into a 500.
- warn "pro-tacts: could not record unhandled request: #{e.message}"
- end
-
- #: (Rack::env env) -> String
- def name_for(env)
- slug = env["PATH_INFO"].to_s.gsub(%r{[^\w]+}, "-").delete_prefix("-").delete_suffix("-")
- slug = "root" if slug.empty?
- "#{env['REQUEST_METHOD'].to_s.downcase}-#{slug}-#{digest(env)}"
- end
-
- #: (Rack::env env) -> String
- def digest(env)
- # Slicing a hexdigest cannot come up short, which String#[] has
- # no way to promise.
- Digest::SHA256.hexdigest([env["REQUEST_METHOD"], env["PATH_INFO"], request_body(env)].join("\n"))[0, 8] #: String
- end
-
- #: (Rack::env env) -> String
- def render_request(env)
- lines = ["#{env['REQUEST_METHOD']} #{full_path(env)} #{env.fetch('SERVER_PROTOCOL', 'HTTP/1.1')}"]
- lines += each_header(env).map { |name, value| "#{name}: #{value}" }
- message(lines, request_body(env))
- end
-
- #: (Integer status, Rack::headers headers, String body) -> String
- def render_response(status, headers, body)
- message([status.to_s] + headers.map { |name, value| "#{name}: #{value}" }, body)
- end
-
- #: (Array[String] lines, String body) -> String
- def message(lines, body)
- head = lines.join("\n") + "\n\n"
- body = body.to_s.chomp
- body.empty? ? head : "#{head}#{body}\n"
- end
-
- #: (Rack::env env) -> String
- def full_path(env)
- path = env["PATH_INFO"].to_s
- query = env["QUERY_STRING"].to_s
- query.empty? ? path : "#{path}?#{query}"
- end
-
- #: (Rack::env env) -> Array[[String, untyped]]
- def each_header(env)
- env.filter_map { |key, value|
- case key
- when /\AHTTP_(.+)\z/ then [header_name(key.delete_prefix("HTTP_")), value]
- when "CONTENT_TYPE" then ["Content-Type", value]
- when "CONTENT_LENGTH" then ["Content-Length", value]
- end
- # The two-element arrays are pairs, which filter_map has no way
- # to say.
- }.sort #: Array[[String, untyped]]
- end
-
- #: (String name) -> String
- def header_name(name)
- name.split("_").map(&:capitalize).join("-")
- end
-
- #: (Rack::env env) -> String
- def request_body(env)
- input = env["rack.input"]
- return "" if input.nil?
-
- body = input.read.to_s
- input.rewind
- body
- end
- end
-end
diff --git a/lib/pro_tacts/web.rb b/lib/pro_tacts/web.rb
index 58febed..b49bfc1 100644
--- a/lib/pro_tacts/web.rb
+++ b/lib/pro_tacts/web.rb
@@ -7,11 +7,10 @@ require "sentry-ruby"
require "rack/rewindable_input"
require "roda"
-require "pro_tacts/debug_logger"
require "pro_tacts/contact"
+require "pro_tacts/exchange_log"
require "pro_tacts/store"
require "pro_tacts/tailscale_auth"
-require "pro_tacts/unhandled_requests"
require "roda/plugins/dav_verbs"
module ProTacts
@@ -47,25 +46,17 @@ module ProTacts
end
end
- # RewindableInput lets the capture middlewares below read the request
- # body and rewind it for the application.
+ # RewindableInput lets the exchange log below read the request body
+ # after the application has.
use Rack::RewindableInput::Middleware
use Sentry::Rack::CaptureExceptions
- # Outside the route's identity gate (#unauthorized), and safe there
- # because a refusal is a 401, which it does not keep
- # (UnhandledRequests.capture?): a refused request is not missing
- # functionality, and recording one would write an unauthenticated
- # body to disk.
- use ProTacts::UnhandledRequests, directory: ProTacts.config.unhandled_dir
-
- # Outside the identity gate too, so a refused request is dumped with
- # the rest. That is the point of a debug log, which is off by default
- # and kept on a local machine.
- if ProTacts.config.debug?
- logger = ProTacts::DebugLogger.open_log(ProTacts.config.debug_log_path)
- use ProTacts::DebugLogger, logger: logger
- end
+ # Inside CaptureExceptions, so the exchange tag lands on the scope it
+ # opens for the request. Outside the route's identity gate
+ # (#unauthorized), and safe there because a 401 is not a failure it
+ # keeps (ExchangeLog#failed?). The log opens when Roda builds the
+ # stack, not here, so requiring the app writes nothing.
+ use ProTacts::ExchangeLog, path: ProTacts.config.exchange_log_path, everything: ProTacts.config.debug?
plugin :all_verbs
plugin :dav_verbs
diff --git a/lib/pro_tacts/web/dav.rb b/lib/pro_tacts/web/dav.rb
index 7669912..685109a 100644
--- a/lib/pro_tacts/web/dav.rb
+++ b/lib/pro_tacts/web/dav.rb
@@ -239,9 +239,9 @@ module ProTacts
# section 3.6) — the report asked for has to be one the
# resource supports. Answering an unsupported report with an
# empty 207 reads to the client as a successful empty result,
- # and to us as nothing at all: 207 is not a status
- # UnhandledRequests captures, so the one signal that a client
- # wanted something unimplemented never fired.
+ # and to us as nothing at all: 207 is not a status the
+ # exchange log keeps, so the one signal that a client wanted
+ # something unimplemented never fired.
#
# 403 with the precondition named in a DAV:error body is the
# marshalling RFC 4918 section 16 defines, and 403 is its
diff --git a/sig/gems/sentry.rbs b/sig/gems/sentry.rbs
index 2dba630..a91f803 100644
--- a/sig/gems/sentry.rbs
+++ b/sig/gems/sentry.rbs
@@ -1,12 +1,17 @@
# Sentry is reached wherever a handler has something to report: the
# exception-capturing middleware web.rb mounts, the 404 and arrival
# messages web.rb and store.rb send, and the photo decode refusal
-# contact.rb captures.
+# contact.rb captures. ExchangeLog tags the request's scope and reads
+# whether anything was reported under it.
module Sentry
def self.capture_message: (String message, ?level: Symbol) -> untyped
def self.capture_exception: (Exception exception, ?level: Symbol) -> untyped
+ def self.set_tags: (**String tags) -> void
+
+ def self.last_event_id: () -> String?
+
module Rack
class CaptureExceptions
end
diff --git a/tasks/probe.rake b/tasks/probe.rake
index 7d7419d..6d641d0 100644
--- a/tasks/probe.rake
+++ b/tasks/probe.rake
@@ -35,17 +35,17 @@ namespace :probe do
response.code
end
- # The shared half of every probe's instructions: a successful PUT is
- # not an unhandled request, so the debug log is the only place it
- # lands. `edit` is what to change in the client: a probe that reads
+ # The shared half of every probe's instructions: a successful PUT did
+ # not go wrong, so the exchange log keeps it only with PRO_TACTS_DEBUG
+ # set. `edit` is what to change in the client: a probe that reads
# what the rewrite does to the rest of the card does not care, and
# one whose experiment is the edit itself says which to make.
def reading_the_result(id, name, edit: "any field, the edit itself does not matter")
<<~STEPS
1. The server needs PRO_TACTS_DEBUG=1 for the write to be logged —
- a successful PUT is not an unhandled request, so log/unhandled
- will not have it. Restart with `PRO_TACTS_DEBUG=1 rake dev` if
- it is not set.
+ without it the exchange log keeps only exchanges that went
+ wrong. Restart with `PRO_TACTS_DEBUG=1 rake dev` if it is not
+ set.
2. Resync the client and let a write through, editing "#{name}":
#{edit}.
3. The PUT body lands in log/dev.log after a `>>` line, under
diff --git a/test/pro_tacts/test_config.rb b/test/pro_tacts/test_config.rb
index 0bb0252..8449438 100644
--- a/test/pro_tacts/test_config.rb
+++ b/test/pro_tacts/test_config.rb
@@ -49,13 +49,13 @@ class ConfigTest < Minitest::Test
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
+ def test_exchange_log_path_defaults_to_a_file
+ assert_equal "log/exchange.log", ProTacts::Config.new({}).exchange_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
+ def test_exchange_log_path_is_overridable
+ assert_equal "/tmp/dav.log", ProTacts::Config.new("PRO_TACTS_EXCHANGE_LOG" => "/tmp/dav.log").exchange_log_path
+ assert_equal "stderr", ProTacts::Config.new("PRO_TACTS_EXCHANGE_LOG" => "stderr").exchange_log_path
end
# nil rather than a default, so the fallback stays Profile's alone.
diff --git a/test/pro_tacts/test_debug_logger.rb b/test/pro_tacts/test_debug_logger.rb
deleted file mode 100644
index fd76286..0000000
--- a/test/pro_tacts/test_debug_logger.rb
+++ /dev/null
@@ -1,99 +0,0 @@
-
-require "minitest/autorun"
-require "logger"
-require "stringio"
-
-require "pro_tacts/debug_logger"
-
-class DebugLoggerTest < Minitest::Test
- def setup
- @io = StringIO.new
- @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.
- 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 { "HTTP_#{it.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, {}, [""]] },
- logger: Logger.new(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 OpenLogTest < Minitest::Test
- def test_appends_timestamped_lines_to_a_file_it_creates
- require "pathname"
- require "tmpdir"
- Dir.mktmpdir do |dir|
- path = Pathname.new(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
diff --git a/test/pro_tacts/test_exchange_log.rb b/test/pro_tacts/test_exchange_log.rb
new file mode 100644
index 0000000..2a0c2c5
--- /dev/null
+++ b/test/pro_tacts/test_exchange_log.rb
@@ -0,0 +1,180 @@
+require_relative "../test_helper"
+require "rack/test"
+require "tmpdir"
+
+require "pro_tacts/exchange_log"
+
+class ExchangeLogTest < Minitest::Test
+ include Sentry::TestHelper
+ include SentryMessages
+ include Rack::Test::Methods
+
+ # Answers whatever the test asks for, so each case drives the logging
+ # decision directly. It reads the body first, as the DAV routes do.
+ class Stub
+ attr_accessor :status, :report, :error
+
+ def initialize
+ @status = 200
+ end
+
+ def call(env)
+ env["rack.input"]&.read
+ Sentry.capture_message("reported") if @report
+ raise @error if @error
+
+ [@status, { "content-type" => "text/plain" }, ["body from the app"]]
+ end
+ end
+
+ def setup
+ setup_sentry
+ @directory = Pathname.new(Dir.mktmpdir("exchange-log"))
+ @stub = Stub.new
+ @everything = false
+ end
+
+ def teardown
+ teardown_sentry_test
+ FileUtils.remove_entry(@directory)
+ end
+
+ def app
+ @app ||= ProTacts::ExchangeLog.new(@stub, path: @directory / "exchange.log", everything: @everything)
+ end
+
+ # Logger heads a new file with a comment line of its own.
+ def logged
+ path = @directory / "exchange.log"
+ path.exist? ? path.readlines.reject { it.start_with?("#") }.join : ""
+ end
+
+ def test_a_successful_exchange_is_not_logged
+ request "/dav/addressbook/", method: "PROPFIND"
+
+ assert_empty logged
+ end
+
+ def test_a_client_or_server_error_is_logged
+ [400, 403, 404, 410, 412, 500].each do |status|
+ @stub.status = status
+
+ request "/dav/addressbook/", method: "PROPFIND"
+
+ assert_includes logged, "<< #{status}", status
+ end
+ end
+
+ # An unauthenticated request is refused at the identity gate, and its
+ # body came from outside the tailnet.
+ def test_a_401_is_not_logged
+ @stub.status = 401
+
+ request "/dav/addressbook/", method: "PROPFIND"
+
+ assert_empty logged
+ end
+
+ # An arrival report on a PUT that succeeded: the alert carries an
+ # exchange id, so the exchange has to be there to read.
+ def test_an_exchange_that_reported_to_sentry_is_logged_though_it_succeeded
+ @stub.status = 201
+ @stub.report = true
+
+ put "/dav/addressbook/new.vcf", "BEGIN:VCARD"
+
+ assert_includes logged, "<< 201 Created"
+ end
+
+ def test_an_exchange_that_raised_is_logged_and_still_raises
+ @stub.error = RuntimeError.new("boom")
+
+ assert_raises(RuntimeError) do
+ request "/dav/addressbook/", method: "REPORT", input: "<nonsense/>"
+ end
+
+ assert_includes logged, ">> REPORT /dav/addressbook/"
+ assert_includes logged, "!! RuntimeError: boom"
+ end
+
+ def test_the_request_is_logged_whole
+ @stub.status = 404
+
+ request "/dav/addressbook/", method: "REPORT", input: "<sync-collection>\n <sync-token/>\n</sync-collection>",
+ "CONTENT_TYPE" => "text/xml", "HTTP_DEPTH" => "1"
+
+ assert_match(%r{>> REPORT /dav/addressbook/ HTTP/1\.\d$}, logged)
+ assert_includes logged, ">> Depth: 1"
+ assert_includes logged, ">> Content-Type: text/xml"
+ assert_includes logged, ">> <sync-collection>"
+ assert_includes logged, ">> <sync-token/>"
+ end
+
+ def test_the_response_is_logged_whole
+ @stub.status = 404
+
+ get "/dav/addressbook/nope.vcf"
+
+ assert_includes logged, "<< 404 Not Found"
+ assert_includes logged, "<< content-type: text/plain"
+ assert_includes logged, "<< body from the app"
+ end
+
+ def test_every_line_carries_the_id_sentry_was_given
+ @stub.status = 412
+ @stub.report = true
+
+ put "/dav/addressbook/new.vcf", "BEGIN:VCARD\r\nEND:VCARD\r\n"
+
+ id = sentry_events.last.tags.fetch(:exchange)
+
+ refute_empty logged
+ logged.each_line do |line|
+ assert_match(/\A\d{4}-\d\d-\d\dT\d\d:\d\d:\d\d\.\d{3} #{id} (>>|<<) /, line)
+ end
+ end
+
+ def test_the_client_still_gets_the_whole_response
+ @stub.status = 404
+
+ get "/dav/addressbook/nope.vcf"
+
+ assert_equal 404, last_response.status
+ assert_equal "body from the app", last_response.body
+ end
+
+ def test_admin_traffic_is_not_logged
+ @stub.status = 404
+
+ get "/contacts/nope"
+ post "/contacts"
+
+ assert_empty logged
+ end
+
+ def test_a_dav_verb_to_any_path_is_logged
+ @stub.status = 404
+
+ request "/nowhere", method: "PROPFIND"
+
+ assert_includes logged, ">> PROPFIND /nowhere"
+ end
+
+ def test_everything_logs_a_successful_exchange_too
+ @everything = true
+
+ request "/", method: "PROPFIND"
+
+ assert_includes logged, "<< 200 OK"
+ end
+
+ def test_a_body_that_is_not_utf_8_logs_beside_one_that_is
+ @stub.status = 412
+ app
+ @stub.define_singleton_method(:call) { |_env| [412, {}, ["Zoë"]] }
+
+ put "/dav/addressbook/new.vcf", "\xFF\xFE".b
+
+ assert_includes logged.b, "<< Zoë".b
+ end
+end
diff --git a/test/pro_tacts/test_unhandled_requests.rb b/test/pro_tacts/test_unhandled_requests.rb
deleted file mode 100644
index 687f4ef..0000000
--- a/test/pro_tacts/test_unhandled_requests.rb
+++ /dev/null
@@ -1,156 +0,0 @@
-require_relative "../test_helper"
-require "rack/test"
-require "tmpdir"
-
-require "pro_tacts/unhandled_requests"
-
-class UnhandledRequestsTest < Minitest::Test
- include Rack::Test::Methods
-
- # Returns whatever status the test asks for, so each case can drive the
- # capture decision directly.
- class Stub
- attr_accessor :status
-
- def initialize
- @status = 200
- end
-
- def call(_env)
- [@status, { "Content-Type" => "text/plain" }, ["body from the app"]]
- end
- end
-
- def setup
- @directory = Pathname.new(Dir.mktmpdir("unhandled"))
- @stub = Stub.new
- @app = ProTacts::UnhandledRequests.new(@stub, directory: @directory)
- end
-
- def teardown
- FileUtils.remove_entry(@directory)
- end
-
- attr_reader :app
-
- def captures
- @directory.children.select(&:directory?)
- end
-
- def test_successful_requests_are_not_captured
- @stub.status = 200
-
- get "/dav/addressbook/"
-
- assert_empty captures
- end
-
- def test_a_404_is_captured
- @stub.status = 404
-
- get "/dav/unknown/"
-
- assert_equal 1, captures.size
- end
-
- def test_a_server_error_is_captured
- @stub.status = 500
-
- get "/dav/addressbook/"
-
- assert_equal 1, captures.size
- end
-
- # An unsupported REPORT type: the app saying it routed the request and
- # will not serve it. An unauthenticated request is a 401 instead.
- def test_a_403_from_the_app_is_captured
- @stub.status = 403
-
- request "/dav/addressbook/", method: "REPORT", input: "<addressbook-query/>"
-
- assert_equal 1, captures.size
- end
-
- def test_capture_records_the_request_verbatim
- @stub.status = 404
-
- request "/dav/addressbook/", method: "REPORT", input: "<sync-collection/>",
- "CONTENT_TYPE" => "text/xml", "HTTP_DEPTH" => "1"
-
- recorded = (captures.first / "request").read
-
- assert_match(%r{\AREPORT /dav/addressbook/ HTTP/1\.\d\n}, recorded)
- assert_includes recorded, "Depth: 1"
- assert_includes recorded, "Content-Type: text/xml"
- assert_includes recorded, "<sync-collection/>"
- end
-
- def test_capture_records_the_response
- @stub.status = 404
-
- get "/dav/unknown/"
-
- recorded = (captures.first / "response").read
-
- assert_includes recorded, "404"
- assert_includes recorded, "Content-Type: text/plain"
- assert_includes recorded, "body from the app"
- end
-
- # The whole point of the format: a capture drops into the fixture suite.
- def test_capture_uses_the_fixture_layout
- @stub.status = 404
-
- get "/dav/unknown/"
-
- assert_equal %w[request response], captures.first.children.map { it.basename.to_s }.sort
- end
-
- def test_the_app_still_sees_its_own_body
- @stub.status = 404
-
- get "/dav/unknown/"
-
- assert_equal "body from the app", last_response.body
- end
-
- def test_a_repeated_request_is_captured_once
- @stub.status = 404
-
- 3.times do
- get "/dav/unknown/"
- end
-
- assert_equal 1, captures.size
- end
-
- def test_different_requests_are_captured_separately
- @stub.status = 404
-
- get "/dav/unknown/"
- get "/dav/other/"
-
- assert_equal 2, captures.size
- end
-
- # Same path, different body: the multiget case, where what was asked for
- # is the part that matters.
- def test_the_body_distinguishes_captures
- @stub.status = 404
-
- request "/dav/addressbook/", method: "REPORT", input: "<one/>"
- request "/dav/addressbook/", method: "REPORT", input: "<two/>"
-
- assert_equal 2, captures.size
- end
-
- def test_an_unwritable_directory_does_not_break_the_response
- app = ProTacts::UnhandledRequests.new(@stub, directory: @directory / "nested" / "deep")
- @stub.status = 404
-
- session = Rack::Test::Session.new(Rack::MockSession.new(app))
- session.get "/dav/unknown/"
-
- assert_equal 404, session.last_response.status
- end
-end
diff --git a/test/pro_tacts/test_web.rb b/test/pro_tacts/test_web.rb
index 7250a89..8cec221 100644
--- a/test/pro_tacts/test_web.rb
+++ b/test/pro_tacts/test_web.rb
@@ -132,35 +132,19 @@ class WebTest < Minitest::Test
assert_includes last_response.body, "AB12C345-6789-0DEF-1234-567890ABCDEF.vcf"
end
- # Guards the wiring rather than the middleware: mounted in the stack and
- # pointed at the configured directory.
- def test_an_unhandled_request_is_kept_on_disk
- directory = ProTacts.config.unhandled_dir
- FileUtils.rm_rf(directory)
-
+ # Guards the wiring rather than the middleware: mounted inside the
+ # scope Sentry opens for the request, and pointed at the configured
+ # log. The 404's own report is what carries the tag here.
+ def test_a_failed_exchange_is_logged_under_the_id_sentry_carries
get "/dav/addressbook/no-such-contact.vcf"
assert_equal 404, last_response.status
- captured = Pathname.new(directory).glob("*/request").map(&:read)
-
- assert_equal 1, captured.size
- assert_includes captured.first, "/dav/addressbook/no-such-contact.vcf"
- ensure
- FileUtils.rm_rf(directory)
- end
-
- def test_a_refused_request_is_not_kept_on_disk
- directory = ProTacts.config.unhandled_dir
- FileUtils.rm_rf(directory)
+ id = sentry_events.last.tags.fetch(:exchange)
+ logged = Pathname.new(ProTacts.config.exchange_log_path).read
- header "Tailscale-User-Login", ""
- get "/dav/addressbook/no-such-contact.vcf"
-
- assert_equal 401, last_response.status
- refute Pathname.new(directory).exist?, "a refused request should leave nothing behind"
- ensure
- FileUtils.rm_rf(directory)
+ assert_includes logged, "#{id} >> GET /dav/addressbook/no-such-contact.vcf"
+ assert_includes logged, "#{id} << 404 Not Found"
end
## Refusing a request that names nobody
@@ -1051,8 +1035,8 @@ class WebTest < Minitest::Test
# it fell through to the multiget branch, found no hrefs, and answered with
# an empty 207 that read as a successful empty address book.
def test_unsupported_report_is_refused_rather_than_answered_emptily
- directory = ProTacts.config.unhandled_dir
- FileUtils.rm_rf(directory)
+ log = Pathname.new(ProTacts.config.exchange_log_path)
+ offset = log.exist? ? log.size : 0
with_contacts({"aiden" => "Aiden"}) do
request "/dav/addressbook/", method: "REPORT", input: addressbook_query
@@ -1062,13 +1046,11 @@ class WebTest < Minitest::Test
refute_includes last_response.body, "multistatus"
# The refusal is what makes the ask visible; an empty 207 left nothing.
- captured = Pathname.new(directory).glob("*/request").map(&:read)
+ logged = log.read(nil, offset)
- assert_equal 1, captured.size
- assert_includes captured.first, "addressbook-query"
+ assert_includes logged, "addressbook-query"
+ assert_includes logged, "<< 403 Forbidden"
end
- ensure
- FileUtils.rm_rf(directory)
end
def test_etags_agree_across_listing_multiget_and_get
diff --git a/test/test_helper.rb b/test/test_helper.rb
index c99f9fa..e92c2cf 100644
--- a/test/test_helper.rb
+++ b/test/test_helper.rb
@@ -10,17 +10,11 @@
# which the TestTask command and several test files require first —
# would fire BEFORE the tests and delete the database mid-suite.
#
-# The removal is rm_rf rather than remove_entry because WebTest's
-# wired-middleware tests rm_rf the configured unhandled directory to
-# assert capture behavior from a clean slate; whether that directory
-# still exists at cleanup depends on test order, and rm_rf tolerates
-# it being gone.
-#
# The environment is set before the app is required rather than after it,
# so the requires cannot all sit at the top: the app reads configuration
-# as it loads, because the unhandled-request middleware is given its
-# directory at class-definition time. Set it afterwards and the captures
-# land in log/ instead of the tmpdir.
+# as it loads, because the exchange log is given its path at
+# class-definition time. Set it afterwards and the failed exchanges land
+# in log/ instead of the tmpdir.
require "fileutils"
require "minitest"
require "pathname"
@@ -28,19 +22,14 @@ require "tmpdir"
data_dir = Pathname.new(Dir.mktmpdir("pro-tacts-test"))
ENV["PRO_TACTS_DATA_DIR"] = data_dir.to_s
-Minitest.after_run { FileUtils.rm_rf(data_dir) }
-
-# Several tests provoke 404s. Keep the captures out of log/ and out of the
-# fixtures; UnhandledRequestsTest points the middleware at its own tmpdir.
-unhandled_dir = Pathname.new(Dir.mktmpdir("pro-tacts-unhandled"))
-ENV["PRO_TACTS_UNHANDLED_DIR"] = unhandled_dir.to_s
-Minitest.after_run { FileUtils.rm_rf(unhandled_dir) }
+Minitest.after_run { FileUtils.remove_entry(data_dir) }
-# Debug exchanges, when PRO_TACTS_DEBUG is exported for a test run, get
-# their own log, truncated per run: stderr would bury the test progress
-# under full bodies, and log/debug.log is for real client sessions only.
-ENV["PRO_TACTS_DEBUG_LOG"] ||= "log/test.log"
-File.truncate("log/test.log", 0) if File.exist?("log/test.log")
+# Several tests provoke failed exchanges. Their log goes with the run
+# unless PRO_TACTS_EXCHANGE_LOG is exported to keep it, and stays out of
+# log/exchange.log, which is for real client sessions only.
+exchange_dir = Pathname.new(Dir.mktmpdir("pro-tacts-exchanges"))
+ENV["PRO_TACTS_EXCHANGE_LOG"] ||= (exchange_dir / "exchange.log").to_s
+Minitest.after_run { FileUtils.remove_entry(exchange_dir) }
require_relative "fixture_data"
require "pro_tacts/web"