From 37499053673685dc75a90873381b6246b9fd3a84 Mon Sep 17 00:00:00 2001 From: Andy Aylward Date: Mon, 31 Aug 2026 21:55:25 -0400 Subject: [PATCH 01/10] aura: one JSON access-log line per request, in the metrics vocabulary MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit http_method and route are the bounded labels the instruments carry, so a dashboard-to-logs pivot is a copy-paste; the raw target rides in its own field, JSON-escaped — it is attacker-controlled, and an unescaped quote or control byte would let a crafted URI forge its own log entry. duration moves to microseconds to match the histogram. One file, four services: portrait, golf_hub, one_d4_v2, iili (#1459). --- domains/platform/libs/aura/middleware.cc | 92 ++++++++++++++++--- domains/platform/libs/aura/middleware_test.cc | 88 +++++++++++++++++- 2 files changed, 161 insertions(+), 19 deletions(-) diff --git a/domains/platform/libs/aura/middleware.cc b/domains/platform/libs/aura/middleware.cc index 3f52048f4..f099b04ca 100644 --- a/domains/platform/libs/aura/middleware.cc +++ b/domains/platform/libs/aura/middleware.cc @@ -97,15 +97,66 @@ std::string KindName(smithy::http::BeastServerTransport::ConnectionEvent::Kind k return "unknown(" + std::to_string(static_cast(kind)) + ")"; } -// One access-log line per request. Kept separate from Observe because the -// log line needs X-Forwarded-For and the response body size, which -// RequestObservation doesn't carry; it measures its own duration for the -// log line only. The trace_id= field is the W3C trace id parsed from the -// request's traceparent — the transport guard mints or joins it at ingress -// (smithy-cpp ADR-0011), so on transport-served requests it always parses. -// Empty only for hand-driven handler chains in tests. +// JSON string escaping for the access-log line. Stricter than the +// Prometheus label escaping in futility: every control byte below 0x20 +// becomes \uXXXX, because the target reaches the line verbatim and is +// attacker-controlled — a raw control byte or an unescaped quote terminates +// the record early and lets the rest of the URI masquerade as its own log +// entry (smithy-cpp #203). +void AppendJsonEscaped(std::string& out, std::string_view value) { + static constexpr char kHex[] = "0123456789abcdef"; + for (const char c : value) { + switch (c) { + case '"': + out += "\\\""; + break; + case '\\': + out += "\\\\"; + break; + case '\n': + out += "\\n"; + break; + case '\r': + out += "\\r"; + break; + case '\t': + out += "\\t"; + break; + default: + if (static_cast(c) < 0x20) { + out += "\\u00"; + out += kHex[(c >> 4) & 0xF]; + out += kHex[c & 0xF]; + } else { + out += c; + } + } + } +} + +void AppendJsonField(std::string& out, std::string_view name, std::string_view value) { + out += ",\""; + out += name; + out += "\":\""; + AppendJsonEscaped(out, value); + out += '"'; +} + +// One access-log line per request: a single JSON object in the metrics +// vocabulary (#1459) — http_method and route are the bounded labels the +// instruments carry, so a dashboard-to-logs pivot is a copy-paste; the raw +// target rides in its own field where an unbounded value is data, not a +// label. duration_us matches the histogram's unit. +// +// Kept separate from Observe because the line needs X-Forwarded-For and the +// response body size, which RequestObservation doesn't carry; it measures +// its own duration for the line only. The trace_id field is the W3C trace +// id parsed from the request's traceparent — the transport guard mints or +// joins it at ingress (smithy-cpp ADR-0011), so on transport-served +// requests it always parses. Empty only for hand-driven handler chains in +// tests. // -// X-Forwarded-For= is the raw header, which since ADR-0012 is NOT the +// x_forwarded_for is the raw header, which since ADR-0012 is NOT the // identity the rate limiter keys on — a 429's actual bucket (the derived // client address) is not on this line. smithy::server::Middleware AccessLog() { @@ -116,17 +167,30 @@ smithy::server::Middleware AccessLog() { smithy::http::HttpResponse response = next(request); - const auto duration_ms = std::chrono::duration_cast( + const auto duration_us = std::chrono::duration_cast( std::chrono::steady_clock::now() - start); const std::string trace_id = smithy::http::ParseTraceparent(request.headers.Get("traceparent").value_or("")) .value_or(smithy::http::TraceContext{}) .trace_id; - LOG(INFO) << "[" << request.method << " " << request.target - << "]: X-Forwarded-For=" << request.headers.Get("X-Forwarded-For").value_or("") - << " trace_id=" << trace_id << " status=" << response.status - << " res.body.bytes=" << response.body.size() - << " duration_ms=" << duration_ms.count(); + // The log's identity field, same source as the metrics resource. + static const std::string service_name = []() { + const char* name = std::getenv("OTEL_SERVICE_NAME"); + return std::string(name == nullptr ? "" : name); + }(); + + std::string line = R"({"log":"access")"; + AppendJsonField(line, "service_name", service_name); + AppendJsonField(line, "http_method", MethodLabelOf(request.method)); + AppendJsonField(line, "route", RouteLabelOf(response.operation, request.target)); + AppendJsonField(line, "target", request.target); + line += ",\"status\":" + std::to_string(response.status); + line += ",\"duration_us\":" + std::to_string(duration_us.count()); + line += ",\"response_bytes\":" + std::to_string(response.body.size()); + AppendJsonField(line, "trace_id", trace_id); + AppendJsonField(line, "x_forwarded_for", request.headers.Get("X-Forwarded-For").value_or("")); + line += '}'; + LOG(INFO) << line; return response; }; }; diff --git a/domains/platform/libs/aura/middleware_test.cc b/domains/platform/libs/aura/middleware_test.cc index f3558baf7..a914234dc 100644 --- a/domains/platform/libs/aura/middleware_test.cc +++ b/domains/platform/libs/aura/middleware_test.cc @@ -159,12 +159,18 @@ class AuraMiddlewareTest : public ::testing::Test { // Sends one request through the chain and returns the access-log line it // produced. std::string AccessLogLineFor(const std::vector>& headers) { + return AccessLogLineForRequest("POST", "/echo", "hello", headers, 200); + } + + std::string AccessLogLineForRequest( + const std::string& method, const std::string& target, const std::string& body, + const std::vector>& headers, int expected_status) { std::string line; absl::ScopedMockLog log(absl::MockLogDefault::kIgnoreUnexpected); - EXPECT_CALL(log, Log(absl::LogSeverity::kInfo, testing::_, testing::HasSubstr("trace_id="))) + EXPECT_CALL(log, Log(absl::LogSeverity::kInfo, testing::_, testing::HasSubstr("\"trace_id\":"))) .WillOnce(testing::SaveArg<2>(&line)); log.StartCapturingLogs(); - EXPECT_EQ(Send("POST", "/echo", "hello", "", headers).status, 200); + EXPECT_EQ(Send(method, target, body, "", headers).status, expected_status); log.StopCapturingLogs(); return line; } @@ -349,16 +355,16 @@ TEST(AuraChainWithoutLimiterTest, NoGuardWhenAllowRequestUnset) { EXPECT_EQ(sink->completes().size(), 20u); } -// The access-log line's trace_id= field carries the W3C trace id parsed +// The access-log line's "trace_id" field carries the W3C trace id parsed // from the traceparent the transport guard mints or joins at ingress. The // mint/join/replace mechanics themselves are upstream-tested (smithy-cpp // ADR-0011); these tests pin what aura logs. std::string TraceIdIn(const std::string& log_line) { - constexpr char kKey[] = "trace_id="; + constexpr char kKey[] = "\"trace_id\":\""; const auto pos = log_line.find(kKey); if (pos == std::string::npos) return ""; const auto start = pos + sizeof(kKey) - 1; - return log_line.substr(start, log_line.find(' ', start) - start); + return log_line.substr(start, log_line.find('"', start) - start); } bool IsLowercaseHex32(const std::string& value) { @@ -369,6 +375,78 @@ bool IsLowercaseHex32(const std::string& value) { return true; } +// One JSON object per request, speaking the metrics vocabulary +// (http_method, route, status — #1459/#1365): a reader who sees a spike on +// a route="Echo" panel pastes the same word into a log query. The route is +// the bounded label, never the raw path; the raw path rides separately in +// "target". +TEST_F(AuraMiddlewareTest, AccessLogIsOneJsonObjectInTheMetricsVocabulary) { + const std::string line = AccessLogLineFor({{"X-Forwarded-For", "203.0.113.9"}}); + + EXPECT_TRUE(line.front() == '{' && line.back() == '}') << line; + for (const char* field : { + R"("log":"access")", + R"("service_name":")", + R"("http_method":"POST")", + R"("route":"Echo")", + R"("target":"/echo")", + R"("status":200)", + R"("duration_us":)", + R"("response_bytes":4)", + R"("trace_id":")", + R"("x_forwarded_for":"203.0.113.9")", + }) { + EXPECT_THAT(line, testing::HasSubstr(field)); + } +} + +// Sends one request through a fresh chain over the given handler and +// returns the access-log line. The fixture's chain echoes 200 with an +// operation for every path, so the unrouted shapes need their own handler. +std::string AccessLogLineThrough(smithy::http::RequestHandler handler, const std::string& target, + int expected_status) { + auto chain = aura::ProductionChain( + aura::ChainOptions{.metrics = std::make_shared()}, std::move(handler)); + auto loopback = std::make_shared(); + EXPECT_TRUE(loopback->Start(chain).ok()); + + smithy::http::HttpRequest request; + request.method = "POST"; + request.target = target; + request.peer_address = "192.0.2.200"; + + std::string line; + absl::ScopedMockLog log(absl::MockLogDefault::kIgnoreUnexpected); + EXPECT_CALL(log, Log(absl::LogSeverity::kInfo, testing::_, testing::HasSubstr("\"trace_id\":"))) + .WillOnce(testing::SaveArg<2>(&line)); + log.StartCapturingLogs(); + const auto response = loopback->Send(request); + EXPECT_TRUE(response.ok()); + if (response.ok()) EXPECT_EQ(response->status, expected_status); + log.StopCapturingLogs(); + return line; +} + +// The route field is the same bounded vocabulary the metrics speak: an +// unrouted request logs the sentinel, not its path — the path is in +// "target", where an unbounded value is a field, not a label. +TEST(AccessLogJsonTest, RouteFallsBackToTheSharedSentinel) { + const std::string line = AccessLogLineThrough(UnroutedHandler(404), "/no/such/path", 404); + EXPECT_THAT(line, testing::HasSubstr(R"("route":"unmatched")")); + EXPECT_THAT(line, testing::HasSubstr(R"("target":"/no/such/path")")); +} + +// The target is attacker-controlled and reaches the line verbatim, so JSON +// escaping is security-adjacent (smithy-cpp #203): an unescaped quote or a +// raw control byte terminates the record early and lets the rest of the URI +// masquerade as its own log entry. +TEST(AccessLogJsonTest, QuotesAndControlBytesInTheTargetAreEscaped) { + const std::string line = AccessLogLineThrough(UnroutedHandler(404), "/e\"cho\x01?a=\\b", 404); + + EXPECT_THAT(line, testing::HasSubstr(R"("target":"/e\"cho\u0001?a=\\b")")); + EXPECT_THAT(line, testing::Not(testing::HasSubstr("\x01"))); +} + TEST_F(AuraMiddlewareTest, AccessLogJoinsInboundTraceIdentity) { constexpr char kInbound[] = "00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01"; EXPECT_EQ(TraceIdIn(AccessLogLineFor({{"traceparent", kInbound}})), From d03255eb41462dfedb69cfc3d7c94cbf5fce5935 Mon Sep 17 00:00:00 2001 From: Andy Aylward Date: Mon, 31 Aug 2026 22:01:56 -0400 Subject: [PATCH 02/10] server_pal: emit a JSON request log; binaries switch to init_logging MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The rust services logged no requests at all — TraceLayer's events sit below the INFO default. One tracing event per request now carries the metrics vocabulary (http_method, route from the matched template or the shared sentinel, service_name) plus target, status, duration_us, trace_id and the raw x-forwarded-for, layered beside the metrics middleware so 429s appear too. init_logging installs the flattened-JSON subscriber in posterize, mithril and microgpt_serve, replacing bare fmt::init (#1459). --- Cargo.lock | 19 ++- domains/ai/apis/microgpt_serve/Cargo.toml | 1 - domains/ai/apis/microgpt_serve/src/main.rs | 2 +- domains/games/apis/mithril/Cargo.toml | 1 - domains/games/apis/mithril/src/main.rs | 3 +- domains/graphics/apis/posterize/Cargo.toml | 1 - domains/graphics/apis/posterize/src/main.rs | 2 +- domains/platform/libs/server_pal/Cargo.toml | 5 + domains/platform/libs/server_pal/src/lib.rs | 173 +++++++++++++++++++- 9 files changed, 196 insertions(+), 11 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 9d84ebe4c..97113dabc 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2149,7 +2149,6 @@ dependencies = [ "tokio", "tower", "tracing", - "tracing-subscriber", ] [[package]] @@ -2204,7 +2203,6 @@ dependencies = [ "server_pal", "tokio", "tracing", - "tracing-subscriber", "wordchains", ] @@ -2683,7 +2681,6 @@ dependencies = [ "tokio", "tower", "tracing", - "tracing-subscriber", ] [[package]] @@ -3450,10 +3447,13 @@ dependencies = [ "opentelemetry_sdk", "reqwest", "rustls", + "serde_json", "tokio", "tower", "tower-http 0.7.0", "tower_governor", + "tracing", + "tracing-subscriber", "webpki-root-certs", ] @@ -4075,6 +4075,16 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-serde" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "704b1aeb7be0d0a84fc9828cae51dab5970fee5088f83d1dd7ee6f6246fc6ff1" +dependencies = [ + "serde", + "tracing-core", +] + [[package]] name = "tracing-subscriber" version = "0.3.23" @@ -4085,12 +4095,15 @@ dependencies = [ "nu-ansi-term", "once_cell", "regex-automata", + "serde", + "serde_json", "sharded-slab", "smallvec", "thread_local", "tracing", "tracing-core", "tracing-log", + "tracing-serde", ] [[package]] diff --git a/domains/ai/apis/microgpt_serve/Cargo.toml b/domains/ai/apis/microgpt_serve/Cargo.toml index d32cf9ffb..4841e77cd 100644 --- a/domains/ai/apis/microgpt_serve/Cargo.toml +++ b/domains/ai/apis/microgpt_serve/Cargo.toml @@ -19,7 +19,6 @@ serde_json = { workspace = true } server_pal = { workspace = true } tokio = { workspace = true, features = ["macros", "rt-multi-thread"] } tracing = { workspace = true } -tracing-subscriber = { workspace = true } [dev-dependencies] tower = { workspace = true } diff --git a/domains/ai/apis/microgpt_serve/src/main.rs b/domains/ai/apis/microgpt_serve/src/main.rs index 1a9001c39..8de4a30e9 100644 --- a/domains/ai/apis/microgpt_serve/src/main.rs +++ b/domains/ai/apis/microgpt_serve/src/main.rs @@ -25,7 +25,7 @@ pub struct AppState { #[tokio::main] async fn main() { - tracing_subscriber::fmt::init(); + server_pal::init_logging(); // Must be initialised before AppMetrics::new() so the global provider is // in place when OTel instruments are created. diff --git a/domains/games/apis/mithril/Cargo.toml b/domains/games/apis/mithril/Cargo.toml index 69e8dbf56..d0d6e70be 100644 --- a/domains/games/apis/mithril/Cargo.toml +++ b/domains/games/apis/mithril/Cargo.toml @@ -11,5 +11,4 @@ serde = { workspace = true, features = ["derive"] } server_pal = {workspace = true } tokio = { workspace = true, features = ["macros", "rt-multi-thread"] } tracing = { workspace = true } -tracing-subscriber = { workspace = true } wordchains = { workspace = true } diff --git a/domains/games/apis/mithril/src/main.rs b/domains/games/apis/mithril/src/main.rs index a3a3b505c..0bdeab5ab 100644 --- a/domains/games/apis/mithril/src/main.rs +++ b/domains/games/apis/mithril/src/main.rs @@ -4,7 +4,6 @@ use serde::{Deserialize, Deserializer, Serialize}; use server_pal::{listen_addr_pal, router_builder, serve}; use std::sync::Arc; use tracing::{Level, event}; -use tracing_subscriber; use wordchains::{Graph, bfs_for_target, initialize_graph}; fn validate_word<'de, D>(deserializer: D) -> Result @@ -60,7 +59,7 @@ async fn wordchain_post( #[tokio::main] async fn main() { - tracing_subscriber::fmt::init(); + server_pal::init_logging(); // Keeps the exporter alive for the process lifetime; without this the // http_server_* instruments record into the no-op global meter. let _otel_provider = server_pal::init_otel(); diff --git a/domains/graphics/apis/posterize/Cargo.toml b/domains/graphics/apis/posterize/Cargo.toml index 9a5c5e10a..0164fde18 100644 --- a/domains/graphics/apis/posterize/Cargo.toml +++ b/domains/graphics/apis/posterize/Cargo.toml @@ -13,7 +13,6 @@ serde = { workspace = true, features = ["derive"] } server_pal = {workspace = true } tokio = { workspace = true, features = ["macros", "rt-multi-thread"] } tracing = { workspace = true } -tracing-subscriber = { workspace = true } imagine = { workspace = true } [dev-dependencies] diff --git a/domains/graphics/apis/posterize/src/main.rs b/domains/graphics/apis/posterize/src/main.rs index 9b65b0f12..3aea91c58 100644 --- a/domains/graphics/apis/posterize/src/main.rs +++ b/domains/graphics/apis/posterize/src/main.rs @@ -9,7 +9,7 @@ use tracing::{Level, event}; #[tokio::main] async fn main() { - tracing_subscriber::fmt::init(); + server_pal::init_logging(); // Keeps the exporter alive for the process lifetime; without this the // http_server_* instruments record into the no-op global meter. let _otel_provider = server_pal::init_otel(); diff --git a/domains/platform/libs/server_pal/Cargo.toml b/domains/platform/libs/server_pal/Cargo.toml index c64990899..533340d7d 100644 --- a/domains/platform/libs/server_pal/Cargo.toml +++ b/domains/platform/libs/server_pal/Cargo.toml @@ -16,8 +16,13 @@ opentelemetry-otlp = { workspace = true } tokio = { workspace = true, features = ["net"] } tower_governor = { workspace = true } tower-http = { workspace = true, features = ["full"] } +tracing = { workspace = true } +# json: the request log is one JSON object per line (#1459); the feature +# pulls serde into the subscriber and nothing else. +tracing-subscriber = { workspace = true, features = ["json"] } [dev-dependencies] +serde_json = { workspace = true } tokio = { workspace = true, features = ["macros", "rt-multi-thread", "time"] } tower = "0.5" # The in-memory exporter behind the label-set and unit tests. Costs one new diff --git a/domains/platform/libs/server_pal/src/lib.rs b/domains/platform/libs/server_pal/src/lib.rs index eae4cbe0e..7a22c661b 100644 --- a/domains/platform/libs/server_pal/src/lib.rs +++ b/domains/platform/libs/server_pal/src/lib.rs @@ -101,6 +101,92 @@ fn latency_bucket_view(instrument: &Instrument) -> Option { ) } +/// Installs the process-wide log subscriber: one flattened JSON object per +/// event on stdout (#1459). Replaces the bare `tracing_subscriber::fmt::init()` +/// the binaries used to call, under which the request log below would render +/// as human-format text — machine-readable everywhere or nowhere. +pub fn init_logging() { + tracing_subscriber::fmt() + .json() + .flatten_event(true) + .with_current_span(false) + .with_span_list(false) + // The formatter's own "target" (the Rust module path) would collide + // with the access log's target field and win; the module path earns + // no place on a request line. + .with_target(false) + .init(); +} + +/// The log's identity field, same source as the metrics resource. +fn service_name_from_env() -> &'static str { + static NAME: OnceLock = OnceLock::new(); + NAME.get_or_init(|| env::var("OTEL_SERVICE_NAME").unwrap_or_default()) +} + +/// The W3C trace id off a traceparent header, or "" when absent/malformed. +/// The full mint/join semantics live on the C++ rail (smithy-cpp ADR-0011); +/// here the header is Caddy's or the caller's to send, so parse-don't-trust +/// is the whole contract. +fn trace_id_of(traceparent: Option<&str>) -> &str { + let Some(header) = traceparent else { return "" }; + let mut parts = header.split('-'); + let (Some(_version), Some(trace_id)) = (parts.next(), parts.next()) else { + return ""; + }; + if trace_id.len() == 32 && trace_id.bytes().all(|b| b.is_ascii_hexdigit()) { + trace_id + } else { + "" + } +} + +/// One access-log line per request: a single JSON event in the metrics +/// vocabulary (#1459) — http_method and route are the bounded labels the +/// instruments carry, so a dashboard-to-logs pivot is a copy-paste; the raw +/// path-and-query rides in "target" where an unbounded value is data, not a +/// label. duration_us matches the histogram's unit. x_forwarded_for is the +/// raw header, which since ADR-0012 is NOT the identity the rate limiter +/// keys on. +async fn access_log_middleware(req: Request, next: Next) -> Response { + let start = std::time::Instant::now(); + let http_method = bounded_method_label(req.method()); + let route = req + .extensions() + .get::() + .map(|p| p.as_str().to_string()) + .unwrap_or_else(|| UNMATCHED_ROUTE.to_string()); + let target = req.uri().to_string(); + let x_forwarded_for = req + .headers() + .get("x-forwarded-for") + .and_then(|v| v.to_str().ok()) + .unwrap_or("") + .to_string(); + let traceparent = req + .headers() + .get("traceparent") + .and_then(|v| v.to_str().ok()) + .unwrap_or("") + .to_string(); + + let resp = next.run(req).await; + + tracing::info!( + log = "access", + service_name = service_name_from_env(), + http_method, + route, + target, + status = resp.status().as_u16(), + duration_us = start.elapsed().as_micros() as u64, + trace_id = trace_id_of(Some(traceparent.as_str())), + x_forwarded_for, + "request" + ); + resp +} + /// Initialise the global OTel meter provider when /// OTEL_EXPORTER_OTLP_ENDPOINT is set; a no-op None otherwise. Callers /// keep the returned provider alive for the process lifetime — dropping @@ -508,13 +594,16 @@ impl RouterBuilder { let health = common_layers(Router::new().route("/health", get(|| async { "Ok" }))); // HTTP metrics middleware sits outside rate-limiting so rate-limited - // requests (429) are also counted as failures. + // requests (429) are also counted as failures; the access log sits + // beside it for the same reason — a 429 is a request the log must + // show, and Router::layer runs after routing so both see MatchedPath. health .merge(limited) .layer(axum::middleware::from_fn_with_state( cell, http_metrics_middleware, )) + .layer(axum::middleware::from_fn(access_log_middleware)) } } @@ -719,6 +808,88 @@ mod tests { let resp = app.oneshot(make_request("/wp-login.php")).await.unwrap(); assert_eq!(resp.status(), StatusCode::TOO_MANY_REQUESTS); } + + /// Collects the JSON subscriber's output so a test can read the line + /// the access log wrote. + #[derive(Clone)] + struct SharedWriter(Arc>>); + impl std::io::Write for SharedWriter { + fn write(&mut self, buf: &[u8]) -> std::io::Result { + self.0.lock().unwrap().extend_from_slice(buf); + Ok(buf.len()) + } + fn flush(&mut self) -> std::io::Result<()> { + Ok(()) + } + } + + async fn access_line_for(path: &str, expected_status: StatusCode) -> serde_json::Value { + let buf: Arc>> = Arc::default(); + let writer_buf = buf.clone(); + let subscriber = tracing_subscriber::fmt() + .json() + .flatten_event(true) + .with_target(false) + .with_writer(move || SharedWriter(writer_buf.clone())) + .finish(); + let _guard = tracing::subscriber::set_default(subscriber); + + let app = router_builder::() + .route("/widgets/{id}", get(|| async { "w" })) + .rate_limit(None) + .build() + .with_state(NoState); + let mut req = make_request(path); + req.headers_mut() + .insert("x-forwarded-for", "203.0.113.9".parse().unwrap()); + req.headers_mut().insert( + "traceparent", + "00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01" + .parse() + .unwrap(), + ); + let resp = app.oneshot(req).await.unwrap(); + assert_eq!(resp.status(), expected_status); + + let output = String::from_utf8(buf.lock().unwrap().clone()).unwrap(); + let line = output + .lines() + .find(|l| l.contains("\"log\":\"access\"")) + .unwrap_or_else(|| panic!("no access line in: {output}")) + .to_string(); + serde_json::from_str(&line).expect("the access line must be one parseable JSON object") + } + + /// One JSON object per request, speaking the metrics vocabulary + /// (http_method, route, service_name — #1459): a spike on a + /// route="/widgets/{id}" panel pastes into a log query unchanged. The + /// route is the matched template, never the raw path; the raw path rides + /// in "target". + #[tokio::test] + async fn access_log_is_one_json_object_in_the_metrics_vocabulary() { + let v = access_line_for("/widgets/7?q=1", StatusCode::OK).await; + + assert_eq!(v["http_method"], "GET"); + assert_eq!(v["route"], "/widgets/{id}"); + assert_eq!(v["target"], "/widgets/7?q=1"); + assert_eq!(v["status"], 200); + assert!(v["duration_us"].is_number(), "duration_us: {v}"); + assert_eq!(v["trace_id"], "4bf92f3577b34da6a3ce929d0e0e4736"); + assert_eq!(v["x_forwarded_for"], "203.0.113.9"); + assert!(v["service_name"].is_string(), "service_name: {v}"); + } + + /// Unrouted requests log the shared sentinel, the same spelling the + /// instruments use and otel_contract pins across rails — the raw path + /// stays in "target" where an unbounded value is data, not a label. + #[tokio::test] + async fn access_log_route_falls_back_to_the_shared_sentinel() { + let v = access_line_for("/no/such/path", StatusCode::NOT_FOUND).await; + + assert_eq!(v["route"], UNMATCHED_ROUTE); + assert_eq!(v["status"], 404); + assert_eq!(v["target"], "/no/such/path"); + } } #[cfg(test)] From 1d01a1954cd52a9677b63c6096ca8d66e44e28f1 Mon Sep 17 00:00:00 2001 From: Andy Aylward Date: Mon, 31 Aug 2026 22:04:31 -0400 Subject: [PATCH 03/10] logback: one JSON object per line from the shared config MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit logback's own JsonEncoder — no new dependency — so one_d4 and mcpserver stdout parses offline like every other rail (#1459). The epoch-millis timestamp is absolute, closing the date-less-pattern half of #1456 for good. LogbackConfigTest boots the real config and pins the shape. --- domains/platform/libs/logging/BUILD.bazel | 22 +++++- .../platform/logging/LogbackConfigTest.java | 69 +++++++++++++++++++ domains/platform/resources/logback.xml | 11 ++- 3 files changed, 95 insertions(+), 7 deletions(-) create mode 100644 domains/platform/libs/logging/src/test/java/com/muchq/platform/logging/LogbackConfigTest.java diff --git a/domains/platform/libs/logging/BUILD.bazel b/domains/platform/libs/logging/BUILD.bazel index a64cb26c8..d61b221cb 100644 --- a/domains/platform/libs/logging/BUILD.bazel +++ b/domains/platform/libs/logging/BUILD.bazel @@ -1,4 +1,4 @@ -load("//bazel/rules:java.bzl", "artifact", "java_library") +load("//bazel/rules:java.bzl", "artifact", "java_library", "java_test_suite") java_library( name = "logging", @@ -12,3 +12,23 @@ java_library( artifact("org.slf4j:slf4j-api"), ], ) + +java_test_suite( + name = "logging_tests", + size = "small", + srcs = [ + "src/test/java/com/muchq/platform/logging/LogbackConfigTest.java", + ], + runtime_deps = [ + # The config under test rides this library's classpath, and so does + # the SentryAppender class it names. + ":logging", + ], + deps = [ + artifact("ch.qos.logback:logback-classic"), + artifact("ch.qos.logback:logback-core"), + artifact("com.fasterxml.jackson.core:jackson-databind"), + artifact("org.junit.jupiter:junit-jupiter-api"), + artifact("org.assertj:assertj-core"), + ], +) diff --git a/domains/platform/libs/logging/src/test/java/com/muchq/platform/logging/LogbackConfigTest.java b/domains/platform/libs/logging/src/test/java/com/muchq/platform/logging/LogbackConfigTest.java new file mode 100644 index 000000000..da837d1e4 --- /dev/null +++ b/domains/platform/libs/logging/src/test/java/com/muchq/platform/logging/LogbackConfigTest.java @@ -0,0 +1,69 @@ +package com.muchq.platform.logging; + +import static java.nio.charset.StandardCharsets.UTF_8; +import static org.assertj.core.api.Assertions.assertThat; + +import ch.qos.logback.classic.Logger; +import ch.qos.logback.classic.LoggerContext; +import ch.qos.logback.classic.joran.JoranConfigurator; +import com.fasterxml.jackson.databind.JsonNode; +import com.fasterxml.jackson.databind.ObjectMapper; +import java.io.ByteArrayOutputStream; +import java.io.PrintStream; +import java.time.Instant; +import org.junit.jupiter.api.Test; + +/** + * Boots the shared logback.xml — the one config every Java service ships — and reads what its + * console appender actually writes. The stats pipeline parses these lines offline (#1459), so the + * contract is structural: one JSON object per line, carrying an absolute timestamp. Before #1456 + * the pattern rendered bare {@code HH:mm:ss} wall-clock time, which two days of shipped logs cannot + * even order. + */ +public class LogbackConfigTest { + + @Test + public void theSharedConfigEmitsOneParseableJsonObjectPerLineWithAnAbsoluteTimestamp() + throws Exception { + ByteArrayOutputStream captured = new ByteArrayOutputStream(); + PrintStream original = System.out; + LoggerContext context = new LoggerContext(); + try { + // Before configuration: ConsoleAppender binds System.out at start. + System.setOut(new PrintStream(captured, true, UTF_8)); + // A hand-built context has no MDC adapter (slf4j installs one on the + // default context); appending NPEs without it. + context.setMDCAdapter(new ch.qos.logback.classic.util.LogbackMDCAdapter()); + JoranConfigurator configurator = new JoranConfigurator(); + configurator.setContext(context); + configurator.doConfigure(getClass().getClassLoader().getResource("logback.xml")); + Logger logger = context.getLogger("com.muchq.some.Service"); + logger.info("hello structured world"); + } finally { + System.setOut(original); + context.stop(); + } + + String line = null; + for (String candidate : captured.toString(UTF_8).split("\n")) { + if (candidate.contains("hello structured world")) { + line = candidate; + } + } + if (line == null) { + ch.qos.logback.core.util.StatusPrinter.print(context); + } + assertThat(line).as("the logged line reached the console appender").isNotNull(); + + JsonNode node = new ObjectMapper().readTree(line); + assertThat(node.get("message").asText()).isEqualTo("hello structured world"); + assertThat(node.get("level").asText()).isEqualTo("INFO"); + assertThat(node.get("loggerName").asText()).isEqualTo("com.muchq.some.Service"); + // Epoch millis: absolute, order-preserving across days — the property + // the old date-less pattern lacked. + assertThat(node.get("timestamp").asLong()) + .isBetween( + Instant.parse("2026-01-01T00:00:00Z").toEpochMilli(), + Instant.parse("2100-01-01T00:00:00Z").toEpochMilli()); + } +} diff --git a/domains/platform/resources/logback.xml b/domains/platform/resources/logback.xml index cbe6f8bc1..7625096a5 100644 --- a/domains/platform/resources/logback.xml +++ b/domains/platform/resources/logback.xml @@ -1,11 +1,10 @@ - - - %d{yyyy-MM-dd'T'HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n - + + INFO From a4e6ba292b0f0c464237263a2cb27a4da3704c78 Mon Sep 17 00:00:00 2001 From: Andy Aylward Date: Mon, 31 Aug 2026 22:05:42 -0400 Subject: [PATCH 04/10] otel_contract: pin the request-log field vocabulary across rails MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The C++ and Rust access lines must spell service_name, http_method, route, target, status, duration_us, trace_id and x_forwarded_for identically, or a cross-service log query silently misses a rail. Spelling pinned here, wire shape pinned per rail behaviorally — the same division the sentinel test uses. Java is deliberately absent: its services emit JSON app logs but no access line; caddy fronts them. --- domains/platform/libs/aura/BUILD.bazel | 5 +- .../platform/libs/otel_contract/BUILD.bazel | 2 + .../otel_contract/request_log_fields_test.go | 50 +++++++++++++++++++ 3 files changed, 56 insertions(+), 1 deletion(-) create mode 100644 domains/platform/libs/otel_contract/request_log_fields_test.go diff --git a/domains/platform/libs/aura/BUILD.bazel b/domains/platform/libs/aura/BUILD.bazel index b9eb37866..39937b029 100644 --- a/domains/platform/libs/aura/BUILD.bazel +++ b/domains/platform/libs/aura/BUILD.bazel @@ -2,7 +2,10 @@ load("@rules_cc//cc:defs.bzl", "cc_library", "cc_test") # Read as text by //domains/platform/libs/otel_contract, which pins the # route sentinel and health-route literal equal across the three rails. -exports_files(["middleware.h"]) +exports_files([ + "middleware.cc", + "middleware.h", +]) # aura: the serving chain for smithy-cpp services — observability over the # shared futility/otel HTTP instruments (plus the access log), health, and diff --git a/domains/platform/libs/otel_contract/BUILD.bazel b/domains/platform/libs/otel_contract/BUILD.bazel index acf568a69..5f5eb6854 100644 --- a/domains/platform/libs/otel_contract/BUILD.bazel +++ b/domains/platform/libs/otel_contract/BUILD.bazel @@ -10,6 +10,7 @@ go_test( "http_instrument_descriptions_test.go", "http_instrument_labels_test.go", "http_latency_buckets_test.go", + "request_log_fields_test.go", ], # Read as text rather than linked. There is no build configuration in which # a Go test could link all three, and the declaration site is what has to @@ -17,6 +18,7 @@ go_test( # named-constant declarations are pinned this way; label sets and units # are pinned per rail against real exported payloads instead. data = [ + "//domains/platform/libs/aura:middleware.cc", "//domains/platform/libs/aura:middleware.h", "//domains/platform/libs/futility/otel:http_instrument_descriptions.h", "//domains/platform/libs/futility/otel:otel_provider.h", diff --git a/domains/platform/libs/otel_contract/request_log_fields_test.go b/domains/platform/libs/otel_contract/request_log_fields_test.go new file mode 100644 index 000000000..86f1b816d --- /dev/null +++ b/domains/platform/libs/otel_contract/request_log_fields_test.go @@ -0,0 +1,50 @@ +package otel_contract + +import ( + "testing" + + "github.com/stretchr/testify/assert" +) + +// The request-log field vocabulary (#1459): the C++ and Rust rails each +// emit one JSON object per request, and a reader who pivots from a +// dashboard to a log query must find the same words on both — including +// the label names the metric contract already pins (http_method, route, +// service_name). Like the sentinel test above, this pins only the +// cross-language spelling; that the fields actually reach the wire is each +// rail's own behavioral test (aura's middleware_test reads the served line +// off a mock log sink, server_pal's access_log tests parse the subscriber's +// JSON output). +// +// The Java rail is deliberately absent: one_d4 and mcpserver emit JSON app +// logs (logback's JsonEncoder, pinned by LogbackConfigTest) but no +// per-request access line — Caddy fronts every route they serve. +var requestLogFields = []string{ + "service_name", + "http_method", + "route", + "target", + "status", + "duration_us", + "trace_id", + "x_forwarded_for", +} + +func TestRequestLogFieldSpellingAgreesAcrossRails(t *testing.T) { + emitters := []struct { + path string + marker string + }{ + {path: "../aura/middleware.cc", marker: "AppendJsonField"}, + {path: "../server_pal/src/lib.rs", marker: "access_log_middleware"}, + } + for _, emitter := range emitters { + source := string(codeLines(t, emitter.path, emitter.marker)) + for _, field := range requestLogFields { + assert.Contains(t, source, field, + "%s does not name request-log field %q; the two rails' lines no longer "+ + "speak one vocabulary and a cross-service log query silently misses "+ + "this rail", emitter.path, field) + } + } +} From b5727e8287bdaf131d4e363ee9fef876e5bfd169 Mon Sep 17 00:00:00 2001 From: Andy Aylward Date: Mon, 31 Aug 2026 22:06:58 -0400 Subject: [PATCH 05/10] bazel rules: declare size=small on the generated test targets MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The oci image structure tests and the analysis-time rules_test guards were implicitly medium — each finishes in under a second. Set once in the generating macros, which covers all fourteen image tests and every rules_test fixture at their one declaration site. --- bazel/rules/java_rules_test.bzl | 3 +++ bazel/rules/oci.bzl | 2 ++ 2 files changed, 5 insertions(+) diff --git a/bazel/rules/java_rules_test.bzl b/bazel/rules/java_rules_test.bzl index 1083c72ac..ed82ad5c1 100644 --- a/bazel/rules/java_rules_test.bzl +++ b/bazel/rules/java_rules_test.bzl @@ -315,6 +315,7 @@ def java_rules_test_suite(name): java_test_suite( name = name + "_suite_fixture", + size = "small", srcs = [ "testdata/SuiteProbeHelper.java", "testdata/SuiteProbeTest.java", @@ -346,6 +347,7 @@ def java_rules_test_suite(name): test_name = "{}_{}_{}".format(name, fixture_label, guard_label) guard( name = test_name, + size = "small", target_under_test = fixture, ) tests.append(test_name) @@ -353,6 +355,7 @@ def java_rules_test_suite(name): micronaut_name = "{}_{}_micronaut".format(name, fixture_label) micronaut_test( name = micronaut_name, + size = "small", target_under_test = fixture, expected = micronaut, ) diff --git a/bazel/rules/oci.bzl b/bazel/rules/oci.bzl index dc8a63515..989ec94b4 100644 --- a/bazel/rules/oci.bzl +++ b/bazel/rules/oci.bzl @@ -68,6 +68,7 @@ def _create_oci_image(bin_name, binary_target, binary_path): container_structure_test( name = bin_name + "_image_test", + size = "small", configs = ["//bazel/rules:oci_image_test.yaml"], image = ":" + image_name, tags = ["manual"], @@ -135,6 +136,7 @@ def linux_oci_java(bin_name): container_structure_test( name = bin_name + "_image_test", + size = "small", configs = ["//bazel/rules:java_image_test.yaml"], image = ":" + image_name, tags = ["manual"], From 2417e63ed141e9c6e53f8e8b09897bc67c1f7f2a Mon Sep 17 00:00:00 2001 From: Andy Aylward Date: Mon, 31 Aug 2026 22:14:28 -0400 Subject: [PATCH 06/10] docs: catch the comments up with the json access lines middleware.h and the aura README still described the deleted key=value format; the service_name comment claimed a shared source the C++ rail does not have; the rust x_forwarded_for note pointed at a derived-client key this rail's governor does not use; two smaller references corrected. --- domains/platform/libs/aura/README.md | 7 ++++--- domains/platform/libs/aura/middleware.cc | 11 +++++++---- domains/platform/libs/aura/middleware.h | 11 ++++++----- .../libs/otel_contract/request_log_fields_test.go | 6 ++++-- domains/platform/libs/server_pal/src/lib.rs | 4 ++-- 5 files changed, 23 insertions(+), 16 deletions(-) diff --git a/domains/platform/libs/aura/README.md b/domains/platform/libs/aura/README.md index cd136cc57..000cb4536 100644 --- a/domains/platform/libs/aura/README.md +++ b/domains/platform/libs/aura/README.md @@ -22,9 +22,10 @@ without `scripts/make-git-overrides.sh`. - **`ProductionChain(ChainOptions, handler)`** — the one entry point: - `ServingObservability` outermost, so health probes and 429s are observed too: the shared `http_server_*` instruments - (`futility/otel:http_metrics`) plus one access-log line per request - with the W3C `trace_id=` from the request's traceparent (smithy-cpp - ADR-0011). The route label is bounded (#1305): the matched Smithy + (`futility/otel:http_metrics`) plus one access-log line per request — + a single JSON object carrying the metrics vocabulary plus the raw + target and the W3C `trace_id` from the request's traceparent + (smithy-cpp ADR-0011). The route label is bounded (#1305): the matched Smithy operation name the generated router stamps on its responses, `kHealthRoute` for the health endpoint, or the `kUnmatchedRoute` sentinel — never the raw request path. The method label is bounded the diff --git a/domains/platform/libs/aura/middleware.cc b/domains/platform/libs/aura/middleware.cc index f099b04ca..6dcfbc5d2 100644 --- a/domains/platform/libs/aura/middleware.cc +++ b/domains/platform/libs/aura/middleware.cc @@ -97,9 +97,9 @@ std::string KindName(smithy::http::BeastServerTransport::ConnectionEvent::Kind k return "unknown(" + std::to_string(static_cast(kind)) + ")"; } -// JSON string escaping for the access-log line. Stricter than the -// Prometheus label escaping in futility: every control byte below 0x20 -// becomes \uXXXX, because the target reaches the line verbatim and is +// JSON string escaping for the access-log line. Every byte below 0x20 is +// escaped (\uXXXX, or the short form for \n \r \t), because the target +// reaches the line verbatim and is // attacker-controlled — a raw control byte or an unescaped quote terminates // the record early and lets the rest of the URI masquerade as its own log // entry (smithy-cpp #203). @@ -173,7 +173,10 @@ smithy::server::Middleware AccessLog() { smithy::http::ParseTraceparent(request.headers.Get("traceparent").value_or("")) .value_or(smithy::http::TraceContext{}) .trace_id; - // The log's identity field, same source as the metrics resource. + // The log's identity, from the compose contract (OTEL_SERVICE_NAME). + // Note the C++ metrics resource does NOT read this variable — each + // service compiles its name into OtelConfig — so the two agree by + // convention, not construction. static const std::string service_name = []() { const char* name = std::getenv("OTEL_SERVICE_NAME"); return std::string(name == nullptr ? "" : name); diff --git a/domains/platform/libs/aura/middleware.h b/domains/platform/libs/aura/middleware.h index f32ae1000..2cdcf5a2a 100644 --- a/domains/platform/libs/aura/middleware.h +++ b/domains/platform/libs/aura/middleware.h @@ -74,11 +74,12 @@ std::shared_ptr MakeHttpMetricsSink( /// histogram at completion, labeled with the bounded route — the matched /// Smithy operation name from the generated router, kHealthRoute for the /// endpoint ProductionChain composes, kUnmatchedRoute for everything else -/// - one access-log line per request, with trace_id carrying the W3C -/// trace id parsed from the request's traceparent (minted or joined at -/// transport ingress, smithy-cpp ADR-0011): -/// [METHOD URI]: X-Forwarded-For= trace_id=<32hex> status= -/// res.body.bytes= duration_ms= +/// - one access-log line per request: a single JSON object in the +/// metrics vocabulary (#1459) — service_name, http_method, route, +/// target, status, duration_us, response_bytes, trace_id (the W3C id +/// minted or joined at transport ingress, smithy-cpp ADR-0011) and +/// x_forwarded_for. Field spelling is pinned cross-rail by +/// //domains/platform/libs/otel_contract. smithy::server::Middleware ServingObservability(std::shared_ptr metrics); /// The production middleware chain around a generated server's handler, diff --git a/domains/platform/libs/otel_contract/request_log_fields_test.go b/domains/platform/libs/otel_contract/request_log_fields_test.go index 86f1b816d..28df7053d 100644 --- a/domains/platform/libs/otel_contract/request_log_fields_test.go +++ b/domains/platform/libs/otel_contract/request_log_fields_test.go @@ -10,7 +10,8 @@ import ( // emit one JSON object per request, and a reader who pivots from a // dashboard to a log query must find the same words on both — including // the label names the metric contract already pins (http_method, route, -// service_name). Like the sentinel test above, this pins only the +// service_name). Like the sentinel test in http_instrument_labels_test.go, +// this pins only the // cross-language spelling; that the fields actually reach the wire is each // rail's own behavioral test (aura's middleware_test reads the served line // off a mock log sink, server_pal's access_log tests parse the subscriber's @@ -18,7 +19,8 @@ import ( // // The Java rail is deliberately absent: one_d4 and mcpserver emit JSON app // logs (logback's JsonEncoder, pinned by LogbackConfigTest) but no -// per-request access line — Caddy fronts every route they serve. +// per-request access line — Caddy's log covers their external traffic, and +// compose-internal calls (mcpserver -> one_d4) are the accepted gap. var requestLogFields = []string{ "service_name", "http_method", diff --git a/domains/platform/libs/server_pal/src/lib.rs b/domains/platform/libs/server_pal/src/lib.rs index 7a22c661b..a02c8d0a9 100644 --- a/domains/platform/libs/server_pal/src/lib.rs +++ b/domains/platform/libs/server_pal/src/lib.rs @@ -146,8 +146,8 @@ fn trace_id_of(traceparent: Option<&str>) -> &str { /// instruments carry, so a dashboard-to-logs pivot is a copy-paste; the raw /// path-and-query rides in "target" where an unbounded value is data, not a /// label. duration_us matches the histogram's unit. x_forwarded_for is the -/// raw header, which since ADR-0012 is NOT the identity the rate limiter -/// keys on. +/// raw header, not the limiter's key — this rail's governor keys on the +/// socket peer address (see RateLimit). async fn access_log_middleware(req: Request, next: Next) -> Response { let start = std::time::Instant::now(); let http_method = bounded_method_label(req.method()); From 7d21846ab8f1dbbfc39ad0af3c50e932814034e1 Mon Sep 17 00:00:00 2001 From: Andy Aylward Date: Mon, 31 Aug 2026 22:21:54 -0400 Subject: [PATCH 07/10] structured logs: harden the lines the review panel poked through MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The rust subscriber regressed RUST_LOG — the free fmt::init parses it into a Targets filter even without env-filter, so init_logging now does the same. aura's escaper replaces invalid UTF-8 with U+FFFD (a stray high byte is legal in a Beast request-target and would make the record unparseable) and caps the caller-controlled fields under absl's 15000- byte truncation. The discriminator key becomes event: docker's json-file envelope already owns 'log'. Access lines are now parsed by real JSON parsers in tests on both rails, service_name is asserted by value, the cross-rail pin matches emitted keys rather than identifiers, and the logback test pins the raw-template-plus-arguments message semantic the query stats will rely on. --- domains/platform/libs/aura/BUILD.bazel | 4 + domains/platform/libs/aura/README.md | 4 +- domains/platform/libs/aura/middleware.cc | 107 ++++++++---- domains/platform/libs/aura/middleware_test.cc | 127 +++++++++----- .../platform/logging/LogbackConfigTest.java | 28 +++ .../otel_contract/request_log_fields_test.go | 43 +++-- domains/platform/libs/server_pal/BUILD.bazel | 3 + domains/platform/libs/server_pal/README.md | 14 +- domains/platform/libs/server_pal/src/lib.rs | 164 +++++++++++++----- 9 files changed, 354 insertions(+), 140 deletions(-) diff --git a/domains/platform/libs/aura/BUILD.bazel b/domains/platform/libs/aura/BUILD.bazel index 39937b029..b9695e01c 100644 --- a/domains/platform/libs/aura/BUILD.bazel +++ b/domains/platform/libs/aura/BUILD.bazel @@ -76,12 +76,16 @@ cc_test( name = "middleware_test", size = "small", srcs = ["middleware_test.cc"], + # The vocabulary test asserts the service_name VALUE, so an env-key typo + # in the reader cannot pass as an empty-but-present field. + env = {"OTEL_SERVICE_NAME": "aura-under-test"}, deps = [ ":aura", "//domains/platform/libs/futility/rate_limiter:sliding_window_rate_limiter", "@com_google_absl//absl/base:log_severity", "@com_google_absl//absl/log:scoped_mock_log", "@googletest//:gtest_main", + "@nlohmann_json//:json", "@smithy_cpp//runtime:http", "@smithy_cpp//runtime:http_beast", "@smithy_cpp//runtime:server", diff --git a/domains/platform/libs/aura/README.md b/domains/platform/libs/aura/README.md index 000cb4536..c59768c60 100644 --- a/domains/platform/libs/aura/README.md +++ b/domains/platform/libs/aura/README.md @@ -25,7 +25,9 @@ without `scripts/make-git-overrides.sh`. (`futility/otel:http_metrics`) plus one access-log line per request — a single JSON object carrying the metrics vocabulary plus the raw target and the W3C `trace_id` from the request's traceparent - (smithy-cpp ADR-0011). The route label is bounded (#1305): the matched Smithy + (smithy-cpp ADR-0011). The object rides inside absl's stderr record, + so the shipped line is `I0831 ... middleware.cc:NNN] {...}` — a + consumer strips the prefix up to `] ` before parsing. The route label is bounded (#1305): the matched Smithy operation name the generated router stamps on its responses, `kHealthRoute` for the health endpoint, or the `kUnmatchedRoute` sentinel — never the raw request path. The method label is bounded the diff --git a/domains/platform/libs/aura/middleware.cc b/domains/platform/libs/aura/middleware.cc index 6dcfbc5d2..6c94f605a 100644 --- a/domains/platform/libs/aura/middleware.cc +++ b/domains/platform/libs/aura/middleware.cc @@ -1,5 +1,6 @@ #include "domains/platform/libs/aura/middleware.h" +#include #include #include #include @@ -98,38 +99,57 @@ std::string KindName(smithy::http::BeastServerTransport::ConnectionEvent::Kind k } // JSON string escaping for the access-log line. Every byte below 0x20 is -// escaped (\uXXXX, or the short form for \n \r \t), because the target -// reaches the line verbatim and is -// attacker-controlled — a raw control byte or an unescaped quote terminates +// escaped (\uXXXX, or the short form for \n \r \t) and invalid UTF-8 is +// replaced with U+FFFD, because the target reaches the line verbatim and is +// attacker-controlled - a raw control byte or an unescaped quote terminates // the record early and lets the rest of the URI masquerade as its own log -// entry (smithy-cpp #203). +// entry (smithy-cpp #203), and a stray non-UTF-8 byte (legal in a request +// target per Beast's parser) would make the one record describing that +// request the record strict JSON parsers reject. void AppendJsonEscaped(std::string& out, std::string_view value) { static constexpr char kHex[] = "0123456789abcdef"; - for (const char c : value) { + static constexpr char kReplacement[] = "\xEF\xBF\xBD"; // U+FFFD + for (size_t i = 0; i < value.size(); ++i) { + const unsigned char c = static_cast(value[i]); switch (c) { case '"': out += "\\\""; - break; + continue; case '\\': out += "\\\\"; - break; + continue; case '\n': out += "\\n"; - break; + continue; case '\r': out += "\\r"; - break; + continue; case '\t': out += "\\t"; - break; - default: - if (static_cast(c) < 0x20) { - out += "\\u00"; - out += kHex[(c >> 4) & 0xF]; - out += kHex[c & 0xF]; - } else { - out += c; - } + continue; + } + if (c < 0x20) { + out += "\\u00"; + out += kHex[(c >> 4) & 0xF]; + out += kHex[c & 0xF]; + continue; + } + if (c < 0x80) { + out += static_cast(c); + continue; + } + // Multi-byte lead: accept a well-formed sequence whole, replace anything + // else. Truncated sequences and stray continuation bytes both land here. + const int continuations = c >= 0xF0 ? 3 : c >= 0xE0 ? 2 : c >= 0xC2 ? 1 : -1; + bool valid = continuations > 0 && i + continuations < value.size(); + for (int k = 1; valid && k <= continuations; ++k) { + valid = (static_cast(value[i + k]) & 0xC0) == 0x80; + } + if (valid) { + out.append(value.substr(i, continuations + 1)); + i += continuations; + } else { + out += kReplacement; } } } @@ -142,6 +162,33 @@ void AppendJsonField(std::string& out, std::string_view name, std::string_view v out += '"'; } +void AppendJsonNumber(std::string& out, std::string_view name, long long value) { + out += ",\""; + out += name; + out += "\":"; + out += std::to_string(value); +} + +// absl truncates a LOG message at its 15000-byte buffer, and a truncated +// record is unparseable JSON - so the two unbounded, caller-controlled +// fields are capped well under it. 2KB of target is more than any +// legitimate route needs and enough of a hostile one to be diagnosable. +std::string_view Capped(std::string_view value, size_t cap) { + return value.substr(0, std::min(value.size(), cap)); +} + +// The log's identity, from the compose contract (OTEL_SERVICE_NAME). +// Note the C++ metrics resource does NOT read this variable - each +// service compiles its name into OtelConfig - so the two agree by +// convention, not construction. +const std::string& ServiceNameFromEnv() { + static const std::string name = []() { + const char* value = std::getenv("OTEL_SERVICE_NAME"); + return std::string(value == nullptr ? "" : value); + }(); + return name; +} + // One access-log line per request: a single JSON object in the metrics // vocabulary (#1459) — http_method and route are the bounded labels the // instruments carry, so a dashboard-to-logs pivot is a copy-paste; the raw @@ -173,25 +220,17 @@ smithy::server::Middleware AccessLog() { smithy::http::ParseTraceparent(request.headers.Get("traceparent").value_or("")) .value_or(smithy::http::TraceContext{}) .trace_id; - // The log's identity, from the compose contract (OTEL_SERVICE_NAME). - // Note the C++ metrics resource does NOT read this variable — each - // service compiles its name into OtelConfig — so the two agree by - // convention, not construction. - static const std::string service_name = []() { - const char* name = std::getenv("OTEL_SERVICE_NAME"); - return std::string(name == nullptr ? "" : name); - }(); - - std::string line = R"({"log":"access")"; - AppendJsonField(line, "service_name", service_name); + std::string line = R"({"event":"access")"; + AppendJsonField(line, "service_name", ServiceNameFromEnv()); AppendJsonField(line, "http_method", MethodLabelOf(request.method)); AppendJsonField(line, "route", RouteLabelOf(response.operation, request.target)); - AppendJsonField(line, "target", request.target); - line += ",\"status\":" + std::to_string(response.status); - line += ",\"duration_us\":" + std::to_string(duration_us.count()); - line += ",\"response_bytes\":" + std::to_string(response.body.size()); + AppendJsonField(line, "target", Capped(request.target, 2048)); + AppendJsonNumber(line, "status", response.status); + AppendJsonNumber(line, "duration_us", duration_us.count()); + AppendJsonNumber(line, "response_bytes", static_cast(response.body.size())); AppendJsonField(line, "trace_id", trace_id); - AppendJsonField(line, "x_forwarded_for", request.headers.Get("X-Forwarded-For").value_or("")); + AppendJsonField(line, "x_forwarded_for", + Capped(request.headers.Get("X-Forwarded-For").value_or(""), 256)); line += '}'; LOG(INFO) << line; return response; diff --git a/domains/platform/libs/aura/middleware_test.cc b/domains/platform/libs/aura/middleware_test.cc index a914234dc..5751c9ad2 100644 --- a/domains/platform/libs/aura/middleware_test.cc +++ b/domains/platform/libs/aura/middleware_test.cc @@ -11,8 +11,10 @@ #include #include +#include #include #include +#include #include #include #include @@ -96,6 +98,27 @@ smithy::http::RequestHandler UnroutedHandler(int status) { }; } +// Runs `send` under a mock log and returns the one access-log line it wrote. +std::string CaptureAccessLogLine(const std::function& send) { + std::string line; + absl::ScopedMockLog log(absl::MockLogDefault::kIgnoreUnexpected); + EXPECT_CALL(log, Log(absl::LogSeverity::kInfo, testing::_, testing::HasSubstr("\"trace_id\":"))) + .WillOnce(testing::SaveArg<2>(&line)); + log.StartCapturingLogs(); + send(); + log.StopCapturingLogs(); + return line; +} + +// The line must be one parseable JSON object, not merely quote-balanced — +// substring checks cannot see structural invalidity, which is exactly what +// a hostile target tries to cause. +nlohmann::json ParsedAccessLine(const std::string& line) { + nlohmann::json parsed = nlohmann::json::parse(line, nullptr, /*allow_exceptions=*/false); + EXPECT_FALSE(parsed.is_discarded()) << "not valid JSON: " << line; + return parsed; +} + // The production chain via the shared builder, with a small rate-limit // budget so tests can exhaust it quickly. The rate limiter keys on the // ADR-0012 derived client address anchored at peer_address, which Loopback @@ -159,20 +182,8 @@ class AuraMiddlewareTest : public ::testing::Test { // Sends one request through the chain and returns the access-log line it // produced. std::string AccessLogLineFor(const std::vector>& headers) { - return AccessLogLineForRequest("POST", "/echo", "hello", headers, 200); - } - - std::string AccessLogLineForRequest( - const std::string& method, const std::string& target, const std::string& body, - const std::vector>& headers, int expected_status) { - std::string line; - absl::ScopedMockLog log(absl::MockLogDefault::kIgnoreUnexpected); - EXPECT_CALL(log, Log(absl::LogSeverity::kInfo, testing::_, testing::HasSubstr("\"trace_id\":"))) - .WillOnce(testing::SaveArg<2>(&line)); - log.StartCapturingLogs(); - EXPECT_EQ(Send(method, target, body, "", headers).status, expected_status); - log.StopCapturingLogs(); - return line; + return CaptureAccessLogLine( + [&] { EXPECT_EQ(Send("POST", "/echo", "hello", "", headers).status, 200); }); } std::shared_ptr sink_; @@ -381,23 +392,21 @@ bool IsLowercaseHex32(const std::string& value) { // the bounded label, never the raw path; the raw path rides separately in // "target". TEST_F(AuraMiddlewareTest, AccessLogIsOneJsonObjectInTheMetricsVocabulary) { - const std::string line = AccessLogLineFor({{"X-Forwarded-For", "203.0.113.9"}}); - - EXPECT_TRUE(line.front() == '{' && line.back() == '}') << line; - for (const char* field : { - R"("log":"access")", - R"("service_name":")", - R"("http_method":"POST")", - R"("route":"Echo")", - R"("target":"/echo")", - R"("status":200)", - R"("duration_us":)", - R"("response_bytes":4)", - R"("trace_id":")", - R"("x_forwarded_for":"203.0.113.9")", - }) { - EXPECT_THAT(line, testing::HasSubstr(field)); - } + const nlohmann::json line = + ParsedAccessLine(AccessLogLineFor({{"X-Forwarded-For", "203.0.113.9"}})); + + EXPECT_EQ(line["event"], "access"); + // The value, not just the key: the BUILD target sets OTEL_SERVICE_NAME, so + // an env-key typo in the reader cannot pass as an empty-but-present field. + EXPECT_EQ(line["service_name"], "aura-under-test"); + EXPECT_EQ(line["http_method"], "POST"); + EXPECT_EQ(line["route"], "Echo"); + EXPECT_EQ(line["target"], "/echo"); + EXPECT_EQ(line["status"], 200); + EXPECT_TRUE(line["duration_us"].is_number()) << line.dump(); + EXPECT_EQ(line["response_bytes"], 4); + EXPECT_TRUE(line["trace_id"].is_string()) << line.dump(); + EXPECT_EQ(line["x_forwarded_for"], "203.0.113.9"); } // Sends one request through a fresh chain over the given handler and @@ -415,25 +424,24 @@ std::string AccessLogLineThrough(smithy::http::RequestHandler handler, const std request.target = target; request.peer_address = "192.0.2.200"; - std::string line; - absl::ScopedMockLog log(absl::MockLogDefault::kIgnoreUnexpected); - EXPECT_CALL(log, Log(absl::LogSeverity::kInfo, testing::_, testing::HasSubstr("\"trace_id\":"))) - .WillOnce(testing::SaveArg<2>(&line)); - log.StartCapturingLogs(); - const auto response = loopback->Send(request); - EXPECT_TRUE(response.ok()); - if (response.ok()) EXPECT_EQ(response->status, expected_status); - log.StopCapturingLogs(); - return line; + return CaptureAccessLogLine([&] { + const auto response = loopback->Send(request); + EXPECT_TRUE(response.ok()); + if (response.ok()) EXPECT_EQ(response->status, expected_status); + }); } // The route field is the same bounded vocabulary the metrics speak: an // unrouted request logs the sentinel, not its path — the path is in // "target", where an unbounded value is a field, not a label. TEST(AccessLogJsonTest, RouteFallsBackToTheSharedSentinel) { - const std::string line = AccessLogLineThrough(UnroutedHandler(404), "/no/such/path", 404); - EXPECT_THAT(line, testing::HasSubstr(R"("route":"unmatched")")); - EXPECT_THAT(line, testing::HasSubstr(R"("target":"/no/such/path")")); + const nlohmann::json line = + ParsedAccessLine(AccessLogLineThrough(UnroutedHandler(404), "/no/such/path", 404)); + EXPECT_EQ(line["route"], "unmatched"); + EXPECT_EQ(line["target"], "/no/such/path"); + // No X-Forwarded-For on this request: the field must read absent-as-empty, + // never a fabricated value. + EXPECT_EQ(line["x_forwarded_for"], ""); } // The target is attacker-controlled and reaches the line verbatim, so JSON @@ -441,10 +449,35 @@ TEST(AccessLogJsonTest, RouteFallsBackToTheSharedSentinel) { // raw control byte terminates the record early and lets the rest of the URI // masquerade as its own log entry. TEST(AccessLogJsonTest, QuotesAndControlBytesInTheTargetAreEscaped) { - const std::string line = AccessLogLineThrough(UnroutedHandler(404), "/e\"cho\x01?a=\\b", 404); + const std::string raw = + AccessLogLineThrough(UnroutedHandler(404), "/e\"cho\x01?a=\\b&z=\x1f", 404); + + EXPECT_THAT(raw, testing::HasSubstr(R"("target":"/e\"cho\u0001?a=\\b&z=\u001f")")); + EXPECT_THAT(raw, testing::Not(testing::HasSubstr("\x01"))); + EXPECT_THAT(raw, testing::Not(testing::HasSubstr("\x1f"))); + EXPECT_EQ(ParsedAccessLine(raw)["target"], "/e\"cho\u0001?a=\\b&z=\u001f"); +} + +// Beast admits bytes 0x80-0xFF in a request-target, so a stray non-UTF-8 +// byte reaches the escaper — passed through raw it would make the line +// invalid UTF-8, and RFC 8259 parsers reject the whole record. Well-formed +// multi-byte sequences pass untouched; anything else becomes U+FFFD. +TEST(AccessLogJsonTest, InvalidUtf8IsReplacedAndValidUtf8Survives) { + const nlohmann::json line = + ParsedAccessLine(AccessLogLineThrough(UnroutedHandler(404), "/caf\xC3\xA9/\xFFx/\xC3", 404)); + + EXPECT_EQ(line["target"], "/caf\xC3\xA9/\xEF\xBF\xBDx/\xEF\xBF\xBD"); +} + +// absl truncates a LOG message at 15000 bytes, and a truncated record is +// unparseable — so the caller-controlled fields are capped far below it and +// a hostile 8KB target still yields one valid record. +TEST(AccessLogJsonTest, AHugeTargetIsCappedAndTheLineStaysParseable) { + const std::string huge = "/" + std::string(8000, '"'); + const nlohmann::json line = + ParsedAccessLine(AccessLogLineThrough(UnroutedHandler(404), huge, 404)); - EXPECT_THAT(line, testing::HasSubstr(R"("target":"/e\"cho\u0001?a=\\b")")); - EXPECT_THAT(line, testing::Not(testing::HasSubstr("\x01"))); + EXPECT_EQ(line["target"].get().size(), 2048u); } TEST_F(AuraMiddlewareTest, AccessLogJoinsInboundTraceIdentity) { diff --git a/domains/platform/libs/logging/src/test/java/com/muchq/platform/logging/LogbackConfigTest.java b/domains/platform/libs/logging/src/test/java/com/muchq/platform/logging/LogbackConfigTest.java index da837d1e4..c3733ba53 100644 --- a/domains/platform/libs/logging/src/test/java/com/muchq/platform/logging/LogbackConfigTest.java +++ b/domains/platform/libs/logging/src/test/java/com/muchq/platform/logging/LogbackConfigTest.java @@ -39,6 +39,8 @@ public void theSharedConfigEmitsOneParseableJsonObjectPerLineWithAnAbsoluteTimes configurator.doConfigure(getClass().getClassLoader().getResource("logback.xml")); Logger logger = context.getLogger("com.muchq.some.Service"); logger.info("hello structured world"); + logger.info("widget {} failed after {} tries", "w-7", 3); + logger.error("boom", new IllegalStateException("connection refused")); } finally { System.setOut(original); context.stop(); @@ -65,5 +67,31 @@ public void theSharedConfigEmitsOneParseableJsonObjectPerLineWithAnAbsoluteTimes .isBetween( Instant.parse("2026-01-01T00:00:00Z").toEpochMilli(), Instant.parse("2100-01-01T00:00:00Z").toEpochMilli()); + + // The parameterized case is what services actually write, and + // JsonEncoder's contract there is NOT "message is the rendered text": + // the raw template rides in "message" and the values in "arguments". + // The stats pipeline reads queries out of exactly this shape — one_d4's + // QueryController logs `query={}` and the query text is arguments[0] — + // so the semantic is pinned, not discovered. + JsonNode parameterized = lineContaining(captured.toString(UTF_8), "widget {} failed"); + assertThat(parameterized.get("message").asText()).isEqualTo("widget {} failed after {} tries"); + assertThat(parameterized.get("arguments").get(0).asText()).isEqualTo("w-7"); + assertThat(parameterized.get("arguments").get(1).asText()).isEqualTo("3"); + + // An ERROR with a throwable — the line Sentry and any alerting reads — + // stays one parseable object with the exception structured inside it. + JsonNode error = lineContaining(captured.toString(UTF_8), "boom"); + assertThat(error.get("level").asText()).isEqualTo("ERROR"); + assertThat(error.get("throwable").toString()).contains("connection refused"); + } + + private JsonNode lineContaining(String output, String needle) throws Exception { + for (String candidate : output.split("\n")) { + if (candidate.contains(needle)) { + return new ObjectMapper().readTree(candidate); + } + } + throw new AssertionError("no line containing " + needle); } } diff --git a/domains/platform/libs/otel_contract/request_log_fields_test.go b/domains/platform/libs/otel_contract/request_log_fields_test.go index 28df7053d..0a70031f8 100644 --- a/domains/platform/libs/otel_contract/request_log_fields_test.go +++ b/domains/platform/libs/otel_contract/request_log_fields_test.go @@ -1,9 +1,11 @@ package otel_contract import ( + "strings" "testing" "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" ) // The request-log field vocabulary (#1459): the C++ and Rust rails each @@ -32,21 +34,34 @@ var requestLogFields = []string{ "x_forwarded_for", } +// response_bytes is deliberately not in the list: the C++ rail emits it and +// the Rust rail cannot without wrapping the response body to count it, so a +// cross-service response_bytes query covers the C++ services only. + func TestRequestLogFieldSpellingAgreesAcrossRails(t *testing.T) { - emitters := []struct { - path string - marker string - }{ - {path: "../aura/middleware.cc", marker: "AppendJsonField"}, - {path: "../server_pal/src/lib.rs", marker: "access_log_middleware"}, + // C++: every emitted key is a quoted string literal handed to + // AppendJsonField / AppendJsonNumber, so the pin matches `"key"` — a + // bare identifier elsewhere in the file cannot satisfy it. + aura := string(codeLines(t, "../aura/middleware.cc", "AppendJsonField")) + for _, field := range requestLogFields { + assert.Contains(t, aura, `"`+field+`"`, + "aura's access line no longer emits a %q key; the two rails' lines no "+ + "longer speak one vocabulary and a cross-service log query silently "+ + "misses this rail", field) } - for _, emitter := range emitters { - source := string(codeLines(t, emitter.path, emitter.marker)) - for _, field := range requestLogFields { - assert.Contains(t, source, field, - "%s does not name request-log field %q; the two rails' lines no longer "+ - "speak one vocabulary and a cross-service log query silently misses "+ - "this rail", emitter.path, field) - } + + // Rust: the emitted keys are the field names inside the one + // tracing::info! block, so the pin reads only that block — a local + // variable elsewhere cannot satisfy it. + rust := string(codeLines(t, "../server_pal/src/lib.rs", "access_log_middleware")) + start := strings.Index(rust, "tracing::info!(") + require.GreaterOrEqual(t, start, 0, "no tracing::info! block in access_log_middleware") + end := strings.Index(rust[start:], ");") + require.GreaterOrEqual(t, end, 0) + event := rust[start : start+end] + for _, field := range requestLogFields { + assert.Contains(t, event, field, + "server_pal's access event no longer carries a %q field; a cross-service "+ + "log query silently misses this rail", field) } } diff --git a/domains/platform/libs/server_pal/BUILD.bazel b/domains/platform/libs/server_pal/BUILD.bazel index b142e80bb..98db873aa 100644 --- a/domains/platform/libs/server_pal/BUILD.bazel +++ b/domains/platform/libs/server_pal/BUILD.bazel @@ -28,5 +28,8 @@ rust_test( name = "server_pal_test", size = "small", crate = ":server_pal", + # The vocabulary test asserts the service_name VALUE, so an env-key typo + # in the reader cannot pass as an empty-but-present field. + env = {"OTEL_SERVICE_NAME": "server-pal-under-test"}, deps = all_crate_deps(normal_dev = True), ) diff --git a/domains/platform/libs/server_pal/README.md b/domains/platform/libs/server_pal/README.md index 3cf9815df..494332b34 100644 --- a/domains/platform/libs/server_pal/README.md +++ b/domains/platform/libs/server_pal/README.md @@ -5,7 +5,12 @@ Opinionated Axum router builder with batteries included. ## Features - Per-IP rate limiting via `tower_governor` (default: 100 req/s, burst 200) -- Request logging via `tower_http::trace` +- One JSON access-log line per request (#1459) — the metrics vocabulary + (`http_method`, `route`, `service_name`) plus `target`, `status`, + `duration_us`, `trace_id` and the raw `x_forwarded_for`. Binaries call + `server_pal::init_logging()` to install the JSON subscriber; `RUST_LOG` + still filters. (`tower_http::trace` stays in the stack for its ERROR + event on failures.) - Request body size limit (4MB) - Response compression - `Accept: application/json` header validation @@ -63,8 +68,11 @@ The default limit is **100 req/s, burst 200**. Override with `.rate_limit()`: .rate_limit(None) ``` -Requests over the limit receive `429 Too Many Requests`. Rate-limited requests -are rejected before `TraceLayer`, so they won't appear in request logs. +Requests over the limit receive `429 Too Many Requests`, and the access log +records them — it sits outside the governor for exactly that reason. A +request the client abandons mid-flight is counted by the instruments (the +metrics guard fires on drop) but never logged: the access line is written +after the handler returns. `per_second` is a rate — requests per second — and `burst` is how many may arrive at once before that rate binds. `tower_governor`'s own builder takes a diff --git a/domains/platform/libs/server_pal/src/lib.rs b/domains/platform/libs/server_pal/src/lib.rs index a02c8d0a9..8760faebc 100644 --- a/domains/platform/libs/server_pal/src/lib.rs +++ b/domains/platform/libs/server_pal/src/lib.rs @@ -101,11 +101,13 @@ fn latency_bucket_view(instrument: &Instrument) -> Option { ) } -/// Installs the process-wide log subscriber: one flattened JSON object per -/// event on stdout (#1459). Replaces the bare `tracing_subscriber::fmt::init()` -/// the binaries used to call, under which the request log below would render -/// as human-format text — machine-readable everywhere or nowhere. -pub fn init_logging() { +/// The one subscriber configuration, shared by `init_logging` and the tests +/// that parse its output — so `flatten_event` and friends are pinned in the +/// thing that ships, not in a test-local copy. +fn log_subscriber_builder() -> tracing_subscriber::fmt::SubscriberBuilder< + tracing_subscriber::fmt::format::JsonFields, + tracing_subscriber::fmt::format::Format, +> { tracing_subscriber::fmt() .json() .flatten_event(true) @@ -115,9 +117,43 @@ pub fn init_logging() { // with the access log's target field and win; the module path earns // no place on a request line. .with_target(false) +} + +/// Installs the process-wide log subscriber: one flattened JSON object per +/// event on stdout (#1459). Replaces the bare `tracing_subscriber::fmt::init()` +/// the binaries used to call, under which the request log below would render +/// as human-format text — machine-readable everywhere or nowhere. +/// +/// `RUST_LOG` still works: the free `fmt::init()` parsed it into a `Targets` +/// filter even without the env-filter feature, and dropping that would turn +/// an operator's `RUST_LOG=debug` into a silent no-op. Same shape here. +pub fn init_logging() { + use tracing_subscriber::{filter::Targets, layer::SubscriberExt, util::SubscriberInitExt}; + let targets = match env::var("RUST_LOG") { + Ok(var) => var.parse::().unwrap_or_else(|e| { + eprintln!("Ignoring RUST_LOG={var:?}: {e}"); + Targets::new().with_default(tracing::level_filters::LevelFilter::INFO) + }), + Err(_) => Targets::new().with_default(tracing::level_filters::LevelFilter::INFO), + }; + log_subscriber_builder() + .with_max_level(tracing::level_filters::LevelFilter::TRACE) + .finish() + .with(targets) .init(); } +/// The bounded route label: the matched template axum stamped after +/// routing, or the shared sentinel. One derivation for the instruments and +/// the access log, so "same vocabulary as the metrics" holds by +/// construction. +fn route_label(req: &Request) -> String { + req.extensions() + .get::() + .map(|p| p.as_str().to_string()) + .unwrap_or_else(|| UNMATCHED_ROUTE.to_string()) +} + /// The log's identity field, same source as the metrics resource. fn service_name_from_env() -> &'static str { static NAME: OnceLock = OnceLock::new(); @@ -128,10 +164,8 @@ fn service_name_from_env() -> &'static str { /// The full mint/join semantics live on the C++ rail (smithy-cpp ADR-0011); /// here the header is Caddy's or the caller's to send, so parse-don't-trust /// is the whole contract. -fn trace_id_of(traceparent: Option<&str>) -> &str { - let Some(header) = traceparent else { return "" }; - let mut parts = header.split('-'); - let (Some(_version), Some(trace_id)) = (parts.next(), parts.next()) else { +fn trace_id_of(traceparent: &str) -> &str { + let Some(trace_id) = traceparent.split('-').nth(1) else { return ""; }; if trace_id.len() == 32 && trace_id.bytes().all(|b| b.is_ascii_hexdigit()) { @@ -151,18 +185,15 @@ fn trace_id_of(traceparent: Option<&str>) -> &str { async fn access_log_middleware(req: Request, next: Next) -> Response { let start = std::time::Instant::now(); let http_method = bounded_method_label(req.method()); - let route = req - .extensions() - .get::() - .map(|p| p.as_str().to_string()) - .unwrap_or_else(|| UNMATCHED_ROUTE.to_string()); + let route = route_label(&req); let target = req.uri().to_string(); + // Lossy, not blanked: a deliberately malformed forwarded-for chain is + // forensic content, and "" would read as the header being absent. let x_forwarded_for = req .headers() .get("x-forwarded-for") - .and_then(|v| v.to_str().ok()) - .unwrap_or("") - .to_string(); + .map(|v| String::from_utf8_lossy(v.as_bytes()).into_owned()) + .unwrap_or_default(); let traceparent = req .headers() .get("traceparent") @@ -173,14 +204,17 @@ async fn access_log_middleware(req: Request, next: Next) -> Response { let resp = next.run(req).await; tracing::info!( - log = "access", + // "event", not "log": docker's json-file driver wraps container + // stdout in an object whose payload key is "log", and a flattening + // consumer would collide the two. + event = "access", service_name = service_name_from_env(), http_method, route, target, status = resp.status().as_u16(), duration_us = start.elapsed().as_micros() as u64, - trace_id = trace_id_of(Some(traceparent.as_str())), + trace_id = trace_id_of(&traceparent), x_forwarded_for, "request" ); @@ -401,14 +435,8 @@ async fn http_metrics_middleware( let method = bounded_method_label(req.method()); // Router::layer middleware runs after routing, so the matched route // template ("/widgets/{id}", never the raw path) is already in the - // request extensions here. The fallback leaves it absent, and mapping - // that to a fixed sentinel is what keeps the label bounded: a scanner's - // paths all collapse into one series instead of minting one each. - let route = req - .extensions() - .get::() - .map(|p| p.as_str().to_string()) - .unwrap_or_else(|| UNMATCHED_ROUTE.to_string()); + // request extensions here (see route_label). + let route = route_label(&req); let gauge_attrs = [ KeyValue::new("http_method", method.clone()), @@ -511,6 +539,9 @@ pub struct RouterBuilder { /// stack than the traffic it reports on. fn common_layers(router: Router) -> Router { router + // Kept alongside the access log: TraceLayer's DefaultOnFailure logs + // failures at ERROR, which the INFO access line does not replace for + // alerting. .layer(TraceLayer::new_for_http()) .layer(DefaultBodyLimit::disable()) .layer(RequestBodyLimitLayer::new(4 * 1024 * 1024)) @@ -824,12 +855,17 @@ mod tests { } async fn access_line_for(path: &str, expected_status: StatusCode) -> serde_json::Value { + access_line(path, expected_status, true).await + } + + async fn access_line( + path: &str, + expected_status: StatusCode, + with_headers: bool, + ) -> serde_json::Value { let buf: Arc>> = Arc::default(); let writer_buf = buf.clone(); - let subscriber = tracing_subscriber::fmt() - .json() - .flatten_event(true) - .with_target(false) + let subscriber = log_subscriber_builder() .with_writer(move || SharedWriter(writer_buf.clone())) .finish(); let _guard = tracing::subscriber::set_default(subscriber); @@ -840,21 +876,23 @@ mod tests { .build() .with_state(NoState); let mut req = make_request(path); - req.headers_mut() - .insert("x-forwarded-for", "203.0.113.9".parse().unwrap()); - req.headers_mut().insert( - "traceparent", - "00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01" - .parse() - .unwrap(), - ); + if with_headers { + req.headers_mut() + .insert("x-forwarded-for", "203.0.113.9".parse().unwrap()); + req.headers_mut().insert( + "traceparent", + "00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01" + .parse() + .unwrap(), + ); + } let resp = app.oneshot(req).await.unwrap(); assert_eq!(resp.status(), expected_status); let output = String::from_utf8(buf.lock().unwrap().clone()).unwrap(); let line = output .lines() - .find(|l| l.contains("\"log\":\"access\"")) + .find(|l| l.contains("\"event\":\"access\"")) .unwrap_or_else(|| panic!("no access line in: {output}")) .to_string(); serde_json::from_str(&line).expect("the access line must be one parseable JSON object") @@ -876,7 +914,23 @@ mod tests { assert!(v["duration_us"].is_number(), "duration_us: {v}"); assert_eq!(v["trace_id"], "4bf92f3577b34da6a3ce929d0e0e4736"); assert_eq!(v["x_forwarded_for"], "203.0.113.9"); - assert!(v["service_name"].is_string(), "service_name: {v}"); + // The value, not just the key. The bazel target sets + // OTEL_SERVICE_NAME=server-pal-under-test, so under CI an env-key + // typo in the reader cannot pass; a bare `cargo test` has it unset + // and the field must then be "". + assert_eq!( + v["service_name"], + env::var("OTEL_SERVICE_NAME").unwrap_or_default() + ); + } + + /// Absent headers read as empty fields — never a fabricated value, and + /// never a missing key. + #[tokio::test] + async fn absent_headers_log_as_empty_fields() { + let v = access_line("/no/such/path", StatusCode::NOT_FOUND, false).await; + assert_eq!(v["x_forwarded_for"], ""); + assert_eq!(v["trace_id"], ""); } /// Unrouted requests log the shared sentinel, the same spelling the @@ -890,6 +944,34 @@ mod tests { assert_eq!(v["status"], 404); assert_eq!(v["target"], "/no/such/path"); } + + /// The probe path is deliberately access-logged (the layer sits outside + /// the health/limited split); a layer move that silences — or floods — + /// it should fail a test, not surprise an operator. + #[tokio::test] + async fn access_log_covers_the_health_route() { + let v = access_line_for("/health", StatusCode::OK).await; + assert_eq!(v["route"], "/health"); + assert_eq!(v["status"], 200); + } + + /// Parse-don't-trust is the whole contract, so the rejection branches + /// are pinned, not just the happy path. + #[test] + fn trace_id_of_rejects_malformed_traceparents() { + assert_eq!( + trace_id_of("00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01"), + "4bf92f3577b34da6a3ce929d0e0e4736" + ); + assert_eq!(trace_id_of(""), ""); + assert_eq!(trace_id_of("no-dashes-here"), ""); + assert_eq!( + trace_id_of("00-4bf92f3577b34da6a3ce929d0e0e4736ff-x-01"), + "" + ); + assert_eq!(trace_id_of("00-4BF92F3577B34DA6A3CE929D0E0E473G-x-01"), ""); + assert_eq!(trace_id_of("00"), ""); + } } #[cfg(test)] From 49c5da22ca4d007ee24101036616278668e987a1 Mon Sep 17 00:00:00 2001 From: Andy Aylward Date: Mon, 31 Aug 2026 22:29:05 -0400 Subject: [PATCH 08/10] stats: aggregate shipped caddy logs into served per-entity counts MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The s3 client moves out of log_shipper into libs/s3lite and grows signed GETs and ListObjectsV2 (query-string canonicalization included, self-consistency-tested like the PUT path). The stats service lists the shipped objects, streams each once, and rolls lines up into bounded keys — vhost, status, nine-verb method, and a four-class user-agent vocabulary with AI scrapers split out — plus per-slug iili redirect counts. Rollup and processed marker commit in one transaction, so a crash re-processes and a duplicate no-ops. Served at /stats/v1/* via mucks; postgres via pgx, the store test gated on STATS_TEST_DB_URL. --- bazel/go.MODULE.bazel | 1 + domains/platform/apis/stats/BUILD.bazel | 47 +++++ domains/platform/apis/stats/README.md | 45 +++++ domains/platform/apis/stats/aggregate.go | 113 +++++++++++ domains/platform/apis/stats/aggregate_test.go | 61 ++++++ domains/platform/apis/stats/api.go | 87 +++++++++ domains/platform/apis/stats/api_test.go | 102 ++++++++++ domains/platform/apis/stats/classify.go | 99 ++++++++++ domains/platform/apis/stats/classify_test.go | 59 ++++++ domains/platform/apis/stats/loop.go | 97 ++++++++++ domains/platform/apis/stats/loop_test.go | 145 ++++++++++++++ domains/platform/apis/stats/main/main.go | 91 +++++++++ domains/platform/apis/stats/store.go | 178 ++++++++++++++++++ domains/platform/apis/stats/store_test.go | 91 +++++++++ domains/platform/apps/log_shipper/BUILD.bazel | 9 +- domains/platform/apps/log_shipper/README.md | 2 +- .../platform/apps/log_shipper/main/main.go | 5 +- domains/platform/libs/s3lite/BUILD.bazel | 26 +++ .../{apps/log_shipper => libs/s3lite}/s3.go | 110 ++++++++++- .../log_shipper => libs/s3lite}/s3_test.go | 70 ++++++- .../log_shipper => libs/s3lite}/sigv4.go | 38 +++- .../log_shipper => libs/s3lite}/sigv4_test.go | 23 ++- go.mod | 5 + go.sum | 12 ++ 24 files changed, 1493 insertions(+), 23 deletions(-) create mode 100644 domains/platform/apis/stats/BUILD.bazel create mode 100644 domains/platform/apis/stats/README.md create mode 100644 domains/platform/apis/stats/aggregate.go create mode 100644 domains/platform/apis/stats/aggregate_test.go create mode 100644 domains/platform/apis/stats/api.go create mode 100644 domains/platform/apis/stats/api_test.go create mode 100644 domains/platform/apis/stats/classify.go create mode 100644 domains/platform/apis/stats/classify_test.go create mode 100644 domains/platform/apis/stats/loop.go create mode 100644 domains/platform/apis/stats/loop_test.go create mode 100644 domains/platform/apis/stats/main/main.go create mode 100644 domains/platform/apis/stats/store.go create mode 100644 domains/platform/apis/stats/store_test.go create mode 100644 domains/platform/libs/s3lite/BUILD.bazel rename domains/platform/{apps/log_shipper => libs/s3lite}/s3.go (50%) rename domains/platform/{apps/log_shipper => libs/s3lite}/s3_test.go (72%) rename domains/platform/{apps/log_shipper => libs/s3lite}/sigv4.go (73%) rename domains/platform/{apps/log_shipper => libs/s3lite}/sigv4_test.go (85%) diff --git a/bazel/go.MODULE.bazel b/bazel/go.MODULE.bazel index f344f6d59..3a31bddd0 100644 --- a/bazel/go.MODULE.bazel +++ b/bazel/go.MODULE.bazel @@ -17,6 +17,7 @@ use_repo( "com_github_golang_jwt_jwt_v5", "com_github_google_uuid", "com_github_gorilla_websocket", + "com_github_jackc_pgx_v5", "com_github_prometheus_client_golang", "com_github_prometheus_common", "com_github_stretchr_testify", diff --git a/domains/platform/apis/stats/BUILD.bazel b/domains/platform/apis/stats/BUILD.bazel new file mode 100644 index 000000000..7cada874b --- /dev/null +++ b/domains/platform/apis/stats/BUILD.bazel @@ -0,0 +1,47 @@ +load("@io_bazel_rules_go//go:def.bzl", "go_binary", "go_library", "go_test") +load("//bazel/rules:oci.bzl", "linux_oci_go") + +go_library( + name = "stats_lib", + srcs = [ + "aggregate.go", + "api.go", + "classify.go", + "loop.go", + "store.go", + ], + importpath = "github.com/muchq/moonbase/domains/platform/apis/stats", + visibility = ["//visibility:public"], + deps = [ + "@com_github_jackc_pgx_v5//:pgx", + "@com_github_jackc_pgx_v5//pgxpool", + ], +) + +# store_test.go skips without STATS_TEST_DB_URL, like the repo's other +# Postgres-gated suites — a local green run may have exercised no SQL. +go_test( + name = "stats_test", + size = "small", + srcs = [ + "aggregate_test.go", + "api_test.go", + "classify_test.go", + "loop_test.go", + "store_test.go", + ], + embed = [":stats_lib"], +) + +go_binary( + name = "stats", + srcs = ["main/main.go"], + visibility = ["//visibility:public"], + deps = [ + ":stats_lib", + "//domains/platform/libs/mucks", + "//domains/platform/libs/s3lite", + ], +) + +linux_oci_go(bin_name = "stats") diff --git a/domains/platform/apis/stats/README.md b/domains/platform/apis/stats/README.md new file mode 100644 index 000000000..334b30e18 --- /dev/null +++ b/domains/platform/apis/stats/README.md @@ -0,0 +1,45 @@ +# stats + +Serves the aggregates the log pipeline computes (#1460, part of #1365), +and runs the aggregation loop that computes them — one process, because +the box budgets a quarter CPU per container and the loop is idle between +passes. + +## The loop + +Every `AGGREGATE_INTERVAL` (default `15m`): list +`s3://$S3_BUCKET/logs/source=caddy/`, and for every object no successful +pass has marked processed, stream it (gunzip included), roll up its lines +in memory, and apply the rollup plus the processed marker in one +transaction. A crash between the two re-processes the object; the marker's +conflict arm makes a duplicate application a no-op — so counts survive +crashes without double-counting. Per-object failures are logged and +retried next pass. + +Aggregates are bounded on purpose: hosts are Caddy's vhosts, methods +collapse through the nine-verb rule the metrics rails use, user agents +collapse to four classes (`ai_scraper`, `bot`, `browser`, `other`), and +iili slugs are the one caller-shaped key — one path segment, max 64 +bytes, only on the redirect routes. The raw lines stay in S3, so a +better classifier is a re-aggregation, not lost data. + +## The API + +- `GET /stats/v1/summary?days=7` — per day/host/agent-class request and + error counts +- `GET /stats/v1/iili/top?days=30&limit=20` — most-followed short links +- `GET /health` + +Public through Caddy at `api.muchq.com/stats/v1/*`; the reasons for 500s +stay in the log, not on the wire. + +## Configuration + +`STATS_DB_URL` (postgres), `S3_BUCKET`, `S3_REGION`, `AWS_ACCESS_KEY_ID`, +`AWS_SECRET_ACCESS_KEY` — the same stats IAM user the shipper writes with, +which therefore needs `s3:GetObject` and `s3:ListBucket` on the `logs/*` +prefix as well as `s3:PutObject`. `AGGREGATE_INTERVAL` and `PORT` +(default 8092) are optional. + +The store integration test needs `STATS_TEST_DB_URL` and skips without it, +like the repo's other Postgres-gated suites. diff --git a/domains/platform/apis/stats/aggregate.go b/domains/platform/apis/stats/aggregate.go new file mode 100644 index 000000000..36e555b56 --- /dev/null +++ b/domains/platform/apis/stats/aggregate.go @@ -0,0 +1,113 @@ +package stats + +import ( + "bufio" + "encoding/json" + "fmt" + "io" +) + +// RequestKey is one row of the per-day request rollup: everything bounded, +// nothing caller-controlled — host is one of Caddy's configured vhosts, +// the method collapses through the same nine-verb rule the metrics rails +// use, and the agent class is the four-value vocabulary in classify.go. +type RequestKey struct { + Date string + Host string + Status int + Method string + AgentClass string +} + +// SlugKey is one row of the iili redirect rollup. The slug is +// caller-shaped but bounded by SlugOf (one path segment, max 64 bytes), +// and only rows for requests that reached the redirect route exist at all. +type SlugKey struct { + Date string + Slug string + Status int +} + +// Rollup is one processed object's aggregates, accumulated in memory and +// applied to the store in a single transaction with the processed marker — +// so a crash between the two reprocesses the object rather than losing or +// double-counting it. +type Rollup struct { + Requests map[RequestKey]int64 + Slugs map[SlugKey]int64 +} + +func NewRollup() *Rollup { + return &Rollup{Requests: map[RequestKey]int64{}, Slugs: map[SlugKey]int64{}} +} + +// caddyLine is the slice of Caddy's JSON access log this pipeline reads. +// Everything else in the line is ignored on decode. +type caddyLine struct { + Status int `json:"status"` + Request struct { + Host string `json:"host"` + Method string `json:"method"` + URI string `json:"uri"` + Headers map[string][]string `json:"headers"` + } `json:"request"` +} + +func (l *caddyLine) userAgent() string { + values := l.Request.Headers["User-Agent"] + if len(values) == 0 { + return "" + } + return values[0] +} + +// The nine RFC 9110 methods pass through, anything else collapses — +// the same bounding rule as every metrics rail (#1305), because a scanner +// spraying invented verbs must not mint a row per token. +var knownMethods = map[string]bool{ + "GET": true, "HEAD": true, "POST": true, "PUT": true, "DELETE": true, + "CONNECT": true, "OPTIONS": true, "TRACE": true, "PATCH": true, +} + +func boundedMethod(method string) string { + if knownMethods[method] { + return method + } + return "CUSTOM" +} + +// Consume aggregates one object's worth of Caddy JSON lines into the +// rollup. date is the object's dt= partition — the roll date — not +// anything parsed out of the lines. Unparseable lines are counted and +// skipped: one corrupt line must not discard the other hundred thousand, +// but a wholly corrupt object should be loud, so the count comes back. +func (r *Rollup) Consume(reader io.Reader, date string) (skipped int, err error) { + scanner := bufio.NewScanner(reader) + scanner.Buffer(make([]byte, 0, 64*1024), 1024*1024) + for scanner.Scan() { + line := scanner.Bytes() + if len(line) == 0 { + continue + } + var parsed caddyLine + if json.Unmarshal(line, &parsed) != nil || parsed.Request.Host == "" { + skipped++ + continue + } + method := boundedMethod(parsed.Request.Method) + r.Requests[RequestKey{ + Date: date, + Host: parsed.Request.Host, + Status: parsed.Status, + Method: method, + AgentClass: AgentClassOf(parsed.userAgent()), + }]++ + if slug := SlugOf(parsed.Request.Host, parsed.Request.Method, parsed.Request.URI); slug != "" { + r.Slugs[SlugKey{Date: date, Slug: slug, Status: parsed.Status}]++ + } + } + if err := scanner.Err(); err != nil { + return skipped, fmt.Errorf("reading log lines: %w", err) + } + return skipped, nil +} diff --git a/domains/platform/apis/stats/aggregate_test.go b/domains/platform/apis/stats/aggregate_test.go new file mode 100644 index 000000000..9e489c7d7 --- /dev/null +++ b/domains/platform/apis/stats/aggregate_test.go @@ -0,0 +1,61 @@ +package stats + +import ( + "strings" + "testing" +) + +const sampleLines = `{"status":200,"request":{"host":"api.1d4.net","method":"POST","uri":"/mcp","headers":{"User-Agent":["Mozilla/5.0 (Macintosh) Chrome/126.0"]}}} +{"status":200,"request":{"host":"api.1d4.net","method":"POST","uri":"/mcp","headers":{"User-Agent":["Mozilla/5.0 (Macintosh) Chrome/126.0"]}}} +{"status":403,"request":{"host":"git.muchq.com","method":"GET","uri":"/repo/src","headers":{"User-Agent":["meta-externalagent/1.1"]}}} +{"status":302,"request":{"host":"i.iili.uk","method":"GET","uri":"/r/abc123","headers":{"User-Agent":["curl/8.6.0"]}}} +{"status":302,"request":{"host":"i.iili.uk","method":"GET","uri":"/r/abc123","headers":{"User-Agent":["Mozilla/5.0 Chrome"]}}} +{"status":404,"request":{"host":"i.iili.uk","method":"GET","uri":"/r/gone","headers":{}}} +not json at all +{"status":418,"request":{"method":"GET","uri":"/hostless","headers":{}}} +{"status":200,"request":{"host":"api.muchq.com","method":"WEIRD","uri":"/x","headers":{}}} +` + +func TestConsumeAggregatesRequestsSlugsAndSkipsCorruptLines(t *testing.T) { + rollup := NewRollup() + + skipped, err := rollup.Consume(strings.NewReader(sampleLines), "2026-08-30") + + if err != nil { + t.Fatal(err) + } + // The bare-garbage line and the hostless line are skipped, counted. + if skipped != 2 { + t.Errorf("skipped = %d, want 2", skipped) + } + if got := rollup.Requests[RequestKey{"2026-08-30", "api.1d4.net", 200, "POST", AgentBrowser}]; got != 2 { + t.Errorf("mcp browser POSTs = %d, want 2", got) + } + if got := rollup.Requests[RequestKey{"2026-08-30", "git.muchq.com", 403, "GET", AgentAIScraper}]; got != 1 { + t.Errorf("blocked ai scraper = %d, want 1", got) + } + // An invented verb collapses like every metrics rail's method label. + if got := rollup.Requests[RequestKey{"2026-08-30", "api.muchq.com", 200, "CUSTOM", AgentOther}]; got != 1 { + t.Errorf("CUSTOM-method row = %d, want 1", got) + } + // The redirect rollup counts per slug and status, across agent classes. + if got := rollup.Slugs[SlugKey{"2026-08-30", "abc123", 302}]; got != 2 { + t.Errorf("abc123 hits = %d, want 2", got) + } + if got := rollup.Slugs[SlugKey{"2026-08-30", "gone", 404}]; got != 1 { + t.Errorf("gone-slug 404s = %d, want 1", got) + } +} + +func TestConsumeSurvivesOversizedLines(t *testing.T) { + huge := `{"status":200,"request":{"host":"x","method":"GET","uri":"/` + + strings.Repeat("a", 2*1024*1024) + `","headers":{}}}` + + _, err := NewRollup().Consume(strings.NewReader(huge), "2026-08-30") + + // A line over the scanner cap is an error the caller must see — the + // object needs investigating — not a silent partial read. + if err == nil { + t.Error("a line over the scanner's cap must surface as an error") + } +} diff --git a/domains/platform/apis/stats/api.go b/domains/platform/apis/stats/api.go new file mode 100644 index 000000000..43c8cb336 --- /dev/null +++ b/domains/platform/apis/stats/api.go @@ -0,0 +1,87 @@ +package stats + +import ( + "context" + "encoding/json" + "log/slog" + "net/http" + "strconv" +) + +// Reader is what the HTTP handlers need from the store — an interface so +// the handler tests run against a map instead of a database. +type Reader interface { + Summary(ctx context.Context, days int) ([]SummaryRow, error) + TopSlugs(ctx context.Context, days, limit int) ([]SlugRow, error) +} + +type Handlers struct { + reader Reader + logger *slog.Logger +} + +func NewHandlers(reader Reader, logger *slog.Logger) *Handlers { + return &Handlers{reader: reader, logger: logger} +} + +func (h *Handlers) Health(w http.ResponseWriter, _ *http.Request) { + w.Write([]byte(`{"status":"healthy"}`)) +} + +// queryInt reads an integer query parameter, clamped to [1, max]; absent +// or unparseable reads as the default rather than an error — a stats page +// with a mangled query string should degrade to the default window, not 400. +func queryInt(r *http.Request, name string, def, max int) int { + raw := r.URL.Query().Get(name) + value, err := strconv.Atoi(raw) + if raw == "" || err != nil { + return def + } + if value < 1 { + return 1 + } + if value > max { + return max + } + return value +} + +func (h *Handlers) GetSummary(w http.ResponseWriter, r *http.Request) { + days := queryInt(r, "days", 7, 365) + rows, err := h.reader.Summary(r.Context(), days) + if err != nil { + h.serverError(w, "summary", err) + return + } + writeJSON(w, map[string]any{"days": days, "rows": emptyIfNil(rows)}) +} + +func (h *Handlers) GetTopSlugs(w http.ResponseWriter, r *http.Request) { + days := queryInt(r, "days", 30, 365) + limit := queryInt(r, "limit", 20, 200) + rows, err := h.reader.TopSlugs(r.Context(), days, limit) + if err != nil { + h.serverError(w, "top slugs", err) + return + } + writeJSON(w, map[string]any{"days": days, "rows": emptyIfNil(rows)}) +} + +func (h *Handlers) serverError(w http.ResponseWriter, what string, err error) { + h.logger.Error("stats query failed", "query", what, "error", err) + // The reason goes to the log, not the wire: these endpoints are public. + http.Error(w, `{"error":"internal"}`, http.StatusInternalServerError) +} + +func writeJSON(w http.ResponseWriter, payload any) { + json.NewEncoder(w).Encode(payload) +} + +// emptyIfNil keeps "no rows yet" serializing as [] rather than null — the +// dashboard maps over it. +func emptyIfNil[T any](rows []T) []T { + if rows == nil { + return []T{} + } + return rows +} diff --git a/domains/platform/apis/stats/api_test.go b/domains/platform/apis/stats/api_test.go new file mode 100644 index 000000000..3a588f0ec --- /dev/null +++ b/domains/platform/apis/stats/api_test.go @@ -0,0 +1,102 @@ +package stats + +import ( + "context" + "encoding/json" + "errors" + "io" + "log/slog" + "net/http" + "net/http/httptest" + "strings" + "testing" +) + +type fakeReader struct { + summary []SummaryRow + slugs []SlugRow + lastDays int + lastLimit int + fail bool +} + +func (f *fakeReader) Summary(_ context.Context, days int) ([]SummaryRow, error) { + if f.fail { + return nil, errors.New("db is having a day") + } + f.lastDays = days + return f.summary, nil +} + +func (f *fakeReader) TopSlugs(_ context.Context, days, limit int) ([]SlugRow, error) { + if f.fail { + return nil, errors.New("db is having a day") + } + f.lastDays, f.lastLimit = days, limit + return f.slugs, nil +} + +func handlersWith(reader *fakeReader) *Handlers { + return NewHandlers(reader, slog.New(slog.NewTextHandler(io.Discard, nil))) +} + +func get(t *testing.T, handler http.HandlerFunc, url string) (*httptest.ResponseRecorder, map[string]any) { + t.Helper() + recorder := httptest.NewRecorder() + handler(recorder, httptest.NewRequest("GET", url, nil)) + var body map[string]any + if recorder.Code == http.StatusOK { + if err := json.Unmarshal(recorder.Body.Bytes(), &body); err != nil { + t.Fatalf("unparseable response %q: %v", recorder.Body.String(), err) + } + } + return recorder, body +} + +func TestSummaryClampsDaysAndReturnsRows(t *testing.T) { + reader := &fakeReader{summary: []SummaryRow{ + {Date: "2026-08-30", Host: "api.1d4.net", AgentClass: "browser", Requests: 10, Errors: 1}, + }} + handlers := handlersWith(reader) + + _, body := get(t, handlers.GetSummary, "/stats/v1/summary?days=99999") + if reader.lastDays != 365 { + t.Errorf("days clamped to %d, want 365", reader.lastDays) + } + if rows := body["rows"].([]any); len(rows) != 1 { + t.Errorf("rows = %v", body["rows"]) + } + + // Absent and garbage both degrade to the default window, not a 400 — a + // public stats page with a mangled query string still renders. + get(t, handlers.GetSummary, "/stats/v1/summary") + if reader.lastDays != 7 { + t.Errorf("default days = %d, want 7", reader.lastDays) + } + get(t, handlers.GetSummary, "/stats/v1/summary?days=banana") + if reader.lastDays != 7 { + t.Errorf("garbage days = %d, want the default 7", reader.lastDays) + } +} + +func TestTopSlugsPassesWindowAndLimit(t *testing.T) { + reader := &fakeReader{} + _, body := get(t, handlersWith(reader).GetTopSlugs, "/stats/v1/iili/top?days=30&limit=5") + if reader.lastDays != 30 || reader.lastLimit != 5 { + t.Errorf("(days, limit) = (%d, %d)", reader.lastDays, reader.lastLimit) + } + // No rows yet must serialize as [], not null — the dashboard maps it. + if body["rows"] == nil { + t.Error(`rows serialized as null; want []`) + } +} + +func TestAStoreFailureIs500WithoutTheReasonOnTheWire(t *testing.T) { + recorder, _ := get(t, handlersWith(&fakeReader{fail: true}).GetSummary, "/stats/v1/summary") + if recorder.Code != http.StatusInternalServerError { + t.Errorf("status = %d, want 500", recorder.Code) + } + if strings.Contains(recorder.Body.String(), "db is having a day") { + t.Error("the failure reason leaked to a public endpoint") + } +} diff --git a/domains/platform/apis/stats/classify.go b/domains/platform/apis/stats/classify.go new file mode 100644 index 000000000..44eea63f7 --- /dev/null +++ b/domains/platform/apis/stats/classify.go @@ -0,0 +1,99 @@ +package stats + +import "strings" + +// The bounded user-agent vocabulary the stats tables key on. Four values, +// not a UA string per row: the point of classification is that "how much of +// my traffic is AI scrapers" is one GROUP BY, and an unbounded ua column is +// the same cardinality trap the metrics rails solved with route sentinels. +const ( + AgentAIScraper = "ai_scraper" + AgentBot = "bot" + AgentBrowser = "browser" + AgentOther = "other" +) + +// Self-identified AI crawlers, matched case-insensitively as substrings. +// The list is additive and best-effort — an unlisted scraper lands in +// "bot" (if it self-identifies at all) or "browser" (if it lies), and the +// raw logs stay in S3 for reclassification when the list grows. +var aiScraperMarkers = []string{ + "gptbot", + "oai-searchbot", + "chatgpt-user", + "claudebot", + "claude-web", + "claude-user", + "anthropic-ai", + "ccbot", + "bytespider", + "perplexitybot", + "perplexity-user", + "meta-externalagent", + "meta-externalfetcher", + "google-extended", + "applebot-extended", + "amazonbot", + "cohere-ai", + "diffbot", + "ai2bot", + "omgili", + "timpibot", + "youbot", +} + +var botMarkers = []string{ + "bot", "spider", "crawl", "curl", "wget", "python-requests", "python/", + "go-http-client", "libwww", "httpclient", "okhttp", "scrapy", "java/", + "apache-httpclient", "phantom", "headless", "scanner", "nmap", "zgrab", + "masscan", "nuclei", "censys", +} + +// AgentClassOf buckets a User-Agent header. Order matters: AI scrapers +// self-identify with names that also match the generic bot markers. +func AgentClassOf(userAgent string) string { + ua := strings.ToLower(userAgent) + if ua == "" { + return AgentOther + } + for _, marker := range aiScraperMarkers { + if strings.Contains(ua, marker) { + return AgentAIScraper + } + } + for _, marker := range botMarkers { + if strings.Contains(ua, marker) { + return AgentBot + } + } + if strings.HasPrefix(ua, "mozilla/") { + return AgentBrowser + } + return AgentOther +} + +// SlugOf extracts the iili short-link slug from a request, or "" when the +// request is not a redirect lookup. Two shapes reach iili: the public +// i.iili.uk/r/{slug} host and the api.muchq.com/iili/v1/r/{slug} route. +func SlugOf(host, method, uri string) string { + if method != "GET" && method != "HEAD" { + return "" + } + path := uri + if q := strings.IndexByte(path, '?'); q >= 0 { + path = path[:q] + } + var rest string + switch { + case strings.HasPrefix(host, "i.iili.uk") && strings.HasPrefix(path, "/r/"): + rest = path[len("/r/"):] + case strings.HasPrefix(path, "/iili/v1/r/"): + rest = path[len("/iili/v1/r/"):] + default: + return "" + } + if rest == "" || strings.ContainsRune(rest, '/') || len(rest) > 64 { + return "" + } + return rest +} diff --git a/domains/platform/apis/stats/classify_test.go b/domains/platform/apis/stats/classify_test.go new file mode 100644 index 000000000..6f23ef450 --- /dev/null +++ b/domains/platform/apis/stats/classify_test.go @@ -0,0 +1,59 @@ +package stats + +import ( + "strings" + "testing" +) + +func TestAgentClassificationCoversTheVocabulary(t *testing.T) { + cases := []struct { + ua string + want string + }{ + // AI scrapers win over the generic bot markers they also match. + {"Mozilla/5.0 AppleWebKit/537.36; compatible; GPTBot/1.2; +https://openai.com/gptbot", AgentAIScraper}, + {"Mozilla/5.0 (compatible; ClaudeBot/1.0; +claudebot@anthropic.com)", AgentAIScraper}, + {"meta-externalagent/1.1 (+https://developers.facebook.com/docs/sharing/webmasters/crawler)", AgentAIScraper}, + {"Bytespider; spider-feedback@bytedance.com", AgentAIScraper}, + {"PerplexityBot/1.0", AgentAIScraper}, + + {"Mozilla/5.0 (compatible; Googlebot/2.1; +http://www.google.com/bot.html)", AgentBot}, + {"curl/8.6.0", AgentBot}, + {"python-requests/2.32.0", AgentBot}, + {"Go-http-client/2.0", AgentBot}, + + {"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/126.0 Safari/537.36", AgentBrowser}, + + {"", AgentOther}, + {"definitely-not-a-browser", AgentOther}, + } + for _, c := range cases { + if got := AgentClassOf(c.ua); got != c.want { + t.Errorf("AgentClassOf(%q) = %s, want %s", c.ua, got, c.want) + } + } +} + +func TestSlugExtractionIsBoundedAndRouteScoped(t *testing.T) { + cases := []struct { + host, method, uri string + want string + }{ + {"i.iili.uk", "GET", "/r/abc123", "abc123"}, + {"i.iili.uk", "HEAD", "/r/abc123?utm=x", "abc123"}, + {"api.muchq.com", "GET", "/iili/v1/r/xyz", "xyz"}, + // POSTs are not redirect lookups; deep paths and oversized slugs + // are scanner shapes, not slugs. + {"i.iili.uk", "POST", "/r/abc123", ""}, + {"i.iili.uk", "GET", "/r/a/b", ""}, + {"i.iili.uk", "GET", "/r/", ""}, + {"i.iili.uk", "GET", "/r/" + strings.Repeat("a", 100), ""}, + {"api.muchq.com", "GET", "/portrait/v1/trace", ""}, + {"git.muchq.com", "GET", "/r/abc", ""}, + } + for _, c := range cases { + if got := SlugOf(c.host, c.method, c.uri); got != c.want { + t.Errorf("SlugOf(%q, %s, %q) = %q, want %q", c.host, c.method, c.uri, got, c.want) + } + } +} diff --git a/domains/platform/apis/stats/loop.go b/domains/platform/apis/stats/loop.go new file mode 100644 index 000000000..2d1e7d2de --- /dev/null +++ b/domains/platform/apis/stats/loop.go @@ -0,0 +1,97 @@ +package stats + +import ( + "compress/gzip" + "context" + "fmt" + "io" + "log/slog" + "regexp" + "strings" +) + +// ObjectStore is the slice of s3lite the aggregation loop needs, an +// interface so the loop tests run against maps. +type ObjectStore interface { + List(prefix string) ([]string, error) + Get(key string) (io.ReadCloser, error) +} + +// Applier is the write half of the store, split from Reader so the loop +// tests record applications without a database. +type Applier interface { + Unprocessed(ctx context.Context, keys []string) ([]string, error) + ApplyRollup(ctx context.Context, key string, rollup *Rollup) error +} + +// The shipper's layout: logs/source=caddy/dt=YYYY-MM-DD/. The date +// group is the partition the rollup is keyed by. +var objectKey = regexp.MustCompile(`^logs/source=caddy/dt=(\d{4}-\d{2}-\d{2})/`) + +type Aggregator struct { + Objects ObjectStore + Store Applier + Logger *slog.Logger +} + +// RunOnce aggregates every not-yet-processed object under the caddy +// prefix. Per-object failures are logged and skipped — the object stays +// unprocessed and the next pass retries it — so one corrupt or half- +// shipped object cannot wedge the loop. +func (a *Aggregator) RunOnce(ctx context.Context) (processed int, err error) { + keys, err := a.Objects.List("logs/source=caddy/") + if err != nil { + return 0, fmt.Errorf("listing log objects: %w", err) + } + var candidates []string + for _, key := range keys { + if objectKey.MatchString(key) { + candidates = append(candidates, key) + } + } + if len(candidates) == 0 { + return 0, nil + } + pending, err := a.Store.Unprocessed(ctx, candidates) + if err != nil { + return 0, fmt.Errorf("checking processed markers: %w", err) + } + for _, key := range pending { + if err := a.processObject(ctx, key); err != nil { + a.Logger.Error("aggregating object failed; will retry next pass", + "key", key, "error", err) + continue + } + processed++ + } + return processed, nil +} + +func (a *Aggregator) processObject(ctx context.Context, key string) error { + date := objectKey.FindStringSubmatch(key)[1] + body, err := a.Objects.Get(key) + if err != nil { + return err + } + defer body.Close() + + var reader io.Reader = body + if strings.HasSuffix(key, ".gz") { + gz, err := gzip.NewReader(body) + if err != nil { + return fmt.Errorf("not gzip: %w", err) + } + defer gz.Close() + reader = gz + } + + rollup := NewRollup() + skipped, err := rollup.Consume(reader, date) + if err != nil { + return err + } + if skipped > 0 { + a.Logger.Warn("object had unparseable lines", "key", key, "skipped", skipped) + } + return a.Store.ApplyRollup(ctx, key, rollup) +} diff --git a/domains/platform/apis/stats/loop_test.go b/domains/platform/apis/stats/loop_test.go new file mode 100644 index 000000000..dbe00d2ec --- /dev/null +++ b/domains/platform/apis/stats/loop_test.go @@ -0,0 +1,145 @@ +package stats + +import ( + "bytes" + "compress/gzip" + "context" + "errors" + "io" + "log/slog" + "testing" +) + +type fakeObjects struct { + objects map[string][]byte + fail map[string]error +} + +func (f *fakeObjects) List(prefix string) ([]string, error) { + var keys []string + for k := range f.objects { + keys = append(keys, k) + } + return keys, nil +} + +func (f *fakeObjects) Get(key string) (io.ReadCloser, error) { + if err := f.fail[key]; err != nil { + return nil, err + } + return io.NopCloser(bytes.NewReader(f.objects[key])), nil +} + +type fakeApplier struct { + processed map[string]bool + applied map[string]*Rollup +} + +func newFakeApplier() *fakeApplier { + return &fakeApplier{processed: map[string]bool{}, applied: map[string]*Rollup{}} +} + +func (f *fakeApplier) Unprocessed(_ context.Context, keys []string) ([]string, error) { + var out []string + for _, k := range keys { + if !f.processed[k] { + out = append(out, k) + } + } + return out, nil +} + +func (f *fakeApplier) ApplyRollup(_ context.Context, key string, rollup *Rollup) error { + f.processed[key] = true + f.applied[key] = rollup + return nil +} + +func gzipped(t *testing.T, contents string) []byte { + t.Helper() + var buf bytes.Buffer + w := gzip.NewWriter(&buf) + if _, err := w.Write([]byte(contents)); err != nil { + t.Fatal(err) + } + if err := w.Close(); err != nil { + t.Fatal(err) + } + return buf.Bytes() +} + +const oneLine = `{"status":200,"request":{"host":"api.1d4.net","method":"GET","uri":"/x","headers":{}}}` + +func testAggregator(objects *fakeObjects, store *fakeApplier) *Aggregator { + return &Aggregator{ + Objects: objects, + Store: store, + Logger: slog.New(slog.NewTextHandler(io.Discard, nil)), + } +} + +func TestRunOnceAggregatesNewObjectsAndSkipsProcessedAndForeignKeys(t *testing.T) { + objects := &fakeObjects{objects: map[string][]byte{ + "logs/source=caddy/dt=2026-08-30/a.log.gz": gzipped(t, oneLine), + "logs/source=caddy/dt=2026-08-31/b.log.gz": gzipped(t, oneLine), + "logs/source=app/dt=2026-08-30/c.log.gz": gzipped(t, oneLine), + "unrelated/readme.txt": []byte("x"), + }} + store := newFakeApplier() + store.processed["logs/source=caddy/dt=2026-08-30/a.log.gz"] = true + + processed, err := testAggregator(objects, store).RunOnce(context.Background()) + + if err != nil || processed != 1 { + t.Fatalf("RunOnce = (%d, %v), want only the new caddy object", processed, err) + } + rollup := store.applied["logs/source=caddy/dt=2026-08-31/b.log.gz"] + if rollup == nil { + t.Fatal("the new object was not applied") + } + // The partition date keys the rollup — the object's own dt=, not today. + if got := rollup.Requests[RequestKey{"2026-08-31", "api.1d4.net", 200, "GET", AgentOther}]; got != 1 { + t.Errorf("rollup rows = %v", rollup.Requests) + } +} + +func TestRunOnceLeavesAFailingObjectForTheNextPassAndProcessesTheRest(t *testing.T) { + objects := &fakeObjects{ + objects: map[string][]byte{ + "logs/source=caddy/dt=2026-08-30/bad.log.gz": []byte("not gzip"), + "logs/source=caddy/dt=2026-08-30/good.log.gz": gzipped(t, oneLine), + }, + fail: map[string]error{}, + } + store := newFakeApplier() + + processed, err := testAggregator(objects, store).RunOnce(context.Background()) + + if err != nil { + t.Fatalf("a per-object failure must not fail the pass: %v", err) + } + if processed != 1 { + t.Errorf("processed = %d, want the good object", processed) + } + if store.processed["logs/source=caddy/dt=2026-08-30/bad.log.gz"] { + t.Error("the corrupt object was marked processed; it can never be retried or noticed") + } +} + +func TestRunOnceSurfacesAListingFailure(t *testing.T) { + objects := &fakeObjects{objects: map[string][]byte{}} + store := newFakeApplier() + agg := testAggregator(objects, store) + agg.Objects = failingLister{} + + if _, err := agg.RunOnce(context.Background()); err == nil { + t.Error("a listing failure is the whole pass failing; it must not read as quiet success") + } +} + +type failingLister struct{} + +func (failingLister) List(string) ([]string, error) { return nil, errors.New("s3 down") } +func (failingLister) Get(string) (io.ReadCloser, error) { + return nil, errors.New("unreachable") +} diff --git a/domains/platform/apis/stats/main/main.go b/domains/platform/apis/stats/main/main.go new file mode 100644 index 000000000..d7692c863 --- /dev/null +++ b/domains/platform/apis/stats/main/main.go @@ -0,0 +1,91 @@ +// stats serves the aggregates the log pipeline computes (#1460) and runs +// the aggregation loop that computes them: every AGGREGATE_INTERVAL it +// lists the shipped caddy logs in S3, rolls up the new objects, and +// applies them to the stats database in per-object transactions. +package main + +import ( + "context" + "log/slog" + "net/http" + "os" + "time" + + "github.com/muchq/moonbase/domains/platform/apis/stats" + "github.com/muchq/moonbase/domains/platform/libs/mucks" + "github.com/muchq/moonbase/domains/platform/libs/s3lite" +) + +func requireEnv(logger *slog.Logger, name string) string { + value := os.Getenv(name) + if value == "" { + logger.Error("required environment variable is not set", "name", name) + os.Exit(1) + } + return value +} + +func main() { + logger := slog.New(slog.NewJSONHandler(os.Stdout, nil)) + + interval := 15 * time.Minute + if raw := os.Getenv("AGGREGATE_INTERVAL"); raw != "" { + parsed, err := time.ParseDuration(raw) + if err != nil { + logger.Error("AGGREGATE_INTERVAL does not parse as a Go duration", "value", raw, "error", err) + os.Exit(1) + } + interval = parsed + } + port := os.Getenv("PORT") + if port == "" { + port = "8092" + } + + store, err := stats.NewStore(context.Background(), requireEnv(logger, "STATS_DB_URL")) + if err != nil { + logger.Error("cannot open the stats database", "error", err) + os.Exit(1) + } + defer store.Close() + + aggregator := &stats.Aggregator{ + Objects: &s3lite.S3{ + Bucket: requireEnv(logger, "S3_BUCKET"), + Region: requireEnv(logger, "S3_REGION"), + Creds: s3lite.Credentials{ + AccessKeyID: requireEnv(logger, "AWS_ACCESS_KEY_ID"), + SecretAccessKey: requireEnv(logger, "AWS_SECRET_ACCESS_KEY"), + }, + Client: &http.Client{Timeout: 5 * time.Minute}, + Now: time.Now, + }, + Store: store, + Logger: logger, + } + go func() { + ticker := time.NewTicker(interval) + defer ticker.Stop() + for { + processed, err := aggregator.RunOnce(context.Background()) + if err != nil { + logger.Error("aggregation pass failed", "error", err) + } else if processed > 0 { + logger.Info("aggregation pass complete", "objects", processed) + } + <-ticker.C + } + }() + + handlers := stats.NewHandlers(store, logger) + router := mucks.NewJsonMucks() + router.HandleFunc("GET /health", handlers.Health) + router.HandleFunc("GET /stats/v1/summary", handlers.GetSummary) + router.HandleFunc("GET /stats/v1/iili/top", handlers.GetTopSlugs) + + logger.Info("stats started", "port", port, "interval", interval.String()) + if err := http.ListenAndServe(":"+port, router); err != nil { + logger.Error("server exited", "error", err) + os.Exit(1) + } +} diff --git a/domains/platform/apis/stats/store.go b/domains/platform/apis/stats/store.go new file mode 100644 index 000000000..b2e76ec0d --- /dev/null +++ b/domains/platform/apis/stats/store.go @@ -0,0 +1,178 @@ +package stats + +import ( + "context" + "fmt" + + "github.com/jackc/pgx/v5" + "github.com/jackc/pgx/v5/pgxpool" +) + +// The stats schema, applied idempotently at boot — the same in-service +// pattern iili uses for its migrations. Aggregates only: the raw lines +// stay in S3, so a schema change is a re-aggregation, never data loss. +var schema = []string{ + `CREATE TABLE IF NOT EXISTS processed_log_objects ( + key text PRIMARY KEY, + processed_at timestamptz NOT NULL DEFAULT now() + )`, + `CREATE TABLE IF NOT EXISTS request_stats ( + dt date NOT NULL, + host text NOT NULL, + status int NOT NULL, + http_method text NOT NULL, + agent_class text NOT NULL, + requests bigint NOT NULL, + PRIMARY KEY (dt, host, status, http_method, agent_class) + )`, + `CREATE TABLE IF NOT EXISTS iili_slug_stats ( + dt date NOT NULL, + slug text NOT NULL, + status int NOT NULL, + requests bigint NOT NULL, + PRIMARY KEY (dt, slug, status) + )`, +} + +type Store struct { + pool *pgxpool.Pool +} + +func NewStore(ctx context.Context, databaseURL string) (*Store, error) { + pool, err := pgxpool.New(ctx, databaseURL) + if err != nil { + return nil, err + } + for _, ddl := range schema { + if _, err := pool.Exec(ctx, ddl); err != nil { + pool.Close() + return nil, fmt.Errorf("applying schema: %w", err) + } + } + return &Store{pool: pool}, nil +} + +func (s *Store) Close() { s.pool.Close() } + +// Unprocessed filters keys down to the ones no successful ApplyRollup has +// marked yet. +func (s *Store) Unprocessed(ctx context.Context, keys []string) ([]string, error) { + rows, err := s.pool.Query(ctx, + `SELECT key FROM processed_log_objects WHERE key = ANY($1)`, keys) + if err != nil { + return nil, err + } + seen := map[string]bool{} + var key string + if _, err := pgx.ForEachRow(rows, []any{&key}, func() error { + seen[key] = true + return nil + }); err != nil { + return nil, err + } + var out []string + for _, k := range keys { + if !seen[k] { + out = append(out, k) + } + } + return out, nil +} + +// ApplyRollup writes one object's aggregates and its processed marker in a +// single transaction: a crash between the two re-processes the object, and +// the marker's conflict arm makes a concurrent duplicate a no-op rather +// than a double count. +func (s *Store) ApplyRollup(ctx context.Context, key string, rollup *Rollup) error { + tx, err := s.pool.Begin(ctx) + if err != nil { + return err + } + defer tx.Rollback(ctx) + + tag, err := tx.Exec(ctx, + `INSERT INTO processed_log_objects (key) VALUES ($1) ON CONFLICT DO NOTHING`, key) + if err != nil { + return err + } + if tag.RowsAffected() == 0 { + return nil // someone else already applied this object + } + for k, count := range rollup.Requests { + if _, err := tx.Exec(ctx, + `INSERT INTO request_stats (dt, host, status, http_method, agent_class, requests) + VALUES ($1, $2, $3, $4, $5, $6) + ON CONFLICT (dt, host, status, http_method, agent_class) + DO UPDATE SET requests = request_stats.requests + EXCLUDED.requests`, + k.Date, k.Host, k.Status, k.Method, k.AgentClass, count); err != nil { + return err + } + } + for k, count := range rollup.Slugs { + if _, err := tx.Exec(ctx, + `INSERT INTO iili_slug_stats (dt, slug, status, requests) + VALUES ($1, $2, $3, $4) + ON CONFLICT (dt, slug, status) + DO UPDATE SET requests = iili_slug_stats.requests + EXCLUDED.requests`, + k.Date, k.Slug, k.Status, count); err != nil { + return err + } + } + return tx.Commit(ctx) +} + +type SummaryRow struct { + Date string `json:"date"` + Host string `json:"host"` + AgentClass string `json:"agent_class"` + Requests int64 `json:"requests"` + Errors int64 `json:"errors"` +} + +type SlugRow struct { + Slug string `json:"slug"` + Requests int64 `json:"requests"` +} + +func (s *Store) Summary(ctx context.Context, days int) ([]SummaryRow, error) { + rows, err := s.pool.Query(ctx, + `SELECT dt::text, host, agent_class, + SUM(requests) AS requests, + COALESCE(SUM(requests) FILTER (WHERE status >= 400), 0) AS errors + FROM request_stats + WHERE dt >= current_date - $1::int + GROUP BY dt, host, agent_class + ORDER BY dt DESC, host, agent_class`, days) + if err != nil { + return nil, err + } + var out []SummaryRow + var row SummaryRow + _, err = pgx.ForEachRow(rows, + []any{&row.Date, &row.Host, &row.AgentClass, &row.Requests, &row.Errors}, + func() error { + out = append(out, row) + return nil + }) + return out, err +} + +func (s *Store) TopSlugs(ctx context.Context, days, limit int) ([]SlugRow, error) { + rows, err := s.pool.Query(ctx, + `SELECT slug, SUM(requests) AS requests + FROM iili_slug_stats + WHERE dt >= current_date - $1::int AND status < 400 + GROUP BY slug + ORDER BY requests DESC, slug + LIMIT $2`, days, limit) + if err != nil { + return nil, err + } + var out []SlugRow + var row SlugRow + _, err = pgx.ForEachRow(rows, []any{&row.Slug, &row.Requests}, func() error { + out = append(out, row) + return nil + }) + return out, err +} diff --git a/domains/platform/apis/stats/store_test.go b/domains/platform/apis/stats/store_test.go new file mode 100644 index 000000000..d9d239f7a --- /dev/null +++ b/domains/platform/apis/stats/store_test.go @@ -0,0 +1,91 @@ +package stats + +import ( + "context" + "fmt" + "os" + "testing" + "time" +) + +// Real-database coverage for the store: schema, the processed-marker +// transaction, upsert accumulation, and both read queries. Gated the same +// way the repo's other Postgres suites are: without STATS_TEST_DB_URL this +// skips, and CI supplies the URL from its postgres service. +func testStore(t *testing.T) *Store { + t.Helper() + url := os.Getenv("STATS_TEST_DB_URL") + if url == "" { + t.Skip("STATS_TEST_DB_URL not set; skipping store integration test") + } + store, err := NewStore(context.Background(), url) + if err != nil { + t.Fatal(err) + } + t.Cleanup(store.Close) + return store +} + +func TestApplyRollupIsTransactionalIdempotentAndReadable(t *testing.T) { + store := testStore(t) + ctx := context.Background() + // Unique key per run: the database persists across test runs. + key := fmt.Sprintf("logs/source=caddy/dt=%s/test-%d.log.gz", + time.Now().UTC().Format("2006-01-02"), time.Now().UnixNano()) + date := time.Now().UTC().Format("2006-01-02") + + rollup := NewRollup() + rollup.Requests[RequestKey{date, "test-host.example", 200, "GET", AgentBrowser}] = 5 + rollup.Requests[RequestKey{date, "test-host.example", 403, "GET", AgentAIScraper}] = 2 + rollup.Slugs[SlugKey{date, "test-slug", 302}] = 3 + + if pending, err := store.Unprocessed(ctx, []string{key}); err != nil || len(pending) != 1 { + t.Fatalf("Unprocessed = (%v, %v), want the fresh key pending", pending, err) + } + if err := store.ApplyRollup(ctx, key, rollup); err != nil { + t.Fatal(err) + } + // Applying the same object twice must not double-count: the marker's + // conflict arm turns the second application into a no-op. + if err := store.ApplyRollup(ctx, key, rollup); err != nil { + t.Fatal(err) + } + if pending, err := store.Unprocessed(ctx, []string{key}); err != nil || len(pending) != 0 { + t.Fatalf("Unprocessed after apply = (%v, %v), want none", pending, err) + } + + summary, err := store.Summary(ctx, 2) + if err != nil { + t.Fatal(err) + } + var browser, scraper *SummaryRow + for i := range summary { + row := &summary[i] + if row.Host == "test-host.example" && row.AgentClass == AgentBrowser { + browser = row + } + if row.Host == "test-host.example" && row.AgentClass == AgentAIScraper { + scraper = row + } + } + if browser == nil || browser.Requests < 5 || browser.Errors != 0 { + t.Errorf("browser row = %+v", browser) + } + if scraper == nil || scraper.Requests < 2 || scraper.Errors < 2 { + t.Errorf("scraper row = %+v; 403s must count as errors", scraper) + } + + slugs, err := store.TopSlugs(ctx, 2, 100) + if err != nil { + t.Fatal(err) + } + found := false + for _, row := range slugs { + if row.Slug == "test-slug" && row.Requests >= 3 { + found = true + } + } + if !found { + t.Errorf("test-slug missing from top slugs: %v", slugs) + } +} diff --git a/domains/platform/apps/log_shipper/BUILD.bazel b/domains/platform/apps/log_shipper/BUILD.bazel index f80b36b3c..f15a84c58 100644 --- a/domains/platform/apps/log_shipper/BUILD.bazel +++ b/domains/platform/apps/log_shipper/BUILD.bazel @@ -4,9 +4,7 @@ load("//bazel/rules:oci.bzl", "linux_oci_go") go_library( name = "log_shipper_lib", srcs = [ - "s3.go", "shipper.go", - "sigv4.go", ], importpath = "github.com/muchq/moonbase/domains/platform/apps/log_shipper", visibility = ["//visibility:public"], @@ -16,9 +14,7 @@ go_test( name = "log_shipper_test", size = "small", srcs = [ - "s3_test.go", "shipper_test.go", - "sigv4_test.go", ], embed = [":log_shipper_lib"], ) @@ -27,7 +23,10 @@ go_binary( name = "log_shipper", srcs = ["main/main.go"], visibility = ["//visibility:public"], - deps = [":log_shipper_lib"], + deps = [ + ":log_shipper_lib", + "//domains/platform/libs/s3lite", + ], ) linux_oci_go(bin_name = "log_shipper") diff --git a/domains/platform/apps/log_shipper/README.md b/domains/platform/apps/log_shipper/README.md index d6772d0b7..5a71ff11e 100644 --- a/domains/platform/apps/log_shipper/README.md +++ b/domains/platform/apps/log_shipper/README.md @@ -37,7 +37,7 @@ and anything that is not a rolled log are never touched. | --- | --- | | `S3_BUCKET` | Destination bucket (required) | | `S3_REGION` | Bucket's region (required) | -| `AWS_ACCESS_KEY_ID` / `AWS_SECRET_ACCESS_KEY` | An IAM user whose policy is `s3:PutObject` on the bucket's `logs/*` prefix and nothing else (required) | +| `AWS_ACCESS_KEY_ID` / `AWS_SECRET_ACCESS_KEY` | The stats IAM user: `s3:PutObject` for this shipper, plus `s3:GetObject`/`s3:ListBucket` for the aggregator, all scoped to the bucket's `logs/*` prefix (required) | | `LOG_DIR` | Directory Caddy rolls into (`/var/log/caddy` in compose) | | `LOG_SOURCE` | Partition label, default `caddy` | | `SHIP_INTERVAL` | Go duration between passes, default `1h` | diff --git a/domains/platform/apps/log_shipper/main/main.go b/domains/platform/apps/log_shipper/main/main.go index d4107ada0..27ddf3328 100644 --- a/domains/platform/apps/log_shipper/main/main.go +++ b/domains/platform/apps/log_shipper/main/main.go @@ -14,6 +14,7 @@ import ( "time" shipper "github.com/muchq/moonbase/domains/platform/apps/log_shipper" + "github.com/muchq/moonbase/domains/platform/libs/s3lite" ) func requireEnv(logger *slog.Logger, name string) string { @@ -48,10 +49,10 @@ func main() { // Caddy's roller writes rolled files in place; two minutes of // quiet is the proxy for "nobody is still writing this". MinAge: 2 * time.Minute, - Uploader: &shipper.S3{ + Uploader: &s3lite.S3{ Bucket: requireEnv(logger, "S3_BUCKET"), Region: requireEnv(logger, "S3_REGION"), - Creds: shipper.Credentials{ + Creds: s3lite.Credentials{ AccessKeyID: requireEnv(logger, "AWS_ACCESS_KEY_ID"), SecretAccessKey: requireEnv(logger, "AWS_SECRET_ACCESS_KEY"), }, diff --git a/domains/platform/libs/s3lite/BUILD.bazel b/domains/platform/libs/s3lite/BUILD.bazel new file mode 100644 index 000000000..e1a8d9d01 --- /dev/null +++ b/domains/platform/libs/s3lite/BUILD.bazel @@ -0,0 +1,26 @@ +load("@io_bazel_rules_go//go:def.bzl", "go_library", "go_test") + +# A header-signed S3 client for exactly three operations — PutObject, +# GetObject, ListObjectsV2 — with SigV4 hand-rolled on the usual dep-light +# reasoning: the SDK is ~20 modules for four HMACs and some +# canonicalization. The derivation is pinned against AWS's published worked +# example in sigv4_test.go. +go_library( + name = "s3lite", + srcs = [ + "s3.go", + "sigv4.go", + ], + importpath = "github.com/muchq/moonbase/domains/platform/libs/s3lite", + visibility = ["//visibility:public"], +) + +go_test( + name = "s3lite_test", + size = "small", + srcs = [ + "s3_test.go", + "sigv4_test.go", + ], + embed = [":s3lite"], +) diff --git a/domains/platform/apps/log_shipper/s3.go b/domains/platform/libs/s3lite/s3.go similarity index 50% rename from domains/platform/apps/log_shipper/s3.go rename to domains/platform/libs/s3lite/s3.go index 1358926ac..68d98ae79 100644 --- a/domains/platform/apps/log_shipper/s3.go +++ b/domains/platform/libs/s3lite/s3.go @@ -1,8 +1,9 @@ -package log_shipper +package s3lite import ( "crypto/sha256" "encoding/hex" + "encoding/xml" "fmt" "io" "net/http" @@ -10,6 +11,9 @@ import ( "time" ) +// The SHA256 of an empty payload, which is what GETs sign. +const emptyPayloadHash = "e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855" + type Credentials struct { AccessKeyID string SecretAccessKey string @@ -70,7 +74,7 @@ func (s *S3) Put(key string, body io.ReadSeeker, size int64) error { req.Header.Set("x-amz-content-sha256", hashHex) req.Header.Set("Authorization", authorizationHeader( s.Creds.AccessKeyID, s.Creds.SecretAccessKey, when, s.Region, - http.MethodPut, path, host, hashHex, nil)) + http.MethodPut, path, "", host, hashHex, nil)) // Redirects are reported, never followed: Go's client would replay the // request against a host the signature does not cover, and the eventual @@ -100,3 +104,105 @@ func (s *S3) Put(key string, body io.ReadSeeker, size int64) error { } return nil } + +// urlParts resolves host, path and base URL for a key (or "" for the +// bucket root), mirroring Put's virtual-hosted/endpoint split. +func (s *S3) urlParts(key string) (requestURL, host, path string, err error) { + if s.Endpoint == "" { + host = s.Bucket + ".s3." + s.Region + ".amazonaws.com" + path = "/" + key + return "https://" + host + path, host, path, nil + } + parsed, err := url.Parse(s.Endpoint) + if err != nil { + return "", "", "", err + } + host = parsed.Host + path = "/" + s.Bucket + if key != "" { + path += "/" + key + } + return s.Endpoint + path, host, path, nil +} + +func (s *S3) signedGet(key string, params map[string]string) (*http.Response, error) { + requestURL, host, path, err := s.urlParts(key) + if err != nil { + return nil, err + } + query := canonicalQuery(params) + if query != "" { + requestURL += "?" + query + } + when := s.Now().UTC() + req, err := http.NewRequest(http.MethodGet, requestURL, nil) + if err != nil { + return nil, err + } + req.Header.Set("x-amz-date", when.Format(amzDateFormat)) + req.Header.Set("x-amz-content-sha256", emptyPayloadHash) + req.Header.Set("Authorization", authorizationHeader( + s.Creds.AccessKeyID, s.Creds.SecretAccessKey, when, s.Region, + http.MethodGet, path, query, host, emptyPayloadHash, nil)) + + client := *s.Client + client.CheckRedirect = func(*http.Request, []*http.Request) error { + return http.ErrUseLastResponse + } + resp, err := client.Do(req) + if err != nil { + return nil, err + } + if resp.StatusCode != http.StatusOK { + reason, _ := io.ReadAll(io.LimitReader(resp.Body, 2048)) + resp.Body.Close() + return nil, fmt.Errorf("s3 get %s: HTTP %d: %s", key, resp.StatusCode, reason) + } + return resp, nil +} + +// Get streams one object; the caller closes the reader. +func (s *S3) Get(key string) (io.ReadCloser, error) { + resp, err := s.signedGet(key, nil) + if err != nil { + return nil, err + } + return resp.Body, nil +} + +type listResult struct { + IsTruncated bool `xml:"IsTruncated"` + Contents []struct { + Key string `xml:"Key"` + } `xml:"Contents"` +} + +// List returns every key under prefix, in order, paginating with +// start-after until S3 reports the listing complete. +func (s *S3) List(prefix string) ([]string, error) { + var keys []string + after := "" + for { + params := map[string]string{"list-type": "2", "prefix": prefix} + if after != "" { + params["start-after"] = after + } + resp, err := s.signedGet("", params) + if err != nil { + return nil, err + } + var page listResult + err = xml.NewDecoder(resp.Body).Decode(&page) + resp.Body.Close() + if err != nil { + return nil, fmt.Errorf("s3 list %s: unparseable response: %w", prefix, err) + } + for _, entry := range page.Contents { + keys = append(keys, entry.Key) + } + if !page.IsTruncated || len(page.Contents) == 0 { + return keys, nil + } + after = keys[len(keys)-1] + } +} diff --git a/domains/platform/apps/log_shipper/s3_test.go b/domains/platform/libs/s3lite/s3_test.go similarity index 72% rename from domains/platform/apps/log_shipper/s3_test.go rename to domains/platform/libs/s3lite/s3_test.go index 9373f778b..465a30881 100644 --- a/domains/platform/apps/log_shipper/s3_test.go +++ b/domains/platform/libs/s3lite/s3_test.go @@ -1,10 +1,11 @@ -package log_shipper +package s3lite import ( "bytes" "io" "net/http" "net/http/httptest" + "slices" "strings" "testing" "time" @@ -85,7 +86,7 @@ func TestTheSignatureCoversTheRequestActuallySent(t *testing.T) { recomputed := authorizationHeader( "AKID", "secret", signingClock().UTC(), "us-east-1", - got.Method, got.URL.Path, got.Host, got.Header.Get("x-amz-content-sha256"), nil) + got.Method, got.URL.Path, got.URL.RawQuery, got.Host, got.Header.Get("x-amz-content-sha256"), nil) if auth := got.Header.Get("Authorization"); auth != recomputed { t.Errorf("Authorization does not cover the request as sent:\nsent: %s\nrecomputed: %s", auth, recomputed) @@ -121,7 +122,7 @@ func TestProductionUsesTheVirtualHostedURLAndSignsIt(t *testing.T) { } recomputed := authorizationHeader( "AKID", "secret", signingClock().UTC(), "us-east-1", - http.MethodPut, got.URL.Path, got.URL.Host, got.Header.Get("x-amz-content-sha256"), nil) + http.MethodPut, got.URL.Path, "", got.URL.Host, got.Header.Get("x-amz-content-sha256"), nil) if auth := got.Header.Get("Authorization"); auth != recomputed { t.Errorf("Authorization does not cover the virtual-hosted request:\nsent: %s\nrecomputed: %s", auth, recomputed) @@ -177,3 +178,66 @@ func TestARegionRedirectIsReportedWithItsLocationNotFollowed(t *testing.T) { } } } + +func TestGetStreamsTheObjectAndSignsTheRequest(t *testing.T) { + var got *http.Request + s3 := testS3(t, func(w http.ResponseWriter, r *http.Request) { + got = r + w.Write([]byte("object bytes")) + }) + + body, err := s3.Get("logs/source=caddy/dt=2026-08-31/x.log.gz") + if err != nil { + t.Fatal(err) + } + defer body.Close() + contents, _ := io.ReadAll(body) + if string(contents) != "object bytes" { + t.Errorf("body = %q", contents) + } + recomputed := authorizationHeader( + "AKID", "secret", signingClock().UTC(), "us-east-1", + got.Method, got.URL.Path, got.URL.RawQuery, got.Host, + got.Header.Get("x-amz-content-sha256"), nil) + if auth := got.Header.Get("Authorization"); auth != recomputed { + t.Errorf("Authorization does not cover the GET as sent:\nsent: %s\nrecomputed: %s", + auth, recomputed) + } +} + +func TestListPaginatesWithStartAfterAndSignsTheQuery(t *testing.T) { + var queries []string + var auths []bool + s3 := testS3(t, func(w http.ResponseWriter, r *http.Request) { + queries = append(queries, r.URL.RawQuery) + recomputed := authorizationHeader( + "AKID", "secret", signingClock().UTC(), "us-east-1", + r.Method, r.URL.Path, r.URL.RawQuery, r.Host, + r.Header.Get("x-amz-content-sha256"), nil) + auths = append(auths, r.Header.Get("Authorization") == recomputed) + if len(queries) == 1 { + w.Write([]byte(`true` + + `logs/alogs/b` + + ``)) + return + } + w.Write([]byte(`false` + + `logs/c`)) + }) + + keys, err := s3.List("logs/") + if err != nil { + t.Fatal(err) + } + if want := []string{"logs/a", "logs/b", "logs/c"}; !slices.Equal(keys, want) { + t.Errorf("keys = %v, want %v", keys, want) + } + if len(queries) != 2 || !strings.Contains(queries[1], "start-after=logs%2Fb") { + t.Errorf("pagination queries = %v, want a start-after continuation", queries) + } + for i, ok := range auths { + if !ok { + t.Errorf("request %d's Authorization does not cover the query it sent", i) + } + } +} diff --git a/domains/platform/apps/log_shipper/sigv4.go b/domains/platform/libs/s3lite/sigv4.go similarity index 73% rename from domains/platform/apps/log_shipper/sigv4.go rename to domains/platform/libs/s3lite/sigv4.go index f4acedcf2..77c3cc152 100644 --- a/domains/platform/apps/log_shipper/sigv4.go +++ b/domains/platform/libs/s3lite/sigv4.go @@ -5,7 +5,7 @@ // request shape. The derivation is pinned against // AWS's published worked example in sigv4_test.go, intermediate values // included, so any drift names the stage that drifted. -package log_shipper +package s3lite import ( "crypto/hmac" @@ -45,7 +45,35 @@ func canonicalURI(path string) string { return b.String() } -func canonicalRequest(method, path, host, payloadHash string, when time.Time, extra map[string]string) (string, string) { +// canonicalQuery renders query parameters the way S3's signer expects: +// each name and value URI-encoded with the strict rules, pairs sorted by +// encoded name. An empty map is the empty string. +func canonicalQuery(params map[string]string) string { + encoded := make([]string, 0, len(params)) + for name, value := range params { + encoded = append(encoded, uriEncode(name)+"="+uriEncode(value)) + } + sort.Strings(encoded) + return strings.Join(encoded, "&") +} + +// uriEncode is AWS's own encoding: unreserved characters only, uppercase +// hex, space as %20 — Go's url.QueryEscape differs on '+' and '~'. +func uriEncode(value string) string { + var b strings.Builder + for _, c := range []byte(value) { + switch { + case c >= 'A' && c <= 'Z', c >= 'a' && c <= 'z', c >= '0' && c <= '9', + c == '-', c == '.', c == '_', c == '~': + b.WriteByte(c) + default: + fmt.Fprintf(&b, "%%%02X", c) + } + } + return b.String() +} + +func canonicalRequest(method, path, query, host, payloadHash string, when time.Time, extra map[string]string) (string, string) { headers := map[string]string{ "host": host, "x-amz-content-sha256": payloadHash, @@ -64,7 +92,7 @@ func canonicalRequest(method, path, host, payloadHash string, when time.Time, ex var b strings.Builder b.WriteString(method + "\n") b.WriteString(canonicalURI(path) + "\n") - b.WriteString("\n") // no query string on a plain PUT + b.WriteString(query + "\n") for _, name := range names { b.WriteString(name + ":" + headers[name] + "\n") } @@ -101,8 +129,8 @@ func signature(secretKey string, when time.Time, region, toSign string) string { } func authorizationHeader(accessKey, secretKey string, when time.Time, region, - method, path, host, payloadHash string, extra map[string]string) string { - canonical, signedHeaders := canonicalRequest(method, path, host, payloadHash, when, extra) + method, path, query, host, payloadHash string, extra map[string]string) string { + canonical, signedHeaders := canonicalRequest(method, path, query, host, payloadHash, when, extra) sig := signature(secretKey, when, region, stringToSign(when, region, canonical)) return "AWS4-HMAC-SHA256 " + "Credential=" + accessKey + "/" + credentialScope(when, region) + "," + diff --git a/domains/platform/apps/log_shipper/sigv4_test.go b/domains/platform/libs/s3lite/sigv4_test.go similarity index 85% rename from domains/platform/apps/log_shipper/sigv4_test.go rename to domains/platform/libs/s3lite/sigv4_test.go index 916d27423..441e91abc 100644 --- a/domains/platform/apps/log_shipper/sigv4_test.go +++ b/domains/platform/libs/s3lite/sigv4_test.go @@ -1,4 +1,4 @@ -package log_shipper +package s3lite import ( "strings" @@ -14,8 +14,6 @@ import ( const ( exampleAccessKey = "AKIAIOSFODNN7EXAMPLE" exampleSecretKey = "wJalrXUtnFEMI/K7MDENG/bPxRfiCYEXAMPLEKEY" - // SHA256 of the empty payload. - emptyPayloadHash = "e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855" ) var exampleTime = time.Date(2013, 5, 24, 0, 0, 0, 0, time.UTC) @@ -69,7 +67,7 @@ func TestCanonicalURIEncodesEqualsButNotSlashes(t *testing.T) { func TestAuthorizationHeaderCarriesScopeSignedHeadersAndSignature(t *testing.T) { header := authorizationHeader( exampleAccessKey, exampleSecretKey, exampleTime, "us-east-1", - "GET", "/test.txt", "examplebucket.s3.amazonaws.com", emptyPayloadHash, + "GET", "/test.txt", "", "examplebucket.s3.amazonaws.com", emptyPayloadHash, map[string]string{"range": "bytes=0-9"}) want := "AWS4-HMAC-SHA256 " + @@ -88,7 +86,7 @@ func TestAuthorizationHeaderCarriesScopeSignedHeadersAndSignature(t *testing.T) // header lands lowercased, trimmed, and in sorted order. func TestCanonicalRequestCarriesTheMethodAndExtraHeaders(t *testing.T) { canonical, signedHeaders := canonicalRequest( - "PUT", "/k", "bucket.s3.us-east-1.amazonaws.com", emptyPayloadHash, + "PUT", "/k", "", "bucket.s3.us-east-1.amazonaws.com", emptyPayloadHash, exampleTime, map[string]string{"X-Amz-Storage-Class": " REDUCED_REDUNDANCY "}) if !strings.HasPrefix(canonical, "PUT\n") { @@ -101,3 +99,18 @@ func TestCanonicalRequestCarriesTheMethodAndExtraHeaders(t *testing.T) { t.Errorf("extra header is not lowercased and trimmed in the canonical form:\n%s", canonical) } } + +// Query parameters are sorted by encoded name and use AWS's strict +// encoding — Go's QueryEscape would emit '+' for space and escape '~', +// both SignatureDoesNotMatch on the wire. +func TestCanonicalQuerySortsAndStrictlyEncodes(t *testing.T) { + got := canonicalQuery(map[string]string{ + "prefix": "logs/source=caddy/", + "list-type": "2", + "start-after": "logs/a b~c", + }) + want := "list-type=2&prefix=logs%2Fsource%3Dcaddy%2F&start-after=logs%2Fa%20b~c" + if got != want { + t.Errorf("canonicalQuery = %s, want %s", got, want) + } +} diff --git a/go.mod b/go.mod index db8e8216c..1999b2071 100644 --- a/go.mod +++ b/go.mod @@ -6,6 +6,7 @@ require ( github.com/golang-jwt/jwt/v5 v5.3.1 github.com/google/uuid v1.6.0 github.com/gorilla/websocket v1.5.3 + github.com/jackc/pgx/v5 v5.10.0 github.com/prometheus/client_golang v1.23.2 github.com/prometheus/common v0.69.0 github.com/stretchr/testify v1.11.1 @@ -15,6 +16,9 @@ require ( require ( github.com/davecgh/go-spew v1.1.1 // indirect + github.com/jackc/pgpassfile v1.0.0 // indirect + github.com/jackc/pgservicefile v0.0.0-20240606120523-5a60cdf6a761 // indirect + github.com/jackc/puddle/v2 v2.2.2 // indirect github.com/json-iterator/go v1.1.12 // indirect github.com/kr/text v0.2.0 // indirect github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd // indirect @@ -22,6 +26,7 @@ require ( github.com/pmezard/go-difflib v1.0.0 // indirect github.com/prometheus/client_model v0.6.2 // indirect golang.org/x/net v0.55.0 // indirect + golang.org/x/sync v0.20.0 // indirect golang.org/x/sys v0.45.0 // indirect golang.org/x/text v0.37.0 // indirect google.golang.org/genproto/googleapis/rpc v0.0.0-20260414002931-afd174a4e478 // indirect diff --git a/go.sum b/go.sum index 9c1e6849c..2d71e563c 100644 --- a/go.sum +++ b/go.sum @@ -21,6 +21,14 @@ github.com/google/uuid v1.6.0 h1:NIvaJDMOsjHA8n1jAhLSgzrAzy1Hgr+hNrb57e+94F0= github.com/google/uuid v1.6.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo= github.com/gorilla/websocket v1.5.3 h1:saDtZ6Pbx/0u+bgYQ3q96pZgCzfhKXGPqt7kZ72aNNg= github.com/gorilla/websocket v1.5.3/go.mod h1:YR8l580nyteQvAITg2hZ9XVh4b55+EU/adAjf1fMHhE= +github.com/jackc/pgpassfile v1.0.0 h1:/6Hmqy13Ss2zCq62VdNG8tM1wchn8zjSGOBJ6icpsIM= +github.com/jackc/pgpassfile v1.0.0/go.mod h1:CEx0iS5ambNFdcRtxPj5JhEz+xB6uRky5eyVu/W2HEg= +github.com/jackc/pgservicefile v0.0.0-20240606120523-5a60cdf6a761 h1:iCEnooe7UlwOQYpKFhBabPMi4aNAfoODPEFNiAnClxo= +github.com/jackc/pgservicefile v0.0.0-20240606120523-5a60cdf6a761/go.mod h1:5TJZWKEWniPve33vlWYSoGYefn3gLQRzjfDlhSJ9ZKM= +github.com/jackc/pgx/v5 v5.10.0 h1:VhSvgU2jSli8o3AqIEOTJr7rZwAEUVo4E4XhR94Zfr0= +github.com/jackc/pgx/v5 v5.10.0/go.mod h1:mal1tBGAFfLHvZzaYh77YS/eC6IX9OWbRV1QIIM0Jn4= +github.com/jackc/puddle/v2 v2.2.2 h1:PR8nw+E/1w0GLuRFSmiioY6UooMp6KJv0/61nB7icHo= +github.com/jackc/puddle/v2 v2.2.2/go.mod h1:vriiEXHvEE654aYKXXjOvZM39qJ0q+azkZFrfEOc3H4= github.com/jpillora/backoff v1.0.0 h1:uvFg412JmmHBHw7iwprIxkPMI+sGQ4kzOWsMeHnm2EA= github.com/jpillora/backoff v1.0.0/go.mod h1:J/6gKK9jxlEcS3zixgDgUAsiuZ7yrSoa/FX5e0EB2j4= github.com/json-iterator/go v1.1.12 h1:PV8peI4a0ysnczrg+LtxykD8LfKY9ML6u2jnxaEnrnM= @@ -52,6 +60,7 @@ github.com/rogpeppe/go-internal v1.10.0 h1:TMyTOH3F/DB16zRVcYyreMH6GnZZrwQVAoYjR github.com/rogpeppe/go-internal v1.10.0/go.mod h1:UQnix2H7Ngw/k4C5ijL5+65zddjncjaFoBhdsK/akog= github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI= +github.com/stretchr/testify v1.7.0/go.mod h1:6Fq8oRcR53rry900zMqJjRRixrwX3KX962/h/Wwjteg= github.com/stretchr/testify v1.11.1 h1:7s2iGBzp5EwR7/aIZr8ao5+dra3wiQyKjjFuvgVKu7U= github.com/stretchr/testify v1.11.1/go.mod h1:wZwfW3scLgRK+23gO65QZefKpKQRnfz6sD981Nm4B6U= go.opentelemetry.io/auto/sdk v1.2.1 h1:jXsnJ4Lmnqd11kwkBV2LgLoFMZKizbCi5fNZ/ipaZ64= @@ -72,6 +81,8 @@ golang.org/x/net v0.55.0 h1:bcvxaJn3e1U6InsFWt1JUq1aSjnRxLzT2rtD2KfkDF8= golang.org/x/net v0.55.0/go.mod h1:L5U2KuzuOe1lY7Z+aWVIKK6qEeJXnXV9yzGA+WCHJww= golang.org/x/oauth2 v0.36.0 h1:peZ/1z27fi9hUOFCAZaHyrpWG5lwe0RJEEEeH0ThlIs= golang.org/x/oauth2 v0.36.0/go.mod h1:YDBUJMTkDnJS+A4BP4eZBjCqtokkg1hODuPjwiGPO7Q= +golang.org/x/sync v0.20.0 h1:e0PTpb7pjO8GAtTs2dQ6jYa5BWYlMuX047Dco/pItO4= +golang.org/x/sync v0.20.0/go.mod h1:9xrNwdLfx4jkKbNva9FpL6vEN7evnE43NNNJQ2LF3+0= golang.org/x/sys v0.45.0 h1:dO4czNzziLiiXplLQgBCEpCvXQ3dnkn0SdaZSYdQ+FY= golang.org/x/sys v0.45.0/go.mod h1:4GL1E5IUh+htKOUEOaiffhrAeqysfVGipDYzABqnCmw= golang.org/x/text v0.37.0 h1:Cqjiwd9eSg8e0QAkyCaQTNHFIIzWtidPahFWR83rTrc= @@ -87,5 +98,6 @@ google.golang.org/protobuf v1.36.11/go.mod h1:HTf+CrKn2C3g5S8VImy6tdcUvCska2kB7j gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c h1:Hei/4ADfdWqJk1ZMxUNpqntNwaWcugrBjAiHlqqRiVk= gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c/go.mod h1:JHkPIbrfpd72SG/EVd6muEfDQjcINNoR0C8j2r3qZ4Q= +gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA= gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= From 036904afc3f2830bb608996920107003485bd712 Mon Sep 17 00:00:00 2001 From: Andy Aylward Date: Mon, 31 Aug 2026 22:30:15 -0400 Subject: [PATCH 09/10] deploy: wire the stats pair behind the stats profile MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit stats_db_init provisions the role and database the way golf_hub's init does; the stats service joins the same profile as log_shipper — both halves need the S3 credentials in ~/.env, so a default up -d starts neither. Caddy routes GET api.muchq.com/stats/v1/* to it, pinned in the public-routes guard, GET-only on purpose. --- deploy/consolidated/Caddyfile | 7 +++ deploy/consolidated/compose.yaml | 62 +++++++++++++++++++++++ deploy/consolidated/deploy_config_test.go | 19 +++++++ 3 files changed, 88 insertions(+) diff --git a/deploy/consolidated/Caddyfile b/deploy/consolidated/Caddyfile index 660e8f1de..fc5b21bbc 100644 --- a/deploy/consolidated/Caddyfile +++ b/deploy/consolidated/Caddyfile @@ -59,6 +59,11 @@ api.muchq.com { path /v2/analyze } + @get_stats { + method GET + path /stats/v1/* + } + @post_iili_shorten { method POST path /iili/v1/shorten @@ -157,6 +162,8 @@ api.muchq.com { # Same pattern (#1359): iili serves /iili/v1/* unrewritten. reverse_proxy @post_iili_shorten iili:8091 + # stats (#1460): read-only aggregates, unrewritten like the rest. + reverse_proxy @get_stats stats:8092 reverse_proxy @get_iili_redirect iili:8091 log { diff --git a/deploy/consolidated/compose.yaml b/deploy/consolidated/compose.yaml index 97914bf7d..07b7dcbac 100644 --- a/deploy/consolidated/compose.yaml +++ b/deploy/consolidated/compose.yaml @@ -615,6 +615,68 @@ services: cpus: '0.25' memory: 128M + stats_db_init: + image: postgres:18 + restart: "no" + logging: *default-logging + profiles: + - stats + environment: + PGHOST: shared_postgres + PGUSER: one_d4 + PGDATABASE: one_d4 + PGPASSWORD: ${ONE_D4_DB_PASSWORD} + STATS_DB_PASSWORD: ${STATS_DB_PASSWORD} + entrypoint: ["/bin/bash", "-ec"] + command: + - | + psql -v ON_ERROR_STOP=1 -tAc "SELECT 1 FROM pg_roles WHERE rolname = 'stats'" | grep -q 1 \ + || psql -v ON_ERROR_STOP=1 -c "CREATE ROLE stats LOGIN" + psql -v ON_ERROR_STOP=1 -c "ALTER ROLE stats WITH LOGIN PASSWORD '$${STATS_DB_PASSWORD}'" + psql -v ON_ERROR_STOP=1 -tAc "SELECT 1 FROM pg_database WHERE datname = 'stats'" | grep -q 1 \ + || psql -v ON_ERROR_STOP=1 -c "CREATE DATABASE stats OWNER stats" + networks: + - app_network + depends_on: + shared_postgres: + condition: service_healthy + + stats: + image: ghcr.io/muchq/stats:${STATS_SHA:-${DEPLOY_SHA:-latest}} + labels: + com.muchq.description: "Log-derived stats aggregator and API (Go)" + restart: always + logging: *default-logging + # Same profile as log_shipper: both halves of the pipeline need the + # stats S3 credentials in ~/.env, so neither starts on a default up -d. + profiles: + - stats + environment: + - STATS_DB_URL=postgresql://stats:${STATS_DB_PASSWORD}@shared_postgres:5432/stats + - AWS_ACCESS_KEY_ID=${STATS_AWS_ACCESS_KEY_ID} + - AWS_SECRET_ACCESS_KEY=${STATS_AWS_SECRET_ACCESS_KEY} + - S3_BUCKET=${STATS_S3_BUCKET} + - S3_REGION=${STATS_S3_REGION:-us-east-1} + - PORT=8092 + networks: + - app_network + depends_on: + shared_postgres: + condition: service_healthy + stats_db_init: + condition: service_completed_successfully + healthcheck: + # Steady /health probe (#1307); see golf_hub's for the full rationale. + test: ["CMD", "timeout", "4", "bash", "-c", 'exec 3<>/dev/tcp/127.0.0.1/8092 && printf "GET /health HTTP/1.0\r\n\r\n" >&3 && head -1 <&3 | grep -q " 200"'] + interval: 30s + timeout: 5s + retries: 3 + deploy: + resources: + limits: + cpus: '0.25' + memory: 256M + forgejo: image: codeberg.org/forgejo/forgejo:16 restart: always diff --git a/deploy/consolidated/deploy_config_test.go b/deploy/consolidated/deploy_config_test.go index a7c6b7be0..5bca24283 100644 --- a/deploy/consolidated/deploy_config_test.go +++ b/deploy/consolidated/deploy_config_test.go @@ -1025,6 +1025,8 @@ var publicRoutes = []struct { // iili (#1359): the redirect matcher is the product. {"@post_iili_shorten", []string{"method POST", "path /iili/v1/shorten"}, "iili:8091"}, {"@get_iili_redirect", []string{"method GET", "path /iili/v1/r/*"}, "iili:8091"}, + // stats (#1460): read-only aggregates, GET-only on purpose. + {"@get_stats", []string{"method GET", "path /stats/v1/*"}, "stats:8092"}, } func TestPublicRoutesAreDeliberatelyExact(t *testing.T) { @@ -2033,3 +2035,20 @@ func TestLogShipperReadsTheCaddyLogMountAndIsProfileGated(t *testing.T) { "start it with no S3 credentials and it would crash-loop. Block was:\n%s", block) } } + +// The stats pair is profile-gated together: the aggregator needs the same +// S3 credentials the shipper does, so a default `up -d` must start +// neither the service nor its db-init — half the pair running is a +// crash-loop or a database nothing writes to. +func TestTheStatsPairIsProfileGatedTogether(t *testing.T) { + for _, service := range []string{"stats", "stats_db_init"} { + block := serviceBlock(t, "compose.yaml", service) + if !strings.Contains(block, "profiles:") { + t.Errorf("%s is not profile-gated; a default `up -d` starts it without "+ + "S3 credentials (#1460). Block was:\n%s", service, block) + } + } + if !strings.Contains(serviceBlock(t, "compose.yaml", "stats"), "postgresql://stats:") { + t.Errorf("stats names no stats database URL; the aggregates have nowhere to land") + } +} From 42e28b968df95f2c46594c01197ed4cd26d625b3 Mon Sep 17 00:00:00 2001 From: Andy Aylward Date: Mon, 31 Aug 2026 22:48:05 -0400 Subject: [PATCH 10/10] deploy docs: record the stats profile opt-in COMPOSE_PROFILES=stats in ~/.env is what keeps the stats trio inside every unflagged deploy; a one-off --profile up starts them once and then silently stops being updated. Written down with the other ~/.env variables so a host rebuild finds it. --- deploy/consolidated/README.md | 17 +++++++++++++++++ domains/platform/apps/log_shipper/README.md | 8 ++++++-- 2 files changed, 23 insertions(+), 2 deletions(-) diff --git a/deploy/consolidated/README.md b/deploy/consolidated/README.md index dc731f37c..7baba6a9e 100644 --- a/deploy/consolidated/README.md +++ b/deploy/consolidated/README.md @@ -208,6 +208,23 @@ a role and database holding live rows is an operation, not a rename. Keep it URL `@ / ? # %` or quotes): it rides in a libpq URL and a single-quoted SQL literal. Compose refuses to start the service if it's unset. +### The stats profile + +`log_shipper`, `stats` and `stats_db_init` sit behind the `stats` compose profile: they fail +fast without the `STATS_*` credentials, so a fresh host must not start them by default. This +host opts in permanently with one more `~/.env` line: + +``` +COMPOSE_PROFILES=stats +``` + +deploy.sh runs compose in `~`, where compose reads that file, so every normal deploy includes +the trio. Alongside it live `STATS_AWS_ACCESS_KEY_ID`, `STATS_AWS_SECRET_ACCESS_KEY`, +`STATS_S3_BUCKET`, `STATS_S3_REGION`, and `STATS_DB_PASSWORD` (same URL-safe rules as the +other database passwords: it rides in a libpq URL and a single-quoted SQL literal). Without +the `COMPOSE_PROFILES` line the containers keep running after a deploy but silently stop +being updated — compose ignores profile-gated services on an unflagged `up -d`. + Keeping a URL here rather than in a host file is what makes the hostname visible to this repo: `deploy_config_test.go` fails if a database host is not a Postgres service this file publishes, so the instance can be renamed (#1225) by editing one file instead of by keeping the old name diff --git a/domains/platform/apps/log_shipper/README.md b/domains/platform/apps/log_shipper/README.md index 5a71ff11e..6234c2d2c 100644 --- a/domains/platform/apps/log_shipper/README.md +++ b/domains/platform/apps/log_shipper/README.md @@ -50,9 +50,13 @@ design. Once the bucket and the put-only IAM user exist and `STATS_AWS_ACCESS_KEY_ID`, `STATS_AWS_SECRET_ACCESS_KEY`, `STATS_S3_BUCKET` and `STATS_S3_REGION` are in `~/.env` on the host: -```bash -docker compose --profile stats up -d ``` +COMPOSE_PROFILES=stats +``` + +in `~/.env` (the permanent opt-in — deploy.sh's unflagged `up -d` then +includes the profile on every deploy; a one-off `docker compose --profile +stats up -d` works but stops being updated by later deploys). The mount is read-write on purpose — deletion after upload is what keeps the host disk bounded once shipping owns retention. Caddy's `roll_keep`