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:
parent
e97d8a75f0
commit
21c522ba99
1 changed files with 75 additions and 1 deletions
|
|
@ -44,6 +44,26 @@ const PAIRING_TIMEOUT: Duration = Duration::from_secs(300);
|
||||||
/// App name advertised to signers during client-initiated pairing.
|
/// App name advertised to signers during client-initiated pairing.
|
||||||
const APP_NAME: &str = "Keynectr";
|
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.
|
/// Internal state for a pending approval.
|
||||||
struct PendingApprovalInner {
|
struct PendingApprovalInner {
|
||||||
method: String,
|
method: String,
|
||||||
|
|
@ -468,6 +488,13 @@ impl Nip46ClientSigner {
|
||||||
"No usable relays are configured, so there is nowhere to pair over.",
|
"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,
|
// Ephemeral session keys: the URI authority is this throwaway key,
|
||||||
// never a profile key. The secret proves WE are the app the user
|
// never a profile key. The secret proves WE are the app the user
|
||||||
|
|
@ -494,6 +521,17 @@ impl Nip46ClientSigner {
|
||||||
));
|
));
|
||||||
}
|
}
|
||||||
inner.phase = Nip46Phase::Connecting;
|
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 signer = self.clone();
|
||||||
let task = tokio::spawn(async move {
|
let task = tokio::spawn(async move {
|
||||||
if let Err(e) = signer
|
if let Err(e) = signer
|
||||||
|
|
@ -519,6 +557,12 @@ impl Nip46ClientSigner {
|
||||||
secret: String,
|
secret: String,
|
||||||
label: String,
|
label: String,
|
||||||
) -> Result<(), 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()
|
let client = Client::builder()
|
||||||
.authenticator(SignerAuthenticator::new(keys.clone()))
|
.authenticator(SignerAuthenticator::new(keys.clone()))
|
||||||
.build();
|
.build();
|
||||||
|
|
@ -588,7 +632,9 @@ impl Nip46ClientSigner {
|
||||||
);
|
);
|
||||||
// Local-only debug capture (never leaves this machine): keep the
|
// Local-only debug capture (never leaves this machine): keep the
|
||||||
// full event so a failed handshake can be dissected offline.
|
// 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 =
|
let path =
|
||||||
std::path::Path::new("/home/avi/Tools/keynctr-debug/pairing-capture.jsonl");
|
std::path::Path::new("/home/avi/Tools/keynctr-debug/pairing-capture.jsonl");
|
||||||
if let Some(dir) = path.parent() {
|
if let Some(dir) = path.parent() {
|
||||||
|
|
@ -602,6 +648,11 @@ impl Nip46ClientSigner {
|
||||||
use std::io::Write;
|
use std::io::Write;
|
||||||
let _ = writeln!(f, "{}", event.as_json());
|
let _ = writeln!(f, "{}", event.as_json());
|
||||||
}
|
}
|
||||||
|
pairing_trace(&format!(
|
||||||
|
"inbound 24133 from {} (content len {})",
|
||||||
|
event.pubkey.to_hex(),
|
||||||
|
event.content.len()
|
||||||
|
));
|
||||||
}
|
}
|
||||||
// Never answer ourselves.
|
// Never answer ourselves.
|
||||||
if event.pubkey == our_pk {
|
if event.pubkey == our_pk {
|
||||||
|
|
@ -623,16 +674,30 @@ impl Nip46ClientSigner {
|
||||||
"[nip46 pairing] payload did not decrypt: {e} (frame {} chars b64)",
|
"[nip46 pairing] payload did not decrypt: {e} (frame {} chars b64)",
|
||||||
event.content.len()
|
event.content.len()
|
||||||
);
|
);
|
||||||
|
if live_capture {
|
||||||
|
pairing_trace(&format!(
|
||||||
|
"payload did not decrypt: {e} (frame {} chars b64)",
|
||||||
|
event.content.len()
|
||||||
|
));
|
||||||
|
}
|
||||||
continue;
|
continue;
|
||||||
}
|
}
|
||||||
};
|
};
|
||||||
let Ok(request) = serde_json::from_str::<RawRequest>(&plain) else {
|
let Ok(request) = serde_json::from_str::<RawRequest>(&plain) else {
|
||||||
eprintln!("[nip46 pairing] decrypted payload is not a NIP-46 request: {plain}");
|
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;
|
continue;
|
||||||
};
|
};
|
||||||
if request.method != "connect" {
|
if request.method != "connect" {
|
||||||
// Anything before the handshake is premature — ignore.
|
// Anything before the handshake is premature — ignore.
|
||||||
eprintln!("[nip46 pairing] pre-handshake '{}' ignored", request.method);
|
eprintln!("[nip46 pairing] pre-handshake '{}' ignored", request.method);
|
||||||
|
if live_capture {
|
||||||
|
pairing_trace(&format!("pre-handshake '{}' ignored", request.method));
|
||||||
|
}
|
||||||
continue;
|
continue;
|
||||||
}
|
}
|
||||||
// NIP-46: the client answers the signer's `connect` with the
|
// 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}"));
|
return Err(format!("Could not answer the connect request: {e}"));
|
||||||
}
|
}
|
||||||
eprintln!("[nip46 pairing] connect answered; awaiting identity handshake");
|
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 —
|
// Optional requested_perms ride in params[1]; parse leniently —
|
||||||
// a malformed grant list degrades to "no local enforcement",
|
// a malformed grant list degrades to "no local enforcement",
|
||||||
// which defers to the signer's own approval prompts.
|
// which defers to the signer's own approval prompts.
|
||||||
|
|
@ -868,6 +936,7 @@ impl Nip46ClientSigner {
|
||||||
fn fail(&self, message: impl Into<String>) {
|
fn fail(&self, message: impl Into<String>) {
|
||||||
let message = message.into();
|
let message = message.into();
|
||||||
eprintln!("[nip46] session failed: {message}");
|
eprintln!("[nip46] session failed: {message}");
|
||||||
|
pairing_trace(&format!("session failed: {message}"));
|
||||||
if let Ok(mut inner) = self.inner.try_lock() {
|
if let Ok(mut inner) = self.inner.try_lock() {
|
||||||
inner.phase = Nip46Phase::Error(message);
|
inner.phase = Nip46Phase::Error(message);
|
||||||
inner.task = None;
|
inner.task = None;
|
||||||
|
|
@ -1606,6 +1675,11 @@ impl Nip46ClientSigner {
|
||||||
conn.profile_npub = Some(identity_npub.clone());
|
conn.profile_npub = Some(identity_npub.clone());
|
||||||
}
|
}
|
||||||
inner.phase = Nip46Phase::Connected;
|
inner.phase = Nip46Phase::Connected;
|
||||||
|
pairing_trace(&format!(
|
||||||
|
"identity adopted: npub={} peer={} — CONNECTED",
|
||||||
|
identity_npub,
|
||||||
|
peer.to_hex()
|
||||||
|
));
|
||||||
drop(inner);
|
drop(inner);
|
||||||
|
|
||||||
// Background enrichment (post-Connected by design): look up the
|
// Background enrichment (post-Connected by design): look up the
|
||||||
|
|
|
||||||
Loading…
Add table
Add a link
Reference in a new issue