diff --git a/.dockerignore b/.dockerignore new file mode 100644 index 00000000..10e7628a --- /dev/null +++ b/.dockerignore @@ -0,0 +1,6 @@ +.git +.worktrees +target +**/target +**/node_modules +apps/desktop/dist diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 25ede6b4..fcad42a7 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -66,6 +66,32 @@ jobs: - name: check run: bash crates/forge/conformance/forge-check.sh + # Advisory (not a required context): the sc-forge container image builds and works (git new + # enough, boots, serves, clones, and exits 0 on SIGTERM). Only runs when the forge, its image + # or the lockfile changed. + forge-image: + name: sc-forge image + runs-on: ubuntu-latest + steps: + - uses: actions/checkout@3d3c42e5aac5ba805825da76410c181273ba90b1 # v7.0.1 + with: + fetch-depth: 0 + - name: changed? + id: changed + run: | + base="${{ github.event.pull_request.base.sha || github.event.before }}" + if [ -z "$base" ] || ! git diff --quiet "$base" HEAD -- crates/forge crates/core crates/crypto Cargo.toml Cargo.lock .dockerignore rust-toolchain.toml 2>/dev/null; then + echo "run=true" >> "$GITHUB_OUTPUT" + else + echo "run=false" >> "$GITHUB_OUTPUT" + fi + - name: build + if: steps.changed.outputs.run == 'true' + run: docker build -f crates/forge/Dockerfile -t sc-forge:ci . + - name: smoke + if: steps.changed.outputs.run == 'true' + run: bash crates/forge/docker/smoke.sh sc-forge:ci + # Advisory (not a required context): proves the Windows build and the owner-only # ACL on .sc/local-key, the `sc keygen` identity and the TLS serve key (#214, # #281). Deliberately not `cargo test --workspace`; the wider suite still has diff --git a/ROADMAP.md b/ROADMAP.md index 2c000fd0..6f862f89 100644 --- a/ROADMAP.md +++ b/ROADMAP.md @@ -707,7 +707,7 @@ and reconciler, collaborators, branches) and F2b (smart-HTTP git transport via ` `pre-receive` ref policy, admission control, threat-model pass #1) and F3a (content reads: refs, tags, commits, trees, contents, archives) and F3b (contents writes: create, update, delete as server-made commits) and F4a (branch protection enforced on push, contents API and branch delete; commit statuses) and F4b (pull requests, reviews, comments, retention -refs) and F4c (merge with a crash-safe journal, required-check gating, kill -9 and protection-matrix tests) and F5a (two-stage gc, merge-commit retention, runtime cleanup of stale locks and quarantine directories) are built. Hosted repos are +refs) and F4c (merge with a crash-safe journal, required-check gating, kill -9 and protection-matrix tests) and F5a (two-stage gc, merge-commit retention, runtime cleanup of stale locks and quarantine directories) and F5b (structured logs, graceful SIGTERM drain, bind-gate tests, container image, operations guide) are built. Hosted repos are bare Git and get none of the `.sc/` features. Other follow-up work is tracked as GitHub issues and listed under Deferred diff --git a/crates/forge/Dockerfile b/crates/forge/Dockerfile new file mode 100644 index 00000000..39bbfd46 --- /dev/null +++ b/crates/forge/Dockerfile @@ -0,0 +1,27 @@ +# sc-forge image. Build from the repository root: +# docker build -f crates/forge/Dockerfile -t sc-forge . +# Base images are pinned by digest; bump them together with rust-toolchain.toml. + +FROM rust:1.96.1-bookworm@sha256:a339861ae23e9abb272cea45dfafde21760d2ce6577a70f8a926153677902663 AS build +WORKDIR /src +COPY . . +RUN cargo build --release --locked -p scl-forge --bin sc-forge + +# trixie, not bookworm: sc-forge needs git 2.40 or newer (merge-tree --write-tree, quarantine +# naming) and bookworm ships 2.39. No sshd, no shell tooling beyond the base. +FROM debian:trixie-slim@sha256:62bd423aeee912639ca8ee681c2b762cb3e25137e0a92b20be455898a9f034ad +RUN apt-get update \ + && apt-get install -y --no-install-recommends git ca-certificates tini \ + && rm -rf /var/lib/apt/lists/* \ + && useradd --system --uid 10001 --home-dir /data --shell /usr/sbin/nologin forge \ + && mkdir /data && chown forge:forge /data +COPY --from=build /src/target/release/sc-forge /usr/local/bin/sc-forge +USER forge +VOLUME /data +EXPOSE 3000 +# SIGTERM drains (see docs/FORGE-OPERATIONS.md); give the orchestrator longer than --shutdown-timeout. +STOPSIGNAL SIGTERM +# tini is PID 1: it reaps the git processes that outlive a killed transport (orphans are re-parented +# to PID 1 and would otherwise stay zombies until pids.max runs out) and forwards SIGTERM. +ENTRYPOINT ["/usr/bin/tini", "--", "/usr/local/bin/sc-forge"] +CMD ["--help"] diff --git a/crates/forge/docker/smoke.sh b/crates/forge/docker/smoke.sh new file mode 100755 index 00000000..cba0ddd8 --- /dev/null +++ b/crates/forge/docker/smoke.sh @@ -0,0 +1,37 @@ +#!/usr/bin/env bash +# Smoke test of the sc-forge image: it starts, answers /healthz, git is new enough, a repository +# can be created and cloned, and `docker stop` ends it with exit code 0 (the SIGTERM drain). +# Usage: smoke.sh +set -euo pipefail +image=${1:?usage: smoke.sh } +name=sc-forge-smoke-$$ +port=${SMOKE_PORT:-13000} +cleanup() { docker rm -f "$name" >/dev/null 2>&1 || true; docker volume rm -f "$name-data" >/dev/null 2>&1 || true; } +trap cleanup EXIT + +docker run --rm --entrypoint git "$image" --version +docker volume create "$name-data" >/dev/null +docker run --rm -v "$name-data:/data" "$image" admin user create --data-dir /data \ + --username siteadmin --password "$(head -c 24 /dev/urandom | base64)" \ + --email admin@example.invalid --admin --must-change-password=false >/dev/null +token=$(docker run --rm -v "$name-data:/data" "$image" admin user generate-access-token --data-dir /data \ + --username siteadmin --token-name smoke --scopes all --raw) +docker run -d --name "$name" -v "$name-data:/data" -p "127.0.0.1:$port:3000" "$image" serve \ + --data-dir /data --listen 0.0.0.0:3000 --behind-proxy --public-url "http://127.0.0.1:$port" >/dev/null + +for _ in $(seq 1 60); do + curl -fsS "http://127.0.0.1:$port/api/healthz" >/dev/null 2>&1 && break + sleep 0.5 +done +curl -fsS "http://127.0.0.1:$port/api/healthz" >/dev/null +curl -fsS -H "Authorization: token $token" -H 'Content-Type: application/json' \ + -d '{"name":"smoke","auto_init":true}' "http://127.0.0.1:$port/api/v1/user/repos" >/dev/null +work=$(mktemp -d) +git clone -q "http://siteadmin:$token@127.0.0.1:$port/siteadmin/smoke.git" "$work/smoke" +test -f "$work/smoke/README.md" +rm -rf "$work" + +docker stop -t 40 "$name" >/dev/null +code=$(docker inspect -f '{{.State.ExitCode}}' "$name") +[ "$code" = 0 ] || { echo "sc-forge exited with $code after SIGTERM" >&2; docker logs "$name" >&2; exit 1; } +echo "smoke ok" diff --git a/crates/forge/src/cgi.rs b/crates/forge/src/cgi.rs index e515db83..3720f945 100644 --- a/crates/forge/src/cgi.rs +++ b/crates/forge/src/cgi.rs @@ -345,7 +345,7 @@ impl Pump { GROW_STEP, ); if !ok { - eprintln!("sc-forge: push aborted: the disk reserve cannot cover it"); + crate::log::warning!("push aborted: the disk reserve cannot cover it"); self.stop(ABORT_NO_SPACE); return false; } @@ -453,6 +453,9 @@ fn environment(l: &Launch, marker: &std::path::Path) -> Vec<(String, String)> { ("uploadpackfilter.allow", "false".into()), ("uploadpackfilter.blob:none.allow", "true".into()), ("receive.maxInputSize", cfg.max_pack.to_string()), + // git sizes its pack threads by the host's CPUs, which a container does not narrow: bound + // them, or one transport on a big node starts dozens of threads (see FORGE-OPERATIONS.md). + ("pack.threads", "4".into()), ("receive.autogc", "false".into()), ("receive.advertisePushOptions", "true".into()), ]; @@ -815,8 +818,8 @@ impl Supervise { let _ = verdict.send(ok); let err = tail.and_then(|t| t.join().ok()).unwrap_or_default(); if !ok { - eprintln!( - "sc-forge: git transport on repository {repo_id} ended ({reason}, {}): {}", + crate::log::warning!( + "git transport on repository {repo_id} ended ({reason}, {}): {}", status.map_or_else(|e| e.to_string(), |s| s.to_string()), String::from_utf8_lossy(&err).trim() ); @@ -964,7 +967,7 @@ pub async fn handle(app: Arc, req: Req, body: Incoming, path: GitPath) -> R Ok(Err(LaunchError::Gone)) => return buffered(transport::repo_not_found()), Ok(Err(LaunchError::Stopped)) => return buffered(shutting_down()), Ok(Err(LaunchError::Io(e))) => { - eprintln!("sc-forge: could not start git: {e}"); + crate::log::warning!("could not start git: {e}"); return buffered(text(500, "internal server error\n")); } Err(e) if e.is_cancelled() => return buffered(shutting_down()), @@ -1004,7 +1007,7 @@ pub async fn handle(app: Arc, req: Req, body: Incoming, path: GitPath) -> R let why = abort.load(Ordering::SeqCst); let status = if why != 0 { why } else { 502 }; if let Ok(Err(e)) = other { - eprintln!("sc-forge: git transport failed before answering: {e}"); + crate::log::warning!("git transport failed before answering: {e}"); } return buffered(text(status, "git transport failed\n")); } diff --git a/crates/forge/src/cli.rs b/crates/forge/src/cli.rs index 1c5e68c4..85c2f018 100644 --- a/crates/forge/src/cli.rs +++ b/crates/forge/src/cli.rs @@ -104,6 +104,9 @@ struct ServeArgs { /// Wall-clock limit of the garbage collection of one repository, seconds. #[arg(long, default_value_t = 3_600)] gc_timeout: u64, + /// Seconds a SIGTERM waits for requests in flight before it ends the git processes still running. + #[arg(long, default_value_t = 30)] + shutdown_timeout: u64, /// Concurrent password verifications (Argon2 is memory-hard). #[arg(long, default_value_t = 4)] argon2_concurrency: usize, @@ -278,6 +281,7 @@ fn run_serve(a: ServeArgs) -> Result<()> { ("--max-pack-size", a.max_pack_size), ("--max-request-bytes", a.max_request_bytes), ("--gc-timeout", a.gc_timeout), + ("--shutdown-timeout", a.shutdown_timeout), ] { if v == 0 { bail!("{flag} must be at least 1"); @@ -312,9 +316,9 @@ fn run_serve(a: ServeArgs) -> Result<()> { bail!("--trusted-proxy-header and --trusted-proxies must be given together"); } if a.behind_proxy && cidrs.is_empty() { - eprintln!( - "sc-forge: warning: --behind-proxy without --trusted-proxy-header/--trusted-proxies: every client shares the proxy's address, \ - so the per-source password-failure budget (30/min) applies to all of them together" + scl_forge::log::warning_line( + "warning: --behind-proxy without --trusted-proxy-header/--trusted-proxies: every client shares the proxy's address, \ + so the per-source password-failure budget (30/min) applies to all of them together", ); } let proxies = Proxies { @@ -334,7 +338,7 @@ fn run_serve(a: ServeArgs) -> Result<()> { a.git_concurrency, )?); let git_version = scl_forge::gitproc::check_version(&git).map_err(anyhow::Error::msg)?; - eprintln!("sc-forge: {git_version}"); + scl_forge::log::info_line(&git_version); scl_forge::hook::install( &std::fs::canonicalize(&a.data_dir)?, &std::env::current_exe().context("cannot find the sc-forge binary")?, @@ -346,7 +350,7 @@ fn run_serve(a: ServeArgs) -> Result<()> { // Resolve whatever a crash left, before the listener is bound. let report = life.reconcile(&db::connect(&a.data_dir)?, scl_forge::timefmt::now())?; if report != scl_forge::lifecycle::Report::default() { - eprintln!("sc-forge: reconciled {report:?}"); + scl_forge::log::info_line(&format!("reconciled {report:?}")); } // Pull request refs and rows agree again before anything is served. scl_forge::pulls::reconcile_all(&life, &db::connect(&a.data_dir)?, scl_forge::timefmt::now()); @@ -389,16 +393,25 @@ fn run_serve(a: ServeArgs) -> Result<()> { let listener = tokio::net::TcpListener::bind(a.listen) .await .with_context(|| format!("bind {}", a.listen))?; - eprintln!("sc-forge: listening on {}", listener.local_addr()?); + // Handlers first, announcement second: a SIGTERM that follows the "listening" line (a + // supervisor that stops a service the moment it is up) must drain, not kill the process. + use tokio::signal::unix::{signal, SignalKind}; + let (mut term, mut int) = ( + signal(SignalKind::terminate()).context("install the SIGTERM handler")?, + signal(SignalKind::interrupt()).context("install the SIGINT handler")?, + ); + scl_forge::log::info_line(&format!("listening on {}", listener.local_addr()?)); let stop = async { - use tokio::signal::unix::{signal, SignalKind}; - let (mut term, mut int) = ( - signal(SignalKind::terminate()).expect("signal"), - signal(SignalKind::interrupt()).expect("signal"), - ); tokio::select! { _ = term.recv() => {}, _ = int.recv() => {} } }; - serve(listener, app, limits, stop, Duration::from_secs(30)).await; + serve( + listener, + app, + limits, + stop, + Duration::from_secs(a.shutdown_timeout), + ) + .await; Ok(()) }); // Queued password verifications run on blocking threads that the drain deadline diff --git a/crates/forge/src/content_write.rs b/crates/forge/src/content_write.rs index c21e5da8..5e3c481b 100644 --- a/crates/forge/src/content_write.rs +++ b/crates/forge/src/content_write.rs @@ -442,17 +442,17 @@ fn run(ctx: &Ctx, a: &Access, row: &Repo, w: &Write) -> Resp { ) } Outcome::Fatal => { - eprintln!("sc-forge: update-ref {full} failed on attempt {attempt}: {failure}"); + crate::log::warning!("update-ref {full} failed on attempt {attempt}: {failure}"); return ctx.app.internal(&"could not update the branch"); } } - eprintln!("sc-forge: contents write to {full} lost round {attempt}: {failure}"); + crate::log::warning!("contents write to {full} lost round {attempt}: {failure}"); } if locked { // Three rounds against a ref lock that never cleared: nothing changed the branch. A killed // git can leave `refs/heads/.lock` behind; it blocks pushes as well. - eprintln!( - "sc-forge: refs/heads/{target_name} of repository {} stayed locked; if no git process is running, remove its .lock file", + crate::log::warning!( + "refs/heads/{target_name} of repository {} stayed locked; if no git process is running, remove its .lock file", a.repo.id ); return error(&ctx.app.base, 503, "the branch is locked, try again later"); @@ -472,7 +472,7 @@ fn write_err(ctx: &Ctx, a: &Access, e: WriteErr) -> Resp { match e { WriteErr::Git(e) => read_err(ctx, a, e), WriteErr::Rewrite(m) => { - eprintln!("sc-forge: contents write could not rewrite a directory: {m}"); + crate::log::warning!("contents write could not rewrite a directory: {m}"); unprocessable(ctx, "a directory on the path cannot be rewritten") } } @@ -481,8 +481,8 @@ fn write_err(ctx: &Ctx, a: &Access, e: WriteErr) -> Resp { /// The ref moved: stamp the repository (log-only, the write is already public) and answer. fn published(ctx: &Ctx, a: &Access, resp: Resp) -> Resp { if let Err(e) = repos::touch(ctx.conn, a.repo.id, now()) { - eprintln!( - "sc-forge: could not stamp repository {} after a contents write: {e}", + crate::log::warning!( + "could not stamp repository {} after a contents write: {e}", a.repo.id ); } diff --git a/crates/forge/src/db.rs b/crates/forge/src/db.rs index a64b7042..f7e5438a 100644 --- a/crates/forge/src/db.rs +++ b/crates/forge/src/db.rs @@ -271,8 +271,8 @@ fn ensure_dir(data_dir: &Path) -> Result<(), DbError> { std::fs::create_dir_all(data_dir)?; let mode = std::fs::metadata(data_dir)?.permissions().mode() & 0o777; if mode != 0o700 { - eprintln!( - "sc-forge: tightening {} from {mode:o} to 700: it holds password and token hashes", + crate::log::warning!( + "tightening {} from {mode:o} to 700: it holds password and token hashes", data_dir.display() ); std::fs::set_permissions(data_dir, std::fs::Permissions::from_mode(0o700))?; diff --git a/crates/forge/src/lib.rs b/crates/forge/src/lib.rs index 797090c7..28f362e0 100644 --- a/crates/forge/src/lib.rs +++ b/crates/forge/src/lib.rs @@ -23,6 +23,7 @@ pub mod hook; pub mod http; pub mod lifecycle; pub mod limits; +pub mod log; pub mod maintenance; pub mod merges; pub mod names; diff --git a/crates/forge/src/lifecycle.rs b/crates/forge/src/lifecycle.rs index 37c17898..20367cf2 100644 --- a/crates/forge/src/lifecycle.rs +++ b/crates/forge/src/lifecycle.rs @@ -332,8 +332,8 @@ impl Lifecycle { Ok(()) => { let _ = repos::delete_row(conn, row.id); } - Err(c) => eprintln!( - "sc-forge: could not remove {} ({c}); the row stays `creating` for the next startup", + Err(c) => crate::log::warning!( + "could not remove {} ({c}); the row stays `creating` for the next startup", self.repo_dir(row.id).display() ), } @@ -450,8 +450,8 @@ impl Lifecycle { repos::delete_row(conn, repo.id)?; self.step("row-deleted")?; if let Err(e) = std::fs::remove_dir_all(&to) { - eprintln!( - "sc-forge: could not remove trash/{}.git ({e}); startup reconcile will", + crate::log::warning!( + "could not remove trash/{}.git ({e}); startup reconcile will", repo.id ); } @@ -647,8 +647,8 @@ impl Lifecycle { }; if !known { let to = self.to_orphans(&p)?; - eprintln!( - "sc-forge: {} has no repository row; moved to {}", + crate::log::warning!( + "{} has no repository row; moved to {}", p.display(), to.display() ); @@ -661,9 +661,11 @@ impl Lifecycle { for r in repos::list_in_state(conn, "live")? { let dir = self.repo_dir(r.id); if !dir.is_dir() { - eprintln!( - "sc-forge: repository {}/{} (id {}) has no directory", - r.owner, r.name, r.id + crate::log::warning!( + "repository {}/{} (id {}) has no directory", + r.owner, + r.name, + r.id ); rep.missing_dirs += 1; continue; @@ -685,9 +687,11 @@ impl Lifecycle { Ok(true) => rep.head_repaired += 1, Ok(false) => {} Err(e) => { - eprintln!( - "sc-forge: cannot repair HEAD of {}/{} (id {}): {e}", - r.owner, r.name, r.id + crate::log::warning!( + "cannot repair HEAD of {}/{} (id {}): {e}", + r.owner, + r.name, + r.id ); rep.head_repair_failed += 1; } diff --git a/crates/forge/src/log.rs b/crates/forge/src/log.rs new file mode 100644 index 00000000..c58eaeba --- /dev/null +++ b/crates/forge/src/log.rs @@ -0,0 +1,189 @@ +//! Structured logs: one JSON object per line on stderr, shaped for Cloud Logging +//! (`time`, `severity`, `message`; further keys are fields). +//! +//! Nothing here sees a secret by construction: the access log records the method, the path +//! without its query, the status, the duration and the client address, never a header or a body, +//! and a message is built by the caller from facts the caller already holds. A value longer than +//! [`MAX_VALUE`] bytes is cut, so one hostile path or branch name cannot make a line unbounded. +//! Writes go through a bounded queue to one writer thread, so a stderr that nobody reads cannot freeze +//! request handling (lines are dropped and counted instead). Git hook messages bound for a pushing client (`hook.rs`) are not logs and do not come here. + +use serde_json::{json, Map, Value}; +use std::io::Write; +use std::sync::atomic::{AtomicU64, AtomicUsize, Ordering}; +use std::sync::OnceLock; + +/// The longest string kept in a log line, in bytes. +pub const MAX_VALUE: usize = 512; + +fn clip(s: &str) -> String { + if s.len() <= MAX_VALUE { + return s.to_string(); + } + let mut end = MAX_VALUE; + while !s.is_char_boundary(end) { + end -= 1; + } + format!("{}…", &s[..end]) +} + +/// Render one line (without the newline). Fields may not overwrite `time`, `severity` or `message`. +pub fn render(time: i64, severity: &str, message: &str, fields: Option) -> String { + let mut m = Map::new(); + if let Some(Value::Object(f)) = fields { + for (k, v) in f { + let v = match v { + Value::String(s) => Value::String(clip(&s)), + other => other, + }; + m.insert(k, v); + } + } + m.insert("time".into(), json!(crate::timefmt::rfc3339(time))); + m.insert("severity".into(), json!(severity)); + m.insert("message".into(), json!(clip(message))); + Value::Object(m).to_string() +} + +/// Lines waiting for the writer thread before new ones are dropped. +const QUEUE: usize = 4096; + +struct Sink { + tx: std::sync::mpsc::SyncSender, + pending: AtomicUsize, + dropped: AtomicU64, +} + +fn sink() -> &'static Sink { + static SINK: OnceLock = OnceLock::new(); + SINK.get_or_init(|| { + let (tx, rx) = std::sync::mpsc::sync_channel::(QUEUE); + std::thread::Builder::new() + .name("log-writer".into()) + .spawn(move || { + for line in rx { + // A stderr nobody reads blocks here, not in a request handler. + let _ = std::io::stderr().lock().write_all(line.as_bytes()); + sink().pending.fetch_sub(1, Ordering::SeqCst); + } + }) + .expect("start the log writer"); + Sink { + tx, + pending: AtomicUsize::new(0), + dropped: AtomicU64::new(0), + } + }) +} + +/// Queue one log line for stderr. Never blocks: a stalled log consumer must not stall requests, the +/// drain or signal handling, so when the queue is full the line is dropped and counted (the next +/// line that fits is preceded by a note of how many were lost). +pub fn emit(severity: &str, message: &str, fields: Option) { + let sink = sink(); + let now = crate::timefmt::now(); + let mut line = render(now, severity, message, fields); + // The note about lost lines travels in the same queue entry as the line that follows it, so + // reporting a loss can never use up the slot the current event needs. + let lost = sink.dropped.swap(0, Ordering::SeqCst); + if lost > 0 { + let note = render( + now, + "WARNING", + "log lines were dropped: stderr is not being read", + Some(json!({ "dropped": lost })), + ); + line = format!("{note}\n{line}"); + } + if !enqueue(sink, line) { + sink.dropped.fetch_add(lost + 1, Ordering::SeqCst); + } +} + +fn enqueue(sink: &Sink, mut line: String) -> bool { + line.push('\n'); + sink.pending.fetch_add(1, Ordering::SeqCst); + if sink.tx.try_send(line).is_ok() { + true + } else { + sink.pending.fetch_sub(1, Ordering::SeqCst); + false + } +} + +/// Wait up to two seconds for queued lines to reach stderr (before the process exits). +pub fn flush() { + let end = std::time::Instant::now() + std::time::Duration::from_secs(2); + while sink().pending.load(Ordering::SeqCst) > 0 && std::time::Instant::now() < end { + std::thread::sleep(std::time::Duration::from_millis(5)); + } +} + +/// `INFO` line from a message (for the binary, which cannot use the crate-private macros). +pub fn info_line(message: &str) { + emit("INFO", message, None); +} + +/// `WARNING` line from a message. +pub fn warning_line(message: &str) { + emit("WARNING", message, None); +} + +macro_rules! info { + ($($arg:tt)*) => { $crate::log::emit("INFO", &format!($($arg)*), None) }; +} +macro_rules! warning { + ($($arg:tt)*) => { $crate::log::emit("WARNING", &format!($($arg)*), None) }; +} +macro_rules! error { + ($($arg:tt)*) => { $crate::log::emit("ERROR", &format!($($arg)*), None) }; +} +pub(crate) use {error, info, warning}; + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn a_line_is_one_json_object_with_the_reserved_keys_last() { + let l = render( + 0, + "INFO", + "hello \"world\"\nnext", + Some(json!({"message": "spoof", "status": 200})), + ); + assert!(!l.contains('\n'), "the newline is escaped"); + let v: Value = serde_json::from_str(&l).unwrap(); + assert_eq!(v["message"], "hello \"world\"\nnext"); + assert_eq!(v["severity"], "INFO"); + assert_eq!(v["time"], "1970-01-01T00:00:00Z"); + assert_eq!(v["status"], 200); + } + + #[test] + fn long_values_are_cut_on_a_character_boundary() { + let long = "é".repeat(MAX_VALUE); + let l = render(0, "INFO", &long, Some(json!({"path": long}))); + let v: Value = serde_json::from_str(&l).unwrap(); + assert!(v["path"].as_str().unwrap().len() <= MAX_VALUE + 3); + assert!(v["message"].as_str().unwrap().ends_with('…')); + } + + #[test] + fn a_full_queue_drops_instead_of_blocking() { + // A sink whose writer never runs: after QUEUE lines the next ones are refused, not waited on. + let (tx, _rx) = std::sync::mpsc::sync_channel::(QUEUE); + let sink = Sink { + tx, + pending: AtomicUsize::new(0), + dropped: AtomicU64::new(0), + }; + let started = std::time::Instant::now(); + let kept = (0..QUEUE + 10) + .filter(|i| enqueue(&sink, format!("line {i}"))) + .count(); + assert_eq!(kept, QUEUE); + assert!(started.elapsed() < std::time::Duration::from_secs(2)); + assert_eq!(sink.pending.load(Ordering::SeqCst), QUEUE); + } +} diff --git a/crates/forge/src/main.rs b/crates/forge/src/main.rs index 8dd19a63..97b1a040 100644 --- a/crates/forge/src/main.rs +++ b/crates/forge/src/main.rs @@ -12,7 +12,15 @@ mod cli; #[cfg(unix)] fn main() { if let Err(e) = cli::run() { - eprintln!("sc-forge: {e:#}"); + // `serve` failing (a bind error, a second server, a migration) is a service event: log it + // as one so an alert on severity sees a crash loop. Other commands answer a terminal. + if std::env::args().nth(1).as_deref() == Some("serve") { + scl_forge::log::emit("ERROR", &format!("{e:#}"), None); + } else { + eprintln!("sc-forge: {e:#}"); + } + scl_forge::log::flush(); std::process::exit(1); } + scl_forge::log::flush(); } diff --git a/crates/forge/src/maintenance.rs b/crates/forge/src/maintenance.rs index 751bb4aa..a32836fa 100644 --- a/crates/forge/src/maintenance.rs +++ b/crates/forge/src/maintenance.rs @@ -162,7 +162,7 @@ pub fn spawn(app: Arc) -> std::thread::JoinHandle<()> { continue; } let pass = run_pass(&app); - eprintln!("sc-forge: maintenance pass finished: {pass:?} (requested: {requested})"); + crate::log::info!("maintenance pass finished: {pass:?} (requested: {requested})"); // Not running again before the count moves, so a request that follows an observed // increment is always accepted. m.state().running = false; @@ -178,14 +178,14 @@ pub fn run_pass(app: &App) -> Pass { let conn = match db::connect(&app.data_dir) { Ok(c) => c, Err(e) => { - eprintln!("sc-forge: maintenance cannot open the database: {e}"); + crate::log::warning!("maintenance cannot open the database: {e}"); return pass; } }; let ids: Vec = match repos::list_in_state(&conn, "live") { Ok(r) => r.into_iter().map(|r| r.id).collect(), Err(e) => { - eprintln!("sc-forge: maintenance cannot list the repositories: {e}"); + crate::log::warning!("maintenance cannot list the repositories: {e}"); return pass; } }; @@ -200,18 +200,18 @@ pub fn run_pass(app: &App) -> Pass { after_kib, } => { pass.done += 1; - eprintln!( - "sc-forge: maintenance of repository {id}: {before_kib} KiB -> {after_kib} KiB" + crate::log::info!( + "maintenance of repository {id}: {before_kib} KiB -> {after_kib} KiB" ); } Outcome::Skipped(why) => { pass.skipped += 1; - eprintln!("sc-forge: maintenance of repository {id} skipped: {why}"); + crate::log::warning!("maintenance of repository {id} skipped: {why}"); } Outcome::Gone => {} Outcome::Failed(e) => { pass.failed += 1; - eprintln!("sc-forge: maintenance of repository {id} failed: {e}"); + crate::log::warning!("maintenance of repository {id} failed: {e}"); } } } @@ -290,8 +290,8 @@ pub fn maintain_repo(app: &App, conn: &rusqlite::Connection, id: i64) -> Outcome Ok(Some(Some(_))) => { orphans::remove_dead(&dir); } - Ok(_) => eprintln!( - "sc-forge: repository {id}: stale lock cleanup deferred (a writer may be running)" + Ok(_) => crate::log::warning!( + "repository {id}: stale lock cleanup deferred (a writer may be running)" ), // Optional work: a busy gate must not cost the repository its gc. Err(Outcome::Gone) => return Outcome::Gone, @@ -329,7 +329,7 @@ pub fn maintain_repo(app: &App, conn: &rusqlite::Connection, id: i64) -> Outcome return o; } // Stage 2 does not depend on stage 1: it only removes aged loose objects. - eprintln!("sc-forge: gc of repository {id} failed: {o:?}"); + crate::log::warning!("gc of repository {id} failed: {o:?}"); note = Some("gc failed"); } @@ -337,7 +337,7 @@ pub fn maintain_repo(app: &App, conn: &rusqlite::Connection, id: i64) -> Outcome if let Some(n) = note { // Without a completed stage 1 reachable objects may still be loose and old; git's own gc // does not prune after a failed repack either. - eprintln!("sc-forge: repository {id}: stage 1 did not complete ({n}); nothing pruned"); + crate::log::warning!("repository {id}: stage 1 did not complete ({n}); nothing pruned"); return Outcome::Skipped("stage 1 did not complete"); } let stage2 = || -> Outcome { @@ -358,7 +358,9 @@ pub fn maintain_repo(app: &App, conn: &rusqlite::Connection, id: i64) -> Outcome }; if let Err(e) = roots { // Without every retention ref confirmed, deleting could destroy the only copy. - eprintln!("sc-forge: repository {id}: retention refs could not be reconciled ({e}); nothing pruned"); + crate::log::warning!( + "repository {id}: retention refs could not be reconciled ({e}); nothing pruned" + ); return Outcome::Skipped("retention refs could not be reconciled"); } // A merge intent still pending after the reconcile has a commit only the journal names. diff --git a/crates/forge/src/merges.rs b/crates/forge/src/merges.rs index feda595c..b510cbf2 100644 --- a/crates/forge/src/merges.rs +++ b/crates/forge/src/merges.rs @@ -225,16 +225,16 @@ fn finish( recovered: bool, ) -> Result<(), ComputeError> { if let Err(e) = pulls::retain(git, dir, i.pull_number, &i.head_oid) { - eprintln!( - "sc-forge: could not retain the head of merged pull request {}: {e}", + crate::log::warning!( + "could not retain the head of merged pull request {}: {e}", i.pull_number ); } // The marker goes below; from here on this ref is what keeps the merge commit alive when the // base is rewritten away from it. if let Err(e) = pulls::retain_at(git, dir, &pulls::merge_ref(i.pull_number), &i.merge_oid) { - eprintln!( - "sc-forge: could not retain the merge commit of pull request {}: {e}", + crate::log::warning!( + "could not retain the merge commit of pull request {}: {e}", i.pull_number ); } @@ -542,10 +542,7 @@ fn run(ctx: &Ctx, a: &Access, n: i64, want_head: Option<&str>) -> Resp { if intent_id.is_some() { let (git, dir) = (&ctx.app.life.git, ctx.app.life.repo_dir(a.repo.id)); if let Err(e) = recover_locked(ctx.conn, git, &dir, a.repo.id) { - eprintln!( - "sc-forge: could not settle a merge of repository {}: {e}", - a.repo.id - ); + crate::log::warning!("could not settle a merge of repository {}: {e}", a.repo.id); } } outcome diff --git a/crates/forge/src/orphans.rs b/crates/forge/src/orphans.rs index 184e70e2..bba2c35f 100644 --- a/crates/forge/src/orphans.rs +++ b/crates/forge/src/orphans.rs @@ -210,10 +210,7 @@ fn remove_locks(dir: &Path, depth: usize, min_age: Option) -> usize { && old_enough(&p, min_age) && std::fs::remove_file(&p).is_ok() { - eprintln!( - "sc-forge: removed the ref lock {} left by a killed git", - p.display() - ); + crate::log::info!("removed the ref lock {} left by a killed git", p.display()); n += 1; } } @@ -285,8 +282,8 @@ fn clean_inner(repo: &Path, min_age: Option, rename_only: bool) -> usi std::fs::remove_dir_all(&p).is_ok() } { - eprintln!( - "sc-forge: removed the quarantine {} left by a killed git", + crate::log::info!( + "removed the quarantine {} left by a killed git", p.display() ); n += 1; @@ -316,21 +313,21 @@ pub fn remove_stale_locks(data_dir: &Path) -> usize { pub fn sweep(data_dir: &Path, git_bin: Option<&Path>) -> Swept { let Some((killed, survivors)) = kill_orphan_git(data_dir, std::process::id() as i32, git_bin) else { - eprintln!( - "sc-forge: could not read the process table; leaving any orphaned git writers and ref locks alone" + crate::log::warning!( + "could not read the process table; leaving any orphaned git writers and ref locks alone" ); return Swept::default(); }; let locks = if survivors == 0 { remove_stale_locks(data_dir) } else { - eprintln!( - "sc-forge: {survivors} orphaned git process(es) would not die; leaving the ref locks in place" + crate::log::warning!( + "{survivors} orphaned git process(es) would not die; leaving the ref locks in place" ); 0 }; if killed + locks > 0 { - eprintln!("sc-forge: startup cleanup killed {killed} orphaned git process(es) and removed {locks} stale lock(s)"); + crate::log::info!("startup cleanup killed {killed} orphaned git process(es) and removed {locks} stale lock(s)"); } Swept { killed, locks } } diff --git a/crates/forge/src/pulls.rs b/crates/forge/src/pulls.rs index a5830334..3fd3394e 100644 --- a/crates/forge/src/pulls.rs +++ b/crates/forge/src/pulls.rs @@ -568,7 +568,7 @@ pub fn sync_locked( // One PR that cannot be synced (a git failure on its ref) must not keep the others from it. match sync_one(conn, git, dir, p, &kept, &heads, now) { Ok(c) => closed += usize::from(c), - Err(e) => eprintln!("sc-forge: could not sync pull request {number}: {e}"), + Err(e) => crate::log::warning!("could not sync pull request {number}: {e}"), } } Ok(closed) @@ -722,14 +722,14 @@ pub fn sync(life: &Lifecycle, conn: &Connection, repo_id: i64, now: i64) { }) { Ok(WriteRun::Ran(Ok(_))) | Ok(WriteRun::Gone) => {} Ok(WriteRun::Ran(Err(e))) => { - eprintln!("sc-forge: pull request sync of repository {repo_id} failed: {e}") + crate::log::warning!("pull request sync of repository {repo_id} failed: {e}") } Ok(WriteRun::Busy) => { - eprintln!( - "sc-forge: pull request sync of repository {repo_id} skipped: repository busy" + crate::log::warning!( + "pull request sync of repository {repo_id} skipped: repository busy" ) } - Err(e) => eprintln!("sc-forge: pull request sync of repository {repo_id} failed: {e}"), + Err(e) => crate::log::warning!("pull request sync of repository {repo_id} failed: {e}"), } } @@ -741,16 +741,13 @@ pub fn reconcile_all(life: &Lifecycle, conn: &Connection, now: i64) { let repos = match crate::repos::list_in_state(conn, "live") { Ok(v) => v, Err(e) => { - eprintln!("sc-forge: pull request reconcile could not list repositories: {e}"); + crate::log::warning!("pull request reconcile could not list repositories: {e}"); return; } }; for r in repos { if let Err(e) = reconcile_repo(conn, &life.git, &life.repo_dir(r.id), r.id, now) { - eprintln!( - "sc-forge: pull request reconcile of repository {} failed: {e}", - r.id - ); + crate::log::warning!("pull request reconcile of repository {} failed: {e}", r.id); } } } diff --git a/crates/forge/src/pulls_api.rs b/crates/forge/src/pulls_api.rs index 7ab4ed8c..706c20fe 100644 --- a/crates/forge/src/pulls_api.rs +++ b/crates/forge/src/pulls_api.rs @@ -292,10 +292,7 @@ fn converge(ctx: &Ctx, a: &Access) { pub(crate) fn sync_held(ctx: &Ctx, a: &Access) { if let Err(e) = pulls::sync_locked(ctx.conn, &ctx.app.life.git, &dir(ctx, a), a.repo.id, now()) { - eprintln!( - "sc-forge: pull request sync of repository {} failed: {e}", - a.repo.id - ); + crate::log::warning!("pull request sync of repository {} failed: {e}", a.repo.id); } } diff --git a/crates/forge/src/repo_api.rs b/crates/forge/src/repo_api.rs index fc250d57..92884c49 100644 --- a/crates/forge/src/repo_api.rs +++ b/crates/forge/src/repo_api.rs @@ -203,9 +203,11 @@ fn listed(ctx: &Ctx, rows: &[Repo]) -> Result, Resp> { )) } Ok(Some(Err(e))) => { - eprintln!( - "sc-forge: cannot read {}/{} (id {}): {e}; listed as empty", - r.owner, r.name, r.id + crate::log::warning!( + "cannot read {}/{} (id {}): {e}; listed as empty", + r.owner, + r.name, + r.id ); true } diff --git a/crates/forge/src/routes.rs b/crates/forge/src/routes.rs index 3ea02ceb..0184bbf7 100644 --- a/crates/forge/src/routes.rs +++ b/crates/forge/src/routes.rs @@ -56,7 +56,7 @@ impl App { /// Log the detail, answer a bare 500: database errors never reach clients. pub fn internal(&self, e: &dyn std::fmt::Display) -> Resp { - eprintln!("sc-forge: internal error: {e}"); + crate::log::error!("internal error: {e}"); error(&self.base, 500, "internal server error") } } diff --git a/crates/forge/src/server.rs b/crates/forge/src/server.rs index 20e610ab..4752f6b1 100644 --- a/crates/forge/src/server.rs +++ b/crates/forge/src/server.rs @@ -60,11 +60,51 @@ pub fn bind_gate( )) } +/// Answer one request and write its access-log line: method, path without the query (a query may +/// carry anything), status, time to the response head (a git transfer streams after that), and the +/// client address. Never a header or a body. Successful health probes are not logged. async fn handle( app: Arc, limits: Limits, peer: IpAddr, req: Request, +) -> Result, std::convert::Infallible> { + let started = std::time::Instant::now(); + let method = req.method().as_str().to_string(); + let path = req.uri().path().to_string(); + let source = app.proxies.resolve( + peer, + app.proxies + .header + .as_deref() + .and_then(|h| req.headers().get(h)) + .and_then(|v| v.to_str().ok()), + ); + let resp = handle_request(app, limits, peer, req).await; + if let Ok(r) = &resp { + let status = r.status().as_u16(); + if !(status == 200 && matches!(path.as_str(), "/healthz" | "/api/healthz")) { + crate::log::emit( + if status >= 500 { "ERROR" } else { "INFO" }, + "request", + Some(serde_json::json!({ + "method": method, + "path": path, + "status": status, + "ms": started.elapsed().as_millis() as u64, + "source": source.to_string(), + })), + ); + } + } + resp +} + +async fn handle_request( + app: Arc, + limits: Limits, + peer: IpAddr, + req: Request, ) -> Result, std::convert::Infallible> { let (parts, body) = req.into_parts(); let headers = parts @@ -262,6 +302,7 @@ pub async fn serve( ) { let slots = Arc::new(Semaphore::new(limits.max_connections)); let mut conns = JoinSet::new(); + let (stop_tx, stop_rx) = tokio::sync::watch::channel(false); tokio::pin!(shutdown); loop { tokio::select! { @@ -275,16 +316,29 @@ pub async fn serve( let Ok(permit) = slots.clone().try_acquire_owned() else { continue }; let (app, limits) = (app.clone(), limits.clone()); let header_timeout = limits.header_timeout; + let mut stop = stop_rx.clone(); conns.spawn(async move { let svc = service_fn(move |req| handle(app.clone(), limits.clone(), peer.ip(), req)); let mut http = hyper::server::conn::http1::Builder::new(); http.timer(TokioTimer::new()).header_read_timeout(header_timeout); - let _ = http.serve_connection(TokioIo::new(stream), svc).await; + let conn = http.serve_connection(TokioIo::new(stream), svc); + tokio::pin!(conn); + tokio::select! { + _ = conn.as_mut() => {} + _ = stop.changed() => { + // Finish the request in flight, close an idle keep-alive at once. + conn.as_mut().graceful_shutdown(); + let _ = conn.await; + } + } drop(permit); }); } } } + // No new connection from here on: the listening socket closes now, not when the drain ends. + drop(listener); + let _ = stop_tx.send(true); let _ = tokio::time::timeout(drain, async { while conns.join_next().await.is_some() {} }).await; // Whatever git is still running at the deadline ends now; wait for the children to be reaped. let registry = app.life.registry.clone(); diff --git a/crates/forge/src/transport.rs b/crates/forge/src/transport.rs index 5bfd5935..19e022c2 100644 --- a/crates/forge/src/transport.rs +++ b/crates/forge/src/transport.rs @@ -301,7 +301,7 @@ pub fn authorize(app: &App, req: &Req, path: GitPath) -> Result { } fn internal(app: &App, e: &dyn std::fmt::Display) -> Resp { - eprintln!("sc-forge: internal error: {e}"); + crate::log::error!("internal error: {e}"); let _ = app; text(500, "internal server error\n") } diff --git a/crates/forge/tests/e2e_ops.rs b/crates/forge/tests/e2e_ops.rs new file mode 100644 index 00000000..a90b5bb3 --- /dev/null +++ b/crates/forge/tests/e2e_ops.rs @@ -0,0 +1,499 @@ +//! F5b: the operating surface of a real `sc-forge serve` process: the SIGTERM drain, the bind +//! gate and the log lines. +#![cfg(unix)] + +use serde_json::Value; +use std::io::{Read, Write}; +use std::net::TcpStream; +use std::path::{Path, PathBuf}; +use std::process::{Child, Command, ExitStatus, Stdio}; +use std::time::{Duration, Instant}; + +const BIN: &str = env!("CARGO_BIN_EXE_sc-forge"); + +struct Tmp(PathBuf); +impl Drop for Tmp { + fn drop(&mut self) { + let _ = std::fs::remove_dir_all(&self.0); + } +} + +fn tmp(tag: &str) -> Tmp { + let d = std::env::temp_dir().join(format!("scl-forge-ops-{tag}-{}", std::process::id())); + let _ = std::fs::remove_dir_all(&d); + std::fs::create_dir_all(&d).unwrap(); + Tmp(d) +} + +fn free_port() -> u16 { + std::net::TcpListener::bind("127.0.0.1:0") + .unwrap() + .local_addr() + .unwrap() + .port() +} + +struct Proc { + child: Child, + port: u16, + log: PathBuf, +} + +impl Proc { + /// Start `serve` on a free loopback port with `extra` flags and wait for `/healthz`. + fn start(root: &Path, extra: &[&str]) -> Proc { + let data = root.join("data"); + let port = free_port(); + let log = root.join("stderr.log"); + let child = Command::new(BIN) + .args(["serve", "--data-dir"]) + .arg(&data) + .args([ + "--listen", + &format!("127.0.0.1:{port}"), + "--public-url", + &format!("http://127.0.0.1:{port}"), + ]) + .args(extra) + .stdout(Stdio::null()) + .stderr(std::fs::File::create(&log).unwrap()) + .spawn() + .expect("start sc-forge"); + let p = Proc { child, port, log }; + let t0 = Instant::now(); + while t0.elapsed() < Duration::from_secs(30) { + if p.get("/api/healthz", None).is_some_and(|(s, _)| s == 200) { + return p; + } + std::thread::sleep(Duration::from_millis(50)); + } + panic!("sc-forge did not come up: {}", p.stderr()); + } + + fn stderr(&self) -> String { + std::fs::read_to_string(&self.log).unwrap_or_default() + } + + fn get(&self, path: &str, token: Option<&str>) -> Option<(u16, String)> { + self.send("GET", path, token, None) + } + + fn send( + &self, + method: &str, + path: &str, + token: Option<&str>, + body: Option<&Value>, + ) -> Option<(u16, String)> { + let mut s = TcpStream::connect(("127.0.0.1", self.port)).ok()?; + s.set_read_timeout(Some(Duration::from_secs(20))).ok()?; + let b = body.map(Value::to_string).unwrap_or_default(); + let mut head = format!("{method} {path} HTTP/1.1\r\nHost: x\r\nConnection: close\r\n"); + if let Some(t) = token { + head += &format!("Authorization: token {t}\r\n"); + } + if body.is_some() { + head += &format!( + "Content-Type: application/json\r\nContent-Length: {}\r\n", + b.len() + ); + } + s.write_all(format!("{head}\r\n{b}").as_bytes()).ok()?; + let mut buf = Vec::new(); + s.read_to_end(&mut buf).ok()?; + let text = String::from_utf8_lossy(&buf).to_string(); + let (h, rest) = text.split_once("\r\n\r\n")?; + Some((h.split(' ').nth(1)?.parse().ok()?, rest.to_string())) + } + + fn sigterm(&self) { + // SAFETY: SIGTERM to the server this test spawned. + unsafe { libc::kill(self.child.id() as i32, libc::SIGTERM) }; + } + + /// Wait for the process to exit, at most `limit`. + fn wait(&mut self, limit: Duration) -> Option { + let t0 = Instant::now(); + while t0.elapsed() < limit { + if let Ok(Some(st)) = self.child.try_wait() { + return Some(st); + } + std::thread::sleep(Duration::from_millis(20)); + } + None + } +} + +impl Drop for Proc { + fn drop(&mut self) { + let _ = self.child.kill(); + let _ = self.child.wait(); + } +} + +/// Create the site admin (as Engine's bootstrap does) and return an all-scope token. +fn bootstrap(root: &Path) -> String { + let data = root.join("data"); + scl_forge::admin::user_create( + &data, + "siteadmin", + &scl_crypto::generate_token(), + "admin@example.invalid", + true, + false, + ) + .unwrap(); + scl_forge::admin::generate_access_token(&data, "siteadmin", "boot", &["all".to_string()]) + .unwrap() +} + +#[test] +fn sigterm_closes_idle_connections_refuses_new_ones_and_exits_zero() { + let root = tmp("idle"); + let mut p = Proc::start(&root.0, &["--shutdown-timeout", "3"]); + // A keep-alive client that went idle after its request. + let mut idle = TcpStream::connect(("127.0.0.1", p.port)).unwrap(); + idle.write_all(b"GET /api/healthz HTTP/1.1\r\nHost: x\r\n\r\n") + .unwrap(); + idle.set_read_timeout(Some(Duration::from_secs(5))).unwrap(); + let mut buf = [0u8; 1024]; + assert!(idle.read(&mut buf).unwrap() > 0, "the first response"); + // A stalled request keeps the drain open, so what follows is observed while the server is still up. + let mut stalled = TcpStream::connect(("127.0.0.1", p.port)).unwrap(); + stalled + .write_all( + b"POST /api/v1/user/repos HTTP/1.1\r\nHost: x\r\nContent-Type: application/json\r\nContent-Length: 100\r\n\r\n{", + ) + .unwrap(); + std::thread::sleep(Duration::from_millis(300)); + p.sigterm(); + // Closed by the server at once, not after the drain deadline. + let t0 = Instant::now(); + let mut rest = Vec::new(); + let _ = idle.read_to_end(&mut rest); + assert!( + t0.elapsed() < Duration::from_secs(5), + "an idle keep-alive connection must not hold the drain" + ); + let refused = (0..100).any(|_| { + std::thread::sleep(Duration::from_millis(30)); + TcpStream::connect(("127.0.0.1", p.port)).is_err() + }); + assert!(refused, "the listening socket closes when the drain starts"); + assert!( + p.child.try_wait().unwrap().is_none(), + "the server is still draining the stalled request" + ); + let st = p.wait(Duration::from_secs(20)).expect("exits"); + assert!(st.success(), "{st:?}"); + drop(stalled); +} + +#[test] +fn sigterm_lets_a_request_in_flight_finish() { + let root = tmp("flight"); + let token = bootstrap(&root.0); + let mut p = Proc::start(&root.0, &[]); + let body = r#"{"name":"drained","auto_init":true}"#; + let mut s = TcpStream::connect(("127.0.0.1", p.port)).unwrap(); + s.set_read_timeout(Some(Duration::from_secs(20))).unwrap(); + let head = format!( + "POST /api/v1/user/repos HTTP/1.1\r\nHost: x\r\nConnection: close\r\nAuthorization: token {token}\r\nContent-Type: application/json\r\nContent-Length: {}\r\n\r\n", + body.len() + ); + s.write_all(head.as_bytes()).unwrap(); + s.write_all(&body.as_bytes()[..10]).unwrap(); + std::thread::sleep(Duration::from_millis(300)); + p.sigterm(); + std::thread::sleep(Duration::from_millis(500)); + s.write_all(&body.as_bytes()[10..]).unwrap(); + let mut resp = String::new(); + s.read_to_string(&mut resp).unwrap(); + assert!(resp.starts_with("HTTP/1.1 201"), "{resp}"); + let st = p.wait(Duration::from_secs(15)).expect("exits after it"); + assert!(st.success(), "{st:?}"); +} + +#[test] +fn a_stalled_request_does_not_hold_the_shutdown_past_its_deadline() { + let root = tmp("stall"); + let token = bootstrap(&root.0); + let mut p = Proc::start(&root.0, &["--shutdown-timeout", "2"]); + let mut s = TcpStream::connect(("127.0.0.1", p.port)).unwrap(); + s.write_all( + format!( + "POST /api/v1/user/repos HTTP/1.1\r\nHost: x\r\nAuthorization: token {token}\r\nContent-Type: application/json\r\nContent-Length: 100\r\n\r\n{{" + ) + .as_bytes(), + ) + .unwrap(); + std::thread::sleep(Duration::from_millis(300)); + let t0 = Instant::now(); + p.sigterm(); + let st = p.wait(Duration::from_secs(20)).expect("exits"); + assert!(st.success(), "{st:?}"); + assert!( + t0.elapsed() < Duration::from_secs(10), + "exit took {:?}", + t0.elapsed() + ); + drop(s); +} + +fn serve_with(tag: &str, listen: &str, extra: &[&str]) -> (Child, Tmp) { + let root = tmp(tag); + let child = Command::new(BIN) + .args(["serve", "--data-dir"]) + .arg(root.0.join("data")) + .args([ + "--listen", + listen, + "--public-url", + "https://git.example.test", + ]) + .args(extra) + .stdout(Stdio::null()) + .stderr(Stdio::piped()) + .spawn() + .unwrap(); + (child, root) +} + +#[test] +fn a_public_plaintext_bind_is_refused_unless_the_operator_says_otherwise() { + for listen in ["0.0.0.0:0", "[::]:0", "10.1.2.3:0", "[::ffff:127.0.0.1]:0"] { + let (child, _root) = serve_with("refused", listen, &[]); + let out = child.wait_with_output().unwrap(); + assert!(!out.status.success(), "{listen} must be refused"); + let err = String::from_utf8_lossy(&out.stderr); + assert!( + err.contains("--behind-proxy") && err.contains("--allow-plaintext"), + "{listen}: {err}" + ); + } +} + +/// Start `serve` with its stderr in a file; returns once it logs "listening on" (or fails the test). +fn serve_to_file(tag: &str, listen: &str, extra: &[&str]) -> (Child, PathBuf, Tmp) { + let root = tmp(tag); + let log = root.0.join("stderr.log"); + let mut child = Command::new(BIN) + .args(["serve", "--data-dir"]) + .arg(root.0.join("data")) + .args([ + "--listen", + listen, + "--public-url", + "https://git.example.test", + ]) + .args(extra) + .stdout(Stdio::null()) + .stderr(std::fs::File::create(&log).unwrap()) + .spawn() + .unwrap(); + let t0 = Instant::now(); + loop { + if std::fs::read_to_string(&log).is_ok_and(|t| t.contains("listening on")) { + return (child, log, root); + } + if let Some(st) = child.try_wait().unwrap() { + panic!( + "{listen} {extra:?} exited early ({st:?}): {}", + std::fs::read_to_string(&log).unwrap_or_default() + ); + } + assert!( + t0.elapsed() < Duration::from_secs(30), + "{listen} never listened" + ); + std::thread::sleep(Duration::from_millis(25)); + } +} + +fn stop(mut child: Child) -> ExitStatus { + // SAFETY: SIGTERM to the child this test spawned. + unsafe { libc::kill(child.id() as i32, libc::SIGTERM) }; + let t0 = Instant::now(); + loop { + if let Some(st) = child.try_wait().unwrap() { + return st; + } + if t0.elapsed() > Duration::from_secs(20) { + let _ = child.kill(); + let _ = child.wait(); + panic!("no exit after SIGTERM"); + } + std::thread::sleep(Duration::from_millis(20)); + } +} + +#[test] +fn the_flags_that_allow_a_public_bind_do_start_the_server() { + for (i, flags) in [&["--behind-proxy"][..], &["--allow-plaintext"][..]] + .into_iter() + .enumerate() + { + let (child, _log, _root) = serve_to_file(&format!("allowed{i}"), "0.0.0.0:0", flags); + let st = stop(child); + assert!(st.success(), "{flags:?}: {st:?}"); + } +} + +#[test] +fn loopback_binds_need_no_flag() { + let mut addrs = vec!["127.0.0.1:0"]; + // A host without IPv6 cannot bind [::1] whatever the gate says. + if std::net::TcpListener::bind("[::1]:0").is_ok() { + addrs.push("[::1]:0"); + } + for (i, listen) in addrs.into_iter().enumerate() { + let (child, _log, _root) = serve_to_file(&format!("loop{i}"), listen, &[]); + assert!(stop(child).success(), "{listen}"); + } +} + +#[test] +fn a_log_consumer_that_stops_reading_does_not_stall_the_server() { + let root = tmp("stuck"); + let data = root.0.join("data"); + let port = free_port(); + // stderr is a pipe nobody reads: once it is full, log writes block. + let mut child = Command::new(BIN) + .args(["serve", "--data-dir"]) + .arg(&data) + .args([ + "--listen", + &format!("127.0.0.1:{port}"), + "--public-url", + &format!("http://127.0.0.1:{port}"), + ]) + .stdout(Stdio::null()) + .stderr(Stdio::piped()) + .spawn() + .unwrap(); + let get = |path: &str| -> Option { + let mut s = TcpStream::connect(("127.0.0.1", port)).ok()?; + s.set_read_timeout(Some(Duration::from_secs(10))).ok()?; + s.write_all( + format!("GET {path} HTTP/1.1\r\nHost: x\r\nConnection: close\r\n\r\n").as_bytes(), + ) + .ok()?; + let mut b = String::new(); + s.read_to_string(&mut b).ok()?; + b.split(' ').nth(1)?.parse().ok() + }; + let t0 = Instant::now(); + while get("/api/healthz") != Some(200) { + assert!(t0.elapsed() < Duration::from_secs(30), "no start"); + std::thread::sleep(Duration::from_millis(50)); + } + // Far more request lines than a pipe (64 KiB) plus the log queue (4096 lines) can hold. + std::thread::scope(|sc| { + for _ in 0..8 { + sc.spawn(|| { + for _ in 0..800 { + let _ = get("/nope"); + } + }); + } + }); + assert_eq!( + get("/api/healthz"), + Some(200), + "the server must still answer" + ); + // SAFETY: SIGTERM to the child this test spawned. + unsafe { libc::kill(child.id() as i32, libc::SIGTERM) }; + let t0 = Instant::now(); + let st = loop { + if let Some(st) = child.try_wait().unwrap() { + break st; + } + if t0.elapsed() > Duration::from_secs(20) { + let _ = child.kill(); + panic!("the drain hung behind a blocked log pipe"); + } + std::thread::sleep(Duration::from_millis(20)); + }; + assert!(st.success(), "{st:?}"); +} + +#[test] +fn logs_are_json_lines_and_carry_no_secret() { + let root = tmp("logs"); + let token = bootstrap(&root.0); + let mut p = Proc::start(&root.0, &[]); + let password = "correct-horse-battery-staple-9f3"; + // A wrong password, a query that would carry a token if one were accepted there, a good call + // with the token, a missing route, and a git clone with the token as the password. + let basic = scl_forge::b64::encode(format!("siteadmin:{password}").as_bytes()); + let mut s = TcpStream::connect(("127.0.0.1", p.port)).unwrap(); + s.write_all( + format!( + "GET /api/v1/user HTTP/1.1\r\nHost: x\r\nConnection: close\r\nAuthorization: Basic {basic}\r\n\r\n" + ) + .as_bytes(), + ) + .unwrap(); + let mut sink = Vec::new(); + let _ = s.read_to_end(&mut sink); + p.get( + &format!("/api/v1/version?access_token={token}&token={token}"), + None, + ); + p.get("/api/v1/user", Some(&token)); + p.get("/nope", None); + let made = p + .send( + "POST", + "/api/v1/user/repos", + Some(&token), + Some(&serde_json::json!({"name": "logged", "auto_init": true})), + ) + .unwrap(); + assert_eq!(made.0, 201, "{}", made.1); + let url = format!( + "http://siteadmin:{token}@127.0.0.1:{}/siteadmin/logged.git", + p.port + ); + let dest = root.0.join("clone"); + let cloned = Command::new("git") + .args(["clone", "-q", &url]) + .arg(&dest) + .env("GIT_CONFIG_GLOBAL", "/dev/null") + .env("GIT_CONFIG_NOSYSTEM", "1") + .env("GIT_TERMINAL_PROMPT", "0") + .output() + .unwrap(); + assert!( + cloned.status.success(), + "{}", + String::from_utf8_lossy(&cloned.stderr) + ); + p.sigterm(); + assert!(p.wait(Duration::from_secs(15)).is_some()); + let log = p.stderr(); + assert!(!log.is_empty()); + let mut requests = 0; + for line in log.lines() { + let v: Value = + serde_json::from_str(line).unwrap_or_else(|e| panic!("not a JSON line ({e}): {line}")); + for k in ["time", "severity", "message"] { + assert!(v[k].is_string(), "{k} missing: {line}"); + } + if v["message"] == "request" { + requests += 1; + assert!(v["status"].is_u64() && v["ms"].is_u64(), "{line}"); + assert!(!v["path"].as_str().unwrap().contains('?'), "{line}"); + } + } + assert!(requests >= 5, "{requests} request lines:\n{log}"); + for secret in [token.as_str(), password, basic.as_str()] { + assert!(!log.contains(secret), "a secret reached the log"); + } + assert!( + !log.contains("/api/healthz"), + "successful health probes are not logged" + ); + assert!(log.contains("listening on"), "{log}"); +} diff --git a/docs/FORGE-OPERATIONS.md b/docs/FORGE-OPERATIONS.md new file mode 100644 index 00000000..961b97cf --- /dev/null +++ b/docs/FORGE-OPERATIONS.md @@ -0,0 +1,106 @@ +# Running sc-forge + +`sc-forge` is the Git forge of P38 (a Gitea-compatible replacement for Codento Engine). This guide is for whoever runs it. Design +is in `docs/superpowers/specs/2026-10-22-p38-forge-design.md`, the security boundaries in `docs/THREAT-MODEL.md` (the `sc-forge` +sections). Numbers marked *estimate* were derived from the code, not measured under load. + +## Image + +```sh +docker build -f crates/forge/Dockerfile -t sc-forge . # from the repository root +bash crates/forge/docker/smoke.sh sc-forge # boot, healthz, create, clone, docker stop -> exit 0 +``` + +Debian trixie with git 2.47 or newer (the server needs 2.40: `merge-tree --write-tree`, and it refuses to start on older git), no +sshd, `tini` as PID 1 (without an init process, git children that outlive a killed transport stay zombies and use up `pids.max`; outside this image use `docker run --init` or your orchestrator's equivalent), runs as uid 10001 with `/data` as the only writable volume. Base images are pinned by digest in the Dockerfile. The default command only +prints help: pass `serve ...` (below). A Debian security update of git reaches you by rebuilding without the layer cache: `docker build --pull --no-cache ...`. + +Bootstrap, as Engine does it: + +```sh +sc-forge admin user create --data-dir /data --username --password --email --admin --must-change-password=false +sc-forge admin user generate-access-token --data-dir /data --username --token-name bootstrap --scopes all --raw +``` + +## Serving + +```sh +sc-forge serve --data-dir /data --listen 0.0.0.0:3000 --behind-proxy \ + --public-url https://git.example.com \ + --trusted-proxy-header X-Forwarded-For --trusted-proxies 10.0.0.0/8 +``` + +- **TLS is not in the binary.** A non-loopback `--listen` is refused unless you pass `--behind-proxy` (a TLS-terminating proxy + fronts it) or `--allow-plaintext`. Behind a proxy also pass `--trusted-proxy-header` and `--trusted-proxies`, otherwise every client + shares the proxy's address and the per-source password-failure budget (30 per minute) applies to all of them together. +- **One server per data directory** (a lock file); a second one exits at once. +- **Probes.** `GET /api/healthz` (also `/healthz`) is 200 when the database and every table answer, 503 otherwise. Use it for + liveness and readiness. +- **Flags** (defaults in `sc-forge serve --help`): connection and body limits (`--max-connections`, `--max-body-bytes`), git + concurrency (`--git-concurrency`, `--max-transports`, `--max-transports-per-repo`, `--admission-wait`), transfer bounds + (`--git-timeout`, `--git-idle-timeout`, `--max-pack-size`, `--max-request-bytes`, `--git-memory-limit`), disk (`--min-free-bytes`, + `--push-reserve`), password hashing (`--argon2-concurrency`), maintenance (below) and `--shutdown-timeout`. Duration flags take + seconds, 0 is refused where it would mean "no limit", and maintenance durations are capped at ten years. + +## Stopping + +SIGTERM (or SIGINT) closes the listening socket, closes idle keep-alive connections, lets requests in flight finish for up to +`--shutdown-timeout` seconds (default 30), then cancels the git transports and maintenance runs still going (SIGTERM, then SIGKILL after a second) and +waits up to 10 s for them to be reaped. Exit code 0. A second signal is ignored (only SIGKILL ends the drain early); the longest +stop is `--shutdown-timeout` + 12 s. API-side git (contents writes, merges) is not cancelled; merges are journalled and settle at the next start. Set the orchestrator's grace period to `--shutdown-timeout` plus about 15 s +(Kubernetes `terminationGracePeriodSeconds`, `docker stop -t`). The listening socket closes at once, while a load balancer +or Service takes a few seconds to stop sending traffic: add a `preStop` sleep of a few seconds. A SIGKILL is also safe: the next start kills orphaned git processes +of the data directory, removes their ref locks and quarantine directories, and settles interrupted creates, deletes and merges +(`docs/THREAT-MODEL.md`, F2a and F4c). + +## Logs + +One JSON object per line on stderr, shaped for Cloud Logging: `time` (RFC 3339 UTC), `severity` (`INFO`, `WARNING`, `ERROR`) and +`message`, plus fields. A `serve` that fails to start (bind, second server, migration) logs its error the same way; a Rust panic +still prints plain text. Every request except a successful health probe logs `message: "request"` with `method`, `path` (no query +string), `status`, `ms` (to the response head; a git transfer streams after it) and `source` (the client address after the trusted-proxy +rule). Lines go through a bounded queue to one writer thread: if nothing reads stderr, lines are dropped (and counted in the next +line that fits) rather than stalling requests. Headers, bodies, credentials and query strings are never logged, and a string longer than 512 bytes is cut. Operator +commands (`admin ...`) print plain text to stdout and stderr, not log lines. + +## Maintenance (garbage collection) + +Aborted merges, refused writes and force-pushed history leave unreferenced objects; the server collects them itself. + +- `--maintenance-interval` seconds (default 86400, 0 = off) and `POST /api/v1/admin/cron/git_gc_repos` (site admin, `admin` write + scope; 204 at once, the pass runs in the background, one at a time). Both are logged. +- Stage 1 repacks (`git gc --prune=never`), stage 2 prunes unreferenced objects older than `--gc-prune-expire` (default 14 days; + not below twice `--git-timeout` and an hour). Writers to the repository can wait on its write gate while stage 2 runs + (`--gc-timeout` bounds stage 1, the prune has its own 10-minute limit). +- Stage 1 needs free disk of about the repository's size plus `--min-free-bytes`; below that the repository is skipped and not pruned. + Unreachable objects are stored loose until pruned (no cruft packs), so a history that is rewritten often costs disk for up to + `--gc-prune-expire`. +- A pass also removes stale ref locks, commit-graph locks and quarantine directories of killed git processes, only when nothing can + own them. + +## Resource limits (cgroups) + +The server bounds its own git children (timeouts, `RLIMIT_CPU`/`RLIMIT_FSIZE`, output caps, `--git-memory-limit` as `RLIMIT_DATA` on +Linux only). Those are per-process; the hard bound for the whole service is the container's cgroup. Starting points, *estimates*: + +| Limit | Basis | Starting value | +|---|---|---| +| `pids.max` | per transport about 8 processes (http-backend, upload-pack or receive-pack, pack-objects or index-pack, the hook, helpers) plus up to 4 pack threads each (`pack.threads` is pinned to 4 for transports; maintenance uses 2), `--git-concurrency` x 4 for API-side git, up to `--max-connections` request threads, 64 spare | `12 x max_transports + 4 x git_concurrency + max_connections + 64` = 1376 with the defaults | +| `memory.max` | a transport needs a few hundred MiB for a large repository, a maintenance pass about 0.5 GiB more (`pack.windowMemory` 256 MiB x 2 threads), each password check holds the Argon2 memory (about 19 MiB with the crate defaults) x `--argon2-concurrency`, the server itself under 100 MiB | 4 GiB with `--max-transports 16`; scale the transports with the memory, not the other way round | +| `cpu.max` | git packing is CPU bound; no hard need | 2 to 4 CPUs | +| disk | repositories grow without a quota (per-owner quotas are not built); `--min-free-bytes` and `--push-reserve` refuse pushes before the disk fills | a volume you can grow; alert at 80% | + +The default `--git-memory-limit` (8 GiB per child) is far above any sensible `memory.max / max_transports`: set it explicitly +below that quotient or the cgroup OOM-kills first. A cgroup OOM kill of a git child +behaves like any killed git process (the transfer fails, the next maintenance pass or start cleans up). + +## Backup and restore + +State is `/data/forge.db` (SQLite, WAL) and `/data/repos/.git`. Take them together: stop the server (or take a filesystem +snapshot of the volume) so the database and the repositories are from the same moment. A restore starts the server, which +reconciles rows and directories (creates, deletes, pull-request retention refs). Not tested end to end. + +## Upgrades + +Migrations run forward at start and are never undone; keep a backup before upgrading. The hooks directory is rewritten at every +start. Do not run two versions against one data directory. diff --git a/docs/THREAT-MODEL.md b/docs/THREAT-MODEL.md index 1912fb40..a7bb0f24 100644 --- a/docs/THREAT-MODEL.md +++ b/docs/THREAT-MODEL.md @@ -1144,6 +1144,29 @@ why each deletion is safe: `--min-free-bytes` plus that size). Writers to a repository wait on the gate (10 s) while stage 2 runs and see 503 if it outlasts that; stage 2 is a reachability walk and a scan of loose objects, not a repack. +### Operating surface: logs, shutdown, bind gate, image (F5b) + +- **Logs carry no secret by construction.** `log.rs` writes JSON lines; the access log records method, path without query, status, + duration and client address, never a header, body or query (a query could carry a token a client wrongly sends). Strings are cut + at 512 bytes and JSON-escaped, so a hostile path or branch name cannot forge a line or grow one. A test sends a wrong password, a + token in the query and in the clone URL, and asserts none of them appears in the output, that every line parses, and that + health probes stay out. Limits: an error text from SQLite or git is logged as it comes (they have not been seen to echo + credentials); a repository, branch or user name appears in paths and messages by design. +- **Shutdown.** SIGTERM closes the listening socket first (a restarting service is refused rather than left hanging in the backlog), + closes idle keep-alive connections at once (they used to hold the drain for the whole deadline), lets requests in flight finish up + to `--shutdown-timeout`, then cancels the git processes still running. The signal handlers are installed before the "listening" + line, so a supervisor that stops the service as soon as it is up still gets the drain. A stalled request does not hold the exit past + the deadline plus up to ten seconds for the cancelled git processes to be reaped and the runtime's two-second teardown. Log + writes cannot hold it either: they go through a bounded queue and a writer thread, and a stderr nobody reads costs dropped lines, + not a frozen server (a test fills a pipe with 6400 requests). Not covered by a test: a git transfer in flight across SIGTERM + (the order `drop(listener)`, stop signal, drain, `cancel_all` is source-reviewed). +- **Bind gate.** Process tests pin it: `0.0.0.0`, `[::]`, a private address and a v4-mapped loopback are refused without + `--behind-proxy` or `--allow-plaintext`; loopback needs no flag. Fail-closed on an address it cannot classify. +- **Image.** Base images pinned by digest; trixie git (2.47) because the server needs 2.40 and bookworm has 2.39; runs as uid 10001; no + sshd or shell tooling added. The image build is an advisory CI job with a smoke test, not a required check. Not done: scanning + the image for known vulnerabilities, signing it, a read-only root filesystem (the server writes only under `/data` and, through + git, `/data/tmp`; untested with a read-only root). + ## Reporting Security reports go to **toni@git-agentic.com** or GitHub private vulnerability diff --git a/docs/superpowers/specs/2026-10-22-p38-forge-design.md b/docs/superpowers/specs/2026-10-22-p38-forge-design.md index 30697ddb..1403b00f 100644 --- a/docs/superpowers/specs/2026-10-22-p38-forge-design.md +++ b/docs/superpowers/specs/2026-10-22-p38-forge-design.md @@ -905,6 +905,18 @@ F3b is the write half of the content API (plan: `docs/superpowers/plans/2026-10- deterministic interfering writer); the F4 `refs/forge/pull//head` refresh for a contents write to a PR branch; portable-name collision rules; a disk reservation sized to the exact rebuilt trees. +### F5b decisions (as built) + +The operating half of F5 (guide: `docs/FORGE-OPERATIONS.md`; threat model: "Operating surface"). + +- **Logs.** JSON lines on stderr with `time`, `severity`, `message` (Cloud Logging keys), an access log line per request and no + headers, bodies or query strings. Hook messages for a pushing client and operator CLI output are not logs and stay plain text. +- **Shutdown.** `--shutdown-timeout` (default 30). The listener closes first, idle keep-alives close at once (hyper graceful + shutdown), requests in flight finish, the rest is cancelled; exit 0. +- **Image.** `crates/forge/Dockerfile` (trixie, digest-pinned bases, uid 10001), `crates/forge/docker/smoke.sh`, advisory CI job. +- **Not built.** Per-owner quotas and per-user transport limits (#297); a free-space admission test for contents writes and merges + (pushes have one, `a_full_disk_reserve_refuses_pushes_with_507_but_not_reads`); image scanning and signing. + ### F5a decisions (as built) F5a is the maintenance half of F5 (plan: `docs/superpowers/plans/2026-10-24-p38-f5a-maintenance.md`); logs, drain, the bind-gate