@sanderegg use log_context

Author: bisgaard-itis

services/api-server/src/simcore_service_api_server/api/routes/files.py

@@ -17,6 +17,7 @@
 from models_library.projects_nodes_io import NodeID
 from pydantic import PositiveInt, ValidationError
 from servicelib.fastapi.requests_decorators import cancel_on_disconnect
+from servicelib.logging_utils import log_context
 from simcore_sdk.node_ports_common.constants import SIMCORE_LOCATION
 from simcore_sdk.node_ports_common.file_io_utils import UploadableFileObject
 from simcore_sdk.node_ports_common.filemanager import (
@@ -302,9 +303,12 @@ async def get_upload_links(
         webserver_api=webserver_api, file_id=None, client_file=client_file
     )
 
-    upload_links = await storage_client.get_file_upload_links(
-        user_id=user_id, file=file_meta, client_file=client_file
-    )
+    with log_context(
+        logger=_logger, level=logging.DEBUG, msg=f"Getting upload links for {file_meta}"
+    ):
+        upload_links = await storage_client.get_file_upload_links(
+            user_id=user_id, file=file_meta, client_file=client_file
+        )
 
     completion_url: URL = request.url_for(
         "complete_multipart_upload", file_id=file_meta.id

services/storage/src/simcore_service_storage/api/rest/_files.py

@@ -20,6 +20,7 @@
 from models_library.projects_nodes_io import LocationID, StorageFileID
 from pydantic import AnyUrl, ByteSize, TypeAdapter
 from servicelib.aiohttp import status
+from servicelib.logging_utils import log_context
 from yarl import URL
 
 from ...dsm import get_dsm_provider
@@ -185,17 +186,17 @@ async def upload_file(
     """
     # NOTE: Used by legacy dynamic services with single presigned link -> MUST BE BACKWARDS COMPATIBLE
     dsm = get_dsm_provider(request.app).get(location_id)
-    _logger.debug(
-        "creating upload links for file %s at location %s", file_id, location_id
-    )
-    links: UploadLinks = await dsm.create_file_upload_links(
-        user_id=query_params.user_id,
-        file_id=file_id,
-        link_type=query_params.link_type,
-        file_size_bytes=query_params.file_size or ByteSize(0),
-        is_directory=query_params.is_directory,
-        sha256_checksum=query_params.sha256_checksum,
-    )
+    with log_context(
+        logger=_logger, level=logging.DEBUG, msg=f"Creating upload links for {file_id=}"
+    ):
+        links: UploadLinks = await dsm.create_file_upload_links(
+            user_id=query_params.user_id,
+            file_id=file_id,
+            link_type=query_params.link_type,
+            file_size_bytes=query_params.file_size or ByteSize(0),
+            is_directory=query_params.is_directory,
+            sha256_checksum=query_params.sha256_checksum,
+        )
     if query_params.is_v1_upload:
         # return v1 response
         assert len(links.urls) == 1  # nosec

services/storage/src/simcore_service_storage/simcore_s3_dsm.py

@@ -452,7 +452,6 @@ async def create_file_upload_links(
         # NOTE: if this gets called successively with the same file_id, and
         # there was a multipart upload in progress beforehand, it MUST be
         # cancelled to prevent unwanted costs in AWS
-        _logger.debug("Cleaning pending uploads for file_id=%s", file_id)
         await self._clean_pending_upload(
             TypeAdapter(SimcoreS3FileID).validate_python(file_id)
         )
@@ -462,7 +461,6 @@ async def create_file_upload_links(
         ):  # NOTE: Delete is not needed for directories that are synced via an external tool (rclone/aws s3 cli).
             # ensure file is deleted first in case it already exists
             # https://github.com/ITISFoundation/osparc-simcore/pull/5108
-            _logger.debug("Attempting to delete file_id=%s", file_id)
             await self.delete_file(
                 user_id=user_id,
                 file_id=file_id,
@@ -491,19 +489,23 @@ async def create_file_upload_links(
             file_size_bytes
         ):
             # create multipart links
-            _logger.debug("Creating multipart upload links for file_id=%s", file_id)
-            assert file_size_bytes  # nosec
-            multipart_presigned_links = await get_s3_client(
-                self.app
-            ).create_multipart_upload_links(
-                bucket=fmd.bucket_name,
-                object_key=fmd.file_id,
-                file_size=file_size_bytes,
-                expiration_secs=get_application_settings(
+            with log_context(
+                logger=_logger,
+                level=logging.DEBUG,
+                msg=f"Creating multipart upload links for {file_id=}",
+            ):
+                assert file_size_bytes  # nosec
+                multipart_presigned_links = await get_s3_client(
                     self.app
-                ).STORAGE_DEFAULT_PRESIGNED_LINK_EXPIRATION_SECONDS,
-                sha256_checksum=fmd.sha256_checksum,
-            )
+                ).create_multipart_upload_links(
+                    bucket=fmd.bucket_name,
+                    object_key=fmd.file_id,
+                    file_size=file_size_bytes,
+                    expiration_secs=get_application_settings(
+                        self.app
+                    ).STORAGE_DEFAULT_PRESIGNED_LINK_EXPIRATION_SECONDS,
+                    sha256_checksum=fmd.sha256_checksum,
+                )
             # update the database so we keep the upload id
             fmd.upload_id = multipart_presigned_links.upload_id
             await FileMetaDataRepository.instance(get_db_engine(self.app)).upsert(
@@ -515,29 +517,35 @@ async def create_file_upload_links(
             )
         if link_type == LinkType.PRESIGNED:
             # create single presigned link
-            _logger.debug(
-                "Creating single presigned upload link for file_id=%s", file_id
-            )
-            single_presigned_link = await get_s3_client(
-                self.app
-            ).create_single_presigned_upload_link(
-                bucket=self.simcore_bucket_name,
-                object_key=fmd.file_id,
-                expiration_secs=get_application_settings(
+            with log_context(
+                logger=_logger,
+                level=logging.DEBUG,
+                msg=f"Creating single presigned upload link for {file_id=}",
+            ):
+                single_presigned_link = await get_s3_client(
                     self.app
-                ).STORAGE_DEFAULT_PRESIGNED_LINK_EXPIRATION_SECONDS,
-            )
+                ).create_single_presigned_upload_link(
+                    bucket=self.simcore_bucket_name,
+                    object_key=fmd.file_id,
+                    expiration_secs=get_application_settings(
+                        self.app
+                    ).STORAGE_DEFAULT_PRESIGNED_LINK_EXPIRATION_SECONDS,
+                )
             return UploadLinks(
                 [single_presigned_link],
                 file_size_bytes or MAX_LINK_CHUNK_BYTE_SIZE[link_type],
             )
 
         # user wants just the s3 link
-        _logger.debug("Creating S3 link for file_id=%s", file_id)
-        s3_link = get_s3_client(self.app).compute_s3_url(
-            bucket=self.simcore_bucket_name,
-            object_key=TypeAdapter(SimcoreS3FileID).validate_python(file_id),
-        )
+        with log_context(
+            logger=_logger,
+            level=logging.DEBUG,
+            msg=f"Compute S3 link for file_id={file_id}",
+        ):
+            s3_link = get_s3_client(self.app).compute_s3_url(
+                bucket=self.simcore_bucket_name,
+                object_key=TypeAdapter(SimcoreS3FileID).validate_python(file_id),
+            )
         return UploadLinks(
             [s3_link], file_size_bytes or MAX_LINK_CHUNK_BYTE_SIZE[link_type]
         )
@@ -694,46 +702,52 @@ async def delete_file(
         # Only use this in those circumstances where a collaborator requires to delete a file (the current
         # permissions model will not allow him to do so, even though this is a legitimate action)
         # SEE https://github.com/ITISFoundation/osparc-simcore/issues/5159
+        with log_context(
+            logger=_logger, level=logging.DEBUG, msg=f"Deleting file {file_id=}"
+        ):
+            if enforce_access_rights:
+                can = await AccessLayerRepository.instance(
+                    get_db_engine(self.app)
+                ).get_file_access_rights(user_id=user_id, file_id=file_id)
+                if not can.delete:
+                    raise FileAccessRightError(access_right="delete", file_id=file_id)
 
-        if enforce_access_rights:
-            can = await AccessLayerRepository.instance(
-                get_db_engine(self.app)
-            ).get_file_access_rights(user_id=user_id, file_id=file_id)
-            if not can.delete:
-                raise FileAccessRightError(access_right="delete", file_id=file_id)
-
-        try:
-            await get_s3_client(self.app).delete_objects_recursively(
-                bucket=self.simcore_bucket_name,
-                prefix=file_id,
-            )
-        except S3KeyNotFoundError:
-            _logger.warning("File %s not found in S3", file_id)
-            # we still need to clean up the database entry (it exists)
-            # and to invalidate the size of the parent directory
+            try:
+                await get_s3_client(self.app).delete_objects_recursively(
+                    bucket=self.simcore_bucket_name,
+                    prefix=file_id,
+                )
+            except S3KeyNotFoundError:
+                _logger.warning("File %s not found in S3", file_id)
+                # we still need to clean up the database entry (it exists)
+                # and to invalidate the size of the parent directory
 
-        async with transaction_context(get_db_engine(self.app)) as connection:
-            file_meta_data_repo = FileMetaDataRepository.instance(
-                get_db_engine(self.app)
-            )
-            await file_meta_data_repo.delete(connection=connection, file_ids=[file_id])
-
-            if parent_dir_fmds := await file_meta_data_repo.list_filter_with_partial_file_id(
-                connection=connection,
-                user_or_project_filter=UserOrProjectFilter(
-                    user_id=user_id, project_ids=[]
-                ),
-                file_id_prefix=compute_file_id_prefix(file_id, 2),
-                partial_file_id=None,
-                is_directory=True,
-                sha256_checksum=None,
-            ):
-                parent_dir_fmd = max(parent_dir_fmds, key=lambda fmd: len(fmd.file_id))
-                parent_dir_fmd.file_size = UNDEFINED_SIZE
-                await file_meta_data_repo.upsert(
-                    connection=connection, fmd=parent_dir_fmd
+            async with transaction_context(get_db_engine(self.app)) as connection:
+                file_meta_data_repo = FileMetaDataRepository.instance(
+                    get_db_engine(self.app)
+                )
+                await file_meta_data_repo.delete(
+                    connection=connection, file_ids=[file_id]
                 )
 
+                if parent_dir_fmds := await file_meta_data_repo.list_filter_with_partial_file_id(
+                    connection=connection,
+                    user_or_project_filter=UserOrProjectFilter(
+                        user_id=user_id, project_ids=[]
+                    ),
+                    file_id_prefix=compute_file_id_prefix(file_id, 2),
+                    partial_file_id=None,
+                    is_directory=True,
+                    sha256_checksum=None,
+                ):
+                    parent_dir_fmd = max(
+                        parent_dir_fmds, key=lambda fmd: len(fmd.file_id)
+                    )
+                    parent_dir_fmd.file_size = UNDEFINED_SIZE
+                    await file_meta_data_repo.upsert(
+                        connection=connection, fmd=parent_dir_fmd
+                    )
+
     async def delete_project_simcore_s3(
         self, user_id: UserID, project_id: ProjectID, node_id: NodeID | None = None
     ) -> None:
@@ -963,17 +977,22 @@ async def create_soft_link(
         return convert_db_to_model(await file_meta_data_repo.insert(fmd=target))
 
     async def _clean_pending_upload(self, file_id: SimcoreS3FileID) -> None:
-        with suppress(FileMetaDataNotFoundError):
-            fmd = await FileMetaDataRepository.instance(get_db_engine(self.app)).get(
-                file_id=file_id
-            )
-            if is_valid_managed_multipart_upload(fmd.upload_id):
-                assert fmd.upload_id  # nosec
-                await get_s3_client(self.app).abort_multipart_upload(
-                    bucket=self.simcore_bucket_name,
-                    object_key=file_id,
-                    upload_id=fmd.upload_id,
-                )
+        with log_context(
+            logger=_logger,
+            level=logging.DEBUG,
+            msg=f"Cleaning pending uploads for {file_id=}",
+        ):
+            with suppress(FileMetaDataNotFoundError):
+                fmd = await FileMetaDataRepository.instance(
+                    get_db_engine(self.app)
+                ).get(file_id=file_id)
+                if is_valid_managed_multipart_upload(fmd.upload_id):
+                    assert fmd.upload_id  # nosec
+                    await get_s3_client(self.app).abort_multipart_upload(
+                        bucket=self.simcore_bucket_name,
+                        object_key=file_id,
+                        upload_id=fmd.upload_id,
+                    )
 
     async def _clean_expired_uploads(self) -> None:
         """this method will check for all incomplete updates by checking