Add tracing to media `/upload` endpoint (#15850)

Add tracing instrumentation to media `/upload` code paths to investigate https://github.com/matrix-org/synapse/issues/15841

changelog.d/15850.misc

@@ -0,0 +1 @@
+Add tracing to media `/upload` code paths.

synapse/media/media_repository.py

@@ -35,6 +35,7 @@ from synapse.api.errors import (
 from synapse.config.repository import ThumbnailRequirement
 from synapse.http.site import SynapseRequest
 from synapse.logging.context import defer_to_thread
+from synapse.logging.opentracing import trace
 from synapse.media._base import (
     FileInfo,
     Responder,
@@ -174,6 +175,7 @@ class MediaRepository:
         else:
             self.recently_accessed_locals.add(media_id)
 
+    @trace
     async def create_content(
         self,
         media_type: str,
@@ -710,6 +712,7 @@ class MediaRepository:
         # Could not generate thumbnail.
         return None
 
+    @trace
     async def _generate_thumbnails(
         self,
         server_name: Optional[str],

synapse/media/media_storage.py

@@ -38,6 +38,7 @@ from twisted.protocols.basic import FileSender
 
 from synapse.api.errors import NotFoundError
 from synapse.logging.context import defer_to_thread, make_deferred_yieldable
+from synapse.logging.opentracing import trace
 from synapse.util import Clock
 from synapse.util.file_consumer import BackgroundFileConsumer
 
@@ -76,6 +77,7 @@ class MediaStorage:
         self._spam_checker_module_callbacks = hs.get_module_api_callbacks().spam_checker
         self.clock = hs.get_clock()
 
+    @trace
     async def store_file(self, source: IO, file_info: FileInfo) -> str:
         """Write `source` to the on disk media store, and also any other
         configured storage providers
@@ -95,10 +97,12 @@ class MediaStorage:
 
         return fname
 
+    @trace
     async def write_to_file(self, source: IO, output: IO) -> None:
         """Asynchronously write the `source` to `output`."""
         await defer_to_thread(self.reactor, _write_file_synchronously, source, output)
 
+    @trace
     @contextlib.contextmanager
     def store_into_file(
         self, file_info: FileInfo
@@ -214,6 +218,7 @@ class MediaStorage:
 
         return None
 
+    @trace
     async def ensure_media_is_in_local_cache(self, file_info: FileInfo) -> str:
         """Ensures that the given file is in the local cache. Attempts to
         download it from storage providers if it isn't.
@@ -259,6 +264,7 @@ class MediaStorage:
 
         raise NotFoundError()
 
+    @trace
     def _file_info_to_path(self, file_info: FileInfo) -> str:
         """Converts file_info into a relative path.
 
@@ -301,6 +307,7 @@ class MediaStorage:
         return self.filepaths.local_media_filepath_rel(file_info.file_id)
 
 
+@trace
 def _write_file_synchronously(source: IO, dest: IO) -> None:
     """Write `source` to the file like `dest` synchronously. Should be called
     from a thread.

synapse/media/storage_provider.py

@@ -20,6 +20,7 @@ from typing import TYPE_CHECKING, Callable, Optional
 
 from synapse.config._base import Config
 from synapse.logging.context import defer_to_thread, run_in_background
+from synapse.logging.opentracing import trace
 from synapse.util.async_helpers import maybe_awaitable
 
 from ._base import FileInfo, Responder
@@ -86,6 +87,7 @@ class StorageProviderWrapper(StorageProvider):
     def __str__(self) -> str:
         return "StorageProviderWrapper[%s]" % (self.backend,)
 
+    @trace
     async def store_file(self, path: str, file_info: FileInfo) -> None:
         if not file_info.server_name and not self.store_local:
             return None
@@ -114,6 +116,7 @@ class StorageProviderWrapper(StorageProvider):
 
             run_in_background(store)
 
+    @trace
     async def fetch(self, path: str, file_info: FileInfo) -> Optional[Responder]:
         if file_info.url_cache:
             # Files in the URL preview cache definitely aren't stored here,
@@ -141,6 +144,7 @@ class FileStorageProviderBackend(StorageProvider):
     def __str__(self) -> str:
         return "FileStorageProviderBackend[%s]" % (self.base_directory,)
 
+    @trace
     async def store_file(self, path: str, file_info: FileInfo) -> None:
         """See StorageProvider.store_file"""
 
@@ -159,6 +163,7 @@ class FileStorageProviderBackend(StorageProvider):
             backup_fname,
         )
 
+    @trace
     async def fetch(self, path: str, file_info: FileInfo) -> Optional[Responder]:
         """See StorageProvider.fetch"""
 

synapse/media/thumbnailer.py

@@ -19,6 +19,8 @@ from typing import Optional, Tuple, Type
 
 from PIL import Image
 
+from synapse.logging.opentracing import trace
+
 logger = logging.getLogger(__name__)
 
 EXIF_ORIENTATION_TAG = 0x0112
@@ -82,6 +84,7 @@ class Thumbnailer:
             # A lot of parsing errors can happen when parsing EXIF
             logger.info("Error parsing image EXIF information: %s", e)
 
+    @trace
     def transpose(self) -> Tuple[int, int]:
         """Transpose the image using its EXIF Orientation tag
 
@@ -133,6 +136,7 @@ class Thumbnailer:
                     self.image = self.image.convert("RGB")
         return self.image.resize((width, height), Image.LANCZOS)
 
+    @trace
     def scale(self, width: int, height: int, output_type: str) -> BytesIO:
         """Rescales the image to the given dimensions.
 
@@ -142,6 +146,7 @@ class Thumbnailer:
         with self._resize(width, height) as scaled:
             return self._encode_image(scaled, output_type)
 
+    @trace
     def crop(self, width: int, height: int, output_type: str) -> BytesIO:
         """Rescales and crops the image to the given dimensions preserving
         aspect::

synapse/module_api/callbacks/spamchecker_callbacks.py

@@ -788,6 +788,7 @@ class SpamCheckerModuleApiCallbacks:
 
         return RegistrationBehaviour.ALLOW
 
+    @trace
     async def check_media_file_for_spam(
         self, file_wrapper: ReadableFileWrapper, file_info: FileInfo
     ) -> Union[Tuple[Codes, dict], Literal["NOT_SPAM"]]:

synapse/storage/databases/main/media_repository.py

@@ -27,6 +27,7 @@ from typing import (
 )
 
 from synapse.api.constants import Direction
+from synapse.logging.opentracing import trace
 from synapse.storage._base import SQLBaseStore
 from synapse.storage.database import (
     DatabasePool,
@@ -328,6 +329,7 @@ class MediaRepositoryStore(MediaRepositoryBackgroundUpdateStore):
             "get_local_media_ids", _get_local_media_ids_txn
         )
 
+    @trace
     async def store_local_media(
         self,
         media_id: str,
@@ -447,6 +449,7 @@ class MediaRepositoryStore(MediaRepositoryBackgroundUpdateStore):
             desc="get_local_media_thumbnails",
         )
 
+    @trace
     async def store_local_thumbnail(
         self,
         media_id: str,
@@ -568,6 +571,7 @@ class MediaRepositoryStore(MediaRepositoryBackgroundUpdateStore):
             desc="get_remote_media_thumbnails",
         )
 
+    @trace
     async def get_remote_media_thumbnail(
         self,
         origin: str,
@@ -599,6 +603,7 @@ class MediaRepositoryStore(MediaRepositoryBackgroundUpdateStore):
             desc="get_remote_media_thumbnail",
         )
 
+    @trace
     async def store_remote_media_thumbnail(
         self,
         origin: str,