fix: scrub Nostr keys from 14 more log lines + add a CI check (#836)

.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

.gitignore

@@ -24,3 +24,5 @@ CLAUDE.md
 # Mutation testing output
 mutants.out/
 mutants.out.old/
+
+__pycache__/

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: <reason>` 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} <reason>` 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())

scripts/check_log_redaction_test.py

@@ -0,0 +1,62 @@
+#!/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(len(violations), 1)
+
+    def test_brace_call_flags_pubkey(self):
+        violations = self._violations("fn x() { trace! {pubkey} }")
+        self.assertEqual(len(violations), 1)
+
+    def test_bracket_call_flags_pubkey(self):
+        violations = self._violations("fn x() { trace![pubkey] }")
+        self.assertEqual(len(violations), 1)
+
+    def test_identity_key_variant_is_flagged(self):
+        violations = self._violations('fn x() { info!("{}", identity_key); }')
+        self.assertEqual(len(violations), 1)
+
+    def test_sender_key_variant_is_flagged(self):
+        violations = self._violations('fn x() { info!("{}", sender_key); }')
+        self.assertEqual(len(violations), 1)
+
+    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()

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;
     }
 

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

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"
             );
         }

src/app/cancel.rs

@@ -216,7 +216,6 @@ async fn cancel_order_by_taker<L: CancelLightning + Send>(
     my_keys: &Keys,
     request_id: Option<u64>,
     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<L: CancelLightning + Send>(
 
     // 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<L: CancelLightning + Send>(
@@ -282,7 +272,6 @@ async fn cancel_order_by_taker_inner<L: CancelLightning + Send>(
     my_keys: &Keys,
     request_id: Option<u64>,
     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<L: CancelLightning + Send>(
         .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<L: CancelLightning + Send>(
                 .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<L: CancelLightning + Send>(
         )
         .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));
     }