From a4eb4f2367d814b60ddf6a1f865f98f1efd0a5cf Mon Sep 17 00:00:00 2001 From: thePR0M3TH3AN <53631862+PR0M3TH3AN@users.noreply.github.com> Date: Thu, 2 Oct 2025 16:44:13 -0400 Subject: [PATCH] Add detailed logging for watch history flow --- js/nostr.js | 92 ++++++++++++++++++++++++++++++ js/watchHistoryService.js | 115 +++++++++++++++++++++++++++++++++++++- 2 files changed, 206 insertions(+), 1 deletion(-) diff --git a/js/nostr.js b/js/nostr.js index 2b6511f7..621fb452 100644 --- a/js/nostr.js +++ b/js/nostr.js @@ -2319,6 +2319,19 @@ class NostrClient { relays = Array.from(RELAY_URLS); } + console.info( + "[nostr] Preparing to publish watch history snapshot.", + { + actor: actorKey, + snapshotId, + itemCount: canonicalItems.length, + chunkCount: chunks.length, + relaysRequested: relays, + attempt: options.attempt || 0, + source: options.source || "unknown", + } + ); + const createdAtBase = Math.max( Math.floor(Date.now() / 1000), this.watchHistoryLastCreatedAt + 1, @@ -2404,6 +2417,17 @@ class NostrClient { return tag; }); + console.info( + "[nostr] Publishing watch history chunk.", + { + actor: actorKey, + snapshotId, + chunkIndex: index, + chunkSize: chunkItems.length, + relays, + } + ); + const plaintext = JSON.stringify({ version: 2, snapshot: snapshotId, @@ -2504,6 +2528,15 @@ class NostrClient { return { ok: false, error: "signing-failed", retryable: false }; } + console.info( + "[nostr] Publishing watch history pointer event.", + { + actor: actorKey, + snapshotId, + relays, + } + ); + const pointerResults = await publishEventToRelays( this.pool, relays, @@ -2588,6 +2621,16 @@ class NostrClient { result.error = errorCode; } + console.info("[nostr] Watch history snapshot publish result.", { + actor: actorKey, + snapshotId, + success, + partialAcceptance, + error: result.error || null, + pointerAcceptedCount, + chunkAcceptedCounts: chunkResults.map((entry) => entry.acceptedCount), + }); + return result; } @@ -2628,6 +2671,13 @@ class NostrClient { canonicalItems, ); + console.info("[nostr] Updating watch history list.", { + actor: resolvedActor, + incomingItemCount: incomingItems.length, + finalItemCount: canonicalItems.length, + replace: options.replace === true, + }); + const publishResult = await this.publishWatchHistorySnapshot( canonicalItems, { @@ -2637,6 +2687,13 @@ class NostrClient { }, ); + console.info("[nostr] Watch history list publish attempt finished.", { + actor: resolvedActor, + snapshotId: publishResult.snapshotId || null, + success: !!publishResult.ok, + retryable: !!publishResult.retryable, + }); + const metadata = sanitizeWatchHistoryMetadata(cachedEntry.metadata); metadata.updatedAt = Date.now(); metadata.status = publishResult.ok ? "ok" : "error"; @@ -2734,6 +2791,11 @@ class NostrClient { return { pointerEvent: null, items: [], snapshotId: "" }; } + console.info("[nostr] Fetching watch history from relays.", { + actor: resolvedActor, + forceRefresh: options.forceRefresh === true, + }); + const extension = window?.nostr; const existingEntry = this.watchHistoryCache.get(actorKey); @@ -2746,6 +2808,11 @@ class NostrClient { Number.isFinite(existingEntry.savedAt) && now - existingEntry.savedAt < ttl ) { + console.info("[nostr] Using cached watch history entry.", { + actor: resolvedActor, + itemCount: Array.isArray(existingEntry.items) ? existingEntry.items.length : 0, + cacheAgeMs: now - existingEntry.savedAt, + }); return { pointerEvent: existingEntry.pointerEvent || null, items: existingEntry.items || [], @@ -2754,6 +2821,7 @@ class NostrClient { } if (!this.pool) { + console.warn("[nostr] Cannot fetch watch history because relay pool is unavailable. Returning cached values."); return { pointerEvent: existingEntry?.pointerEvent || null, items: existingEntry?.items || [], @@ -2820,6 +2888,12 @@ class NostrClient { }, null); if (!pointerEvent) { + console.info( + "[nostr] No watch history pointer event found on relays. Falling back to storage.", + { + actor: resolvedActor, + } + ); const storageEntry = this.getWatchHistoryStorage().actors?.[actorKey]; const items = Array.isArray(storageEntry?.items) ? canonicalizeWatchHistoryItems(storageEntry.items, WATCH_HISTORY_MAX_ITEMS) @@ -3080,6 +3154,11 @@ class NostrClient { return []; } + console.info("[nostr] Resolving watch history for actor.", { + actor: resolvedActor, + forceRefresh: options.forceRefresh === true, + }); + const storage = this.getWatchHistoryStorage(); const fallbackItems = Array.isArray(storage.actors?.[actorKey]?.items) ? canonicalizeWatchHistoryItems( @@ -3123,6 +3202,19 @@ class NostrClient { canonicalItems, ); + console.info("[nostr] Watch history fetch complete.", { + actor: resolvedActor, + snapshotId: fetchResult.snapshotId || null, + pointerFound: !!fetchResult.pointerEvent, + itemCount: canonicalItems.length, + }); + + console.info("[nostr] Watch history resolved and cached.", { + actor: resolvedActor, + itemCount: canonicalItems.length, + snapshotId: fetchResult.snapshotId || null, + }); + const entry = { actor: resolvedActor, items: canonicalItems, diff --git a/js/watchHistoryService.js b/js/watchHistoryService.js index 1aeb3bef..00eeeec6 100644 --- a/js/watchHistoryService.js +++ b/js/watchHistoryService.js @@ -825,12 +825,25 @@ async function publishView(pointerInput, createdAt, metadata = {}) { const viewResult = await nostrClient.recordVideoView(pointerInput, recordOptions); + console.info( + "[watchHistoryService] Video view recorded. Preparing watch list update.", + { + pointer: pointerInput, + createdAt, + hasMetadata: !!metadata, + } + ); + if (!isFeatureEnabled()) { return viewResult; } const pointer = normalizePointerInput(pointerInput); if (!pointer) { + console.warn( + "[watchHistoryService] Skipping watch list update because pointer normalization failed.", + { pointerInput } + ); return viewResult; } @@ -842,16 +855,28 @@ async function publishView(pointerInput, createdAt, metadata = {}) { ""; const actorKey = normalizeActorKey(actorCandidate); if (!actorKey) { + console.warn( + "[watchHistoryService] Unable to resolve actor for watch list update.", + { actorCandidate } + ); return viewResult; } const queue = ensureQueue(actorKey); if (!queue) { + console.warn( + "[watchHistoryService] Failed to resolve queue for actor.", + { actorKey } + ); return viewResult; } const normalizedPointer = normalizePointerInput(pointer); if (!normalizedPointer) { + console.warn( + "[watchHistoryService] Pointer normalization failed during queue preparation.", + { pointerInput } + ); return viewResult; } @@ -860,6 +885,17 @@ async function publishView(pointerInput, createdAt, metadata = {}) { viewResult?.event?.created_at ); + const key = pointerKey(normalizedPointer); + console.info( + "[watchHistoryService] Watch list process triggered by video view.", + { + actor: actorKey, + pointerKey: key, + watchedAt: normalizedPointer.watchedAt, + sessionEvent: normalizedPointer.session === true, + } + ); + const normalizedLogged = normalizeActorKey(nostrClient?.pubkey); const normalizedEventActor = normalizeActorKey( viewResult?.event?.pubkey || actorCandidate @@ -868,8 +904,11 @@ async function publishView(pointerInput, createdAt, metadata = {}) { normalizedPointer.session = true; } - const key = pointerKey(normalizedPointer); if (!key) { + console.warn( + "[watchHistoryService] Pointer key generation failed. Skipping queue update.", + { pointer: normalizedPointer } + ); return viewResult; } @@ -896,6 +935,14 @@ async function publishView(pointerInput, createdAt, metadata = {}) { queue.throttle.set(key, now); persistQueueState(); notifyQueueChange(actorKey); + console.info( + "[watchHistoryService] Updated existing watch list entry.", + { + actor: actorKey, + pointerKey: key, + watchedAt: existing.pointer.watchedAt, + } + ); return viewResult; } @@ -918,6 +965,15 @@ async function publishView(pointerInput, createdAt, metadata = {}) { persistQueueState(); notifyQueueChange(actorKey); + console.info( + "[watchHistoryService] Added pointer to pending watch list snapshot queue.", + { + actor: actorKey, + pointerKey: key, + queueSize: queue.items.size, + } + ); + return viewResult; } @@ -952,6 +1008,16 @@ async function snapshot(items, options = {}) { const queue = ensureQueue(actorKey); + console.info( + "[watchHistoryService] Initiating watch list snapshot publish.", + { + actor: actorKey, + reason, + itemCount: payloadItems.length, + queued: queue?.items?.size ?? 0, + } + ); + const run = (async () => { emit("snapshot-start", { actor: actorKey, reason, items: payloadItems }); const publishResult = await nostrClient.publishWatchHistorySnapshot( @@ -962,6 +1028,17 @@ async function snapshot(items, options = {}) { } ); + console.info( + "[watchHistoryService] Watch list snapshot publish completed.", + { + actor: actorKey, + reason, + success: !!publishResult?.ok, + snapshotId: publishResult?.snapshotId || null, + retryable: !!publishResult?.retryable, + } + ); + if (!publishResult?.ok) { if (publishResult?.retryable && publishResult?.snapshotId) { if (queue) { @@ -988,6 +1065,14 @@ async function snapshot(items, options = {}) { await updateFingerprintCache(actorKey, publishResult.items || payloadItems); emit("snapshot-complete", { actor: actorKey, reason, result: publishResult }); + console.info( + "[watchHistoryService] Watch list snapshot processed and fingerprint cache updated.", + { + actor: actorKey, + reason, + fingerprintUpdated: true, + } + ); return publishResult; })() .catch((error) => { @@ -1015,16 +1100,37 @@ async function loadLatest(actorInput) { const now = Date.now(); const cacheEntry = state.fingerprintCache.get(actorKey); + console.info( + "[watchHistoryService] loadLatest invoked.", + { + actor: actorKey, + cacheHasItems: Array.isArray(cacheEntry?.items), + cacheExpiresAt: cacheEntry?.expiresAt || null, + } + ); if ( cacheEntry?.items && cacheEntry.expiresAt && cacheEntry.expiresAt > now && Array.isArray(cacheEntry.items) ) { + console.info( + "[watchHistoryService] Returning cached watch list items.", + { + actor: actorKey, + itemCount: cacheEntry.items.length, + } + ); return cacheEntry.items; } if (cacheEntry?.promise) { + console.info( + "[watchHistoryService] Awaiting in-flight watch list refresh.", + { + actor: actorKey, + } + ); return cacheEntry.promise; } @@ -1048,6 +1154,13 @@ async function loadLatest(actorInput) { } }); + console.info( + "[watchHistoryService] Triggered nostr watch list refresh.", + { + actor: actorKey, + } + ); + state.fingerprintCache.set(actorKey, { ...(cacheEntry || {}), promise,