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
2025-08-26 09:02:15 +02:00
parent f245fe2399
commit d9dde270b2
5 changed files with 36 additions and 5 deletions
--- a/features/messages/impl/src/main/kotlin/io/element/android/features/messages/impl/attachments/preview/AttachmentsPreviewPresenter.kt
+++ b/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 = {
--- a/features/messages/impl/src/test/kotlin/io/element/android/features/messages/impl/attachments/AttachmentsPreviewPresenterTest.kt
+++ b/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 {
--- a/libraries/matrix/impl/src/main/kotlin/io/element/android/libraries/matrix/impl/timeline/RustTimeline.kt
+++ b/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(
--- a/libraries/mediaupload/api/src/main/kotlin/io/element/android/libraries/mediaupload/api/MediaSender.kt
+++ b/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()
--- a/libraries/mediaupload/impl/src/main/kotlin/io/element/android/libraries/mediaupload/impl/AndroidMediaPreProcessor.kt
+++ b/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))