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,146 @@
+#!/usr/bin/env python3
+"""CI gate for AGENTS.md's Security & Configuration Tips ("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 2021 captured identifiers in a format string, e.g. `"pubkey {pubkey}"`.
+# Only bare identifiers are captures (`{}`/`{:?}`/`{0}` are positional/empty
+# and can't name a variable), and `{{`/`}}` are the escaped-brace literals —
+# excluded so `"{{not_a_capture}}"` isn't misread as one.
+FORMAT_CAPTURE_RE = re.compile(r"(?<!\{)\{([A-Za-z_]\w*)(?::[^}]*)?\}(?!\})")
+
+# 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, str]:
+    """Return (index just past the delimiter matching `text[open_delim]`,
+    the call's source with string-literal *contents* blanked out, and the
+    format captures pulled from those strings before blanking). 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. But a Rust 2021 captured identifier (`"pubkey {pubkey}"`) IS
+    an interpolated argument living inside that same string, so its capture
+    names are extracted first and returned alongside, not lost to blanking.
+    """
+    open_ch = text[open_delim]
+    close_ch = DELIMITER_PAIRS[open_ch]
+    depth = 0
+    i = open_delim
+    n = len(text)
+    out = []
+    captures = []
+    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
+            literal = text[start:i]
+            captures.extend(m.group(1) for m in FORMAT_CAPTURE_RE.finditer(literal))
+            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), " ".join(captures)
+        i += 1
+    return n, "".join(out), " ".join(captures)  # 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, captures = find_call_span(text, open_delim)
+        found = SUSPICIOUS_RE.search(code_only) or SUSPICIOUS_RE.search(captures)
+        if not found:
+            continue
+        previous_line = line_before(text, m.start()).lstrip()
+        if previous_line.startswith(f"// {ALLOW_COMMENT}"):
+            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, Security & "
+                f"Configuration Tips). 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,105 @@
+#!/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_inline_capture_flags_pubkey(self):
+        # Rust 2021 captured identifiers live inside the string literal
+        # itself — the checker must pull them out before blanking, not lose
+        # them along with the surrounding prose.
+        violations = self._violations(
+            'fn x(pubkey: &str) { tracing::info!("User with pubkey {pubkey} did X"); }'
+        )
+        self.assertEqual(violations, [(1, "pubkey")])
+
+    def test_inline_capture_with_format_spec_flags_pubkey(self):
+        violations = self._violations(
+            'fn x(pubkey: &str) { info!("pubkey={pubkey:?}"); }'
+        )
+        self.assertEqual(violations, [(1, "pubkey")])
+
+    def test_positional_placeholder_is_not_a_capture(self):
+        violations = self._violations('fn x() { info!("{} {:?}", pubkey, 1); }')
+        self.assertEqual(violations, [(1, "pubkey")])
+
+    def test_escaped_braces_are_not_a_capture(self):
+        violations = self._violations('fn x() { info!("{{pubkey}}"); }')
+        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, [])
+
+    def test_allow_marker_inside_string_literal_does_not_exempt(self):
+        # The marker must sit in an actual `//` comment on the line above —
+        # not just appear anywhere on that line, e.g. inside another string.
+        violations = self._violations(
+            "fn x() {\n"
+            'let note = "pubkey-log-allow: not a real exemption";\n'
+            'info!("{}", pubkey);\n'
+            "}"
+        )
+        self.assertEqual(violations, [(3, "pubkey")])
+
+
+if __name__ == "__main__":
+    unittest.main()

src/app.rs

@@ -341,9 +341,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, Security & Configuration Tips).
                 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;
@@ -386,11 +386,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, Security & Configuration Tips).
+        tracing::warn!("Missing inner signature: identity differs from trade key");
         return None;
     }
 

src/app/admin_add_solver.rs

@@ -70,7 +70,8 @@ pub async fn admin_add_solver_action(
     let user = User::new(public_key.to_string(), 0, 1, 0, category, trade_index);
 
     match add_new_user(pool, user).await {
-        Ok(r) => info!("Solver added: {} with category {}", r, category),
+        // No key in the log line — solver pubkey (AGENTS.md, Security & Configuration Tips).
+        Ok(_) => info!("Solver added with category {}", category),
         Err(ee) => {
             error!("Error creating solver: {:#?}", ee);
             return Err(MostroInternalErr(ServiceError::DbAccessError(

src/app/admin_cancel.rs

@@ -151,8 +151,9 @@ pub async fn admin_cancel_action(
         let event = new_dispute_event(my_keys, "", dispute_id.to_string(), tags)
             .map_err(|e| MostroInternalErr(ServiceError::NostrError(e.to_string())))?;
 
-        // Publish dispute event with update
-        info!("Dispute event to be published: {event:#?}");
+        // Publish dispute event with update. No full event dump — it carries
+        // the pubkey, tags and content in clear (AGENTS.md, Security & Configuration Tips).
+        info!("Dispute event to be published for dispute {dispute_id}");
 
         let client = ctx.nostr_client();
         if let Err(e) = client.send_event(&event).await {

src/app/admin_settle.rs

@@ -150,8 +150,9 @@ pub async fn admin_settle_action(
         let event = new_dispute_event(my_keys, "", dispute_id.to_string(), tags)
             .map_err(|e| MostroInternalErr(ServiceError::NostrError(e.to_string())))?;
 
-        // Print event dispute with update
-        tracing::info!("Dispute event to be published: {event:#?}");
+        // No full event dump — it carries the pubkey, tags and content in
+        // clear (AGENTS.md, Security & Configuration Tips).
+        tracing::info!("Dispute event to be published for dispute {dispute_id}");
 
         let client = ctx.nostr_client();
         if let Err(e) = client.send_event(&event).await {

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, Security & Configuration Tips).
+    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, Security & Configuration Tips).
+    info!("Dispute {} taken by a solver", dispute.id);
 
     // Save it to DB
     dispute
@@ -272,7 +270,9 @@ pub async fn admin_take_dispute_action(
     // nip33 kind with dispute id as identifier (kind 38386 for disputes)
     let event = new_dispute_event(mostro_keys, "", dispute.id.to_string(), tags)
         .map_err(|e| MostroInternalErr(ServiceError::NostrError(e.to_string())))?;
-    info!("Dispute event to be published: {event:#?}");
+    // No full event dump — it carries the pubkey, tags and content in clear
+    // (AGENTS.md, Security & Configuration Tips).
+    info!("Dispute event to be published for dispute {}", dispute.id);
 
     let client = ctx.nostr_client();
     client