diff --git a/src/logger/types.ts b/src/logger/types.ts index cc700dc58b..9d18f4ff06 100644 --- a/src/logger/types.ts +++ b/src/logger/types.ts @@ -7,8 +7,7 @@ export enum LogContext { Default = 'logger', Session = 'session', Notifications = 'notifications', - ConversationAgent = 'conversation-agent', - DMsAgent = 'dms-agent', + Chat = 'chat', ReportDialog = 'report-dialog', FeedFeedback = 'feed-feedback', PostSource = 'post-source', diff --git a/src/screens/Messages/Conversation.tsx b/src/screens/Messages/Conversation.tsx index 428ece2b7a..fcaecc425b 100644 --- a/src/screens/Messages/Conversation.tsx +++ b/src/screens/Messages/Conversation.tsx @@ -27,11 +27,12 @@ import {useEmail} from '#/state/email-verification' import {ConvoProvider, isConvoActive, useConvo} from '#/state/messages/convo' import {ConvoStatus} from '#/state/messages/convo/types' import {useCurrentConvoId} from '#/state/messages/current-convo-id' +import {logger} from '#/state/messages/logger' import {useModerationOpts} from '#/state/preferences/moderation-opts' import {useConvoQuery} from '#/state/queries/messages/conversation' import {useSession} from '#/state/session' import {MessagesList} from '#/screens/Messages/components/MessagesList' -import {atoms as a, useTheme, web} from '#/alf' +import {atoms as a, web} from '#/alf' import {AgeRestrictedScreen} from '#/components/ageAssurance/AgeRestrictedScreen' import {useAgeAssuranceCopy} from '#/components/ageAssurance/useAgeAssuranceCopy' import * as Dialog from '#/components/Dialog' @@ -100,7 +101,6 @@ export function MessagesConversationScreenInner({route}: Props) { } function Inner({convoId}: {convoId: string}) { - const t = useTheme() const convoState = useConvo() const {t: l} = useLingui() const {currentAccount} = useSession() @@ -124,12 +124,35 @@ function Inner({convoId}: {convoId: string}) { !convoState.isFetchingHistory && convoState.items.length === 0) + const prevReadyToShow = useRef(readyToShow) + // eslint-disable-next-line react-hooks/refs + if (prevReadyToShow.current !== readyToShow) { + logger.debug('readyToShow flip', { + convoId, + // eslint-disable-next-line react-hooks/refs + from: prevReadyToShow.current, + to: readyToShow, + hasScrolled, + status: convoState.status, + isFetchingHistory: convoState.isFetchingHistory, + itemCount: isConvoActive(convoState) ? convoState.items.length : 0, + }) + // eslint-disable-next-line react-hooks/refs + prevReadyToShow.current = readyToShow + } + // Any time that we re-render the `Initializing` state, we have to reset `hasScrolled` to false. After entering this // state, we know that we're resetting the list of messages and need to re-scroll to the bottom when they get added. const [prevState, setPrevState] = useState(convoState.status) if (prevState !== convoState.status) { + logger.debug('status transition', { + convoId, + from: prevState, + to: convoState.status, + }) setPrevState(convoState.status) if (convoState.status === ConvoStatus.Initializing) { + logger.debug('resetting hasScrolled (Initializing)', {convoId}) setHasScrolled(false) } } @@ -176,7 +199,8 @@ function Inner({convoId}: {convoId: string}) { a.h_full, a.justify_center, a.align_center, - t.atoms.bg, + // t.atoms.bg, + {backgroundColor: 'rgba(255,0,0,0.2)'}, ]}> diff --git a/src/screens/Messages/components/MessagesList.tsx b/src/screens/Messages/components/MessagesList.tsx index c0ea298ba5..8319ad26a0 100644 --- a/src/screens/Messages/components/MessagesList.tsx +++ b/src/screens/Messages/components/MessagesList.tsx @@ -37,13 +37,13 @@ import { convertBskyAppUrlIfNeeded, isBskyPostUrl, } from '#/lib/strings/url-helpers' -import {logger} from '#/logger' import { type ActiveConvoStates, isConvoActive, useConvoActive, } from '#/state/messages/convo' import {type ConvoState, ConvoStatus} from '#/state/messages/convo/types' +import {logger} from '#/state/messages/logger' import {useGetPost} from '#/state/queries/post' import {useAgent} from '#/state/session' import {List, type ListMethods} from '#/view/com/util/List' @@ -230,10 +230,16 @@ export function MessagesList({ if (!hasInitiallyScrolled.current && renderItems.length > 0) { hasInitiallyScrolled.current = true flatListRef.current?.scrollToOffset({offset: height, animated: false}) + logger.debug('onContentSizeChange: initial scroll', { + height, + itemCount: convoState.items.length, + isFetchingHistory: convoState.isFetchingHistory, + }) // If history is already done loading, mark ready after a frame for the scroll to settle. // Otherwise, the footer sentinel's onLayout will handle it when history finishes. if (!convoState.isFetchingHistory) { requestAnimationFrame(() => { + logger.debug('setHasScrolled(true) via onContentSizeChange') setHasScrolled(true) }) } @@ -388,6 +394,7 @@ export function MessagesList({ rt = stripInvalidMentions(rt) if (!hasScrolled) { + logger.debug('setHasScrolled(true) via onSendMessage') setHasScrolled(true) } @@ -448,12 +455,18 @@ export function MessagesList({ // Footer sentinel: when history is still loading during the initial scroll, the footer's onLayout fires each time // new items are prepended (shifting its position). Once history finishes, this triggers setHasScrolled. const onFooterLayout = useCallback(() => { + logger.debug('onFooterLayout', { + hasInitiallyScrolled: hasInitiallyScrolled.current, + hasScrolled, + isFetchingHistory: convoState.isFetchingHistory, + }) if ( hasInitiallyScrolled.current && !hasScrolled && !convoState.isFetchingHistory ) { requestAnimationFrame(() => { + logger.debug('setHasScrolled(true) via onFooterLayout') setHasScrolled(true) }) } diff --git a/src/state/messages/convo/agent.ts b/src/state/messages/convo/agent.ts index 6220d5faac..e4a92ad8d6 100644 --- a/src/state/messages/convo/agent.ts +++ b/src/state/messages/convo/agent.ts @@ -16,7 +16,6 @@ import { isErrorMaybeAppPasswordPermissions, isNetworkError, } from '#/lib/strings/errors' -import {Logger} from '#/logger' import { ACTIVE_POLL_INTERVAL, BACKGROUND_POLL_INTERVAL, @@ -37,6 +36,7 @@ import { } from '#/state/messages/convo/types' import {type MessagesEventBus} from '#/state/messages/events/agent' import {type MessagesEventBusError} from '#/state/messages/events/types' +import {logger} from '#/state/messages/logger' import { type ConvoWithDetails, type GroupConvoMember, @@ -44,8 +44,6 @@ import { } from '#/components/dms/util' import {IS_NATIVE} from '#/env' -const logger = Logger.create(Logger.Context.ConversationAgent) - export function isConvoItemMessage( item: ConvoItem, ): item is ConvoItem & {type: 'message'} { @@ -283,6 +281,7 @@ export class Convo { dispatch(action: ConvoDispatch) { const prevStatus = this.status + const dispatchStart = Date.now() switch (this.status) { case ConvoStatus.Uninitialized: { @@ -465,8 +464,10 @@ export class Convo { logger.debug(`dispatch '${action.event}'`, { id: this.id, + convoId: this.convoId, prev: prevStatus, next: this.status, + dispatchMs: Date.now() - dispatchStart, }) this.updateLastActiveTimestamp() @@ -542,6 +543,8 @@ export class Convo { } private async setup() { + const setupStart = Date.now() + logger.debug('setup start', {id: this.id, convoId: this.convoId}) try { const {convo} = await this.fetchConvo() @@ -562,6 +565,13 @@ export class Convo { const userIsDisabled = Boolean(self.chatDisabled) + logger.debug('setup complete', { + id: this.id, + convoId: this.convoId, + setupMs: Date.now() - setupStart, + userIsDisabled, + }) + if (userIsDisabled) { this.dispatch({event: ConvoDispatchEvent.Disable}) } else { @@ -569,6 +579,12 @@ export class Convo { } } catch (err) { const e = err as Error + logger.debug('setup failed', { + id: this.id, + convoId: this.convoId, + setupMs: Date.now() - setupStart, + message: e.message, + }) if (!isNetworkError(e) && !isErrorMaybeAppPasswordPermissions(e)) { logger.error('setup failed', { safeMessage: e.message, @@ -637,6 +653,8 @@ export class Convo { // non-blocking void this.fetchMemberList() + const fetchStart = Date.now() + logger.debug('fetchConvo start', {id: this.id, convoId: this.convoId}) this.pendingFetchConvo = (async () => { try { const response = await networkRetry(2, () => { @@ -648,6 +666,12 @@ export class Convo { const convo = response.data.convo + logger.debug('fetchConvo done', { + id: this.id, + convoId: this.convoId, + fetchMs: Date.now() - fetchStart, + }) + return { convo, } @@ -680,7 +704,14 @@ export class Convo { // use `useListConvoMembersQuery` // we shouldn't also block loading off of this - the UI should be resilient async fetchMemberList() { + const start = Date.now() let cursor: string | undefined + let pages = 0 + let total = 0 + logger.debug('fetchMemberList start', { + id: this.id, + convoId: this.convoId, + }) do { const result = await networkRetry(2, () => { return this.agent.chat.bsky.convo.getConvoMembers( @@ -693,16 +724,31 @@ export class Convo { ) }) cursor = result.data.cursor + pages++ + total += result.data.members.length for (const member of result.data.members) { this.relatedProfiles.set(member.did, member) } } while (cursor) + logger.debug('fetchMemberList done', { + id: this.id, + convoId: this.convoId, + pages, + total, + fetchMs: Date.now() - start, + }) } private fetchMessageHistoryError: {retry: () => void} | undefined async fetchMessageHistory() { - logger.debug('fetch message history', {}) + logger.debug('fetchMessageHistory called', { + id: this.id, + convoId: this.convoId, + oldestRev: this.oldestRev, + isFetchingHistory: this.isFetchingHistory, + hasError: !!this.fetchMessageHistoryError, + }) /* * If oldestRev is null, we've fetched all history. @@ -721,6 +767,7 @@ export class Convo { */ if (this.fetchMessageHistoryError) return + const start = Date.now() try { this.isFetchingHistory = true this.commit() @@ -738,6 +785,15 @@ export class Convo { }) const {cursor, messages, relatedProfiles} = response.data + logger.debug('fetchMessageHistory done', { + id: this.id, + convoId: this.convoId, + fetchMs: Date.now() - start, + returnedMessages: messages.length, + returnedCursor: cursor, + prevCursor: nextCursor, + }) + this.oldestRev = cursor ?? null if (relatedProfiles) { @@ -773,6 +829,12 @@ export class Convo { } } catch (err) { const e = err as Error + logger.debug('fetchMessageHistory failed', { + id: this.id, + convoId: this.convoId, + fetchMs: Date.now() - start, + message: e.message, + }) if (!isNetworkError(e) && !isErrorMaybeAppPasswordPermissions(e)) { logger.error('failed to fetch message history', { safeMessage: e.message, @@ -835,6 +897,14 @@ export class Convo { ingestFirehose(events: ChatBskyConvoGetLog.OutputSchema['logs']) { let needsCommit = false + const hadHistory = this.oldestRev !== undefined + logger.debug('ingestFirehose', { + id: this.id, + convoId: this.convoId, + eventCount: events.length, + hadHistory, + latestRev: this.latestRev, + }) for (const ev of events) { /* diff --git a/src/state/messages/events/agent.ts b/src/state/messages/events/agent.ts index ce9518212b..5e575f1f12 100644 --- a/src/state/messages/events/agent.ts +++ b/src/state/messages/events/agent.ts @@ -8,7 +8,6 @@ import { isErrorMaybeAppPasswordPermissions, isNetworkError, } from '#/lib/strings/errors' -import {Logger} from '#/logger' import { BACKGROUND_POLL_INTERVAL, DEFAULT_POLL_INTERVAL, @@ -21,8 +20,7 @@ import { type MessagesEventBusParams, MessagesEventBusStatus, } from '#/state/messages/events/types' - -const logger = Logger.create(Logger.Context.DMsAgent) +import {logger} from '#/state/messages/logger' export class MessagesEventBus { private id: string @@ -110,6 +108,7 @@ export class MessagesEventBus { private dispatch(action: MessagesEventBusDispatch) { const prevStatus = this.status + const dispatchStart = Date.now() switch (this.status) { case MessagesEventBusStatus.Initializing: { @@ -235,11 +234,14 @@ export class MessagesEventBus { id: this.id, prev: prevStatus, next: this.status, + pollInterval: this.pollInterval, + dispatchMs: Date.now() - dispatchStart, }) } private async init() { - logger.debug(`init`, {}) + const start = Date.now() + logger.debug(`init start`, {id: this.id}) try { const response = await networkRetry(2, () => { @@ -261,8 +263,19 @@ export class MessagesEventBus { } } + logger.debug(`init done`, { + id: this.id, + initMs: Date.now() - start, + latestRev: this.latestRev, + }) + this.dispatch({event: MessagesEventBusDispatchEvent.Ready}) } catch (e: any) { + logger.debug(`init failed`, { + id: this.id, + initMs: Date.now() - start, + message: e.message, + }) if (!isNetworkError(e) && !isErrorMaybeAppPasswordPermissions(e)) { logger.error(`init failed`, { safeMessage: e.message, @@ -327,15 +340,7 @@ export class MessagesEventBus { if (this.isPolling) return this.isPolling = true - - // logger.debug( - // `poll`, - // { - // requestedPollIntervals: Array.from( - // this.requestedPollIntervals.values(), - // ), - // }, - // ) + const start = Date.now() try { const response = await networkRetry(2, () => { @@ -375,9 +380,20 @@ export class MessagesEventBus { } if (needsEmit) { + logger.debug('poll emit', { + id: this.id, + pollMs: Date.now() - start, + batchSize: batch.length, + totalReturned: events.length, + }) this.emitter.emit('event', {type: 'logs', logs: batch}) } } catch (e: any) { + logger.debug('poll failed', { + id: this.id, + pollMs: Date.now() - start, + message: e.message, + }) if (!isNetworkError(e) && !isErrorMaybeAppPasswordPermissions(e)) { logger.error(`poll events failed`, { safeMessage: e.message, diff --git a/src/state/messages/logger.ts b/src/state/messages/logger.ts new file mode 100644 index 0000000000..1041ce6baf --- /dev/null +++ b/src/state/messages/logger.ts @@ -0,0 +1,3 @@ +import {Logger} from '#/logger' + +export const logger = Logger.create(Logger.Context.Chat)