From 89986759e09c57c21d8e4dfed09f2f0433d0fd26 Mon Sep 17 00:00:00 2001 From: thePR0M3TH3AN <53631862+PR0M3TH3AN@users.noreply.github.com> Date: Thu, 9 Oct 2025 15:26:51 -0400 Subject: [PATCH 1/5] Short-circuit hex actor keys --- js/nostr.js | 39 +++++++++-- tests/watch-history.test.mjs | 123 +++++++++++++++++++++++++++++------ 2 files changed, 138 insertions(+), 24 deletions(-) diff --git a/js/nostr.js b/js/nostr.js index 7feff552..1ec94372 100644 --- a/js/nostr.js +++ b/js/nostr.js @@ -2323,6 +2323,10 @@ function normalizeActorKey(actor) { return ""; } + if (/^[0-9a-f]{64}$/i.test(trimmed)) { + return trimmed.toLowerCase(); + } + const decodedHex = decodeNpubToHex(trimmed); if (decodedHex) { return decodedHex.toLowerCase(); @@ -2587,23 +2591,48 @@ function cloneEventForCache(event) { } function decodeNpubToHex(npub) { - if (typeof npub !== "string" || !npub.trim()) { + if (typeof npub !== "string") { return ""; } - const tools = getCachedNostrTools(); + const trimmed = npub.trim(); + if (!trimmed) { + return ""; + } + + if (/^[0-9a-f]{64}$/i.test(trimmed)) { + return trimmed.toLowerCase(); + } + + const lower = trimmed.toLowerCase(); + const hasNpubPrefix = lower.startsWith("npub1"); + if (!hasNpubPrefix) { + return ""; + } + + const warnableNpub = /^npub1[023456789acdefghjklmnpqrstuvwxyz]+$/i.test( + trimmed + ); + + let tools = cachedNostrTools; + if (!tools || typeof tools?.nip19?.decode !== "function") { + const fallbackTools = readToolkitFromScope(); + if (fallbackTools) { + tools = fallbackTools; + } + } if (!tools?.nip19 || typeof tools.nip19.decode !== "function") { return ""; } try { - const decoded = tools.nip19.decode(npub.trim()); + const decoded = tools.nip19.decode(trimmed); if (decoded?.type === "npub" && typeof decoded.data === "string") { return decoded.data; } } catch (error) { - if (isDevMode) { - console.warn(`[nostr] Failed to decode npub: ${npub}`, error); + if (isDevMode && warnableNpub) { + console.warn(`[nostr] Failed to decode npub: ${trimmed}`, error); } } return ""; diff --git a/tests/watch-history.test.mjs b/tests/watch-history.test.mjs index 805f755b..f5d3705f 100644 --- a/tests/watch-history.test.mjs +++ b/tests/watch-history.test.mjs @@ -20,6 +20,7 @@ const { const { nostrClient, chunkWatchHistoryPayloadItems, + normalizeActorKey, } = await import("../js/nostr.js"); const { watchHistoryService } = await import("../js/watchHistoryService.js"); const { getApplication, setApplication } = await import( @@ -348,9 +349,86 @@ function maxCreatedAt(events = []) { }, 0); } +async function testNormalizeActorKeyShortCircuit() { + console.log("Running normalizeActorKey short-circuit test..."); + + const actorHex = "f".repeat(64); + const actorNpub = "npub1qqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqq"; + if (!window.NostrTools || typeof window.NostrTools !== "object") { + window.NostrTools = {}; + } + const previousNip19 = window.NostrTools.nip19; + const previousDecode = + previousNip19 && typeof previousNip19.decode === "function" + ? previousNip19.decode + : null; + const decodeCalls = []; + + window.NostrTools.nip19 = { + ...(previousNip19 || {}), + decode(value) { + decodeCalls.push(value); + if (value === actorNpub) { + return { type: "npub", data: actorHex }; + } + if (typeof previousDecode === "function") { + return previousDecode(value); + } + throw new Error("unsupported-npub"); + }, + }; + + const originalWarn = console.warn; + const warnings = []; + console.warn = (...args) => { + warnings.push(args); + }; + + try { + const upperHex = actorHex.toUpperCase(); + const normalizedHex = normalizeActorKey(upperHex); + assert.equal( + normalizedHex, + actorHex, + "hex inputs should normalize to lowercase hex", + ); + assert.equal( + decodeCalls.length, + 0, + "hex inputs should not invoke nip19.decode", + ); + assert.equal( + warnings.length, + 0, + "hex inputs should not emit decode warnings", + ); + + const normalizedNpub = normalizeActorKey(actorNpub); + assert.equal(normalizedNpub, actorHex, "npub inputs should decode to hex"); + assert.equal( + decodeCalls.length, + 1, + "npub inputs should invoke nip19.decode", + ); + assert.equal( + warnings.length, + 0, + "successful npub decode should not emit warnings", + ); + } finally { + console.warn = originalWarn; + if (previousNip19) { + window.NostrTools.nip19 = previousNip19; + } else if (window.NostrTools) { + delete window.NostrTools.nip19; + } + } +} + async function testFetchWatchHistoryExtensionDecryptsHexAndNpub() { const actorHex = "0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef"; - const actorNpub = "npub-test-extension-decrypt"; + const actorNpub = + "npub1testextensiondecryptqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqqq"; const snapshotId = "extension-fetch"; const chunkIdentifier = "chunk-extension"; @@ -401,23 +479,25 @@ async function testFetchWatchHistoryExtensionDecryptsHexAndNpub() { ], }; - const previousNostrTools = window.NostrTools || {}; - window.NostrTools = { - ...previousNostrTools, - nip19: { - ...(previousNostrTools.nip19 || {}), - decode: (value) => { - if (value === actorNpub) { - return { type: "npub", data: actorHex }; - } - if ( - previousNostrTools.nip19 && - typeof previousNostrTools.nip19.decode === "function" - ) { - return previousNostrTools.nip19.decode(value); - } - throw new Error("unsupported-npub"); - }, + if (!window.NostrTools || typeof window.NostrTools !== "object") { + window.NostrTools = {}; + } + const previousNip19 = window.NostrTools.nip19; + const previousDecode = + previousNip19 && typeof previousNip19.decode === "function" + ? previousNip19.decode + : null; + + window.NostrTools.nip19 = { + ...(previousNip19 || {}), + decode: (value) => { + if (value === actorNpub) { + return { type: "npub", data: actorHex }; + } + if (typeof previousDecode === "function") { + return previousDecode(value); + } + throw new Error("unsupported-npub"); }, }; @@ -505,7 +585,11 @@ async function testFetchWatchHistoryExtensionDecryptsHexAndNpub() { await runVariant("hex", actorHex, actorHex); await runVariant("npub", actorNpub, actorNpub); } finally { - window.NostrTools = previousNostrTools; + if (previousNip19) { + window.NostrTools.nip19 = previousNip19; + } else if (window.NostrTools) { + delete window.NostrTools.nip19; + } nostrClient.ensureSessionActor = originalEnsure; nostrClient.sessionActor = originalSession; nostrClient.pubkey = originalPub; @@ -1573,6 +1657,7 @@ await testWatchHistoryStaleCacheRefresh(); await testWatchHistoryLocalFallbackWhenDisabled(); await testWatchHistorySyncEnabledForLoggedInUsers(); await testWatchHistoryAppLoginFallback(); +await testNormalizeActorKeyShortCircuit(); console.log("watch-history.test.mjs completed successfully"); From 5d7df0eb61e3337e151f13d81bfbf7930bbc7d63 Mon Sep 17 00:00:00 2001 From: thePR0M3TH3AN <53631862+PR0M3TH3AN@users.noreply.github.com> Date: Thu, 9 Oct 2025 15:37:52 -0400 Subject: [PATCH 2/5] Add manual npub decode fallback and expand tests --- js/nostr.js | 153 ++++++++++++++++++++++++++++++++--- tests/watch-history.test.mjs | 44 ++++++++++ 2 files changed, 186 insertions(+), 11 deletions(-) diff --git a/js/nostr.js b/js/nostr.js index 1ec94372..b40d1bfe 100644 --- a/js/nostr.js +++ b/js/nostr.js @@ -2590,6 +2590,126 @@ function cloneEventForCache(event) { return cloned; } +const BECH32_CHARSET = "qpzry9x8gf2tvdw0s3jn54khce6mua7l"; +const BECH32_CHARSET_MAP = (() => { + const map = new Map(); + for (let index = 0; index < BECH32_CHARSET.length; index += 1) { + map.set(BECH32_CHARSET[index], index); + } + return map; +})(); + +const BECH32_GENERATORS = [ + 0x3b6a57b2, + 0x26508e6d, + 0x1ea119fa, + 0x3d4233dd, + 0x2a1462b3, +]; + +function bech32Polymod(values) { + let chk = 1; + for (const value of values) { + const top = chk >>> 25; + chk = ((chk & 0x1ffffff) << 5) ^ value; + for (let bit = 0; bit < BECH32_GENERATORS.length; bit += 1) { + if ((top >>> bit) & 1) { + chk ^= BECH32_GENERATORS[bit]; + } + } + } + return chk; +} + +function bech32HrpExpand(hrp) { + const expansion = []; + for (let i = 0; i < hrp.length; i += 1) { + expansion.push(hrp.charCodeAt(i) >>> 5); + } + expansion.push(0); + for (let i = 0; i < hrp.length; i += 1) { + expansion.push(hrp.charCodeAt(i) & 31); + } + return expansion; +} + +function bech32VerifyChecksum(hrp, values) { + return bech32Polymod([...bech32HrpExpand(hrp), ...values]) === 1; +} + +function convertBits(data, fromBits, toBits) { + let acc = 0; + let bits = 0; + const maxValue = (1 << toBits) - 1; + const result = []; + + for (const value of data) { + if (value < 0 || value >>> fromBits !== 0) { + return null; + } + acc = (acc << fromBits) | value; + bits += fromBits; + while (bits >= toBits) { + bits -= toBits; + result.push((acc >>> bits) & maxValue); + } + } + + if (bits > 0) { + if ((acc << (toBits - bits)) & maxValue) { + return null; + } + } + + return result; +} + +function decodeBech32Npub(value) { + if (typeof value !== "string") { + return ""; + } + + const hasMixedCase = value !== value.toLowerCase() && value !== value.toUpperCase(); + if (hasMixedCase) { + return ""; + } + + const normalized = value.toLowerCase(); + const separatorIndex = normalized.lastIndexOf("1"); + if (separatorIndex <= 0 || separatorIndex + 7 > normalized.length) { + return ""; + } + + const hrp = normalized.slice(0, separatorIndex); + if (hrp !== "npub") { + return ""; + } + + const dataPart = normalized.slice(separatorIndex + 1); + const values = []; + for (let i = 0; i < dataPart.length; i += 1) { + const mapped = BECH32_CHARSET_MAP.get(dataPart[i]); + if (typeof mapped !== "number") { + return ""; + } + values.push(mapped); + } + + if (values.length < 7 || !bech32VerifyChecksum(hrp, values)) { + return ""; + } + + const words = values.slice(0, -6); + const bytes = convertBits(words, 5, 8); + if (!bytes || bytes.length !== 32) { + return ""; + } + + return Array.from(bytes) + .map((byte) => byte.toString(16).padStart(2, "0")) + .join(""); +} + function decodeNpubToHex(npub) { if (typeof npub !== "string") { return ""; @@ -2621,20 +2741,31 @@ function decodeNpubToHex(npub) { tools = fallbackTools; } } - if (!tools?.nip19 || typeof tools.nip19.decode !== "function") { - return ""; + + let decodeError = null; + if (tools?.nip19 && typeof tools.nip19.decode === "function") { + try { + const decoded = tools.nip19.decode(trimmed); + if (decoded?.type === "npub" && typeof decoded.data === "string") { + return decoded.data; + } + } catch (error) { + decodeError = error; + } } - try { - const decoded = tools.nip19.decode(trimmed); - if (decoded?.type === "npub" && typeof decoded.data === "string") { - return decoded.data; - } - } catch (error) { - if (isDevMode && warnableNpub) { - console.warn(`[nostr] Failed to decode npub: ${trimmed}`, error); - } + const manualDecoded = decodeBech32Npub(trimmed); + if (manualDecoded) { + return manualDecoded; } + + if (isDevMode && warnableNpub) { + console.warn( + `[nostr] Failed to decode npub: ${trimmed}`, + decodeError || new Error("invalid-npub"), + ); + } + return ""; } diff --git a/tests/watch-history.test.mjs b/tests/watch-history.test.mjs index f5d3705f..85116589 100644 --- a/tests/watch-history.test.mjs +++ b/tests/watch-history.test.mjs @@ -425,6 +425,49 @@ async function testNormalizeActorKeyShortCircuit() { } } +async function testNormalizeActorKeyManualFallback() { + console.log("Running normalizeActorKey manual fallback test..."); + + const actorHex = + "a4a6b5849bc917b3befd5c81865ee0b88773690609c207ba6588ef3e1e05b95b"; + const actorNpub = + "npub15jnttpymeytm80hatjqcvhhqhzrhx6gxp8pq0wn93rhnu8s9h9dsha32lx"; + + if (!window.NostrTools || typeof window.NostrTools !== "object") { + window.NostrTools = {}; + } + + const previousNip19 = window.NostrTools.nip19; + const originalWarn = console.warn; + const warnings = []; + + delete window.NostrTools.nip19; + console.warn = (...args) => { + warnings.push(args); + }; + + try { + const normalized = normalizeActorKey(actorNpub); + assert.equal( + normalized, + actorHex, + "manual fallback should decode npub values to hex", + ); + assert.equal( + warnings.length, + 0, + "manual fallback decode should not emit warnings", + ); + } finally { + console.warn = originalWarn; + if (previousNip19 !== undefined) { + window.NostrTools.nip19 = previousNip19; + } else { + delete window.NostrTools.nip19; + } + } +} + async function testFetchWatchHistoryExtensionDecryptsHexAndNpub() { const actorHex = "0123456789abcdef0123456789abcdef0123456789abcdef0123456789abcdef"; const actorNpub = @@ -1658,6 +1701,7 @@ await testWatchHistoryLocalFallbackWhenDisabled(); await testWatchHistorySyncEnabledForLoggedInUsers(); await testWatchHistoryAppLoginFallback(); await testNormalizeActorKeyShortCircuit(); +await testNormalizeActorKeyManualFallback(); console.log("watch-history.test.mjs completed successfully"); From 492c591f06400792a13fae9980b40c17449f08fa Mon Sep 17 00:00:00 2001 From: thePR0M3TH3AN <53631862+PR0M3TH3AN@users.noreply.github.com> Date: Thu, 9 Oct 2025 15:46:33 -0400 Subject: [PATCH 3/5] Add detailed watch history decryption logging --- js/nostr.js | 109 ++++++++++++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 105 insertions(+), 4 deletions(-) diff --git a/js/nostr.js b/js/nostr.js index b40d1bfe..e3f04ed4 100644 --- a/js/nostr.js +++ b/js/nostr.js @@ -4905,38 +4905,105 @@ export class NostrClient { const tools = await ensureNostrTools(); if (tools?.nip04 && typeof tools.nip04.decrypt === "function") { cachedDecryptTools = tools; + console.info("[nostr] Loaded nostr-tools nip04 helpers for watch history decryption."); return cachedDecryptTools; } + console.warn("[nostr] Unable to load nostr-tools nip04 helpers for watch history decryption."); return null; }; - const decryptChunk = async (ciphertext) => { + const decryptChunk = async (ciphertext, context = {}) => { if (!ciphertext || typeof ciphertext !== "string") { throw new Error("empty-ciphertext"); } + const ciphertextPreview = ciphertext.slice(0, 32); + console.info("[nostr] Attempting to decrypt watch history chunk.", { + actorKey, + chunkIdentifier: context.chunkIdentifier ?? null, + eventId: context.eventId ?? null, + ciphertextPreview, + ciphertextFormat: "base64 NIP-04 ciphertext", + expectedPlaintextFormat: + "JSON string with { version, items, snapshot, chunkIndex, totalChunks }", + }); const extensionDecrypt = extension && typeof extension?.nip04?.decrypt === "function" && normalizeActorKey(this.pubkey) === actorKey; if (extensionDecrypt) { await this.ensureExtensionPermissions(DEFAULT_NIP07_PERMISSION_METHODS); - return extension.nip04.decrypt(actorKey, ciphertext); + console.info( + "[nostr] Using logged in user's extension key to decrypt watch history chunk.", + { + actorKey, + chunkIdentifier: context.chunkIdentifier ?? null, + eventId: context.eventId ?? null, + }, + ); + const plaintext = await extension.nip04.decrypt(actorKey, ciphertext); + console.info("[nostr] Successfully decrypted watch history chunk via extension key.", { + actorKey, + chunkIdentifier: context.chunkIdentifier ?? null, + eventId: context.eventId ?? null, + }); + return plaintext; } if (!this.sessionActor || this.sessionActor.pubkey !== actorKey) { + console.info( + "[nostr] Session actor mismatch while decrypting watch history chunk. Ensuring session actor matches requested key.", + { + actorKey, + chunkIdentifier: context.chunkIdentifier ?? null, + eventId: context.eventId ?? null, + currentSessionActor: this.sessionActor?.pubkey ?? null, + }, + ); await this.ensureSessionActor(); } if (!this.sessionActor || this.sessionActor.pubkey !== actorKey) { + console.error( + "[nostr] Watch history decrypt failed: session actor key unavailable after ensure.", + { + actorKey, + chunkIdentifier: context.chunkIdentifier ?? null, + eventId: context.eventId ?? null, + currentSessionActor: this.sessionActor?.pubkey ?? null, + }, + ); throw new Error("missing-session-key"); } const tools = await ensureDecryptTools(); if (!tools?.nip04 || typeof tools.nip04.decrypt !== "function") { + console.error( + "[nostr] Watch history decrypt failed: nip04 helpers unavailable.", + { + actorKey, + chunkIdentifier: context.chunkIdentifier ?? null, + eventId: context.eventId ?? null, + }, + ); throw new Error("nip04-unavailable"); } - return tools.nip04.decrypt( + console.info( + "[nostr] Using session actor private key to decrypt watch history chunk.", + { + actorKey, + chunkIdentifier: context.chunkIdentifier ?? null, + eventId: context.eventId ?? null, + sessionActor: this.sessionActor?.pubkey ?? null, + }, + ); + const plaintext = await tools.nip04.decrypt( this.sessionActor.privateKey, actorKey, ciphertext, ); + console.info("[nostr] Successfully decrypted watch history chunk via session actor key.", { + actorKey, + chunkIdentifier: context.chunkIdentifier ?? null, + eventId: context.eventId ?? null, + }); + return plaintext; }; const chunkCount = latestChunks.size || chunkIdentifiers.length || 0; @@ -4951,10 +5018,26 @@ export class NostrClient { } const fallbackPointers = extractPointerItemsFromEvent(event); const ciphertext = typeof event.content === "string" ? event.content : ""; + const ciphertextPreview = ciphertext.slice(0, 32); let payload; + const chunkContext = { + chunkIdentifier: identifier, + eventId: event.id ?? null, + }; if (isNip04EncryptedWatchHistoryEvent(event, ciphertext)) { + console.info("[nostr] Watch history chunk is marked as NIP-04 encrypted. Beginning decrypt flow.", { + actorKey, + ...chunkContext, + }); try { - const plaintext = await decryptChunk(ciphertext); + const plaintext = await decryptChunk(ciphertext, chunkContext); + console.info("[nostr] Decrypted watch history chunk. Parsing plaintext payload.", { + actorKey, + ...chunkContext, + plaintextPreview: typeof plaintext === "string" ? plaintext.slice(0, 64) : null, + expectedPlaintextFormat: + "JSON string with { version, items, snapshot, chunkIndex, totalChunks }", + }); payload = parseWatchHistoryContentWithFallback( plaintext, fallbackPointers, @@ -4968,12 +5051,30 @@ export class NostrClient { ); } catch (error) { decryptErrors.push(error); + console.error("[nostr] Decrypt failed for watch history chunk. Falling back to pointer items.", { + actorKey, + ...chunkContext, + error: error?.message || error, + ciphertextPreview, + fallbackPointerCount: Array.isArray(fallbackPointers) + ? fallbackPointers.length + : 0, + expectedPlaintextFormat: + "JSON string with { version, items, snapshot, chunkIndex, totalChunks }", + }); payload = { version: 0, items: fallbackPointers, }; } } else { + console.info("[nostr] Watch history chunk is plaintext. Attempting to parse expected payload format.", { + actorKey, + ...chunkContext, + ciphertextPreview, + expectedPlaintextFormat: + "JSON string with { version, items, snapshot, chunkIndex, totalChunks }", + }); payload = parseWatchHistoryContentWithFallback( ciphertext, fallbackPointers, From 3792b218a98321f3c572c34231cd20c355e8d52a Mon Sep 17 00:00:00 2001 From: thePR0M3TH3AN <53631862+PR0M3TH3AN@users.noreply.github.com> Date: Thu, 9 Oct 2025 16:06:46 -0400 Subject: [PATCH 4/5] Add verbose logging for watch history metadata resolution --- js/watchHistoryMetadata.js | 167 ++++++++++++++++++++++++------------- 1 file changed, 111 insertions(+), 56 deletions(-) diff --git a/js/watchHistoryMetadata.js b/js/watchHistoryMetadata.js index 1cb1cd2f..742e5cbc 100644 --- a/js/watchHistoryMetadata.js +++ b/js/watchHistoryMetadata.js @@ -7,11 +7,37 @@ import { nostrClient } from "./nostr.js"; const isDevEnv = typeof process !== "undefined" && process?.env?.NODE_ENV !== "production"; +function logInfo(message, details) { + if (!isDevEnv) { + return; + } + if (details && typeof details === "object") { + console.info(`[watchHistoryMetadata] ${message}`, details); + } else { + console.info(`[watchHistoryMetadata] ${message}`); + } +} + +function logWarn(message, details) { + if (!isDevEnv) { + return; + } + if (details && typeof details === "object") { + console.warn(`[watchHistoryMetadata] ${message}`, details); + } else { + console.warn(`[watchHistoryMetadata] ${message}`); + } +} + function normalizeVideoCandidate(candidate) { if (!candidate || typeof candidate !== "object") { + logInfo("Discarded non-object video candidate while normalizing."); return null; } if (candidate.deleted) { + logInfo("Discarded deleted video candidate while normalizing.", { + eventId: candidate.id || null, + }); return null; } return candidate; @@ -31,25 +57,29 @@ export function createWatchHistoryMetadataResolver({ try { return typeof appResolver === "function" ? appResolver() : getApplication(); } catch (error) { - if (isDevEnv) { - console.warn( - "[watchHistoryMetadata] Failed to resolve application instance:", - error, - ); - } + logWarn("Failed to resolve application instance.", { error }); return null; } } async function resolveVideo(pointer) { if (!pointer || typeof pointer !== "object") { + logInfo("Received invalid pointer when resolving video metadata.", { + pointerType: typeof pointer, + }); return null; } const app = getAppInstance(); const type = pointer.type === "a" ? "a" : "e"; const value = typeof pointer.value === "string" ? pointer.value.trim() : ""; + logInfo("Attempting to resolve watch history pointer.", { + pointerType: type, + pointerValue: value || null, + hasAppInstance: Boolean(app), + }); if (!value) { + logInfo("Pointer value was empty after trimming. Skipping resolution."); return null; } @@ -57,6 +87,9 @@ export function createWatchHistoryMetadataResolver({ const fromAppCache = app?.videosMap?.get?.(value); const normalizedAppCache = normalizeVideoCandidate(fromAppCache); if (normalizedAppCache) { + logInfo("Resolved pointer from application videos map.", { + pointerValue: value, + }); return normalizedAppCache; } @@ -65,6 +98,9 @@ export function createWatchHistoryMetadataResolver({ : null; const normalizedClientCache = normalizeVideoCandidate(fromClientCache); if (normalizedClientCache) { + logInfo("Resolved pointer from nostr client event cache.", { + pointerValue: value, + }); return normalizedClientCache; } @@ -73,15 +109,16 @@ export function createWatchHistoryMetadataResolver({ const fetched = await app.getOldEventById(value); const normalized = normalizeVideoCandidate(fetched); if (normalized) { + logInfo("Resolved pointer via app.getOldEventById.", { + pointerValue: value, + }); return normalized; } } catch (error) { - if (isDevEnv) { - console.warn( - "[watchHistoryMetadata] Failed to fetch old event by id:", - error, - ); - } + logWarn("Failed to fetch old event by id.", { + pointerValue: value, + error, + }); } } @@ -90,18 +127,20 @@ export function createWatchHistoryMetadataResolver({ const fetched = await client.getEventById(value); const normalized = normalizeVideoCandidate(fetched); if (normalized) { + logInfo("Resolved pointer via nostrClient.getEventById.", { + pointerValue: value, + }); return normalized; } } catch (error) { - if (isDevEnv) { - console.warn( - "[watchHistoryMetadata] Failed to fetch event by id:", - error, - ); - } + logWarn("Failed to fetch event by id via nostrClient.", { + pointerValue: value, + error, + }); } } + logInfo("Failed to resolve pointer by event id.", { pointerValue: value }); return null; } @@ -114,16 +153,21 @@ export function createWatchHistoryMetadataResolver({ } try { const address = app.getVideoAddressPointer(candidate); - return typeof address === "string" && address.trim() === value; - } catch (error) { - if (isDevEnv) { - console.warn( - "[watchHistoryMetadata] Failed to compute address pointer:", - error, - ); + const isMatch = typeof address === "string" && address.trim() === value; + if (isMatch) { + logInfo("Candidate matched address pointer.", { + pointerValue: value, + candidateId: candidate.id || null, + }); } + return isMatch; + } catch (error) { + logWarn("Failed to compute address pointer for candidate.", { + pointerValue: value, + error, + }); + return false; } - return false; }; if (app?.videosMap instanceof Map) { @@ -149,12 +193,10 @@ export function createWatchHistoryMetadataResolver({ app.isAuthorBlocked(pubkey) ); } catch (error) { - if (isDevEnv) { - console.warn( - "[watchHistoryMetadata] Failed to evaluate isAuthorBlocked:", - error, - ); - } + logWarn("Failed to evaluate isAuthorBlocked callback.", { + pointerValue: value, + error, + }); return false; } }, @@ -165,13 +207,17 @@ export function createWatchHistoryMetadataResolver({ caches.activeVideos = nostr.getFilteredActiveVideos ? nostr.getFilteredActiveVideos(filterOptions) : []; + logInfo("Loaded active videos cache for pointer resolution.", { + pointerValue: value, + candidateCount: Array.isArray(caches.activeVideos) + ? caches.activeVideos.length + : 0, + }); } catch (error) { - if (isDevEnv) { - console.warn( - "[watchHistoryMetadata] Failed to read active videos cache:", - error, - ); - } + logWarn("Failed to read active videos cache.", { + pointerValue: value, + error, + }); caches.activeVideos = []; } } @@ -182,21 +228,26 @@ export function createWatchHistoryMetadataResolver({ if (compareAddress(candidate)) { const normalized = normalizeVideoCandidate(candidate); if (normalized) { + logInfo("Resolved pointer from active videos cache.", { + pointerValue: value, + candidateId: normalized.id || null, + }); return normalized; } } } if (!caches.catalogPromise && typeof nostr.fetchVideos === "function") { + logInfo("Fetching video catalog for pointer resolution.", { + pointerValue: value, + }); caches.catalogPromise = nostr .fetchVideos(filterOptions) .catch((error) => { - if (isDevEnv) { - console.warn( - "[watchHistoryMetadata] Failed to fetch video catalog:", - error, - ); - } + logWarn("Failed to fetch video catalog while resolving pointer.", { + pointerValue: value, + error, + }); return []; }); } @@ -208,20 +259,25 @@ export function createWatchHistoryMetadataResolver({ if (compareAddress(candidate)) { const normalized = normalizeVideoCandidate(candidate); if (normalized) { + logInfo("Resolved pointer from fetched video catalog.", { + pointerValue: value, + candidateId: normalized.id || null, + }); return normalized; } } } } catch (error) { - if (isDevEnv) { - console.warn( - "[watchHistoryMetadata] Failed to resolve catalog pointer:", - error, - ); - } + logWarn("Failed to resolve pointer from fetched catalog.", { + pointerValue: value, + error, + }); } } + logInfo("Failed to resolve pointer after exhausting lookup strategies.", { + pointerValue: value, + }); return null; } @@ -239,22 +295,21 @@ export function createWatchHistoryMetadataResolver({ ? app.getProfileCacheEntry(pubkey) : null; if (cacheEntry && typeof cacheEntry === "object") { + logInfo("Resolved profile from application cache.", { pubkey }); return cacheEntry.profile || null; } } catch (error) { - if (isDevEnv) { - console.warn( - "[watchHistoryMetadata] Failed to read profile cache entry:", - error, - ); - } + logWarn("Failed to read profile cache entry.", { pubkey, error }); } + logInfo("Profile cache miss during watch history hydration.", { pubkey }); return null; } function reset() { caches.activeVideos = null; + logInfo("Reset active videos cache for watch history metadata resolver."); caches.catalogPromise = null; + logInfo("Reset catalog promise for watch history metadata resolver."); } return { From 614ff3b1f126dc1e0c6754b230758193514defc5 Mon Sep 17 00:00:00 2001 From: thePR0M3TH3AN <53631862+PR0M3TH3AN@users.noreply.github.com> Date: Thu, 9 Oct 2025 16:18:31 -0400 Subject: [PATCH 5/5] Enable runtime watch history debug logging --- js/app.js | 34 ++++- js/feedEngine/watchHistoryFeed.js | 157 +++++++++++++++++++++++ js/watchHistoryDebug.js | 203 ++++++++++++++++++++++++++++++ js/watchHistoryMetadata.js | 22 +--- 4 files changed, 396 insertions(+), 20 deletions(-) create mode 100644 js/watchHistoryDebug.js diff --git a/js/app.js b/js/app.js index 00ea290f..e29aab5e 100644 --- a/js/app.js +++ b/js/app.js @@ -42,6 +42,7 @@ import WatchHistoryController from "./ui/watchHistoryController.js"; import WatchHistoryTelemetry from "./services/watchHistoryTelemetry.js"; import { getSidebarLoadingMarkup } from "./sidebarLoading.js"; import { subscriptions } from "./subscriptions.js"; +import { isWatchHistoryDebugEnabled } from "./watchHistoryDebug.js"; import { initViewCounter, subscribeToVideoViewCount, @@ -186,7 +187,38 @@ class Application { this.nostrService = services.nostrService || nostrService; this.r2Service = services.r2Service || r2Service; - this.feedEngine = services.feedEngine || createFeedEngine(); + + const feedEngineLogger = (...args) => { + if (!isWatchHistoryDebugEnabled()) { + return; + } + if (!Array.isArray(args) || args.length === 0) { + return; + } + const [prefix, ...rest] = args; + if (typeof prefix === "string" && !prefix.includes("watch-history")) { + return; + } + try { + if (rest.length) { + console.info(prefix, ...rest); + } else { + console.info(prefix); + } + } catch (error) { + if (rest.length) { + console.log(prefix, ...rest); + } else { + console.log(prefix); + } + } + }; + + this.feedEngine = + services.feedEngine || + createFeedEngine({ + logger: feedEngineLogger, + }); this.payments = services.payments || null; this.splitAndZap = (services.payments && services.payments.splitAndZap) || diff --git a/js/feedEngine/watchHistoryFeed.js b/js/feedEngine/watchHistoryFeed.js index 0f76d96a..b93d19c1 100644 --- a/js/feedEngine/watchHistoryFeed.js +++ b/js/feedEngine/watchHistoryFeed.js @@ -4,12 +4,26 @@ import { pointerKey, normalizePointerInput } from "../nostr.js"; import watchHistoryService from "../watchHistoryService.js"; import nostrService from "../services/nostrService.js"; import { createWatchHistoryMetadataResolver } from "../watchHistoryMetadata.js"; +import { + isWatchHistoryDebugEnabled, + logWatchHistoryDebug, +} from "../watchHistoryDebug.js"; import { createBlacklistFilterStage, createWatchHistorySuppressionStage, } from "./stages.js"; import { isPlainObject } from "./utils.js"; +const WATCH_HISTORY_FEED_LOG_NAMESPACE = "watchHistoryFeed"; + +function debugInfo(message, details) { + logWatchHistoryDebug(WATCH_HISTORY_FEED_LOG_NAMESPACE, "info", message, details); +} + +function debugWarn(message, details) { + logWatchHistoryDebug(WATCH_HISTORY_FEED_LOG_NAMESPACE, "warn", message, details); +} + function normalizeActorCandidate(...values) { for (const value of values) { if (typeof value === "string") { @@ -213,6 +227,11 @@ function createWatchHistoryHydratorStage({ ? item.pointerKey : pointerKey(item.pointer); + const pointerType = + typeof item?.pointer?.type === "string" ? item.pointer.type : null; + const pointerValue = + typeof item?.pointer?.value === "string" ? item.pointer.value : null; + const watchedAtValue = Number.isFinite(item?.watchedAt) ? Math.max(0, Math.floor(Number(item.watchedAt))) : Number.isFinite(item?.metadata?.watchedAt) @@ -222,40 +241,133 @@ function createWatchHistoryHydratorStage({ let video = item.video || null; let profile = item.metadata?.profile || null; + if (isWatchHistoryDebugEnabled()) { + debugInfo("Hydrating watch history item.", { + pointerKey: pointerKeyValue || null, + pointerType, + pointerValue, + hasInitialVideo: Boolean(video), + hasInitialProfile: Boolean(profile), + watchedAt: watchedAtValue || null, + }); + } + if (pointerKeyValue && typeof service?.getLocalMetadata === "function") { try { const stored = service.getLocalMetadata(pointerKeyValue); if (stored) { + const hadVideo = Boolean(video); + const hadProfile = Boolean(profile); video = video || stored.video || null; profile = profile || stored.profile || null; + if (isWatchHistoryDebugEnabled()) { + debugInfo("Loaded cached metadata for pointer.", { + pointerKey: pointerKeyValue, + hadVideo, + hadProfile, + cachedVideo: Boolean(stored.video), + cachedProfile: Boolean(stored.profile), + resultingVideo: Boolean(video), + resultingProfile: Boolean(profile), + }); + } } } catch (error) { context?.log?.( "[watch-history-feed] Failed to read cached metadata", error, ); + if (isWatchHistoryDebugEnabled()) { + debugWarn("Failed to read cached metadata for pointer.", { + pointerKey: pointerKeyValue || null, + error, + }); + } } } if (!video && resolver?.resolveVideo) { + if (isWatchHistoryDebugEnabled()) { + debugInfo("Resolving video via metadata resolver.", { + pointerKey: pointerKeyValue || null, + pointerType, + pointerValue, + }); + } try { video = await resolver.resolveVideo(item.pointer); + if (isWatchHistoryDebugEnabled()) { + if (video) { + debugInfo("Metadata resolver returned video candidate.", { + pointerKey: pointerKeyValue || null, + videoId: typeof video.id === "string" ? video.id : null, + title: + typeof video.title === "string" && video.title.trim() + ? video.title + : null, + invalid: Boolean(video.invalid), + }); + } else { + debugWarn("Metadata resolver returned no video candidate.", { + pointerKey: pointerKeyValue || null, + }); + } + } } catch (error) { context?.log?.( "[watch-history-feed] Failed to resolve video from pointer", error, ); + if (isWatchHistoryDebugEnabled()) { + debugWarn("Metadata resolver threw while resolving video.", { + pointerKey: pointerKeyValue || null, + error, + }); + } } } if (video?.pubkey && !profile && resolver?.resolveProfile) { + if (isWatchHistoryDebugEnabled()) { + debugInfo("Resolving profile for video author.", { + pointerKey: pointerKeyValue || null, + pubkey: video.pubkey, + }); + } try { profile = resolver.resolveProfile(video.pubkey) || null; + if (isWatchHistoryDebugEnabled()) { + if (profile) { + const label = + profile.display_name || + profile.name || + profile.username || + profile.nip05 || + null; + debugInfo("Resolved profile for video author.", { + pointerKey: pointerKeyValue || null, + pubkey: video.pubkey, + label: label || null, + }); + } else { + debugWarn("Resolver returned no profile for video author.", { + pointerKey: pointerKeyValue || null, + pubkey: video.pubkey, + }); + } + } } catch (error) { context?.log?.( "[watch-history-feed] Failed to resolve profile for pointer", error, ); + if (isWatchHistoryDebugEnabled()) { + debugWarn("Profile resolver threw while hydrating metadata.", { + pointerKey: pointerKeyValue || null, + pubkey: video.pubkey, + error, + }); + } } } @@ -270,6 +382,27 @@ function createWatchHistoryHydratorStage({ profile: profile || null, }; + if (isWatchHistoryDebugEnabled()) { + const summary = { + pointerKey: pointerKeyValue || null, + pointerType, + pointerValue, + watchedAt: watchedAtValue || null, + videoId: typeof video?.id === "string" ? video.id : null, + title: + typeof video?.title === "string" && video.title?.trim() + ? video.title + : null, + invalid: Boolean(video?.invalid), + hasProfile: Boolean(profile), + }; + if (video) { + debugInfo("Hydrated watch history entry metadata.", summary); + } else { + debugWarn("Hydrated entry is missing resolved video metadata.", summary); + } + } + const nextItem = { ...item, pointerKey: pointerKeyValue, @@ -286,20 +419,44 @@ function createWatchHistoryHydratorStage({ video: metadata.video, profile: metadata.profile, }); + if (isWatchHistoryDebugEnabled()) { + debugInfo("Stored metadata cache entry for pointer.", { + pointerKey: pointerKeyValue, + cachedVideo: Boolean(metadata.video), + cachedProfile: Boolean(metadata.profile), + }); + } } catch (error) { context?.log?.( "[watch-history-feed] Failed to persist metadata cache", error, ); + if (isWatchHistoryDebugEnabled()) { + debugWarn("Failed to persist metadata cache entry.", { + pointerKey: pointerKeyValue, + error, + }); + } } } else if (typeof service?.removeLocalMetadata === "function") { try { service.removeLocalMetadata(pointerKeyValue); + if (isWatchHistoryDebugEnabled()) { + debugInfo("Cleared metadata cache entry for pointer.", { + pointerKey: pointerKeyValue, + }); + } } catch (error) { context?.log?.( "[watch-history-feed] Failed to clear cached metadata", error, ); + if (isWatchHistoryDebugEnabled()) { + debugWarn("Failed to clear cached metadata entry.", { + pointerKey: pointerKeyValue, + error, + }); + } } } } diff --git a/js/watchHistoryDebug.js b/js/watchHistoryDebug.js new file mode 100644 index 00000000..64c7e5f8 --- /dev/null +++ b/js/watchHistoryDebug.js @@ -0,0 +1,203 @@ +// js/watchHistoryDebug.js + +const WATCH_HISTORY_DEBUG_STORAGE_KEY = + "bitvid:debug:watch-history"; + +const globalScope = + typeof globalThis !== "undefined" + ? globalThis + : typeof window !== "undefined" + ? window + : typeof self !== "undefined" + ? self + : null; + +const TRUTHY_VALUES = new Set([ + "1", + "true", + "yes", + "on", + "enable", + "enabled", + "debug", + "verbose", + "watch", +]); + +const FALSY_VALUES = new Set([ + "0", + "false", + "no", + "off", + "disable", + "disabled", + "quiet", + "silent", +]); + +function parseFlagValue(value) { + if (value === null || value === undefined) { + return true; + } + if (typeof value === "boolean") { + return value; + } + if (typeof value !== "string") { + return null; + } + const normalized = value.trim().toLowerCase(); + if (!normalized) { + return true; + } + if (TRUTHY_VALUES.has(normalized)) { + return true; + } + if (FALSY_VALUES.has(normalized)) { + return false; + } + return null; +} + +function safeReadStorageFlag(storage) { + if (!storage || typeof storage.getItem !== "function") { + return null; + } + try { + const raw = storage.getItem(WATCH_HISTORY_DEBUG_STORAGE_KEY); + if (raw === null || raw === undefined) { + return null; + } + return parseFlagValue(String(raw)); + } catch (error) { + return null; + } +} + +function safeWriteStorageFlag(storage, value) { + if (!storage || typeof storage.setItem !== "function") { + return; + } + try { + storage.setItem(WATCH_HISTORY_DEBUG_STORAGE_KEY, value ? "true" : "false"); + } catch (error) { + // Ignore storage errors (e.g., quota exceeded, private mode restrictions). + } +} + +function persistFlag(scope, value) { + if (value === null) { + return; + } + safeWriteStorageFlag(scope?.sessionStorage, value); + safeWriteStorageFlag(scope?.localStorage, value); +} + +function readFlagFromUrl(scope) { + if (!scope || typeof scope.location?.search !== "string") { + return null; + } + const search = scope.location.search; + if (!search) { + return null; + } + try { + const params = new URLSearchParams(search); + if (!params.has("watchHistoryDebug")) { + return null; + } + const parsed = parseFlagValue(params.get("watchHistoryDebug")); + if (parsed === null) { + return null; + } + persistFlag(scope, parsed); + return parsed; + } catch (error) { + return null; + } +} + +function resolveExplicitFlag(scope) { + if (!scope) { + return null; + } + + const runtimeFlag = scope.__BITVID_ENABLE_WATCH_HISTORY_DEBUG__; + if (runtimeFlag === true || runtimeFlag === false) { + return Boolean(runtimeFlag); + } + + const altRuntimeFlag = scope.BITVID_WATCH_HISTORY_DEBUG; + if (altRuntimeFlag === true || altRuntimeFlag === false) { + return Boolean(altRuntimeFlag); + } + + const urlFlag = readFlagFromUrl(scope); + if (urlFlag !== null) { + return urlFlag; + } + + const sessionFlag = safeReadStorageFlag(scope.sessionStorage); + if (sessionFlag !== null) { + return sessionFlag; + } + + const localFlag = safeReadStorageFlag(scope.localStorage); + if (localFlag !== null) { + return localFlag; + } + + return null; +} + +export function isWatchHistoryDebugEnabled() { + const scope = globalScope; + const explicitFlag = resolveExplicitFlag(scope); + if (explicitFlag !== null) { + return explicitFlag; + } + + if (typeof process !== "undefined" && process?.env?.NODE_ENV) { + return process.env.NODE_ENV !== "production"; + } + + return false; +} + +export function logWatchHistoryDebug(namespace, level, message, details) { + if (!isWatchHistoryDebugEnabled()) { + return; + } + + const scopeConsole = + (globalScope && globalScope.console) || (typeof console !== "undefined" ? console : null); + if (!scopeConsole) { + return; + } + + const methodName = + typeof level === "string" && level && typeof scopeConsole[level] === "function" + ? level + : typeof scopeConsole.info === "function" + ? "info" + : "log"; + + const prefix = namespace ? `[${namespace}] ${message}` : message; + + try { + if (details && typeof details === "object") { + scopeConsole[methodName](prefix, details); + } else { + scopeConsole[methodName](prefix); + } + } catch (error) { + try { + if (details && typeof details === "object") { + scopeConsole.log(prefix, details); + } else { + scopeConsole.log(prefix); + } + } catch (fallbackError) { + // Swallow logging errors entirely. + } + } +} diff --git a/js/watchHistoryMetadata.js b/js/watchHistoryMetadata.js index 742e5cbc..1efda14d 100644 --- a/js/watchHistoryMetadata.js +++ b/js/watchHistoryMetadata.js @@ -3,30 +3,14 @@ import { getApplication } from "./applicationContext.js"; import nostrService from "./services/nostrService.js"; import { nostrClient } from "./nostr.js"; - -const isDevEnv = - typeof process !== "undefined" && process?.env?.NODE_ENV !== "production"; +import { logWatchHistoryDebug } from "./watchHistoryDebug.js"; function logInfo(message, details) { - if (!isDevEnv) { - return; - } - if (details && typeof details === "object") { - console.info(`[watchHistoryMetadata] ${message}`, details); - } else { - console.info(`[watchHistoryMetadata] ${message}`); - } + logWatchHistoryDebug("watchHistoryMetadata", "info", message, details); } function logWarn(message, details) { - if (!isDevEnv) { - return; - } - if (details && typeof details === "object") { - console.warn(`[watchHistoryMetadata] ${message}`, details); - } else { - console.warn(`[watchHistoryMetadata] ${message}`); - } + logWatchHistoryDebug("watchHistoryMetadata", "warn", message, details); } function normalizeVideoCandidate(candidate) {