diff --git a/README.md b/README.md index 42667fe46152dd0f574ffd501130ad100e5319da..2066b25c35f75e57bbe5b99ac80217772ec90452 100644 --- a/README.md +++ b/README.md @@ -170,6 +170,24 @@ public keys. Store it as a secret. The dump is for inspection and comparison; it is not a restore format. +## Observability + +The `serve` command writes one JSON object per line to standard error. HTTP +request events contain a request ID, method, status, and duration. SSH +connection, authentication, and command events contain an operation ID. Server +lifecycle events record start, readiness, and shutdown. + +Logs do not contain URLs, request headers, request bodies, public keys, or +client addresses. Thus, they do not contain authorization headers, cookies, +feed tokens, recovery credentials, login challenges, raw signatures, or SSH +private keys. Audit history continues to record durable security and mutation +events in SQLite. + +`GET /metrics` returns six fixed process counters as plain text. The counters +cover HTTP requests, HTTP errors, active HTTP requests, SSH connections, +rejected SSH authentication, and SSH operations. The endpoint has no labels +and does not contain repository, account, path, or client data. + An authenticated account can create a repository with SSH: ```text @@ -634,3 +652,16 @@ limits. Read the [limits and abuse resistance architectural decision record](docs/adr/0031-limits-and-abuse-resistance.md) for the limit values and failure behavior. + +## Milestone 6.5 gate + +Install stock Git and OpenSSH. Then, run the observability gate: + +```text +./scripts/check-m6-5 +``` + +This command tests structured HTTP, SSH, and lifecycle logs, request and +operation IDs, fixed metrics, audit records, and secret redaction. Read the +[observability architectural decision record](docs/adr/0032-observability.md) +for the event and redaction contracts. diff --git a/docs/adr/0032-observability.md b/docs/adr/0032-observability.md new file mode 100644 index 0000000000000000000000000000000000000000..e39a07c50de71aebf9c9d53683abbb9e09f063df --- /dev/null +++ b/docs/adr/0032-observability.md @@ -1,0 +1,89 @@ +# Architectural decision record 0032: observability + +Status: Accepted + +Date: 2026-07-23 + +## Context + +An operator must identify slow requests, rejected access, active work, and +process lifecycle changes. Audit history supplies durable security and mutation +records, but it is not a process log or a metrics interface. + +Observability data must not copy credentials or unbounded user values. URLs can +contain feed tokens. Headers can contain authorization values, cookies, and +signatures. Request bodies can contain recovery credentials, login challenges, +and raw signatures. + +## Decision + +Write structured JSON Lines events to standard error. Each event has a +millisecond Unix timestamp, a fixed level, and a fixed event name. An HTTP event +also has a random 128-bit request ID, normalized method, status, and duration in +milliseconds. The response includes the request ID in `X-Request-ID`. + +An SSH connection gets a random 128-bit connection operation ID. Authentication +events use this ID. Each SSH exec request gets a new random 128-bit operation +ID. The server records that an operation started, but it does not record the +command, repository, username, public key, fingerprint, or client address. + +Record lifecycle events for process start, listener readiness, shutdown start, +and shutdown completion. Keep the existing SQLite audit history for durable +account, login, repository, collaborator, issue, pull-request, and ref +mutations. Audit records keep their existing correlation IDs. + +Add `GET /metrics`. It returns these fixed counters without labels: + +- total HTTP requests; +- total HTTP responses with status 400 or higher; +- active HTTP requests; +- total SSH connections; +- total rejected SSH authentication attempts; and +- total SSH exec operations. + +The metrics response uses `no-store`. It does not contain account, repository, +path, ref, client, or credential data. Fixed counter names prevent unbounded +metric dimensions. + +The logging interface accepts only fixed event, outcome, and HTTP method values +plus generated IDs, numeric status values, and numeric durations. It does not +accept a URL, header, body, key, username, error string, or network address. +This API boundary supplies redaction instead of a list that can miss a new +secret field. + +## Failure and threat cases + +A feed token in a URL must not enter a log. HTTP logs do not contain the URL or +query. Authorization headers, cookies, recovery credentials, login challenges, +raw signatures, and SSH keys must not enter a log. The logger does not receive +these values. + +Metrics can reveal the amount of process activity. They cannot identify a user +or repository. An operator that does not want public activity counters must +restrict `/metrics` in the reverse proxy. + +Log output can fail when standard error is closed. A log failure does not stop +request processing or a security operation. Durable audit events remain part of +their SQLite transactions. + +## Evidence + +The production server test performs Web login, account recovery, a private +session, an invitation, HTTP repository access, and an SSH clone. It checks the +metrics response and parses each server log line as JSON. It requires HTTP +request IDs, SSH operation IDs, and completed lifecycle events. It also proves +that supplied authorization, cookie, feed-token, recovery, invitation, +challenge, session, and signature values do not occur in the logs. + +The Milestone 3.5 gate continues to prove successful and failed audit events, +correlation IDs, and secret exclusion. Unit tests prove that the metrics output +has only the six fixed counters. + +## Consequences + +The implementation uses `serde_json`, which is already a dependency. It does +not add a logging framework or a metrics registry. + +The process writes one line for each HTTP request, SSH connection, SSH +authentication result, SSH operation, and lifecycle change. A later release +can add sampling only if volume becomes an operational problem. diff --git a/scripts/check-m6-5 b/scripts/check-m6-5 new file mode 100755 index 0000000000000000000000000000000000000000..2dec90573051a6134c5b90b244f810d4bfda2122 --- /dev/null +++ b/scripts/check-m6-5 @@ -1,0 +1,8 @@ +#!/bin/sh +set -eu + +./scripts/check +cargo test --locked --release --test account_lifecycle +cargo test --locked --release --test web_session +cargo test --locked --release --test serve serves_an_imported_repository_through_http_and_ssh +cargo test --locked --release --bin tit telemetry::tests::emits_only_fixed_bounded_metrics diff --git a/src/http/mod.rs b/src/http/mod.rs index 02535c022c12c3be4313fc9e1ad02a4ae48cf628..4755eea70bce12dfcfe7191364c0974cf7c91c63 100644 --- a/src/http/mod.rs +++ b/src/http/mod.rs @@ -9,7 +9,7 @@ use std::path::PathBuf; use std::sync::Arc; use std::sync::atomic::{AtomicBool, Ordering}; -use std::time::Duration; +use std::time::{Duration, Instant}; use askama::Template; use axum::Router; @@ -39,6 +39,7 @@ use crate::search::MetadataSearchService; use crate::session::{SessionError, WebLoginService}; use crate::store::StoreError; +use crate::telemetry::Telemetry; use crate::watch::WatchService; use self::public::PublicWeb; @@ -63,6 +64,7 @@ requests: Arc, login_attempts: AttemptLimiter, max_request_bytes: usize, + telemetry: Telemetry, key_reloader: Option, login: Option, repositories: Option, @@ -128,6 +130,7 @@ requests: Arc::new(Semaphore::new(1024)), login_attempts: login_attempt_limiter(), max_request_bytes: 1024 * 1024, + telemetry: Telemetry::default(), key_reloader: None, login: None, repositories: None, @@ -147,7 +150,7 @@ address: SocketAddr, config: PublicWebConfig, ) -> Result { - Self::start_public_inner(address, config, None, None, None).await + Self::start_public_inner(address, config, None, None, None, Telemetry::default()).await } pub(crate) async fn start_public_with_key_reload( @@ -156,6 +159,7 @@ key_reloader: AccountKeyReloader, readiness: ListenerReadiness, maintenance: MaintenanceGate, + telemetry: Telemetry, ) -> Result { Self::start_public_inner( address, @@ -163,6 +167,7 @@ Some(key_reloader), Some(readiness), Some(maintenance), + telemetry, ) .await } @@ -173,6 +178,7 @@ key_reloader: Option, readiness: Option, maintenance: Option, + telemetry: Telemetry, ) -> Result { let jobs = Arc::new(Semaphore::new(MAX_BLOCKING_WEB_JOBS)); let requests = Arc::new(Semaphore::new(config.max_connections)); @@ -209,6 +215,7 @@ requests, login_attempts: login_attempt_limiter(), max_request_bytes, + telemetry, key_reloader, login: Some(login), repositories: Some(repositories), @@ -279,6 +286,7 @@ requests: Arc::new(Semaphore::new(1024)), login_attempts: login_attempt_limiter(), max_request_bytes: 1024 * 1024, + telemetry: Telemetry::default(), key_reloader: None, login: None, repositories: None, @@ -306,6 +314,7 @@ Router::new() .route("/", get(home)) .route("/healthz", get(health)) + .route("/metrics", get(metrics)) .route("/go", get(go_to_repository)) .route( "/signup", @@ -349,8 +358,20 @@ .method_not_allowed_fallback(method_not_allowed) .layer(RequestBodyLimitLayer::new(max_request_bytes)) .layer(middleware::from_fn_with_state(state.clone(), request_guard)) - .layer(middleware::from_fn(response_policy)) + .layer(middleware::from_fn_with_state( + state.clone(), + response_policy, + )) .with_state(state) +} + +async fn metrics(State(state): State) -> Response { + Response::builder() + .status(StatusCode::OK) + .header(header::CONTENT_TYPE, "text/plain; charset=utf-8") + .header(header::CACHE_CONTROL, "no-store") + .body(Body::from(state.telemetry.metrics())) + .expect("the metrics response is valid") } fn login_attempt_limiter() -> AttemptLimiter { @@ -1337,8 +1358,15 @@ response } -async fn response_policy(mut request: Request, next: Next) -> Response { +async fn response_policy( + State(state): State, + mut request: Request, + next: Next, +) -> Response { let request_id = RequestId(format!("{:032x}", rand::random::())); + let method = logged_method(request.method()); + let started = Instant::now(); + let _in_flight = state.telemetry.http_start(); let is_head = request.method() == Method::HEAD; request.extensions_mut().insert(request_id.clone()); let mut response = next.run(request).await; @@ -1385,7 +1413,28 @@ ); } } + state.telemetry.http_finish( + &request_id.0, + method, + response.status().as_u16(), + started.elapsed(), + ); response +} + +fn logged_method(method: &Method) -> &'static str { + match *method { + Method::GET => "GET", + Method::HEAD => "HEAD", + Method::POST => "POST", + Method::PUT => "PUT", + Method::PATCH => "PATCH", + Method::DELETE => "DELETE", + Method::OPTIONS => "OPTIONS", + Method::CONNECT => "CONNECT", + Method::TRACE => "TRACE", + _ => "OTHER", + } } fn render_home( diff --git a/src/main.rs b/src/main.rs index 2c43c46a067ab8614fa78c070a54acdcb9a1bd70..c0f22b60f826d4c77ca096ccb6d426143066f8f0 100644 --- a/src/main.rs +++ b/src/main.rs @@ -33,6 +33,7 @@ #[allow(dead_code, reason = "the server uses only part of the shared SSH API")] mod ssh; mod store; +mod telemetry; mod watch; use std::process::ExitCode; diff --git a/src/serve.rs b/src/serve.rs index b733dc48053e21f58cd1e3c82696b1a5ff27c6db..7af25391e3da6dfc00f65d52f30c7ab0fc8670a5 100644 --- a/src/serve.rs +++ b/src/serve.rs @@ -21,10 +21,13 @@ use crate::pull_request::{PullRequestError, PullRequestService}; use crate::ssh::{AuthorizedSshKeys, RunningSshServer, SshServerError}; use crate::store::{Store, StoreError}; +use crate::telemetry::Telemetry; const SHUTDOWN_DRAIN_LIMIT: Duration = Duration::from_secs(10); pub(crate) async fn run(config: &Config) -> Result<(), ServeError> { + let telemetry = Telemetry::enabled(); + telemetry.lifecycle("server.start", "started"); let _lock = InstanceLock::acquire(&config.instance_dir)?; let database = prepare_database(&config.instance_dir)?; let repository_root = prepare_repository_root(&config.instance_dir)?; @@ -76,6 +79,7 @@ reload_keys, readiness.clone(), maintenance, + telemetry.clone(), ) .await?; let ssh = match RunningSshServer::start_with_dynamic_keys( @@ -84,6 +88,7 @@ git, host_key, usize::try_from(config.max_connections).map_err(|_| ServeError::ConnectionLimit)?, + telemetry.clone(), ) .await { @@ -95,9 +100,11 @@ } }; readiness.mark_ready(); + telemetry.lifecycle("server.readiness", "ready"); let signal = shutdown_signal().await; readiness.mark_stopping(); + telemetry.lifecycle("server.shutdown", "started"); let (ssh_result, web_result, control_result) = tokio::join!( ssh.shutdown_bounded(SHUTDOWN_DRAIN_LIMIT), web.shutdown_bounded(SHUTDOWN_DRAIN_LIMIT), @@ -110,6 +117,10 @@ if !drained { eprintln!("tit: the shutdown drain limit expired; unfinished connections were canceled"); } + telemetry.lifecycle( + "server.shutdown", + if drained { "completed" } else { "bounded" }, + ); signal.map_err(ServeError::Signal) } diff --git a/src/ssh.rs b/src/ssh.rs index 5c2212fe8c9e037d63e65d737b7591577f7996f1..5406871dd4515bb8a1eb70bf4eda5a791d1d6d19 100644 --- a/src/ssh.rs +++ b/src/ssh.rs @@ -25,6 +25,7 @@ use crate::rate_limit::AttemptLimiter; use crate::repository::{RepositoryService, RepositoryServiceError}; use crate::store::{Store, StoreError}; +use crate::telemetry::Telemetry; const VERSION_COMMAND: &[u8] = b"tit --version"; const GIT_PROTOCOL_VARIABLE: &str = "GIT_PROTOCOL"; @@ -150,6 +151,7 @@ repositories: GitRepositories, host_key: PrivateKey, max_connections: usize, + telemetry: Telemetry, ) -> Result { recover_pushes(&repositories).await?; Self::start_inner_with_keys( @@ -159,6 +161,7 @@ Some(repositories), host_key, max_connections, + telemetry, ) .await } @@ -195,6 +198,7 @@ repositories, host_key, 1024, + Telemetry::default(), ) .await } @@ -206,6 +210,7 @@ repositories: Option, host_key: PrivateKey, max_connections: usize, + telemetry: Telemetry, ) -> Result { let listener = TcpListener::bind(address).await?; let address = listener.local_addr()?; @@ -248,6 +253,7 @@ Duration::from_secs(60), MAX_SSH_CLIENTS, ), + telemetry, }; let (handle_sender, handle_receiver) = oneshot::channel(); let task = tokio::spawn(async move { @@ -333,12 +339,15 @@ repositories: Option>, connections: Arc, attempts: AttemptLimiter, + telemetry: Telemetry, } impl Server for SshServer { type Handler = SshSession; fn new_client(&mut self, peer_address: Option) -> Self::Handler { + let connection_id = format!("{:032x}", rand::random::()); + self.telemetry.ssh_connection(&connection_id); SshSession { authorized_keys: self.authorized_keys.clone(), writable_keys: Arc::clone(&self.writable_keys), @@ -354,6 +363,8 @@ .unwrap_or(IpAddr::V4(Ipv4Addr::LOCALHOST)), attempts: self.attempts.clone(), _connection_permit: self.connections.clone().try_acquire_owned().ok(), + telemetry: self.telemetry.clone(), + connection_id, } } } @@ -371,6 +382,8 @@ peer_address: IpAddr, attempts: AttemptLimiter, _connection_permit: Option, + telemetry: Telemetry, + connection_id: String, } enum ExecChannel { @@ -423,14 +436,17 @@ public_key: &PublicKey, ) -> Result { if self._connection_permit.is_none() || !self.attempts.allow(self.peer_address) { + self.telemetry.ssh_auth(&self.connection_id, false); return Ok(Auth::reject()); } if let Some(identity) = self.authorized_keys.identity(public_key) { self.authenticated_identity = Some(identity); self.authenticated_key = Some(public_key.clone()); self.authenticated_writer = self.writable_keys.contains(public_key); + self.telemetry.ssh_auth(&self.connection_id, true); Ok(Auth::Accept) } else { + self.telemetry.ssh_auth(&self.connection_id, false); Ok(Auth::reject()) } } @@ -552,6 +568,8 @@ command: &[u8], session: &mut Session, ) -> Result<(), Self::Error> { + let operation_id = format!("{:032x}", rand::random::()); + self.telemetry.ssh_operation(&operation_id); if command == VERSION_COMMAND { self.audit.accepted_exec.fetch_add(1, Ordering::Relaxed); session.channel_success(channel)?; diff --git a/src/telemetry.rs b/src/telemetry.rs new file mode 100644 index 0000000000000000000000000000000000000000..4385dc68ebe641ff36f5581c8bd9846e06ca4446 --- /dev/null +++ b/src/telemetry.rs @@ -1,0 +1,219 @@ +use std::io::Write; +use std::sync::Arc; +use std::sync::atomic::{AtomicU64, Ordering}; +use std::time::{Duration, SystemTime, UNIX_EPOCH}; + +use serde::Serialize; + +#[derive(Clone, Default)] +pub(crate) struct Telemetry { + counters: Arc, + enabled: bool, +} + +#[derive(Default)] +struct Counters { + http_requests: AtomicU64, + http_errors: AtomicU64, + http_in_flight: AtomicU64, + ssh_connections: AtomicU64, + ssh_auth_rejected: AtomicU64, + ssh_operations: AtomicU64, +} + +pub(crate) struct HttpInFlight { + counters: Arc, +} + +impl Drop for HttpInFlight { + fn drop(&mut self) { + self.counters.http_in_flight.fetch_sub(1, Ordering::Relaxed); + } +} + +impl Telemetry { + #[allow( + dead_code, + reason = "integration tests use disabled telemetry outside the production server" + )] + pub(crate) fn enabled() -> Self { + Self { + counters: Arc::new(Counters::default()), + enabled: true, + } + } + + pub(crate) fn http_start(&self) -> HttpInFlight { + self.counters.http_requests.fetch_add(1, Ordering::Relaxed); + self.counters.http_in_flight.fetch_add(1, Ordering::Relaxed); + HttpInFlight { + counters: Arc::clone(&self.counters), + } + } + + pub(crate) fn http_finish( + &self, + request_id: &str, + method: &str, + status: u16, + duration: Duration, + ) { + if status >= 400 { + self.counters.http_errors.fetch_add(1, Ordering::Relaxed); + } + self.write_event(&Event { + timestamp_ms: timestamp_ms(), + level: "info", + event: "http.request", + request_id: Some(request_id), + operation_id: None, + method: Some(method), + status: Some(status), + duration_ms: Some(duration.as_millis().min(u128::from(u64::MAX)) as u64), + outcome: None, + }); + } + + pub(crate) fn ssh_connection(&self, connection_id: &str) { + self.counters + .ssh_connections + .fetch_add(1, Ordering::Relaxed); + self.write_ssh_event("ssh.connection", connection_id, "accepted"); + } + + pub(crate) fn ssh_auth(&self, connection_id: &str, accepted: bool) { + if !accepted { + self.counters + .ssh_auth_rejected + .fetch_add(1, Ordering::Relaxed); + } + self.write_ssh_event( + "ssh.authentication", + connection_id, + if accepted { "accepted" } else { "rejected" }, + ); + } + + pub(crate) fn ssh_operation(&self, operation_id: &str) { + self.counters.ssh_operations.fetch_add(1, Ordering::Relaxed); + self.write_ssh_event("ssh.operation", operation_id, "started"); + } + + #[allow( + dead_code, + reason = "some integration tests compile telemetry without process lifecycle" + )] + pub(crate) fn lifecycle(&self, event: &'static str, outcome: &'static str) { + self.write_event(&Event { + timestamp_ms: timestamp_ms(), + level: "info", + event, + request_id: None, + operation_id: None, + method: None, + status: None, + duration_ms: None, + outcome: Some(outcome), + }); + } + + pub(crate) fn metrics(&self) -> String { + format!( + concat!( + "tit_http_requests_total {}\n", + "tit_http_errors_total {}\n", + "tit_http_requests_in_flight {}\n", + "tit_ssh_connections_total {}\n", + "tit_ssh_auth_rejected_total {}\n", + "tit_ssh_operations_total {}\n" + ), + self.counters.http_requests.load(Ordering::Relaxed), + self.counters.http_errors.load(Ordering::Relaxed), + self.counters.http_in_flight.load(Ordering::Relaxed), + self.counters.ssh_connections.load(Ordering::Relaxed), + self.counters.ssh_auth_rejected.load(Ordering::Relaxed), + self.counters.ssh_operations.load(Ordering::Relaxed), + ) + } + + fn write_ssh_event(&self, event: &'static str, operation_id: &str, outcome: &'static str) { + self.write_event(&Event { + timestamp_ms: timestamp_ms(), + level: "info", + event, + request_id: None, + operation_id: Some(operation_id), + method: None, + status: None, + duration_ms: None, + outcome: Some(outcome), + }); + } + + fn write_event(&self, event: &Event<'_>) { + if !self.enabled { + return; + } + let Ok(line) = serde_json::to_string(event) else { + return; + }; + let mut error = std::io::stderr().lock(); + let _ = writeln!(error, "{line}"); + } +} + +fn timestamp_ms() -> u64 { + SystemTime::now() + .duration_since(UNIX_EPOCH) + .unwrap_or_default() + .as_millis() + .min(u128::from(u64::MAX)) as u64 +} + +#[derive(Serialize)] +struct Event<'a> { + timestamp_ms: u64, + level: &'static str, + event: &'static str, + #[serde(skip_serializing_if = "Option::is_none")] + request_id: Option<&'a str>, + #[serde(skip_serializing_if = "Option::is_none")] + operation_id: Option<&'a str>, + #[serde(skip_serializing_if = "Option::is_none")] + method: Option<&'a str>, + #[serde(skip_serializing_if = "Option::is_none")] + status: Option, + #[serde(skip_serializing_if = "Option::is_none")] + duration_ms: Option, + #[serde(skip_serializing_if = "Option::is_none")] + outcome: Option<&'static str>, +} + +#[cfg(test)] +mod tests { + use super::Telemetry; + use std::time::Duration; + + #[test] + fn emits_only_fixed_bounded_metrics() { + let telemetry = Telemetry::default(); + let request = telemetry.http_start(); + telemetry.http_finish("request", "GET", 404, Duration::from_millis(2)); + drop(request); + telemetry.ssh_connection("connection"); + telemetry.ssh_auth("connection", false); + telemetry.ssh_operation("operation"); + + assert_eq!( + telemetry.metrics(), + concat!( + "tit_http_requests_total 1\n", + "tit_http_errors_total 1\n", + "tit_http_requests_in_flight 0\n", + "tit_ssh_connections_total 1\n", + "tit_ssh_auth_rejected_total 1\n", + "tit_ssh_operations_total 1\n" + ) + ); + } +} diff --git a/tests/git_push_ssh.rs b/tests/git_push_ssh.rs index 179035d0559f5d2ec9984c11fd5a262afe8c8904..32acfe58a3f005f5f369665b2c5d12eee2f8b51a 100644 --- a/tests/git_push_ssh.rs +++ b/tests/git_push_ssh.rs @@ -36,6 +36,8 @@ #[allow(dead_code, reason = "the SSH push test does not use each store API")] #[path = "../src/store/mod.rs"] mod store; +#[path = "../src/telemetry.rs"] +mod telemetry; use std::env; use std::fs; diff --git a/tests/git_ssh.rs b/tests/git_ssh.rs index 8e85534522bd3a4ee8d386bfe402eb0a536af919..364a380ab5f1dde06535d96330e7e0c0e7a371fa 100644 --- a/tests/git_ssh.rs +++ b/tests/git_ssh.rs @@ -36,6 +36,8 @@ #[allow(dead_code, reason = "the SSH Git test does not use the intent store")] #[path = "../src/store/mod.rs"] mod store; +#[path = "../src/telemetry.rs"] +mod telemetry; use std::fs; use std::net::{Ipv4Addr, SocketAddr}; diff --git a/tests/public_routes.rs b/tests/public_routes.rs index 1501c8e25bb97056f5642985d9d1b6150da39807..176d62bd750873cf3a6475c752279e2683633559 100644 --- a/tests/public_routes.rs +++ b/tests/public_routes.rs @@ -70,6 +70,8 @@ )] #[path = "../src/store/mod.rs"] mod store; +#[path = "../src/telemetry.rs"] +mod telemetry; #[allow(dead_code, reason = "the public-route test does not change watches")] #[path = "../src/watch.rs"] mod watch; diff --git a/tests/serve.rs b/tests/serve.rs index 197efce11042c3c5aab0036d84054ee83051173e..9fba7cee6a12b5e7a0ca1b6601adbaf5d36e8060 100644 --- a/tests/serve.rs +++ b/tests/serve.rs @@ -497,7 +497,63 @@ assert_eq!(locked.status.code(), Some(1)); assert!(String::from_utf8_lossy(&locked.stderr).contains("owns the instance lock")); - server.terminate(); + let metrics = http_get(http, "/metrics"); + assert!(metrics.starts_with("HTTP/1.1 200")); + assert!(metrics.contains("tit_http_requests_total ")); + assert!(metrics.contains("tit_http_requests_in_flight 1")); + assert!(metrics.contains("tit_ssh_connections_total ")); + assert!(metrics.contains("tit_ssh_operations_total ")); + + let authorization_secret = "Bearer tit-secret-authorization"; + let cookie_secret = "tit-session=tit-secret-cookie"; + let feed_secret = "tit-secret-feed-token"; + let _ = http_get_with_headers( + http, + "/", + &[ + ("Authorization", authorization_secret), + ("Cookie", cookie_secret), + ], + ); + let _ = http_get(http, &format!("/feeds/{feed_secret}.atom")); + + let logs = server.terminate_capture(); + let logs = String::from_utf8(logs).expect("read structured server logs"); + assert!(!logs.contains(authorization_secret)); + assert!(!logs.contains(cookie_secret)); + assert!(!logs.contains(feed_secret)); + for secret in [ + recovery, + challenge, + signature.as_str(), + invitation.trim(), + private_cookies.as_str(), + upload_signature.as_str(), + ] { + assert!(!logs.contains(secret)); + } + let events: Vec = logs + .lines() + .map(|line| serde_json::from_str(line).expect("parse a structured server log")) + .collect(); + assert!(events.iter().any(|event| { + event["event"] == "http.request" + && event["request_id"] + .as_str() + .is_some_and(|request_id| request_id.len() == 32) + })); + assert!(events.iter().any(|event| { + event["event"] == "ssh.operation" + && event["operation_id"] + .as_str() + .is_some_and(|operation_id| operation_id.len() == 32) + })); + assert!( + events + .iter() + .any(|event| event["event"] == "server.shutdown" && event["outcome"] == "completed") + ); + assert!(!control_socket.exists()); let host_key = fs::read(instance.path().join("ssh_host_ed25519_key")) .expect("read the generated SSH host key"); @@ -1779,6 +1835,24 @@ struct ChildGuard(Option); impl ChildGuard { + fn terminate_capture(&mut self) -> Vec { + let child = self.0.take().expect("the server process is active"); + let signal = Command::new("kill") + .args(["-TERM", &child.id().to_string()]) + .output() + .expect("send SIGTERM to the tit server"); + assert!(signal.status.success(), "cannot send SIGTERM"); + let output = child + .wait_with_output() + .expect("wait for the tit server and read its output"); + assert!( + output.status.success(), + "tit serve did not stop cleanly: {}", + output.status + ); + output.stderr + } + fn terminate(&mut self) { if let Some(mut child) = self.0.take() { let signal = Command::new("kill") diff --git a/tests/ssh.rs b/tests/ssh.rs index 2b2a660466cf95da0922116bcf13374869e70951..401c758568f6a76d0f3b5259c9f3983158e12900 100644 --- a/tests/ssh.rs +++ b/tests/ssh.rs @@ -45,6 +45,8 @@ )] #[path = "../src/store/mod.rs"] mod store; +#[path = "../src/telemetry.rs"] +mod telemetry; use std::fs; use std::net::{Ipv4Addr, SocketAddr}; diff --git a/tests/web_shell.rs b/tests/web_shell.rs index 14f949804b8c03ec0705bc4220303ed1dc1ca0a9..39a102c8fd278c7cd5cc2d54de0deb96c5522783 100644 --- a/tests/web_shell.rs +++ b/tests/web_shell.rs @@ -59,6 +59,8 @@ #[allow(dead_code, reason = "the shell test does not use repository storage")] #[path = "../src/store/mod.rs"] mod store; +#[path = "../src/telemetry.rs"] +mod telemetry; #[allow(dead_code, reason = "the Web shell test does not change watches")] #[path = "../src/watch.rs"] mod watch;