diff --git a/.changeset/feat-internal-debug-logging.md b/.changeset/feat-internal-debug-logging.md new file mode 100644 index 000000000..30d7e68c8 --- /dev/null +++ b/.changeset/feat-internal-debug-logging.md @@ -0,0 +1,5 @@ +--- +sable: minor +--- + +Add internal debug logging system with viewer UI, realtime updates, and instrumentation across sync, timeline, and messaging diff --git a/src/app/components/leave-room-prompt/LeaveRoomPrompt.tsx b/src/app/components/leave-room-prompt/LeaveRoomPrompt.tsx index 21b108e6d..36cdd89de 100644 --- a/src/app/components/leave-room-prompt/LeaveRoomPrompt.tsx +++ b/src/app/components/leave-room-prompt/LeaveRoomPrompt.tsx @@ -20,6 +20,9 @@ import { MatrixError } from '$types/matrix-sdk'; import { useMatrixClient } from '$hooks/useMatrixClient'; import { AsyncStatus, useAsyncCallback } from '$hooks/useAsyncCallback'; import { stopPropagation } from '$utils/keyboard'; +import { createDebugLogger } from '$utils/debugLogger'; + +const debugLog = createDebugLogger('LeaveRoomPrompt'); type LeaveRoomPromptProps = { roomId: string; @@ -31,6 +34,7 @@ export function LeaveRoomPrompt({ roomId, onDone, onCancel }: LeaveRoomPromptPro const [leaveState, leaveRoom] = useAsyncCallback( useCallback(async () => { + debugLog.info('ui', 'Leave room button clicked', { roomId }); mx.leave(roomId); }, [mx, roomId]) ); @@ -41,9 +45,10 @@ export function LeaveRoomPrompt({ roomId, onDone, onCancel }: LeaveRoomPromptPro useEffect(() => { if (leaveState.status === AsyncStatus.Success) { + debugLog.info('ui', 'Successfully left room', { roomId }); onDone(); } - }, [leaveState, onDone]); + }, [leaveState, onDone, roomId]); return ( }> diff --git a/src/app/features/create-room/CreateRoom.tsx b/src/app/features/create-room/CreateRoom.tsx index 38716c457..7347ba586 100644 --- a/src/app/features/create-room/CreateRoom.tsx +++ b/src/app/features/create-room/CreateRoom.tsx @@ -41,8 +41,11 @@ import { import { RoomType } from '$types/matrix/room'; import { CreateRoomTypeSelector } from '$components/create-room/CreateRoomTypeSelector'; import { getRoomIconSrc } from '$utils/room'; +import { createDebugLogger } from '$utils/debugLogger'; import { ErrorCode } from '../../cs-errorcode'; +const debugLog = createDebugLogger('CreateRoom'); + const getCreateRoomAccessToIcon = (access: CreateRoomAccess, type?: CreateRoomType) => { const isVoiceRoom = type === CreateRoomType.VoiceRoom; @@ -139,6 +142,16 @@ export function CreateRoomForm({ let roomType: RoomType | undefined; if (type === CreateRoomType.VoiceRoom) roomType = RoomType.Call; + debugLog.info('ui', 'Create room button clicked', { + roomName, + access, + type, + publicRoom, + encryption, + hasParent: !!space, + parentRoomId: space?.roomId, + }); + create({ version: selectedRoomVersion, type: roomType, @@ -152,6 +165,12 @@ export function CreateRoomForm({ allowFederation: federation, additionalCreators: allowAdditionalCreators ? additionalCreators : undefined, }).then((roomId) => { + debugLog.info('ui', 'Room created successfully', { + roomId, + roomName, + access, + type, + }); if (alive()) { onCreate?.(roomId); } diff --git a/src/app/features/room/Room.tsx b/src/app/features/room/Room.tsx index b7aef9107..694b1c7f8 100644 --- a/src/app/features/room/Room.tsx +++ b/src/app/features/room/Room.tsx @@ -1,4 +1,4 @@ -import { useCallback } from 'react'; +import { useCallback, useEffect } from 'react'; import { Box, Line } from 'folds'; import { useParams } from 'react-router-dom'; import { isKeyHotkey } from 'is-hotkey'; @@ -15,20 +15,43 @@ import { useRoomMembers } from '$hooks/useRoomMembers'; import { CallView } from '$features/call/CallView'; import { WidgetsDrawer } from '$features/widgets/WidgetsDrawer'; import { callChatAtom } from '$state/callEmbed'; +import { createDebugLogger } from '$utils/debugLogger'; import { RoomViewHeader } from './RoomViewHeader'; import { MembersDrawer } from './MembersDrawer'; import { RoomView } from './RoomView'; import { CallChatView } from './CallChatView'; +const debugLog = createDebugLogger('Room'); + export function Room() { const { eventId } = useParams(); const room = useRoom(); const mx = useMatrixClient(); + // Log room mount + useEffect(() => { + debugLog.info('ui', 'Room component mounted', { roomId: room.roomId, eventId }); + return () => { + debugLog.info('ui', 'Room component unmounted', { roomId: room.roomId }); + }; + }, [room.roomId, eventId]); + const [isDrawer] = useSetting(settingsAtom, 'isPeopleDrawer'); const [isWidgetDrawerOpen] = useSetting(settingsAtom, 'isWidgetDrawer'); const [hideReads] = useSetting(settingsAtom, 'hideReads'); const screenSize = useScreenSizeContext(); + + // Log drawer state changes + useEffect(() => { + debugLog.debug('ui', 'Members drawer state changed', { roomId: room.roomId, isOpen: isDrawer }); + }, [isDrawer, room.roomId]); + + useEffect(() => { + debugLog.debug('ui', 'Widgets drawer state changed', { + roomId: room.roomId, + isOpen: isWidgetDrawerOpen, + }); + }, [isWidgetDrawerOpen, room.roomId]); const powerLevels = usePowerLevels(room); const members = useRoomMembers(mx, room.roomId); const chat = useAtomValue(callChatAtom); @@ -47,6 +70,11 @@ export function Room() { const callView = room.isCallRoom(); + // Log call view state + useEffect(() => { + debugLog.debug('ui', 'Room view mode', { roomId: room.roomId, callView, chatOpen: chat }); + }, [callView, chat, room.roomId]); + return ( diff --git a/src/app/features/room/RoomInput.tsx b/src/app/features/room/RoomInput.tsx index 6cbf52de1..3f7becd55 100644 --- a/src/app/features/room/RoomInput.tsx +++ b/src/app/features/room/RoomInput.tsx @@ -128,6 +128,7 @@ import { useImagePackRooms } from '$hooks/useImagePackRooms'; import { useComposingCheck } from '$hooks/useComposingCheck'; import { useSableCosmetics } from '$hooks/useSableCosmetics'; import { createLogger } from '$utils/debug'; +import { createDebugLogger } from '$utils/debugLogger'; import FocusTrap from 'focus-trap-react'; import { useQueryClient } from '@tanstack/react-query'; import { @@ -176,6 +177,7 @@ const getReplyContent = (replyDraft: IReplyDraft | undefined): IEventRelation => }; const log = createLogger('RoomInput'); +const debugLog = createDebugLogger('RoomInput'); interface ReplyEventContent { 'm.relates_to'?: IEventRelation; } @@ -422,10 +424,24 @@ export const RoomInput = forwardRef( await Promise.all( contents.map((content) => - mx.sendMessage(roomId, content as any).catch((error: unknown) => { - log.error('failed to send uploaded message', { roomId }, error); - throw error; - }) + mx + .sendMessage(roomId, content as any) + .then((res) => { + debugLog.info('message', 'Uploaded file message sent', { + roomId, + eventId: res.event_id, + msgtype: content.msgtype, + }); + return res; + }) + .catch((error: unknown) => { + debugLog.error('message', 'Failed to send uploaded file message', { + roomId, + error: error instanceof Error ? error.message : String(error), + }); + log.error('failed to send uploaded message', { roomId }, error); + throw error; + }) ) ); }; @@ -569,18 +585,39 @@ export const RoomInput = forwardRef( } else if (editingScheduledDelayId) { try { await cancelDelayedEvent(mx, editingScheduledDelayId); - mx.sendMessage(roomId, content as any); + debugLog.info('message', 'Sending message after cancelling scheduled event', { + roomId, + scheduledDelayId: editingScheduledDelayId, + }); + const res = await mx.sendMessage(roomId, content as any); + debugLog.info('message', 'Message sent successfully', { roomId, eventId: res.event_id }); invalidate(); setEditingScheduledDelayId(null); resetInput(); - } catch { + } catch (error) { + debugLog.error('message', 'Failed to send message after cancelling scheduled event', { + roomId, + error: error instanceof Error ? error.message : String(error), + }); // Cancel failed — leave state intact for retry } } else { resetInput(); - mx.sendMessage(roomId, content as any).catch((error: unknown) => { - log.error('failed to send message', { roomId }, error); - }); + debugLog.info('message', 'Sending message', { roomId, msgtype: (content as any).msgtype }); + mx.sendMessage(roomId, content as any) + .then((res) => { + debugLog.info('message', 'Message sent successfully', { + roomId, + eventId: res.event_id, + }); + }) + .catch((error: unknown) => { + debugLog.error('message', 'Failed to send message', { + roomId, + error: error instanceof Error ? error.message : String(error), + }); + log.error('failed to send message', { roomId }, error); + }); } }, [ editor, diff --git a/src/app/features/room/RoomTimeline.tsx b/src/app/features/room/RoomTimeline.tsx index 39fc9d1cc..6bffcfd2e 100644 --- a/src/app/features/room/RoomTimeline.tsx +++ b/src/app/features/room/RoomTimeline.tsx @@ -131,9 +131,12 @@ import { useRoomPermissions } from '$hooks/useRoomPermissions'; import { useGetMemberPowerTag } from '$hooks/useMemberPowerTag'; import { profilesCacheAtom } from '$state/userRoomProfile'; import { ClientSideHoverFreeze } from '$components/ClientSideHoverFreeze'; +import { createDebugLogger } from '$utils/debugLogger'; import * as css from './RoomTimeline.css'; import { EncryptedContent, Event, ForwardedMessageProps, Message, Reactions } from './message'; +const debugLog = createDebugLogger('RoomTimeline'); + const TimelineFloat = as<'div', css.TimelineFloatVariants>( ({ position, className, ...props }, ref) => ( { + debugLog.info('timeline', 'Timeline mounted', { + roomId: room.roomId, + eventId, + initialEventsCount: eventsLength, + liveTimelineLinked, + }); + return () => { + debugLog.info('timeline', 'Timeline unmounted', { roomId: room.roomId }); + }; + // eslint-disable-next-line react-hooks/exhaustive-deps + }, [room.roomId, eventId]); // Only log on mount/unmount - intentionally capturing initial values + + // Log live timeline linking state changes + useEffect(() => { + debugLog.debug('timeline', 'Live timeline link state changed', { + roomId: room.roomId, + liveTimelineLinked, + eventsLength, + }); + }, [liveTimelineLinked, room.roomId, eventsLength]); const canPaginateBack = typeof timeline.linkedTimelines[0]?.getPaginationToken(Direction.Backward) === 'string'; const rangeAtStart = timeline.range.start === 0; @@ -739,6 +778,13 @@ export function RoomTimeline({ if (!alive()) return; const evLength = getTimelinesEventsCount(lTimelines); + debugLog.info('timeline', 'Loading event timeline', { + roomId: room.roomId, + eventId: evtId, + totalEvents: evLength, + focusIndex: evtAbsIndex, + }); + setAtBottom(false); setFocusItem({ index: evtAbsIndex, @@ -753,10 +799,11 @@ export function RoomTimeline({ }, }); }, - [alive, setAtBottom] + [alive, setAtBottom, room.roomId] ), useCallback(() => { if (!alive()) return; + debugLog.info('timeline', 'Resetting timeline to initial state', { roomId: room.roomId }); setTimeline(getInitialTimeline(room)); scrollToBottomRef.current.count += 1; scrollToBottomRef.current.smooth = false; @@ -830,6 +877,12 @@ export function RoomTimeline({ highlight = true, onScroll: ((scrolled: boolean) => void) | undefined = undefined ) => { + debugLog.info('timeline', 'Jumping to event', { + roomId: room.roomId, + eventId: evtId, + highlight, + }); + const evtTimeline = getEventTimeline(room, evtId); const absoluteIndex = evtTimeline && getEventIdAbsoluteIndex(timeline.linkedTimelines, evtTimeline, evtId); @@ -848,7 +901,16 @@ export function RoomTimeline({ scrollTo: !scrolled, highlight, }); + debugLog.debug('timeline', 'Event found in current timeline', { + roomId: room.roomId, + eventId: evtId, + index: absoluteIndex, + }); } else { + debugLog.debug('timeline', 'Event not in current timeline, loading timeline', { + roomId: room.roomId, + eventId: evtId, + }); loadEventTimeline(evtId); } }, @@ -880,6 +942,7 @@ export function RoomTimeline({ // "Jump to Latest" button to stick permanently. Forcing atBottom here is // correct: TimelineRefresh always reinits to the live end, so the user // should be repositioned to the bottom regardless. + debugLog.info('timeline', 'Live timeline refresh triggered', { roomId: room.roomId }); setTimeline(getInitialTimeline(room)); setAtBottom(true); scrollToBottomRef.current.count += 1; @@ -969,16 +1032,18 @@ export function RoomTimeline({ if (targetEntry.isIntersecting) { // User has reached the bottom + debugLog.debug('timeline', 'Scrolled to bottom', { roomId: room.roomId }); setAtBottom(true); if (atLiveEndRef.current && document.hasFocus()) { tryAutoMarkAsRead(); } } else { // User has intentionally scrolled up. + debugLog.debug('timeline', 'Scrolled away from bottom', { roomId: room.roomId }); setAtBottom(false); } }, - [tryAutoMarkAsRead, setAtBottom] + [tryAutoMarkAsRead, setAtBottom, room.roomId] ), useCallback( () => ({ diff --git a/src/app/features/settings/developer-tools/DebugLogViewer.tsx b/src/app/features/settings/developer-tools/DebugLogViewer.tsx new file mode 100644 index 000000000..8e5ae01e1 --- /dev/null +++ b/src/app/features/settings/developer-tools/DebugLogViewer.tsx @@ -0,0 +1,631 @@ +import { useEffect, useState, useCallback, useMemo, MouseEventHandler } from 'react'; +import { useAtom, useAtomValue, useSetAtom } from 'jotai'; +import { Box, Text, Button, color, config, Badge, Menu, MenuItem, PopOut, RectCords } from 'folds'; +import { SequenceCard } from '$components/sequence-card'; + +import { debugLoggerEnabledAtom, debugLogsAtom, clearDebugLogsAtom } from '$state/debugLogger'; +import { LogEntry, getDebugLogger, LogLevel, LogCategory } from '$utils/debugLogger'; +import { SequenceCardStyle } from '$features/settings/styles.css'; + +const formatTimestamp = (timestamp: number): string => { + const date = new Date(timestamp); + return date.toLocaleTimeString('en-US', { + hour12: false, + hour: '2-digit', + minute: '2-digit', + second: '2-digit', + fractionalSecondDigits: 3, + }); +}; + +const getLevelColor = (level: string): string => { + switch (level) { + case 'error': + return color.Critical.Main; + case 'warn': + return color.Warning.Main; + case 'info': + return color.Success.Main; + default: + return color.Secondary.Main; + } +}; + +const getCategoryBadgeVariant = ( + category: string +): 'Primary' | 'Secondary' | 'Success' | 'Warning' | 'Critical' => { + switch (category) { + case 'error': + return 'Critical'; + case 'sync': + return 'Primary'; + case 'notification': + return 'Success'; + case 'message': + return 'Secondary'; + case 'call': + return 'Warning'; + default: + return 'Secondary'; + } +}; + +function LogEntryItem({ entry }: { entry: LogEntry }) { + const [expanded, setExpanded] = useState(false); + + return ( + + + + + {entry.level.toUpperCase()} + + + {entry.category} + + + {formatTimestamp(entry.timestamp)} + + + [{entry.namespace}] + + + {entry.data != null && ( + + )} + + + {entry.message} + + {expanded && entry.data != null && ( + + + {JSON.stringify(entry.data, null, 2)} + + + )} + + ); +} + +export function DebugLogViewer() { + const [enabled, setEnabled] = useAtom(debugLoggerEnabledAtom); + const logs = useAtomValue(debugLogsAtom); + const clearLogs = useSetAtom(clearDebugLogsAtom); + const [autoScroll, setAutoScroll] = useState(true); + const scrollRef = useState(null)[0]; + const [filterLevel, setFilterLevel] = useState('all'); + const [filterCategory, setFilterCategory] = useState('all'); + const [categoryAnchor, setCategoryAnchor] = useState(); + const [levelAnchor, setLevelAnchor] = useState(); + + const handleOpenCategoryMenu: MouseEventHandler = (evt) => { + evt.stopPropagation(); + setCategoryAnchor(evt.currentTarget.getBoundingClientRect()); + }; + + const handleOpenLevelMenu: MouseEventHandler = (evt) => { + evt.stopPropagation(); + setLevelAnchor(evt.currentTarget.getBoundingClientRect()); + }; + + // Filter logs based on current filters + const filteredLogs = useMemo(() => { + if (filterLevel === 'all' && filterCategory === 'all') { + return logs; + } + + const debugLogger = getDebugLogger(); + return debugLogger.getFilteredLogs({ + level: filterLevel !== 'all' ? filterLevel : undefined, + category: filterCategory !== 'all' ? filterCategory : undefined, + }); + }, [logs, filterLevel, filterCategory]); + + // Auto-refresh logs when new entries arrive + useEffect(() => { + if (!enabled) return undefined; + + const debugLogger = getDebugLogger(); + const unsubscribe = debugLogger.addListener(() => { + // Trigger re-render by refreshing the atom + // This will be handled by the debugLogsAtom's refresh mechanism + }); + + return unsubscribe; + }, [enabled]); + + // Auto-scroll to bottom when new logs arrive + useEffect(() => { + if (autoScroll && scrollRef) { + scrollRef.scrollTop = scrollRef.scrollHeight; + } + }, [filteredLogs, autoScroll, scrollRef]); + + const handleExportLogs = useCallback( + (filtered: boolean) => { + const debugLogger = getDebugLogger(); + let jsonData: string; + + if (filtered && (filterLevel !== 'all' || filterCategory !== 'all')) { + // Export filtered logs + const logsToExport = debugLogger.getFilteredLogs({ + level: filterLevel !== 'all' ? filterLevel : undefined, + category: filterCategory !== 'all' ? filterCategory : undefined, + }); + jsonData = JSON.stringify( + { + exportedAt: new Date().toISOString(), + build: `v${APP_VERSION}${BUILD_HASH ? ` (${BUILD_HASH})` : ''}`, + filters: { + level: filterLevel !== 'all' ? filterLevel : 'none', + category: filterCategory !== 'all' ? filterCategory : 'none', + }, + logsCount: logsToExport.length, + logs: logsToExport.map((log) => ({ + ...log, + timestamp: new Date(log.timestamp).toISOString(), + })), + }, + null, + 2 + ); + } else { + // Export all logs + jsonData = debugLogger.exportLogs(); + } + + const blob = new Blob([jsonData], { type: 'application/json' }); + const url = URL.createObjectURL(blob); + const a = document.createElement('a'); + a.href = url; + const filterSuffix = + filtered && (filterLevel !== 'all' || filterCategory !== 'all') + ? `-${filterCategory !== 'all' ? filterCategory : 'all'}-${filterLevel !== 'all' ? filterLevel : 'all'}` + : ''; + a.download = `sable-debug-logs${filterSuffix}-${new Date().toISOString()}.json`; + document.body.appendChild(a); + a.click(); + document.body.removeChild(a); + URL.revokeObjectURL(url); + }, + [filterLevel, filterCategory] + ); + + const handleCopyToClipboard = useCallback( + (filtered: boolean) => { + const debugLogger = getDebugLogger(); + let jsonData: string; + + if (filtered && (filterLevel !== 'all' || filterCategory !== 'all')) { + const logsToExport = debugLogger.getFilteredLogs({ + level: filterLevel !== 'all' ? filterLevel : undefined, + category: filterCategory !== 'all' ? filterCategory : undefined, + }); + jsonData = JSON.stringify( + { + exportedAt: new Date().toISOString(), + build: `v${APP_VERSION}${BUILD_HASH ? ` (${BUILD_HASH})` : ''}`, + filters: { + level: filterLevel !== 'all' ? filterLevel : 'none', + category: filterCategory !== 'all' ? filterCategory : 'none', + }, + logsCount: logsToExport.length, + logs: logsToExport.map((log) => ({ + ...log, + timestamp: new Date(log.timestamp).toISOString(), + })), + }, + null, + 2 + ); + } else { + jsonData = debugLogger.exportLogs(); + } + + navigator.clipboard.writeText(jsonData); + }, + [filterLevel, filterCategory] + ); + + return ( + + + + Debug Log Status + + {enabled ? 'Active' : 'Inactive'} + + + + + Internal debug logging captures sync state, network events, notifications, messages, + calls, UI component lifecycle, and timeline operations. Logs are stored in memory (max + 1000 entries) and cleared when you close the app. + + + {/* Filter Controls */} + + + Filters: + + + { + setFilterCategory('all'); + setCategoryAnchor(undefined); + }} + disabled={filterCategory === 'all'} + > + All Categories + + { + setFilterCategory('sync'); + setCategoryAnchor(undefined); + }} + disabled={filterCategory === 'sync'} + > + Sync + + { + setFilterCategory('network'); + setCategoryAnchor(undefined); + }} + disabled={filterCategory === 'network'} + > + Network + + { + setFilterCategory('notification'); + setCategoryAnchor(undefined); + }} + disabled={filterCategory === 'notification'} + > + Notification + + { + setFilterCategory('message'); + setCategoryAnchor(undefined); + }} + disabled={filterCategory === 'message'} + > + Message + + { + setFilterCategory('call'); + setCategoryAnchor(undefined); + }} + disabled={filterCategory === 'call'} + > + Call + + { + setFilterCategory('ui'); + setCategoryAnchor(undefined); + }} + disabled={filterCategory === 'ui'} + > + UI + + { + setFilterCategory('timeline'); + setCategoryAnchor(undefined); + }} + disabled={filterCategory === 'timeline'} + > + Timeline + + { + setFilterCategory('general'); + setCategoryAnchor(undefined); + }} + disabled={filterCategory === 'general'} + > + General + + { + setFilterCategory('error'); + setCategoryAnchor(undefined); + }} + disabled={filterCategory === 'error'} + > + Error + + + } + > + + + + + { + setFilterLevel('all'); + setLevelAnchor(undefined); + }} + disabled={filterLevel === 'all'} + > + All Levels + + { + setFilterLevel('debug'); + setLevelAnchor(undefined); + }} + disabled={filterLevel === 'debug'} + > + Debug + + { + setFilterLevel('info'); + setLevelAnchor(undefined); + }} + disabled={filterLevel === 'info'} + > + Info + + { + setFilterLevel('warn'); + setLevelAnchor(undefined); + }} + disabled={filterLevel === 'warn'} + > + Warning + + { + setFilterLevel('error'); + setLevelAnchor(undefined); + }} + disabled={filterLevel === 'error'} + > + Error + + + } + > + + + + {(filterLevel !== 'all' || filterCategory !== 'all') && ( + + )} + + + + + + + + + + + {enabled && ( + + + + Recent Logs ( + {filterLevel !== 'all' || filterCategory !== 'all' + ? `${filteredLogs.length}/${logs.length}` + : `${logs.length}/1000`} + ) + + + + + + {filteredLogs.length === 0 ? ( + + + {logs.length === 0 + ? 'No logs captured yet. Use the app to generate log entries.' + : 'No logs match the current filters.'} + + + ) : ( + filteredLogs.map((log) => ( + + )) + )} + + + )} + + + ); +} diff --git a/src/app/features/settings/developer-tools/DevelopTools.tsx b/src/app/features/settings/developer-tools/DevelopTools.tsx index d65c97db0..d230620ae 100644 --- a/src/app/features/settings/developer-tools/DevelopTools.tsx +++ b/src/app/features/settings/developer-tools/DevelopTools.tsx @@ -11,6 +11,7 @@ import { copyToClipboard } from '$utils/dom'; import { SequenceCardStyle } from '$features/settings/styles.css'; import { AccountData } from './AccountData'; import { SyncDiagnostics } from './SyncDiagnostics'; +import { DebugLogViewer } from './DebugLogViewer'; type DeveloperToolsProps = { requestClose: () => void; @@ -120,6 +121,11 @@ export function DeveloperTools({ requestClose }: DeveloperToolsProps) { onSelect={setAccountDataType} /> )} + {developerTools && ( + + + + )} diff --git a/src/app/features/settings/notifications/PushNotifications.tsx b/src/app/features/settings/notifications/PushNotifications.tsx index 08310d28d..eb1f775e5 100644 --- a/src/app/features/settings/notifications/PushNotifications.tsx +++ b/src/app/features/settings/notifications/PushNotifications.tsx @@ -1,6 +1,9 @@ import { MatrixClient } from '$types/matrix-sdk'; +import { createDebugLogger } from '$utils/debugLogger'; import { ClientConfig } from '../../../hooks/useClientConfig'; +const debugLog = createDebugLogger('PushNotifications'); + type PushSubscriptionState = [ PushSubscriptionJSON | null, (subscription: PushSubscription | null) => void, @@ -8,12 +11,18 @@ type PushSubscriptionState = [ export async function requestBrowserNotificationPermission(): Promise { if (!('Notification' in window)) { + debugLog.warn('notification', 'Notification API not available in this browser'); return 'denied'; } try { + debugLog.info('notification', 'Requesting browser notification permission'); const permission: NotificationPermission = await Notification.requestPermission(); + debugLog.info('notification', 'Notification permission result', { permission }); return permission; - } catch { + } catch (error) { + debugLog.error('notification', 'Failed to request notification permission', { + error: error instanceof Error ? error.message : String(error), + }); return 'denied'; } } @@ -24,8 +33,13 @@ export async function enablePushNotifications( pushSubscriptionAtom: PushSubscriptionState ): Promise { if (!('serviceWorker' in navigator) || !('PushManager' in window)) { + debugLog.error( + 'notification', + 'Push messaging not supported - missing serviceWorker or PushManager' + ); throw new Error('Push messaging is not supported in this browser.'); } + debugLog.info('notification', 'Enabling push notifications'); const [pushSubAtom, setPushSubscription] = pushSubscriptionAtom; const registration = await navigator.serviceWorker.ready; const currentBrowserSub = await registration.pushManager.getSubscription(); @@ -34,6 +48,9 @@ export async function enablePushNotifications( only when necessary. This prevents us from needing an external call to get back the web push info. */ if (currentBrowserSub && pushSubAtom && currentBrowserSub.endpoint === pushSubAtom.endpoint) { + debugLog.info('notification', 'Push subscription already exists and is valid - reusing', { + endpoint: pushSubAtom.endpoint, + }); const { keys } = pushSubAtom; if (!keys?.p256dh || !keys.auth) return; const pusherData = { @@ -63,19 +80,25 @@ export async function enablePushNotifications( } if (currentBrowserSub) { + debugLog.info('notification', 'Unsubscribing old push subscription'); await currentBrowserSub.unsubscribe(); } + debugLog.info('notification', 'Creating new push subscription'); const newSubscription = await registration.pushManager.subscribe({ userVisibleOnly: true, applicationServerKey: clientConfig.pushNotificationDetails?.vapidPublicKey, }); + debugLog.info('notification', 'Push subscription created successfully', { + endpoint: newSubscription.endpoint, + }); setPushSubscription(newSubscription); const subJson = newSubscription.toJSON(); const { keys } = subJson; if (!keys?.p256dh || !keys.auth) { + debugLog.error('notification', 'Push subscription missing required keys'); throw new Error('Push subscription keys missing.'); } const pusherData = { @@ -113,6 +136,7 @@ export async function disablePushNotifications( clientConfig: ClientConfig, pushSubscriptionAtom: PushSubscriptionState ): Promise { + debugLog.info('notification', 'Disabling push notifications'); const [pushSubAtom] = pushSubscriptionAtom; const pusherData = { diff --git a/src/app/hooks/useAppVisibility.ts b/src/app/hooks/useAppVisibility.ts index 0688f2637..7fd5f2325 100644 --- a/src/app/hooks/useAppVisibility.ts +++ b/src/app/hooks/useAppVisibility.ts @@ -8,6 +8,9 @@ import { useSetting } from '../state/hooks/settings'; import { settingsAtom } from '../state/settings'; import { pushSubscriptionAtom } from '../state/pushSubscription'; import { mobileOrTablet } from '../utils/user-agent'; +import { createDebugLogger } from '../utils/debugLogger'; + +const debugLog = createDebugLogger('AppVisibility'); export function useAppVisibility(mx: MatrixClient | undefined) { const clientConfig = useClientConfig(); @@ -18,6 +21,11 @@ export function useAppVisibility(mx: MatrixClient | undefined) { useEffect(() => { const handleVisibilityChange = () => { const isVisible = document.visibilityState === 'visible'; + debugLog.info( + 'general', + `App visibility changed: ${isVisible ? 'visible (foreground)' : 'hidden (background)'}`, + { visibilityState: document.visibilityState } + ); appEvents.onVisibilityChange?.(isVisible); if (!isVisible) { appEvents.onVisibilityHidden?.(); diff --git a/src/app/pages/auth/login/loginUtil.ts b/src/app/pages/auth/login/loginUtil.ts index 1659e5474..30d9e5e67 100644 --- a/src/app/pages/auth/login/loginUtil.ts +++ b/src/app/pages/auth/login/loginUtil.ts @@ -11,10 +11,12 @@ import { import { getHomePath } from '$pages/pathUtils'; import { activeSessionIdAtom, sessionsAtom } from '$state/sessions'; import { createLogger } from '$utils/debug'; +import { createDebugLogger } from '$utils/debugLogger'; import { ErrorCode } from '../../../cs-errorcode'; import { autoDiscovery, specVersions } from '../../../cs-api'; const log = createLogger('loginUtil'); +const debugLog = createDebugLogger('loginUtil'); export enum GetBaseUrlError { NotAllow = 'NotAllow', @@ -75,35 +77,45 @@ export const login = async ( } const mx = createClient({ baseUrl: url }); + debugLog.info('general', 'Attempting login', { baseUrl: url, loginType: data.type }); const [err, res] = await to(mx.loginRequest(data)); if (err) { if (err.httpStatus === 400) { + debugLog.error('general', 'Login failed - invalid request', { httpStatus: 400 }); throw new MatrixError({ errcode: LoginError.InvalidRequest, }); } if (err.httpStatus === 429) { + debugLog.error('general', 'Login failed - rate limited', { httpStatus: 429 }); throw new MatrixError({ errcode: LoginError.RateLimited, }); } if (err.errcode === ErrorCode.M_USER_DEACTIVATED) { + debugLog.error('general', 'Login failed - user deactivated', { errcode: err.errcode }); throw new MatrixError({ errcode: LoginError.UserDeactivated, }); } if (err.httpStatus === 403) { + debugLog.error('general', 'Login failed - forbidden', { httpStatus: 403 }); throw new MatrixError({ errcode: LoginError.Forbidden, }); } + debugLog.error('general', 'Login failed - unknown error', { + error: err.message, + httpStatus: err.httpStatus, + }); throw new MatrixError({ errcode: LoginError.Unknown, }); } + debugLog.info('general', 'Login successful', { userId: res.user_id, deviceId: res.device_id }); return { baseUrl: url, response: res, diff --git a/src/app/pages/client/BackgroundNotifications.tsx b/src/app/pages/client/BackgroundNotifications.tsx index 9ca53b5cb..0a00fcc15 100644 --- a/src/app/pages/client/BackgroundNotifications.tsx +++ b/src/app/pages/client/BackgroundNotifications.tsx @@ -1,4 +1,4 @@ -import { useEffect, useRef } from 'react'; +import { useEffect, useMemo, useRef } from 'react'; import { ClientEvent, createClient, @@ -32,6 +32,7 @@ import { } from '$utils/room'; import { NotificationType, StateEvent } from '$types/matrix/room'; import { createLogger } from '$utils/debug'; +import { createDebugLogger } from '$utils/debugLogger'; import LogoSVG from '$public/res/svg/cinny.svg'; import { nicknamesAtom } from '$state/nicknames'; import { @@ -43,6 +44,7 @@ import { useClientConfig } from '$hooks/useClientConfig'; import { mobileOrTablet } from '$utils/user-agent'; const log = createLogger('BackgroundNotifications'); +const debugLog = createDebugLogger('BackgroundNotifications'); const isClientReadyForNotifications = (state: SyncState | string | null): boolean => state === SyncState.Prepared || state === SyncState.Syncing || state === SyncState.Catchup; @@ -68,21 +70,29 @@ const startBackgroundClient = async ( /** * Wait for the background client to finish its initial sync so that * push rules and account data are available before processing events. + * Rejects after 30 seconds so callers can handle a stalled client instead + * of blocking indefinitely. */ const waitForSync = (mx: MatrixClient): Promise => - new Promise((resolve) => { + new Promise((resolve, reject) => { const state = mx.getSyncState(); if (isClientReadyForNotifications(state)) { resolve(); return; } + let syncTimer: ReturnType | undefined; const onSync = (newState: SyncState) => { if (isClientReadyForNotifications(newState)) { + if (syncTimer !== undefined) clearTimeout(syncTimer); mx.removeListener(ClientEvent.Sync, onSync); resolve(); } }; mx.on(ClientEvent.Sync, onSync); + syncTimer = setTimeout(() => { + mx.removeListener(ClientEvent.Sync, onSync); + reject(new Error('background client sync timed out')); + }, 30_000); }); export function BackgroundNotifications() { @@ -120,10 +130,18 @@ export function BackgroundNotifications() { setBackgroundUnreadsRef.current = setBackgroundUnreads; const setInAppBannerRef = useRef(setInAppBanner); setInAppBannerRef.current = setInAppBanner; + // Per-client listener teardown callbacks, so we can explicitly remove event + // listeners before stopping a background client. + const clientCleanupRef = useRef void>>(new Map()); - const inactiveSessions = sessions.filter( - (s) => s.userId !== (activeSessionId ?? sessions[0]?.userId) + const inactiveSessions = useMemo( + () => sessions.filter((s) => s.userId !== (activeSessionId ?? sessions[0]?.userId)), + [sessions, activeSessionId] ); + // Ref so retry setTimeout callbacks can access the current session list + // without stale closures. + const inactiveSessionsRef = useRef(inactiveSessions); + inactiveSessionsRef.current = inactiveSessions; interface NotifyOptions { /** Title shown in the notification banner. */ @@ -192,6 +210,8 @@ export function BackgroundNotifications() { current.forEach((mx, userId) => { if (!activeIds.has(userId)) { + clientCleanupRef.current.get(userId)?.(); + clientCleanupRef.current.delete(userId); stopClient(mx); current.delete(userId); // Clear the background unread badge when this session is no longer a background account. @@ -203,11 +223,14 @@ export function BackgroundNotifications() { } }); - inactiveSessions.forEach((session) => { - const alreadyRunning = current.has(session.userId); - if (alreadyRunning) return; + // startSession handles init, listener teardown tracking, and retry-on-failure. + // Using a named function (vs. inline .then) lets the .catch() schedule a + // fresh retry referencing the latest session from inactiveSessionsRef. + const startSession = (session: Session, attempt = 0): void => { + let sessionMx: MatrixClient | undefined; startBackgroundClient(session, clientConfig.slidingSync) .then(async (mx) => { + sessionMx = mx; current.set(session.userId, mx); await waitForSync(mx); @@ -303,6 +326,10 @@ export function BackgroundNotifications() { const notificationType = getNotificationType(mx, room.roomId); if (notificationType === NotificationType.Mute) { + debugLog.debug('notification', 'Room is muted - skipping notification', { + roomId: room.roomId, + eventId, + }); return; } @@ -329,9 +356,27 @@ export function BackgroundNotifications() { const shouldNotify = pushActions?.notify || shouldForceDMNotification; if (!shouldNotify) { + debugLog.debug('notification', 'Event filtered - no push action match', { + eventId, + roomId: room.roomId, + eventType, + isDM, + }); return; } + const loudByRule = Boolean(pushActions.tweaks?.sound); + const isHighlight = Boolean(pushActions.tweaks?.highlight); + + debugLog.info('notification', 'Processing notification event', { + eventId, + roomId: room.roomId, + eventType, + isDM, + isHighlight, + loud: loudByRule, + }); + const senderName = getMemberDisplayName(room, sender, nicknamesRef.current) ?? getMxIdLocalPart(sender) ?? @@ -343,10 +388,7 @@ export function BackgroundNotifications() { ? (mxcUrlToHttp(mx, avatarMxc, false, 96, 96, 'crop') ?? undefined) : LogoSVG; - const loudByRule = Boolean(pushActions.tweaks?.sound); - // Track background unread count for every notifiable event (loud or silent). - const isHighlight = Boolean(pushActions.tweaks?.highlight); setBackgroundUnreadsRef.current((prev) => { const cur = prev[session.userId] ?? { total: 0, highlight: 0 }; return { @@ -360,6 +402,10 @@ export function BackgroundNotifications() { // Silent-rule events: unread badge updated above; no OS notification or sound. if (!loudByRule && !isHighlight) { + debugLog.debug('notification', 'Silent notification - badge updated only', { + eventId, + roomId: room.roomId, + }); return; } @@ -410,6 +456,11 @@ export function BackgroundNotifications() { if (canShowInAppBanner) { // App is in the foreground on a different account — show the themed in-app banner. + debugLog.info('notification', 'Showing in-app banner', { + eventId, + roomId: room.roomId, + title: notificationPayload.title, + }); setInAppBannerRef.current({ id: dedupeId, title: notificationPayload.title, @@ -422,6 +473,12 @@ export function BackgroundNotifications() { } else if (loudByRule) { // App is backgrounded or in-app notifications disabled — fire an OS notification. // Only send for loud (sound-tweak) rules; highlight-only events are silently counted. + debugLog.info('notification', 'Sending OS notification', { + eventId, + roomId: room.roomId, + title: notificationPayload.title, + hasSound: !notificationPayload.options.silent, + }); sendNotification({ title: notificationPayload.title, icon: notificationPayload.options.icon, @@ -435,14 +492,58 @@ export function BackgroundNotifications() { }; mx.on(RoomEvent.Timeline, handleTimeline as unknown as (...args: unknown[]) => void); + + // Register teardown so these listeners are removed when this client is stopped. + clientCleanupRef.current.set(session.userId, () => { + mx.off(ClientEvent.AccountData as any, handleAccountData); + mx.off(RoomEvent.Timeline, handleTimeline as unknown as (...args: unknown[]) => void); + }); }) .catch((err) => { log.error('failed to start background client for', session.userId, err); + debugLog.error('notification', 'Failed to start background client', { + userId: session.userId, + error: err, + }); + + // Remove the stuck/failed client from current so future runs (or the + // retry below) can attempt a fresh start. + if (sessionMx && current.get(session.userId) === sessionMx) { + clientCleanupRef.current.get(session.userId)?.(); + clientCleanupRef.current.delete(session.userId); + current.delete(session.userId); + stopClient(sessionMx); + } + + // Retry with exponential backoff, up to 5 attempts (5s, 10s, 20s, 40s, 60s cap). + if (attempt < 5) { + const retryDelay = Math.min(5_000 * 2 ** attempt, 60_000); + setTimeout(() => { + const latestSession = inactiveSessionsRef.current.find( + (s) => s.userId === session.userId + ); + if (latestSession && !current.has(session.userId)) { + startSession(latestSession, attempt + 1); + } + }, retryDelay); + } }); + }; + + inactiveSessions.forEach((session) => { + if (!current.has(session.userId)) startSession(session); }); return () => { - current.forEach((mx) => stopClient(mx)); + // Reading ref.current in cleanup is intentional - we want cleanup functions + // that were registered during async startBackgroundClient operations + // eslint-disable-next-line react-hooks/exhaustive-deps + const cleanupMap = clientCleanupRef.current; + current.forEach((mx, userId) => { + cleanupMap.get(userId)?.(); + cleanupMap.delete(userId); + stopClient(mx); + }); current.clear(); }; }, [ diff --git a/src/app/pages/client/sidebar/AccountSwitcherTab.tsx b/src/app/pages/client/sidebar/AccountSwitcherTab.tsx index 1b722d244..39438b114 100644 --- a/src/app/pages/client/sidebar/AccountSwitcherTab.tsx +++ b/src/app/pages/client/sidebar/AccountSwitcherTab.tsx @@ -42,10 +42,12 @@ import { useSessionProfiles } from '$hooks/useSessionProfiles'; import { Settings } from '$features/settings'; import { Modal500 } from '$components/Modal500'; import { createLogger } from '$utils/debug'; +import { createDebugLogger } from '$utils/debugLogger'; import { useClientConfig } from '$hooks/useClientConfig'; import { UnreadBadge, UnreadBadgeCenter } from '$components/unread-badge'; const log = createLogger('AccountSwitcherTab'); +const debugLog = createDebugLogger('AccountSwitcherTab'); function AccountRow({ session, @@ -246,6 +248,9 @@ export function AccountSwitcherTab() { }; const handleOpenSettings = () => { + debugLog.info('ui', 'Settings button clicked', { + userId: activeSession?.userId, + }); setMenuAnchor(undefined); setSettingsOpen(true); }; diff --git a/src/app/pages/client/space/Space.tsx b/src/app/pages/client/space/Space.tsx index bc88b9af5..aae2f2d7b 100644 --- a/src/app/pages/client/space/Space.tsx +++ b/src/app/pages/client/space/Space.tsx @@ -72,6 +72,9 @@ import { mobileOrTablet } from '$utils/user-agent'; import { lastVisitedRoomIdAtom } from '$state/room/lastRoom'; import { SwipeableOverlayWrapper } from '$components/SwipeableOverlayWrapper'; import { useCallEmbed } from '$hooks/useCallEmbed'; +import { createDebugLogger } from '$utils/debugLogger'; + +const debugLog = createDebugLogger('Space'); type SpaceMenuProps = { room: Room; @@ -122,6 +125,7 @@ const SpaceMenu = forwardRef(({ room, requestClo }; const handleOpenTimeline = () => { + debugLog.info('ui', 'Space timeline opened', { roomId: room.roomId }); navigateRoom(room.roomId); requestClose(); }; diff --git a/src/app/plugins/call/CallEmbed.ts b/src/app/plugins/call/CallEmbed.ts index c370bfac5..570b66f76 100644 --- a/src/app/plugins/call/CallEmbed.ts +++ b/src/app/plugins/call/CallEmbed.ts @@ -25,6 +25,9 @@ import { } from './types'; import { CallControl } from './CallControl'; import { CallControlState } from './CallControlState'; +import { createDebugLogger } from '../../utils/debugLogger'; + +const debugLog = createDebugLogger('CallEmbed'); export class CallEmbed { private mx: MatrixClient; @@ -127,6 +130,8 @@ export class CallEmbed { container: HTMLElement, initialControlState?: CallControlState ) { + debugLog.info('call', 'Initializing call embed', { roomId: room.roomId }); + const iframe = CallEmbed.getIframe( widget.getCompleteUrl({ currentUserId: mx.getSafeUserId() }) ); @@ -174,6 +179,7 @@ export class CallEmbed { } public hangup() { + debugLog.info('call', 'Hanging up call', { roomId: this.roomId }); return this.call.transport.send(ElementWidgetActions.HangupCall, {}); } @@ -194,6 +200,7 @@ export class CallEmbed { } private start() { + debugLog.info('call', 'Starting call widget', { roomId: this.roomId }); // Room widgets get locked to the room they were added in this.call.setViewedRoomId(this.roomId); this.disposables.push( @@ -224,6 +231,7 @@ export class CallEmbed { * @param opts */ public dispose(): void { + debugLog.info('call', 'Disposing call widget', { roomId: this.roomId }); this.disposables.forEach((disposable) => { disposable(); }); @@ -242,6 +250,7 @@ export class CallEmbed { } private onCallJoined(): void { + debugLog.info('call', 'Call joined', { roomId: this.roomId }); this.joined = true; this.applyStyles(); this.control.startObserving(); diff --git a/src/app/plugins/call/CallWidgetDriver.ts b/src/app/plugins/call/CallWidgetDriver.ts index a2cbc8ddc..ba1b170ec 100644 --- a/src/app/plugins/call/CallWidgetDriver.ts +++ b/src/app/plugins/call/CallWidgetDriver.ts @@ -26,6 +26,9 @@ import { } from 'matrix-js-sdk'; import { getCallCapabilities } from './utils'; import { downloadMedia, mxcUrlToHttp } from '../../utils/matrix'; +import { createDebugLogger } from '../../utils/debugLogger'; + +const debugLog = createDebugLogger('CallWidgetDriver'); export class CallWidgetDriver extends WidgetDriver { private allowedCapabilities: Set; @@ -40,8 +43,12 @@ export class CallWidgetDriver extends WidgetDriver { this.mx = mx; const deviceId = mx.getDeviceId(); - if (!deviceId) throw new Error('Failed to initialize CallWidgetDriver! Device ID not found.'); + if (!deviceId) { + debugLog.error('call', 'Failed to initialize CallWidgetDriver - no device ID'); + throw new Error('Failed to initialize CallWidgetDriver! Device ID not found.'); + } + debugLog.info('call', 'Initializing CallWidgetDriver', { roomId: inRoomId, deviceId }); this.allowedCapabilities = getCallCapabilities(inRoomId, mx.getSafeUserId(), deviceId); } @@ -59,7 +66,16 @@ export class CallWidgetDriver extends WidgetDriver { const client = this.mx; const roomId = targetRoomId || this.inRoomId; - if (!client || !roomId) throw new Error('Not in a room or not attached to a client'); + if (!client || !roomId) { + debugLog.error('call', 'Cannot send event - no client or room', { eventType, roomId }); + throw new Error('Not in a room or not attached to a client'); + } + + debugLog.info('call', 'Sending call event', { + eventType, + roomId, + hasStateKey: stateKey !== null, + }); let r: { event_id: string } | null; if (typeof stateKey === 'string') { @@ -80,6 +96,7 @@ export class CallWidgetDriver extends WidgetDriver { ); } + debugLog.info('call', 'Call event sent successfully', { eventId: r.event_id, eventType }); return { roomId, eventId: r.event_id }; } diff --git a/src/app/state/debugLogger.ts b/src/app/state/debugLogger.ts new file mode 100644 index 000000000..5221cf571 --- /dev/null +++ b/src/app/state/debugLogger.ts @@ -0,0 +1,43 @@ +/** + * Jotai atoms for debug logger state management + */ +import { atom } from 'jotai'; +import { atomWithRefresh } from 'jotai/utils'; +import { getDebugLogger } from '$utils/debugLogger'; + +const debugLogger = getDebugLogger(); + +/** + * Atom for retrieving debug logs with refresh capability + */ +export const debugLogsAtom = atomWithRefresh(() => debugLogger.getLogs()); + +/** + * Atom for enabling/disabling debug logging + */ +export const debugLoggerEnabledAtom = atom( + debugLogger.isEnabled(), + (get, set, enabled: boolean) => { + debugLogger.setEnabled(enabled); + set(debugLoggerEnabledAtom, enabled); + set(debugLogsAtom); + } +); + +/** + * Atom for filtered logs + */ +export const filteredDebugLogsAtom = atom((get) => get(debugLogsAtom)); + +/** + * Action to clear all debug logs + */ +export const clearDebugLogsAtom = atom(null, (_, set) => { + debugLogger.clear(); + set(debugLogsAtom); +}); + +/** + * Action to export debug logs + */ +export const exportDebugLogsAtom = atom(null, () => debugLogger.exportLogs()); diff --git a/src/app/utils/debugLogger.ts b/src/app/utils/debugLogger.ts new file mode 100644 index 000000000..53b146818 --- /dev/null +++ b/src/app/utils/debugLogger.ts @@ -0,0 +1,174 @@ +/** + * Enhanced debug logger for Sable with circular buffer storage and categorization. + * + * Enable via Developer Tools UI or with: + * localStorage.setItem('sable_internal_debug', '1'); location.reload(); + */ + +export type LogLevel = 'debug' | 'info' | 'warn' | 'error'; + +export type LogCategory = + | 'sync' + | 'network' + | 'notification' + | 'message' + | 'call' + | 'ui' + | 'timeline' + | 'error' + | 'general'; + +export interface LogEntry { + timestamp: number; + level: LogLevel; + category: LogCategory; + namespace: string; + message: string; + data?: unknown; +} + +type LogListener = (entry: LogEntry) => void; + +class DebugLoggerService { + private logs: LogEntry[] = []; + + private maxLogs = 1000; // Circular buffer size + + private enabled = false; + + private listeners: Set = new Set(); + + constructor() { + // Check if debug logging is enabled from localStorage + this.enabled = localStorage.getItem('sable_internal_debug') === '1'; + } + + public isEnabled(): boolean { + return this.enabled; + } + + public setEnabled(enabled: boolean): void { + this.enabled = enabled; + if (enabled) { + localStorage.setItem('sable_internal_debug', '1'); + } else { + localStorage.removeItem('sable_internal_debug'); + } + } + + public addListener(listener: LogListener): () => void { + this.listeners.add(listener); + return () => this.listeners.delete(listener); + } + + private notifyListeners(entry: LogEntry): void { + this.listeners.forEach((listener) => { + try { + listener(entry); + } catch (error) { + // Silently catch listener errors to prevent debug logging from breaking the app + console.error('[DebugLogger] Listener error:', error); + } + }); + } + + public log( + level: LogLevel, + category: LogCategory, + namespace: string, + message: string, + data?: unknown + ): void { + if (!this.enabled && level !== 'error') return; + + const entry: LogEntry = { + timestamp: Date.now(), + level, + category, + namespace, + message, + data, + }; + + // Add to circular buffer + if (this.logs.length >= this.maxLogs) { + this.logs.shift(); // Remove oldest entry + } + this.logs.push(entry); + + // Notify listeners + this.notifyListeners(entry); + + // Also log to console for developer convenience + const prefix = `[sable:${category}:${namespace}]`; + const consoleLevel = level === 'debug' ? 'log' : level; + // eslint-disable-next-line no-console + console[consoleLevel](prefix, message, data !== undefined ? data : ''); + } + + public getLogs(): LogEntry[] { + return [...this.logs]; + } + + public getFilteredLogs(filters?: { + level?: LogLevel; + category?: LogCategory; + since?: number; + }): LogEntry[] { + let filtered = [...this.logs]; + + if (filters?.level) { + filtered = filtered.filter((log) => log.level === filters.level); + } + + if (filters?.category) { + filtered = filtered.filter((log) => log.category === filters.category); + } + + if (filters?.since) { + const { since } = filters; + filtered = filtered.filter((log) => log.timestamp >= since); + } + + return filtered; + } + + public clear(): void { + this.logs = []; + } + + public exportLogs(): string { + return JSON.stringify( + { + exportedAt: new Date().toISOString(), + build: `v${APP_VERSION}${BUILD_HASH ? ` (${BUILD_HASH})` : ''}`, + logsCount: this.logs.length, + logs: this.logs.map((log) => ({ + ...log, + timestamp: new Date(log.timestamp).toISOString(), + })), + }, + null, + 2 + ); + } +} + +// Singleton instance +const debugLoggerService = new DebugLoggerService(); + +export const getDebugLogger = (): DebugLoggerService => debugLoggerService; + +/** + * Creates a logger for a specific namespace + */ +export const createDebugLogger = (namespace: string) => ({ + debug: (category: LogCategory, message: string, data?: unknown) => + debugLoggerService.log('debug', category, namespace, message, data), + info: (category: LogCategory, message: string, data?: unknown) => + debugLoggerService.log('info', category, namespace, message, data), + warn: (category: LogCategory, message: string, data?: unknown) => + debugLoggerService.log('warn', category, namespace, message, data), + error: (category: LogCategory, message: string, data?: unknown) => + debugLoggerService.log('error', category, namespace, message, data), +}); diff --git a/src/client/initMatrix.ts b/src/client/initMatrix.ts index 47c8ba29d..71bbc3167 100644 --- a/src/client/initMatrix.ts +++ b/src/client/initMatrix.ts @@ -16,11 +16,13 @@ import { } from '$state/sessions'; import { getLocalStorageItem } from '$state/utils/atomWithLocalStorage'; import { createLogger } from '$utils/debug'; +import { createDebugLogger } from '$utils/debugLogger'; import { pushSessionToSW } from '../sw-session'; import { cryptoCallbacks } from './secretStorageKeys'; import { SlidingSyncConfig, SlidingSyncDiagnostics, SlidingSyncManager } from './slidingSync'; const log = createLogger('initMatrix'); +const debugLog = createDebugLogger('initMatrix'); const slidingSyncByClient = new WeakMap(); const FAST_SYNC_POLL_TIMEOUT_MS = 10000; const SLIDING_SYNC_POLL_TIMEOUT_MS = 20000; @@ -150,6 +152,10 @@ const waitForClientReady = (mx: MatrixClient, timeoutMs: number): Promise let timer = 0; let finish = () => {}; const onSync = (state: string) => { + debugLog.info('sync', `Sync state changed: ${state}`, { + state, + ready: isClientReadyForUi(state), + }); if (isClientReadyForUi(state)) finish(); }; @@ -263,7 +269,10 @@ const buildClient = async (session: Session): Promise => { export const initClient = async (session: Session): Promise => { const storeName = getSessionStoreName(session); - log.log('initClient', { userId: session.userId, baseUrl: session.baseUrl, storeName }); + debugLog.info('sync', 'Initializing Matrix client', { + userId: session.userId, + baseUrl: session.baseUrl, + }); const isMismatch = (err: unknown): boolean => { const msg = err instanceof Error ? err.message : String(err); @@ -277,6 +286,7 @@ export const initClient = async (session: Session): Promise => { const wipeAllStores = async () => { log.warn('initClient: wiping all stores for', session.userId); + debugLog.warn('sync', 'Wiping all stores due to mismatch', { userId: session.userId }); await deleteSessionStores(storeName); try { const allDbs = await window.indexedDB.databases(); @@ -297,8 +307,12 @@ export const initClient = async (session: Session): Promise => { try { mx = await buildClient(session); } catch (err) { - if (!isMismatch(err)) throw err; + if (!isMismatch(err)) { + debugLog.error('sync', 'Failed to build client', { error: err }); + throw err; + } log.warn('initClient: mismatch on buildClient — wiping and retrying:', err); + debugLog.warn('sync', 'Client build mismatch - wiping stores and retrying', { error: err }); await wipeAllStores(); mx = await buildClient(session); } @@ -306,8 +320,12 @@ export const initClient = async (session: Session): Promise => { try { await mx.initRustCrypto({ cryptoDatabasePrefix: storeName.rustCryptoPrefix }); } catch (err) { - if (!isMismatch(err)) throw err; + if (!isMismatch(err)) { + debugLog.error('sync', 'Failed to initialize crypto', { error: err }); + throw err; + } log.warn('initClient: mismatch on initRustCrypto — wiping and retrying:', err); + debugLog.warn('sync', 'Crypto init mismatch - wiping stores and retrying', { error: err }); mx.stopClient(); await wipeAllStores(); mx = await buildClient(session); @@ -336,16 +354,11 @@ const disposeSlidingSync = (mx: MatrixClient): void => { slidingSyncByClient.delete(mx); }; -export const stopClient = (mx: MatrixClient): void => { - disposeSlidingSync(mx); - mx.stopClient(); -}; - export const getSlidingSyncManager = (mx: MatrixClient): SlidingSyncManager | undefined => slidingSyncByClient.get(mx); -export const startClient = async (mx: MatrixClient, config?: StartClientConfig) => { - log.log('startClient', mx.getUserId()); +export const startClient = async (mx: MatrixClient, config?: StartClientConfig): Promise => { + debugLog.info('sync', 'Starting Matrix client', { userId: mx.getUserId() }); disposeSlidingSync(mx); const slidingConfig = config?.slidingSync; const slidingEnabledOnServer = resolveSlidingEnabled(slidingConfig?.enabled); @@ -361,6 +374,11 @@ export const startClient = async (mx: MatrixClient, config?: StartClientConfig) proxyBaseUrl, hasSlidingProxy, }); + debugLog.info('sync', 'Sliding sync configuration', { + enabledOnServer: slidingEnabledOnServer, + requested: slidingRequested, + hasProxy: hasSlidingProxy, + }); const startClassicSync = async (fallbackFromSliding: boolean, reason: SyncTransportReason) => { syncTransportByClient.set(mx, { @@ -416,8 +434,12 @@ export const startClient = async (mx: MatrixClient, config?: StartClientConfig) if (await shouldBootstrapClassicOnColdCache()) { log.log('startClient cold-cache bootstrap: using classic sync for this run', mx.getUserId()); await startClassicSync(false, 'cold_cache_bootstrap'); - waitForClientReady(mx, COLD_CACHE_BOOTSTRAP_TIMEOUT_MS).catch(() => { - /* ignore */ + waitForClientReady(mx, COLD_CACHE_BOOTSTRAP_TIMEOUT_MS).catch((err) => { + debugLog.warn('network', 'Cold cache bootstrap timed out', { + userId: mx.getUserId(), + timeout: `${COLD_CACHE_BOOTSTRAP_TIMEOUT_MS}ms`, + error: err instanceof Error ? err.message : String(err), + }); }); return; } @@ -437,6 +459,11 @@ export const startClient = async (mx: MatrixClient, config?: StartClientConfig) }); if (!supported) { log.warn('Sliding Sync unavailable, falling back to classic sync for', mx.getUserId()); + debugLog.warn('network', 'Sliding Sync probe failed, falling back to classic sync', { + userId: mx.getUserId(), + proxyBaseUrl: resolvedProxyBaseUrl, + probeTimeout: `${probeTimeoutMs}ms`, + }); await startClassicSync(true, 'probe_failed_fallback'); return; } @@ -467,11 +494,25 @@ export const startClient = async (mx: MatrixClient, config?: StartClientConfig) slidingSync: manager.slidingSync, }); } catch (err) { + debugLog.error('network', 'Failed to start client with sliding sync', { + error: err instanceof Error ? err.message : String(err), + userId: mx.getUserId(), + proxyBaseUrl: resolvedProxyBaseUrl, + stack: err instanceof Error ? err.stack : undefined, + }); disposeSlidingSync(mx); throw err; } }; +export const stopClient = (mx: MatrixClient): void => { + log.log('stopClient', mx.getUserId()); + debugLog.info('sync', 'Stopping client', { userId: mx.getUserId() }); + disposeSlidingSync(mx); + mx.stopClient(); + syncTransportByClient.delete(mx); +}; + export const clearCacheAndReload = async (mx: MatrixClient) => { log.log('clearCacheAndReload', mx.getUserId()); stopClient(mx); @@ -504,10 +545,12 @@ export const getClientSyncDiagnostics = (mx: MatrixClient): ClientSyncDiagnostic */ export const logoutClient = async (mx: MatrixClient, session?: Session) => { log.log('logoutClient', { userId: mx.getUserId(), sessionUserId: session?.userId }); + debugLog.info('general', 'Logging out client', { userId: mx.getUserId() }); pushSessionToSW(); stopClient(mx); try { await mx.logout(); + debugLog.info('general', 'Logout successful', { userId: mx.getUserId() }); } catch { // ignore } @@ -525,6 +568,7 @@ export const logoutClient = async (mx: MatrixClient, session?: Session) => { }; export const clearLoginData = async () => { + debugLog.info('general', 'Clearing all login data and reloading'); const dbs = await window.indexedDB.databases(); dbs.forEach((idbInfo) => { const { name } = idbInfo; diff --git a/src/client/slidingSync.ts b/src/client/slidingSync.ts index eacb7a472..7cd01cab7 100644 --- a/src/client/slidingSync.ts +++ b/src/client/slidingSync.ts @@ -16,8 +16,10 @@ import { User, } from '$types/matrix-sdk'; import { createLogger } from '$utils/debug'; +import { createDebugLogger } from '$utils/debugLogger'; const log = createLogger('slidingSync'); +const debugLog = createDebugLogger('slidingSync'); export const LIST_JOINED = 'joined'; export const LIST_INVITES = 'invites'; @@ -316,6 +318,12 @@ export class SlidingSyncManager { private listsFullyLoaded = false; + private initialSyncCompleted = false; + + private syncCount = 0; + + private previousListCounts: Map = new Map(); + public readonly slidingSync: SlidingSync; public readonly probeTimeoutMs: number; @@ -359,17 +367,123 @@ export class SlidingSyncManager { ); this.onLifecycle = (state, resp, err) => { - if (this.disposed || err || !resp || state !== SlidingSyncState.Complete) return; + const syncStartTime = performance.now(); + this.syncCount += 1; + + debugLog.info('sync', `Sliding sync lifecycle: ${state} (cycle #${this.syncCount})`, { + state, + hasError: !!err, + syncNumber: this.syncCount, + isInitialSync: !this.initialSyncCompleted, + }); + + if (err) { + debugLog.error('sync', 'Sliding sync error', { + error: err, + errorMessage: err.message, + syncNumber: this.syncCount, + state, + }); + } + + if (this.disposed) { + debugLog.warn('sync', 'Sync lifecycle called after disposal', { state }); + return; + } + + if (err || !resp || state !== SlidingSyncState.Complete) return; + + // Track what changed in this sync cycle + const changes: Record = {}; + let totalRoomCount = 0; + let hasChanges = false; + + this.listKeys.forEach((key) => { + const listData = this.slidingSync.getListData(key); + const currentCount = listData?.joinedCount ?? 0; + const previousCount = this.previousListCounts.get(key) ?? 0; + + totalRoomCount += currentCount; + + if (currentCount !== previousCount) { + changes[key] = { + previous: previousCount, + current: currentCount, + delta: currentCount - previousCount, + }; + this.previousListCounts.set(key, currentCount); + hasChanges = true; + } + }); + + if (hasChanges || !this.initialSyncCompleted) { + debugLog.info('sync', 'Room counts changed in sync cycle', { + syncNumber: this.syncCount, + changes, + totalRoomCount, + isInitialSync: !this.initialSyncCompleted, + }); + } + + // Mark initial sync as complete after first successful cycle + if (!this.initialSyncCompleted) { + this.initialSyncCompleted = true; + debugLog.info('sync', 'Initial sync completed', { + syncNumber: this.syncCount, + totalRoomCount, + listCounts: Object.fromEntries( + this.listKeys.map((key) => [key, this.slidingSync.getListData(key)?.joinedCount ?? 0]) + ), + timeElapsed: `${(performance.now() - syncStartTime).toFixed(2)}ms`, + }); + } + this.expandListsToKnownCount(); + + const syncDuration = performance.now() - syncStartTime; + if (syncDuration > 1000) { + debugLog.warn('sync', 'Slow sync cycle detected', { + syncNumber: this.syncCount, + duration: `${syncDuration.toFixed(2)}ms`, + totalRoomCount, + }); + } }; this.onConnectionChange = () => { + const isOnline = navigator.onLine; + const connectionInfo = + typeof navigator !== 'undefined' ? (navigator as any).connection : undefined; + const effectiveType = connectionInfo?.effectiveType; + const downlink = connectionInfo?.downlink; + + debugLog.info('network', `Network connectivity changed: ${isOnline ? 'online' : 'offline'}`, { + online: isOnline, + effectiveType, + downlink: downlink ? `${downlink} Mbps` : undefined, + }); + + if (!isOnline) { + debugLog.warn('network', 'Device went offline - sync paused', { + syncNumber: this.syncCount, + }); + } else { + debugLog.info('network', 'Device back online - sync will resume', { + syncNumber: this.syncCount, + }); + } + if (this.disposed || !this.adaptiveTimeline) return; const nextLimit = resolveAdaptiveRoomTimelineLimit( this.configuredTimelineLimit, readAdaptiveSignals() ); if (nextLimit === this.roomTimelineLimit) return; + debugLog.info('sync', `Adaptive timeline limit updated to ${nextLimit}`, { + limit: nextLimit, + previousLimit: this.roomTimelineLimit, + reason: 'connection change', + }); this.roomTimelineLimit = nextLimit; this.applyRoomTimelineLimit(nextLimit); log.log( @@ -379,6 +493,15 @@ export class SlidingSyncManager { } public attach(): void { + debugLog.info('sync', 'Attaching sliding sync listeners', { + proxyBaseUrl: this.proxyBaseUrl, + listPageSize: this.listPageSize, + roomTimelineLimit: this.roomTimelineLimit, + adaptiveTimeline: this.adaptiveTimeline, + maxRooms: this.maxRooms, + lists: this.listKeys, + }); + this.slidingSync.on(SlidingSyncEvent.Lifecycle, this.onLifecycle); const connection = ( typeof navigator !== 'undefined' ? (navigator as any).connection : undefined @@ -395,10 +518,21 @@ export class SlidingSyncManager { window.addEventListener('online', this.onConnectionChange); window.addEventListener('offline', this.onConnectionChange); } + + debugLog.info('sync', 'Sliding sync listeners attached successfully', { + hasConnectionAPI: !!connection, + hasWindowEvents: typeof window !== 'undefined', + }); } public dispose(): void { if (this.disposed) return; + + debugLog.info('sync', 'Disposing sliding sync', { + syncCount: this.syncCount, + initialSyncCompleted: this.initialSyncCompleted, + }); + this.disposed = true; this.slidingSync.removeListener(SlidingSyncEvent.Lifecycle, this.onLifecycle); const connection = ( @@ -416,6 +550,10 @@ export class SlidingSyncManager { window.removeEventListener('online', this.onConnectionChange); window.removeEventListener('offline', this.onConnectionChange); } + + debugLog.info('sync', 'Sliding sync disposed successfully', { + totalSyncCycles: this.syncCount, + }); } private applyRoomTimelineLimit(timelineLimit: number): void { @@ -455,10 +593,16 @@ export class SlidingSyncManager { let allListsComplete = true; let expandedAny = false; + const expansionStartTime = performance.now(); + const expansionDetails: Record = {}; + this.listKeys.forEach((key) => { const listData = this.slidingSync.getListData(key); const knownCount = listData?.joinedCount ?? 0; - if (knownCount <= 0) return; + if (knownCount <= 0) { + expansionDetails[key] = { status: 'empty', knownCount: 0 }; + return; + } const existing = this.slidingSync.getListParams(key); const currentEnd = getListEndIndex(existing); @@ -468,6 +612,7 @@ export class SlidingSyncManager { if (currentEnd >= maxEnd) { // This list is fully loaded + expansionDetails[key] = { status: 'complete', knownCount, currentEnd }; return; } @@ -480,16 +625,51 @@ export class SlidingSyncManager { const chunkSize = 100; const desiredEnd = Math.min(currentEnd + chunkSize, maxEnd); + if (desiredEnd === currentEnd) { + expansionDetails[key] = { + status: 'complete', + knownCount, + currentEnd, + desiredEnd, + }; + return; + } + this.slidingSync.setListRanges(key, [[0, desiredEnd]]); expandedAny = true; + expansionDetails[key] = { + status: 'expanding', + knownCount, + previousEnd: currentEnd, + newEnd: desiredEnd, + roomsToLoad: desiredEnd - currentEnd, + }; + + debugLog.info('sync', `Expanding list "${key}" to full range`, { + list: key, + knownCount, + previousEnd: currentEnd, + newEnd: desiredEnd, + roomsToLoad: desiredEnd - currentEnd, + }); + if (knownCount > this.maxRooms) { log.warn( `Sliding Sync list "${key}" capped at ${this.maxRooms}/${knownCount} rooms for ${this.mx.getUserId()}` ); + debugLog.warn('sync', `List "${key}" exceeds maxRooms limit`, { + list: key, + knownCount, + maxRooms: this.maxRooms, + cappedCount: this.maxRooms, + }); } }); + const expansionDuration = performance.now() - expansionStartTime; + const hasExpansions = Object.values(expansionDetails).some((d) => d.status === 'expanding'); + // Mark as fully loaded once all lists are complete if (allListsComplete) { this.listsFullyLoaded = true; @@ -497,6 +677,23 @@ export class SlidingSyncManager { } else if (expandedAny) { log.log(`Sliding Sync lists expanding... for ${this.mx.getUserId()}`); } + + if (hasExpansions) { + debugLog.info('sync', 'List expansion completed', { + syncNumber: this.syncCount, + lists: expansionDetails, + timeElapsed: `${expansionDuration.toFixed(2)}ms`, + }); + } + + if (expansionDuration > 500) { + debugLog.warn('sync', 'Slow list expansion detected', { + duration: `${expansionDuration.toFixed(2)}ms`, + expandedLists: Object.keys(expansionDetails).filter( + (key) => expansionDetails[key].status === 'expanding' + ), + }); + } } /** @@ -530,8 +727,13 @@ export class SlidingSyncManager { } else { this.slidingSync.setList(listKey, list); } - } catch { + } catch (error) { // ignore — the list will be re-sent on the next sync cycle + debugLog.warn('sync', `Failed to update list "${listKey}"`, { + list: listKey, + error: error instanceof Error ? error.message : String(error), + updateType: updateArgs.ranges && Object.keys(updateArgs).length === 1 ? 'ranges' : 'full', + }); } return this.slidingSync.getListParams(listKey) ?? list; }