From d9dde270b208a0954bf7b3213e5d9daceeb6572a Mon Sep 17 00:00:00 2001 From: Jorge Martin Espinosa Date: Tue, 26 Aug 2025 09:02:15 +0200 Subject: [PATCH] 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 --- .../preview/AttachmentsPreviewPresenter.kt | 2 ++ .../AttachmentsPreviewPresenterTest.kt | 5 ++++- .../matrix/impl/timeline/RustTimeline.kt | 5 +++++ .../libraries/mediaupload/api/MediaSender.kt | 20 +++++++++++++++---- .../impl/AndroidMediaPreProcessor.kt | 9 +++++++++ 5 files changed, 36 insertions(+), 5 deletions(-) diff --git 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 index 10f99b7641..d01b11a026 100644 --- 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 = { diff --git 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 index 38535f3bdb..0f1da066bd 100644 --- 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 { diff --git 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 index ee60a464e7..97d9ef68c1 100644 --- 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 { + 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 { + 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 { + 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 { + Timber.d("Sending file ${file.path.hash()}") return sendAttachment(listOf(file)) { inner.sendFile( params = UploadParameters( diff --git 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 index e11ec804cd..2de5b84284 100644 --- 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 { + 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 { + 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.handleSendResult() = this + private fun Result.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() diff --git 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 index e1758e9429..cbca90f940 100644 --- 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))