From 7fde050a00b1ca82d378199bfd129d9e496acbd1 Mon Sep 17 00:00:00 2001 From: thePR0M3TH3AN <53631862+PR0M3TH3AN@users.noreply.github.com> Date: Wed, 22 Oct 2025 09:46:17 -0400 Subject: [PATCH] Add detailed dev logging for NIP-46 handshake flow --- js/nostr.js | 165 +++++++++++++++++++++++++++++ js/services/authProviders/nip46.js | 72 +++++++++++++ 2 files changed, 237 insertions(+) diff --git a/js/nostr.js b/js/nostr.js index a5dba67a..0d555ccb 100644 --- a/js/nostr.js +++ b/js/nostr.js @@ -4194,6 +4194,35 @@ async function decryptNip46PayloadWithKeys(privateKey, remotePubkey, ciphertext) throw failure; } +function summarizeHexForLog(value) { + if (typeof value !== "string" || !value.trim()) { + return ""; + } + + const normalized = value.trim().toLowerCase(); + if (normalized.length <= 12) { + return `${normalized} (len:${normalized.length})`; + } + return `${normalized.slice(0, 8)}…${normalized.slice(-4)} (len:${normalized.length})`; +} + +function summarizeSecretForLog(value) { + if (typeof value !== "string" || !value.trim()) { + return ""; + } + + const trimmed = value.trim(); + const visible = trimmed.length <= 4 ? "*".repeat(trimmed.length) : `${"*".repeat(3)}…`; + return `${visible} (len:${trimmed.length})`; +} + +function summarizeMetadataForLog(metadata) { + if (!metadata || typeof metadata !== "object") { + return []; + } + return Object.keys(metadata).slice(0, 12); +} + async function attemptDecryptNip46HandshakePayload({ clientPrivateKey, candidateRemotePubkeys = [], @@ -4208,14 +4237,26 @@ async function attemptDecryptNip46HandshakePayload({ continue; } seen.add(normalized); + devLogger.debug("[nostr] Handshake decrypt attempt", { + remotePubkey: summarizeHexForLog(normalized), + ciphertextLength: typeof ciphertext === "string" ? ciphertext.length : 0, + }); try { const result = await decryptNip46PayloadWithKeys( clientPrivateKey, normalized, ciphertext, ); + devLogger.debug("[nostr] Handshake decrypt succeeded", { + remotePubkey: summarizeHexForLog(normalized), + algorithm: result?.algorithm || null, + }); return { ...result, remotePubkey: normalized }; } catch (error) { + devLogger.debug("[nostr] Handshake decrypt failed for candidate", { + remotePubkey: summarizeHexForLog(normalized), + error: error?.message || error, + }); tried.push({ remotePubkey: normalized, error }); } } @@ -4224,6 +4265,12 @@ async function attemptDecryptNip46HandshakePayload({ "Failed to decrypt remote signer handshake payload with provided keys.", ); failure.attempts = tried; + devLogger.warn("[nostr] Exhausted handshake decrypt candidates", { + attempts: tried.map((entry) => ({ + remotePubkey: summarizeHexForLog(entry.remotePubkey), + error: entry.error?.message || entry.error, + })), + }); throw failure; } @@ -5440,6 +5487,14 @@ export class NostrClient { const handshakeSecret = typeof secret === "string" && secret.trim() ? secret.trim() : generateNip46Secret(); + devLogger.debug("[nostr] Preparing remote signer handshake", { + clientPublicKey: summarizeHexForLog(keyPair.publicKey), + relays: resolvedRelays, + permissions: requestedPermissions || null, + secret: summarizeSecretForLog(handshakeSecret), + metadataKeys: summarizeMetadataForLog(sanitizedMetadata), + }); + const params = []; for (const relay of resolvedRelays) { params.push(`relay=${encodeURIComponent(relay)}`); @@ -5457,6 +5512,12 @@ export class NostrClient { const query = params.length ? `?${params.join("&")}` : ""; const uri = `nostrconnect://${keyPair.publicKey}${query}`; + devLogger.debug("[nostr] Prepared nostrconnect URI", { + uri, + relayCount: resolvedRelays.length, + metadataKeys: summarizeMetadataForLog(sanitizedMetadata), + }); + return { type: "client", connectionString: uri, @@ -5516,6 +5577,14 @@ export class NostrClient { throw new Error("No relays available to complete the remote signer handshake."); } + devLogger.debug("[nostr] Waiting for remote signer handshake", { + clientPubkey: summarizeHexForLog(normalizedClientPublicKey), + relays: resolvedRelays, + secret: summarizeSecretForLog(secret), + timeoutMs: Number.isFinite(timeoutMs) ? timeoutMs : undefined, + expectedRemotePubkey: summarizeHexForLog(expectedRemotePubkey || ""), + }); + const pool = await this.ensurePool(); const filters = [ { @@ -5590,14 +5659,23 @@ export class NostrClient { cleanup(); const error = new Error("Timed out waiting for the remote signer to acknowledge the connection."); error.code = "nip46-handshake-timeout"; + devLogger.warn("[nostr] Handshake wait timed out", { + clientPubkey: summarizeHexForLog(normalizedClientPublicKey), + relays: resolvedRelays, + }); reject(error); }, waitTimeout); let subscription; try { subscription = pool.sub(resolvedRelays, filters); + devLogger.debug("[nostr] Handshake subscription established", { + relays: resolvedRelays, + filters, + }); } catch (error) { cleanup(); + devLogger.warn("[nostr] Failed to subscribe for handshake responses", error); reject(error); return; } @@ -5608,6 +5686,7 @@ export class NostrClient { } if (!event || event.kind !== NIP46_RPC_KIND) { + devLogger.debug("[nostr] Ignoring non-handshake event during wait", event); return; } @@ -5620,6 +5699,15 @@ export class NostrClient { candidateRemotePubkeys.push(eventRemotePubkey); } + devLogger.debug("[nostr] Processing handshake event", { + eventId: typeof event.id === "string" ? event.id : "", + eventPubkey: summarizeHexForLog(eventRemotePubkey || ""), + candidateRemotePubkeys: candidateRemotePubkeys.map((key) => + summarizeHexForLog(key), + ), + contentLength: typeof event.content === "string" ? event.content.length : 0, + }); + Promise.resolve() .then(() => attemptDecryptNip46HandshakePayload({ @@ -5638,6 +5726,15 @@ export class NostrClient { return; } + devLogger.debug("[nostr] Handshake payload parsed", { + remotePubkey: summarizeHexForLog(payloadResult?.remotePubkey || ""), + eventPubkey: summarizeHexForLog(eventRemotePubkey || ""), + algorithm: payloadResult?.algorithm || null, + requestId: typeof parsed?.id === "string" ? parsed.id : "", + hasResult: parsed?.result !== undefined, + hasError: parsed?.error !== undefined, + }); + const resultValue = coerceStructuredString(parsed?.result); const errorValue = coerceStructuredString(parsed?.error); @@ -5690,6 +5787,13 @@ export class NostrClient { response: parsed, algorithm: normalizeNip46EncryptionAlgorithm(payloadResult?.algorithm), }); + + devLogger.debug("[nostr] Handshake wait resolved", { + remotePubkey: summarizeHexForLog(payloadResult?.remotePubkey || eventRemotePubkey || ""), + eventPubkey: summarizeHexForLog(eventRemotePubkey || ""), + result: resultValue || null, + hasSecret: Boolean(secret), + }); }) .catch((error) => { devLogger.warn("[nostr] Failed to decrypt remote signer handshake payload:", error); @@ -5728,6 +5832,21 @@ export class NostrClient { const overrideMetadata = sanitizeNip46Metadata(providedMetadata); const metadata = { ...baseMetadata, ...overrideMetadata }; + devLogger.debug("[nostr] Connecting to remote signer", { + connectionType: parsed.type, + parsedRemotePubkey: summarizeHexForLog(parsed.remotePubkey || ""), + providedClientPublicKey: summarizeHexForLog(providedClientPublicKey), + providedClientPrivateKey: summarizeSecretForLog( + typeof providedClientPrivateKey === "string" ? providedClientPrivateKey : "", + ), + providedSecret: summarizeSecretForLog(providedSecret), + providedPermissions: providedPermissions || null, + handshakeTimeoutMs, + parsedRelays: parsed.relays, + overrideRelayCount: Array.isArray(providedRelays) ? providedRelays.length : 0, + metadataKeys: summarizeMetadataForLog(metadata), + }); + const handleStatus = (status) => { if (typeof onStatus !== "function") { return; @@ -5895,9 +6014,24 @@ export class NostrClient { encryption: handshakeAlgorithm, }); + devLogger.debug("[nostr] Remote signer RPC client created", { + clientPublicKey: summarizeHexForLog(client.clientPublicKey), + remotePubkey: summarizeHexForLog(remotePubkey), + relays, + permissions, + secret: summarizeSecretForLog(secret), + metadataKeys: summarizeMetadataForLog(metadata), + handshakeAlgorithm, + }); + try { await client.ensureSubscription(); + devLogger.debug("[nostr] Remote signer subscription ready", { + remotePubkey: summarizeHexForLog(remotePubkey), + relayCount: relays.length, + }); + handleStatus({ phase: "connect", state: "request", @@ -5909,9 +6043,20 @@ export class NostrClient { // Attempt the connect RPC, handling auth challenges when provided. for (;;) { try { + devLogger.debug("[nostr] Sending NIP-46 connect request", { + remotePubkey: summarizeHexForLog(remotePubkey), + attempt: attempts + 1, + permissions: permissions || null, + }); await client.connect({ permissions }); break; } catch (error) { + devLogger.warn("[nostr] Connect RPC attempt failed", { + remotePubkey: summarizeHexForLog(remotePubkey), + attempt: attempts + 1, + code: error?.code || null, + message: error?.message || String(error), + }); if (error?.code === "auth-challenge" && error.authUrl) { attempts += 1; handleStatus({ @@ -5937,6 +6082,10 @@ export class NostrClient { } const userPubkey = await client.getUserPubkey(); + devLogger.debug("[nostr] Retrieved user pubkey from remote signer", { + remotePubkey: summarizeHexForLog(remotePubkey), + userPubkey: summarizeHexForLog(userPubkey), + }); client.metadata = metadata; const signer = this.installNip46Client(client, { userPubkey }); @@ -5974,8 +6123,24 @@ export class NostrClient { userPubkey, }); + devLogger.debug("[nostr] Remote signer connection established", { + remotePubkey: summarizeHexForLog(remotePubkey), + userPubkey: summarizeHexForLog(userPubkey), + relays, + permissions: permissions || null, + secret: summarizeSecretForLog(secret), + }); + return { pubkey: userPubkey, signer }; } catch (error) { + devLogger.error("[nostr] Remote signer connection failed", { + remotePubkey: summarizeHexForLog(remotePubkey), + relays, + permissions: permissions || null, + secret: summarizeSecretForLog(secret), + message: error?.message || String(error), + code: error?.code || null, + }); await client.destroy().catch(() => {}); this.nip46Client = null; if (!remember) { diff --git a/js/services/authProviders/nip46.js b/js/services/authProviders/nip46.js index badaa808..091a830a 100644 --- a/js/services/authProviders/nip46.js +++ b/js/services/authProviders/nip46.js @@ -1,5 +1,35 @@ import { devLogger } from "../../utils/logger.js"; +function summarizeHexForLog(value) { + if (typeof value !== "string" || !value.trim()) { + return ""; + } + + const normalized = value.trim().toLowerCase(); + if (normalized.length <= 12) { + return `${normalized} (len:${normalized.length})`; + } + return `${normalized.slice(0, 8)}…${normalized.slice(-4)} (len:${normalized.length})`; +} + +function summarizeSecretForLog(value) { + if (typeof value !== "string" || !value.trim()) { + return ""; + } + + const trimmed = value.trim(); + const visible = trimmed.length <= 4 ? "*".repeat(trimmed.length) : `${"*".repeat(3)}…`; + return `${visible} (len:${trimmed.length})`; +} + +function sanitizeNip46UriForLog(value) { + if (typeof value !== "string" || !value) { + return ""; + } + + return value.replace(/(secret=)([^&#]+)/gi, "$1***"); +} + const PROVIDER_ID = "nip46"; const PROVIDER_LABEL = "remote signer (nip-46)"; const PROVIDER_DESCRIPTION = @@ -112,6 +142,16 @@ export default { } const normalized = normalizeOptions(options); + + devLogger.debug("[nip46] Login requested", { + mode: normalized.mode, + reuseStored: normalized.reuseStored, + remember: normalized.remember, + hasConnectionString: Boolean(normalized.connectionString), + relayCount: normalized.relays.length, + permissions: normalized.permissions || null, + secret: summarizeSecretForLog(normalized.secret), + }); let result = null; if (normalized.reuseStored) { @@ -120,8 +160,12 @@ export default { error.code = "no-stored-session"; throw error; } + devLogger.debug("[nip46] Reusing stored remote signer session"); result = await nostrClient.useStoredRemoteSigner(); + devLogger.debug("[nip46] Stored remote signer returned", { + pubkey: summarizeHexForLog(normalizePubkey(result)), + }); } else if (normalized.mode === "manual") { const uri = normalized.connectionString; if (!uri) { @@ -130,12 +174,20 @@ export default { throw error; } + devLogger.debug("[nip46] Initiating manual remote signer connect", { + uri: sanitizeNip46UriForLog(uri), + remember: normalized.remember, + }); + result = await nostrClient.connectRemoteSigner({ connectionString: uri, remember: normalized.remember, onAuthUrl: normalized.onAuthUrl, onStatus: normalized.onStatus, }); + devLogger.debug("[nip46] Manual connect completed", { + pubkey: summarizeHexForLog(normalizePubkey(result)), + }); } else { if (normalized.onStatus) { try { @@ -156,6 +208,15 @@ export default { permissions: normalized.permissions, }); + devLogger.debug("[nip46] Prepared remote signer handshake", { + relays: Array.isArray(handshake.relays) ? handshake.relays : [], + permissions: handshake.permissions || null, + clientPublicKey: summarizeHexForLog(handshake.clientPublicKey), + secret: summarizeSecretForLog(handshake.secret), + metadataKeys: Object.keys(handshake.metadata || {}), + connectionString: sanitizeNip46UriForLog(handshake.connectionString), + }); + if (normalized.onHandshakePrepared) { try { normalized.onHandshakePrepared(handshake); @@ -164,6 +225,12 @@ export default { } } + devLogger.debug("[nip46] Connecting to remote signer with prepared handshake", { + remember: normalized.remember, + handshakeAlgorithm: handshake.algorithm || null, + connectionString: sanitizeNip46UriForLog(handshake.connectionString), + }); + result = await nostrClient.connectRemoteSigner({ connectionString: handshake.connectionString, remember: normalized.remember, @@ -185,6 +252,11 @@ export default { const pubkey = normalizePubkey(result); + devLogger.debug("[nip46] Login finished", { + pubkey: summarizeHexForLog(pubkey), + hasSigner: Boolean(result && typeof result === "object" && result.signer), + }); + return { authType: PROVIDER_ID, pubkey,