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

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,7 +62,9 @@ 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,
@@ -66,7 +72,7 @@ class MediaSender @AssistedInject constructor(
                 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))