chore(pairing): durable trace log + keep e2e loopback traffic out of forensics files

The Sep 16 forensics file pairing-capture.jsonl turned out to be
polluted: the e2e harness pairs over loopback relays but its fake
scanner events were appended to the same file (lines 6-7 from today's
test runs). Now loopback pairings skip both the capture file and the
new pairing-trace.log.

pairing-trace.log records the full pairing outcome at every decision
point (started, inbound, decrypt-fail, not-a-request, pre-handshake,
connect answered, identity adopted, session failed) with timestamps,
because backend stderr only reaches the Electron console and /tmp logs
get cleaned — a failed live handshake previously left no durable trace.

Release binary rebuilt at this commit.
This commit is contained in:
Avi 2026-09-18 21:00:31 -05:00
commit 21c522ba99

View file

@ -44,6 +44,26 @@ const PAIRING_TIMEOUT: Duration = Duration::from_secs(300);
/// App name advertised to signers during client-initiated pairing.
const APP_NAME: &str = "Keynectr";
/// Append a line to the local pairing trace log so a failed handshake
/// survives the session: backend stderr reaches the dev console only, and
/// nothing else (logs, vault) records why pairing stopped. Local-only debug
/// surface — this file never leaves the machine.
fn pairing_trace(msg: &str) {
let path = std::path::Path::new("/home/avi/Tools/keynctr-debug/pairing-trace.log");
if let Some(dir) = path.parent() {
let _ = std::fs::create_dir_all(dir);
}
if let Ok(mut f) = std::fs::OpenOptions::new()
.create(true)
.append(true)
.open(path)
{
use std::io::Write;
let now = crate::vault::unix_timestamp().unwrap_or(0);
let _ = writeln!(f, "[{now}] {msg}");
}
}
/// Internal state for a pending approval.
struct PendingApprovalInner {
method: String,
@ -468,6 +488,13 @@ impl Nip46ClientSigner {
"No usable relays are configured, so there is nowhere to pair over.",
));
}
// Loopback-only relay sets belong to the e2e harness: their fake
// scanner events must never pollute the real pairing capture/trace
// files used to dissect live signer handshakes.
let live_capture = relays.iter().any(|r| {
let u = r.to_string().to_lowercase();
!(u.contains("127.0.0.1") || u.contains("localhost") || u.contains("[::1]"))
});
// Ephemeral session keys: the URI authority is this throwaway key,
// never a profile key. The secret proves WE are the app the user
@ -494,6 +521,17 @@ impl Nip46ClientSigner {
));
}
inner.phase = Nip46Phase::Connecting;
if live_capture {
pairing_trace(&format!(
"pairing started: ephemeral={} relays={}",
keys.public_key().to_hex(),
relays
.iter()
.map(|r| r.to_string())
.collect::<Vec<_>>()
.join(",")
));
}
let signer = self.clone();
let task = tokio::spawn(async move {
if let Err(e) = signer
@ -519,6 +557,12 @@ impl Nip46ClientSigner {
secret: String,
label: String,
) -> Result<(), String> {
// The e2e harness pairs over loopback relays only; its fake-scanner
// events must not pollute the real pairing forensics files.
let live_capture = relays.iter().any(|r| {
let u = r.to_string().to_lowercase();
!(u.contains("127.0.0.1") || u.contains("localhost") || u.contains("[::1]"))
});
let client = Client::builder()
.authenticator(SignerAuthenticator::new(keys.clone()))
.build();
@ -588,7 +632,9 @@ impl Nip46ClientSigner {
);
// Local-only debug capture (never leaves this machine): keep the
// full event so a failed handshake can be dissected offline.
{
// Loopback (e2e harness) pairings are excluded so test traffic
// never pollutes the forensics files.
if live_capture {
let path =
std::path::Path::new("/home/avi/Tools/keynctr-debug/pairing-capture.jsonl");
if let Some(dir) = path.parent() {
@ -602,6 +648,11 @@ impl Nip46ClientSigner {
use std::io::Write;
let _ = writeln!(f, "{}", event.as_json());
}
pairing_trace(&format!(
"inbound 24133 from {} (content len {})",
event.pubkey.to_hex(),
event.content.len()
));
}
// Never answer ourselves.
if event.pubkey == our_pk {
@ -623,16 +674,30 @@ impl Nip46ClientSigner {
"[nip46 pairing] payload did not decrypt: {e} (frame {} chars b64)",
event.content.len()
);
if live_capture {
pairing_trace(&format!(
"payload did not decrypt: {e} (frame {} chars b64)",
event.content.len()
));
}
continue;
}
};
let Ok(request) = serde_json::from_str::<RawRequest>(&plain) else {
eprintln!("[nip46 pairing] decrypted payload is not a NIP-46 request: {plain}");
if live_capture {
pairing_trace(&format!(
"decrypted payload is not a NIP-46 request: {plain}"
));
}
continue;
};
if request.method != "connect" {
// Anything before the handshake is premature — ignore.
eprintln!("[nip46 pairing] pre-handshake '{}' ignored", request.method);
if live_capture {
pairing_trace(&format!("pre-handshake '{}' ignored", request.method));
}
continue;
}
// NIP-46: the client answers the signer's `connect` with the
@ -650,6 +715,9 @@ impl Nip46ClientSigner {
return Err(format!("Could not answer the connect request: {e}"));
}
eprintln!("[nip46 pairing] connect answered; awaiting identity handshake");
if live_capture {
pairing_trace("connect answered; awaiting identity handshake");
}
// Optional requested_perms ride in params[1]; parse leniently —
// a malformed grant list degrades to "no local enforcement",
// which defers to the signer's own approval prompts.
@ -868,6 +936,7 @@ impl Nip46ClientSigner {
fn fail(&self, message: impl Into<String>) {
let message = message.into();
eprintln!("[nip46] session failed: {message}");
pairing_trace(&format!("session failed: {message}"));
if let Ok(mut inner) = self.inner.try_lock() {
inner.phase = Nip46Phase::Error(message);
inner.task = None;
@ -1606,6 +1675,11 @@ impl Nip46ClientSigner {
conn.profile_npub = Some(identity_npub.clone());
}
inner.phase = Nip46Phase::Connected;
pairing_trace(&format!(
"identity adopted: npub={} peer={} — CONNECTED",
identity_npub,
peer.to_hex()
));
drop(inner);
// Background enrichment (post-Connected by design): look up the