Skip to content

Commit e0b4d15

Browse files
pheubergerpheuberger
authored
Merge pull request #18 from pheuberger/bla
debug: add comprehensive logging for bookmark sync debugging
2 parents 4bdc053 + 989b74a commit e0b4d15

2 files changed

Lines changed: 244 additions & 5 deletions

File tree

‎src/hooks/useNostrSync.js‎

Lines changed: 205 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -39,6 +39,151 @@ let initializationPromise = null // Guard against concurrent initialization
3939
let processedEventIds = new Set() // Track processed events to prevent duplicates
4040
let deletedBookmarkIds = new Set() // Track deleted bookmarks to skip duplicate delete events
4141

42+
// ============================================================================
43+
// DEBUG UTILITIES - Remove after fixing bookmark undo persistence issue
44+
// ============================================================================
45+
const DEBUG_SYNC = true // Set to false to disable verbose logging
46+
47+
const syncDebug = {
48+
eventLog: [], // Chronological log of all events
49+
bookmarkSnapshots: new Map(), // bookmarkId -> array of state snapshots
50+
51+
log(type, data) {
52+
const entry = {
53+
time: new Date().toISOString(),
54+
timestamp: Date.now(),
55+
type,
56+
...data
57+
}
58+
this.eventLog.push(entry)
59+
if (DEBUG_SYNC) {
60+
const prefix = type.includes('DELETE') ? '🗑️' : type.includes('BOOKMARK') ? '📖' : 'ℹ️'
61+
console.log(`[SyncDebug] ${prefix} ${type}`, data)
62+
}
63+
},
64+
65+
snapshot(bookmarkId, state, source) {
66+
if (!this.bookmarkSnapshots.has(bookmarkId)) {
67+
this.bookmarkSnapshots.set(bookmarkId, [])
68+
}
69+
this.bookmarkSnapshots.get(bookmarkId).push({
70+
time: new Date().toISOString(),
71+
timestamp: Date.now(),
72+
source,
73+
state: JSON.parse(JSON.stringify(state))
74+
})
75+
},
76+
77+
// Get timeline for a specific bookmark
78+
getTimeline(bookmarkId) {
79+
return this.bookmarkSnapshots.get(bookmarkId) || []
80+
},
81+
82+
// Get all events for a bookmark
83+
getEventsFor(bookmarkId) {
84+
return this.eventLog.filter(e => e.bookmarkId === bookmarkId)
85+
},
86+
87+
// Print summary
88+
printSummary() {
89+
console.log('=== SYNC DEBUG SUMMARY ===')
90+
console.log(`Total events: ${this.eventLog.length}`)
91+
console.log(`Bookmarks tracked: ${this.bookmarkSnapshots.size}`)
92+
console.log('\nEvent breakdown:')
93+
const counts = {}
94+
this.eventLog.forEach(e => { counts[e.type] = (counts[e.type] || 0) + 1 })
95+
Object.entries(counts).forEach(([type, count]) => console.log(` ${type}: ${count}`))
96+
},
97+
98+
// Republish a bookmark with fresh timestamp (to fix "doomed" bookmarks)
99+
async republishBookmark(bookmarkId) {
100+
const ydoc = getYdocInstance()
101+
if (!ydoc) {
102+
console.error('Ydoc not available')
103+
return
104+
}
105+
const bookmarksMap = ydoc.getMap('bookmarks')
106+
const bookmark = bookmarksMap.get(bookmarkId)
107+
if (!bookmark) {
108+
console.error(`Bookmark ${bookmarkId} not found locally. It may have been deleted.`)
109+
console.log('Tip: Call this right after you see the bookmark flash, or check syncDebug.eventLog for the bookmark data')
110+
return
111+
}
112+
113+
const data = bookmark.get ? {
114+
url: bookmark.get('url'),
115+
title: bookmark.get('title'),
116+
description: bookmark.get('description') || '',
117+
tags: bookmark.get('tags')?.toArray?.() || bookmark.get('tags') || [],
118+
readLater: bookmark.get('readLater') || false,
119+
inbox: bookmark.get('inbox') || false,
120+
favicon: bookmark.get('favicon') || null,
121+
preview: bookmark.get('preview') || null,
122+
createdAt: bookmark.get('createdAt'),
123+
updatedAt: Date.now(), // Fresh timestamp!
124+
} : { ...bookmark, updatedAt: Date.now() }
125+
126+
// Save locally with fresh timestamp
127+
ydoc.transact(() => {
128+
bookmarksMap.set(bookmarkId, data)
129+
}, 'local')
130+
131+
// Publish to Nostr
132+
if (nostrSyncService && nostrSyncService.isInitialized) {
133+
await nostrSyncService.queueBookmarkUpdate(bookmarkId, data)
134+
console.log(`✅ Republished ${bookmarkId} with fresh timestamp: ${data.updatedAt}`)
135+
} else {
136+
console.log(`⚠️ Saved locally but Nostr not connected. Will sync when connected.`)
137+
}
138+
},
139+
140+
// Republish from cached event data (for bookmarks that flash and disappear)
141+
async republishFromCache(bookmarkId) {
142+
const events = this.getEventsFor(bookmarkId)
143+
const bookmarkEvent = events.find(e => e.type === 'BOOKMARK_RECEIVED' && e.bookmarkData)
144+
if (!bookmarkEvent) {
145+
console.error(`No cached bookmark data for ${bookmarkId}`)
146+
console.log('Available bookmark IDs in cache:', [...new Set(this.eventLog.filter(e => e.bookmarkData).map(e => e.bookmarkId))])
147+
return
148+
}
149+
150+
const ydoc = getYdocInstance()
151+
const bookmarksMap = ydoc.getMap('bookmarks')
152+
const freshData = { ...bookmarkEvent.bookmarkData, updatedAt: Date.now() }
153+
154+
// Save locally
155+
ydoc.transact(() => {
156+
bookmarksMap.set(bookmarkId, freshData)
157+
}, 'local')
158+
159+
// Publish to Nostr
160+
if (nostrSyncService && nostrSyncService.isInitialized) {
161+
await nostrSyncService.queueBookmarkUpdate(bookmarkId, freshData)
162+
console.log(`✅ Republished ${bookmarkId} from cache with fresh timestamp: ${freshData.updatedAt}`)
163+
} else {
164+
console.log(`⚠️ Saved locally but Nostr not connected.`)
165+
}
166+
}
167+
}
168+
169+
// Expose debug utilities on window
170+
if (typeof window !== 'undefined') {
171+
window.__syncDebug = syncDebug
172+
window.__getNostrSync = () => nostrSyncService
173+
window.__getYdoc = getYdocInstance
174+
console.log(`
175+
🔧 NOSTR SYNC DEBUG UTILITIES AVAILABLE:
176+
window.__syncDebug.printSummary() - Print event summary
177+
window.__syncDebug.eventLog - All events (chronological)
178+
window.__syncDebug.getEventsFor(id) - Events for specific bookmark
179+
window.__syncDebug.getTimeline(id) - State snapshots for bookmark
180+
window.__syncDebug.republishBookmark(id) - Fix a doomed bookmark (if visible)
181+
window.__syncDebug.republishFromCache(id) - Fix from cached data (after flash)
182+
window.__getYdoc() - Get Yjs document
183+
window.__getNostrSync() - Get NostrSyncService instance
184+
`)
185+
}
186+
42187
/**
43188
* Convert a plain bookmark object to a Y.Map for Yjs storage
44189
* @param {Object} bookmarkData - Plain bookmark object from Nostr
@@ -350,13 +495,27 @@ export function useNostrSync(options = {}) {
350495
// Set up bookmark sync subscription with performance optimizations
351496
bookmarkSubscriptionRef.current = await nostrSyncService.subscribeToBookmarks(
352497
async (bookmarkId, bookmarkData, event) => {
498+
// Log incoming bookmark event
499+
syncDebug.log('BOOKMARK_RECEIVED', {
500+
bookmarkId,
501+
eventId: event?.id?.substring(0, 12),
502+
eventCreatedAt: event?.created_at,
503+
eventCreatedAtDate: event?.created_at ? new Date(event.created_at * 1000).toISOString() : null,
504+
bookmarkUpdatedAt: bookmarkData?.updatedAt,
505+
bookmarkUpdatedAtDate: bookmarkData?.updatedAt ? new Date(bookmarkData.updatedAt).toISOString() : null,
506+
bookmarkTitle: bookmarkData?.title,
507+
bookmarkData: bookmarkData, // Cache full data for republishing
508+
})
509+
353510
// Early validation - skip invalid/empty bookmarks immediately
354511
if (!bookmarkData || !bookmarkData.url || !bookmarkData.title) {
512+
syncDebug.log('BOOKMARK_SKIPPED_INVALID', { bookmarkId, reason: 'missing url or title' })
355513
return
356514
}
357515

358516
// Deduplicate: skip if we've already processed this event
359517
if (event?.id && processedEventIds.has(event.id)) {
518+
syncDebug.log('BOOKMARK_SKIPPED_DUPLICATE', { bookmarkId, eventId: event.id.substring(0, 12) })
360519
return
361520
}
362521
if (event?.id) {
@@ -378,13 +537,29 @@ export function useNostrSync(options = {}) {
378537
const existing = bookmarksMap.get(bookmarkId)
379538
// Handle both Y.Map (local) and plain object (legacy) formats
380539
const existingUpdatedAt = existing?.get ? existing.get('updatedAt') : existing?.updatedAt
540+
541+
syncDebug.log('BOOKMARK_APPLY_CHECK', {
542+
bookmarkId,
543+
hasExisting: !!existing,
544+
existingUpdatedAt,
545+
existingUpdatedAtDate: existingUpdatedAt ? new Date(existingUpdatedAt).toISOString() : null,
546+
incomingUpdatedAt: bookmarkData.updatedAt,
547+
incomingUpdatedAtDate: new Date(bookmarkData.updatedAt).toISOString(),
548+
willApply: !existing || !existingUpdatedAt || existingUpdatedAt < bookmarkData.updatedAt,
549+
reason: !existing ? 'no local copy' : !existingUpdatedAt ? 'no local timestamp' : existingUpdatedAt < bookmarkData.updatedAt ? 'incoming is newer' : 'local is same or newer',
550+
})
551+
381552
if (!existing || !existingUpdatedAt || existingUpdatedAt < bookmarkData.updatedAt) {
382553
// Convert plain object to Y.Map for consistent Yjs storage
383554
const bookmarkYMap = bookmarkDataToYMap(bookmarkData)
384555
// Use transaction with 'nostr-sync' origin so observer knows not to re-publish
385556
ydoc.transact(() => {
386557
bookmarksMap.set(bookmarkId, bookmarkYMap)
387558
}, 'nostr-sync')
559+
syncDebug.log('BOOKMARK_APPLIED', { bookmarkId, updatedAt: bookmarkData.updatedAt })
560+
syncDebug.snapshot(bookmarkId, bookmarkData, 'nostr-incoming')
561+
} else {
562+
syncDebug.log('BOOKMARK_SKIPPED_OLDER', { bookmarkId, existingUpdatedAt, incomingUpdatedAt: bookmarkData.updatedAt })
388563
}
389564
}
390565
setLastSyncTime(Date.now())
@@ -393,8 +568,19 @@ export function useNostrSync(options = {}) {
393568
setLastSyncTime(Date.now())
394569
},
395570
async (bookmarkId, event) => {
571+
// Log incoming deletion event
572+
const deletionTime = event?.created_at ? event.created_at * 1000 : 0
573+
syncDebug.log('DELETE_RECEIVED', {
574+
bookmarkId,
575+
eventId: event?.id?.substring(0, 12),
576+
eventCreatedAt: event?.created_at,
577+
eventCreatedAtDate: event?.created_at ? new Date(event.created_at * 1000).toISOString() : null,
578+
deletionTimeMs: deletionTime,
579+
})
580+
396581
// Deduplicate: skip if we've already processed this event
397582
if (event?.id && processedEventIds.has(event.id)) {
583+
syncDebug.log('DELETE_SKIPPED_DUPLICATE_EVENT', { bookmarkId, eventId: event.id.substring(0, 12) })
398584
return
399585
}
400586
if (event?.id) {
@@ -403,6 +589,7 @@ export function useNostrSync(options = {}) {
403589

404590
// Deduplicate: skip if we've already deleted this bookmark
405591
if (deletedBookmarkIds.has(bookmarkId)) {
592+
syncDebug.log('DELETE_SKIPPED_ALREADY_DELETED', { bookmarkId })
406593
return
407594
}
408595

@@ -419,12 +606,24 @@ export function useNostrSync(options = {}) {
419606
if (existing) {
420607
const updatedAt = existing?.get ? existing.get('updatedAt') : existing?.updatedAt
421608
// Nostr events use seconds, our timestamps use milliseconds
422-
const deletionTime = event?.created_at ? event.created_at * 1000 : 0
423-
424-
if (updatedAt && updatedAt > deletionTime) {
425-
console.log('[useNostrSync] Skipping deletion - local bookmark is newer:', bookmarkId, { updatedAt, deletionTime })
609+
const deletionTimeMs = event?.created_at ? event.created_at * 1000 : 0
610+
611+
syncDebug.log('DELETE_APPLY_CHECK', {
612+
bookmarkId,
613+
localUpdatedAt: updatedAt,
614+
localUpdatedAtDate: updatedAt ? new Date(updatedAt).toISOString() : null,
615+
deletionTimeMs,
616+
deletionTimeDate: new Date(deletionTimeMs).toISOString(),
617+
localIsNewer: updatedAt && updatedAt > deletionTimeMs,
618+
willDelete: !(updatedAt && updatedAt > deletionTimeMs),
619+
})
620+
621+
if (updatedAt && updatedAt > deletionTimeMs) {
622+
syncDebug.log('DELETE_SKIPPED_LOCAL_NEWER', { bookmarkId, localUpdatedAt: updatedAt, deletionTimeMs })
426623
return
427624
}
625+
} else {
626+
syncDebug.log('DELETE_NO_LOCAL_COPY', { bookmarkId, willDelete: false })
428627
}
429628

430629
// Track this deletion
@@ -439,6 +638,8 @@ export function useNostrSync(options = {}) {
439638
ydoc.transact(() => {
440639
bookmarksMap.delete(bookmarkId)
441640
}, 'nostr-sync')
641+
syncDebug.log('DELETE_APPLIED', { bookmarkId })
642+
syncDebug.snapshot(bookmarkId, { deleted: true }, 'nostr-deletion')
442643
}
443644
setLastSyncTime(Date.now())
444645
}, 0)

‎src/hooks/useYjs.js‎

Lines changed: 39 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,11 @@ import { Awareness } from 'y-protocols/awareness'
66
import { retrieveLEK } from '../services/key-storage'
77
import { deriveYjsPassword } from '../services/crypto'
88

9+
// ============================================================================
10+
// DEBUG FLAG - Set to true to enable verbose logging for bookmark persistence
11+
// ============================================================================
12+
const DEBUG_YJS = true
13+
914
let ydoc = null
1015
let webrtcProvider = null
1116
let indexeddbProvider = null
@@ -79,7 +84,18 @@ function initializeYjs(roomName = 'hypermark') {
7984
indexeddbProvider = new IndexeddbPersistence(roomName, ydoc)
8085

8186
indexeddbProvider.on('synced', () => {
82-
console.log('[Yjs] IndexedDB synced')
87+
const bookmarksMap = ydoc.getMap('bookmarks')
88+
const bookmarkCount = bookmarksMap.size
89+
console.log('[Yjs] IndexedDB synced - loaded', bookmarkCount, 'bookmarks')
90+
91+
if (DEBUG_YJS && bookmarkCount > 0) {
92+
console.log('[Yjs] IndexedDB bookmark summary:')
93+
bookmarksMap.forEach((bookmark, id) => {
94+
const updatedAt = bookmark?.get ? bookmark.get('updatedAt') : bookmark?.updatedAt
95+
const title = bookmark?.get ? bookmark.get('title') : bookmark?.title
96+
console.log(` 📖 ${id}: "${title}" (updatedAt: ${updatedAt} = ${updatedAt ? new Date(updatedAt).toISOString() : 'N/A'})`)
97+
})
98+
}
8399
})
84100

85101
awareness = new Awareness(ydoc)
@@ -99,11 +115,33 @@ function initializeYjs(roomName = 'hypermark') {
99115

100116
undoManager.on('stack-item-added', (event) => {
101117
console.log('[Yjs] Undo stack item added:', event.type)
118+
if (DEBUG_YJS) {
119+
// Log what changed
120+
const meta = event.stackItem?.meta
121+
const deletions = event.stackItem?.deletions
122+
const insertions = event.stackItem?.insertions
123+
console.log('[Yjs] Stack item details:', {
124+
type: event.type,
125+
meta: meta ? Object.fromEntries(meta) : {},
126+
hasDeletions: deletions?.clients?.size > 0,
127+
hasInsertions: insertions?.clients?.size > 0,
128+
})
129+
}
102130
notifyUndoManagerListeners({ type: 'stack-item-added', ...event })
103131
})
104132

105133
undoManager.on('stack-item-popped', (event) => {
106134
console.log('[Yjs] Undo stack item popped:', event.type)
135+
if (DEBUG_YJS) {
136+
// Log state after undo/redo
137+
console.log('[Yjs] After undo/redo - bookmark count:', bookmarksMap.size)
138+
console.log('[Yjs] Bookmarks after', event.type + ':')
139+
bookmarksMap.forEach((bookmark, id) => {
140+
const updatedAt = bookmark?.get ? bookmark.get('updatedAt') : bookmark?.updatedAt
141+
const title = bookmark?.get ? bookmark.get('title') : bookmark?.title
142+
console.log(` 📖 ${id}: "${title}" (updatedAt: ${updatedAt} = ${updatedAt ? new Date(updatedAt).toISOString() : 'N/A'})`)
143+
})
144+
}
107145
notifyUndoManagerListeners({ type: 'stack-item-popped', ...event })
108146
})
109147

0 commit comments

Comments
 (0)