[TMP] More missing message debugging

Change-Id: Ia6ad08fa6a51365ba6f4e5a880f9ce804f3026c5
SchildiChat · Mar 11, 2022 · 12e4853 · 12e4853
1 parent 38cfd2a
commit 12e4853
Show file tree

Hide file tree

Showing 2 changed files with 24 additions and 4 deletions.
diff --git a/...id/src/main/java/org/matrix/android/sdk/internal/session/room/timeline/DefaultTimeline.kt b/...id/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<TimelineEvent>) {
-    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,18 +401,20 @@ fun checkTimelineConsistency(location: String, events: List<TimelineEvent>) {
                 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)) {
                     // Note that jumps in either direction may be normal for some scenarios:
                     // - 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/...roid/src/main/java/org/matrix/android/sdk/internal/session/room/timeline/TimelineChunk.kt b/...roid/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<TimelineEvent>()
         //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<TimelineEventEntity>, 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)
         }