add a bunch of chat debug logging

This commit is contained in:
Samuel Newman
2026-04-28 15:29:47 +01:00
parent 366cf7e040
commit 5b481954fe
6 changed files with 148 additions and 23 deletions
+1 -2
View File
@@ -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',
+27 -3
View File
@@ -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)'},
]}>
<View style={[{marginBottom: 75}]}>
<Loader size="xl" />
@@ -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)
})
}
+74 -4
View File
@@ -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) {
/*
+29 -13
View File
@@ -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,
+3
View File
@@ -0,0 +1,3 @@
import {Logger} from '#/logger'
export const logger = Logger.create(Logger.Context.Chat)