diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 000a4cc8..92cf44b2 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -15,6 +15,15 @@ jobs: - name: cargo fmt -- --check run: cargo fmt --all -- --check + log-redaction: + runs-on: ubuntu-latest + steps: + - uses: actions/checkout@v6 + - name: Regression-test the log-redaction checker itself + run: python3 scripts/check_log_redaction_test.py + - name: Check for Nostr key/identity leaks in tracing calls + run: python3 scripts/check_log_redaction.py + clippy: runs-on: ubuntu-latest steps: @@ -32,7 +41,7 @@ jobs: test: runs-on: ubuntu-latest - needs: [fmt, clippy] + needs: [fmt, clippy, log-redaction] steps: - uses: actions/checkout@v6 - uses: dtolnay/rust-toolchain@stable diff --git a/.gitignore b/.gitignore index fd5316fb..24eb37dd 100644 --- a/.gitignore +++ b/.gitignore @@ -24,3 +24,5 @@ CLAUDE.md # Mutation testing output mutants.out/ mutants.out.old/ + +__pycache__/ diff --git a/scripts/check_log_redaction.py b/scripts/check_log_redaction.py new file mode 100644 index 00000000..0bf371df --- /dev/null +++ b/scripts/check_log_redaction.py @@ -0,0 +1,132 @@ +#!/usr/bin/env python3 +"""CI gate for AGENTS.md:48 ("Scrub logs that might leak invoices or Nostr +keys"). Flags any `tracing::{trace,debug,info,warn,error}!(...)` call whose +argument list interpolates an identifier that looks like a Nostr +key/identity, so a new log-scrubbing regression (issue #836's pattern) fails +CI instead of shipping quietly. + +Not a Rust parser: string literals are skipped so a key-shaped *word* inside +a log message's own text doesn't trigger a false positive, but the paren +matching is a plain depth counter — a macro call containing a raw string +literal with unbalanced parens would confuse it. None of this codebase's +tracing calls do that today; if one ever needs to, exempt it inline (see +ALLOW_COMMENT below) rather than fighting the matcher. +""" + +import re +import sys +from pathlib import Path + +REPO_ROOT = Path(__file__).resolve().parent.parent +SRC_ROOT = REPO_ROOT / "src" + +MACRO_RE = re.compile(r"\b(?:tracing::)?(?:trace|debug|info|warn|error)!\s*([({\[])") + +# Rust macros accept any of these three delimiter pairs; the matcher must +# track whichever one was actually opened. +DELIMITER_PAIRS = {"(": ")", "{": "}", "[": "]"} + +# Identifiers that name a Nostr key/identity in this codebase. Extend this +# list, don't loosen it to a bare `key` — that also matches innocuous things +# like HashMap iteration variables. +SUSPICIOUS_RE = re.compile( + r"\b(" + r"\w*pubkey\w*" + r"|identity\w*" + r"|sender\w*" + r"|master_key" + r"|trade_key" + r"|nsec\w*" + r"|priv(?:ate)?_?key\w*" + r")\b" +) + +# A `// pubkey-log-allow: ` comment on the line right before a +# flagged macro call exempts it — for a documented, deliberate exception +# (e.g. an already-redacted/truncated value) rather than a silent miss. +ALLOW_COMMENT = "pubkey-log-allow:" + + +def find_call_span(text: str, open_delim: int) -> tuple[int, str]: + """Return (index just past the delimiter matching + `text[open_delim]`, the call's source with string-literal *contents* + blanked out). Handles all three Rust macro delimiter pairs: `()`, + `{}`, `[]`. + + Blanking string contents (not just skipping them for delimiter-matching) + matters: a format string's own English prose can contain a key-shaped + word ("...pubkey in order...") that isn't an interpolated argument at + all — only the blanked version should be searched for suspicious + identifiers, or every message that merely *mentions* a pubkey false- + positives. + """ + open_ch = text[open_delim] + close_ch = DELIMITER_PAIRS[open_ch] + depth = 0 + i = open_delim + n = len(text) + out = [] + while i < n: + c = text[i] + if c == '"': + start = i + i += 1 + while i < n and text[i] != '"': + i += 2 if text[i] == "\\" else 1 + i += 1 + out.append('"' * (i - start)) + continue + out.append(c) + if c == open_ch: + depth += 1 + elif c == close_ch: + depth -= 1 + if depth == 0: + return i + 1, "".join(out) + i += 1 + return n, "".join(out) # unbalanced — best effort + + +def line_before(text: str, index: int) -> str: + line_start = text.rfind("\n", 0, index) + prev_start = text.rfind("\n", 0, line_start) + 1 if line_start != -1 else 0 + return text[prev_start:line_start] if line_start != -1 else "" + + +def check_file(path: Path) -> list[tuple[int, str]]: + text = path.read_text(encoding="utf-8") + violations = [] + for m in MACRO_RE.finditer(text): + open_delim = m.end() - 1 + _end, code_only = find_call_span(text, open_delim) + found = SUSPICIOUS_RE.search(code_only) + if not found: + continue + if ALLOW_COMMENT in line_before(text, m.start()): + continue + line_no = text.count("\n", 0, m.start()) + 1 + violations.append((line_no, found.group(0))) + return violations + + +def main() -> int: + total = 0 + for path in sorted(SRC_ROOT.rglob("*.rs")): + for line_no, ident in check_file(path): + rel = path.relative_to(REPO_ROOT) + print( + f"{rel}:{line_no}: tracing call interpolates `{ident}` — " + f"looks like a Nostr key/identity (AGENTS.md:48). Drop it from " + f"the log line, or mark a deliberate exception with a " + f"`// {ALLOW_COMMENT} ` comment on the line above." + ) + total += 1 + if total: + print(f"\n{total} log-redaction violation(s) found.", file=sys.stderr) + return 1 + print("check_log_redaction: clean.") + return 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/scripts/check_log_redaction_test.py b/scripts/check_log_redaction_test.py new file mode 100644 index 00000000..ec7b7957 --- /dev/null +++ b/scripts/check_log_redaction_test.py @@ -0,0 +1,71 @@ +#!/usr/bin/env python3 +"""Regression coverage for check_log_redaction.py's macro/identifier +matching (delimiter forms and suspicious-identifier variants). Run via +`python3 scripts/check_log_redaction_test.py` — wired into the +`log-redaction` CI job alongside the checker itself. +""" + +import tempfile +import unittest +from pathlib import Path + +from check_log_redaction import check_file + + +class CheckLogRedactionTest(unittest.TestCase): + def _violations(self, rust_src: str) -> list[tuple[int, str]]: + with tempfile.NamedTemporaryFile( + "w", suffix=".rs", delete=False, encoding="utf-8" + ) as f: + f.write(rust_src) + path = Path(f.name) + try: + return check_file(path) + finally: + path.unlink() + + def test_paren_call_flags_pubkey(self): + violations = self._violations('fn x() { tracing::info!("{}", pubkey); }') + self.assertEqual(violations, [(1, "pubkey")]) + + def test_brace_call_flags_pubkey(self): + violations = self._violations("fn x() { trace! {pubkey} }") + self.assertEqual(violations, [(1, "pubkey")]) + + def test_bracket_call_flags_pubkey(self): + violations = self._violations("fn x() { trace![pubkey] }") + self.assertEqual(violations, [(1, "pubkey")]) + + def test_identity_key_variant_is_flagged(self): + violations = self._violations('fn x() { info!("{}", identity_key); }') + self.assertEqual(violations, [(1, "identity_key")]) + + def test_sender_key_variant_is_flagged(self): + violations = self._violations('fn x() { info!("{}", sender_key); }') + self.assertEqual(violations, [(1, "sender_key")]) + + def test_reported_line_is_the_macro_line_not_the_first(self): + # Every other positive case is a one-liner, so its `1` would hold + # even if the line number were never computed. Put the call further + # down so the assertion actually exercises that arithmetic. + violations = self._violations( + "fn x() {\n let a = 1;\n info!(\"{}\", pubkey);\n}" + ) + self.assertEqual(violations, [(3, "pubkey")]) + + def test_prose_mention_is_not_flagged(self): + violations = self._violations('fn x() { info!("logging pubkey redaction"); }') + self.assertEqual(violations, []) + + def test_allow_comment_exempts_call(self): + violations = self._violations( + "fn x() {\n" + "// pubkey-log-allow: already truncated\n" + 'info!("{}", pubkey);\n' + "}" + ) + self.assertEqual(violations, []) + + +if __name__ == "__main__": + unittest.main() diff --git a/src/app.rs b/src/app.rs index 938641a6..65873cec 100644 --- a/src/app.rs +++ b/src/app.rs @@ -340,9 +340,9 @@ async fn accept_event( // we decrypt. New orders/takes legitimately arrive // here — so does spam, hence the PoW toll. if !gate.is_known(&event.pubkey.to_string()) && !event.check_pow(pow_first_contact) { + // No key in the log line — sender pubkey (AGENTS.md:48). tracing::info!( - "Dropping first-contact kind-14 event from unknown key {} below pow_first_contact ({} bits)", - event.pubkey, + "Dropping first-contact kind-14 event below pow_first_contact ({} bits)", pow_first_contact ); return None; @@ -385,11 +385,8 @@ async fn accept_event( // signature — unwrap_message already verified it, so if identity // and sender differ here without a signature we bail out. if unwrapped.identity != unwrapped.sender && unwrapped.signature.is_none() { - tracing::warn!( - "Missing inner signature: identity {} differs from trade key {}", - unwrapped.identity, - unwrapped.sender - ); + // No keys in the log line — identity/trade key (AGENTS.md:48). + tracing::warn!("Missing inner signature: identity differs from trade key"); return None; } diff --git a/src/app/admin_take_dispute.rs b/src/app/admin_take_dispute.rs index 23b9b0e9..3fa1f327 100644 --- a/src/app/admin_take_dispute.rs +++ b/src/app/admin_take_dispute.rs @@ -92,12 +92,9 @@ pub async fn pubkey_event_can_solve( ) -> bool { let sender_pubkey = ev_pubkey.to_string(); - // Is mostro admin taking dispute? - info!( - "admin pubkey {} -event pubkey {} ", - my_keys.public_key().to_string(), - sender_pubkey - ); + // Is mostro admin taking dispute? No keys in the log line — admin/event + // pubkeys (AGENTS.md:48). + info!("Checking whether the dispute event was sent by the mostro admin"); if sender_pubkey == my_keys.public_key().to_string() && matches!(status, DisputeStatus::InProgress | DisputeStatus::Initiated) { @@ -192,7 +189,8 @@ pub async fn admin_take_dispute_action( dispute.solver_pubkey = Some(event.identity.to_string()); dispute.taken_at = Timestamp::now().as_secs() as i64; - info!("Dispute {} taken by {}", dispute.id, event.identity); + // No key in the log line — solver identity (AGENTS.md:48). + info!("Dispute {} taken by a solver", dispute.id); // Save it to DB dispute diff --git a/src/app/bond/payout.rs b/src/app/bond/payout.rs index def5859d..f82102ec 100644 --- a/src/app/bond/payout.rs +++ b/src/app/bond/payout.rs @@ -454,11 +454,11 @@ async fn request_payout_invoice( return Ok(()); } + // No key in the log fields — recipient pubkey (AGENTS.md:48). info!( bond_id = %bond.id, order_id = %bond.order_id, amount_sats = counterparty_share, - recipient = %recipient_pubkey, slashed_at, attempt = bond.invoice_request_attempts + 1, "bond payout: requesting invoice from counterparty" @@ -1349,18 +1349,18 @@ pub async fn add_bond_invoice_action( match apply_payout_invoice(pool, &bond, &payment_request, now, claim_window_seconds).await? { InvoiceApplyOutcome::Persisted => { + // No key in the log fields — sender pubkey (AGENTS.md:48). info!( bond_id = %bond.id, order_id = %bond.order_id, - sender = %sender, "bond payout: invoice accepted; awaiting scheduler tick for payout" ); } InvoiceApplyOutcome::Resurrected => { + // No key in the log fields — sender pubkey (AGENTS.md:48). info!( bond_id = %bond.id, order_id = %bond.order_id, - sender = %sender, "bond payout: Failed -> PendingPayout (user submitted fresh invoice within claim window); payout_attempts reset, awaiting scheduler tick for payout" ); } diff --git a/src/app/cancel.rs b/src/app/cancel.rs index d5ab8631..eb3d42b1 100644 --- a/src/app/cancel.rs +++ b/src/app/cancel.rs @@ -216,7 +216,6 @@ async fn cancel_order_by_taker( my_keys: &Keys, request_id: Option, ln_client: &mut L, - taker_pubkey: PublicKey, ) -> Result<(), MostroError> { let order_id = order.id; let sender_str = event.sender.to_string(); @@ -263,16 +262,7 @@ async fn cancel_order_by_taker( // No surviving bonds: run the full reset-and-republish path so // the order goes back into the book exactly as before. - cancel_order_by_taker_inner( - pool, - event, - order, - my_keys, - request_id, - ln_client, - taker_pubkey, - ) - .await + cancel_order_by_taker_inner(pool, event, order, my_keys, request_id, ln_client).await } async fn cancel_order_by_taker_inner( @@ -282,7 +272,6 @@ async fn cancel_order_by_taker_inner( my_keys: &Keys, request_id: Option, ln_client: &mut L, - taker_pubkey: PublicKey, ) -> Result<(), MostroError> { // Cancel hold invoice if present if let Some(hash) = &order.hash { @@ -318,10 +307,8 @@ async fn cancel_order_by_taker_inner( .await .map_err(|e| MostroInternalErr(ServiceError::NostrError(e.to_string())))?; - info!( - "{}: Canceled order Id {} republishing order", - taker_pubkey, order.id - ); + // No key in the log line — taker pubkey (AGENTS.md:48). + info!("Canceled order Id {} republishing order", order.id); // Notify the creator about the republished order after the taker-side cancellation flow completes notify_creator(&order_updated, request_id).await?; @@ -551,16 +538,7 @@ async fn cancel_action_generic( .as_deref() .is_some_and(|p| p == sender_str && p != order.creator_pubkey); if bond_match || order_taker_match { - cancel_order_by_taker( - pool, - event, - order, - my_keys, - request_id, - ln_client, - event.sender, - ) - .await?; + cancel_order_by_taker(pool, event, order, my_keys, request_id, ln_client).await?; return Ok(()); } return Err(MostroCantDo(CantDoReason::IsNotYourOrder)); @@ -672,16 +650,7 @@ async fn cancel_not_active_order( ) .await?; } else if event.sender == taker_pubkey { - cancel_order_by_taker( - pool, - event, - order, - my_keys, - request_id, - ln_client, - taker_pubkey, - ) - .await?; + cancel_order_by_taker(pool, event, order, my_keys, request_id, ln_client).await?; } else { return Err(MostroCantDo(CantDoReason::InvalidPubkey)); } diff --git a/src/app/last_trade_index.rs b/src/app/last_trade_index.rs index eda69e68..7007d4d7 100644 --- a/src/app/last_trade_index.rs +++ b/src/app/last_trade_index.rs @@ -82,11 +82,9 @@ pub async fn last_trade_index( .as_json() .map_err(|_| MostroError::MostroInternalErr(ServiceError::MessageSerializationError))?; - // Print the last trade index message - tracing::info!( - "User with pubkey: {} requested last trade index", - user.pubkey - ); + // Print the last trade index message. No key in the log line — user + // pubkey (AGENTS.md:48). + tracing::info!("User requested last trade index"); tracing::info!("Last trade index: {}", user.last_trade_index); // Send message back to the requester diff --git a/src/db.rs b/src/db.rs index 3bbdb57e..f5aa45a3 100644 --- a/src/db.rs +++ b/src/db.rs @@ -1254,11 +1254,8 @@ pub async fn is_assigned_solver( solver_pubkey: &str, order_id: Uuid, ) -> Result { - tracing::info!( - "Solver_pubkey: {} assigned to order {}", - solver_pubkey, - order_id - ); + // No key in the log line — solver pubkey (AGENTS.md:48). + tracing::info!("Solver assigned to order {}", order_id); let result = sqlx::query( "SELECT EXISTS(SELECT 1 FROM disputes WHERE solver_pubkey = ? AND order_id = ?)", ) diff --git a/src/rpc/service.rs b/src/rpc/service.rs index fb2b6748..d08b01c9 100644 --- a/src/rpc/service.rs +++ b/src/rpc/service.rs @@ -318,10 +318,8 @@ impl AdminService for AdminServiceImpl { request: Request, ) -> Result, Status> { let req = request.into_inner(); - info!( - "Received add solver request for pubkey: {}", - req.solver_pubkey - ); + // No key in the log line — solver pubkey (AGENTS.md:48). + info!("Received add solver request"); match self .call_admin_add_solver(req.solver_pubkey, req.request_id) diff --git a/src/scheduler.rs b/src/scheduler.rs index b28e3ba4..8cdad003 100644 --- a/src/scheduler.rs +++ b/src/scheduler.rs @@ -299,10 +299,9 @@ async fn notify_users_canceled_order( } }; + // No keys in the log line — maker/taker pubkeys (AGENTS.md:48). tracing::info!( - "Notifying maker {} that taker {} canceled the order {}", - maker_pubkey.to_string(), - taker_pubkey.to_string(), + "Notifying maker and taker that order {} was canceled", old_order.id ); @@ -519,7 +518,6 @@ async fn job_cancel_orders(ctx: AppContext) { // Get edited order to use for update_order_event let edited_order = if let Ok(edited_order) = edited_order { - println!("Edited order: {:?}", edited_order); edited_order } else { tracing::warn!("Error editing pubkeys in order {} cancel", order.id); diff --git a/src/util.rs b/src/util.rs index b590c04c..b7f636fe 100644 --- a/src/util.rs +++ b/src/util.rs @@ -657,11 +657,11 @@ pub async fn send_dm( payload: &str, expiration: Option, ) -> Result<(), MostroError> { - info!( - "sender key {} - receiver key {}", - sender_keys.public_key().to_hex(), - receiver_pubkey.to_hex() - ); + // No keys in the log line — sender/receiver pubkeys (AGENTS.md:48). This + // is the highest-frequency send path in the daemon (every outbound + // protocol message), so it's also the highest-blast-radius instance of + // this pattern. + info!("Sending DM"); let mut message = Message::from_json(payload) .map_err(|_| MostroInternalErr(ServiceError::MessageSerializationError))?; @@ -704,12 +704,9 @@ pub async fn send_dm( ) .await?; - info!( - "Sending message, Event ID: {} to {} with payload: {:#?}", - event.id, - receiver_pubkey.to_hex(), - payload - ); + // No key in the log line — payload can carry a Nostr pubkey (e.g. + // Payload::Peer sent by admin_take_dispute_action) (AGENTS.md:48). + info!("Sending message, Event ID: {}", event.id); if let Ok(client) = get_nostr_client() { client