diff --git a/.claude/skills/e2e-node-management-test/SKILL.md b/.claude/skills/e2e-node-management-test/SKILL.md index 208bbd66..2b479c60 100644 --- a/.claude/skills/e2e-node-management-test/SKILL.md +++ b/.claude/skills/e2e-node-management-test/SKILL.md @@ -378,9 +378,99 @@ ant node status --json Verify all 3 nodes are `running` before proceeding to cleanup. -### Phase 9: Cleanup +### Phase 9: Log forwarding -**Step 9.1 — Stop all nodes:** +Validates `ant node logs forward` (V2-1021). Forwarding ships node logs to the beta Elasticsearch +endpoint, so this phase must **never** point at the real endpoint. Everything below uses +`--endpoint` against a throwaway local listener, and the phase ends with forwarding disabled. + +Note that the nodes added in Phase 6 were added **without** `--log-dir-path`, so they have no log +files. That is the point of Steps 9.1–9.3: the common default must report itself honestly rather +than silently forward nothing. + +**Step 9.1 — Status before enabling:** + +``` +ant node logs forward status --json +``` + +Verify: `enabled` is `false` and `token_fingerprint` is `null`. + +**Step 9.2 — Enable against a local endpoint:** + +``` +ant node logs forward enable --token e2e-test-token --endpoint http://127.0.0.1:19999 --json +``` + +Verify: `enabled` is `true`, `endpoint` is the local URL, and `min_level` is `"info"`. + +**Step 9.3 — Nodes without logging are reported as skipped:** + +Verify from the same response that `nodes_forwarding` is empty and `nodes_skipped` has one entry per +node added in Phase 6, each with a `reason` mentioning `--log-dir-path`. A node with no log +directory writes no log files, so there is nothing to forward and the command must say so. + +**Step 9.4 — Add a node with logging and confirm it is picked up:** + +``` +ant node add --rewards-address 0x03B770D9cD32077cC0bF330c13C114a87643B124 --count 1 --bootstrap --evm-network arbitrum-sepolia --log-dir-path /e2e-logs --json +ant node logs forward status --json +``` + +Verify: `nodes_forwarding` now has one entry, whose `log_dir` is under the path just given. + +**Step 9.5 — The token is never returned:** + +``` +curl -s /logs/forward +``` + +Verify: the response contains `token_fingerprint` but the string `e2e-test-token` appears **nowhere** +in it. The daemon must not hand the write key back out over its API. + +**Step 9.6 — Config file permissions (Unix only):** + +``` +ls -l "${XDG_CONFIG_HOME:-$HOME/.config}/ant/log_forward.json" +``` + +Verify: the mode is `-rw-------` (0600). The file holds the write token. Skip on Windows. + +**Step 9.7 — Enable is reflected in the OpenAPI spec:** + +``` +curl -s /openapi.json | grep -c "logs/forward" +``` + +Verify: the count is at least 3 (status, enable and disable paths are all documented). + +**Step 9.8 — Disable:** + +``` +ant node logs forward disable --json +ant node logs forward status --json +``` + +Verify: `enabled` is `false` in both responses, and `active` is `false`. Disabling must not change +anything else about the nodes — confirm with `ant node status --json` that every node's status and +PID are unchanged from before Step 9.2. + +**Step 9.9 — Re-enable needs no token:** + +``` +ant node logs forward enable --json +``` + +Verify: succeeds without `--token`, reusing the stored one, and reports the same +`token_fingerprint` as Step 9.5. Then disable again so the phase leaves forwarding off: + +``` +ant node logs forward disable --json +``` + +### Phase 10: Cleanup + +**Step 10.1 — Stop all nodes:** ``` ant node stop --json @@ -388,7 +478,7 @@ ant node stop --json Verify all nodes stopped. -**Step 9.2 — Reset:** +**Step 10.2 — Reset:** ``` ant node reset --force --json @@ -396,7 +486,7 @@ ant node reset --force --json Verify: `nodes_cleared` is 3. -**Step 9.3 — Stop the daemon:** +**Step 10.3 — Stop the daemon:** ``` ant node daemon stop --json @@ -404,7 +494,7 @@ ant node daemon stop --json Verify: response contains `pid`. -**Step 9.4 — Verify daemon stopped:** +**Step 10.4 — Verify daemon stopped:** ``` ant node daemon status --json @@ -412,7 +502,7 @@ ant node daemon status --json Verify: `running` is `false`. -### Phase 10: Report +### Phase 11: Report Print a summary of all test steps and their results. Include the operating system and architecture at the top of the report (e.g., from `uname -a` on Linux/macOS or `systeminfo` on Windows): @@ -454,10 +544,21 @@ Phase 8: Daemon Restart Adoption [PASS] 8.7 Liveness monitor detected external kill [PASS] 8.8 Killed node restarted -Phase 9: Cleanup - [PASS] 9.1 Stop all nodes - [PASS] 9.2 Reset - [PASS] 9.3 Daemon stop +Phase 9: Log Forwarding + [PASS] 9.1 Status before enabling (off) + [PASS] 9.2 Enable against a local endpoint + [PASS] 9.3 Nodes without logging reported as skipped + [PASS] 9.4 Node with --log-dir-path picked up + [PASS] 9.5 Token never returned by the API + [PASS] 9.6 Config file is 0600 + [PASS] 9.7 OpenAPI documents the forward paths + [PASS] 9.8 Disable leaves nodes untouched + [PASS] 9.9 Re-enable reuses the stored token + +Phase 10: Cleanup + [PASS] 10.1 Stop all nodes + [PASS] 10.2 Reset + [PASS] 10.3 Daemon stop [PASS] 9.4 Daemon not running Result: ALL TESTS PASSED diff --git a/CLAUDE.md b/CLAUDE.md index 3730c3af..3e452f7a 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -85,7 +85,17 @@ ant-core/src/ │ ├── mod.rs │ ├── client.rs # Daemon client API (start/stop/status via HTTP) │ ├── server.rs # HTTP server (axum), REST API handlers - │ └── supervisor.rs # Process supervision with backoff + │ ├── supervisor.rs # Process supervision with backoff + │ └── forward/ # Opt-in beta log forwarding (V2-1021) + │ ├── mod.rs # Status/result types, enable-request merging + │ ├── config.rs # Persisted opt-in + token (0600), LogLevel + │ ├── parse.rs # Log line -> LogEvent (text and JSON layouts) + │ ├── tail.rs # Rotation-aware tailing, multi-line events + │ ├── offsets.rs # Persisted tail positions + │ ├── document.rs # Tagging into the beta index's field names + │ ├── sink.rs # LogSink trait, bounded queue, batching, retry + │ ├── es.rs # Elasticsearch _bulk sink + │ └── runner.rs # The background forwarding task └── process/ ├── mod.rs ├── spawn.rs # Spawning node processes @@ -103,6 +113,7 @@ ant-cli/src/ ├── mod.rs ├── add.rs # ant node add command ├── daemon.rs # daemon start/stop/status/info/run commands + ├── logs.rs # ant node logs forward enable/disable/status ├── start.rs # ant node start ├── stop.rs # ant node stop ├── status.rs # ant node status @@ -132,6 +143,12 @@ cargo run --bin ant -- --help # Run the CLI - **Registry file locking**: Use `NodeRegistry::load_locked()` for read-modify-write operations to prevent concurrent CLI invocations from corrupting the registry. The returned `File` handle holds the lock until dropped. - **Dual-path CLI commands**: Commands that modify the registry (like `ant node add`) check if the daemon is running. If so, they route through the REST API; otherwise, they operate directly on the registry file. - **Binary source resolution**: Node binary sources are represented by the `BinarySource` enum (Latest, Version, Url, LocalPath). Download variants are stubbed until release infrastructure is available. +- **Log forwarding is opt-in and node-logging-dependent**: `ant node logs forward enable` is the + consent act. It only forwards nodes whose `NodeConfig.log_dir` is `Some` — node file logging is + off unless the node was added with `--log-dir-path` — and reports the nodes it is skipping. + Enabling never restarts a node or changes its arguments. See + `ant-core/src/node/daemon/forward/` and the V2-1016 ingest contract documented at the top of + `forward/es.rs` (`create` actions, per-position `items[].status`, deterministic `_id`s). ## E2E Test Skill diff --git a/README.md b/README.md index 7ba0b420..38796d6a 100644 --- a/README.md +++ b/README.md @@ -25,6 +25,14 @@ curl -fsSL https://raw.githubusercontent.com/WithAutonomi/ant-client/main/instal irm https://raw.githubusercontent.com/WithAutonomi/ant-client/main/install.ps1 | iex ``` +Both installers take the same environment variables: + +| Variable | Description | +|----------|-------------| +| `ANT_CHANNEL` | Release channel: `stable` (default) or `beta`. See [Beta Programme](#beta-programme). | +| `ANT_VERSION` | Install one specific version, e.g. `0.3.3`. Overrides `ANT_CHANNEL`. | +| `INSTALL_DIR` | Where to put the binary. Defaults to `~/.local/bin` on Linux, `/usr/local/bin` on macOS, `%LOCALAPPDATA%\ant\bin` on Windows. | + ## Quick Start ### Store and retrieve a file (production) @@ -355,6 +363,53 @@ Remove all node data, log directories, and clear the registry. All nodes must be $ ant node reset --force ``` +#### `ant node logs forward` + +Optionally ship this machine's node logs to the Autonomi beta log endpoint, to help judge a beta +build. Off by default and never enabled for you — running `enable` yourself is the whole of the +consent, and `disable` stops it. See +[Forwarding your node logs](#forwarding-your-node-logs-optional) for the walkthrough. + +``` +$ ant node logs forward enable --token +$ ant node logs forward status +$ ant node logs forward disable +``` + +**`enable` options:** + +| Flag | Description | +|------|-------------| +| `--token ` | The write-only token issued with your beta enrolment. Only needed the first time; re-enabling after a `disable` reuses the stored one. | +| `--endpoint ` | Send somewhere other than the default endpoint. Intended for testing against a local sink. | +| `--level ` | Lowest level to forward: `trace`, `debug`, `info`, `warn`, `error`. Defaults to `info`. | + +`status` reports whether forwarding is on, which nodes are being tailed, which are being skipped and +why, and how many events have been delivered: + +``` +$ ant node logs forward status +Log forwarding: on + Endpoint: https://logs.autonomi.com Level: INFO and above + Token: 75f57160d2c2 + + Forwarding (1) + ● node1 (1) + + Not forwarding (2) + ○ node2 (2) — logging is not enabled for this node — re-add it with --log-dir-path to forward its logs + ○ node3 (3) — logging is not enabled for this node — re-add it with --log-dir-path to forward its logs + + Node logging is off unless a node was added with --log-dir-path. + + Delivery + Forwarded: 1284 Batches: 7 sent, 0 failed +``` + +The token is stored at `~/.config/ant/log_forward.json` with owner-only permissions and is never +printed back or returned by the API — `status` shows a short fingerprint of it instead, enough to +tell which token is in use. + ### `ant update` — Self-Update Replace the running `ant` binary with the newest release from GitHub. The downloaded archive's @@ -385,15 +440,30 @@ Because a beta version outranks the stable release it was cut from, `--channel s walk a beta build backwards — it will report that you are already up to date. Leaving the beta channel means installing a stable build manually. -### Beta channel +--- + +## Beta Programme -The beta channel carries the week's build ahead of the stable train, for people who want to soak -it. Both the client and the nodes have one, and they are opted into separately. +The beta channel carries the week's build ahead of the stable train, for people who want to soak it +and report back. + +Taking part means [running beta builds](#running-beta-builds). That is the whole requirement. + +Separately, and entirely optionally, you can [forward your node logs](#forwarding-your-node-logs-optional) +to us. It is off by default, it is not a condition of being on the beta channel, and choosing not to +turn it on costs you nothing. + +### Running beta builds + +The client and the nodes have separate beta channels, opted into separately. ```bash -# 1. Install the beta client. First install is manual: download the ant-cli-v-beta.N -# archive for your platform from the releases page, extract it, and put `ant` on your PATH. -# The quick-start installers always fetch the latest stable build, so they cannot do this. +# 1. Install the beta client. Pass ANT_CHANNEL=beta to the quick-start installer: +$ curl -fsSL https://raw.githubusercontent.com/WithAutonomi/ant-client/main/install.sh \ + | ANT_CHANNEL=beta bash + +# On Windows: +# $env:ANT_CHANNEL="beta"; irm https://raw.githubusercontent.com/WithAutonomi/ant-client/main/install.ps1 | iex # 2. From then on, self-update stays on beta with no flag needed. $ ant update @@ -406,6 +476,104 @@ $ ant node add --rewards-address 0xYourWallet --count 3 --upgrade-channel beta Existing nodes are not switched to the beta channel by any of this — `--upgrade-channel` applies to nodes at the point they are added, so opting in means adding new nodes. +### Forwarding your node logs (optional) + +**This is opt-in and stays off until you ask for it.** Nothing leaves your machine unless you run +`ant node logs forward enable` yourself, and running it is the whole of the consent. You can skip +this section entirely and still run beta builds. + +If you do want to help: beta enrolment comes with a write-only token, and handing it to that command +makes the daemon tail your nodes' log files and ship them to the Autonomi beta log endpoint. It is +the difference between us judging a build on a handful of self-reported problems and judging it on +what the nodes actually did, so it is genuinely useful — but it is your call, and `disable` stops it +at any point. + +**If you do turn it on, the order of these three steps matters:** + +```bash +# 1. Add nodes WITH LOGGING ENABLED. Node file logging is off by default; without +# --log-dir-path a node writes no log files at all and there is nothing to forward. +$ ant node add --rewards-address 0xYourWallet --count 3 \ + --upgrade-channel beta --log-dir-path ~/.local/share/ant + +# 2. Enable forwarding BEFORE starting the nodes. +$ ant node logs forward enable --token + +# 3. Now start them. +$ ant node start +``` + +#### Why the order matters + +**`--log-dir-path` has to be set when the node is added.** The value is a prefix — each node gets +`/node-/logs` — and there is no way to turn logging on for an existing node short of +removing it and adding it again. If you forget, `enable` will tell you — +those nodes appear under "Not forwarding" in `ant node logs forward status` — but the node has to be +re-added to fix it. + +**Enable before you start, not after.** Enabling forwarding is forward-looking consent: for any log +file that *already exists*, the daemon starts reading from the end of it, so nothing written before +you opted in is ever uploaded. A node that has not run yet has no log file, so the one it creates +when it starts is read from its first line. + +The practical difference is the node's startup line, which is where its version, commit and peer ID +are recorded, along with the bootstrap and listen-address lines that show whether it actually joined +the network. Enable first and those are captured. Enable afterwards and they are skipped, so every +event forwarded from that run is missing the fields that identify which build produced it — which is +most of what makes the logs useful. + +If you have already started a node, restarting it does not necessarily help: the node appends to the +same daily file, so a restart on the same day resumes from where the daemon had got to rather than +from the new run's first line. + +#### What gets sent + +Worth knowing before you decide. Only events at `INFO` and above, from nodes with logging enabled. +Every event is tagged with the node ID, service name, binary version, release channel, and the OS +and architecture of the machine. + +Each event also carries a random identifier generated when you first enable forwarding, stored in +`~/.config/ant/log_forward.json`. Because every participant writes into the same daily index, it is +there to stop two machines' events colliding and overwriting one another. It is generated from +random bytes — not from your hostname, MAC address or username — so it distinguishes your +installation from others without describing it. + +Your machine's hostname is **not** sent. Your wallet and rewards address are not part of what the +daemon adds. Beyond those tags, the content is whatever `ant-node` itself wrote to its log at `INFO` +or above — the same lines you can read yourself in the node's log directory. + +#### If something looks wrong + +`ant node logs forward status` is the place to look. `Batches: N sent, M failed` with an error line +underneath means the endpoint is unreachable or rejecting the token. Delivery is best-effort by +design: it is bounded in memory, it retries a few times and then gives up on a batch, and it never +blocks or slows a node. Losing some log lines is an acceptable outcome; a stalled node is not. + +`disable` takes effect immediately: it waits for any request already in flight to be abandoned +before reporting that forwarding has stopped, so nothing is still being uploaded once the command +returns. + +Forwarding survives a daemon restart, picking up where it left off without re-sending what it had +already delivered. If you want a genuinely clean slate, `disable` first, then delete +`~/.local/share/ant/log_forward_offsets.json`. + +### Turning forwarding off + +You can stop forwarding at any time, without leaving the beta channel and without giving a reason: + +```bash +$ ant node logs forward disable +``` + +Nothing else about your nodes changes — no restart, no change to how they run, no data touched. They +keep writing their own logs to disk exactly as before; the daemon just stops reading them. + +### Leaving the beta channel + +Separate from the above, and manual. Because a beta version outranks the stable release it was cut +from, `ant update --channel stable` cannot walk a beta build backwards — installing a stable build +means downloading it yourself. Nodes already on `--upgrade-channel beta` stay on it. + --- ## REST API @@ -424,6 +592,9 @@ When the daemon is running, it exposes a REST API on `127.0.0.1:`. Discove | POST | `/api/v1/nodes/{id}/stop` | Stop a specific node | | POST | `/api/v1/nodes/stop-all` | Stop all running nodes | | POST | `/api/v1/reset` | Reset all node state (fails if nodes running) | +| GET | `/api/v1/logs/forward` | Beta log-forwarding status, tailed nodes, delivery counters | +| POST | `/api/v1/logs/forward/enable` | Enable beta log forwarding | +| POST | `/api/v1/logs/forward/disable` | Disable beta log forwarding | | GET | `/api/v1/openapi.json` | OpenAPI 3.1 specification | | GET | `/console` | Web status console (HTML) | @@ -699,6 +870,7 @@ Data operations (upload/download) go directly to the P2P network — they do not │ └── node/ │ ├── add.rs # ant node add │ ├── daemon.rs # ant node daemon start/stop/status/info/run +│ ├── logs.rs # ant node logs forward enable/disable/status │ ├── start.rs # ant node start │ ├── stop.rs # ant node stop │ ├── status.rs # ant node status diff --git a/ant-cli/src/commands/node/logs.rs b/ant-cli/src/commands/node/logs.rs new file mode 100644 index 00000000..761b9434 --- /dev/null +++ b/ant-cli/src/commands/node/logs.rs @@ -0,0 +1,292 @@ +use clap::{Args, Subcommand}; +use colored::Colorize; + +use ant_core::node::daemon::client; +use ant_core::node::daemon::forward::{ + apply_enable, classify_nodes, LogForwardConfig, LogForwardEnableRequest, LogForwardResult, + LogForwardStatus, LogLevel, +}; +use ant_core::node::registry::NodeRegistry; +use ant_core::node::types::DaemonConfig; + +#[derive(Subcommand)] +pub enum LogsCommand { + /// Forward node logs to the Autonomi beta log endpoint + Forward { + #[command(subcommand)] + command: ForwardCommand, + }, +} + +#[derive(Subcommand)] +pub enum ForwardCommand { + /// Start forwarding this machine's node logs. Running this is your consent. + Enable(EnableArgs), + /// Stop forwarding. Nothing else about your nodes changes. + Disable, + /// Show whether forwarding is on and what it has shipped + Status, +} + +#[derive(Args)] +pub struct EnableArgs { + /// Write-only token issued for the beta programme. Only needed the first time — re-enabling + /// after a disable reuses the stored one. + #[arg(long)] + pub token: Option, + + /// Override the endpoint logs are shipped to. Intended for testing against a local sink. + #[arg(long)] + pub endpoint: Option, + + /// Lowest level to forward: trace, debug, info, warn or error. Defaults to info. + #[arg(long)] + pub level: Option, +} + +impl LogsCommand { + pub async fn execute(self, json_output: bool) -> anyhow::Result<()> { + match self { + Self::Forward { command } => command.execute(json_output).await, + } + } +} + +impl ForwardCommand { + pub async fn execute(self, json_output: bool) -> anyhow::Result<()> { + let config = DaemonConfig::default(); + + match self { + Self::Enable(args) => enable(&config, args, json_output).await, + Self::Disable => disable(&config, json_output).await, + Self::Status => status(&config, json_output).await, + } + } +} + +/// Enable forwarding. +/// +/// Dual-path, as elsewhere in the CLI: with the daemon up, this goes through its API so shipping +/// starts at once. With the daemon down the consent is still recorded — the config file is the +/// source of truth and the daemon picks it up when it next starts — and the output says so rather +/// than implying logs are already flowing. +async fn enable(daemon: &DaemonConfig, args: EnableArgs, json_output: bool) -> anyhow::Result<()> { + let request = LogForwardEnableRequest { + token: args.token, + endpoint: args.endpoint, + min_level: args.level, + }; + + let result = if client::status(daemon).await?.running { + client::log_forward_enable(daemon, &request).await? + } else { + enable_without_daemon(daemon, &request)? + }; + + print_result(&result, json_output) +} + +/// Record the opt-in directly, for when the daemon is not running. +fn enable_without_daemon( + daemon: &DaemonConfig, + request: &LogForwardEnableRequest, +) -> anyhow::Result { + let path = LogForwardConfig::default_path()?; + let stored = LogForwardConfig::load(&path)?; + let was_enabled = stored.enabled; + + let config = apply_enable(&stored, request)?; + config.save(&path)?; + + let registry = NodeRegistry::load(&daemon.registry_path)?; + let (nodes_forwarding, nodes_skipped) = classify_nodes(®istry); + + Ok(LogForwardResult { + enabled: true, + already_in_state: was_enabled, + endpoint: config.endpoint.clone(), + min_level: config.min_level, + nodes_forwarding, + nodes_skipped, + pending_daemon_start: true, + }) +} + +async fn disable(daemon: &DaemonConfig, json_output: bool) -> anyhow::Result<()> { + let result = if client::status(daemon).await?.running { + client::log_forward_disable(daemon).await? + } else { + let path = LogForwardConfig::default_path()?; + let mut config = LogForwardConfig::load(&path)?; + let was_enabled = config.enabled; + config.enabled = false; + config.save(&path)?; + + LogForwardResult { + enabled: false, + already_in_state: !was_enabled, + endpoint: config.endpoint.clone(), + min_level: config.min_level, + nodes_forwarding: Vec::new(), + nodes_skipped: Vec::new(), + pending_daemon_start: false, + } + }; + + print_result(&result, json_output) +} + +async fn status(daemon: &DaemonConfig, json_output: bool) -> anyhow::Result<()> { + let status = if client::status(daemon).await?.running { + client::log_forward_status(daemon).await? + } else { + let path = LogForwardConfig::default_path()?; + let config = LogForwardConfig::load(&path)?; + let mut status = LogForwardStatus::inactive(&config); + + let registry = NodeRegistry::load(&daemon.registry_path)?; + let (forwarding, skipped) = classify_nodes(®istry); + status.nodes_forwarding = forwarding; + status.nodes_skipped = skipped; + status + }; + + print_status(&status, json_output) +} + +fn print_result(result: &LogForwardResult, json_output: bool) -> anyhow::Result<()> { + if json_output { + println!("{}", serde_json::to_string_pretty(result)?); + return Ok(()); + } + + if !result.enabled { + if result.already_in_state { + println!("{} Log forwarding was already off", "●".yellow()); + } else { + println!("{} Log forwarding stopped", "✓".green().bold()); + println!(" {}", "Your nodes are otherwise unchanged.".dimmed()); + } + return Ok(()); + } + + if result.already_in_state { + println!( + "{} Log forwarding was already on — settings updated", + "●".yellow() + ); + } else { + println!("{} Log forwarding enabled", "✓".green().bold()); + } + println!( + " Endpoint: {} Level: {} and above", + result.endpoint.cyan(), + result.min_level.to_string().cyan() + ); + + print_node_lists(&result.nodes_forwarding, &result.nodes_skipped); + + if result.pending_daemon_start { + println!( + "\n{} The daemon is not running, so nothing is being shipped yet.", + "●".yellow() + ); + println!( + " Forwarding starts when you run: {}", + "ant node daemon start".cyan() + ); + } + + Ok(()) +} + +fn print_status(status: &LogForwardStatus, json_output: bool) -> anyhow::Result<()> { + if json_output { + println!("{}", serde_json::to_string_pretty(status)?); + return Ok(()); + } + + if status.enabled { + let state = if status.active { + "on".green().bold() + } else { + "on (not yet started)".yellow().bold() + }; + println!("Log forwarding: {state}"); + } else { + println!("Log forwarding: {}", "off".dimmed().bold()); + println!( + " Enable it with: {}", + "ant node logs forward enable --token ".cyan() + ); + return Ok(()); + } + + println!( + " Endpoint: {} Level: {} and above", + status.endpoint.cyan(), + status.min_level.to_string().cyan() + ); + if let Some(fingerprint) = &status.token_fingerprint { + println!(" Token: {}", fingerprint.dimmed()); + } + + print_node_lists(&status.nodes_forwarding, &status.nodes_skipped); + + let stats = &status.stats; + println!("\n {}", "Delivery".bold()); + println!( + " Forwarded: {} Batches: {} sent, {} failed", + stats.events_forwarded.to_string().cyan(), + stats.batches_sent.to_string().cyan(), + stats.batches_failed.to_string().cyan(), + ); + if stats.events_dropped_by_level > 0 || stats.events_dropped_by_overflow > 0 { + println!( + " Dropped: {} below level, {} to keep memory bounded", + stats.events_dropped_by_level.to_string().dimmed(), + stats.events_dropped_by_overflow.to_string().dimmed(), + ); + } + if let Some(error) = &stats.last_error { + println!(" {} {}", "Last error:".red(), error.red()); + } + + Ok(()) +} + +fn print_node_lists( + forwarding: &[ant_core::node::daemon::forward::ForwardingNode], + skipped: &[ant_core::node::daemon::forward::SkippedNode], +) { + if forwarding.is_empty() { + println!("\n {} No nodes have logging enabled.", "●".yellow()); + } else { + println!("\n {} ({})", "Forwarding".bold(), forwarding.len()); + for node in forwarding { + println!( + " {} {} ({})", + "●".green(), + node.service.bold(), + node.node_id.to_string().dimmed() + ); + } + } + + if !skipped.is_empty() { + println!("\n {} ({})", "Not forwarding".bold(), skipped.len()); + for node in skipped { + println!( + " {} {} ({}) — {}", + "○".yellow(), + node.service.bold(), + node.node_id.to_string().dimmed(), + node.reason.dimmed() + ); + } + println!( + "\n {}", + "Node logging is off unless a node was added with --log-dir-path.".dimmed() + ); + } +} diff --git a/ant-cli/src/commands/node/mod.rs b/ant-cli/src/commands/node/mod.rs index 0273c85b..b0eabe2a 100644 --- a/ant-cli/src/commands/node/mod.rs +++ b/ant-cli/src/commands/node/mod.rs @@ -1,6 +1,7 @@ pub mod add; pub mod daemon; pub mod dismiss; +pub mod logs; pub mod reset; pub mod start; pub mod status; @@ -11,6 +12,7 @@ use clap::Subcommand; use crate::commands::node::add::AddArgs; use crate::commands::node::daemon::DaemonCommand; use crate::commands::node::dismiss::DismissArgs; +use crate::commands::node::logs::LogsCommand; use crate::commands::node::reset::ResetArgs; use crate::commands::node::start::StartArgs; use crate::commands::node::status::StatusArgs; @@ -27,6 +29,11 @@ pub enum NodeCommand { }, /// Dismiss an evicted node, removing it from the registry/list Dismiss(DismissArgs), + /// Manage node log handling, including forwarding logs to the beta endpoint + Logs { + #[command(subcommand)] + command: LogsCommand, + }, /// Reset all node state (removes all data, logs, and clears the registry) Reset(ResetArgs), /// Start node(s). With no arguments starts all nodes; use --service-name for a specific node. diff --git a/ant-cli/src/main.rs b/ant-cli/src/main.rs index b8523a3b..ac0c6f51 100644 --- a/ant-cli/src/main.rs +++ b/ant-cli/src/main.rs @@ -113,6 +113,9 @@ async fn run() -> anyhow::Result<()> { commands::node::NodeCommand::Dismiss(args) => { args.execute(json).await?; } + commands::node::NodeCommand::Logs { command } => { + command.execute(json).await?; + } commands::node::NodeCommand::Reset(args) => { args.execute(json).await?; } diff --git a/ant-core/src/error.rs b/ant-core/src/error.rs index 2b62460f..6926d195 100644 --- a/ant-core/src/error.rs +++ b/ant-core/src/error.rs @@ -72,6 +72,9 @@ pub enum Error { "Cannot reset while nodes are running ({0} node(s) still running). Stop all nodes first." )] NodesStillRunning(u32), + + #[error("Log forwarding: {0}")] + LogForward(String), } pub type Result = std::result::Result; diff --git a/ant-core/src/node/daemon/client.rs b/ant-core/src/node/daemon/client.rs index eeb81a4f..2477bb91 100644 --- a/ant-core/src/node/daemon/client.rs +++ b/ant-core/src/node/daemon/client.rs @@ -2,6 +2,7 @@ use std::path::Path; use std::time::Duration; use crate::error::{Error, Result}; +use crate::node::daemon::forward::{LogForwardEnableRequest, LogForwardResult, LogForwardStatus}; use crate::node::daemon::health::FleetHealth; use crate::node::process::detach; use crate::node::types::{ @@ -163,6 +164,76 @@ pub async fn start_node(config: &DaemonConfig, node_id: u32) -> Result Result { + let port = read_port_file(&config.port_file_path).ok_or(Error::DaemonNotRunning)?; + + let url = format!("http://127.0.0.1:{port}/api/v1/logs/forward"); + let resp = reqwest::get(&url) + .await + .map_err(|e| Error::HttpRequest(e.to_string()))?; + + if resp.status().is_success() { + resp.json::() + .await + .map_err(|e| Error::HttpRequest(e.to_string())) + } else { + Err(Error::HttpRequest(resp.text().await.unwrap_or_default())) + } +} + +/// Enable log forwarding via the daemon, so it starts shipping immediately. +pub async fn log_forward_enable( + config: &DaemonConfig, + request: &LogForwardEnableRequest, +) -> Result { + post_log_forward(config, "enable", Some(request)).await +} + +/// Disable log forwarding via the daemon. +pub async fn log_forward_disable(config: &DaemonConfig) -> Result { + post_log_forward(config, "disable", None).await +} + +async fn post_log_forward( + config: &DaemonConfig, + action: &str, + body: Option<&LogForwardEnableRequest>, +) -> Result { + let port = read_port_file(&config.port_file_path).ok_or(Error::DaemonNotRunning)?; + + let url = format!("http://127.0.0.1:{port}/api/v1/logs/forward/{action}"); + let mut request = reqwest::Client::new().post(&url); + if let Some(body) = body { + request = request.json(body); + } + + let resp = request + .send() + .await + .map_err(|e| Error::HttpRequest(e.to_string()))?; + + if resp.status().is_success() { + resp.json::() + .await + .map_err(|e| Error::HttpRequest(e.to_string())) + } else { + // The daemon returns `{"error": "..."}` for a rejected enable; surface just that text + // rather than the raw JSON envelope. + let body = resp.text().await.unwrap_or_default(); + let message = serde_json::from_str::(&body) + .ok() + .and_then(|value| { + value + .get("error") + .and_then(serde_json::Value::as_str) + .map(str::to_string) + }) + .unwrap_or(body); + Err(Error::HttpRequest(message)) + } +} + /// Start all registered nodes via the daemon REST API. pub async fn start_all_nodes(config: &DaemonConfig) -> Result { let port = read_port_file(&config.port_file_path).ok_or(Error::DaemonNotRunning)?; diff --git a/ant-core/src/node/daemon/forward/config.rs b/ant-core/src/node/daemon/forward/config.rs new file mode 100644 index 00000000..31032b8c --- /dev/null +++ b/ant-core/src/node/daemon/forward/config.rs @@ -0,0 +1,494 @@ +//! Persisted opt-in state for beta log forwarding. +//! +//! Running `ant node logs forward enable` is the consent act, and this file is where that consent +//! lives. It holds the write-only Elasticsearch API key, so it is written with owner-only +//! permissions and its token is never returned by the status API — callers get a fingerprint +//! instead (see [`LogForwardStatus`](super::LogForwardStatus)). + +use std::path::{Path, PathBuf}; + +use serde::{Deserialize, Serialize}; + +use crate::config; +use crate::error::{Error, Result}; + +/// Default beta-channel ingest endpoint (V2-1016). +/// +/// A Caddy proxy fronts an Elasticsearch instance on loopback and allowlists the bulk/document +/// paths; it is the Elasticsearch API rather than a translation layer, so the sink speaks plain +/// `_bulk`. Overridable with `--endpoint` for testing against a local mock. +pub const DEFAULT_ENDPOINT: &str = "https://logs.autonomi.com"; + +/// Prefix of the daily index events are written to: `beta-nodes-YYYY.MM.DD`. +/// +/// The write-only API key is scoped to `beta-nodes-*`; anything outside that is rejected with a +/// per-item 403. +pub const DEFAULT_INDEX_PREFIX: &str = "beta-nodes"; + +/// Filename of the persisted forwarding config within [`config::config_dir`]. +const CONFIG_FILENAME: &str = "log_forward.json"; + +/// Severity of a log event, ordered so that filtering is a comparison. +/// +/// The ingest endpoint enforces its own minimum level (currently INFO) and silently drops anything +/// below it while reporting success, so filtering here is not about correctness — it is about not +/// spending the user's bandwidth and disk on events that are discarded on arrival. +#[derive( + Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Serialize, Deserialize, utoipa::ToSchema, +)] +#[serde(rename_all = "lowercase")] +pub enum LogLevel { + Trace, + Debug, + Info, + Warn, + Error, +} + +impl LogLevel { + /// Parse a level as it appears in an ant-node log line, in either log format. + /// + /// Accepts any case: the text layer emits `INFO`, the JSON layer emits `INFO` in its `level` + /// field, and hand-written configs use `info`. + #[must_use] + pub fn parse(s: &str) -> Option { + match s.trim().to_ascii_uppercase().as_str() { + "TRACE" => Some(Self::Trace), + "DEBUG" => Some(Self::Debug), + "INFO" => Some(Self::Info), + "WARN" | "WARNING" => Some(Self::Warn), + "ERROR" => Some(Self::Error), + _ => None, + } + } + + /// The level as it should appear in a forwarded document's `level` field. + #[must_use] + pub fn as_str(self) -> &'static str { + match self { + Self::Trace => "TRACE", + Self::Debug => "DEBUG", + Self::Info => "INFO", + Self::Warn => "WARN", + Self::Error => "ERROR", + } + } +} + +impl std::fmt::Display for LogLevel { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + write!(f, "{}", self.as_str()) + } +} + +impl std::str::FromStr for LogLevel { + type Err = Error; + + fn from_str(s: &str) -> Result { + Self::parse(s).ok_or_else(|| { + Error::LogForward(format!( + "unknown log level '{s}' (expected one of: trace, debug, info, warn, error)" + )) + }) + } +} + +/// The default minimum level: INFO and above, matching both ant-node's own default and the +/// server-side ingest filter. +const fn default_min_level() -> LogLevel { + LogLevel::Info +} + +fn default_endpoint() -> String { + DEFAULT_ENDPOINT.to_string() +} + +fn default_index_prefix() -> String { + DEFAULT_INDEX_PREFIX.to_string() +} + +/// Persisted forwarding configuration. +/// +/// Absent file means "never enabled", which loads as [`LogForwardConfig::disabled`]. +#[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize)] +pub struct LogForwardConfig { + /// Whether the user has opted in. `disable` clears this but keeps the rest, so a later + /// `enable` with no arguments resumes with the same token and endpoint. + pub enabled: bool, + + /// Write-only Elasticsearch API key, sent as `Authorization: ApiKey `. + /// + /// Never serialized into an API response — see [`Self::token_fingerprint`]. + #[serde(default)] + pub token: String, + + /// Ingest endpoint. Defaults to [`DEFAULT_ENDPOINT`]. + #[serde(default = "default_endpoint")] + pub endpoint: String, + + /// Daily index prefix. Defaults to [`DEFAULT_INDEX_PREFIX`]. + #[serde(default = "default_index_prefix")] + pub index_prefix: String, + + /// Drop events below this level before batching. Defaults to [`LogLevel::Info`]. + #[serde(default = "default_min_level")] + pub min_level: LogLevel, + + /// Stable, randomly generated namespace for this installation's document ids. + /// + /// Every participant writes into the same shared `beta-nodes-YYYY.MM.DD` indices, so a document + /// id built only from node id, filename and byte offset is not unique across machines: node 1's + /// first log line sits at offset 0 of the same daily filename on *every* installation. Since a + /// duplicate id is answered with a 409 that the sink counts as delivered, the second machine's + /// event would be silently discarded rather than stored. + /// + /// Prefixing the id with this value removes that collision. It is random rather than derived + /// from anything about the machine — not the hostname, MAC or username — so it identifies an + /// installation only in the sense of separating it from other installations. + /// + /// It must stay stable for the lifetime of the install: the deterministic id is what makes a + /// replayed batch idempotent, and regenerating this would make a replay look like a new + /// document and duplicate it. + #[serde(default)] + pub installation_id: String, +} + +impl Default for LogForwardConfig { + fn default() -> Self { + Self::disabled() + } +} + +impl LogForwardConfig { + /// The state of a machine that has never opted in. + #[must_use] + pub fn disabled() -> Self { + Self { + enabled: false, + token: String::new(), + endpoint: default_endpoint(), + index_prefix: default_index_prefix(), + min_level: default_min_level(), + installation_id: String::new(), + } + } + + /// Generate the installation namespace if this config does not have one yet. + /// + /// Called when forwarding is enabled. Configs written before this field existed load with an + /// empty value and are filled in on their next enable. + pub fn ensure_installation_id(&mut self) { + if self.installation_id.is_empty() { + self.installation_id = generate_installation_id(); + } + } + + /// Path of the persisted config for this machine. + pub fn default_path() -> Result { + Ok(config::config_dir()?.join(CONFIG_FILENAME)) + } + + /// Load the config, returning [`Self::disabled`] when the file does not exist. + /// + /// A corrupt file is an error rather than a silent reset: forwarding is opt-in, and silently + /// falling back to "disabled" would look identical to a user who had opted in and would leave + /// them believing logs were flowing when they were not. + pub fn load(path: &Path) -> Result { + if !path.exists() { + return Ok(Self::disabled()); + } + let contents = std::fs::read_to_string(path)?; + let config: Self = serde_json::from_str(&contents)?; + Ok(config) + } + + /// Write the config atomically with owner-only permissions. + /// + /// Permissions are set on the temporary file *before* the rename, so the token is never + /// readable by other users on the machine, even briefly. + pub fn save(&self, path: &Path) -> Result<()> { + if let Some(parent) = path.parent() { + std::fs::create_dir_all(parent)?; + } + let contents = serde_json::to_string_pretty(self)?; + let tmp_path = path.with_extension("tmp"); + std::fs::write(&tmp_path, &contents)?; + restrict_to_owner(&tmp_path)?; + std::fs::rename(&tmp_path, path)?; + Ok(()) + } + + /// Reject a configuration that cannot possibly ship anything. + pub fn validate(&self) -> Result<()> { + if self.installation_id.is_empty() { + return Err(Error::LogForward( + "internal: installation id was not generated before enabling".into(), + )); + } + if self.token.trim().is_empty() { + return Err(Error::LogForward( + "a write token is required: ant node logs forward enable --token ".into(), + )); + } + if !self.endpoint.starts_with("http://") && !self.endpoint.starts_with("https://") { + return Err(Error::LogForward(format!( + "endpoint must be an http(s) URL, got '{}'", + self.endpoint + ))); + } + if self.index_prefix.trim().is_empty() { + return Err(Error::LogForward("index prefix must not be empty".into())); + } + Ok(()) + } + + /// A non-reversible short identifier for the configured token, safe to show in status output. + /// + /// Returns `None` when no token is set. This exists so a user can confirm *which* key is in + /// use — after re-enrolling, say — without the daemon ever handing the key back out over its + /// HTTP API. + #[must_use] + pub fn token_fingerprint(&self) -> Option { + if self.token.trim().is_empty() { + return None; + } + let digest = blake3::hash(self.token.as_bytes()); + Some(digest.to_hex()[..12].to_string()) + } + + /// The endpoint with any trailing slash removed, so path joining is unambiguous. + #[must_use] + pub fn endpoint_base(&self) -> &str { + self.endpoint.trim_end_matches('/') + } +} + +/// 64 bits of randomness, rendered as hex. +/// +/// Ample for separating a beta cohort — collisions become likely somewhere around a billion +/// installations — while keeping the document id short and readable. +fn generate_installation_id() -> String { + use rand::Rng; + let bytes: [u8; 8] = rand::thread_rng().gen(); + bytes.iter().fold(String::with_capacity(16), |mut acc, b| { + use std::fmt::Write; + let _ = write!(acc, "{b:02x}"); + acc + }) +} + +#[cfg(unix)] +fn restrict_to_owner(path: &Path) -> Result<()> { + use std::os::unix::fs::PermissionsExt; + std::fs::set_permissions(path, std::fs::Permissions::from_mode(0o600))?; + Ok(()) +} + +/// On Windows the config lands in the per-user `%APPDATA%` tree, which is already +/// user-scoped by the default ACL; there is no portable mode bit to set. +#[cfg(not(unix))] +fn restrict_to_owner(_path: &Path) -> Result<()> { + Ok(()) +} + +#[cfg(test)] +mod tests { + use super::*; + + fn enabled_config() -> LogForwardConfig { + LogForwardConfig { + enabled: true, + token: "test-api-key".to_string(), + installation_id: "0123456789abcdef".to_string(), + ..LogForwardConfig::disabled() + } + } + + #[test] + fn levels_order_by_severity() { + assert!(LogLevel::Trace < LogLevel::Debug); + assert!(LogLevel::Debug < LogLevel::Info); + assert!(LogLevel::Info < LogLevel::Warn); + assert!(LogLevel::Warn < LogLevel::Error); + } + + #[test] + fn level_parses_both_log_formats_and_config_casing() { + assert_eq!(LogLevel::parse("INFO"), Some(LogLevel::Info)); + assert_eq!(LogLevel::parse("info"), Some(LogLevel::Info)); + assert_eq!(LogLevel::parse(" WARN "), Some(LogLevel::Warn)); + assert_eq!(LogLevel::parse("WARNING"), Some(LogLevel::Warn)); + assert_eq!(LogLevel::parse("nonsense"), None); + } + + #[test] + fn level_from_str_reports_the_accepted_values() { + let err = "verbose".parse::().unwrap_err().to_string(); + assert!(err.contains("trace, debug, info, warn, error"), "{err}"); + } + + #[test] + fn missing_file_loads_as_disabled() { + let tmp = tempfile::tempdir().unwrap(); + let config = LogForwardConfig::load(&tmp.path().join("absent.json")).unwrap(); + assert_eq!(config, LogForwardConfig::disabled()); + assert!(!config.enabled); + } + + #[test] + fn corrupt_file_is_an_error_rather_than_a_silent_reset() { + let tmp = tempfile::tempdir().unwrap(); + let path = tmp.path().join("log_forward.json"); + std::fs::write(&path, "{ not json").unwrap(); + assert!(LogForwardConfig::load(&path).is_err()); + } + + #[test] + fn save_then_load_round_trips() { + let tmp = tempfile::tempdir().unwrap(); + let path = tmp.path().join("nested").join("log_forward.json"); + let config = enabled_config(); + config.save(&path).unwrap(); + assert_eq!(LogForwardConfig::load(&path).unwrap(), config); + } + + /// An older config written before a field existed must still load, taking the defaults. + #[test] + fn load_tolerates_a_config_missing_the_optional_fields() { + let tmp = tempfile::tempdir().unwrap(); + let path = tmp.path().join("log_forward.json"); + std::fs::write(&path, r#"{"enabled":true,"token":"k"}"#).unwrap(); + let config = LogForwardConfig::load(&path).unwrap(); + assert!(config.enabled); + assert_eq!(config.endpoint, DEFAULT_ENDPOINT); + assert_eq!(config.index_prefix, DEFAULT_INDEX_PREFIX); + assert_eq!(config.min_level, LogLevel::Info); + } + + #[cfg(unix)] + #[test] + fn saved_config_is_owner_only() { + use std::os::unix::fs::PermissionsExt; + let tmp = tempfile::tempdir().unwrap(); + let path = tmp.path().join("log_forward.json"); + enabled_config().save(&path).unwrap(); + let mode = std::fs::metadata(&path).unwrap().permissions().mode(); + assert_eq!( + mode & 0o777, + 0o600, + "token file must not be group/world readable" + ); + } + + #[cfg(unix)] + #[test] + fn overwriting_an_existing_config_keeps_owner_only_permissions() { + use std::os::unix::fs::PermissionsExt; + let tmp = tempfile::tempdir().unwrap(); + let path = tmp.path().join("log_forward.json"); + std::fs::write(&path, "{}").unwrap(); + std::fs::set_permissions(&path, std::fs::Permissions::from_mode(0o644)).unwrap(); + + enabled_config().save(&path).unwrap(); + + let mode = std::fs::metadata(&path).unwrap().permissions().mode(); + assert_eq!(mode & 0o777, 0o600); + } + + #[test] + fn validate_rejects_a_missing_token() { + let config = LogForwardConfig { + token: " ".to_string(), + ..enabled_config() + }; + assert!(config.validate().unwrap_err().to_string().contains("token")); + } + + #[test] + fn an_installation_id_is_generated_once_and_then_left_alone() { + let mut config = LogForwardConfig::disabled(); + assert!(config.installation_id.is_empty()); + + config.ensure_installation_id(); + let first = config.installation_id.clone(); + assert_eq!(first.len(), 16, "64 bits rendered as hex"); + assert!(first.chars().all(|c| c.is_ascii_hexdigit())); + + // Stability is what keeps a replayed batch idempotent. + config.ensure_installation_id(); + assert_eq!(config.installation_id, first); + } + + #[test] + fn separate_installations_get_different_ids() { + let mut a = LogForwardConfig::disabled(); + let mut b = LogForwardConfig::disabled(); + a.ensure_installation_id(); + b.ensure_installation_id(); + assert_ne!(a.installation_id, b.installation_id); + } + + #[test] + fn the_installation_id_survives_a_save_and_reload() { + let tmp = tempfile::tempdir().unwrap(); + let path = tmp.path().join("log_forward.json"); + let config = enabled_config(); + config.save(&path).unwrap(); + assert_eq!( + LogForwardConfig::load(&path).unwrap().installation_id, + config.installation_id + ); + } + + #[test] + fn validate_rejects_a_non_http_endpoint() { + let config = LogForwardConfig { + endpoint: "logs.autonomi.com".to_string(), + ..enabled_config() + }; + assert!(config + .validate() + .unwrap_err() + .to_string() + .contains("http(s) URL")); + } + + #[test] + fn validate_accepts_the_defaults_with_a_token() { + enabled_config().validate().unwrap(); + } + + #[test] + fn fingerprint_is_stable_absent_for_no_token_and_leaks_nothing() { + let config = enabled_config(); + let fingerprint = config.token_fingerprint().unwrap(); + assert_eq!(fingerprint.len(), 12); + assert_eq!(config.token_fingerprint().unwrap(), fingerprint); + assert!(!fingerprint.contains("test-api-key")); + + let other = LogForwardConfig { + token: "a-different-key".to_string(), + ..enabled_config() + }; + assert_ne!(other.token_fingerprint().unwrap(), fingerprint); + assert_eq!(LogForwardConfig::disabled().token_fingerprint(), None); + } + + #[test] + fn endpoint_base_strips_a_trailing_slash() { + let config = LogForwardConfig { + endpoint: "https://logs.autonomi.com/".to_string(), + ..enabled_config() + }; + assert_eq!(config.endpoint_base(), "https://logs.autonomi.com"); + } + + /// The token must never reach an API response body. Status is built from a dedicated type, but + /// this pins the underlying expectation that nothing serializes the config itself outward. + #[test] + fn fingerprint_rather_than_token_is_what_status_can_show() { + let config = enabled_config(); + let fingerprint = config.token_fingerprint().unwrap(); + assert!(!fingerprint.contains(&config.token)); + } +} diff --git a/ant-core/src/node/daemon/forward/document.rs b/ant-core/src/node/daemon/forward/document.rs new file mode 100644 index 00000000..c7f783d9 --- /dev/null +++ b/ant-core/src/node/daemon/forward/document.rs @@ -0,0 +1,289 @@ +//! Building the document that actually goes to Elasticsearch. +//! +//! Field names here are not ours to choose: they are the beta index's mapping (V2-1016), and a +//! mismatch means a field lands as dynamically-mapped text instead of the keyword the dashboards +//! aggregate on. Two in particular read wrong at a glance and are right: +//! +//! - the time field is `@timestamp`, not `timestamp`; +//! - the node's build is `binary_version`, while `version` and `commit` carry whatever ant-node +//! said about *itself* on its startup line. Keeping them separate avoids two half-populated +//! fields meaning the same thing with no rule for which wins. +//! +//! Two mapped fields are deliberately never sent. `host` is stripped by the ingest pipeline — +//! machine hostnames routinely contain someone's name — and `beta_user` is stamped server-side from +//! the authenticated API key, so anything we sent would be discarded and replaced anyway. + +use serde::Serialize; + +use super::tail::TailedEvent; +use crate::node::types::NodeConfig; + +/// Value used for `channel` when a node has never been given an explicit upgrade channel. +/// +/// Not folded into `"stable"`: the beta cohort is counted by aggregating this field, and claiming a +/// node is on stable when nobody ever said so would quietly distort that count. +const CHANNEL_UNSET: &str = "unset"; + +/// The identity fields every event from a given node carries. +/// +/// Resolved once when the forwarder picks the node up, rather than per event. +#[derive(Debug, Clone, PartialEq, Eq)] +pub struct NodeTags { + pub node_id: u32, + pub service: String, + pub binary_version: String, + pub channel: String, +} + +impl NodeTags { + #[must_use] + pub fn from_config(config: &NodeConfig) -> Self { + Self { + node_id: config.id, + service: config.service_name.clone(), + binary_version: config.version.clone(), + channel: config + .upgrade_channel + .map_or_else(|| CHANNEL_UNSET.to_string(), |channel| channel.to_string()), + } + } +} + +/// A document ready to be framed into a bulk request. +#[derive(Debug, Clone, PartialEq, Eq)] +pub struct ForwardDocument { + /// Deterministic `_id`, so replaying a batch is idempotent. + pub id: String, + /// Daily index, derived from this event's own timestamp. + pub index: String, + pub source: DocumentSource, +} + +/// The `_source` body of a forwarded document. +#[derive(Debug, Clone, PartialEq, Eq, Serialize)] +pub struct DocumentSource { + #[serde(rename = "@timestamp")] + pub timestamp: String, + pub level: String, + #[serde(skip_serializing_if = "Option::is_none")] + pub target: Option, + pub message: String, + + /// Keyword in the mapping, so it is sent as a string rather than a number. + pub node_id: String, + pub service: String, + pub binary_version: String, + pub channel: String, + pub os: String, + pub arch: String, + + #[serde(skip_serializing_if = "Option::is_none")] + pub peer_id: Option, + #[serde(skip_serializing_if = "Option::is_none")] + pub version: Option, + #[serde(skip_serializing_if = "Option::is_none")] + pub commit: Option, +} + +impl ForwardDocument { + /// Build a document, or `None` if the event's timestamp cannot name an index. + /// + /// Parsing already rejects unusable timestamps in both layouts, so `None` here is a + /// belt-and-braces case rather than an expected one. + /// + /// `installation_id` namespaces the document id; see [`TailedEvent::document_id`] for why the + /// local position alone is not unique across the beta cohort. + #[must_use] + pub fn build( + tailed: &TailedEvent, + tags: &NodeTags, + index_prefix: &str, + installation_id: &str, + ) -> Option { + let index = format!("{index_prefix}-{}", tailed.event.index_date()?); + + Some(Self { + id: tailed.document_id(installation_id), + index, + source: DocumentSource { + timestamp: tailed.event.timestamp.clone(), + level: tailed.event.level.as_str().to_string(), + target: tailed.event.target.clone(), + message: tailed.event.message.clone(), + node_id: tags.node_id.to_string(), + service: tags.service.clone(), + binary_version: tags.binary_version.clone(), + channel: tags.channel.clone(), + os: std::env::consts::OS.to_string(), + arch: std::env::consts::ARCH.to_string(), + peer_id: tailed.event.peer_id.clone(), + version: tailed.event.version.clone(), + commit: tailed.event.commit.clone(), + }, + }) + } + + /// Approximate serialized size, used to keep a batch well under the endpoint's body cap. + #[must_use] + pub fn approx_bytes(&self) -> usize { + // The action line plus the source line, give or take the JSON punctuation. + self.id.len() + self.index.len() + self.source.message.len() + 256 + } +} + +#[cfg(test)] +mod tests { + use super::*; + use crate::node::daemon::forward::parse::parse_line; + use crate::node::types::{EvmNetwork, UpgradeChannel}; + use std::collections::HashMap; + use std::path::PathBuf; + + fn node_config(channel: Option) -> NodeConfig { + NodeConfig { + id: 7, + service_name: "node7".to_string(), + rewards_address: "0xabc".to_string(), + data_dir: PathBuf::from("/data/node-7"), + log_dir: Some(PathBuf::from("/logs/node-7")), + node_port: None, + binary_path: PathBuf::from("/bin/antnode"), + version: "0.17.2-beta.1".to_string(), + env_variables: HashMap::new(), + bootstrap_peers: Vec::new(), + upgrade_channel: channel, + evm_network: EvmNetwork::default(), + eviction: None, + } + } + + fn tailed(line: &str) -> TailedEvent { + TailedEvent { + node_id: 7, + file_name: "ant-node.2026-08-19.log".to_string(), + byte_offset: 4096, + event: parse_line(line).unwrap(), + } + } + + const INSTALL: &str = "0123456789abcdef"; + + const LINE: &str = + "2026-08-19T20:50:00.123456Z INFO ant_node::node: connected peer_id=12D3KooWabc"; + + #[test] + fn builds_a_document_with_the_mapped_field_names() { + let tags = NodeTags::from_config(&node_config(Some(UpgradeChannel::Beta))); + let document = ForwardDocument::build(&tailed(LINE), &tags, "beta-nodes", INSTALL).unwrap(); + + assert_eq!( + document.id, + "0123456789abcdef-7-ant-node.2026-08-19.log-4096" + ); + assert_eq!(document.index, "beta-nodes-2026.08.19"); + + let json: serde_json::Value = serde_json::to_value(&document.source).unwrap(); + assert_eq!(json["@timestamp"], "2026-08-19T20:50:00.123456Z"); + assert_eq!(json["level"], "INFO"); + assert_eq!(json["target"], "ant_node::node"); + assert_eq!(json["node_id"], "7"); + assert_eq!(json["service"], "node7"); + assert_eq!(json["binary_version"], "0.17.2-beta.1"); + assert_eq!(json["channel"], "beta"); + assert_eq!(json["peer_id"], "12D3KooWabc"); + assert_eq!(json["os"], std::env::consts::OS); + assert_eq!(json["arch"], std::env::consts::ARCH); + } + + /// The time field is `@timestamp`; a document using `timestamp` would not be searchable by time. + #[test] + fn the_time_field_is_at_timestamp_and_nothing_else() { + let tags = NodeTags::from_config(&node_config(None)); + let document = ForwardDocument::build(&tailed(LINE), &tags, "beta-nodes", INSTALL).unwrap(); + let json = serde_json::to_value(&document.source).unwrap(); + + assert!(json.get("@timestamp").is_some()); + assert!(json.get("timestamp").is_none()); + } + + /// Both are stamped or stripped server-side; sending them is at best pointless. + #[test] + fn host_and_beta_user_are_never_sent() { + let tags = NodeTags::from_config(&node_config(Some(UpgradeChannel::Beta))); + let document = ForwardDocument::build(&tailed(LINE), &tags, "beta-nodes", INSTALL).unwrap(); + let json = serde_json::to_value(&document.source).unwrap(); + + assert!(json.get("host").is_none()); + assert!(json.get("beta_user").is_none()); + } + + #[test] + fn an_unspecified_channel_is_not_reported_as_stable() { + let tags = NodeTags::from_config(&node_config(None)); + assert_eq!(tags.channel, "unset"); + + let stable = NodeTags::from_config(&node_config(Some(UpgradeChannel::Stable))); + assert_eq!(stable.channel, "stable"); + } + + #[test] + fn the_index_comes_from_the_events_timestamp_not_the_wall_clock() { + let tags = NodeTags::from_config(&node_config(None)); + + let yesterday = ForwardDocument::build( + &tailed("2026-08-19T23:59:59.000000Z INFO ant_node: late"), + &tags, + "beta-nodes", + INSTALL, + ) + .unwrap(); + let today = ForwardDocument::build( + &tailed("2026-08-20T00:00:01.000000Z INFO ant_node: early"), + &tags, + "beta-nodes", + INSTALL, + ) + .unwrap(); + + assert_eq!(yesterday.index, "beta-nodes-2026.08.19"); + assert_eq!(today.index, "beta-nodes-2026.08.20"); + } + + /// The property that makes a replayed batch idempotent: same event in, same `_id` and index out, + /// no matter when the replay happens. + #[test] + fn rebuilding_the_same_event_yields_the_same_id_and_index() { + let tags = NodeTags::from_config(&node_config(Some(UpgradeChannel::Beta))); + let first = ForwardDocument::build(&tailed(LINE), &tags, "beta-nodes", INSTALL).unwrap(); + let second = ForwardDocument::build(&tailed(LINE), &tags, "beta-nodes", INSTALL).unwrap(); + + assert_eq!(first.id, second.id); + assert_eq!(first.index, second.index); + } + + #[test] + fn absent_optional_fields_are_omitted_rather_than_sent_as_null() { + let tags = NodeTags::from_config(&node_config(None)); + let document = ForwardDocument::build( + &tailed("2026-08-19T20:50:00.123456Z INFO plain message with no fields"), + &tags, + "beta-nodes", + INSTALL, + ) + .unwrap(); + let json = serde_json::to_value(&document.source).unwrap(); + + assert!(json.get("peer_id").is_none()); + assert!(json.get("version").is_none()); + assert!(json.get("commit").is_none()); + assert!(json.get("target").is_none()); + } + + #[test] + fn a_custom_index_prefix_is_honoured() { + let tags = NodeTags::from_config(&node_config(None)); + let document = + ForwardDocument::build(&tailed(LINE), &tags, "my-test-index", INSTALL).unwrap(); + assert_eq!(document.index, "my-test-index-2026.08.19"); + } +} diff --git a/ant-core/src/node/daemon/forward/es.rs b/ant-core/src/node/daemon/forward/es.rs new file mode 100644 index 00000000..20ce5e6f --- /dev/null +++ b/ant-core/src/node/daemon/forward/es.rs @@ -0,0 +1,431 @@ +//! The Elasticsearch bulk sink (V2-1016 contract). +//! +//! The endpoint is Elasticsearch itself behind a transparent reverse proxy, not a translation +//! layer, so this speaks plain `_bulk`. Four details of that contract are easy to get wrong and +//! expensive to debug, so they are stated here rather than left implicit in the code: +//! +//! 1. **The action must be `create`, never `index`.** The write key grants `create_doc`, which can +//! create but not overwrite — `index` comes back as a per-item 403. That restriction is +//! deliberate: it stops one beta participant overwriting another's document by `_id`. +//! 2. **A `_bulk` response is `200 OK` even when documents failed.** Success is per position in +//! `items[]`; trusting the HTTP status alone silently discards failures. +//! 3. **`200` at a position is a success, not a retry.** It means the server-side level filter +//! dropped the document. It is reported as success precisely so forwarders do not retry it +//! forever. +//! 4. **`409` is also a success.** It means a document with that `_id` is already indexed — our own +//! earlier attempt landed after all. That is the entire point of the deterministic `_id`, and +//! treating it as an error would turn a successful recovery into a reported failure. +//! +//! The proxy forces `filter_path=errors,items.*.status,items.*.error` on the response, so positions +//! line up with the submitted documents and a clean batch costs a handful of bytes to acknowledge. + +use std::time::Duration; + +use futures::future::BoxFuture; + +use super::document::ForwardDocument; +use super::sink::{BatchOutcome, DocumentOutcome, LogSink}; + +/// How long to wait for the endpoint before giving up on a batch. +const REQUEST_TIMEOUT: Duration = Duration::from_secs(30); + +/// Ships documents to an Elasticsearch `_bulk` endpoint. +pub struct ElasticsearchSink { + client: reqwest::Client, + bulk_url: String, + token: String, +} + +impl ElasticsearchSink { + /// Build a sink for the given endpoint base and write-only API key. + pub fn new(endpoint_base: &str, token: &str) -> crate::error::Result { + let client = reqwest::Client::builder() + .timeout(REQUEST_TIMEOUT) + .build() + .map_err(|e| crate::error::Error::LogForward(format!("HTTP client: {e}")))?; + + Ok(Self { + client, + bulk_url: format!("{}/_bulk", endpoint_base.trim_end_matches('/')), + token: token.to_string(), + }) + } + + /// Frame documents as an NDJSON bulk body. + /// + /// Each document contributes two lines — the `create` action naming its index and id, then its + /// source — and the body ends with a newline, which Elasticsearch requires. + #[must_use] + pub fn build_body(batch: &[ForwardDocument]) -> String { + let mut body = String::new(); + + for document in batch { + let action = serde_json::json!({ + "create": { "_index": document.index, "_id": document.id } + }); + // Serialization of these types cannot fail: the action is built from strings here, and + // the source is a plain struct of strings and options. + body.push_str(&serde_json::to_string(&action).unwrap_or_default()); + body.push('\n'); + body.push_str(&serde_json::to_string(&document.source).unwrap_or_default()); + body.push('\n'); + } + + body + } + + /// Map a per-item bulk status onto what the forwarder should do next. + #[must_use] + pub fn classify_item_status(status: u64) -> DocumentOutcome { + match status { + // Created, dropped by the server-side level filter, or already present from an earlier + // attempt of ours. All three mean "stop carrying this document around". + 200..=299 | 409 => DocumentOutcome::Delivered, + // Busy or briefly unavailable. + 429 | 500..=599 => DocumentOutcome::Retryable, + // Anything else — 400 mapping conflicts, 403 permission errors — will fail identically + // on every retry. + _ => DocumentOutcome::Rejected, + } + } + + /// Interpret a bulk response body against the batch that produced it. + #[must_use] + pub fn classify_response(body: &str, batch_len: usize) -> BatchOutcome { + let Ok(value) = serde_json::from_str::(body) else { + // An unparseable body from a 2xx response is not something a retry will fix, but nor is + // it safe to call the documents delivered. + return BatchOutcome { + outcomes: vec![DocumentOutcome::Retryable; batch_len], + transport_failure: false, + error: Some("could not parse the bulk response".to_string()), + }; + }; + + if value.get("errors").and_then(serde_json::Value::as_bool) == Some(false) { + return BatchOutcome::all_delivered(batch_len); + } + + let Some(items) = value.get("items").and_then(serde_json::Value::as_array) else { + return BatchOutcome { + outcomes: vec![DocumentOutcome::Retryable; batch_len], + transport_failure: false, + error: Some("bulk response reported errors but listed no items".to_string()), + }; + }; + + let mut outcomes = Vec::with_capacity(items.len()); + // A batch can fail two ways at once — a transient 429 here, a permanent 403 there. Status + // output has room for one, and the permanent one is the one the user can act on, so it + // wins regardless of which came first in the array. + let mut permanent_error = None; + let mut transient_error = None; + + for item in items { + // The action key is `create`, but read whatever key is present rather than assume it. + let entry = item + .as_object() + .and_then(|object| object.values().next()) + .and_then(serde_json::Value::as_object); + + let status = entry + .and_then(|entry| entry.get("status")) + .and_then(serde_json::Value::as_u64); + + let outcome = match status { + Some(status) => { + let classified = Self::classify_item_status(status); + match classified { + DocumentOutcome::Rejected if permanent_error.is_none() => { + permanent_error = Some(describe_item_error(entry, status)); + } + DocumentOutcome::Retryable if transient_error.is_none() => { + transient_error = Some(describe_item_error(entry, status)); + } + _ => {} + } + classified + } + // No status for this position: nothing is known, so do not claim it landed. + None => DocumentOutcome::Retryable, + }; + outcomes.push(outcome); + } + + // A response shorter than the batch leaves a tail unaccounted for; `deliver` retries any + // position it has no outcome for, so padding here would actively lose documents. + BatchOutcome { + outcomes, + transport_failure: false, + error: permanent_error.or(transient_error), + } + } +} + +fn describe_item_error( + entry: Option<&serde_json::Map>, + status: u64, +) -> String { + let reason = entry + .and_then(|entry| entry.get("error")) + .and_then(|error| error.get("reason")) + .and_then(serde_json::Value::as_str); + + match reason { + Some(reason) => format!("bulk item failed with {status}: {reason}"), + None => format!("bulk item failed with {status}"), + } +} + +impl LogSink for ElasticsearchSink { + fn send<'a>(&'a self, batch: &'a [ForwardDocument]) -> BoxFuture<'a, BatchOutcome> { + Box::pin(async move { + if batch.is_empty() { + return BatchOutcome::all_delivered(0); + } + + let response = self + .client + .post(&self.bulk_url) + .header("Authorization", format!("ApiKey {}", self.token)) + .header("Content-Type", "application/x-ndjson") + .body(Self::build_body(batch)) + .send() + .await; + + let response = match response { + Ok(response) => response, + // The request never completed, so nothing is known about what landed. Replaying is + // safe because every document carries a deterministic `_id`. + Err(error) => return BatchOutcome::transport_failure(error.to_string()), + }; + + let status = response.status(); + + if status.is_success() { + let body = response.text().await.unwrap_or_default(); + return Self::classify_response(&body, batch.len()); + } + + // A whole-request rejection. 429 and 5xx are worth another go; 401 (bad key), 413 + // (body too large) and the rest will fail the same way every time. + let outcome = if status.as_u16() == 429 || status.is_server_error() { + DocumentOutcome::Retryable + } else { + DocumentOutcome::Rejected + }; + + BatchOutcome { + outcomes: vec![outcome; batch.len()], + transport_failure: false, + error: Some(format!("bulk request rejected with HTTP {status}")), + } + }) + } + + fn describe(&self) -> String { + self.bulk_url.clone() + } +} + +#[cfg(test)] +mod tests { + use super::*; + use crate::node::daemon::forward::document::DocumentSource; + + fn document(id: &str, index: &str) -> ForwardDocument { + ForwardDocument { + id: id.to_string(), + index: index.to_string(), + source: DocumentSource { + timestamp: "2026-08-19T20:50:00.000000Z".to_string(), + level: "INFO".to_string(), + target: Some("ant_node::node".to_string()), + message: "hello".to_string(), + node_id: "7".to_string(), + service: "node7".to_string(), + binary_version: "0.17.2".to_string(), + channel: "beta".to_string(), + os: "linux".to_string(), + arch: "x86_64".to_string(), + peer_id: None, + version: None, + commit: None, + }, + } + } + + #[test] + fn the_bulk_action_is_create_not_index() { + let body = ElasticsearchSink::build_body(&[document("id-1", "beta-nodes-2026.08.19")]); + let action: serde_json::Value = serde_json::from_str(body.lines().next().unwrap()).unwrap(); + + assert!( + action.get("create").is_some(), + "`index` is refused with a per-item 403: {body}" + ); + assert!(action.get("index").is_none()); + assert_eq!(action["create"]["_index"], "beta-nodes-2026.08.19"); + assert_eq!(action["create"]["_id"], "id-1"); + } + + #[test] + fn the_body_is_ndjson_with_the_required_trailing_newline() { + let body = ElasticsearchSink::build_body(&[ + document("id-1", "beta-nodes-2026.08.19"), + document("id-2", "beta-nodes-2026.08.19"), + ]); + + assert!(body.ends_with('\n'), "Elasticsearch requires it"); + let lines: Vec<&str> = body.lines().collect(); + assert_eq!(lines.len(), 4, "one action and one source per document"); + + for line in &lines { + serde_json::from_str::(line) + .unwrap_or_else(|_| panic!("every line must be standalone JSON: {line}")); + } + let source: serde_json::Value = serde_json::from_str(lines[1]).unwrap(); + assert_eq!(source["@timestamp"], "2026-08-19T20:50:00.000000Z"); + } + + #[test] + fn an_empty_batch_produces_an_empty_body() { + assert_eq!(ElasticsearchSink::build_body(&[]), ""); + } + + /// 201 created, 200 dropped by the server-side level filter, and 409 already-indexed all mean + /// the forwarder is finished with the document. + #[test] + fn created_filtered_and_already_indexed_all_count_as_delivered() { + for status in [200, 201, 409] { + assert_eq!( + ElasticsearchSink::classify_item_status(status), + DocumentOutcome::Delivered, + "status {status}" + ); + } + } + + #[test] + fn busy_and_server_errors_are_retryable() { + for status in [429, 500, 502, 503] { + assert_eq!( + ElasticsearchSink::classify_item_status(status), + DocumentOutcome::Retryable, + "status {status}" + ); + } + } + + #[test] + fn permission_and_mapping_errors_are_permanent() { + for status in [400, 401, 403, 404] { + assert_eq!( + ElasticsearchSink::classify_item_status(status), + DocumentOutcome::Rejected, + "status {status}" + ); + } + } + + #[test] + fn a_clean_response_delivers_the_whole_batch() { + let outcome = ElasticsearchSink::classify_response(r#"{"errors":false}"#, 3); + assert_eq!(outcome.outcomes, vec![DocumentOutcome::Delivered; 3]); + assert!(outcome.error.is_none()); + assert!(!outcome.transport_failure); + } + + /// The shape the proxy's forced `filter_path` produces on a dirty batch: one entry per + /// submitted document, positions preserved. + #[test] + fn a_mixed_response_is_mapped_position_by_position() { + let body = r#"{ + "errors": true, + "items": [ + {"create": {"status": 201}}, + {"create": {"status": 429}}, + {"create": {"status": 403, "error": {"reason": "action [create] is unauthorized"}}}, + {"create": {"status": 200}}, + {"create": {"status": 409}} + ] + }"#; + + let outcome = ElasticsearchSink::classify_response(body, 5); + + assert_eq!( + outcome.outcomes, + vec![ + DocumentOutcome::Delivered, + DocumentOutcome::Retryable, + DocumentOutcome::Rejected, + DocumentOutcome::Delivered, + DocumentOutcome::Delivered, + ] + ); + let error = outcome.error.unwrap(); + assert!( + error.contains("403") && error.contains("unauthorized"), + "the permanent failure is the actionable one, not the transient 429: {error}" + ); + } + + /// With nothing permanent to report, the transient failure is better than saying nothing. + #[test] + fn a_transient_error_is_surfaced_when_it_is_the_only_one() { + let body = r#"{"errors":true,"items":[{"create":{"status":429}}]}"#; + let error = ElasticsearchSink::classify_response(body, 1).error.unwrap(); + assert!(error.contains("429"), "{error}"); + } + + /// A 409 is our own earlier attempt having landed — a recovery, not a failure worth reporting. + #[test] + fn a_conflict_is_not_reported_as_an_error() { + let body = r#"{"errors":true,"items":[{"create":{"status":409}}]}"#; + let outcome = ElasticsearchSink::classify_response(body, 1); + + assert_eq!(outcome.outcomes, vec![DocumentOutcome::Delivered]); + assert!( + outcome.error.is_none(), + "a deduplicated replay is the mechanism working" + ); + } + + #[test] + fn a_short_items_array_leaves_the_tail_unaccounted_for() { + let body = r#"{"errors":true,"items":[{"create":{"status":201}}]}"#; + let outcome = ElasticsearchSink::classify_response(body, 3); + + assert_eq!( + outcome.outcomes.len(), + 1, + "the tail is left for deliver() to retry rather than assumed delivered" + ); + } + + #[test] + fn an_item_without_a_status_is_retried_rather_than_assumed_delivered() { + let body = r#"{"errors":true,"items":[{"create":{}}]}"#; + let outcome = ElasticsearchSink::classify_response(body, 1); + assert_eq!(outcome.outcomes, vec![DocumentOutcome::Retryable]); + } + + #[test] + fn an_unparseable_body_is_retried_not_discarded() { + let outcome = ElasticsearchSink::classify_response("gateway error", 2); + assert_eq!(outcome.outcomes, vec![DocumentOutcome::Retryable; 2]); + assert!(outcome.error.unwrap().contains("parse")); + } + + #[test] + fn errors_reported_without_items_are_retried() { + let outcome = ElasticsearchSink::classify_response(r#"{"errors":true}"#, 2); + assert_eq!(outcome.outcomes, vec![DocumentOutcome::Retryable; 2]); + } + + #[test] + fn the_sink_describes_the_bulk_url_it_targets() { + let sink = ElasticsearchSink::new("https://logs.autonomi.com/", "key").unwrap(); + assert_eq!(sink.describe(), "https://logs.autonomi.com/_bulk"); + } +} diff --git a/ant-core/src/node/daemon/forward/mod.rs b/ant-core/src/node/daemon/forward/mod.rs new file mode 100644 index 00000000..cbb03dbb --- /dev/null +++ b/ant-core/src/node/daemon/forward/mod.rs @@ -0,0 +1,350 @@ +//! Opt-in forwarding of managed nodes' log files to the beta-channel Elasticsearch. +//! +//! The daemon already knows the log directory of every node it manages, so forwarding needs no OS +//! service, no separate install, and nothing platform-specific: `ant node logs forward enable` is +//! the consent act, and from then on a background task tails those files and batch-ships their +//! events until the user runs `disable`. +//! +//! Three properties shape the whole design: +//! +//! - **It must never slow a node down.** The forwarder only *reads* log files. It never touches a +//! node process, its stdio, or any lock on the node's path, and all of its work happens on its +//! own task. +//! - **Delivery is best-effort.** This is logs-only telemetry, so a lost batch is acceptable and +//! nothing here is allowed to grow without bound waiting for the endpoint to come back. +//! - **A daemon restart must not duplicate or lose events.** Tail offsets are persisted, and every +//! document carries a deterministic `_id` so that replaying a batch after a transport failure is +//! idempotent rather than duplicating whatever already landed. + +pub mod config; +pub mod document; +pub mod es; +pub mod offsets; +pub mod parse; +pub mod runner; +pub mod sink; +pub mod tail; + +use serde::{Deserialize, Serialize}; + +pub use config::{LogForwardConfig, LogLevel, DEFAULT_ENDPOINT, DEFAULT_INDEX_PREFIX}; +pub use document::{ForwardDocument, NodeTags}; +pub use es::ElasticsearchSink; +pub use offsets::OffsetStore; +pub use parse::{parse_line, LogEvent}; +pub use runner::{classify_nodes, spawn_log_forwarder, ForwarderHandle, DEFAULT_POLL_INTERVAL}; +pub use sink::{BatchOutcome, DocumentOutcome, DocumentQueue, LogSink, RetryPolicy}; +pub use tail::{LogTailer, TailedEvent}; + +/// A node the forwarder is tailing. +#[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize, utoipa::ToSchema)] +pub struct ForwardingNode { + pub node_id: u32, + pub service: String, + /// Log directory being tailed. + pub log_dir: String, +} + +/// A node the forwarder cannot tail, and why. +/// +/// The common case by far is a node added without `--log-dir-path`: node file logging is off by +/// default, so such a node writes no log files at all and there is nothing to forward. Surfacing +/// these explicitly is what stops `enable` looking like it succeeded while shipping nothing. +#[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize, utoipa::ToSchema)] +pub struct SkippedNode { + pub node_id: u32, + pub service: String, + /// Human-readable explanation, suitable for printing directly. + pub reason: String, +} + +impl SkippedNode { + /// The skip reason for a node that has no log directory configured. + #[must_use] + pub fn no_logging(node_id: u32, service: impl Into) -> Self { + Self { + node_id, + service: service.into(), + reason: "logging is not enabled for this node — re-add it with --log-dir-path to \ + forward its logs" + .to_string(), + } + } +} + +/// Counters describing what the forwarder has done since the daemon started. +/// +/// Deliberately cheap to maintain and safe to lose: these are for answering "is it working?", not +/// for accounting. They reset when the daemon restarts. +#[derive(Debug, Clone, Default, PartialEq, Eq, Serialize, Deserialize, utoipa::ToSchema)] +pub struct ForwardStats { + /// Events accepted by the endpoint. + pub events_forwarded: u64, + /// Events dropped locally for being below the configured minimum level. + pub events_dropped_by_level: u64, + /// Events dropped because the in-memory queue was full — the endpoint could not keep up and + /// the forwarder chose to bound its memory rather than block. + pub events_dropped_by_overflow: u64, + /// Batches the endpoint accepted in full. + pub batches_sent: u64, + /// Batches abandoned after exhausting their retries. + pub batches_failed: u64, + /// Unix seconds of the last batch the endpoint accepted. + pub last_success_unix: Option, + /// Most recent delivery error, retained so `status` can explain a stalled flow. + pub last_error: Option, +} + +/// Everything `ant node logs forward status` reports. +/// +/// Carries a token *fingerprint*, never the token: the daemon serves this over HTTP, and handing +/// the write key back out would widen the blast radius of anything that can reach the API. +#[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize, utoipa::ToSchema)] +pub struct LogForwardStatus { + pub enabled: bool, + pub endpoint: String, + pub index_prefix: String, + pub min_level: LogLevel, + /// Short, non-reversible identifier for the configured token. `None` when none is set. + pub token_fingerprint: Option, + /// Whether the background task is currently running. Distinguishes "enabled but the daemon has + /// not been restarted yet" from "enabled and shipping". + pub active: bool, + pub nodes_forwarding: Vec, + pub nodes_skipped: Vec, + pub stats: ForwardStats, +} + +impl LogForwardStatus { + /// Build a status from persisted config alone, for the case where no forwarder is running — + /// either forwarding is disabled, or the CLI is reading the config with the daemon down. + #[must_use] + pub fn inactive(config: &LogForwardConfig) -> Self { + Self { + enabled: config.enabled, + endpoint: config.endpoint.clone(), + index_prefix: config.index_prefix.clone(), + min_level: config.min_level, + token_fingerprint: config.token_fingerprint(), + active: false, + nodes_forwarding: Vec::new(), + nodes_skipped: Vec::new(), + stats: ForwardStats::default(), + } + } +} + +/// Request body for enabling forwarding. +/// +/// Every field is optional so that re-enabling after a `disable` needs no arguments: the stored +/// token, endpoint and level are reused unless the caller overrides them. Only the very first +/// `enable` on a machine has to supply a token. +#[derive(Debug, Clone, Default, PartialEq, Eq, Serialize, Deserialize, utoipa::ToSchema)] +pub struct LogForwardEnableRequest { + /// Write-only Elasticsearch API key. Reuses the stored one when omitted. + #[serde(default)] + pub token: Option, + /// Ingest endpoint override, for testing against a local sink. + #[serde(default)] + pub endpoint: Option, + /// Minimum level to forward. Defaults to INFO on first enable. + #[serde(default)] + pub min_level: Option, +} + +/// Merge a request onto the stored config and validate the result. +/// +/// Kept out of both the HTTP handler and the CLI so the two paths cannot drift: `enable` means the +/// same thing whether it arrives over the daemon's API or is written straight to disk with the +/// daemon stopped. +pub fn apply_enable( + stored: &LogForwardConfig, + request: &LogForwardEnableRequest, +) -> crate::error::Result { + let mut config = stored.clone(); + config.enabled = true; + + if let Some(token) = &request.token { + config.token = token.trim().to_string(); + } + if let Some(endpoint) = &request.endpoint { + config.endpoint = endpoint.trim().to_string(); + } + if let Some(level) = request.min_level { + config.min_level = level; + } + + // Generated on the first enable and stable thereafter. Document ids are namespaced by it, so a + // machine that has never opted in needs one before it can ship anything. + config.ensure_installation_id(); + + config.validate()?; + Ok(config) +} + +/// Outcome of `enable` or `disable`. +#[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize, utoipa::ToSchema)] +pub struct LogForwardResult { + /// Whether forwarding is enabled after the call. + pub enabled: bool, + /// True when the call found the setting already in the requested state. + pub already_in_state: bool, + pub endpoint: String, + pub min_level: LogLevel, + /// Nodes that will be tailed. + pub nodes_forwarding: Vec, + /// Nodes that cannot be tailed, with reasons — most often because they have no log directory. + pub nodes_skipped: Vec, + /// Set when the config was persisted but no forwarder could be started because the daemon is + /// not running; forwarding begins when it next starts. + pub pending_daemon_start: bool, +} + +#[cfg(test)] +mod tests { + use super::*; + + fn stored_with_token() -> LogForwardConfig { + LogForwardConfig { + enabled: false, + token: "stored-key".to_string(), + installation_id: "0123456789abcdef".to_string(), + ..LogForwardConfig::disabled() + } + } + + #[test] + fn enabling_for_the_first_time_requires_a_token() { + let error = apply_enable( + &LogForwardConfig::disabled(), + &LogForwardEnableRequest::default(), + ) + .unwrap_err() + .to_string(); + assert!(error.contains("token"), "{error}"); + } + + /// Re-enabling after `disable` must not make the user find their key again. + #[test] + fn re_enabling_reuses_the_stored_token_and_settings() { + let stored = LogForwardConfig { + endpoint: "http://127.0.0.1:9999".to_string(), + min_level: LogLevel::Warn, + ..stored_with_token() + }; + + let config = apply_enable(&stored, &LogForwardEnableRequest::default()).unwrap(); + + assert!(config.enabled); + assert_eq!(config.token, "stored-key"); + assert_eq!(config.endpoint, "http://127.0.0.1:9999"); + assert_eq!(config.min_level, LogLevel::Warn); + } + + /// The namespace is minted on the first enable, and never changes afterwards — regenerating it + /// would make a replayed batch look like new documents and duplicate them. + #[test] + fn enabling_mints_an_installation_id_and_later_enables_keep_it() { + let config = apply_enable( + &LogForwardConfig::disabled(), + &LogForwardEnableRequest { + token: Some("first-key".to_string()), + ..LogForwardEnableRequest::default() + }, + ) + .unwrap(); + assert_eq!(config.installation_id.len(), 16); + + let re_enabled = apply_enable(&config, &LogForwardEnableRequest::default()).unwrap(); + assert_eq!(re_enabled.installation_id, config.installation_id); + + // Even rotating the token must not change it. + let rotated = apply_enable( + &config, + &LogForwardEnableRequest { + token: Some("rotated-key".to_string()), + ..LogForwardEnableRequest::default() + }, + ) + .unwrap(); + assert_eq!(rotated.installation_id, config.installation_id); + } + + #[test] + fn a_supplied_token_endpoint_and_level_override_what_was_stored() { + let config = apply_enable( + &stored_with_token(), + &LogForwardEnableRequest { + token: Some(" rotated-key ".to_string()), + endpoint: Some("http://localhost:8080".to_string()), + min_level: Some(LogLevel::Error), + }, + ) + .unwrap(); + + assert_eq!(config.token, "rotated-key", "surrounding space is trimmed"); + assert_eq!(config.endpoint, "http://localhost:8080"); + assert_eq!(config.min_level, LogLevel::Error); + } + + #[test] + fn an_invalid_endpoint_is_rejected_before_anything_is_persisted() { + let error = apply_enable( + &stored_with_token(), + &LogForwardEnableRequest { + endpoint: Some("logs.autonomi.com".to_string()), + ..LogForwardEnableRequest::default() + }, + ) + .unwrap_err() + .to_string(); + assert!(error.contains("http(s) URL"), "{error}"); + } + + #[test] + fn inactive_status_mirrors_the_config_without_exposing_the_token() { + let config = LogForwardConfig { + enabled: true, + token: "secret-api-key".to_string(), + ..LogForwardConfig::disabled() + }; + + let status = LogForwardStatus::inactive(&config); + + assert!(status.enabled); + assert!(!status.active); + assert_eq!(status.endpoint, DEFAULT_ENDPOINT); + assert_eq!(status.min_level, LogLevel::Info); + assert_eq!(status.token_fingerprint, config.token_fingerprint()); + + let json = serde_json::to_string(&status).unwrap(); + assert!( + !json.contains("secret-api-key"), + "status must never carry the token: {json}" + ); + } + + #[test] + fn inactive_status_of_a_disabled_config_has_no_fingerprint() { + let status = LogForwardStatus::inactive(&LogForwardConfig::disabled()); + assert!(!status.enabled); + assert_eq!(status.token_fingerprint, None); + } + + #[test] + fn skip_reason_points_at_the_flag_that_fixes_it() { + let skipped = SkippedNode::no_logging(3, "node3"); + assert_eq!(skipped.node_id, 3); + assert_eq!(skipped.service, "node3"); + assert!(skipped.reason.contains("--log-dir-path")); + } + + #[test] + fn stats_start_at_zero() { + let stats = ForwardStats::default(); + assert_eq!(stats.events_forwarded, 0); + assert_eq!(stats.batches_failed, 0); + assert_eq!(stats.last_success_unix, None); + assert_eq!(stats.last_error, None); + } +} diff --git a/ant-core/src/node/daemon/forward/offsets.rs b/ant-core/src/node/daemon/forward/offsets.rs new file mode 100644 index 00000000..bd7f2b2c --- /dev/null +++ b/ant-core/src/node/daemon/forward/offsets.rs @@ -0,0 +1,231 @@ +//! Persisted tail positions, so a daemon restart resumes where it left off. +//! +//! Without this the forwarder would have to choose between re-reading whole files on every start +//! (duplicating everything) and starting at the end (losing everything written while the daemon was +//! down). The acceptance criterion for V2-1021 is explicitly neither, so positions are written to +//! disk and reloaded. +//! +//! Positions are keyed by absolute log file path. ant-node rotates daily by *filename* +//! (`ant-node.2026-08-19.log`), so a new day is a new key rather than a moved cursor, and the +//! retention limit eventually deletes old ones — hence [`OffsetStore::prune`]. + +use std::collections::HashMap; +use std::path::{Path, PathBuf}; + +use serde::{Deserialize, Serialize}; + +use crate::config; +use crate::error::Result; + +/// Filename of the persisted offsets within [`config::data_dir`]. +const OFFSETS_FILENAME: &str = "log_forward_offsets.json"; + +/// Bytes of a log file that have been read and emitted. +#[derive(Debug, Clone, Copy, PartialEq, Eq, Default, Serialize, Deserialize)] +pub struct FileOffset { + /// Byte position immediately after the last event handed to the sink. + pub offset: u64, +} + +/// Tail positions for every log file being followed. +#[derive(Debug, Clone, Default, Serialize, Deserialize)] +pub struct OffsetStore { + #[serde(default)] + offsets: HashMap, + + #[serde(skip)] + path: PathBuf, + + /// Set when an offset has changed since the last successful save, so an idle forwarder does not + /// rewrite an identical file every poll. + #[serde(skip)] + dirty: bool, +} + +impl OffsetStore { + /// Path of the persisted offsets for this machine. + pub fn default_path() -> Result { + Ok(config::data_dir()?.join(OFFSETS_FILENAME)) + } + + /// Load offsets from disk, starting empty when the file is absent. + /// + /// A corrupt file starts empty rather than failing: unlike the opt-in config, losing positions + /// degrades to "resume from the current end of file", which is a recoverable inconvenience + /// rather than a silent misrepresentation of what the user consented to. + pub fn load(path: &Path) -> Self { + let mut store = std::fs::read_to_string(path) + .ok() + .and_then(|contents| serde_json::from_str::(&contents).ok()) + .unwrap_or_default(); + store.path = path.to_path_buf(); + store + } + + /// Position for a file, or `None` if it has never been read. + #[must_use] + pub fn get(&self, key: &str) -> Option { + self.offsets.get(key).map(|entry| entry.offset) + } + + /// Record a new position. + pub fn set(&mut self, key: &str, offset: u64) { + let entry = self.offsets.entry(key.to_string()).or_default(); + if entry.offset != offset { + entry.offset = offset; + self.dirty = true; + } + } + + /// Forget every file not in `live`, so retention-deleted dailies do not accumulate forever. + pub fn prune(&mut self, live: &[String]) { + let before = self.offsets.len(); + self.offsets.retain(|key, _| live.iter().any(|k| k == key)); + if self.offsets.len() != before { + self.dirty = true; + } + } + + /// Paths of every file with a recorded position. + /// + /// Used to tell a node being *resumed* — one whose files already have positions — from one + /// being adopted for the first time, which must join its log at the end rather than upload the + /// retained history. + pub fn keys(&self) -> impl Iterator { + self.offsets.keys().map(String::as_str) + } + + /// Whether anything has changed since the last successful [`Self::save`]. + #[must_use] + pub fn is_dirty(&self) -> bool { + self.dirty + } + + #[must_use] + pub fn len(&self) -> usize { + self.offsets.len() + } + + #[must_use] + pub fn is_empty(&self) -> bool { + self.offsets.is_empty() + } + + /// Write offsets to disk atomically, if anything changed. + /// + /// The temporary-file-then-rename dance matters here: a half-written offsets file that parsed + /// as valid JSON with a truncated position would replay a chunk of log on the next start. + pub fn save(&mut self) -> Result<()> { + if !self.dirty { + return Ok(()); + } + if let Some(parent) = self.path.parent() { + std::fs::create_dir_all(parent)?; + } + let contents = serde_json::to_string_pretty(self)?; + let tmp_path = self.path.with_extension("tmp"); + std::fs::write(&tmp_path, &contents)?; + std::fs::rename(&tmp_path, &self.path)?; + self.dirty = false; + Ok(()) + } +} + +#[cfg(test)] +mod tests { + use super::*; + + fn store_at(dir: &Path) -> OffsetStore { + OffsetStore::load(&dir.join(OFFSETS_FILENAME)) + } + + #[test] + fn absent_file_loads_empty() { + let tmp = tempfile::tempdir().unwrap(); + let store = store_at(tmp.path()); + assert!(store.is_empty()); + assert_eq!(store.get("anything"), None); + } + + #[test] + fn positions_survive_a_save_and_reload() { + let tmp = tempfile::tempdir().unwrap(); + let mut store = store_at(tmp.path()); + store.set("/logs/ant-node.2026-08-19.log", 4096); + store.save().unwrap(); + + let reloaded = store_at(tmp.path()); + assert_eq!(reloaded.get("/logs/ant-node.2026-08-19.log"), Some(4096)); + } + + #[test] + fn a_corrupt_offsets_file_starts_empty_rather_than_failing() { + let tmp = tempfile::tempdir().unwrap(); + std::fs::write(tmp.path().join(OFFSETS_FILENAME), "{{{ truncated").unwrap(); + assert!(store_at(tmp.path()).is_empty()); + } + + #[test] + fn saving_is_skipped_while_nothing_has_changed() { + let tmp = tempfile::tempdir().unwrap(); + let mut store = store_at(tmp.path()); + assert!(!store.is_dirty()); + + store.set("a", 10); + assert!(store.is_dirty()); + store.save().unwrap(); + assert!(!store.is_dirty()); + + // Setting the same value again is not a change. + store.set("a", 10); + assert!(!store.is_dirty()); + + store.set("a", 11); + assert!(store.is_dirty()); + } + + #[test] + fn pruning_forgets_files_that_retention_deleted() { + let tmp = tempfile::tempdir().unwrap(); + let mut store = store_at(tmp.path()); + store.set("old.log", 1); + store.set("current.log", 2); + store.save().unwrap(); + + store.prune(&["current.log".to_string()]); + + assert_eq!(store.get("old.log"), None); + assert_eq!(store.get("current.log"), Some(2)); + assert!(store.is_dirty(), "pruning is a change worth persisting"); + } + + #[test] + fn keys_lists_every_tracked_file() { + let tmp = tempfile::tempdir().unwrap(); + let mut store = store_at(tmp.path()); + store.set("/logs/node-1/ant-node.2026-08-19.log", 1); + store.set("/logs/node-2/ant-node.2026-08-19.log", 2); + + let mut keys: Vec<&str> = store.keys().collect(); + keys.sort_unstable(); + assert_eq!( + keys, + vec![ + "/logs/node-1/ant-node.2026-08-19.log", + "/logs/node-2/ant-node.2026-08-19.log" + ] + ); + assert!(store.keys().any(|key| key.starts_with("/logs/node-1"))); + } + + #[test] + fn pruning_nothing_is_not_a_change() { + let tmp = tempfile::tempdir().unwrap(); + let mut store = store_at(tmp.path()); + store.set("current.log", 2); + store.save().unwrap(); + + store.prune(&["current.log".to_string()]); + assert!(!store.is_dirty()); + } +} diff --git a/ant-core/src/node/daemon/forward/parse.rs b/ant-core/src/node/daemon/forward/parse.rs new file mode 100644 index 00000000..6510b2ea --- /dev/null +++ b/ant-core/src/node/daemon/forward/parse.rs @@ -0,0 +1,408 @@ +//! Turning a line of an ant-node log file into a forwardable event. +//! +//! A node writes one of two layouts depending on `--log-format`, and the daemon does not set that +//! flag, so a user may have chosen either. Rather than force a format — which would mean adding an +//! argument to every node's command line and restarting them all just to switch forwarding on — +//! this module detects the layout per line: +//! +//! ```text +//! text: 2026-08-19T20:50:00.123456Z INFO ant_node::node: connected peers=3 +//! json: {"timestamp":"2026-08-19T20:50:00.123456Z","level":"INFO","target":"ant_node::node", …} +//! ``` +//! +//! Lines that are neither — panic messages, backtrace frames, anything a dependency writes +//! straight to the file — are continuations of the event above them rather than events in their +//! own right, and are appended to it. That keeps a multi-line panic intact as one document instead +//! of scattering it across twenty timestamp-less ones. + +use serde::{Deserialize, Serialize}; + +use super::config::LogLevel; + +/// A single parsed log event, before it is tagged with the node's identity. +#[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize)] +pub struct LogEvent { + /// RFC3339 timestamp, forwarded as `@timestamp`. + pub timestamp: String, + pub level: LogLevel, + /// Rust module path the event came from, when the layout carried one. + pub target: Option, + /// The event text, including any continuation lines appended to it. + pub message: String, + /// Public protocol identifier, lifted opportunistically when the line happens to carry one. + pub peer_id: Option, + /// Version ant-node reported for itself, present only on its startup line. + pub version: Option, + /// Commit ant-node reported for itself, present only on its startup line. + pub commit: Option, +} + +impl LogEvent { + /// Append a continuation line to this event's message. + pub fn push_continuation(&mut self, line: &str) { + self.message.push('\n'); + self.message.push_str(line); + } + + /// The daily index date for this event, as Elasticsearch wants it: `YYYY.MM.DD`. + /// + /// Derived from the event's own timestamp rather than the wall clock. That is not a stylistic + /// choice: document `_id`s are unique per index, so a batch replayed after midnight must land + /// in the same index its first attempt targeted or the deduplication silently stops working. + #[must_use] + pub fn index_date(&self) -> Option { + index_date_from_timestamp(&self.timestamp) + } +} + +/// Extract `YYYY.MM.DD` from an RFC3339 timestamp, validating the shape rather than trusting it. +#[must_use] +pub fn index_date_from_timestamp(timestamp: &str) -> Option { + let date = timestamp.get(..10)?; + let bytes = date.as_bytes(); + if bytes.len() != 10 || bytes[4] != b'-' || bytes[7] != b'-' { + return None; + } + if !bytes + .iter() + .enumerate() + .all(|(i, b)| matches!(i, 4 | 7) || b.is_ascii_digit()) + { + return None; + } + Some(format!("{}.{}.{}", &date[..4], &date[5..7], &date[8..10])) +} + +/// Parse one line, returning `None` when it is a continuation of the event above it. +#[must_use] +pub fn parse_line(line: &str) -> Option { + let trimmed = line.trim_end_matches(['\r', '\n']); + if trimmed.trim().is_empty() { + return None; + } + if trimmed.trim_start().starts_with('{') { + parse_json_line(trimmed) + } else { + parse_text_line(trimmed) + } +} + +/// Parse the JSON layout produced by `fmt::layer().json().flatten_event(true)`. +/// +/// `flatten_event` lifts the event's fields to the top level, so `message`, `peer_id`, `version` +/// and `commit` all sit beside `timestamp`, `level` and `target`. +fn parse_json_line(line: &str) -> Option { + let value: serde_json::Value = serde_json::from_str(line).ok()?; + let object = value.as_object()?; + + let level = LogLevel::parse(object.get("level")?.as_str()?)?; + let timestamp = object.get("timestamp")?.as_str()?.to_string(); + // Held to the same standard as the text layout: an event whose timestamp cannot be read is an + // event with no index to go to, so it is better treated as a continuation than shipped blind. + index_date_from_timestamp(×tamp)?; + + let message = object + .get("message") + .and_then(|m| { + m.as_str() + .map(str::to_string) + .or_else(|| Some(m.to_string())) + }) + .unwrap_or_default(); + + Some(LogEvent { + timestamp, + level, + target: object + .get("target") + .and_then(|t| t.as_str()) + .map(str::to_string), + message, + peer_id: json_string_field(object, "peer_id"), + version: json_string_field(object, "version"), + commit: json_string_field(object, "commit"), + }) +} + +/// Read a field as a string whether it was logged as one or as a number/bool via `Display`. +fn json_string_field( + object: &serde_json::Map, + key: &str, +) -> Option { + match object.get(key)? { + serde_json::Value::String(s) => Some(s.clone()), + serde_json::Value::Null => None, + other => Some(other.to_string()), + } +} + +/// Parse the default text layout: timestamp, level, optional span scope, target, then the message. +/// +/// The span-scope-and-target prefix is delimited from the message by `": "`, but so is any message +/// that happens to contain a colon. The prefix segments are therefore consumed only while they +/// still look like a span or module path — no whitespace, no stray punctuation — which is what +/// stops `connected to peer: 12D3Koo…` losing its first two words to a phantom target. +fn parse_text_line(line: &str) -> Option { + let mut parts = line.splitn(2, char::is_whitespace); + let timestamp = parts.next()?.to_string(); + // Cheapest available proof that this really is the start of an event rather than a stray line + // that happens to begin with a word. + index_date_from_timestamp(×tamp)?; + + let rest = parts.next()?.trim_start(); + let (level_token, rest) = rest.split_once(char::is_whitespace)?; + let level = LogLevel::parse(level_token)?; + + let (target, message) = split_target_and_message(rest.trim_start()); + + Some(LogEvent { + timestamp, + level, + target, + peer_id: scan_field(line, "peer_id"), + version: scan_field(line, "version"), + commit: scan_field(line, "commit"), + message, + }) +} + +fn split_target_and_message(rest: &str) -> (Option, String) { + let mut remaining = rest; + let mut target = None; + + while let Some(index) = remaining.find(": ") { + let head = &remaining[..index]; + if !looks_like_span_or_target(head) { + break; + } + if looks_like_target(head) { + target = Some(head.to_string()); + } + remaining = &remaining[index + 2..]; + } + + (target, remaining.to_string()) +} + +/// A span scope (`upload{id=1}`) or a module path — never a sentence. +fn looks_like_span_or_target(candidate: &str) -> bool { + !candidate.is_empty() && !candidate.contains(char::is_whitespace) +} + +/// A bare Rust module path, which is what the target always is. +fn looks_like_target(candidate: &str) -> bool { + !candidate.is_empty() + && candidate + .chars() + .all(|c| c.is_ascii_alphanumeric() || c == '_' || c == ':') +} + +/// Find a `key=value` field in a text-format line. +/// +/// Best-effort by design: the text layout does not delimit the message from the trailing fields, so +/// there is no way to do this exactly, and it is not worth a real parser. A false negative costs an +/// absent field on one document. +fn scan_field(line: &str, key: &str) -> Option { + let needle = format!("{key}="); + let mut search_from = 0; + + while let Some(offset) = line[search_from..].find(&needle) { + let start = search_from + offset; + let preceded_by_boundary = start == 0 + || line[..start] + .chars() + .next_back() + .is_some_and(char::is_whitespace); + + if preceded_by_boundary { + let value = &line[start + needle.len()..]; + let value = value + .split_whitespace() + .next() + .unwrap_or_default() + .trim_end_matches(',') + .trim_matches('"'); + if !value.is_empty() { + return Some(value.to_string()); + } + } + search_from = start + needle.len(); + } + + None +} + +#[cfg(test)] +mod tests { + use super::*; + + const TEXT_LINE: &str = + "2026-08-19T20:50:00.123456Z INFO ant_node::node: connected to the network peers=3"; + + #[test] + fn parses_the_text_layout() { + let event = parse_line(TEXT_LINE).unwrap(); + assert_eq!(event.timestamp, "2026-08-19T20:50:00.123456Z"); + assert_eq!(event.level, LogLevel::Info); + assert_eq!(event.target.as_deref(), Some("ant_node::node")); + assert_eq!(event.message, "connected to the network peers=3"); + } + + #[test] + fn parses_the_json_layout() { + let line = r#"{"timestamp":"2026-08-19T20:50:00.123456Z","level":"WARN","target":"ant_node::node","message":"peer unreachable","peer_id":"12D3KooWabc"}"#; + let event = parse_line(line).unwrap(); + assert_eq!(event.timestamp, "2026-08-19T20:50:00.123456Z"); + assert_eq!(event.level, LogLevel::Warn); + assert_eq!(event.target.as_deref(), Some("ant_node::node")); + assert_eq!(event.message, "peer unreachable"); + assert_eq!(event.peer_id.as_deref(), Some("12D3KooWabc")); + } + + #[test] + fn every_level_round_trips_through_the_text_layout() { + for (token, expected) in [ + ("TRACE", LogLevel::Trace), + ("DEBUG", LogLevel::Debug), + ("INFO", LogLevel::Info), + ("WARN", LogLevel::Warn), + ("ERROR", LogLevel::Error), + ] { + let line = format!("2026-08-19T20:50:00.123456Z {token} ant_node: hello"); + assert_eq!(parse_line(&line).unwrap().level, expected, "{token}"); + } + } + + /// The text layer pads the level to five columns, so INFO and WARN arrive with two leading + /// spaces where ERROR and TRACE arrive with one. + #[test] + fn tolerates_the_level_column_padding() { + let padded = "2026-08-19T20:50:00.123456Z INFO ant_node: hello"; + let unpadded = "2026-08-19T20:50:00.123456Z ERROR ant_node: hello"; + assert_eq!(parse_line(padded).unwrap().level, LogLevel::Info); + assert_eq!(parse_line(unpadded).unwrap().level, LogLevel::Error); + } + + /// The case the naive "split on the first colon" approach gets wrong. + #[test] + fn a_colon_in_the_message_does_not_become_a_target() { + let line = "2026-08-19T20:50:00.123456Z INFO ant_node: dialing peer: 12D3KooWabc"; + let event = parse_line(line).unwrap(); + assert_eq!(event.target.as_deref(), Some("ant_node")); + assert_eq!(event.message, "dialing peer: 12D3KooWabc"); + } + + #[test] + fn a_span_scope_before_the_target_is_skipped() { + let line = "2026-08-19T20:50:00.123456Z INFO upload{id=1}: ant_node::store: stored chunk"; + let event = parse_line(line).unwrap(); + assert_eq!(event.target.as_deref(), Some("ant_node::store")); + assert_eq!(event.message, "stored chunk"); + } + + #[test] + fn a_message_with_no_target_still_parses() { + let line = "2026-08-19T20:50:00.123456Z INFO started with no target at all"; + let event = parse_line(line).unwrap(); + assert_eq!(event.target, None); + assert_eq!(event.message, "started with no target at all"); + } + + #[test] + fn lines_without_a_timestamp_are_continuations() { + assert!(parse_line(" at src/node.rs:42").is_none()); + assert!(parse_line("thread 'main' panicked").is_none()); + assert!(parse_line("").is_none()); + assert!(parse_line(" ").is_none()); + } + + #[test] + fn a_line_with_an_unknown_level_is_treated_as_a_continuation() { + let line = "2026-08-19T20:50:00.123456Z NOISE ant_node: hello"; + assert!(parse_line(line).is_none()); + } + + #[test] + fn malformed_json_is_treated_as_a_continuation_rather_than_guessed_at() { + assert!(parse_line(r#"{"level":"INFO""#).is_none()); + assert!(parse_line(r#"{"level":"INFO","target":"x"}"#).is_none()); + } + + /// An event with an unreadable timestamp has no index to be written to, in either layout. + #[test] + fn a_json_line_with_an_unusable_timestamp_is_rejected() { + let line = r#"{"timestamp":"not-a-date","level":"INFO","message":"m"}"#; + assert!(parse_line(line).is_none()); + } + + #[test] + fn every_parsed_event_can_name_its_index() { + for line in [ + TEXT_LINE, + r#"{"timestamp":"2026-08-19T20:50:00.123456Z","level":"INFO","message":"m"}"#, + ] { + assert!(parse_line(line).unwrap().index_date().is_some(), "{line}"); + } + } + + #[test] + fn continuations_are_appended_to_the_event_above_them() { + let mut event = parse_line(TEXT_LINE).unwrap(); + event.push_continuation("thread 'main' panicked"); + event.push_continuation(" at src/node.rs:42"); + assert_eq!( + event.message, + "connected to the network peers=3\nthread 'main' panicked\n at src/node.rs:42" + ); + } + + #[test] + fn lifts_peer_id_version_and_commit_from_a_text_line() { + let line = "2026-08-19T20:50:00.123456Z INFO ant_node: starting version=0.17.2 commit=abc1234 peer_id=12D3KooWabc"; + let event = parse_line(line).unwrap(); + assert_eq!(event.version.as_deref(), Some("0.17.2")); + assert_eq!(event.commit.as_deref(), Some("abc1234")); + assert_eq!(event.peer_id.as_deref(), Some("12D3KooWabc")); + } + + #[test] + fn field_scanning_ignores_a_key_that_is_only_a_suffix_of_another() { + let line = "2026-08-19T20:50:00.123456Z INFO ant_node: hello node_version=9.9.9"; + assert_eq!(parse_line(line).unwrap().version, None); + } + + #[test] + fn field_scanning_strips_quotes_and_trailing_commas() { + let line = r#"2026-08-19T20:50:00.123456Z INFO ant_node: hello peer_id="12D3KooWabc","#; + assert_eq!( + parse_line(line).unwrap().peer_id.as_deref(), + Some("12D3KooWabc") + ); + } + + #[test] + fn a_json_field_logged_as_a_number_still_reads_as_a_string() { + let line = r#"{"timestamp":"2026-08-19T20:50:00.123456Z","level":"INFO","message":"m","peer_id":42}"#; + assert_eq!(parse_line(line).unwrap().peer_id.as_deref(), Some("42")); + } + + #[test] + fn index_date_is_derived_from_the_events_own_timestamp() { + let event = parse_line(TEXT_LINE).unwrap(); + assert_eq!(event.index_date().as_deref(), Some("2026.08.19")); + } + + #[test] + fn index_date_rejects_a_timestamp_it_cannot_trust() { + assert_eq!(index_date_from_timestamp("nonsense"), None); + assert_eq!(index_date_from_timestamp("2026/08/19T00:00:00Z"), None); + assert_eq!(index_date_from_timestamp("20xx-08-19T00:00:00Z"), None); + assert_eq!(index_date_from_timestamp("2026-08"), None); + } + + #[test] + fn trailing_newlines_are_stripped_from_the_message() { + let event = parse_line(&format!("{TEXT_LINE}\r\n")).unwrap(); + assert_eq!(event.message, "connected to the network peers=3"); + } +} diff --git a/ant-core/src/node/daemon/forward/runner.rs b/ant-core/src/node/daemon/forward/runner.rs new file mode 100644 index 00000000..f3d6025e --- /dev/null +++ b/ant-core/src/node/daemon/forward/runner.rs @@ -0,0 +1,686 @@ +//! The background task that does the forwarding. +//! +//! It follows the shape of the daemon's other background workers (`spawn_eviction_monitor`, +//! `spawn_liveness_monitor`): spawned once, driven by a poll interval, stopped by a +//! [`CancellationToken`]. It additionally carries its own token so `disable` can stop forwarding +//! without touching the daemon. +//! +//! The ordering within a cycle is deliberate: **poll, deliver, then persist offsets.** Persisting +//! before delivery would mean a daemon killed mid-cycle had already promised never to re-read +//! events that never left the machine. Doing it after means a crash re-reads a little, which the +//! deterministic document ids turn into harmless duplicates that the endpoint rejects with a 409. + +use std::collections::HashMap; +use std::path::PathBuf; +use std::sync::Arc; +use std::time::Duration; + +use tokio::sync::RwLock; +use tokio_util::sync::CancellationToken; + +use super::config::LogForwardConfig; +use super::document::{ForwardDocument, NodeTags}; +use super::offsets::OffsetStore; +use super::sink::{ + deliver, DocumentQueue, LogSink, RetryPolicy, DEFAULT_BATCH_BYTES, DEFAULT_BATCH_DOCUMENTS, + DEFAULT_QUEUE_CAPACITY, +}; +use super::tail::LogTailer; +use super::{ForwardStats, ForwardingNode, SkippedNode}; +use crate::node::registry::NodeRegistry; + +/// How often the forwarder looks for new log content. +/// +/// Fast enough to satisfy "logs appear within a minute" with room to spare — including the one +/// extra cycle the tailer spends holding a growing file's last event so continuation lines can join +/// it — and slow enough that following a handful of quiet files costs nothing measurable. +pub const DEFAULT_POLL_INTERVAL: Duration = Duration::from_secs(5); + +/// Live view of what the forwarder is doing, shared with the status endpoint. +/// +/// Counters only. Which nodes are being tailed is derived from the registry by +/// [`classify_nodes`] at the point of asking, so that status never reports a stale node list +/// from before the forwarder's first poll. +#[derive(Debug, Clone, Default)] +pub struct ForwarderSnapshot { + pub stats: ForwardStats, +} + +/// Handle to a running forwarder. +/// +/// Dropping this does not stop the task — the daemon holds it for the process's lifetime, and +/// `disable` stops it explicitly. +pub struct ForwarderHandle { + cancel: CancellationToken, + shared: Arc>, + endpoint: String, + /// Retained so that stopping can be *awaited*. Without this there is no way to tell a caller + /// that the last request has actually finished, which is what `disable` needs to promise. + task: tokio::sync::Mutex>>, +} + +impl ForwarderHandle { + /// Signal the forwarder to stop, without waiting for it. Idempotent. + /// + /// Prefer [`Self::stop_and_wait`] where the caller is about to tell a user that forwarding has + /// stopped. + pub fn stop(&self) { + self.cancel.cancel(); + } + + /// Stop forwarding and wait until the task has actually exited. + /// + /// This is what makes `disable` a real revocation boundary rather than a request. Cancellation + /// is observed inside the delivery loop, and dropping the in-flight future cancels the HTTP + /// request with it, so this returns promptly rather than after the retry ladder plays out. + pub async fn stop_and_wait(&self) { + self.cancel.cancel(); + let task = self.task.lock().await.take(); + if let Some(task) = task { + let _ = task.await; + } + } + + #[must_use] + pub fn is_stopped(&self) -> bool { + self.cancel.is_cancelled() + } + + /// Where this forwarder is shipping to, for status output. + #[must_use] + pub fn endpoint(&self) -> &str { + &self.endpoint + } + + /// Current counters and node lists. + pub async fn snapshot(&self) -> ForwarderSnapshot { + self.shared.read().await.clone() + } +} + +/// Start forwarding in the background. +pub fn spawn_log_forwarder( + registry: Arc>, + config: LogForwardConfig, + sink: Arc, + offsets_path: PathBuf, + poll_interval: Duration, + shutdown: CancellationToken, +) -> ForwarderHandle { + let cancel = CancellationToken::new(); + let shared = Arc::new(RwLock::new(ForwarderSnapshot::default())); + + let endpoint = sink.describe(); + let task_cancel = cancel.clone(); + let task_shared = shared.clone(); + + let task = tokio::spawn(async move { + let mut state = ForwarderRun { + registry, + config, + sink, + offsets: OffsetStore::load(&offsets_path), + tailers: HashMap::new(), + queue: DocumentQueue::new(DEFAULT_QUEUE_CAPACITY), + stats: ForwardStats::default(), + retry: RetryPolicy::default(), + cancel: task_cancel.clone(), + }; + + loop { + tokio::select! { + () = shutdown.cancelled() => break, + () = task_cancel.cancelled() => break, + () = tokio::time::sleep(poll_interval) => {} + } + + let snapshot = state.run_cycle().await; + *task_shared.write().await = snapshot; + } + + // A clean shutdown persists what was read, so the next start resumes rather than replays. + if let Err(error) = state.offsets.save() { + tracing::warn!("log forwarding: could not persist tail offsets: {error}"); + } + tracing::info!("log forwarding: stopped"); + }); + + ForwarderHandle { + cancel, + shared, + endpoint, + task: tokio::sync::Mutex::new(Some(task)), + } +} + +/// Everything one running forwarder owns. +struct ForwarderRun { + registry: Arc>, + config: LogForwardConfig, + sink: Arc, + offsets: OffsetStore, + tailers: HashMap, + queue: DocumentQueue, + stats: ForwardStats, + retry: RetryPolicy, + /// Cancelled by `disable` or by daemon shutdown. Checked between batches and raced against each + /// delivery, so neither an in-flight request nor a retry backoff outlives it. + cancel: CancellationToken, +} + +impl ForwarderRun { + /// One poll-and-ship cycle. + async fn run_cycle(&mut self) -> ForwarderSnapshot { + self.refresh_tailers().await; + + for (tailer, tags) in self.tailers.values_mut() { + if self.cancel.is_cancelled() { + break; + } + let outcome = match tailer.poll(&mut self.offsets, self.config.min_level).await { + Ok(outcome) => outcome, + Err(error) => { + tracing::debug!( + "log forwarding: node {} could not be read this cycle: {error}", + tailer.node_id() + ); + continue; + } + }; + + self.stats.events_dropped_by_level += outcome.dropped_by_level; + + for event in &outcome.events { + match ForwardDocument::build( + event, + tags, + &self.config.index_prefix, + &self.config.installation_id, + ) { + Some(document) => self.queue.push(document), + // Parsing rejects unusable timestamps, so this is defensive rather than + // expected; counting it keeps the totals honest either way. + None => self.stats.events_dropped_by_level += 1, + } + } + } + + self.flush_queue().await; + + if let Err(error) = self.offsets.save() { + tracing::warn!("log forwarding: could not persist tail offsets: {error}"); + } + + self.stats.events_dropped_by_overflow = self.queue.dropped(); + + ForwarderSnapshot { + stats: self.stats.clone(), + } + } + + /// Reconcile the tailer set against the registry, so nodes added or removed while forwarding is + /// on are picked up without an enable/disable cycle. + async fn refresh_tailers(&mut self) { + let registry = self.registry.read().await; + let (forwarding, _) = classify_nodes(®istry); + + let live: Vec = forwarding.iter().map(|node| node.node_id).collect(); + self.tailers.retain(|id, _| live.contains(id)); + + for node in ®istry.list() { + let Some(log_dir) = node.log_dir.clone() else { + continue; + }; + let tags = NodeTags::from_config(node); + + match self.tailers.get_mut(&node.id) { + // Identity can change under us: an auto-upgrade replaces the binary and bumps the + // version, and events after that point should say so. + Some((_, existing_tags)) => *existing_tags = tags, + None => { + let mut tailer = LogTailer::new(node.id, log_dir.clone()); + // A node whose files we already have positions for is being resumed, not newly + // adopted, so it must not skip forward to the end of its log. + if self.has_offsets_for(&log_dir) { + tailer.mark_primed(); + } + self.tailers.insert(node.id, (tailer, tags)); + } + } + } + } + + /// Whether persisted offsets already mention a file in this directory. + fn has_offsets_for(&self, log_dir: &std::path::Path) -> bool { + let prefix = log_dir.display().to_string(); + self.offsets.keys().any(|key| key.starts_with(&prefix)) + } + + /// Ship everything currently queued, abandoning the moment forwarding is revoked. + /// + /// Both checks matter. The loop check stops a full queue from taking further batches after + /// `disable`, and the `select!` drops the delivery future mid-flight — which cancels the HTTP + /// request with it, since a dropped `reqwest` future cancels the request, and discards any + /// pending retry backoff along with it. Without the second, a `disable` issued at the wrong + /// moment would keep uploading for the length of the retry ladder. + async fn flush_queue(&mut self) { + while !self.queue.is_empty() { + if self.cancel.is_cancelled() { + return; + } + + let batch = self + .queue + .take_batch(DEFAULT_BATCH_DOCUMENTS, DEFAULT_BATCH_BYTES); + if batch.is_empty() { + break; + } + + let count = batch.len() as u64; + let delivery = deliver(self.sink.as_ref(), batch, self.retry, |delay| { + Box::pin(tokio::time::sleep(delay)) + }); + + let report = tokio::select! { + biased; + () = self.cancel.cancelled() => { + tracing::debug!( + "log forwarding: revoked mid-delivery; abandoning {count} document(s)" + ); + return; + } + report = delivery => report, + }; + + self.stats.events_forwarded += report.delivered; + + if report.is_complete_success() { + self.stats.batches_sent += 1; + self.stats.last_success_unix = Some(now_unix_secs()); + self.stats.last_error = None; + } else { + self.stats.batches_failed += 1; + self.stats.last_error = report.error.clone(); + tracing::debug!( + "log forwarding: {} of {count} documents did not reach {}: {}", + report.rejected + report.abandoned, + self.sink.describe(), + report.error.as_deref().unwrap_or("no detail"), + ); + } + } + } +} + +/// Split the registry into nodes that can be forwarded and nodes that cannot. +/// +/// Node file logging is off unless the user asked for it, so "cannot" is the common case on a +/// default install. Reporting it is what stops `enable` looking like it worked while shipping +/// nothing at all. +pub fn classify_nodes(registry: &NodeRegistry) -> (Vec, Vec) { + let mut forwarding = Vec::new(); + let mut skipped = Vec::new(); + + let mut nodes = registry.list(); + nodes.sort_by_key(|node| node.id); + + for node in nodes { + match &node.log_dir { + Some(log_dir) => forwarding.push(ForwardingNode { + node_id: node.id, + service: node.service_name.clone(), + log_dir: log_dir.display().to_string(), + }), + None => skipped.push(SkippedNode::no_logging(node.id, node.service_name.clone())), + } + } + + (forwarding, skipped) +} + +fn now_unix_secs() -> u64 { + std::time::SystemTime::now() + .duration_since(std::time::UNIX_EPOCH) + .map(|d| d.as_secs()) + .unwrap_or(0) +} + +#[cfg(test)] +mod tests { + use super::*; + use crate::node::daemon::forward::sink::mock::MockSink; + use crate::node::types::{EvmNetwork, NodeConfig, UpgradeChannel}; + use std::collections::HashMap as StdHashMap; + use std::io::Write; + + struct Harness { + _dir: tempfile::TempDir, + root: PathBuf, + registry: Arc>, + } + + impl Harness { + /// One entry per node, in registry order: `true` means the node has logging enabled. + /// + /// Ids are not passed in because `NodeRegistry::add` assigns its own, starting at 1 — so + /// the nth entry here is node `n + 1`. + async fn new(nodes: &[bool]) -> Self { + let dir = tempfile::tempdir().unwrap(); + let root = dir.path().to_path_buf(); + let mut registry = NodeRegistry::load(&root.join("node_registry.json")).unwrap(); + + for (index, with_logging) in nodes.iter().enumerate() { + let id = index as u32 + 1; + let log_dir = with_logging.then(|| root.join(format!("logs-{id}"))); + if let Some(ref path) = log_dir { + std::fs::create_dir_all(path).unwrap(); + } + registry.add(NodeConfig { + id, + service_name: format!("node{id}"), + rewards_address: "0xabc".to_string(), + data_dir: root.join(format!("data-{id}")), + log_dir, + node_port: None, + binary_path: root.join("antnode"), + version: "0.17.2-beta.1".to_string(), + env_variables: StdHashMap::new(), + bootstrap_peers: Vec::new(), + upgrade_channel: Some(UpgradeChannel::Beta), + evm_network: EvmNetwork::default(), + eviction: None, + }); + } + + Self { + _dir: dir, + root, + registry: Arc::new(RwLock::new(registry)), + } + } + + fn append(&self, node_id: u32, contents: &str) { + let path = self + .root + .join(format!("logs-{node_id}")) + .join("ant-node.2026-08-19.log"); + let mut file = std::fs::OpenOptions::new() + .create(true) + .append(true) + .open(path) + .unwrap(); + file.write_all(contents.as_bytes()).unwrap(); + } + + fn config(&self) -> LogForwardConfig { + LogForwardConfig { + enabled: true, + token: "test-key".to_string(), + ..LogForwardConfig::disabled() + } + } + + fn offsets_path(&self) -> PathBuf { + self.root.join("offsets.json") + } + } + + fn line(level: &str, message: &str) -> String { + format!("2026-08-19T20:50:00.123456Z {level} ant_node::node: {message}\n") + } + + /// Drive the forwarder for long enough to observe several poll cycles. + async fn run_briefly(handle: &ForwarderHandle) { + tokio::time::sleep(Duration::from_millis(220)).await; + handle.stop(); + tokio::time::sleep(Duration::from_millis(60)).await; + } + + #[tokio::test] + async fn forwards_a_nodes_log_lines_to_the_sink() { + let harness = Harness::new(&[true]).await; + let sink = Arc::new(MockSink::accepting()); + + let handle = spawn_log_forwarder( + harness.registry.clone(), + harness.config(), + sink.clone(), + harness.offsets_path(), + Duration::from_millis(30), + CancellationToken::new(), + ); + + // Written after the forwarder has joined the file at its end. + tokio::time::sleep(Duration::from_millis(60)).await; + harness.append(1, &line("INFO", "hello from node one")); + run_briefly(&handle).await; + + let ids = sink.submitted_ids(); + assert!(!ids.is_empty(), "nothing was forwarded"); + assert!(handle.snapshot().await.stats.events_forwarded >= 1); + } + + /// A node with no log directory must not stop the forwarder doing its job for the others. + #[tokio::test] + async fn a_node_without_a_log_directory_does_not_disturb_the_rest() { + let harness = Harness::new(&[true, false]).await; + let sink = Arc::new(MockSink::accepting()); + + let handle = spawn_log_forwarder( + harness.registry.clone(), + harness.config(), + sink.clone(), + harness.offsets_path(), + Duration::from_millis(30), + CancellationToken::new(), + ); + + tokio::time::sleep(Duration::from_millis(60)).await; + harness.append(1, &line("INFO", "from the node that does log")); + run_briefly(&handle).await; + + assert!(!sink.submitted_ids().is_empty()); + assert!(handle.snapshot().await.stats.events_forwarded >= 1); + } + + #[tokio::test] + async fn stopping_the_handle_ends_forwarding() { + let harness = Harness::new(&[true]).await; + let sink = Arc::new(MockSink::accepting()); + + let handle = spawn_log_forwarder( + harness.registry.clone(), + harness.config(), + sink.clone(), + harness.offsets_path(), + Duration::from_millis(30), + CancellationToken::new(), + ); + + tokio::time::sleep(Duration::from_millis(60)).await; + handle.stop(); + assert!(handle.is_stopped()); + tokio::time::sleep(Duration::from_millis(60)).await; + + let batches_after_stop = sink.batch_count(); + harness.append(1, &line("INFO", "written after disable")); + tokio::time::sleep(Duration::from_millis(120)).await; + + assert_eq!( + sink.batch_count(), + batches_after_stop, + "disable must stop the flow entirely" + ); + } + + /// `disable` must be a revocation boundary, not a request: once `stop_and_wait` returns, no + /// request may still be in flight. + /// + /// The sink here hangs mid-send, standing in for a slow endpoint. Before cancellation reached + /// the delivery loop, `disable` returned immediately and that send carried on through the whole + /// retry ladder — up to three 30s request timeouts plus backoff — while the CLI had already + /// told the user forwarding had stopped. + #[tokio::test] + async fn stopping_returns_only_once_delivery_has_actually_stopped() { + let harness = Harness::new(&[true]).await; + let release = Arc::new(tokio::sync::Notify::new()); + let sink = Arc::new(MockSink::blocking(release.clone())); + + let handle = spawn_log_forwarder( + harness.registry.clone(), + harness.config(), + sink.clone(), + harness.offsets_path(), + Duration::from_millis(30), + CancellationToken::new(), + ); + + tokio::time::sleep(Duration::from_millis(60)).await; + harness.append(1, &line("INFO", "caught mid-flight")); + + // Wait until a send is genuinely in flight and stuck. + let mut waited = 0; + while sink.batch_count() == 0 && waited < 60 { + tokio::time::sleep(Duration::from_millis(20)).await; + waited += 1; + } + assert_eq!(sink.batch_count(), 1, "a send should be in flight"); + assert_eq!(sink.completed_count(), 0, "and still blocked"); + + // The blocked send is never released; this must still return promptly. + let stopped = tokio::time::timeout(Duration::from_secs(5), handle.stop_and_wait()).await; + assert!( + stopped.is_ok(), + "stop_and_wait must not sit through the retry ladder" + ); + + assert_eq!( + sink.completed_count(), + 0, + "the in-flight request must have been dropped, not allowed to finish" + ); + + // And nothing new may be sent afterwards. + let batches_at_stop = sink.batch_count(); + harness.append(1, &line("INFO", "written after disable")); + tokio::time::sleep(Duration::from_millis(150)).await; + assert_eq!( + sink.batch_count(), + batches_at_stop, + "no request may start after disable has returned" + ); + } + + #[tokio::test] + async fn the_daemon_shutdown_token_also_stops_forwarding() { + let harness = Harness::new(&[true]).await; + let sink = Arc::new(MockSink::accepting()); + let shutdown = CancellationToken::new(); + + let handle = spawn_log_forwarder( + harness.registry.clone(), + harness.config(), + sink.clone(), + harness.offsets_path(), + Duration::from_millis(30), + shutdown.clone(), + ); + + tokio::time::sleep(Duration::from_millis(60)).await; + shutdown.cancel(); + tokio::time::sleep(Duration::from_millis(60)).await; + let batches = sink.batch_count(); + + harness.append(1, &line("INFO", "after shutdown")); + tokio::time::sleep(Duration::from_millis(120)).await; + + assert_eq!(sink.batch_count(), batches); + drop(handle); + } + + /// Offsets are written on the way out, so the next daemon resumes instead of replaying. + #[tokio::test] + async fn offsets_are_persisted_across_a_forwarder_restart() { + let harness = Harness::new(&[true]).await; + harness.append(1, &line("INFO", "before")); + + let sink = Arc::new(MockSink::accepting()); + let handle = spawn_log_forwarder( + harness.registry.clone(), + harness.config(), + sink.clone(), + harness.offsets_path(), + Duration::from_millis(30), + CancellationToken::new(), + ); + tokio::time::sleep(Duration::from_millis(60)).await; + harness.append(1, &line("INFO", "first run")); + run_briefly(&handle).await; + + let first_ids = sink.submitted_ids(); + assert!(harness.offsets_path().exists(), "offsets must be persisted"); + + // A second forwarder over the same offsets file must not resend what the first shipped. + let second_sink = Arc::new(MockSink::accepting()); + let second = spawn_log_forwarder( + harness.registry.clone(), + harness.config(), + second_sink.clone(), + harness.offsets_path(), + Duration::from_millis(30), + CancellationToken::new(), + ); + run_briefly(&second).await; + + let resent: Vec = second_sink + .submitted_ids() + .into_iter() + .filter(|id| first_ids.contains(id)) + .collect(); + assert!( + resent.is_empty(), + "the second run re-sent documents the first had already delivered: {resent:?}" + ); + } + + #[tokio::test] + async fn events_below_the_minimum_level_never_reach_the_sink() { + let harness = Harness::new(&[true]).await; + let sink = Arc::new(MockSink::accepting()); + + let handle = spawn_log_forwarder( + harness.registry.clone(), + harness.config(), + sink.clone(), + harness.offsets_path(), + Duration::from_millis(30), + CancellationToken::new(), + ); + + tokio::time::sleep(Duration::from_millis(60)).await; + harness.append(1, &line("DEBUG", "chatter")); + harness.append(1, &line("TRACE", "more chatter")); + run_briefly(&handle).await; + + assert!(sink.submitted_ids().is_empty()); + assert!(handle.snapshot().await.stats.events_dropped_by_level >= 2); + } + + #[tokio::test] + async fn classify_nodes_orders_by_id_and_separates_by_logging() { + // Nodes 1 and 3 have logging; node 2 does not. + let harness = Harness::new(&[true, false, true]).await; + let registry = harness.registry.read().await; + let (forwarding, skipped) = classify_nodes(®istry); + + assert_eq!( + forwarding.iter().map(|n| n.node_id).collect::>(), + vec![1, 3], + "forwarding nodes are listed in id order" + ); + assert_eq!( + skipped.iter().map(|n| n.node_id).collect::>(), + vec![2] + ); + } +} diff --git a/ant-core/src/node/daemon/forward/sink.rs b/ant-core/src/node/daemon/forward/sink.rs new file mode 100644 index 00000000..b2442b4f --- /dev/null +++ b/ant-core/src/node/daemon/forward/sink.rs @@ -0,0 +1,601 @@ +//! Where documents go, and how hard the forwarder tries to get them there. +//! +//! This is logs-only telemetry, so the governing rule is that nothing here may grow without bound +//! or block waiting for an endpoint that is not answering. A user's node keeps running whatever the +//! ingest endpoint is doing; at worst they lose some log lines, which is a cost they can afford and +//! a stalled or memory-hungry daemon is not. +//! +//! Delivery is per-document rather than per-request. A bulk endpoint can accept most of a batch and +//! reject part of it, so a batch is retried by *position* — only the documents that asked to be +//! retried, never the whole thing. Whole-request replay is reserved for a transport failure, where +//! nothing is known about what landed, and is safe there only because every document carries a +//! deterministic `_id`. + +use std::collections::VecDeque; +use std::time::Duration; + +use futures::future::BoxFuture; + +use super::document::ForwardDocument; + +/// Maximum documents held in memory awaiting delivery. +/// +/// At roughly a kilobyte per event this is a few megabytes — enough to ride out a short endpoint +/// outage, small enough that a long one costs the user nothing they would notice. +pub const DEFAULT_QUEUE_CAPACITY: usize = 10_000; + +/// Maximum documents in one bulk request. +pub const DEFAULT_BATCH_DOCUMENTS: usize = 500; + +/// Soft cap on a batch's serialized size. The endpoint's proxy rejects bodies over 50 MB and +/// Elasticsearch itself over 100 MB; a few megabytes stays far away from both. +pub const DEFAULT_BATCH_BYTES: usize = 4 * 1024 * 1024; + +/// What happened to one submitted document. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub enum DocumentOutcome { + /// Indexed, or already present from an earlier attempt — either way, done with. + Delivered, + /// Worth another attempt: the endpoint was busy or briefly unavailable. + Retryable, + /// Rejected in a way that retrying cannot fix, e.g. a permissions or mapping error. + Rejected, +} + +/// Result of submitting one batch. +#[derive(Debug, Clone, Default, PartialEq, Eq)] +pub struct BatchOutcome { + /// Per-position outcomes, aligned with the submitted slice. Empty when the request itself + /// failed and nothing can be said about individual documents. + pub outcomes: Vec, + /// Set when the request did not complete at all — connection refused, timed out, TLS failure. + /// The whole batch may then be replayed, which the deterministic `_id`s make safe. + pub transport_failure: bool, + /// Human-readable description of the most relevant failure, for `status` output. + pub error: Option, +} + +impl BatchOutcome { + /// Every document accepted. + #[must_use] + pub fn all_delivered(count: usize) -> Self { + Self { + outcomes: vec![DocumentOutcome::Delivered; count], + transport_failure: false, + error: None, + } + } + + /// The request never completed. + #[must_use] + pub fn transport_failure(error: impl Into) -> Self { + Self { + outcomes: Vec::new(), + transport_failure: true, + error: Some(error.into()), + } + } +} + +/// Somewhere documents can be sent. +/// +/// Boxed futures rather than `async fn` so the forwarder can hold a `dyn LogSink` and swap a mock +/// in under test without being generic over the sink everywhere. +pub trait LogSink: Send + Sync + 'static { + fn send<'a>(&'a self, batch: &'a [ForwardDocument]) -> BoxFuture<'a, BatchOutcome>; + + /// Short description of the destination, for status output and logs. + fn describe(&self) -> String; +} + +/// A bounded in-memory queue of documents awaiting delivery. +/// +/// When it fills, the **oldest** documents are dropped. Dropping the newest would be easier but +/// wrong: during an outage the recent events are the ones describing what is going wrong, and they +/// are what a beta debugger needs. +#[derive(Debug)] +pub struct DocumentQueue { + documents: VecDeque, + capacity: usize, + dropped: u64, +} + +impl DocumentQueue { + #[must_use] + pub fn new(capacity: usize) -> Self { + Self { + documents: VecDeque::new(), + capacity: capacity.max(1), + dropped: 0, + } + } + + /// Add a document, evicting the oldest if the queue is full. + pub fn push(&mut self, document: ForwardDocument) { + if self.documents.len() >= self.capacity { + self.documents.pop_front(); + self.dropped += 1; + } + self.documents.push_back(document); + } + + /// Take the next batch, bounded by both document count and approximate size. + pub fn take_batch(&mut self, max_documents: usize, max_bytes: usize) -> Vec { + let mut batch = Vec::new(); + let mut bytes = 0; + + while batch.len() < max_documents { + let Some(next) = self.documents.front() else { + break; + }; + let next_bytes = next.approx_bytes(); + // Always take at least one, so a single oversized document cannot wedge the queue. + if !batch.is_empty() && bytes + next_bytes > max_bytes { + break; + } + bytes += next_bytes; + batch.push(self.documents.pop_front().expect("front was just observed")); + } + + batch + } + + #[must_use] + pub fn len(&self) -> usize { + self.documents.len() + } + + #[must_use] + pub fn is_empty(&self) -> bool { + self.documents.is_empty() + } + + /// Documents discarded because the queue was full. + #[must_use] + pub fn dropped(&self) -> u64 { + self.dropped + } +} + +/// How persistently a batch is retried before it is abandoned. +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub struct RetryPolicy { + pub max_attempts: u32, + pub initial_backoff: Duration, + pub max_backoff: Duration, +} + +impl Default for RetryPolicy { + fn default() -> Self { + Self { + max_attempts: 3, + initial_backoff: Duration::from_secs(2), + max_backoff: Duration::from_secs(30), + } + } +} + +impl RetryPolicy { + /// Backoff before the given attempt number, doubling and then holding at the cap. + #[must_use] + pub fn backoff_for(&self, attempt: u32) -> Duration { + let exponent = attempt.saturating_sub(1).min(16); + let scaled = self + .initial_backoff + .saturating_mul(2u32.saturating_pow(exponent)); + scaled.min(self.max_backoff) + } +} + +/// What became of one delivery attempt, including its retries. +#[derive(Debug, Clone, Default, PartialEq, Eq)] +pub struct DeliveryReport { + pub delivered: u64, + /// Documents the endpoint refused in a way retrying cannot fix. + pub rejected: u64, + /// Documents abandoned with retries exhausted. + pub abandoned: u64, + pub attempts: u32, + pub error: Option, +} + +impl DeliveryReport { + /// Whether every document in the batch was accounted for without loss. + #[must_use] + pub fn is_complete_success(&self) -> bool { + self.rejected == 0 && self.abandoned == 0 + } +} + +/// Deliver a batch, retrying only the positions that asked for it. +/// +/// `sleep` is injected so tests exercise the retry ladder without waiting real seconds. +pub async fn deliver( + sink: &S, + mut batch: Vec, + policy: RetryPolicy, + mut sleep: F, +) -> DeliveryReport +where + S: LogSink + ?Sized, + F: FnMut(Duration) -> BoxFuture<'static, ()>, +{ + let mut report = DeliveryReport::default(); + + for attempt in 1..=policy.max_attempts { + report.attempts = attempt; + let outcome = sink.send(&batch).await; + + if outcome.transport_failure { + report.error = outcome.error; + if attempt < policy.max_attempts { + sleep(policy.backoff_for(attempt)).await; + continue; + } + // Nothing is known about what landed. The batch is abandoned rather than replayed + // forever; a later attempt at the same documents would be idempotent, but holding them + // indefinitely is what unbounded memory looks like. + report.abandoned += batch.len() as u64; + return report; + } + + if outcome.error.is_some() { + report.error = outcome.error.clone(); + } + + let mut retry = Vec::new(); + for (index, document) in batch.into_iter().enumerate() { + match outcome.outcomes.get(index) { + Some(DocumentOutcome::Delivered) => report.delivered += 1, + Some(DocumentOutcome::Rejected) => report.rejected += 1, + Some(DocumentOutcome::Retryable) => retry.push(document), + // A response shorter than the batch: treat the unexplained tail as retryable rather + // than assume it landed. + None => retry.push(document), + } + } + + if retry.is_empty() { + return report; + } + + batch = retry; + if attempt < policy.max_attempts { + sleep(policy.backoff_for(attempt)).await; + } + } + + report.abandoned += batch.len() as u64; + report +} + +/// A sink that records what it was given, for tests. +#[cfg(test)] +pub mod mock { + use super::*; + use std::sync::{Arc, Mutex}; + + /// Records every batch and replies from a script of prepared outcomes. + pub struct MockSink { + pub batches: Mutex>>, + responses: Mutex>, + /// When set, `send` records the batch and then blocks until the notifier fires, standing in + /// for a request that is in flight when forwarding is revoked. + block_until: Option>, + /// Batches whose `send` actually returned, as opposed to being dropped mid-flight. + pub completed: Mutex, + } + + impl MockSink { + /// A sink that accepts everything. + #[must_use] + pub fn accepting() -> Self { + Self { + batches: Mutex::new(Vec::new()), + responses: Mutex::new(VecDeque::new()), + block_until: None, + completed: Mutex::new(0), + } + } + + /// A sink that replies with each prepared outcome in turn, accepting everything after. + #[must_use] + pub fn scripted(responses: Vec) -> Self { + Self { + batches: Mutex::new(Vec::new()), + responses: Mutex::new(responses.into()), + block_until: None, + completed: Mutex::new(0), + } + } + + /// A sink whose sends hang until `release` is notified. + #[must_use] + pub fn blocking(release: Arc) -> Self { + Self { + batches: Mutex::new(Vec::new()), + responses: Mutex::new(VecDeque::new()), + block_until: Some(release), + completed: Mutex::new(0), + } + } + + /// How many sends ran to completion rather than being dropped mid-flight. + #[must_use] + pub fn completed_count(&self) -> usize { + *self.completed.lock().unwrap() + } + + /// Ids of every document submitted, in submission order, across all batches. + #[must_use] + pub fn submitted_ids(&self) -> Vec { + self.batches + .lock() + .unwrap() + .iter() + .flat_map(|batch| batch.iter().map(|d| d.id.clone())) + .collect() + } + + #[must_use] + pub fn batch_count(&self) -> usize { + self.batches.lock().unwrap().len() + } + } + + impl LogSink for MockSink { + fn send<'a>(&'a self, batch: &'a [ForwardDocument]) -> BoxFuture<'a, BatchOutcome> { + Box::pin(async move { + self.batches.lock().unwrap().push(batch.to_vec()); + + if let Some(release) = &self.block_until { + // Dropping this future here is what a cancelled delivery looks like: the + // completion counter below is never reached. + release.notified().await; + } + + *self.completed.lock().unwrap() += 1; + self.responses + .lock() + .unwrap() + .pop_front() + .unwrap_or_else(|| BatchOutcome::all_delivered(batch.len())) + }) + } + + fn describe(&self) -> String { + "mock".to_string() + } + } +} + +#[cfg(test)] +mod tests { + use super::mock::MockSink; + use super::*; + use crate::node::daemon::forward::document::DocumentSource; + + fn document(id: &str) -> ForwardDocument { + ForwardDocument { + id: id.to_string(), + index: "beta-nodes-2026.08.19".to_string(), + source: DocumentSource { + timestamp: "2026-08-19T20:50:00.000000Z".to_string(), + level: "INFO".to_string(), + target: None, + message: "m".to_string(), + node_id: "7".to_string(), + service: "node7".to_string(), + binary_version: "0.17.2".to_string(), + channel: "beta".to_string(), + os: "linux".to_string(), + arch: "x86_64".to_string(), + peer_id: None, + version: None, + commit: None, + }, + } + } + + fn documents(count: usize) -> Vec { + (0..count).map(|i| document(&format!("doc-{i}"))).collect() + } + + /// Sleep that returns instantly, recording nothing — the retry ladder is exercised, not waited on. + fn no_sleep() -> impl FnMut(Duration) -> BoxFuture<'static, ()> { + |_| Box::pin(async {}) + } + + #[test] + fn a_full_queue_drops_the_oldest_not_the_newest() { + let mut queue = DocumentQueue::new(3); + for i in 0..5 { + queue.push(document(&format!("doc-{i}"))); + } + + assert_eq!(queue.len(), 3); + assert_eq!(queue.dropped(), 2); + + let batch = queue.take_batch(10, usize::MAX); + let ids: Vec<&str> = batch.iter().map(|d| d.id.as_str()).collect(); + assert_eq!( + ids, + vec!["doc-2", "doc-3", "doc-4"], + "the recent events are the ones worth keeping" + ); + } + + #[test] + fn a_batch_is_bounded_by_document_count() { + let mut queue = DocumentQueue::new(100); + for doc in documents(10) { + queue.push(doc); + } + + assert_eq!(queue.take_batch(4, usize::MAX).len(), 4); + assert_eq!(queue.len(), 6); + } + + #[test] + fn a_batch_is_bounded_by_approximate_size() { + let mut queue = DocumentQueue::new(100); + for doc in documents(10) { + queue.push(doc); + } + + let one = document("sizing").approx_bytes(); + let batch = queue.take_batch(100, one * 3); + assert_eq!(batch.len(), 3); + } + + /// A single document larger than the whole size budget must still get out. + #[test] + fn an_oversized_document_cannot_wedge_the_queue() { + let mut queue = DocumentQueue::new(10); + queue.push(document("huge")); + + let batch = queue.take_batch(100, 1); + assert_eq!(batch.len(), 1); + assert!(queue.is_empty()); + } + + #[tokio::test] + async fn a_clean_batch_is_delivered_in_one_attempt() { + let sink = MockSink::accepting(); + let report = deliver(&sink, documents(3), RetryPolicy::default(), no_sleep()).await; + + assert_eq!(report.delivered, 3); + assert_eq!(report.attempts, 1); + assert!(report.is_complete_success()); + assert_eq!(sink.batch_count(), 1); + } + + /// The behaviour the ingest contract specifically warned about: a 200 response can still carry + /// per-document failures, and only the failing positions may be resent. + #[tokio::test] + async fn only_the_retryable_positions_are_resent() { + let sink = MockSink::scripted(vec![BatchOutcome { + outcomes: vec![ + DocumentOutcome::Delivered, + DocumentOutcome::Retryable, + DocumentOutcome::Delivered, + DocumentOutcome::Retryable, + ], + transport_failure: false, + error: None, + }]); + + let report = deliver(&sink, documents(4), RetryPolicy::default(), no_sleep()).await; + + assert_eq!(report.delivered, 4, "2 first time, 2 on the retry"); + assert_eq!(report.attempts, 2); + + let batches = sink.batches.lock().unwrap(); + assert_eq!(batches[0].len(), 4); + assert_eq!(batches[1].len(), 2, "only the failures are resent"); + let resent: Vec<&str> = batches[1].iter().map(|d| d.id.as_str()).collect(); + assert_eq!(resent, vec!["doc-1", "doc-3"]); + } + + #[tokio::test] + async fn a_permanently_rejected_document_is_not_retried() { + let sink = MockSink::scripted(vec![BatchOutcome { + outcomes: vec![DocumentOutcome::Rejected, DocumentOutcome::Delivered], + transport_failure: false, + error: Some("403 forbidden".to_string()), + }]); + + let report = deliver(&sink, documents(2), RetryPolicy::default(), no_sleep()).await; + + assert_eq!(report.rejected, 1); + assert_eq!(report.delivered, 1); + assert_eq!(report.attempts, 1, "no point trying again"); + assert!(!report.is_complete_success()); + assert_eq!(report.error.as_deref(), Some("403 forbidden")); + } + + #[tokio::test] + async fn retries_are_abandoned_once_the_policy_is_exhausted() { + let always_busy = BatchOutcome { + outcomes: vec![DocumentOutcome::Retryable, DocumentOutcome::Retryable], + transport_failure: false, + error: Some("429 too many requests".to_string()), + }; + let sink = MockSink::scripted(vec![always_busy.clone(), always_busy.clone(), always_busy]); + + let policy = RetryPolicy { + max_attempts: 3, + ..RetryPolicy::default() + }; + let report = deliver(&sink, documents(2), policy, no_sleep()).await; + + assert_eq!(report.attempts, 3); + assert_eq!(report.abandoned, 2); + assert_eq!(report.delivered, 0); + assert_eq!(sink.batch_count(), 3); + } + + /// The whole batch may be replayed after a transport failure precisely because every document + /// carries a stable `_id`, so the second attempt cannot duplicate the first. + #[tokio::test] + async fn a_transport_failure_replays_the_whole_batch_with_identical_ids() { + let sink = MockSink::scripted(vec![BatchOutcome::transport_failure("connection reset")]); + + let report = deliver(&sink, documents(3), RetryPolicy::default(), no_sleep()).await; + + assert_eq!(report.delivered, 3); + assert_eq!(report.attempts, 2); + + let batches = sink.batches.lock().unwrap(); + let first: Vec<&str> = batches[0].iter().map(|d| d.id.as_str()).collect(); + let second: Vec<&str> = batches[1].iter().map(|d| d.id.as_str()).collect(); + assert_eq!(first, second, "a replay must reuse the same document ids"); + } + + #[tokio::test] + async fn a_batch_is_abandoned_when_transport_failures_persist() { + let sink = MockSink::scripted(vec![ + BatchOutcome::transport_failure("refused"), + BatchOutcome::transport_failure("refused"), + BatchOutcome::transport_failure("refused"), + ]); + + let report = deliver(&sink, documents(2), RetryPolicy::default(), no_sleep()).await; + + assert_eq!(report.abandoned, 2); + assert_eq!(report.delivered, 0); + assert_eq!(report.error.as_deref(), Some("refused")); + } + + /// A response with fewer entries than the batch says nothing about the tail; assuming success + /// there would silently lose documents. + #[tokio::test] + async fn an_unexplained_tail_is_retried_rather_than_assumed_delivered() { + let sink = MockSink::scripted(vec![BatchOutcome { + outcomes: vec![DocumentOutcome::Delivered], + transport_failure: false, + error: None, + }]); + + let report = deliver(&sink, documents(3), RetryPolicy::default(), no_sleep()).await; + + assert_eq!(report.delivered, 3); + let batches = sink.batches.lock().unwrap(); + assert_eq!(batches[1].len(), 2); + } + + #[test] + fn backoff_doubles_then_holds_at_the_ceiling() { + let policy = RetryPolicy { + max_attempts: 10, + initial_backoff: Duration::from_secs(2), + max_backoff: Duration::from_secs(10), + }; + + assert_eq!(policy.backoff_for(1), Duration::from_secs(2)); + assert_eq!(policy.backoff_for(2), Duration::from_secs(4)); + assert_eq!(policy.backoff_for(3), Duration::from_secs(8)); + assert_eq!(policy.backoff_for(4), Duration::from_secs(10)); + assert_eq!(policy.backoff_for(9), Duration::from_secs(10)); + } +} diff --git a/ant-core/src/node/daemon/forward/tail.rs b/ant-core/src/node/daemon/forward/tail.rs new file mode 100644 index 00000000..0038de79 --- /dev/null +++ b/ant-core/src/node/daemon/forward/tail.rs @@ -0,0 +1,777 @@ +//! Following a node's log files as they are written and rotated. +//! +//! ant-node rotates **daily by filename** (`ant-node.YYYY-MM-DD.log`) and prunes to +//! `--log-max-files`, so "rotation" here is a new file appearing beside the old one rather than a +//! cursor moving — which makes the tailer's job mostly bookkeeping over a sorted file list. +//! +//! Two behaviours are worth knowing about before reading the code: +//! +//! - **A partially written line is never emitted.** Only bytes up to the last newline in a chunk +//! are consumed, so an event that is still being written is picked up whole on the next poll. +//! - **A multi-line event is not split across polls.** The last event of a chunk is held back and +//! the stored offset stays at its first byte, so its continuation lines — a panic and its +//! backtrace, most importantly — join it rather than becoming orphans. It is released once the +//! file stops growing. + +use std::collections::HashMap; +use std::path::{Path, PathBuf}; + +use tokio::io::{AsyncReadExt, AsyncSeekExt}; + +use super::config::LogLevel; +use super::offsets::OffsetStore; +use super::parse::{parse_line, LogEvent}; +use crate::error::Result; + +/// Filename prefix ant-node's rolling appender uses. +const LOG_FILENAME_PREFIX: &str = "ant-node."; +/// Filename suffix ant-node's rolling appender uses. +const LOG_FILENAME_SUFFIX: &str = ".log"; + +/// Most bytes read from one file in one poll, bounding the forwarder's memory when it is catching +/// up on a node that logged heavily while the daemon was down. +const MAX_CHUNK_BYTES: usize = 1024 * 1024; + +/// An event together with where it came from — everything the sink needs to build a stable `_id`. +#[derive(Debug, Clone, PartialEq, Eq)] +pub struct TailedEvent { + pub node_id: u32, + /// Bare log filename, e.g. `ant-node.2026-08-19.log`. + pub file_name: String, + /// Byte position of the event's first line within that file. + pub byte_offset: u64, + pub event: LogEvent, +} + +impl TailedEvent { + /// The document `_id` this event will be written under. + /// + /// Deterministic in the four things that identify the event uniquely — which installation, + /// which node, which file, which byte — so that replaying a batch after a transport failure + /// lands on the same `_id` and is rejected as a duplicate instead of writing a second copy. + /// + /// `installation_id` is not optional padding. Node id, filename and byte offset are all local + /// values: every participant has a node `1`, writing the same daily filename, whose first line + /// starts at offset 0. Since all of them write into one shared daily index and a 409 counts as + /// delivered, omitting the installation namespace would make the first event of each day from + /// each node collide across the whole cohort, and every loser would be silently discarded. + #[must_use] + pub fn document_id(&self, installation_id: &str) -> String { + format!( + "{}-{}-{}-{}", + installation_id, self.node_id, self.file_name, self.byte_offset + ) + } +} + +/// Follows one node's log directory. +pub struct LogTailer { + node_id: u32, + log_dir: PathBuf, + /// False until the first poll has run. On that first poll, files already on disk are joined at + /// their end: enabling forwarding is a forward-looking consent, not a request to upload up to a + /// week of retained history. + primed: bool, + /// Length each file had at the previous poll, used to tell "still being written" from + /// "finished", so a held-back multi-line event is released once the file goes quiet. + last_seen_len: HashMap, +} + +impl LogTailer { + #[must_use] + pub fn new(node_id: u32, log_dir: PathBuf) -> Self { + Self { + node_id, + log_dir, + primed: false, + last_seen_len: HashMap::new(), + } + } + + #[must_use] + pub fn node_id(&self) -> u32 { + self.node_id + } + + #[must_use] + pub fn log_dir(&self) -> &Path { + &self.log_dir + } + + /// Adopt existing offsets rather than joining at the end. + /// + /// Called when the persisted offsets already mention this node, i.e. the daemon is restarting + /// rather than the user enabling forwarding for the first time. + pub fn mark_primed(&mut self) { + self.primed = true; + } + + /// Read whatever has been appended since the last poll. + /// + /// Events below `min_level` are dropped here rather than downstream, so they never occupy queue + /// space: the endpoint discards them on arrival anyway, and shipping them would spend the + /// user's bandwidth for nothing. + pub async fn poll( + &mut self, + offsets: &mut OffsetStore, + min_level: LogLevel, + ) -> Result { + let files = self.discover_files().await?; + let mut outcome = PollOutcome::default(); + + for path in &files { + match self.poll_file(path, offsets, min_level).await { + Ok(mut file_outcome) => { + outcome.events.append(&mut file_outcome.events); + outcome.dropped_by_level += file_outcome.dropped_by_level; + } + // A file vanishing mid-poll is retention doing its job, not an error worth + // stopping the whole forwarder for. + Err(error) => { + tracing::debug!( + "log forwarding: skipping {} this poll: {error}", + path.display() + ); + } + } + } + + let live: Vec = files.iter().map(|p| p.display().to_string()).collect(); + offsets.prune(&live); + self.last_seen_len.retain(|key, _| live.contains(key)); + self.primed = true; + + Ok(outcome) + } + + /// List this node's log files, oldest first. + /// + /// The rolling appender's `ant-node.YYYY-MM-DD.log` names sort chronologically under a plain + /// lexicographic sort, so no date parsing is needed to get the order right. + async fn discover_files(&self) -> Result> { + let mut entries = match tokio::fs::read_dir(&self.log_dir).await { + Ok(entries) => entries, + // The directory not existing yet is normal: it is created when the node first starts. + Err(error) if error.kind() == std::io::ErrorKind::NotFound => return Ok(Vec::new()), + Err(error) => return Err(error.into()), + }; + + let mut files = Vec::new(); + while let Some(entry) = entries.next_entry().await? { + let name = entry.file_name().to_string_lossy().to_string(); + if name.starts_with(LOG_FILENAME_PREFIX) && name.ends_with(LOG_FILENAME_SUFFIX) { + files.push(entry.path()); + } + } + files.sort(); + Ok(files) + } + + async fn poll_file( + &mut self, + path: &Path, + offsets: &mut OffsetStore, + min_level: LogLevel, + ) -> Result { + let key = path.display().to_string(); + let file_name = path + .file_name() + .map(|n| n.to_string_lossy().to_string()) + .unwrap_or_else(|| key.clone()); + + let mut file = tokio::fs::File::open(path).await?; + let len = file.metadata().await?.len(); + + let mut start = match offsets.get(&key) { + Some(offset) => offset, + // A file we have never read: join at the end on the very first poll after enabling, + // otherwise (a new day's file, or a node added later) read it from the beginning. + None if !self.primed => len, + None => 0, + }; + + // The file shrank, so it was truncated or replaced under us. Anything we thought we had + // read is gone; the only safe cursor is the beginning. + if len < start { + tracing::debug!("log forwarding: {key} shrank; restarting from the beginning"); + start = 0; + } + + let was_growing = self.last_seen_len.insert(key.clone(), len) != Some(len); + + if len == start { + offsets.set(&key, start); + return Ok(PollOutcome::default()); + } + + let to_read = usize::try_from(len - start) + .unwrap_or(MAX_CHUNK_BYTES) + .min(MAX_CHUNK_BYTES); + file.seek(std::io::SeekFrom::Start(start)).await?; + let mut buffer = vec![0u8; to_read]; + let read = file.read_exact(&mut buffer).await.map(|_| to_read)?; + buffer.truncate(read); + + let reached_eof = start + read as u64 >= len; + + // Never emit a half-written line. If the chunk has no newline at all we are either mid-line + // or looking at a single line longer than the read cap; in the latter case, waiting forever + // would stall the file, so an over-long line is taken as-is. + let usable = match buffer.iter().rposition(|b| *b == b'\n') { + Some(index) => index + 1, + None if read == MAX_CHUNK_BYTES => read, + None => { + offsets.set(&key, start); + return Ok(PollOutcome::default()); + } + }; + + let text = String::from_utf8_lossy(&buffer[..usable]).to_string(); + let outcome = self.collect_events( + &text, + start, + &file_name, + min_level, + // Hold the final event back while the file is still growing, so its continuation lines + // can join it on the next poll. + reached_eof && !was_growing, + ); + + offsets.set(&key, outcome.next_offset); + Ok(outcome.into_poll_outcome()) + } + + /// Split a chunk into events, attaching continuation lines to the event above them. + fn collect_events( + &self, + text: &str, + chunk_start: u64, + file_name: &str, + min_level: LogLevel, + release_final_event: bool, + ) -> CollectOutcome { + let mut outcome = CollectOutcome { + next_offset: chunk_start, + ..CollectOutcome::default() + }; + let mut pending: Option = None; + let mut cursor = chunk_start; + + for line in text.split_inclusive('\n') { + let line_start = cursor; + cursor += line.len() as u64; + let content = line.trim_end_matches(['\n', '\r']); + + match parse_line(content) { + Some(event) => { + if let Some(previous) = pending.take() { + outcome.push(previous, min_level); + } + // Everything before this event has now been emitted, so the cursor may safely + // advance to its first byte — and no further, until it too is released. + outcome.next_offset = line_start; + pending = Some(TailedEvent { + node_id: self.node_id, + file_name: file_name.to_string(), + byte_offset: line_start, + event, + }); + } + None => match pending.as_mut() { + Some(held) => held.event.push_continuation(content), + // A continuation with nothing above it: the parent was emitted in an earlier + // poll, or the file began mid-event. Nothing useful to attach it to. + None => outcome.next_offset = cursor, + }, + } + } + + match pending { + Some(event) if release_final_event => { + outcome.push(event, min_level); + outcome.next_offset = cursor; + } + // Left pending: `next_offset` still points at its first byte, so the next poll re-reads + // it along with whatever continuation lines have since arrived. + Some(_) => {} + None => outcome.next_offset = cursor, + } + + outcome + } +} + +/// What one poll produced. +#[derive(Debug, Default)] +pub struct PollOutcome { + pub events: Vec, + /// Events discarded for being below the configured minimum level. + pub dropped_by_level: u64, +} + +#[derive(Debug, Default)] +struct CollectOutcome { + events: Vec, + dropped_by_level: u64, + next_offset: u64, +} + +impl CollectOutcome { + fn push(&mut self, event: TailedEvent, min_level: LogLevel) { + if event.event.level < min_level { + self.dropped_by_level += 1; + } else { + self.events.push(event); + } + } + + fn into_poll_outcome(self) -> PollOutcome { + PollOutcome { + events: self.events, + dropped_by_level: self.dropped_by_level, + } + } +} + +#[cfg(test)] +mod tests { + use super::*; + use std::io::Write; + + fn line(level: &str, message: &str) -> String { + format!("2026-08-19T20:50:00.123456Z {level} ant_node::node: {message}\n") + } + + struct Fixture { + _dir: tempfile::TempDir, + log_dir: PathBuf, + offsets_path: PathBuf, + } + + impl Fixture { + fn new() -> Self { + let dir = tempfile::tempdir().unwrap(); + let log_dir = dir.path().join("logs"); + std::fs::create_dir_all(&log_dir).unwrap(); + let offsets_path = dir.path().join("offsets.json"); + Self { + _dir: dir, + log_dir, + offsets_path, + } + } + + fn append(&self, file_name: &str, contents: &str) { + let mut file = std::fs::OpenOptions::new() + .create(true) + .append(true) + .open(self.log_dir.join(file_name)) + .unwrap(); + file.write_all(contents.as_bytes()).unwrap(); + } + + fn offsets(&self) -> OffsetStore { + OffsetStore::load(&self.offsets_path) + } + + fn tailer(&self) -> LogTailer { + LogTailer::new(7, self.log_dir.clone()) + } + } + + /// Poll until the file stops growing, merging what comes out. + /// + /// The tailer holds a growing file's final event back for one poll so that continuation lines + /// written just after it can join it, so observing an event that was only just appended takes + /// two polls. That is the intended trade — one poll interval of latency on the tail of a burst, + /// in exchange for panics arriving as one document instead of twenty. + async fn drain( + tailer: &mut LogTailer, + offsets: &mut OffsetStore, + min_level: LogLevel, + ) -> PollOutcome { + let mut merged = tailer.poll(offsets, min_level).await.unwrap(); + let mut second = tailer.poll(offsets, min_level).await.unwrap(); + merged.events.append(&mut second.events); + merged.dropped_by_level += second.dropped_by_level; + merged + } + + /// Enabling forwarding must not upload the retained backlog: the first poll joins at the end. + #[tokio::test] + async fn the_first_poll_joins_existing_files_at_their_end() { + let fixture = Fixture::new(); + fixture.append("ant-node.2026-08-19.log", &line("INFO", "historic")); + + let mut tailer = fixture.tailer(); + let mut offsets = fixture.offsets(); + let outcome = tailer.poll(&mut offsets, LogLevel::Info).await.unwrap(); + + assert!(outcome.events.is_empty(), "history must not be shipped"); + + fixture.append("ant-node.2026-08-19.log", &line("INFO", "fresh")); + let outcome = drain(&mut tailer, &mut offsets, LogLevel::Info).await; + assert_eq!(outcome.events.len(), 1); + assert_eq!(outcome.events[0].event.message, "fresh"); + } + + #[tokio::test] + async fn a_restart_resumes_from_the_persisted_offset_without_duplicating() { + let fixture = Fixture::new(); + fixture.append("ant-node.2026-08-19.log", &line("INFO", "first")); + + let mut tailer = fixture.tailer(); + let mut offsets = fixture.offsets(); + tailer.poll(&mut offsets, LogLevel::Info).await.unwrap(); + fixture.append("ant-node.2026-08-19.log", &line("INFO", "second")); + let before = drain(&mut tailer, &mut offsets, LogLevel::Info).await; + assert_eq!(before.events.len(), 1); + offsets.save().unwrap(); + + // A new daemon: fresh tailer, offsets reloaded from disk. + let mut restarted = fixture.tailer(); + restarted.mark_primed(); + let mut reloaded = fixture.offsets(); + + let outcome = drain(&mut restarted, &mut reloaded, LogLevel::Info).await; + assert!(outcome.events.is_empty(), "nothing new, nothing re-sent"); + + fixture.append("ant-node.2026-08-19.log", &line("INFO", "third")); + let outcome = drain(&mut restarted, &mut reloaded, LogLevel::Info).await; + assert_eq!(outcome.events.len(), 1); + assert_eq!(outcome.events[0].event.message, "third"); + } + + /// The gap half of "no duplication and no large gaps": lines written while the daemon was down + /// are still delivered, because the offset is behind them. + #[tokio::test] + async fn lines_written_while_the_daemon_was_down_are_not_lost() { + let fixture = Fixture::new(); + fixture.append("ant-node.2026-08-19.log", &line("INFO", "before")); + + let mut tailer = fixture.tailer(); + let mut offsets = fixture.offsets(); + tailer.poll(&mut offsets, LogLevel::Info).await.unwrap(); + offsets.save().unwrap(); + + fixture.append("ant-node.2026-08-19.log", &line("INFO", "during downtime")); + + let mut restarted = fixture.tailer(); + restarted.mark_primed(); + let mut reloaded = fixture.offsets(); + let outcome = drain(&mut restarted, &mut reloaded, LogLevel::Info).await; + + assert_eq!(outcome.events.len(), 1); + assert_eq!(outcome.events[0].event.message, "during downtime"); + } + + /// Enabling forwarding *before* the node starts captures its whole first log file, including + /// the startup line carrying version, commit and peer id. + /// + /// The end-join rule only applies to files that already existed when forwarding was switched + /// on. A node that has not run yet has no files, so nothing is joined at the end, and the file + /// it later creates is read from byte zero like any other new file. + #[tokio::test] + async fn a_node_started_after_enabling_is_captured_from_its_first_line() { + let fixture = Fixture::new(); + + // Forwarding is enabled while the node has never run: the log directory is empty. + let mut tailer = fixture.tailer(); + let mut offsets = fixture.offsets(); + let outcome = tailer.poll(&mut offsets, LogLevel::Info).await.unwrap(); + assert!(outcome.events.is_empty()); + + // The node now starts and writes its startup line. + fixture.append( + "ant-node.2026-08-19.log", + &format!( + "{}{}", + line("INFO", "starting version=0.17.2 commit=abc1234"), + line("INFO", "listening for connections"), + ), + ); + let outcome = drain(&mut tailer, &mut offsets, LogLevel::Info).await; + + let messages: Vec<&str> = outcome + .events + .iter() + .map(|e| e.event.message.as_str()) + .collect(); + assert_eq!( + messages, + vec![ + "starting version=0.17.2 commit=abc1234", + "listening for connections" + ], + "the node's first line must not be skipped" + ); + assert_eq!(outcome.events[0].byte_offset, 0); + assert_eq!(outcome.events[0].event.version.as_deref(), Some("0.17.2")); + assert_eq!(outcome.events[0].event.commit.as_deref(), Some("abc1234")); + } + + /// The converse: enabling *after* the node is already running skips whatever it logged before + /// consent — including its startup line, and so the version/commit fields that come with it. + #[tokio::test] + async fn enabling_after_the_node_started_skips_its_startup_line() { + let fixture = Fixture::new(); + fixture.append( + "ant-node.2026-08-19.log", + &line("INFO", "starting version=0.17.2 commit=abc1234"), + ); + + let mut tailer = fixture.tailer(); + let mut offsets = fixture.offsets(); + let outcome = drain(&mut tailer, &mut offsets, LogLevel::Info).await; + assert!( + outcome.events.is_empty(), + "pre-consent lines are not uploaded" + ); + + fixture.append("ant-node.2026-08-19.log", &line("INFO", "later activity")); + let outcome = drain(&mut tailer, &mut offsets, LogLevel::Info).await; + + let messages: Vec<&str> = outcome + .events + .iter() + .map(|e| e.event.message.as_str()) + .collect(); + assert_eq!(messages, vec!["later activity"]); + } + + #[tokio::test] + async fn a_new_days_file_is_read_from_the_beginning() { + let fixture = Fixture::new(); + fixture.append("ant-node.2026-08-19.log", &line("INFO", "yesterday")); + + let mut tailer = fixture.tailer(); + let mut offsets = fixture.offsets(); + tailer.poll(&mut offsets, LogLevel::Info).await.unwrap(); + + fixture.append("ant-node.2026-08-20.log", &line("INFO", "today")); + let outcome = drain(&mut tailer, &mut offsets, LogLevel::Info).await; + + assert_eq!(outcome.events.len(), 1); + assert_eq!(outcome.events[0].event.message, "today"); + assert_eq!(outcome.events[0].file_name, "ant-node.2026-08-20.log"); + } + + #[tokio::test] + async fn a_truncated_file_restarts_from_the_beginning() { + let fixture = Fixture::new(); + fixture.append("ant-node.2026-08-19.log", &line("INFO", "original content")); + + let mut tailer = fixture.tailer(); + let mut offsets = fixture.offsets(); + tailer.poll(&mut offsets, LogLevel::Info).await.unwrap(); + + std::fs::write( + fixture.log_dir.join("ant-node.2026-08-19.log"), + line("INFO", "new"), + ) + .unwrap(); + let outcome = drain(&mut tailer, &mut offsets, LogLevel::Info).await; + + assert_eq!(outcome.events.len(), 1); + assert_eq!(outcome.events[0].event.message, "new"); + } + + #[tokio::test] + async fn a_partially_written_line_is_held_until_it_is_complete() { + let fixture = Fixture::new(); + fixture.append("ant-node.2026-08-19.log", &line("INFO", "complete")); + + let mut tailer = fixture.tailer(); + let mut offsets = fixture.offsets(); + tailer.poll(&mut offsets, LogLevel::Info).await.unwrap(); + + fixture.append( + "ant-node.2026-08-19.log", + "2026-08-19T20:50:01.000000Z INFO ant_node::node: half a li", + ); + let outcome = tailer.poll(&mut offsets, LogLevel::Info).await.unwrap(); + assert!(outcome.events.is_empty(), "a partial line is not an event"); + + fixture.append("ant-node.2026-08-19.log", "ne here\n"); + // One poll observes the new length; the next releases the now-quiet final event. + tailer.poll(&mut offsets, LogLevel::Info).await.unwrap(); + let outcome = tailer.poll(&mut offsets, LogLevel::Info).await.unwrap(); + + assert_eq!(outcome.events.len(), 1); + assert_eq!(outcome.events[0].event.message, "half a line here"); + } + + #[tokio::test] + async fn a_panic_and_its_backtrace_stay_one_event() { + let fixture = Fixture::new(); + fixture.append("ant-node.2026-08-19.log", &line("INFO", "before the panic")); + + let mut tailer = fixture.tailer(); + let mut offsets = fixture.offsets(); + tailer.poll(&mut offsets, LogLevel::Info).await.unwrap(); + + fixture.append( + "ant-node.2026-08-19.log", + &format!( + "{}thread 'main' panicked\n at src/node.rs:42\n", + line("ERROR", "it broke") + ), + ); + tailer.poll(&mut offsets, LogLevel::Info).await.unwrap(); + let outcome = tailer.poll(&mut offsets, LogLevel::Info).await.unwrap(); + + assert_eq!(outcome.events.len(), 1); + assert_eq!( + outcome.events[0].event.message, + "it broke\nthread 'main' panicked\n at src/node.rs:42" + ); + } + + #[tokio::test] + async fn events_below_the_minimum_level_are_dropped_and_counted() { + let fixture = Fixture::new(); + fixture.append("ant-node.2026-08-19.log", &line("INFO", "seed")); + + let mut tailer = fixture.tailer(); + let mut offsets = fixture.offsets(); + tailer.poll(&mut offsets, LogLevel::Info).await.unwrap(); + + fixture.append( + "ant-node.2026-08-19.log", + &format!( + "{}{}{}", + line("DEBUG", "chatter"), + line("TRACE", "more chatter"), + line("WARN", "worth keeping") + ), + ); + let outcome = drain(&mut tailer, &mut offsets, LogLevel::Info).await; + + let messages: Vec<&str> = outcome + .events + .iter() + .map(|e| e.event.message.as_str()) + .collect(); + assert_eq!(messages, vec!["worth keeping"]); + assert_eq!(outcome.dropped_by_level, 2); + } + + #[tokio::test] + async fn a_missing_log_directory_is_not_an_error() { + let dir = tempfile::tempdir().unwrap(); + let mut tailer = LogTailer::new(1, dir.path().join("never-created")); + let mut offsets = OffsetStore::load(&dir.path().join("offsets.json")); + + let outcome = tailer.poll(&mut offsets, LogLevel::Info).await.unwrap(); + assert!(outcome.events.is_empty()); + } + + #[tokio::test] + async fn unrelated_files_in_the_log_directory_are_ignored() { + let fixture = Fixture::new(); + fixture.append("ant-node.2026-08-19.log", &line("INFO", "seed")); + fixture.append("notes.txt", "not a log file\n"); + fixture.append("ant-node.2026-08-19.log.gz", "compressed\n"); + + let mut tailer = fixture.tailer(); + let mut offsets = fixture.offsets(); + tailer.poll(&mut offsets, LogLevel::Info).await.unwrap(); + + assert_eq!(offsets.len(), 1, "only the rolling log file is tracked"); + } + + #[tokio::test] + async fn offsets_for_retention_deleted_files_are_pruned() { + let fixture = Fixture::new(); + fixture.append("ant-node.2026-08-18.log", &line("INFO", "old")); + fixture.append("ant-node.2026-08-19.log", &line("INFO", "current")); + + let mut tailer = fixture.tailer(); + let mut offsets = fixture.offsets(); + tailer.poll(&mut offsets, LogLevel::Info).await.unwrap(); + assert_eq!(offsets.len(), 2); + + std::fs::remove_file(fixture.log_dir.join("ant-node.2026-08-18.log")).unwrap(); + tailer.poll(&mut offsets, LogLevel::Info).await.unwrap(); + + assert_eq!(offsets.len(), 1); + } + + const INSTALL_A: &str = "0123456789abcdef"; + const INSTALL_B: &str = "fedcba9876543210"; + + #[test] + fn the_document_id_is_stable_and_position_derived() { + let event = TailedEvent { + node_id: 7, + file_name: "ant-node.2026-08-19.log".to_string(), + byte_offset: 104_857, + event: parse_line(&line("INFO", "hello")).unwrap(), + }; + + assert_eq!( + event.document_id(INSTALL_A), + "0123456789abcdef-7-ant-node.2026-08-19.log-104857" + ); + assert_eq!( + event.document_id(INSTALL_A), + event.clone().document_id(INSTALL_A) + ); + assert!( + event.document_id(INSTALL_A).len() <= 512, + "Elasticsearch caps _id at 512 bytes" + ); + } + + /// The collision this namespace exists to prevent. Two participants each run a node `1` whose + /// daily log file has the same name and whose first line is at offset 0; without the + /// installation prefix both produce the same `_id`, and because every participant writes into + /// one shared daily index and the sink counts a 409 as delivered, the second one's event would + /// be dropped on the floor rather than stored. + #[test] + fn identical_positions_on_two_installations_do_not_collide() { + let same_event = || TailedEvent { + node_id: 1, + file_name: "ant-node.2026-08-19.log".to_string(), + byte_offset: 0, + event: parse_line(&line("INFO", "starting version=0.17.2")).unwrap(), + }; + + assert_ne!( + same_event().document_id(INSTALL_A), + same_event().document_id(INSTALL_B), + "the same local position on two machines must not share a document id" + ); + } + + #[test] + fn document_ids_differ_across_nodes_files_and_positions() { + let base = TailedEvent { + node_id: 7, + file_name: "ant-node.2026-08-19.log".to_string(), + byte_offset: 100, + event: parse_line(&line("INFO", "hello")).unwrap(), + }; + let other_node = TailedEvent { + node_id: 8, + ..base.clone() + }; + let other_file = TailedEvent { + file_name: "ant-node.2026-08-20.log".to_string(), + ..base.clone() + }; + let other_offset = TailedEvent { + byte_offset: 200, + ..base.clone() + }; + + let ids = [ + base.document_id(INSTALL_A), + other_node.document_id(INSTALL_A), + other_file.document_id(INSTALL_A), + other_offset.document_id(INSTALL_A), + ]; + let unique: std::collections::HashSet<&String> = ids.iter().collect(); + assert_eq!(unique.len(), 4); + } +} diff --git a/ant-core/src/node/daemon/mod.rs b/ant-core/src/node/daemon/mod.rs index 6a6bc6c1..2781abf3 100644 --- a/ant-core/src/node/daemon/mod.rs +++ b/ant-core/src/node/daemon/mod.rs @@ -1,5 +1,6 @@ pub mod client; pub mod disk; +pub mod forward; pub mod health; pub mod server; pub mod supervisor; diff --git a/ant-core/src/node/daemon/server.rs b/ant-core/src/node/daemon/server.rs index 5747a4c0..2f2e5272 100644 --- a/ant-core/src/node/daemon/server.rs +++ b/ant-core/src/node/daemon/server.rs @@ -15,6 +15,11 @@ use tokio_util::sync::CancellationToken; use crate::error::Result; use crate::node::binary::NoopProgress; +use crate::node::daemon::forward::runner::{ForwarderHandle, DEFAULT_POLL_INTERVAL}; +use crate::node::daemon::forward::{ + apply_enable, classify_nodes, spawn_log_forwarder, ElasticsearchSink, LogForwardConfig, + LogForwardEnableRequest, LogForwardResult, LogForwardStatus, LogSink, +}; use crate::node::daemon::health::{DiskThresholds, FleetHealth}; use crate::node::daemon::supervisor::{ spawn_eviction_monitor, spawn_liveness_monitor, Supervisor, EVICTION_POLL_INTERVAL, @@ -40,6 +45,11 @@ pub struct AppState { /// Latest fleet health snapshot, refreshed by the eviction monitor and served at /// `GET /api/v1/health`. pub health: Arc>, + /// The running log forwarder, if the user has opted in. `None` while forwarding is disabled. + pub forwarder: Arc>>, + /// The daemon's shutdown token, kept so a forwarder started later by `enable` still stops when + /// the daemon does. + pub shutdown: CancellationToken, } /// Start the daemon HTTP server. @@ -96,8 +106,15 @@ pub async fn start( config: config.clone(), bound_port: bound_addr.port(), health: health.clone(), + forwarder: Arc::new(RwLock::new(None)), + shutdown: shutdown.clone(), }); + // Background task: if the user has opted into beta log forwarding, resume it. The opt-in is + // persisted rather than held in daemon memory, so restarting the daemon does not silently stop + // shipping logs the user asked for. + start_forwarder_if_enabled(&state).await; + // Background task: monitor free disk space at node data directories. Refreshes the fleet health // snapshot every tick and auto-evicts a node (smallest data dir) on any partition that has // fallen to the eviction threshold while ≥2 nodes remain. The threshold is a fixed internal @@ -175,6 +192,12 @@ fn build_router(state: Arc) -> Router { .route("/api/v1/nodes/{id}/stop", post(post_stop_node)) .route("/api/v1/nodes/stop-all", post(post_stop_all)) .route("/api/v1/reset", post(post_reset)) + .route("/api/v1/logs/forward", get(get_log_forward)) + .route("/api/v1/logs/forward/enable", post(post_log_forward_enable)) + .route( + "/api/v1/logs/forward/disable", + post(post_log_forward_disable), + ) .route("/api/v1/openapi.json", get(get_openapi)) .layer(cors) .with_state(state) @@ -644,6 +667,168 @@ async fn post_reset( } } +/// Load the persisted forwarding config, treating an unreadable one as disabled. +/// +/// The daemon must come up whatever state that file is in; a broken config is reported through the +/// status endpoint rather than by refusing to start. +fn load_forward_config() -> LogForwardConfig { + LogForwardConfig::default_path() + .and_then(|path| LogForwardConfig::load(&path)) + .unwrap_or_else(|error| { + tracing::warn!("log forwarding: could not read the saved config: {error}"); + LogForwardConfig::disabled() + }) +} + +/// Build the sink a config describes. +fn build_sink(config: &LogForwardConfig) -> Result> { + let sink = ElasticsearchSink::new(config.endpoint_base(), &config.token)?; + Ok(Arc::new(sink)) +} + +/// Start a forwarder for the persisted config, if forwarding is enabled. +async fn start_forwarder_if_enabled(state: &Arc) { + let config = load_forward_config(); + if !config.enabled { + return; + } + if let Err(error) = start_forwarder(state, config).await { + tracing::warn!("log forwarding: could not start: {error}"); + } +} + +/// Replace any running forwarder with one for `config`. +async fn start_forwarder(state: &Arc, config: LogForwardConfig) -> Result<()> { + let sink = build_sink(&config)?; + let offsets_path = crate::node::daemon::forward::OffsetStore::default_path()?; + let endpoint = sink.describe(); + + let handle = spawn_log_forwarder( + state.registry.clone(), + config, + sink, + offsets_path, + DEFAULT_POLL_INTERVAL, + state.shutdown.clone(), + ); + + let mut slot = state.forwarder.write().await; + if let Some(previous) = slot.replace(handle) { + // Awaited, not merely signalled: two forwarders tailing the same files and shipping to the + // same endpoint would otherwise overlap for the length of the old one's retry ladder. + previous.stop_and_wait().await; + } + tracing::info!("log forwarding: shipping node logs to {endpoint}"); + Ok(()) +} + +/// Build the status response, merging persisted config with the live forwarder's counters. +/// +/// The node lists always come from the registry rather than the forwarder's snapshot. They are +/// derived from registry state, not runtime state, and reading them live keeps `status` consistent +/// with what `enable` just reported — a snapshot taken before the forwarder's first poll would +/// otherwise show no nodes at all a moment after `enable` listed them. +async fn forward_status(state: &Arc) -> LogForwardStatus { + let config = load_forward_config(); + let mut status = LogForwardStatus::inactive(&config); + + { + let registry = state.registry.read().await; + let (forwarding, skipped) = classify_nodes(®istry); + status.nodes_forwarding = forwarding; + status.nodes_skipped = skipped; + } + + let slot = state.forwarder.read().await; + if let Some(handle) = slot.as_ref().filter(|handle| !handle.is_stopped()) { + status.active = true; + status.stats = handle.snapshot().await.stats; + } + + status +} + +/// GET /api/v1/logs/forward — Whether beta log forwarding is on, and what it is doing. +async fn get_log_forward(State(state): State>) -> Json { + Json(forward_status(&state).await) +} + +/// POST /api/v1/logs/forward/enable — Opt into forwarding node logs to the beta endpoint. +/// +/// Running this is the consent act. It is idempotent: enabling while already enabled re-reads the +/// request, restarts the forwarder against it, and reports `already_in_state`. +async fn post_log_forward_enable( + State(state): State>, + Json(request): Json, +) -> std::result::Result, (StatusCode, Json)> { + let stored = load_forward_config(); + let was_enabled = stored.enabled; + + let config = apply_enable(&stored, &request).map_err(|error| { + ( + StatusCode::BAD_REQUEST, + Json(serde_json::json!({ "error": error.to_string() })), + ) + })?; + + let path = LogForwardConfig::default_path().map_err(internal_error)?; + config.save(&path).map_err(internal_error)?; + + start_forwarder(&state, config.clone()) + .await + .map_err(internal_error)?; + + let registry = state.registry.read().await; + let (nodes_forwarding, nodes_skipped) = classify_nodes(®istry); + + Ok(Json(LogForwardResult { + enabled: true, + already_in_state: was_enabled, + endpoint: config.endpoint.clone(), + min_level: config.min_level, + nodes_forwarding, + nodes_skipped, + pending_daemon_start: false, + })) +} + +/// POST /api/v1/logs/forward/disable — Stop forwarding. +/// +/// Nothing else about any node changes: no restart, no argument change, no data touched. +async fn post_log_forward_disable( + State(state): State>, +) -> std::result::Result, (StatusCode, Json)> { + let mut config = load_forward_config(); + let was_enabled = config.enabled; + + config.enabled = false; + let path = LogForwardConfig::default_path().map_err(internal_error)?; + config.save(&path).map_err(internal_error)?; + + // Awaited rather than signalled. `disable` is a revocation of consent, so it must not return + // — and the CLI must not print "Log forwarding stopped" — while a request is still in flight. + if let Some(handle) = state.forwarder.write().await.take() { + handle.stop_and_wait().await; + } + + Ok(Json(LogForwardResult { + enabled: false, + already_in_state: !was_enabled, + endpoint: config.endpoint.clone(), + min_level: config.min_level, + nodes_forwarding: Vec::new(), + nodes_skipped: Vec::new(), + pending_daemon_start: false, + })) +} + +fn internal_error(error: crate::error::Error) -> (StatusCode, Json) { + ( + StatusCode::INTERNAL_SERVER_ERROR, + Json(serde_json::json!({ "error": error.to_string() })), + ) +} + async fn get_openapi() -> impl IntoResponse { // TODO: Migrate to utoipa-generated OpenAPI spec. Types already derive // utoipa::ToSchema but this spec is still hand-written JSON. @@ -846,10 +1031,137 @@ async fn get_openapi() -> impl IntoResponse { } } } + }, + "/api/v1/logs/forward": { + "get": { + "summary": "Log forwarding status", + "description": "Whether beta log forwarding is enabled, which nodes are being tailed, which are skipped for having no log directory, and delivery counters. Never returns the write token, only a fingerprint of it.", + "responses": { + "200": { + "description": "Forwarding status", + "content": { + "application/json": { + "schema": { "$ref": "#/components/schemas/LogForwardStatus" } + } + } + } + } + } + }, + "/api/v1/logs/forward/enable": { + "post": { + "summary": "Enable log forwarding", + "description": "Opt into forwarding managed nodes' logs to the beta endpoint. This call is the consent act. Omitted fields reuse the stored configuration, so re-enabling after a disable needs no arguments. Idempotent.", + "requestBody": { + "required": false, + "content": { + "application/json": { + "schema": { "$ref": "#/components/schemas/LogForwardEnableRequest" } + } + } + }, + "responses": { + "200": { + "description": "Forwarding enabled", + "content": { + "application/json": { + "schema": { "$ref": "#/components/schemas/LogForwardResult" } + } + } + }, + "400": { + "description": "No token has ever been supplied, or the endpoint is not an http(s) URL" + } + } + } + }, + "/api/v1/logs/forward/disable": { + "post": { + "summary": "Disable log forwarding", + "description": "Stop forwarding. Nothing else about any node changes: no restart, no argument change, no data touched. Idempotent.", + "responses": { + "200": { + "description": "Forwarding disabled", + "content": { + "application/json": { + "schema": { "$ref": "#/components/schemas/LogForwardResult" } + } + } + } + } + } } }, "components": { "schemas": { + "LogLevel": { + "type": "string", + "enum": ["trace", "debug", "info", "warn", "error"] + }, + "ForwardingNode": { + "type": "object", + "properties": { + "node_id": { "type": "integer" }, + "service": { "type": "string" }, + "log_dir": { "type": "string" } + } + }, + "SkippedNode": { + "type": "object", + "description": "A node that cannot be forwarded, with the reason. Almost always a node added without --log-dir-path, which writes no log files at all.", + "properties": { + "node_id": { "type": "integer" }, + "service": { "type": "string" }, + "reason": { "type": "string" } + } + }, + "ForwardStats": { + "type": "object", + "description": "Counters since the daemon started; reset on restart.", + "properties": { + "events_forwarded": { "type": "integer" }, + "events_dropped_by_level": { "type": "integer" }, + "events_dropped_by_overflow": { "type": "integer" }, + "batches_sent": { "type": "integer" }, + "batches_failed": { "type": "integer" }, + "last_success_unix": { "type": "integer", "nullable": true }, + "last_error": { "type": "string", "nullable": true } + } + }, + "LogForwardStatus": { + "type": "object", + "properties": { + "enabled": { "type": "boolean" }, + "endpoint": { "type": "string" }, + "index_prefix": { "type": "string" }, + "min_level": { "$ref": "#/components/schemas/LogLevel" }, + "token_fingerprint": { "type": "string", "nullable": true, "description": "Short non-reversible identifier for the configured token. The token itself is never returned." }, + "active": { "type": "boolean", "description": "Whether the background forwarder is currently running." }, + "nodes_forwarding": { "type": "array", "items": { "$ref": "#/components/schemas/ForwardingNode" } }, + "nodes_skipped": { "type": "array", "items": { "$ref": "#/components/schemas/SkippedNode" } }, + "stats": { "$ref": "#/components/schemas/ForwardStats" } + } + }, + "LogForwardEnableRequest": { + "type": "object", + "properties": { + "token": { "type": "string", "nullable": true, "description": "Write-only Elasticsearch API key. Reuses the stored one when omitted." }, + "endpoint": { "type": "string", "nullable": true }, + "min_level": { "$ref": "#/components/schemas/LogLevel", "nullable": true } + } + }, + "LogForwardResult": { + "type": "object", + "properties": { + "enabled": { "type": "boolean" }, + "already_in_state": { "type": "boolean" }, + "endpoint": { "type": "string" }, + "min_level": { "$ref": "#/components/schemas/LogLevel" }, + "nodes_forwarding": { "type": "array", "items": { "$ref": "#/components/schemas/ForwardingNode" } }, + "nodes_skipped": { "type": "array", "items": { "$ref": "#/components/schemas/SkippedNode" } }, + "pending_daemon_start": { "type": "boolean", "description": "Set when the config was saved but no forwarder could be started because the daemon is not running." } + } + }, "DaemonStatus": { "type": "object", "properties": { diff --git a/ant-core/tests/log_forward_integration.rs b/ant-core/tests/log_forward_integration.rs new file mode 100644 index 00000000..ab1e8d09 --- /dev/null +++ b/ant-core/tests/log_forward_integration.rs @@ -0,0 +1,736 @@ +//! End-to-end tests for beta log forwarding (V2-1021), driven against a real HTTP endpoint that +//! speaks the V2-1016 Elasticsearch bulk contract. +//! +//! The endpoint itself (`logs.autonomi.com`) is still being provisioned, so these stand in for it: +//! an axum server that frames its replies exactly as the real one does — HTTP 200 even for failed +//! documents, per-position `items[].status`, and the forced +//! `filter_path=errors,items.*.status,items.*.error` response shape. Getting those wrong is the +//! failure mode the contract review specifically warned about, so they are what is asserted here. + +use std::collections::HashMap; +use std::io::Write; +use std::net::SocketAddr; +use std::path::{Path, PathBuf}; +use std::sync::{Arc, Mutex}; +use std::time::Duration; + +use axum::extract::State; +use axum::routing::post; +use axum::Router; +use tokio::sync::RwLock; +use tokio_util::sync::CancellationToken; + +use ant_core::node::daemon::forward::{ + spawn_log_forwarder, ElasticsearchSink, LogForwardConfig, LogLevel, +}; +use ant_core::node::registry::NodeRegistry; +use ant_core::node::types::{EvmNetwork, NodeConfig, UpgradeChannel}; + +/// One document as the endpoint received it: its bulk action line and its source line. +#[derive(Debug, Clone)] +struct ReceivedDocument { + action: serde_json::Value, + source: serde_json::Value, +} + +impl ReceivedDocument { + fn id(&self) -> String { + self.action["create"]["_id"] + .as_str() + .unwrap_or("") + .to_string() + } + + fn index(&self) -> String { + self.action["create"]["_index"] + .as_str() + .unwrap_or("") + .to_string() + } + + fn message(&self) -> String { + self.source["message"].as_str().unwrap_or("").to_string() + } +} + +#[derive(Default)] +struct EndpointState { + documents: Vec, + auth_headers: Vec, + content_types: Vec, + bodies: Vec, + /// Number of the next request to fail outright, simulating a dropped connection. + fail_request_numbers: Vec, + request_count: usize, +} + +/// A stand-in for the beta ingest endpoint. +struct MockEndpoint { + addr: SocketAddr, + state: Arc>, + shutdown: CancellationToken, +} + +impl MockEndpoint { + async fn start(fail_request_numbers: Vec) -> Self { + let state = Arc::new(Mutex::new(EndpointState { + fail_request_numbers, + ..EndpointState::default() + })); + let shutdown = CancellationToken::new(); + + let app = Router::new() + .route("/_bulk", post(handle_bulk)) + .with_state(state.clone()); + + let listener = tokio::net::TcpListener::bind("127.0.0.1:0").await.unwrap(); + let addr = listener.local_addr().unwrap(); + + let serve_shutdown = shutdown.clone(); + tokio::spawn(async move { + axum::serve(listener, app) + .with_graceful_shutdown(serve_shutdown.cancelled_owned()) + .await + .ok(); + }); + + Self { + addr, + state, + shutdown, + } + } + + fn base_url(&self) -> String { + format!("http://{}", self.addr) + } + + fn documents(&self) -> Vec { + self.state.lock().unwrap().documents.clone() + } + + fn auth_headers(&self) -> Vec { + self.state.lock().unwrap().auth_headers.clone() + } + + fn content_types(&self) -> Vec { + self.state.lock().unwrap().content_types.clone() + } + + fn bodies(&self) -> Vec { + self.state.lock().unwrap().bodies.clone() + } + + fn stop(&self) { + self.shutdown.cancel(); + } +} + +/// Parse an NDJSON bulk body and answer the way the real endpoint does. +async fn handle_bulk( + State(state): State>>, + headers: axum::http::HeaderMap, + body: String, +) -> axum::response::Response { + use axum::response::IntoResponse; + + let mut guard = state.lock().unwrap(); + guard.request_count += 1; + let request_number = guard.request_count; + + guard.auth_headers.push( + headers + .get("authorization") + .and_then(|v| v.to_str().ok()) + .unwrap_or_default() + .to_string(), + ); + guard.content_types.push( + headers + .get("content-type") + .and_then(|v| v.to_str().ok()) + .unwrap_or_default() + .to_string(), + ); + guard.bodies.push(body.clone()); + + // Simulate a request that dies before the endpoint can answer. + if guard.fail_request_numbers.contains(&request_number) { + return axum::http::StatusCode::SERVICE_UNAVAILABLE.into_response(); + } + + let mut lines = body.lines(); + let mut statuses = Vec::new(); + + while let (Some(action_line), Some(source_line)) = (lines.next(), lines.next()) { + let action: serde_json::Value = serde_json::from_str(action_line).unwrap(); + let source: serde_json::Value = serde_json::from_str(source_line).unwrap(); + let document = ReceivedDocument { action, source }; + + // `create` semantics: a document whose id is already present is a conflict, not an + // overwrite. This is what makes a replayed batch idempotent. + let already_present = guard.documents.iter().any(|d| d.id() == document.id()); + statuses.push(if already_present { 409 } else { 201 }); + + if !already_present { + guard.documents.push(document); + } + } + + let errors = statuses.iter().any(|s| *s != 201); + let body = if errors { + // The forced filter_path shape: one entry per submitted document, positions preserved. + let items: Vec = statuses + .iter() + .map(|status| serde_json::json!({ "create": { "status": status } })) + .collect(); + serde_json::json!({ "errors": true, "items": items }) + } else { + serde_json::json!({ "errors": false }) + }; + + // Note the 200: a bulk response is a success at the HTTP layer even when documents failed. + (axum::http::StatusCode::OK, axum::Json(body)).into_response() +} + +/// A registry with one logging-enabled node, plus somewhere to write its log files. +struct Fixture { + _dir: tempfile::TempDir, + root: PathBuf, + registry: Arc>, +} + +impl Fixture { + fn new() -> Self { + let dir = tempfile::tempdir().unwrap(); + let root = dir.path().to_path_buf(); + let log_dir = root.join("logs"); + std::fs::create_dir_all(&log_dir).unwrap(); + + let mut registry = NodeRegistry::load(&root.join("registry.json")).unwrap(); + registry.add(NodeConfig { + id: 1, + service_name: "node1".to_string(), + rewards_address: "0x1234567890abcdef1234567890abcdef12345678".to_string(), + data_dir: root.join("data"), + log_dir: Some(log_dir), + node_port: None, + binary_path: root.join("antnode"), + version: "0.17.2-beta.1".to_string(), + env_variables: HashMap::new(), + bootstrap_peers: Vec::new(), + upgrade_channel: Some(UpgradeChannel::Beta), + evm_network: EvmNetwork::default(), + eviction: None, + }); + + Self { + _dir: dir, + root, + registry: Arc::new(RwLock::new(registry)), + } + } + + fn log_path(&self, day: &str) -> PathBuf { + self.root.join("logs").join(format!("ant-node.{day}.log")) + } + + fn append(&self, day: &str, contents: &str) { + let mut file = std::fs::OpenOptions::new() + .create(true) + .append(true) + .open(self.log_path(day)) + .unwrap(); + file.write_all(contents.as_bytes()).unwrap(); + } + + fn offsets_path(&self) -> PathBuf { + self.root.join("offsets.json") + } + + fn config(&self, endpoint: &str) -> LogForwardConfig { + self.config_for_installation(endpoint, "0123456789abcdef") + } + + fn config_for_installation(&self, endpoint: &str, installation_id: &str) -> LogForwardConfig { + LogForwardConfig { + enabled: true, + token: "beta-write-key".to_string(), + endpoint: endpoint.to_string(), + index_prefix: "beta-nodes".to_string(), + min_level: LogLevel::Info, + installation_id: installation_id.to_string(), + } + } +} + +fn line(day: &str, time: &str, level: &str, message: &str) -> String { + format!("{day}T{time}.000000Z {level} ant_node::node: {message}\n") +} + +const POLL: Duration = Duration::from_millis(40); + +/// Run a forwarder against the endpoint for long enough to see several cycles. +async fn forward_for( + fixture: &Fixture, + endpoint_base: &str, + offsets_path: &Path, + write: impl FnOnce(), + settle: Duration, +) { + forward_for_installation( + fixture, + endpoint_base, + offsets_path, + "0123456789abcdef", + write, + settle, + ) + .await; +} + +async fn forward_for_installation( + fixture: &Fixture, + endpoint_base: &str, + offsets_path: &Path, + installation_id: &str, + write: impl FnOnce(), + settle: Duration, +) { + let config = fixture.config_for_installation(endpoint_base, installation_id); + let sink = Arc::new(ElasticsearchSink::new(config.endpoint_base(), &config.token).unwrap()); + + let handle = spawn_log_forwarder( + fixture.registry.clone(), + config, + sink, + offsets_path.to_path_buf(), + POLL, + CancellationToken::new(), + ); + + // Let the forwarder join the file at its end before anything is written, so the test exercises + // live tailing rather than the initial adoption path. + tokio::time::sleep(Duration::from_millis(100)).await; + write(); + tokio::time::sleep(settle).await; + + handle.stop(); + tokio::time::sleep(Duration::from_millis(120)).await; +} + +#[tokio::test] +async fn node_logs_reach_the_endpoint_correctly_framed_and_tagged() { + let endpoint = MockEndpoint::start(Vec::new()).await; + let fixture = Fixture::new(); + + forward_for( + &fixture, + &endpoint.base_url(), + &fixture.offsets_path(), + || { + fixture.append( + "2026-08-19", + &line("2026-08-19", "20:50:00", "INFO", "connected to the network"), + ); + }, + Duration::from_millis(400), + ) + .await; + + let documents = endpoint.documents(); + assert_eq!(documents.len(), 1, "expected exactly one document"); + let document = &documents[0]; + + // Framing: the action must be `create`; `index` is refused with a per-item 403. + assert!( + document.action.get("create").is_some(), + "the bulk action must be `create`, got {:?}", + document.action + ); + assert_eq!(document.index(), "beta-nodes-2026.08.19"); + assert_eq!( + document.id(), + "0123456789abcdef-1-ant-node.2026-08-19.log-0", + "the id is namespaced by installation, then node, file and byte offset" + ); + + // Tagging, using the index's own field names. + assert_eq!(document.source["@timestamp"], "2026-08-19T20:50:00.000000Z"); + assert!( + document.source.get("timestamp").is_none(), + "the time field is @timestamp, not timestamp" + ); + assert_eq!(document.source["level"], "INFO"); + assert_eq!(document.source["message"], "connected to the network"); + assert_eq!(document.source["node_id"], "1"); + assert_eq!(document.source["service"], "node1"); + assert_eq!(document.source["binary_version"], "0.17.2-beta.1"); + assert_eq!(document.source["channel"], "beta"); + assert_eq!(document.source["os"], std::env::consts::OS); + assert_eq!(document.source["arch"], std::env::consts::ARCH); + + // Both are server-side concerns; sending either would be discarded or overwritten. + assert!(document.source.get("host").is_none()); + assert!(document.source.get("beta_user").is_none()); + + // Transport details the contract fixes. + assert_eq!(endpoint.auth_headers()[0], "ApiKey beta-write-key"); + assert_eq!(endpoint.content_types()[0], "application/x-ndjson"); + assert!( + endpoint.bodies()[0].ends_with('\n'), + "the bulk body must end with a newline" + ); + + endpoint.stop(); +} + +#[tokio::test] +async fn events_below_info_are_never_shipped() { + let endpoint = MockEndpoint::start(Vec::new()).await; + let fixture = Fixture::new(); + + forward_for( + &fixture, + &endpoint.base_url(), + &fixture.offsets_path(), + || { + fixture.append( + "2026-08-19", + &format!( + "{}{}{}", + line("2026-08-19", "20:50:00", "DEBUG", "chatter"), + line("2026-08-19", "20:50:01", "TRACE", "more chatter"), + line("2026-08-19", "20:50:02", "WARN", "worth keeping"), + ), + ); + }, + Duration::from_millis(400), + ) + .await; + + let messages: Vec = endpoint.documents().iter().map(|d| d.message()).collect(); + assert_eq!( + messages, + vec!["worth keeping"], + "the endpoint drops sub-INFO events anyway; sending them wastes the user's bandwidth" + ); + + endpoint.stop(); +} + +/// The V2-1021 acceptance criterion: a daemon restart must not duplicate or lose events. +#[tokio::test] +async fn a_restart_neither_duplicates_nor_loses_events() { + let endpoint = MockEndpoint::start(Vec::new()).await; + let fixture = Fixture::new(); + let offsets = fixture.offsets_path(); + + forward_for( + &fixture, + &endpoint.base_url(), + &offsets, + || { + fixture.append( + "2026-08-19", + &line("2026-08-19", "20:50:00", "INFO", "before the restart"), + ); + }, + Duration::from_millis(400), + ) + .await; + + assert_eq!(endpoint.documents().len(), 1); + + // Written while no forwarder is running — the "gap" half of the criterion. + fixture.append( + "2026-08-19", + &line( + "2026-08-19", + "20:51:00", + "INFO", + "while the daemon was down", + ), + ); + + // A second forwarder over the same persisted offsets: a restart, not a fresh enable. + forward_for( + &fixture, + &endpoint.base_url(), + &offsets, + || { + fixture.append( + "2026-08-19", + &line("2026-08-19", "20:52:00", "INFO", "after the restart"), + ); + }, + Duration::from_millis(400), + ) + .await; + + let messages: Vec = endpoint.documents().iter().map(|d| d.message()).collect(); + assert_eq!( + messages, + vec![ + "before the restart", + "while the daemon was down", + "after the restart" + ], + "every event exactly once, in order" + ); + + let ids: Vec = endpoint.documents().iter().map(|d| d.id()).collect(); + let unique: std::collections::HashSet<&String> = ids.iter().collect(); + assert_eq!(unique.len(), ids.len(), "no document was written twice"); + + endpoint.stop(); +} + +/// A request that dies in flight is replayed wholesale, which is only safe because the ids are +/// deterministic: the endpoint answers the replay with 409s rather than storing a second copy. +#[tokio::test] +async fn a_failed_request_is_replayed_without_duplicating_documents() { + // Fail the first request outright. + let endpoint = MockEndpoint::start(vec![1]).await; + let fixture = Fixture::new(); + + forward_for( + &fixture, + &endpoint.base_url(), + &fixture.offsets_path(), + || { + fixture.append( + "2026-08-19", + &line("2026-08-19", "20:50:00", "INFO", "survives a failed send"), + ); + }, + // Long enough to cover the retry policy's 2s initial backoff. The wait is the point of the + // test: a shorter one would pass by never reaching the retry at all. + Duration::from_millis(3_500), + ) + .await; + + let documents = endpoint.documents(); + assert_eq!( + documents.len(), + 1, + "the replay must not store a second copy: {:?}", + documents + .iter() + .map(ReceivedDocument::id) + .collect::>() + ); + assert_eq!(documents[0].message(), "survives a failed send"); + assert!( + endpoint.bodies().len() >= 2, + "the batch should have been retried after the failure" + ); + + endpoint.stop(); +} + +/// Each document is filed by its own timestamp, so an event written just before midnight lands in +/// yesterday's index even though it ships today. This is what keeps a replayed batch landing on the +/// same `_id` in the same index. +#[tokio::test] +async fn documents_are_indexed_by_their_own_date_not_the_wall_clock() { + let endpoint = MockEndpoint::start(Vec::new()).await; + let fixture = Fixture::new(); + + forward_for( + &fixture, + &endpoint.base_url(), + &fixture.offsets_path(), + || { + fixture.append( + "2026-08-19", + &format!( + "{}{}", + line("2026-08-19", "23:59:59", "INFO", "just before midnight"), + line("2026-08-20", "00:00:01", "INFO", "just after midnight"), + ), + ); + }, + Duration::from_millis(400), + ) + .await; + + let documents = endpoint.documents(); + assert_eq!(documents.len(), 2); + assert_eq!(documents[0].index(), "beta-nodes-2026.08.19"); + assert_eq!(documents[1].index(), "beta-nodes-2026.08.20"); + + endpoint.stop(); +} + +/// Daily rotation is a new file appearing beside the old one, and the tailer must pick it up +/// without being restarted. +#[tokio::test] +async fn a_days_rotation_is_followed_into_the_new_file() { + let endpoint = MockEndpoint::start(Vec::new()).await; + let fixture = Fixture::new(); + + let config = fixture.config(&endpoint.base_url()); + let sink = Arc::new(ElasticsearchSink::new(config.endpoint_base(), &config.token).unwrap()); + let handle = spawn_log_forwarder( + fixture.registry.clone(), + config, + sink, + fixture.offsets_path(), + POLL, + CancellationToken::new(), + ); + + tokio::time::sleep(Duration::from_millis(100)).await; + fixture.append( + "2026-08-19", + &line("2026-08-19", "23:59:00", "INFO", "end of the day"), + ); + tokio::time::sleep(Duration::from_millis(300)).await; + + // Rotation: a new file, not a moved cursor. + fixture.append( + "2026-08-20", + &line("2026-08-20", "00:00:30", "INFO", "start of the next"), + ); + tokio::time::sleep(Duration::from_millis(400)).await; + + handle.stop(); + tokio::time::sleep(Duration::from_millis(120)).await; + + let documents = endpoint.documents(); + let messages: Vec = documents.iter().map(|d| d.message()).collect(); + assert_eq!(messages, vec!["end of the day", "start of the next"]); + assert!(documents[1].id().contains("ant-node.2026-08-20.log")); + + endpoint.stop(); +} + +/// A panic and its backtrace must arrive as one document, not as an event followed by orphan lines. +#[tokio::test] +async fn a_multi_line_event_arrives_as_a_single_document() { + let endpoint = MockEndpoint::start(Vec::new()).await; + let fixture = Fixture::new(); + + forward_for( + &fixture, + &endpoint.base_url(), + &fixture.offsets_path(), + || { + fixture.append( + "2026-08-19", + &format!( + "{}thread 'main' panicked at src/node.rs:42\n stack frame one\n", + line("2026-08-19", "20:50:00", "ERROR", "the node fell over"), + ), + ); + }, + Duration::from_millis(400), + ) + .await; + + let documents = endpoint.documents(); + assert_eq!( + documents.len(), + 1, + "the backtrace must not become its own document" + ); + let message = documents[0].message(); + assert!(message.contains("the node fell over"), "{message}"); + assert!(message.contains("thread 'main' panicked"), "{message}"); + assert!(message.contains("stack frame one"), "{message}"); + + endpoint.stop(); +} + +/// Enabling forwarding is forward-looking consent: it must not upload the retained backlog. +#[tokio::test] +async fn enabling_does_not_upload_the_existing_backlog() { + let endpoint = MockEndpoint::start(Vec::new()).await; + let fixture = Fixture::new(); + + fixture.append( + "2026-08-19", + &line("2026-08-19", "10:00:00", "INFO", "logged before consent"), + ); + + forward_for( + &fixture, + &endpoint.base_url(), + &fixture.offsets_path(), + || { + fixture.append( + "2026-08-19", + &line("2026-08-19", "20:50:00", "INFO", "logged after consent"), + ); + }, + Duration::from_millis(400), + ) + .await; + + let messages: Vec = endpoint.documents().iter().map(|d| d.message()).collect(); + assert_eq!(messages, vec!["logged after consent"]); + + endpoint.stop(); +} + +/// Two participants, each running a node `1` whose daily log file has the same name and whose first +/// line sits at byte offset 0, writing into the same shared daily index. +/// +/// Without an installation namespace in the document id these two events share an `_id`. The second +/// one would come back as a 409, which the sink counts as delivered, so it would be dropped rather +/// than stored — and because it is the node's *first* line, the loss falls precisely on the startup +/// event carrying version, commit and peer id. +#[tokio::test] +async fn identical_events_from_two_installations_are_both_stored() { + let endpoint = MockEndpoint::start(Vec::new()).await; + + let first = Fixture::new(); + let second = Fixture::new(); + + // Byte-for-byte identical content, at the same offset, in the same filename, for node 1. + let startup = line("2026-08-19", "20:50:00", "INFO", "starting version=0.17.2"); + + forward_for_installation( + &first, + &endpoint.base_url(), + &first.offsets_path(), + "aaaaaaaaaaaaaaaa", + || first.append("2026-08-19", &startup), + Duration::from_millis(400), + ) + .await; + + forward_for_installation( + &second, + &endpoint.base_url(), + &second.offsets_path(), + "bbbbbbbbbbbbbbbb", + || second.append("2026-08-19", &startup), + Duration::from_millis(400), + ) + .await; + + let documents = endpoint.documents(); + assert_eq!( + documents.len(), + 2, + "both installations' events must be stored, got ids {:?}", + documents + .iter() + .map(ReceivedDocument::id) + .collect::>() + ); + + let ids: Vec = documents.iter().map(ReceivedDocument::id).collect(); + assert_ne!(ids[0], ids[1]); + assert!(ids.iter().any(|id| id.starts_with("aaaaaaaaaaaaaaaa-"))); + assert!(ids.iter().any(|id| id.starts_with("bbbbbbbbbbbbbbbb-"))); + + // Both are still the same local position — which is the point. + assert!(ids + .iter() + .all(|id| id.ends_with("-1-ant-node.2026-08-19.log-0"))); + + endpoint.stop(); +} diff --git a/install.ps1 b/install.ps1 index 3d112486..d837fe3a 100644 --- a/install.ps1 +++ b/install.ps1 @@ -4,9 +4,15 @@ # irm https://raw.githubusercontent.com/WithAutonomi/ant-client/main/install.ps1 | iex # # Environment variables: -# ANT_VERSION - install a specific version (e.g. "0.1.1"). Defaults to latest. +# ANT_CHANNEL - release channel to install from: "stable" (default) or "beta". +# ANT_VERSION - install a specific version (e.g. "0.1.1"). Overrides ANT_CHANNEL. # INSTALL_DIR - override install directory (default: %LOCALAPPDATA%\ant\bin). # +# Examples: +# irm | iex # newest stable +# $env:ANT_CHANNEL="beta"; irm | iex # newest beta-eligible +# $env:ANT_VERSION="0.3.3"; irm | iex # a specific version +# # Verification: # Release archives are signed with ML-DSA-65 post-quantum signatures. # Download ant-keygen from https://github.com/WithAutonomi/ant-keygen/releases @@ -23,7 +29,79 @@ $BinaryName = "ant" function Say($msg) { Write-Host $msg } function Err($msg) { Write-Error $msg; exit 1 } -function Get-LatestVersion { +# Whether a version is eligible for a release channel. +# +# Deliberately mirrors version_matches_channel in ant-core/src/channel.rs, which in turn mirrors +# ant-node's own copy. If these drift, the installer hands someone a build that `ant update` would +# then refuse to move off, or vice versa. +# +# stable - final releases only, i.e. no pre-release component at all. +# beta - final releases, plus pre-releases whose first identifier is exactly `beta`. +# +# Every other pre-release suffix is rejected on both channels. `-rc.*` in particular is NOT a beta +# candidate: release candidates are published before the release gates have reported, and semver +# ranks `-rc` above `-beta`, so accepting them would pull beta users onto un-gated code. Both +# 0.3.4-beta.1 and 0.3.4-rc.1 routinely exist at once, which is exactly when this matters. +function Test-VersionMatchesChannel { + param([string]$Version, [string]$Channel) + + $dash = $Version.IndexOf('-') + if ($dash -lt 0) { return $true } # a final release suits every channel + if ($Channel -ne "beta") { return $false } + + $pre = $Version.Substring($dash + 1) + # Compare the whole first identifier, so `betamax.1` is not mistaken for a beta. + return ($pre.Split('.')[0] -eq "beta") +} + +# Compare two versions by semver precedence. Returns -1, 0 or 1. +# +# [version] is not used: it cannot parse a pre-release suffix at all, and would either throw on +# "0.3.4-beta.1" or silently compare the wrong thing. +function Compare-SemVer { + param([string]$A, [string]$B) + + $splitVersion = { + param([string]$v) + $dash = $v.IndexOf('-') + if ($dash -lt 0) { return @{ Core = $v; Pre = "" } } + return @{ Core = $v.Substring(0, $dash); Pre = $v.Substring($dash + 1) } + } + + $left = & $splitVersion $A + $right = & $splitVersion $B + + $leftFields = $left.Core.Split('.') + $rightFields = $right.Core.Split('.') + for ($i = 0; $i -lt 3; $i++) { + $l = if ($i -lt $leftFields.Count) { [int]$leftFields[$i] } else { 0 } + $r = if ($i -lt $rightFields.Count) { [int]$rightFields[$i] } else { 0 } + if ($l -gt $r) { return 1 } + if ($l -lt $r) { return -1 } + } + + # Same core version: a final release outranks any pre-release of it. + if ($left.Pre -eq "" -and $right.Pre -ne "") { return 1 } + if ($left.Pre -ne "" -and $right.Pre -eq "") { return -1 } + if ($left.Pre -eq "" -and $right.Pre -eq "") { return 0 } + + # Both are pre-releases, and only `beta.N` reaches this far, so the trailing number decides. + $parseTrailing = { + param([string]$pre) + $last = $pre.Split('.')[-1] + $n = 0 + if ([int]::TryParse($last, [ref]$n)) { return $n } + return 0 + } + $leftN = & $parseTrailing $left.Pre + $rightN = & $parseTrailing $right.Pre + if ($leftN -gt $rightN) { return 1 } + if ($leftN -lt $rightN) { return -1 } + return 0 +} + +# Newest stable release, via the endpoint that already excludes pre-releases. +function Get-LatestStableVersion { $response = Invoke-RestMethod -Uri "https://api.github.com/repos/$Repo/releases/latest" if ($response.tag_name -match "^ant-cli-v(.+)$") { return $Matches[1] @@ -31,6 +109,39 @@ function Get-LatestVersion { Err "Could not parse version from tag: $($response.tag_name)" } +# Highest release eligible for $Channel, scanning the release list. +# +# /releases/latest cannot serve the beta channel: GitHub excludes pre-releases from it entirely, so +# it would always return the newest stable build. The list endpoint includes them, and the highest +# *eligible* entry wins - which is neither the newest by date nor the highest by raw semver. +function Get-LatestChannelVersion { + param([string]$Channel) + + $releases = Invoke-RestMethod -Uri "https://api.github.com/repos/$Repo/releases?per_page=100" + $best = $null + + foreach ($release in $releases) { + if ($release.tag_name -notmatch "^ant-cli-v(.+)$") { continue } + $version = $Matches[1] + if (-not (Test-VersionMatchesChannel -Version $version -Channel $Channel)) { continue } + if ($null -eq $best -or (Compare-SemVer -A $version -B $best) -gt 0) { + $best = $version + } + } + + if ($null -eq $best) { Err "No $Channel-eligible ant-cli release found" } + return $best +} + +function Resolve-Version { + param([string]$Channel) + switch ($Channel) { + "stable" { return Get-LatestStableVersion } + "beta" { return Get-LatestChannelVersion -Channel "beta" } + default { Err "Unknown channel '$Channel' (expected 'stable' or 'beta')" } + } +} + function Get-DefaultInstallDir { return Join-Path $env:LOCALAPPDATA "ant\bin" } @@ -41,7 +152,8 @@ function Get-ConfigDir { # --- main ------------------------------------------------------------------- -$Version = if ($env:ANT_VERSION) { $env:ANT_VERSION } else { Get-LatestVersion } +$Channel = if ($env:ANT_CHANNEL) { $env:ANT_CHANNEL } else { "stable" } +$Version = if ($env:ANT_VERSION) { $env:ANT_VERSION } else { Resolve-Version -Channel $Channel } $InstallDir = if ($env:INSTALL_DIR) { $env:INSTALL_DIR } else { Get-DefaultInstallDir } $Target = "x86_64-pc-windows-msvc" @@ -49,7 +161,11 @@ if ($env:PROCESSOR_ARCHITECTURE -eq "ARM64") { Say "WARNING: No native ARM64 build available. Installing x86_64 binary (runs under emulation)." } -Say "Installing ant $Version for $Target..." +if ($env:ANT_VERSION) { + Say "Installing ant $Version for $Target..." +} else { + Say "Installing ant $Version for $Target ($Channel channel)..." +} $Archive = "$BinaryName-$Version-$Target.zip" $Url = "https://github.com/$Repo/releases/download/ant-cli-v$Version/$Archive" diff --git a/install.sh b/install.sh index 9c3201ea..7a296c30 100755 --- a/install.sh +++ b/install.sh @@ -5,8 +5,14 @@ # curl -fsSL https://raw.githubusercontent.com/WithAutonomi/ant-client/main/install.sh | bash # # Environment variables: -# ANT_VERSION — install a specific version (e.g. "0.1.1"). Defaults to latest. +# ANT_CHANNEL — release channel to install from: "stable" (default) or "beta". +# ANT_VERSION — install a specific version (e.g. "0.1.1"). Overrides ANT_CHANNEL. # INSTALL_DIR — override install directory (default: ~/.local/bin on Linux, /usr/local/bin on macOS). +# +# Examples: +# curl -fsSL | bash # newest stable +# curl -fsSL | ANT_CHANNEL=beta bash # newest beta-eligible +# curl -fsSL | ANT_VERSION=0.3.3 bash # a specific version set -euo pipefail @@ -66,22 +72,124 @@ default_install_dir() { esac } -latest_version() { +# Whether a version is eligible for a release channel. +# +# Deliberately mirrors `version_matches_channel` in ant-core/src/channel.rs, which in turn mirrors +# ant-node's own copy. If these drift, the installer hands someone a build that `ant update` would +# then refuse to move off, or vice versa. +# +# stable — final releases only, i.e. no pre-release component at all. +# beta — final releases, plus pre-releases whose first identifier is exactly `beta`. +# +# Every other pre-release suffix is rejected on both channels. `-rc.*` in particular is NOT a beta +# candidate: release candidates are published before the release gates have reported, and semver +# ranks `-rc` above `-beta`, so accepting them would pull beta users onto un-gated code. Both +# 0.3.4-beta.1 and 0.3.4-rc.1 routinely exist at once, which is exactly when this matters. +version_matches_channel() { + local version="$1" channel="$2" pre="" + + [ "$version" != "${version%%-*}" ] && pre="${version#*-}" + + # A final release is eligible on every channel. + [ -z "$pre" ] && return 0 + [ "$channel" = "beta" ] || return 1 + # `%%.*` rather than a prefix match, so `betamax.1` is not mistaken for a beta. + [ "${pre%%.*}" = "beta" ] +} + +# True when $1 is a greater version than $2, by semver precedence. +# +# `sort -V` is not used: it does not implement semver's rule that a pre-release ranks *below* the +# release it was cut from, and BSD and GNU builds disagree, which matters because this script runs +# on macOS as well as Linux. +version_gt() { + local a="$1" b="$2" + local a_core="${a%%-*}" b_core="${b%%-*}" + local a_pre="" b_pre="" a_field b_field i + local a_parts b_parts + + [ "$a" != "$a_core" ] && a_pre="${a#*-}" + [ "$b" != "$b_core" ] && b_pre="${b#*-}" + + IFS=. read -r -a a_parts <<< "$a_core" + IFS=. read -r -a b_parts <<< "$b_core" + for i in 0 1 2; do + a_field="${a_parts[$i]:-0}" + b_field="${b_parts[$i]:-0}" + [ "$a_field" -gt "$b_field" ] && return 0 + [ "$a_field" -lt "$b_field" ] && return 1 + done + + # Same core version: a final release outranks any pre-release of it. + if [ -z "$a_pre" ] && [ -n "$b_pre" ]; then return 0; fi + if [ -n "$a_pre" ] && [ -z "$b_pre" ]; then return 1; fi + if [ -z "$a_pre" ] && [ -z "$b_pre" ]; then return 1; fi + + # Both are pre-releases, and only `beta.N` reaches this far, so the trailing number decides. + local a_n="${a_pre##*.}" b_n="${b_pre##*.}" + case "$a_n" in ''|*[!0-9]*) a_n=0 ;; esac + case "$b_n" in ''|*[!0-9]*) b_n=0 ;; esac + [ "$a_n" -gt "$b_n" ] +} + +# Newest stable release, via the endpoint that already excludes pre-releases. +latest_stable_version() { curl -fsSL "https://api.github.com/repos/${REPO}/releases/latest" \ | grep '"tag_name"' \ | sed -E 's/.*"ant-cli-v([^"]+)".*/\1/' } +# Highest release eligible for channel $1, scanning the release list. +# +# `/releases/latest` cannot serve the beta channel: GitHub excludes pre-releases from it entirely, +# so it would always return the newest stable build. The list endpoint includes them, and the +# highest *eligible* entry wins — which is neither the newest by date nor the highest by raw semver. +latest_channel_version() { + local channel="$1" tags version best="" + + tags="$( + curl -fsSL "https://api.github.com/repos/${REPO}/releases?per_page=100" \ + | grep -oE '"tag_name" *: *"ant-cli-v[^"]+"' \ + | sed -E 's/.*"ant-cli-v([^"]+)"/\1/' + )" + + [ -n "$tags" ] || err "could not read the release list for ${REPO}" + + for version in $tags; do + version_matches_channel "$version" "$channel" || continue + if [ -z "$best" ] || version_gt "$version" "$best"; then + best="$version" + fi + done + + [ -n "$best" ] || err "no ${channel}-eligible ant-cli release found" + printf '%s\n' "$best" +} + +resolve_version() { + local channel="$1" + case "$channel" in + stable) latest_stable_version ;; + beta) latest_channel_version beta ;; + *) err "unknown channel '${channel}' (expected 'stable' or 'beta')" ;; + esac +} + # --- main ------------------------------------------------------------------- need curl need tar TARGET="$(detect_target)" -VERSION="${ANT_VERSION:-$(latest_version)}" +CHANNEL="${ANT_CHANNEL:-stable}" +VERSION="${ANT_VERSION:-$(resolve_version "$CHANNEL")}" INSTALL_DIR="${INSTALL_DIR:-$(default_install_dir)}" -say "Installing ant ${VERSION} for ${TARGET}..." +if [ -n "${ANT_VERSION:-}" ]; then + say "Installing ant ${VERSION} for ${TARGET}..." +else + say "Installing ant ${VERSION} for ${TARGET} (${CHANNEL} channel)..." +fi ARCHIVE="${BINARY_NAME}-${VERSION}-${TARGET}.tar.gz" URL="https://github.com/${REPO}/releases/download/ant-cli-v${VERSION}/${ARCHIVE}"