Add extra logs for sending media (#5218)

* Add extra logs for sending media

We have some issues with stuck media uploads that could use some logs to understand where the process gets stuck.

* Fix mocks for test

Author: jmartinesp

features/messages/impl/src/main/kotlin/io/element/android/features/messages/impl/attachments/preview/AttachmentsPreviewPresenter.kt

@@ -24,6 +24,7 @@ import io.element.android.features.messages.impl.attachments.Attachment
 import io.element.android.features.messages.impl.attachments.video.MediaOptimizationSelectorPresenter
 import io.element.android.libraries.androidutils.file.TemporaryUriDeleter
 import io.element.android.libraries.androidutils.file.safeDelete
+import io.element.android.libraries.androidutils.hash.hash
 import io.element.android.libraries.architecture.Presenter
 import io.element.android.libraries.core.coroutine.CoroutineDispatchers
 import io.element.android.libraries.core.coroutine.firstInstanceOf
@@ -261,6 +262,7 @@ class AttachmentsPreviewPresenter @AssistedInject constructor(
             mediaOptimizationConfig = mediaOptimizationConfig,
         ).fold(
             onSuccess = { mediaUploadInfo ->
+                Timber.d("Media ${mediaUploadInfo.file.path.orEmpty().hash()} finished processing, it's now ready to upload")
                 sendActionState.value = SendActionState.Sending.ReadyToUpload(mediaUploadInfo)
             },
             onFailure = {

features/messages/impl/src/test/kotlin/io/element/android/features/messages/impl/attachments/AttachmentsPreviewPresenterTest.kt

@@ -58,6 +58,7 @@ import io.element.android.tests.testutils.lambda.lambdaRecorder
 import io.element.android.tests.testutils.lambda.value
 import io.element.android.tests.testutils.test
 import io.element.android.tests.testutils.testCoroutineDispatchers
+import io.mockk.every
 import io.mockk.mockk
 import kotlinx.collections.immutable.persistentListOf
 import kotlinx.coroutines.CompletableDeferred
@@ -77,7 +78,9 @@ class AttachmentsPreviewPresenterTest {
     @get:Rule
     val warmUpRule = WarmUpRule()
 
-    private val mockMediaUrl: Uri = mockk("localMediaUri")
+    private val mockMediaUrl: Uri = mockk("localMediaUri") {
+        every { path } returns "/path/to/media"
+    }
 
     @Test
     fun `present - initial state`() = runTest {

libraries/matrix/impl/src/main/kotlin/io/element/android/libraries/matrix/impl/timeline/RustTimeline.kt

@@ -7,6 +7,7 @@
 
 package io.element.android.libraries.matrix.impl.timeline
 
+import io.element.android.libraries.androidutils.hash.hash
 import io.element.android.libraries.core.extensions.runCatchingExceptions
 import io.element.android.libraries.matrix.api.core.EventId
 import io.element.android.libraries.matrix.api.core.RoomId
@@ -338,6 +339,7 @@ class RustTimeline(
         formattedCaption: String?,
         inReplyToEventId: EventId?,
     ): Result<MediaUploadHandler> {
+        Timber.d("Sending image ${file.path.hash()}")
         return sendAttachment(listOfNotNull(file, thumbnailFile)) {
             inner.sendImage(
                 params = UploadParameters(
@@ -363,6 +365,7 @@ class RustTimeline(
         formattedCaption: String?,
         inReplyToEventId: EventId?,
     ): Result<MediaUploadHandler> {
+        Timber.d("Sending video ${file.path.hash()}")
         return sendAttachment(listOfNotNull(file, thumbnailFile)) {
             inner.sendVideo(
                 params = UploadParameters(
@@ -387,6 +390,7 @@ class RustTimeline(
         formattedCaption: String?,
         inReplyToEventId: EventId?,
     ): Result<MediaUploadHandler> {
+        Timber.d("Sending audio ${file.path.hash()}")
         return sendAttachment(listOf(file)) {
             inner.sendAudio(
                 params = UploadParameters(
@@ -410,6 +414,7 @@ class RustTimeline(
         formattedCaption: String?,
         inReplyToEventId: EventId?,
     ): Result<MediaUploadHandler> {
+        Timber.d("Sending file ${file.path.hash()}")
         return sendAttachment(listOf(file)) {
             inner.sendFile(
                 params = UploadParameters(

libraries/mediaupload/api/src/main/kotlin/io/element/android/libraries/mediaupload/api/MediaSender.kt

@@ -11,6 +11,7 @@ import android.net.Uri
 import dagger.assisted.Assisted
 import dagger.assisted.AssistedFactory
 import dagger.assisted.AssistedInject
+import io.element.android.libraries.androidutils.hash.hash
 import io.element.android.libraries.core.extensions.flatMap
 import io.element.android.libraries.core.extensions.flatMapCatching
 import io.element.android.libraries.matrix.api.core.EventId
@@ -20,6 +21,8 @@ import io.element.android.libraries.matrix.api.room.JoinedRoom
 import io.element.android.libraries.matrix.api.timeline.Timeline
 import kotlinx.coroutines.CancellationException
 import kotlinx.coroutines.Job
+import timber.log.Timber
+import java.io.File
 import java.util.concurrent.ConcurrentHashMap
 
 class MediaSender @AssistedInject constructor(
@@ -43,6 +46,7 @@ class MediaSender @AssistedInject constructor(
         mimeType: String,
         mediaOptimizationConfig: MediaOptimizationConfig,
     ): Result<MediaUploadInfo> {
+        Timber.d("Pre-processing media | uri: ${mediaId(uri)} | mimeType: $mimeType")
         return preProcessor
             .process(
                 uri = uri,
@@ -58,15 +62,17 @@ class MediaSender @AssistedInject constructor(
         formattedCaption: String?,
         inReplyToEventId: EventId?,
     ): Result<Unit> {
+        val mediaLogId = mediaId(mediaUploadInfo.file)
         return getTimeline().flatMap {
+            Timber.d("Started sending media $mediaLogId using timeline: ${it.mode}")
             it.sendMedia(
                 uploadInfo = mediaUploadInfo,
                 caption = caption,
                 formattedCaption = formattedCaption,
                 inReplyToEventId = inReplyToEventId,
             )
         }
-            .handleSendResult()
+            .handleSendResult(mediaLogId)
     }
 
     suspend fun sendMedia(
@@ -92,7 +98,7 @@ class MediaSender @AssistedInject constructor(
                     inReplyToEventId = inReplyToEventId,
                 )
             }
-            .handleSendResult()
+            .handleSendResult(mediaId(uri))
     }
 
     suspend fun sendVoiceMessage(
@@ -122,17 +128,19 @@ class MediaSender @AssistedInject constructor(
                     inReplyToEventId = inReplyToEventId,
                 )
             }
-            .handleSendResult()
+            .handleSendResult(mediaId(uri))
     }
 
-    private fun Result<Unit>.handleSendResult() = this
+    private fun Result<Unit>.handleSendResult(mediaId: String) = this
         .onFailure { error ->
             val job = ongoingUploadJobs.remove(Job)
+            Timber.e(error, "Sending media $mediaId failed. Removing ongoing upload job. Total: ${ongoingUploadJobs.size}")
             if (error !is CancellationException) {
                 job?.cancel()
             }
         }
         .onSuccess {
+            Timber.d("Sent media $mediaId successfully. Removing ongoing upload job. Total: ${ongoingUploadJobs.size}")
             ongoingUploadJobs.remove(Job)
         }
 
@@ -195,6 +203,7 @@ class MediaSender @AssistedInject constructor(
         @Suppress("RunCatchingNotAllowed")
         return handler
             .mapCatching { uploadHandler ->
+                Timber.d("Added ongoing upload job, total: ${ongoingUploadJobs.size + 1}")
                 ongoingUploadJobs[Job] = uploadHandler
                 uploadHandler.await()
             }
@@ -214,3 +223,6 @@ class MediaSender @AssistedInject constructor(
      */
     fun cleanUp() = preProcessor.cleanUp()
 }
+
+private fun mediaId(uri: Uri?): String = uri?.path.orEmpty().hash()
+private fun mediaId(file: File): String = file.path.orEmpty().hash()

libraries/mediaupload/impl/src/main/kotlin/io/element/android/libraries/mediaupload/impl/AndroidMediaPreProcessor.kt

@@ -17,6 +17,7 @@ import io.element.android.libraries.androidutils.file.TemporaryUriDeleter
 import io.element.android.libraries.androidutils.file.createTmpFile
 import io.element.android.libraries.androidutils.file.getFileName
 import io.element.android.libraries.androidutils.file.safeRenameTo
+import io.element.android.libraries.androidutils.hash.hash
 import io.element.android.libraries.androidutils.media.runAndRelease
 import io.element.android.libraries.core.coroutine.CoroutineDispatchers
 import io.element.android.libraries.core.data.tryOrNull
@@ -107,6 +108,8 @@ class AndroidMediaPreProcessor @Inject constructor(
     }.mapFailure { MediaPreProcessor.Failure(it) }
 
     override fun cleanUp() {
+        Timber.d("Cleaning up temporary media files")
+
         // Clear temporary files created in older versions of the app
         cacheDir.listFiles()?.onEach { file ->
             if (file.isFile) {
@@ -129,6 +132,7 @@ class AndroidMediaPreProcessor @Inject constructor(
     }
 
     private suspend fun processFile(uri: Uri, mimeType: String): MediaUploadInfo {
+        Timber.d("Processing file ${uri.path.orEmpty().hash()}")
         val file = copyToTmpFile(uri)
         val info = FileInfo(
             mimetype = mimeType,
@@ -140,6 +144,7 @@ class AndroidMediaPreProcessor @Inject constructor(
     }
 
     private fun MediaUploadInfo.postProcess(uri: Uri): MediaUploadInfo {
+        Timber.d("Finished processing, post-processing ${uri.path.orEmpty().hash()}")
         val name = context.getFileName(uri) ?: return this
         val renamedFile = File(context.cacheDir, name).also {
             file.safeRenameTo(it)
@@ -154,6 +159,7 @@ class AndroidMediaPreProcessor @Inject constructor(
     }
 
     private suspend fun processImage(uri: Uri, mimeType: String, shouldBeCompressed: Boolean): MediaUploadInfo {
+        Timber.d("Processing image ${uri.path.orEmpty().hash()}")
         suspend fun processImageWithCompression(): MediaUploadInfo {
             // Read the orientation metadata from its own stream. Trying to reuse this stream for compression will fail.
             val orientation = contentResolver.openInputStream(uri).use { input ->
@@ -217,6 +223,7 @@ class AndroidMediaPreProcessor @Inject constructor(
     }
 
     private suspend fun processVideo(uri: Uri, mimeType: String?, videoCompressionPreset: VideoCompressionPreset): MediaUploadInfo {
+        Timber.d("Processing video ${uri.path.orEmpty().hash()}")
         val resultFile = runCatchingExceptions {
             videoCompressor.compress(uri, videoCompressionPreset)
                 .onEach {
@@ -244,12 +251,14 @@ class AndroidMediaPreProcessor @Inject constructor(
                 thumbnailFile = thumbnailInfo?.file
             )
         } else {
+            Timber.d("Could not transcode video ${uri.path.orEmpty().hash()}, sending original file as plain file")
             // If the video could not be compressed, just use the original one, but send it as a file
             return processFile(uri, MimeTypes.OctetStream)
         }
     }
 
     private suspend fun processAudio(uri: Uri, mimeType: String?): MediaUploadInfo {
+        Timber.d("Processing audio ${uri.path.orEmpty().hash()}")
         val file = copyToTmpFile(uri)
         return MediaMetadataRetriever().runAndRelease {
             setDataSource(context, Uri.fromFile(file))