From 12e4853c59f038cff11c320df25c849a0f3eb008 Mon Sep 17 00:00:00 2001 From: SpiritCroc Date: Fri, 11 Mar 2022 08:18:54 +0100 Subject: [PATCH] [TMP] More missing message debugging Change-Id: Ia6ad08fa6a51365ba6f4e5a880f9ce804f3026c5 --- .../session/room/timeline/DefaultTimeline.kt | 7 +++++-- .../session/room/timeline/TimelineChunk.kt | 21 +++++++++++++++++-- 2 files changed, 24 insertions(+), 4 deletions(-) diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/room/timeline/DefaultTimeline.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/room/timeline/DefaultTimeline.kt index f31e0cefd9e..5de7a526e64 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/room/timeline/DefaultTimeline.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/room/timeline/DefaultTimeline.kt @@ -389,8 +389,9 @@ internal class DefaultTimeline(private val roomId: String, } fun checkTimelineConsistency(location: String, events: List) { - Timber.d("Check timeline consistency from $location for ${events.size} events") + Timber.i("Check timeline consistency from $location for ${events.size} events, from ${events.firstOrNull()?.eventId} to ${events.lastOrNull()?.eventId}") try { + var potentialIssues = 0 // Note that the "previous" event is actually newer than the currently looked at event, // since the list is ordered from new to old var prev: TimelineEvent? = null @@ -400,6 +401,7 @@ fun checkTimelineConsistency(location: String, events: List) { if (prev.eventId == event.eventId) { // This should never happen in a bug-free world, as far as I'm aware Timber.e("Timeline inconsistency found at $location, $i/${events.size}: double event ${event.eventId}") + potentialIssues++ } else if (prev.displayIndex != event.displayIndex + 1 && // Jumps from -1 to 1 seem to be normal, have only seen index 0 for local echos yet (prev.displayIndex != 1 || event.displayIndex != -1)) { @@ -407,11 +409,12 @@ fun checkTimelineConsistency(location: String, events: List) { // - Events between two chunks lead to a new indexing, so one may start at 1, or even something negative. // - The list may omit unsupported events (I guess?), thus causing gaps in the indices. Timber.w("Possible timeline inconsistency found at $location, $i/${events.size}: ${event.displayIndex}->${prev.displayIndex}, ${event.eventId} -> ${prev.eventId}") + potentialIssues++ } } prev = event } - Timber.d("Done check timeline consistency from $location") + Timber.i("Done check timeline consistency from $location, found $potentialIssues possible issues") } catch (t: Throwable) { Timber.e("Failed check timeline consistency from $location", t) } diff --git a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/room/timeline/TimelineChunk.kt b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/room/timeline/TimelineChunk.kt index e10d3022178..902e45f8713 100644 --- a/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/room/timeline/TimelineChunk.kt +++ b/matrix-sdk-android/src/main/java/org/matrix/android/sdk/internal/session/room/timeline/TimelineChunk.kt @@ -259,6 +259,7 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity, } // Update the relation of existing event builtEvents.getOrNull(builtIndex)?.let { te -> + Timber.i("TimelineChunk.rebuildEvent $eventId at $builtIndex, which was ${te.eventId}") val rebuiltEvent = builder(te) builtEvents[builtIndex] = rebuiltEvent!! true @@ -288,6 +289,7 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity, * whether or not we reached the end/root message */ private fun loadFromStorage(count: Int, direction: Timeline.Direction): LoadedFromStorage { + Timber.i("TimelineChunk.loadFromStorage() start") val displayIndex = getNextDisplayIndex(direction) ?: return LoadedFromStorage() val baseQuery = timelineEventEntities.where() @@ -298,14 +300,18 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity, val builtTimelineEvents = timelineEvents.map { it.buildAndDecryptIfNeeded() } checkTimelineConsistency("TimelineChunk.loadFromStorage-raw-query", builtTimelineEvents) - if (timelineEvents.isEmpty()) return LoadedFromStorage() + if (timelineEvents.isEmpty()) return LoadedFromStorage().also { Timber.i("TimelineChunk.loadFromStorage() empty abort") } // Disabled due to the new fallback // if(!lightweightSettingsStorage.areThreadMessagesEnabled()) { // fetchRootThreadEventsIfNeeded(timelineEvents) // } if (direction == Timeline.Direction.FORWARDS) { builtEventsIndexes.entries.forEach { it.setValue(it.value + timelineEvents.size) } + Timber.i("TimelineChunk.loadFromStorage: insert ${timelineEvents.size} items forwards at start, old size: ${builtEvents.size}") + } else { + Timber.i("TimelineChunk.loadFromStorage: insert ${timelineEvents.size} items backwards at end, old size: ${builtEvents.size}") } + val extraCheck = mutableListOf() //timelineEvents builtTimelineEvents .mapIndexed { index, timelineEvent -> // timelineEventEntity -> @@ -320,10 +326,14 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity, builtEventsIndexes[timelineEvent.eventId] = builtEvents.size builtEvents.add(timelineEvent) } + extraCheck.add(timelineEvent) } + checkTimelineConsistency("TimelineChunk.loadFromStorage-extra-check", extraCheck) return LoadedFromStorage( threadReachedEnd = threadReachedEnd(timelineEvents), - numberOfEvents = timelineEvents.size) + numberOfEvents = timelineEvents.size).also { + Timber.i("TimelineChunk.loadFromStorage() end") + } } /** @@ -432,6 +442,7 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity, * */ private fun handleDatabaseChangeSet(results: RealmResults, changeSet: OrderedCollectionChangeSet) { + Timber.i("TimelineChunk.handleDatabaseChangeSet() start") val insertions = changeSet.insertionRanges for (range in insertions) { val newItems = results @@ -443,6 +454,7 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity, isLastBackward.set(true) } val correctedIndex = range.startIndex + index + Timber.i("TimelineChunk.handleDatabaseChangeSet: insert ${timelineEvent.eventId} at $correctedIndex (${range.startIndex} + $index)") builtEvents.add(correctedIndex, timelineEvent) builtEventsIndexes[timelineEvent.eventId] = correctedIndex } @@ -452,12 +464,17 @@ internal class TimelineChunk(private val chunkEntity: ChunkEntity, for (modificationIndex in (range.startIndex until range.startIndex + range.length)) { val updatedEntity = results[modificationIndex] ?: continue try { + Timber.i("TimelineChunk.handleDatabaseChangeSet: modify ${updatedEntity.eventId} at $modificationIndex (previous: ${builtEvents.getOrNull(modificationIndex)?.eventId})") + if (updatedEntity.eventId != builtEvents.getOrNull(modificationIndex)?.eventId) { + Timber.e("TimelineChunk.handleDatabaseChangeSet: Unexpected modification, bug?!! was using item index $modificationIndex, better could've been ${builtEventsIndexes.getOrDefault(updatedEntity.eventId, null)}") + } builtEvents[modificationIndex] = updatedEntity.buildAndDecryptIfNeeded() } catch (failure: Throwable) { Timber.v("Fail to update items at index: $modificationIndex") } } } + Timber.i("TimelineChunk.handleDatabaseChangeSet() end") if (insertions.isNotEmpty() || modifications.isNotEmpty()) { onBuiltEvents(true) }