1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
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
# Where a DAV exchange's id rides in the env, which is how
# RefusalAlerts tells a DAV exchange from an admin one.
ENV_KEY = "pro_tacts.exchange" #: 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. A write or rotation that
# fails raises rather than taking Logger's default, a warning on
# stderr: the log is the record a refusal alert sends someone to,
# and one lost quietly would leave that alert pointing at nothing.
#: (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, reraise_write_errors: [StandardError]).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
# 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
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)
env[ENV_KEY] = id
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's error handler): 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)
head = ["#{env.fetch('REQUEST_METHOD')} #{full_path(env)} #{env.fetch('SERVER_PROTOCOL')}"]
env.each do |key, value|
case key
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
message(">>", head, request_body(env))
end
#: (Integer status, Rack::headers headers, String body) -> Array[String]
def response(status, headers, body)
head = ["#{status}#{reason(status)}"]
headers.each do |name, value|
Array(value).each { head << "#{name}: #{it}" }
end
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
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, 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 }
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