diff --git a/nip66-cron/index.mjs b/nip66-cron/index.mjs index 98f7ab98..8aafb3d5 100644 --- a/nip66-cron/index.mjs +++ b/nip66-cron/index.mjs @@ -181,24 +181,23 @@ async function fetchRelayUrlsFromKind10002 (authorPubkey, queryRelayUrls) { await new Promise((resolve, reject) => { let timeoutId let resolved = false - const onOpen = () => { + const cleanup = () => { if (resolved) return resolved = true clearTimeout(timeoutId) + ws.removeListener('open', onOpen) + ws.removeListener('error', onError) + } + const onOpen = () => { + cleanup() resolve() } const onError = (err) => { - if (resolved) return - resolved = true - clearTimeout(timeoutId) - ws.removeListener('open', onOpen) + cleanup() reject(err) } timeoutId = setTimeout(() => { - if (resolved) return - resolved = true - ws.removeListener('open', onOpen) - ws.removeListener('error', onError) + cleanup() reject(new Error('open timeout')) }, 15000) ws.once('open', onOpen) @@ -329,24 +328,23 @@ async function publishEvent (relayUrls, event) { await new Promise((resolve, reject) => { let timeoutId let resolved = false - const onOpen = () => { + const cleanup = () => { if (resolved) return resolved = true clearTimeout(timeoutId) + ws.removeListener('open', onOpen) + ws.removeListener('error', onError) + } + const onOpen = () => { + cleanup() resolve() } const onError = (err) => { - if (resolved) return - resolved = true - clearTimeout(timeoutId) - ws.removeListener('open', onOpen) + cleanup() reject(err) } timeoutId = setTimeout(() => { - if (resolved) return - resolved = true - ws.removeListener('open', onOpen) - ws.removeListener('error', onError) + cleanup() reject(new Error('open timeout')) }, 10000) ws.once('open', onOpen) diff --git a/src/hooks/useFetchProfile.tsx b/src/hooks/useFetchProfile.tsx index 73b0930b..499e0645 100644 --- a/src/hooks/useFetchProfile.tsx +++ b/src/hooks/useFetchProfile.tsx @@ -7,127 +7,343 @@ import { useEffect, useState, useRef, useCallback } from 'react' import logger from '@/lib/logger' export function useFetchProfile(id?: string, skipCache = false) { + // Log hook invocation immediately - this will show if the hook is even being called + logger.info('[useFetchProfile] Hook called', { + id: id || 'undefined', + skipCache, + stack: new Error().stack?.split('\n').slice(1, 4).join('\n') + }) + const { profile: currentAccountProfile } = useNostr() const [isFetching, setIsFetching] = useState(true) const [error, setError] = useState(null) const [profile, setProfile] = useState(null) const [pubkey, setPubkey] = useState(null) const checkIntervalRef = useRef(null) + const processingPubkeyRef = useRef(null) // Track which pubkey we're currently processing (prevents duplicate fetches) + const effectRunCountRef = useRef>(new Map()) // Track how many times effect has run for each pubkey (safety guard against infinite loops) // Function to check for profile updates - // fetchProfileEvent already checks: 1) in-memory cache, 2) IndexedDB, 3) network (with author's relays) + // fetchProfileEvent already checks: 1) IndexedDB, 2) network (with author's relays) // Memoize to prevent recreation on every render const checkProfile = useCallback(async (pubkey: string, cancelled: { current: boolean }) => { - if (cancelled.current) return false + logger.info('[useFetchProfile] checkProfile called', { + pubkey, + cancelled: cancelled.current, + skipCache + }) + + if (cancelled.current) { + logger.info('[useFetchProfile] Already cancelled, returning false') + return false + } + + logger.info('[useFetchProfile] Starting profile fetch', { + pubkey, + skipCache + }) try { + const startTime = Date.now() + logger.info('[useFetchProfile] Calling fetchProfileEvent', { + pubkey + }) + // Use fetchProfileEvent which includes author's relay list for better profile discovery - // fetchProfileEvent handles all cache layers: - // 1. In-memory cache (instant return) - // 2. IndexedDB (fast async) - // 3. Network (with author's relay list for better discovery) const profileEvent = await replaceableEventService.fetchProfileEvent(pubkey, skipCache) + const fetchTime = Date.now() - startTime - if (cancelled.current) return false + logger.info('[useFetchProfile] fetchProfileEvent returned', { + pubkey, + hasEvent: !!profileEvent, + eventId: profileEvent?.id, + fetchTime: `${fetchTime}ms` + }) + + if (cancelled.current) { + logger.info('[useFetchProfile] Fetch cancelled after fetch', { pubkey }) + return false + } if (profileEvent) { // getProfileFromEvent always returns a profile object (with fallback username) const newProfile = getProfileFromEvent(profileEvent) - logger.debug('[useFetchProfile] Profile found', { - pubkey: pubkey.substring(0, 8), + logger.info('[useFetchProfile] Profile found', { + pubkey, username: newProfile.username, - hasAvatar: !!newProfile.avatar + hasAvatar: !!newProfile.avatar, + eventId: profileEvent.id, + fetchTime: `${fetchTime}ms` }) setProfile(newProfile) setIsFetching(false) + // Keep processingPubkeyRef set so we don't re-fetch // Clear interval once we have a profile if (checkIntervalRef.current) { clearInterval(checkIntervalRef.current) checkIntervalRef.current = null } + // Clear run count when profile is found + effectRunCountRef.current.delete(pubkey) return true } - logger.debug('[useFetchProfile] No profile event found', { - pubkey: pubkey.substring(0, 8) + logger.warn('[useFetchProfile] No profile event found', { + pubkey, + fetchTime: `${fetchTime}ms` }) return false } catch (err) { - if (!cancelled.current) { - setError(err as Error) - setIsFetching(false) - } + logger.error('[useFetchProfile] Profile fetch error', { + pubkey, + error: err instanceof Error ? err.message : String(err), + stack: err instanceof Error ? err.stack : undefined, + cancelled: cancelled.current + }) + if (!cancelled.current) { + setError(err as Error) + setIsFetching(false) + } return false } }, [skipCache]) useEffect(() => { + logger.info('[useFetchProfile] useEffect triggered', { + id: id || 'undefined', + skipCache, + processingPubkey: processingPubkeyRef.current + }) + + // Extract pubkey early to check if id has changed + const extractedPubkey = id ? userIdToPubkey(id) : null + + // EARLY EXIT: If we're already processing this exact pubkey, skip immediately + // This prevents the effect from doing any work if it's already running + if (extractedPubkey && processingPubkeyRef.current === extractedPubkey) { + logger.info('[useFetchProfile] EARLY EXIT: Already processing this pubkey', { + extractedPubkey, + processingPubkey: processingPubkeyRef.current + }) + return + } + + // Guard against infinite loops: limit effect runs per pubkey + if (extractedPubkey) { + const runCount = effectRunCountRef.current.get(extractedPubkey) || 0 + if (runCount > 10) { + logger.warn('[useFetchProfile] Too many effect runs for this pubkey, preventing infinite loop', { + extractedPubkey, + runCount + }) + return + } + effectRunCountRef.current.set(extractedPubkey, runCount + 1) + } + + // If id has changed (extractedPubkey is different from processingPubkeyRef), clear the ref + // This allows a new fetch to start for a different pubkey + if (extractedPubkey && processingPubkeyRef.current && processingPubkeyRef.current !== extractedPubkey) { + const oldPubkey = processingPubkeyRef.current + logger.info('[useFetchProfile] ID changed, clearing refs', { + oldPubkey, + newPubkey: extractedPubkey + }) + // Clear run count for old pubkey before clearing ref + effectRunCountRef.current.delete(oldPubkey) + processingPubkeyRef.current = null + } + if (!id) { + logger.warn('[useFetchProfile] No id provided') setProfile(null) setPubkey(null) setIsFetching(false) setError(new Error('No id provided')) + processingPubkeyRef.current = null return } const cancelled = { current: false } - const pubkey = userIdToPubkey(id) - if (!pubkey) { + logger.info('[useFetchProfile] Attempting to extract pubkey', { + id, + idLength: id.length, + idStartsWithNpub: id.startsWith('npub1'), + idStartsWithNprofile: id.startsWith('nprofile1') + }) + + // Use the already-extracted pubkey from above + // const extractedPubkey = userIdToPubkey(id) // Already extracted above + logger.info('[useFetchProfile] Extracted pubkey result', { + id, + extractedPubkey: extractedPubkey || 'null', + pubkeyLength: extractedPubkey ? extractedPubkey.length : 0, + isValidPubkey: extractedPubkey ? /^[0-9a-f]{64}$/.test(extractedPubkey) : false + }) + + if (!extractedPubkey) { + logger.error('[useFetchProfile] Invalid id - could not extract pubkey', { + id, + idLength: id.length + }) setProfile(null) setPubkey(null) setIsFetching(false) setError(new Error('Invalid id: could not extract pubkey')) + processingPubkeyRef.current = null + return + } + + // Validate pubkey format + if (extractedPubkey.length !== 64 || !/^[0-9a-f]{64}$/.test(extractedPubkey)) { + logger.error('[useFetchProfile] Invalid pubkey format', { + id, + extractedPubkey, + pubkeyLength: extractedPubkey.length, + expectedLength: 64 + }) + setProfile(null) + setPubkey(null) + setIsFetching(false) + setError(new Error(`Invalid pubkey format: expected 64 hex chars, got ${extractedPubkey.length}`)) + processingPubkeyRef.current = null + return + } + + // CRITICAL: Check if we're already processing this pubkey IMMEDIATELY after validation + // This must happen before any other logic to prevent infinite loops + if (processingPubkeyRef.current === extractedPubkey) { + logger.info('[useFetchProfile] Already processing this pubkey, skipping duplicate fetch', { + extractedPubkey, + processingPubkey: processingPubkeyRef.current, + hasProfile: !!profile + }) + return + } + + // Also check if we already have a profile for this pubkey before starting a new fetch + if (profile && profile.pubkey === extractedPubkey) { + logger.info('[useFetchProfile] Already have profile for this pubkey, skipping fetch', { + extractedPubkey + }) + // Still update the ref to prevent re-processing + processingPubkeyRef.current = extractedPubkey + setIsFetching(false) + if (pubkey !== extractedPubkey) { + setPubkey(extractedPubkey) + } return } - setPubkey(pubkey) + + // CRITICAL: Mark that we're processing this pubkey IMMEDIATELY after validation + // This must happen before any state updates or async operations + // This prevents the effect from running again for the same pubkey + processingPubkeyRef.current = extractedPubkey + + // Only set pubkey state if it's different to avoid unnecessary re-renders + // Do this AFTER setting the ref to prevent loops + if (pubkey !== extractedPubkey) { + setPubkey(extractedPubkey) + } + logger.info('[useFetchProfile] Starting profile fetch async', { + extractedPubkey, + currentPubkeyState: pubkey || 'null' + }) const run = async () => { - setIsFetching(true) - setError(null) - - // Initial fetch - fetchReplaceableEvent checks: 1) in-memory, 2) IndexedDB, 3) network - const found = await checkProfile(pubkey, cancelled) - - if (cancelled.current) return - - if (found) { - // Profile found (from cache or network), we're done - return - } - - // No profile found yet - set fetching to false so UI can show fallback - // The profile will remain null, allowing components to show npub fallback - setIsFetching(false) - setError(null) // Clear any previous errors - - // If no profile was found, periodically re-check (profiles might load asynchronously) - // Check every 2 seconds for up to 30 seconds (15 checks) - let checkCount = 0 - const maxChecks = 15 + logger.info('[useFetchProfile] run() async function started', { + pubkey: extractedPubkey + }) - checkIntervalRef.current = setInterval(async () => { - if (cancelled.current || checkCount >= maxChecks) { - if (checkIntervalRef.current) { - clearInterval(checkIntervalRef.current) - checkIntervalRef.current = null - } + try { + setIsFetching(true) + setError(null) + + logger.info('[useFetchProfile] Calling checkProfile', { + pubkey: extractedPubkey + }) + + // Initial fetch - fetchReplaceableEvent checks: 1) in-memory, 2) IndexedDB, 3) network + const found = await checkProfile(extractedPubkey, cancelled) + + logger.info('[useFetchProfile] checkProfile returned', { + pubkey: extractedPubkey, + found, + cancelled: cancelled.current + }) + + if (cancelled.current) { + logger.info('[useFetchProfile] Cancelled after checkProfile, cleaning up') + setIsFetching(false) return } - checkCount++ - const found = await checkProfile(pubkey, cancelled) if (found) { - // Profile found, stop checking - if (checkIntervalRef.current) { - clearInterval(checkIntervalRef.current) - checkIntervalRef.current = null + logger.info('[useFetchProfile] Profile found, done') + // Profile found (from cache or network), we're done + return + } + + logger.info('[useFetchProfile] No profile found, setting up interval retry') + // No profile found yet - set fetching to false so UI can show fallback + // The profile will remain null, allowing components to show npub fallback + setIsFetching(false) + setError(null) // Clear any previous errors + + // If no profile was found, periodically re-check (profiles might load asynchronously) + // Check every 2 seconds for up to 30 seconds (15 checks) + let checkCount = 0 + const maxChecks = 15 + + checkIntervalRef.current = setInterval(async () => { + if (cancelled.current || checkCount >= maxChecks) { + if (checkIntervalRef.current) { + clearInterval(checkIntervalRef.current) + checkIntervalRef.current = null + } + return } + + checkCount++ + const found = await checkProfile(extractedPubkey, cancelled) + if (found || cancelled.current) { + // Profile found or cancelled, stop checking + if (checkIntervalRef.current) { + clearInterval(checkIntervalRef.current) + checkIntervalRef.current = null + } + } + }, 2000) // Check every 2 seconds + } catch (err) { + logger.error('[useFetchProfile] run() error', { + pubkey: extractedPubkey, + error: err instanceof Error ? err.message : String(err), + stack: err instanceof Error ? err.stack : undefined + }) + if (!cancelled.current) { + setError(err as Error) + setIsFetching(false) } - }, 2000) // Check every 2 seconds + } } - run() + logger.info('[useFetchProfile] About to call run()', { + pubkey: extractedPubkey + }) + run().catch((err) => { + logger.error('[useFetchProfile] Unhandled error in run()', { + pubkey: extractedPubkey, + error: err instanceof Error ? err.message : String(err), + stack: err instanceof Error ? err.stack : undefined + }) + }) return () => { cancelled.current = true + // Only clear processingPubkeyRef if it matches the current pubkey + // This prevents clearing it if a new fetch has already started + if (processingPubkeyRef.current === extractedPubkey) { + processingPubkeyRef.current = null + } + // Clear interval on cleanup if (checkIntervalRef.current) { clearInterval(checkIntervalRef.current) checkIntervalRef.current = null diff --git a/src/lib/relay-list-builder.ts b/src/lib/relay-list-builder.ts index cf5b7157..1b829a2c 100644 --- a/src/lib/relay-list-builder.ts +++ b/src/lib/relay-list-builder.ts @@ -90,19 +90,32 @@ export async function buildComprehensiveRelayList(options: RelayListBuilderOptio // 4. Author's outboxes (write relays) - where they publish if (authorPubkey) { try { - const authorRelayList = await client.fetchRelayList(authorPubkey) - const authorOutboxes = (authorRelayList.write || []).slice(0, 10) - authorOutboxes.forEach(addRelay) - - // Also include author's read relays (inboxes) for better discovery - const authorInboxes = (authorRelayList.read || []).slice(0, 10) - authorInboxes.forEach(addRelay) - - logger.debug('[RelayListBuilder] Added author relays', { - author: authorPubkey.substring(0, 8), - outboxes: authorOutboxes.length, - inboxes: authorInboxes.length + // Add timeout to prevent hanging - 2 seconds max + const relayListPromise = client.fetchRelayList(authorPubkey) + const timeoutPromise = new Promise((resolve) => { + setTimeout(() => { + logger.debug('[RelayListBuilder] fetchRelayList timeout for author', { + author: authorPubkey.substring(0, 8) + }) + resolve(null) + }, 2000) }) + const authorRelayList = await Promise.race([relayListPromise, timeoutPromise]) + + if (authorRelayList) { + const authorOutboxes = (authorRelayList.write || []).slice(0, 10) + authorOutboxes.forEach(addRelay) + + // Also include author's read relays (inboxes) for better discovery + const authorInboxes = (authorRelayList.read || []).slice(0, 10) + authorInboxes.forEach(addRelay) + + logger.debug('[RelayListBuilder] Added author relays', { + author: authorPubkey.substring(0, 8), + outboxes: authorOutboxes.length, + inboxes: authorInboxes.length + }) + } } catch (error) { logger.debug('[RelayListBuilder] Failed to fetch author relay list', { error }) } @@ -111,12 +124,25 @@ export async function buildComprehensiveRelayList(options: RelayListBuilderOptio // 5. User's own relays (for profiles/metadata) if (includeUserOwnRelays && userPubkey) { try { - const userRelayList = await client.fetchRelayList(userPubkey) - // Include both read and write - const userRead = (userRelayList.read || []).slice(0, 10) - const userWrite = (userRelayList.write || []).slice(0, 10) - userRead.forEach(addRelay) - userWrite.forEach(addRelay) + // Add timeout to prevent hanging - 2 seconds max + const relayListPromise = client.fetchRelayList(userPubkey) + const timeoutPromise = new Promise((resolve) => { + setTimeout(() => { + logger.debug('[RelayListBuilder] fetchRelayList timeout for user', { + user: userPubkey.substring(0, 8) + }) + resolve(null) + }, 2000) + }) + const userRelayList = await Promise.race([relayListPromise, timeoutPromise]) + + if (userRelayList) { + // Include both read and write + const userRead = (userRelayList.read || []).slice(0, 10) + const userWrite = (userRelayList.write || []).slice(0, 10) + userRead.forEach(addRelay) + userWrite.forEach(addRelay) + } // Include local relays from kind 10432 if (includeLocalRelays) { @@ -125,8 +151,8 @@ export async function buildComprehensiveRelayList(options: RelayListBuilderOptio } logger.debug('[RelayListBuilder] Added user own relays', { - read: userRead.length, - write: userWrite.length, + read: userRelayList ? (userRelayList.read || []).length : 0, + write: userRelayList ? (userRelayList.write || []).length : 0, local: includeLocalRelays ? (await getCacheRelayUrls(userPubkey)).length : 0 }) } catch (error) { @@ -135,9 +161,22 @@ export async function buildComprehensiveRelayList(options: RelayListBuilderOptio } else if (userPubkey) { // Even if not including user's own relays, still include user's inboxes for reading try { - const userRelayList = await client.fetchRelayList(userPubkey) - const userInboxes = (userRelayList.read || []).slice(0, 10) - userInboxes.forEach(addRelay) + // Add timeout to prevent hanging - 2 seconds max + const relayListPromise = client.fetchRelayList(userPubkey) + const timeoutPromise = new Promise((resolve) => { + setTimeout(() => { + logger.debug('[RelayListBuilder] fetchRelayList timeout for user inboxes', { + user: userPubkey.substring(0, 8) + }) + resolve(null) + }, 2000) + }) + const userRelayList = await Promise.race([relayListPromise, timeoutPromise]) + + if (userRelayList) { + const userInboxes = (userRelayList.read || []).slice(0, 10) + userInboxes.forEach(addRelay) + } // Include local relays from kind 10432 if enabled if (includeLocalRelays) { @@ -220,13 +259,21 @@ export async function buildReplyWriteRelayList( // OP author's outboxes if (opAuthorPubkey) { try { - const opRelayList = await client.fetchRelayList(opAuthorPubkey) - const opOutboxes = (opRelayList.write || []).slice(0, 10) - opOutboxes.forEach(addRelay) + // Add timeout to prevent hanging - 2 seconds max + const relayListPromise = client.fetchRelayList(opAuthorPubkey) + const timeoutPromise = new Promise((resolve) => { + setTimeout(() => resolve(null), 2000) + }) + const opRelayList = await Promise.race([relayListPromise, timeoutPromise]) - // OP author's inboxes - const opInboxes = (opRelayList.read || []).slice(0, 10) - opInboxes.forEach(addRelay) + if (opRelayList) { + const opOutboxes = (opRelayList.write || []).slice(0, 10) + opOutboxes.forEach(addRelay) + + // OP author's inboxes + const opInboxes = (opRelayList.read || []).slice(0, 10) + opInboxes.forEach(addRelay) + } } catch (error) { logger.debug('[RelayListBuilder] Failed to fetch OP author relay list', { error }) } @@ -235,9 +282,17 @@ export async function buildReplyWriteRelayList( // Reply-to author's inboxes if (replyToAuthorPubkey && replyToAuthorPubkey !== opAuthorPubkey) { try { - const replyToRelayList = await client.fetchRelayList(replyToAuthorPubkey) - const replyToInboxes = (replyToRelayList.read || []).slice(0, 10) - replyToInboxes.forEach(addRelay) + // Add timeout to prevent hanging - 2 seconds max + const relayListPromise = client.fetchRelayList(replyToAuthorPubkey) + const timeoutPromise = new Promise((resolve) => { + setTimeout(() => resolve(null), 2000) + }) + const replyToRelayList = await Promise.race([relayListPromise, timeoutPromise]) + + if (replyToRelayList) { + const replyToInboxes = (replyToRelayList.read || []).slice(0, 10) + replyToInboxes.forEach(addRelay) + } } catch (error) { logger.debug('[RelayListBuilder] Failed to fetch reply-to author relay list', { error }) } @@ -246,9 +301,17 @@ export async function buildReplyWriteRelayList( // User's outboxes if (userPubkey) { try { - const userRelayList = await client.fetchRelayList(userPubkey) - const userOutboxes = (userRelayList.write || []).slice(0, 10) - userOutboxes.forEach(addRelay) + // Add timeout to prevent hanging - 2 seconds max + const relayListPromise = client.fetchRelayList(userPubkey) + const timeoutPromise = new Promise((resolve) => { + setTimeout(() => resolve(null), 2000) + }) + const userRelayList = await Promise.race([relayListPromise, timeoutPromise]) + + if (userRelayList) { + const userOutboxes = (userRelayList.write || []).slice(0, 10) + userOutboxes.forEach(addRelay) + } // User's local relay (kind 10432) const localRelays = await getCacheRelayUrls(userPubkey) diff --git a/src/services/client-replaceable-events.service.ts b/src/services/client-replaceable-events.service.ts index 637968c0..50622221 100644 --- a/src/services/client-replaceable-events.service.ts +++ b/src/services/client-replaceable-events.service.ts @@ -134,10 +134,34 @@ export class ReplaceableEventService { d?: string, containingEventRelays: string[] = [] ): Promise { + const cacheKey = d ? `${kind}:${pubkey}:${d}` : `${kind}:${pubkey}` + logger.info('[ReplaceableEventService] fetchReplaceableEvent start', { + pubkey, + kind, + d, + cacheKey, + containingEventRelays: containingEventRelays.length + }) + // 1. Check IndexedDB (async but faster than network) try { + logger.info('[ReplaceableEventService] Checking IndexedDB', { + pubkey, + kind + }) const indexedDbCached = await indexedDb.getReplaceableEvent(pubkey, kind, d) + logger.info('[ReplaceableEventService] IndexedDB query completed', { + pubkey, + kind, + found: !!indexedDbCached + }) if (indexedDbCached) { + logger.info('[ReplaceableEventService] Found in IndexedDB', { + pubkey, + kind, + eventId: indexedDbCached.id, + created_at: indexedDbCached.created_at + }) // Check tombstone in background (non-blocking) const tombstoneKey = isReplaceableEvent(kind) ? getReplaceableCoordinateFromEvent(indexedDbCached) @@ -145,9 +169,10 @@ export class ReplaceableEventService { indexedDb.isTombstoned(tombstoneKey).then(isTombstoned => { if (isTombstoned) { // Event is tombstoned - will be handled by IndexedDB cleanup - logger.debug('[ReplaceableEventService] Event is tombstoned', { - pubkey: formatPubkey(pubkey), - kind + logger.warn('[ReplaceableEventService] Event is tombstoned', { + pubkey, + kind, + tombstoneKey }) } }).catch(() => { @@ -158,26 +183,44 @@ export class ReplaceableEventService { this.refreshInBackground(pubkey, kind, d).catch(() => {}) return indexedDbCached } + logger.info('[ReplaceableEventService] Not found in IndexedDB', { + pubkey, + kind + }) } catch (error) { // IndexedDB error - continue to network fetch logger.warn('[ReplaceableEventService] IndexedDB error', { - pubkey: formatPubkey(pubkey), + pubkey, kind, - error: error instanceof Error ? error.message : String(error) + error: error instanceof Error ? error.message : String(error), + stack: error instanceof Error ? error.stack : undefined }) } // 2. Not in cache, fetch from network - // Note: DataLoader will use comprehensive relay list from batch load function - // For profiles: if we have containingEventRelays (from fetchProfileEvent), include them - // Profiles are often on the same relays where the author publishes their events + logger.info('[ReplaceableEventService] Fetching from network', { + pubkey, + kind, + usingContainingRelays: containingEventRelays.length > 0 && kind === kinds.Metadata && !d + }) + try { // If we have containing event relays and this is a profile, we need to use a custom relay list // Otherwise, use DataLoader (which uses comprehensive relay list) let event: NEvent | undefined if (containingEventRelays.length > 0 && kind === kinds.Metadata && !d) { // For profiles with containing event relays (author's relay list), build custom relay list and query directly + logger.info('[ReplaceableEventService] Building relay list with containing event relays', { + pubkey, + containingRelayCount: containingEventRelays.length + }) const relayUrls = await this.buildComprehensiveRelayListForAuthor(pubkey, kind, containingEventRelays, []) + logger.info('[ReplaceableEventService] Querying relays', { + pubkey, + relayCount: relayUrls.length, + relays: relayUrls.slice(0, 5) // Log first 5 for debugging + }) + const startTime = Date.now() const events = await this.queryService.query(relayUrls, { authors: [pubkey], kinds: [kind] @@ -186,24 +229,51 @@ export class ReplaceableEventService { eoseTimeout: 200, globalTimeout: 3000 }) + const queryTime = Date.now() - startTime + logger.info('[ReplaceableEventService] Query completed', { + pubkey, + eventCount: events.length, + queryTime: `${queryTime}ms` + }) const sortedEvents = events.sort((a, b) => b.created_at - a.created_at) event = sortedEvents.length > 0 ? sortedEvents[0] : undefined } else { // Use DataLoader for batching + logger.info('[ReplaceableEventService] Using DataLoader', { + pubkey, + kind, + d, + kindValue: kind, + isMetadata: kind === kinds.Metadata, + expectedMetadata: kinds.Metadata + }) + const startTime = Date.now() const loadedEvent = d ? await this.replaceableEventDataLoader.load({ pubkey, kind, d }) : await this.replaceableEventFromBigRelaysDataloader.load({ pubkey, kind }) + const loadTime = Date.now() - startTime + logger.info('[ReplaceableEventService] DataLoader completed', { + pubkey, + found: !!loadedEvent, + loadTime: `${loadTime}ms` + }) event = loadedEvent || undefined } if (event) { + logger.info('[ReplaceableEventService] Event found from network', { + pubkey, + kind, + eventId: event.id, + created_at: event.created_at + }) // Extract relay hints from the found event (for future related fetches) const eventRelayHints = this.extractRelayHintsFromEvent(event) // If we found relay hints, log them (they're already used in the batch load function) if (eventRelayHints.length > 0) { logger.debug('[ReplaceableEventService] Found relay hints in event', { - pubkey: formatPubkey(pubkey), + pubkey, hintCount: eventRelayHints.length }) } @@ -213,20 +283,32 @@ export class ReplaceableEventService { // Log when no event is found (helps debug relay failures) if (kind === kinds.Metadata) { - logger.debug('[ReplaceableEventService] No profile found for pubkey', { - pubkey: formatPubkey(pubkey) + logger.warn('[ReplaceableEventService] No profile found for pubkey', { + pubkey, + cacheKey }) } } catch (error) { // Log errors but don't throw - return undefined so UI can show fallback if (kind === kinds.Metadata) { - logger.warn('[ReplaceableEventService] Error fetching profile', { - pubkey: formatPubkey(pubkey), + logger.error('[ReplaceableEventService] Error fetching profile', { + pubkey, + error: error instanceof Error ? error.message : String(error), + stack: error instanceof Error ? error.stack : undefined + }) + } else { + logger.warn('[ReplaceableEventService] Error fetching replaceable event', { + pubkey, + kind, error: error instanceof Error ? error.message : String(error) }) } } + logger.info('[ReplaceableEventService] fetchReplaceableEvent returning undefined', { + pubkey, + kind + }) return undefined } @@ -311,6 +393,10 @@ export class ReplaceableEventService { private async replaceableEventFromBigRelaysBatchLoadFn( params: readonly { pubkey: string; kind: number }[] ): Promise<(NEvent | null)[]> { + logger.info('[ReplaceableEventService] Batch load function called', { + paramCount: params.length, + pubkeys: params.map(p => p.pubkey.substring(0, 8)) + }) const groups = new Map() params.forEach(({ pubkey, kind }) => { if (!groups.has(kind)) { @@ -325,12 +411,21 @@ export class ReplaceableEventService { // ALWAYS use comprehensive relay list: author's outboxes + user's inboxes + defaults // For profiles/metadata: includes user's own relays (read/write/local) + PROFILE_FETCH_RELAY_URLS // For each pubkey, build comprehensive relay list + logger.info('[ReplaceableEventService] Building relay lists for batch', { + kind, + pubkeyCount: pubkeys.length + }) const relayUrlSets = await Promise.all( pubkeys.map(async (pubkey) => { // Build comprehensive relay list for this author return await this.buildComprehensiveRelayListForAuthor(pubkey, kind, [], []) }) ) + logger.info('[ReplaceableEventService] Relay lists built, merging', { + kind, + pubkeyCount: pubkeys.length, + relayListCount: relayUrlSets.length + }) // Merge all relay sets const mergedRelays = new Set() @@ -339,15 +434,20 @@ export class ReplaceableEventService { }) const relayUrls = Array.from(mergedRelays) - logger.debug('[ReplaceableEventService] Using comprehensive relay list', { + logger.info('[ReplaceableEventService] Using comprehensive relay list', { pubkeyCount: pubkeys.length, totalRelayCount: relayUrls.length, - kind + kind, + relays: relayUrls.slice(0, 5) // Show first 5 for debugging }) // Use all relays in parallel - browsers can handle many concurrent subscriptions // The QueryService manages per-relay concurrency limits to avoid overloading individual relays - + logger.info('[ReplaceableEventService] Starting query for batch', { + kind, + pubkeyCount: pubkeys.length, + relayCount: relayUrls.length + }) const events = await this.queryService.query(relayUrls, { authors: pubkeys, kinds: [kind] @@ -356,6 +456,11 @@ export class ReplaceableEventService { eoseTimeout: 200, globalTimeout: 3000 }) + logger.info('[ReplaceableEventService] Query completed for batch', { + kind, + pubkeyCount: pubkeys.length, + eventCount: events.length + }) // Log when no events are found (helps debug relay failures) if (kind === kinds.Metadata && events.length === 0 && pubkeys.length > 0) { @@ -376,7 +481,7 @@ export class ReplaceableEventService { }) ) - return params.map(({ pubkey, kind }) => { + const results = params.map(({ pubkey, kind }) => { const key = `${pubkey}:${kind}` const event = eventsMap.get(key) if (event) { @@ -387,6 +492,11 @@ export class ReplaceableEventService { return null } }) + logger.info('[ReplaceableEventService] Batch load function completed', { + paramCount: params.length, + foundCount: results.filter(r => r !== null).length + }) + return results } /** @@ -469,52 +579,109 @@ export class ReplaceableEventService { * Fetch profile event by id (hex, npub, nprofile) */ async fetchProfileEvent(id: string, _skipCache: boolean = false): Promise { + logger.info('[ReplaceableEventService] fetchProfileEvent start', { id }) + let pubkey: string | undefined let relays: string[] = [] if (/^[0-9a-f]{64}$/.test(id)) { pubkey = id + logger.info('[ReplaceableEventService] ID is hex pubkey', { pubkey }) } else { - const { data, type } = nip19.decode(id) - switch (type) { - case 'npub': - pubkey = data - break - case 'nprofile': - pubkey = data.pubkey - if (data.relays) relays = data.relays - break + try { + const { data, type } = nip19.decode(id) + logger.info('[ReplaceableEventService] Decoded bech32 ID', { type }) + switch (type) { + case 'npub': + pubkey = data + break + case 'nprofile': + pubkey = data.pubkey + if (data.relays) relays = data.relays + logger.info('[ReplaceableEventService] nprofile has relay hints', { relayCount: relays.length }) + break + } + } catch (error) { + logger.error('[ReplaceableEventService] Failed to decode bech32 ID', { + id, + error: error instanceof Error ? error.message : String(error) + }) } } if (!pubkey) { + logger.error('[ReplaceableEventService] Invalid id - no pubkey extracted', { id }) throw new Error('Invalid id') } + logger.info('[ReplaceableEventService] Fetching author relay list', { + pubkey + }) + // For profiles: get author's relay list (from cache if available) and use those relays // Profiles are often on the same relays where the author publishes their events let authorRelayList: { read?: string[]; write?: string[] } | null = null try { - authorRelayList = await client.fetchRelayList(pubkey) - // Use author's outboxes (write relays) and inboxes (read relays) - profiles are often there - const authorRelays = [ - ...(authorRelayList.write || []).slice(0, 10), - ...(authorRelayList.read || []).slice(0, 10) - ] - relays = [...new Set([...relays, ...authorRelays])] - logger.debug('[ReplaceableEventService] Using author relay list for profile fetch', { - pubkey: formatPubkey(pubkey), - authorRelayCount: authorRelays.length, - totalRelayCount: relays.length + const relayListStartTime = Date.now() + logger.info('[ReplaceableEventService] About to call client.fetchRelayList', { + pubkey + }) + // Add timeout to prevent hanging - 2 seconds max + const relayListPromise = client.fetchRelayList(pubkey) + const timeoutPromise = new Promise((resolve) => { + setTimeout(() => { + logger.warn('[ReplaceableEventService] fetchRelayList timeout, continuing without author relays', { + pubkey + }) + resolve(null) + }, 2000) + }) + authorRelayList = await Promise.race([relayListPromise, timeoutPromise]) + const relayListTime = Date.now() - relayListStartTime + logger.info('[ReplaceableEventService] client.fetchRelayList returned', { + pubkey, + hasRelayList: !!authorRelayList, + fetchTime: `${relayListTime}ms` }) + // Use author's outboxes (write relays) and inboxes (read relays) - profiles are often there + if (authorRelayList) { + const authorRelays = [ + ...(authorRelayList.write || []).slice(0, 10), + ...(authorRelayList.read || []).slice(0, 10) + ] + relays = [...new Set([...relays, ...authorRelays])] + logger.info('[ReplaceableEventService] Using author relay list for profile fetch', { + pubkey, + authorRelayCount: authorRelays.length, + totalRelayCount: relays.length, + fetchTime: `${relayListTime}ms`, + writeRelays: authorRelayList.write?.slice(0, 3) || [], + readRelays: authorRelayList.read?.slice(0, 3) || [] + }) + } else { + logger.info('[ReplaceableEventService] No author relay list available, using default relays', { + pubkey, + existingRelayCount: relays.length + }) + } } catch (error) { - logger.debug('[ReplaceableEventService] Failed to fetch author relay list for profile', { - pubkey: formatPubkey(pubkey), - error + logger.error('[ReplaceableEventService] Failed to fetch author relay list for profile', { + pubkey, + error: error instanceof Error ? error.message : String(error), + stack: error instanceof Error ? error.stack : undefined }) } // Use fetchReplaceableEvent which checks IndexedDB then network + logger.info('[ReplaceableEventService] Calling fetchReplaceableEvent', { + pubkey, + relayCount: relays.length + }) const profileEvent = await this.fetchReplaceableEvent(pubkey, kinds.Metadata, undefined, relays) + logger.info('[ReplaceableEventService] fetchReplaceableEvent returned', { + pubkey, + hasEvent: !!profileEvent, + eventId: profileEvent?.id + }) if (profileEvent) { await this.indexProfile(profileEvent) return profileEvent diff --git a/src/services/client.service.ts b/src/services/client.service.ts index f252a559..b53d3eb5 100644 --- a/src/services/client.service.ts +++ b/src/services/client.service.ts @@ -187,7 +187,7 @@ class ClientService extends EventTarget { ) { if (event.kind === kinds.RelayList) { logger.info('[DetermineTargetRelays] Determining target relays for relay list event', { - pubkey: event.pubkey?.substring(0, 8), + pubkey: event.pubkey, hasSpecifiedRelays: !!specifiedRelayUrls?.length, specifiedRelayCount: specifiedRelayUrls?.length ?? 0, hasAdditionalRelays: !!additionalRelayUrls?.length, @@ -273,7 +273,7 @@ class ClientService extends EventTarget { spellRelayList = await this.fetchRelayList(event.pubkey) } catch (err) { logger.warn('[DetermineTargetRelays] fetchRelayList failed for spell', { - pubkey: event.pubkey?.substring(0, 8), + pubkey: event.pubkey, error: err instanceof Error ? err.message : String(err) }) spellRelayList = { write: [], read: [], originalRelays: [] } @@ -351,7 +351,7 @@ class ClientService extends EventTarget { if (event.kind === kinds.RelayList || event.kind === ExtendedKind.FAVORITE_RELAYS) { logger.debug('[DetermineTargetRelays] Fetching user relay list for event publication', { - pubkey: event.pubkey?.substring(0, 8), + pubkey: event.pubkey, kind: event.kind }) } @@ -360,7 +360,7 @@ class ClientService extends EventTarget { relayList = await this.fetchRelayList(event.pubkey) } catch (err) { logger.warn('[DetermineTargetRelays] fetchRelayList failed, using fallback relays', { - pubkey: event.pubkey?.substring(0, 8), + pubkey: event.pubkey, error: err instanceof Error ? err.message : String(err) }) relayList = { write: [], read: [], originalRelays: [] } @@ -1788,18 +1788,18 @@ class ClientService extends EventTarget { // Deduplicate concurrent requests for the same pubkey's relay list const existingRequest = this.relayListRequestCache.get(pubkey) if (existingRequest) { - logger.debug('[FetchRelayList] Using cached in-flight request', { pubkey: pubkey.substring(0, 8) }) + logger.debug('[FetchRelayList] Using cached in-flight request', { pubkey }) return existingRequest } - logger.debug('[FetchRelayList] Starting fetch', { pubkey: pubkey.substring(0, 8) }) + logger.debug('[FetchRelayList] Starting fetch', { pubkey }) const requestPromise = (async () => { try { const startTime = Date.now() const [relayList] = await this.fetchRelayLists([pubkey]) const duration = Date.now() - startTime logger.debug('[FetchRelayList] Fetch completed', { - pubkey: pubkey.substring(0, 8), + pubkey, duration: `${duration}ms`, hasRelayList: !!relayList, writeCount: relayList?.write?.length ?? 0, @@ -1808,7 +1808,7 @@ class ClientService extends EventTarget { return relayList } catch (error) { logger.error('[FetchRelayList] Fetch failed', { - pubkey: pubkey.substring(0, 8), + pubkey, error: error instanceof Error ? error.message : String(error) }) throw error diff --git a/src/services/indexed-db.service.ts b/src/services/indexed-db.service.ts index ae929097..9defd225 100644 --- a/src/services/indexed-db.service.ts +++ b/src/services/indexed-db.service.ts @@ -282,7 +282,7 @@ class IndexedDbService { : event.id const isTombstoned = await this.isTombstoned(tombstoneKey) if (isTombstoned) { - logger.debug('[IndexedDB] Skipping tombstoned event', { tombstoneKey, eventId: event.id?.substring(0, 8) }) + logger.debug('[IndexedDB] Skipping tombstoned event', { tombstoneKey, eventId: event.id }) return Promise.reject(new Error('Event is tombstoned')) } @@ -299,10 +299,9 @@ class IndexedDbService { logger.debug('[IndexedDB] Putting replaceable event', { kind: cleanEvent.kind, storeName, - eventId: cleanEvent.id?.substring(0, 8), - pubkey: cleanEvent.pubkey?.substring(0, 8), - created_at: cleanEvent.created_at, - fullEventId: cleanEvent.id + eventId: cleanEvent.id, + pubkey: cleanEvent.pubkey, + created_at: cleanEvent.created_at }) await this.initPromise @@ -343,7 +342,7 @@ class IndexedDbService { logger.debug('[IndexedDB] Store exists, proceeding with save', { storeName, kind: cleanEvent.kind, - eventId: cleanEvent.id?.substring(0, 8), + eventId: cleanEvent.id, dbVersion: this.db.version, allStores: Array.from(this.db.objectStoreNames) }) @@ -352,7 +351,7 @@ class IndexedDbService { const store = transaction.objectStore(storeName) const key = this.getReplaceableEventKeyFromEvent(cleanEvent) - logger.debug('[IndexedDB] Getting existing event', { storeName, key, eventId: cleanEvent.id?.substring(0, 8) }) + logger.debug('[IndexedDB] Getting existing event', { storeName, key, eventId: cleanEvent.id }) const getRequest = store.get(key) getRequest.onsuccess = () => { @@ -361,7 +360,7 @@ class IndexedDbService { logger.debug('[IndexedDB] Found existing event', { storeName, key, - oldEventId: oldValue.value.id?.substring(0, 8), + oldEventId: oldValue.value.id, oldCreatedAt: oldValue.value.created_at, newCreatedAt: cleanEvent.created_at, willUpdate: cleanEvent.created_at > oldValue.value.created_at @@ -374,7 +373,7 @@ class IndexedDbService { logger.debug('[IndexedDB] Keeping existing event (newer or same timestamp)', { storeName, key, - existingEventId: oldValue.value.id?.substring(0, 8) + existingEventId: oldValue.value.id }) transaction.commit() return resolve(oldValue.value) @@ -383,17 +382,16 @@ class IndexedDbService { logger.debug('[IndexedDB] Putting new event', { storeName, key, - eventId: cleanEvent.id?.substring(0, 8), - fullEventId: cleanEvent.id, - content: cleanEvent.content?.substring(0, 50) + eventId: cleanEvent.id, + content: cleanEvent.content }) const putRequest = store.put(this.formatValue(key, cleanEvent)) putRequest.onsuccess = () => { logger.debug('[IndexedDB] Successfully put event', { storeName, key, - eventId: cleanEvent.id?.substring(0, 8), - content: cleanEvent.content?.substring(0, 50) + eventId: cleanEvent.id, + content: cleanEvent.content }) transaction.commit() resolve(cleanEvent) @@ -448,6 +446,11 @@ class IndexedDbService { request.onsuccess = () => { const row = request.result as TValue | undefined if (!row) { + logger.debug('[IndexedDB] getReplaceableEvent - no row found', { + pubkey, + kind, + d + }) transaction.commit() return resolve(undefined) } @@ -459,11 +462,18 @@ class IndexedDbService { // Profile is stale, but return it anyway - refresh will happen in background // This prevents the "no profile" state when cache exists but is just old logger.debug('[IndexedDB] Profile cache is stale but returning anyway', { - pubkey: pubkey.substring(0, 8), + pubkey, age: Date.now() - row.addedAt, - maxAge: PROFILE_AND_PAYMENT_CACHE_MAX_AGE_MS + maxAge: PROFILE_AND_PAYMENT_CACHE_MAX_AGE_MS, + eventId: row.value?.id }) } + logger.debug('[IndexedDB] getReplaceableEvent - found', { + pubkey, + kind, + eventId: row.value?.id, + addedAt: row.addedAt + }) transaction.commit() resolve(row.value) }