From 96817ca862e151b5fac365dd477822bdb0f23f83 Mon Sep 17 00:00:00 2001 From: jtyoung84 <104453205+jtyoung84@users.noreply.github.com> Date: Fri, 20 Sep 2024 11:05:50 -0700 Subject: [PATCH] Refactor 52 log messages (#100) * refactor: logs and scripts dir --------- Co-authored-by: Helen Lin --- Dockerfile | 5 +- .../run.sh | 0 .../aind_bucket_indexer.py | 31 +- .../codeocean_bucket_indexer.py | 5 +- .../populate_s3_with_metadata_files.py | 3 +- src/aind_data_asset_indexer/utils.py | 113 +-- tests/test_aind_bucket_indexer.py | 727 ++++++++---------- tests/test_codeocean_bucket_indexer.py | 204 +++-- tests/test_index_aind_buckets.py | 24 +- tests/test_populate_aind_buckets.py | 23 +- tests/test_populate_s3_with_metadata_files.py | 72 +- tests/test_utils.py | 280 +++---- 12 files changed, 682 insertions(+), 805 deletions(-) rename {src/aind_data_asset_indexer => scripts}/run.sh (100%) diff --git a/Dockerfile b/Dockerfile index 19d69e6..b2b6469 100644 --- a/Dockerfile +++ b/Dockerfile @@ -3,6 +3,7 @@ FROM python:3.10-slim WORKDIR /app ADD src ./src +ADD scripts ./scripts ADD pyproject.toml . ADD setup.py . @@ -10,5 +11,5 @@ RUN apt-get update RUN pip install . --no-cache-dir RUN pip install awscli -RUN chmod +x ./src/aind_data_asset_indexer/run.sh -CMD ["./src/aind_data_asset_indexer/run.sh"] +RUN chmod +x ./scripts/run.sh +CMD ["./scripts/run.sh"] diff --git a/src/aind_data_asset_indexer/run.sh b/scripts/run.sh similarity index 100% rename from src/aind_data_asset_indexer/run.sh rename to scripts/run.sh diff --git a/src/aind_data_asset_indexer/aind_bucket_indexer.py b/src/aind_data_asset_indexer/aind_bucket_indexer.py index e01cf95..eb08449 100644 --- a/src/aind_data_asset_indexer/aind_bucket_indexer.py +++ b/src/aind_data_asset_indexer/aind_bucket_indexer.py @@ -272,12 +272,14 @@ def _resolve_schema_information( object_key = create_object_key( prefix=prefix, filename=core_schema_file_name ) - common_kwargs["core_schema_info_in_root"] = ( - get_dict_of_file_info( - s3_client=s3_client, - bucket=self.job_settings.s3_bucket, - keys=[object_key], - ).get(object_key) + common_kwargs[ + "core_schema_info_in_root" + ] = get_dict_of_file_info( + s3_client=s3_client, + bucket=self.job_settings.s3_bucket, + keys=[object_key], + ).get( + object_key ) self._copy_file_from_root_to_subdir(**common_kwargs) # If field is null, a file exists in the root folder, and @@ -391,7 +393,7 @@ def _process_docdb_record( response = collection.delete_one( filter={"_id": docdb_record["_id"]} ) - logging.info(response.raw_result) + logging.debug(response.raw_result) else: # There is a metadata.nd.json file in S3. # Schema info in root level directory s3_core_schema_info = get_dict_of_core_schema_file_info( @@ -422,9 +424,9 @@ def _process_docdb_record( ) db = docdb_client[self.job_settings.doc_db_db_name] collection = db[self.job_settings.doc_db_collection_name] - fields_to_update["last_modified"] = ( - datetime.utcnow().isoformat() - ) + fields_to_update[ + "last_modified" + ] = datetime.utcnow().isoformat() response = collection.update_one( {"_id": docdb_record["_id"]}, {"$set": fields_to_update}, @@ -580,12 +582,15 @@ def _process_prefix( ] if "_id" in json_contents: # TODO: check is_dict_corrupt(json_contents) + logging.info( + f"Adding record to docdb for: {location}" + ) response = collection.update_one( {"_id": json_contents["_id"]}, {"$set": json_contents}, upsert=True, ) - logging.info(response.raw_result) + logging.debug(response.raw_result) cond_copy_then_sync_core_json_files( metadata_json=json.dumps( json_contents, default=str @@ -593,7 +598,6 @@ def _process_prefix( bucket=bucket, prefix=s3_prefix, s3_client=s3_client, - log_flag=True, copy_original_md_subdir=( self.job_settings.copy_original_md_subdir ), @@ -635,7 +639,6 @@ def _process_prefix( bucket=bucket, prefix=s3_prefix, s3_client=s3_client, - log_flag=True, copy_original_md_subdir=( self.job_settings.copy_original_md_subdir ), @@ -648,7 +651,7 @@ def _process_prefix( prefix=s3_prefix, s3_client=s3_client, ) - logging.info(s3_response) + logging.debug(s3_response) # Assume Lambda function will move it to DocDb. If it doesn't, # then next index job will pick it up. else: diff --git a/src/aind_data_asset_indexer/codeocean_bucket_indexer.py b/src/aind_data_asset_indexer/codeocean_bucket_indexer.py index 34457f3..982df2d 100644 --- a/src/aind_data_asset_indexer/codeocean_bucket_indexer.py +++ b/src/aind_data_asset_indexer/codeocean_bucket_indexer.py @@ -278,7 +278,7 @@ def _process_codeocean_record( {"$set": json_contents}, upsert=True, ) - logging.info(x.raw_result) + logging.debug(x.raw_result) else: logging.warning( f"Unable to build metadata record for: {location}!" @@ -363,10 +363,11 @@ def _dask_task_to_delete_record_list(self, record_list: List[str]): db = docdb_client[self.job_settings.doc_db_db_name] collection = db[self.job_settings.doc_db_collection_name] try: + logging.info(f"Removing {len(record_list)} records") response = collection.delete_many( filter={"_id": {"$in": record_list}} ) - logging.info(response.raw_result) + logging.debug(response.raw_result) except Exception as e: logging.error(f"Error deleting records: {repr(e)}") docdb_client.close() diff --git a/src/aind_data_asset_indexer/populate_s3_with_metadata_files.py b/src/aind_data_asset_indexer/populate_s3_with_metadata_files.py index 569a93c..ef2850d 100644 --- a/src/aind_data_asset_indexer/populate_s3_with_metadata_files.py +++ b/src/aind_data_asset_indexer/populate_s3_with_metadata_files.py @@ -79,7 +79,6 @@ def _process_prefix(self, prefix: str, s3_client: S3Client): bucket=bucket, prefix=prefix, s3_client=s3_client, - log_flag=True, copy_original_md_subdir=( self.job_settings.copy_original_md_subdir ), @@ -92,7 +91,7 @@ def _process_prefix(self, prefix: str, s3_client: S3Client): prefix=prefix, s3_client=s3_client, ) - logging.info(response) + logging.debug(response) else: logging.warning( f"Unable to build metadata record for: {location}!" diff --git a/src/aind_data_asset_indexer/utils.py b/src/aind_data_asset_indexer/utils.py index ea93629..e0a7870 100644 --- a/src/aind_data_asset_indexer/utils.py +++ b/src/aind_data_asset_indexer/utils.py @@ -31,38 +31,6 @@ ] -def _log_message( - message: str, log_level: int = logging.INFO, log_flag: bool = True -) -> None: - """ - Log a message using the given log level. If log_flag is False, - then it will not log anything. - - Parameters - ---------- - message : str - log_level : int - Default is logging.INFO - log_flag : bool - Default is True - - Returns - ------- - None - """ - if not log_flag: - return - if log_level not in [ - logging.DEBUG, - logging.INFO, - logging.WARNING, - logging.ERROR, - logging.CRITICAL, - ]: - raise ValueError("Invalid log level") - logging.log(log_level, message) - - def create_object_key(prefix: str, filename: str) -> str: """ For a given s3 prefix and filename, create the expected @@ -656,7 +624,6 @@ def cond_copy_then_sync_core_json_files( prefix: str, s3_client: S3Client, copy_original_md_subdir: str = "original_metadata", - log_flag: bool = False, ) -> None: """ For a given bucket and prefix @@ -675,8 +642,6 @@ def cond_copy_then_sync_core_json_files( The prefix for the S3 object keys. s3_client : S3Client The S3 client object. - log_flag: bool - Flag indicating whether to log operations. Default is False. copy_original_md_subdir : str Subdirectory to copy original core schema json files to. Default is 'original_metadata'. @@ -692,12 +657,9 @@ def cond_copy_then_sync_core_json_files( prefix=prefix, copy_subdir=copy_original_md_subdir, ): - _log_message( - message=( - "Copy of original metadata already exists at " - f"s3://{bucket}/{prefix}/{copy_original_md_subdir}" - ), - log_flag=log_flag, + logging.warning( + "Copy of original metadata already exists at " + f"s3://{bucket}/{prefix}/{copy_original_md_subdir}" ) else: copy_core_json_files( @@ -705,14 +667,12 @@ def cond_copy_then_sync_core_json_files( prefix=prefix, s3_client=s3_client, copy_original_md_subdir=copy_original_md_subdir, - log_flag=log_flag, ) sync_core_json_files( metadata_json=metadata_json, bucket=bucket, prefix=prefix, s3_client=s3_client, - log_flag=log_flag, ) @@ -721,7 +681,6 @@ def copy_core_json_files( prefix: str, s3_client: S3Client, copy_original_md_subdir: str, - log_flag: bool = False, ) -> None: """ For a given bucket and prefix, copy the core schema files to a @@ -735,8 +694,6 @@ def copy_core_json_files( The prefix for the S3 object keys. s3_client : S3Client The S3 client object. - log_flag: bool - Flag indicating whether to log operations. Default is False. copy_original_md_subdir : str Subdirectory to copy original core schema json files to. For example, 'original_metadata'. @@ -766,23 +723,17 @@ def copy_core_json_files( filename=file_name.replace(".json", f".{date_stamp}.json"), ) # Copy original core json files to /original_metadata - _log_message( - message=f"Copying {source} to {target} in s3://{bucket}", - log_flag=log_flag, - ) + logging.info(f"Copying {source} to {target} in s3://{bucket}") response = s3_client.copy_object( Bucket=bucket, CopySource={"Bucket": bucket, "Key": source}, Key=target, ) - _log_message(message=response, log_flag=log_flag) + logging.debug(response) else: - _log_message( - message=( - f"Source file {source_location} does not exist. " - f"Skipping copy." - ), - log_flag=log_flag, + logging.info( + f"Source file {source_location} does not exist. " + f"Skipping copy." ) @@ -791,7 +742,6 @@ def sync_core_json_files( bucket: str, prefix: str, s3_client: S3Client, - log_flag: bool = False, ) -> None: """ Sync the core schema files with the core fields from metadata.nd.json. @@ -810,8 +760,6 @@ def sync_core_json_files( The prefix for the S3 object keys. s3_client : S3Client The S3 client object. - log_flag: bool - Flag indicating whether to log operations. Default is False. Returns ------- @@ -838,28 +786,22 @@ def sync_core_json_files( # Core schema jsons are created if they don't already exist. # Otherwise, they are only updated if their contents are outdated. if core_files_infos[object_key] is None: - _log_message( - message=(f"Uploading new {field_name} to {location}"), - log_flag=log_flag, - ) + logging.info(f"Uploading new {field_name} to {location}") response = upload_json_str_to_s3( bucket=bucket, object_key=object_key, json_str=field_contents_str, s3_client=s3_client, ) - _log_message(message=response, log_flag=log_flag) + logging.debug(response) else: s3_object_hash = core_files_infos[object_key]["e_tag"].strip( '"' ) core_field_md5_hash = compute_md5_hash(field_contents_str) if core_field_md5_hash != s3_object_hash: - _log_message( - message=( - f"Uploading updated {field_name} to {location}" - ), - log_flag=log_flag, + logging.info( + f"Uploading updated {field_name} to {location}" ) response = upload_json_str_to_s3( bucket=bucket, @@ -867,37 +809,28 @@ def sync_core_json_files( json_str=field_contents_str, s3_client=s3_client, ) - _log_message(message=response, log_flag=log_flag) + logging.debug(response) else: - _log_message( - message=( - f"{field_name} is up-to-date in {location}. " - f"Skipping." - ), - log_flag=log_flag, + logging.info( + f"{field_name} is up-to-date in {location}. " + f"Skipping." ) else: # If a core field is None but the core json exists, # delete the core json. if core_files_infos[object_key] is not None: - _log_message( - message=( - f"{field_name} not found in metadata.nd.json for " - f"{prefix} but {location} exists! Deleting." - ), - log_flag=log_flag, + logging.info( + f"{field_name} not found in metadata.nd.json for " + f"{prefix} but {location} exists! Deleting." ) response = s3_client.delete_object( Bucket=bucket, Key=object_key ) - _log_message(message=response, log_flag=log_flag) + logging.debug(response) else: - _log_message( - message=( - f"{field_name} not found in metadata.nd.json for " - f"{prefix} nor in {location}! Skipping." - ), - log_flag=log_flag, + logging.info( + f"{field_name} not found in metadata.nd.json for " + f"{prefix} nor in {location}! Skipping." ) diff --git a/tests/test_aind_bucket_indexer.py b/tests/test_aind_bucket_indexer.py index 4a9e61d..2528a6d 100644 --- a/tests/test_aind_bucket_indexer.py +++ b/tests/test_aind_bucket_indexer.py @@ -55,96 +55,97 @@ def load_utils_json_file(filename: str) -> dict: cls.basic_job = AindIndexBucketJob(job_settings=basic_job_configs) @patch("boto3.client") - @patch("logging.debug") - @patch("logging.info") @patch("aind_data_asset_indexer.aind_bucket_indexer.upload_json_str_to_s3") def test_write_root_file_with_record_info_same_hash( self, mock_upload_json_str_to_s3: MagicMock, - mock_log_info: MagicMock, - mock_log_debug: MagicMock, mock_s3_client: MagicMock, ): """Tests _write_root_file_with_record_info method with same hashes.""" - self.basic_job._write_root_file_with_record_info( - s3_client=mock_s3_client, - core_schema_file_name="metadata.nd.json", - core_schema_info_in_root={ - "last_modified": datetime( - 2024, 5, 15, 17, 41, 28, tzinfo=timezone.utc - ), - "e_tag": '"275d922d2a1e547f2e0f35b5cc54f493"', - "version_id": "version_id", - }, - prefix="ecephys_642478_2023-01-17_13-56-29", - docdb_record_contents=self.example_md_record, - ) + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._write_root_file_with_record_info( + s3_client=mock_s3_client, + core_schema_file_name="metadata.nd.json", + core_schema_info_in_root={ + "last_modified": datetime( + 2024, 5, 15, 17, 41, 28, tzinfo=timezone.utc + ), + "e_tag": '"275d922d2a1e547f2e0f35b5cc54f493"', + "version_id": "version_id", + }, + prefix="ecephys_642478_2023-01-17_13-56-29", + docdb_record_contents=self.example_md_record, + ) + expected_log_messages = [ + "DEBUG:root:DocDB record and " + "s3://aind-ephys-data-dev-u5u0i5/" + "ecephys_642478_2023-01-17_13-56-29/metadata.nd.json are the same." + " Skipped writing." + ] + self.assertEqual(expected_log_messages, captured.output) mock_upload_json_str_to_s3.assert_not_called() - mock_log_info.assert_not_called() - mock_log_debug.assert_called_once_with( - "DocDB record and s3://aind-ephys-data-dev-u5u0i5/" - "ecephys_642478_2023-01-17_13-56-29/metadata.nd.json are the " - "same. Skipped writing." - ) @patch("boto3.client") - @patch("logging.debug") - @patch("logging.info") @patch("aind_data_asset_indexer.aind_bucket_indexer.upload_json_str_to_s3") def test_write_root_file_with_record_info_diff_hash( self, mock_upload_json_str_to_s3: MagicMock, - mock_log_info: MagicMock, - mock_log_debug: MagicMock, mock_s3_client: MagicMock, ): """Tests _write_root_file_with_record_info method with diff hash.""" mock_upload_json_str_to_s3.return_value = "Uploaded a file" - self.basic_job._write_root_file_with_record_info( - s3_client=mock_s3_client, - core_schema_file_name="metadata.nd.json", - core_schema_info_in_root={ - "last_modified": datetime( - 2024, 5, 15, 17, 41, 28, tzinfo=timezone.utc - ), - "e_tag": '"e6dd2b7ab819f7a0fc21dba512a4071c"', # Changed this - "version_id": "version_id", - }, - prefix="ecephys_642478_2023-01-17_13-56-29", - docdb_record_contents=self.example_md_record, - ) + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._write_root_file_with_record_info( + s3_client=mock_s3_client, + core_schema_file_name="metadata.nd.json", + core_schema_info_in_root={ + "last_modified": datetime( + 2024, 5, 15, 17, 41, 28, tzinfo=timezone.utc + ), + "e_tag": '"e6dd2b7ab819f7a0fc21dba512a4071c"', # Changed + "version_id": "version_id", + }, + prefix="ecephys_642478_2023-01-17_13-56-29", + docdb_record_contents=self.example_md_record, + ) + expected_log_messages = [ + "INFO:root:Writing docdb record info to " + "s3://aind-ephys-data-dev-u5u0i5/" + "ecephys_642478_2023-01-17_13-56-29/metadata.nd.json", + "DEBUG:root:Uploaded a file", + ] + self.assertEqual(expected_log_messages, captured.output) mock_upload_json_str_to_s3.assert_called_once_with( bucket="aind-ephys-data-dev-u5u0i5", object_key="ecephys_642478_2023-01-17_13-56-29/metadata.nd.json", json_str=json.dumps(self.example_md_record, default=str), s3_client=mock_s3_client, ) - mock_log_debug.assert_called_once_with("Uploaded a file") - mock_log_info.assert_called_once_with( - "Writing docdb record info to s3://aind-ephys-data-dev-u5u0i5/" - "ecephys_642478_2023-01-17_13-56-29/metadata.nd.json" - ) @patch("boto3.client") - @patch("logging.debug") - @patch("logging.info") @patch("aind_data_asset_indexer.aind_bucket_indexer.upload_json_str_to_s3") def test_write_root_file_with_record_info_none( self, mock_upload_json_str_to_s3: MagicMock, - mock_log_info: MagicMock, - mock_log_debug: MagicMock, mock_s3_client: MagicMock, ): """Tests _write_root_file_with_record_info method with no s3 info.""" mock_upload_json_str_to_s3.return_value = "Uploaded a file" - self.basic_job._write_root_file_with_record_info( - s3_client=mock_s3_client, - core_schema_file_name="subject.json", - core_schema_info_in_root=None, - prefix="ecephys_642478_2023-01-17_13-56-29", - docdb_record_contents=self.example_md_record.get("subject"), - ) + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._write_root_file_with_record_info( + s3_client=mock_s3_client, + core_schema_file_name="subject.json", + core_schema_info_in_root=None, + prefix="ecephys_642478_2023-01-17_13-56-29", + docdb_record_contents=self.example_md_record.get("subject"), + ) + expected_log_messages = [ + "INFO:root:Writing docdb record info to " + "s3://aind-ephys-data-dev-u5u0i5/" + "ecephys_642478_2023-01-17_13-56-29/subject.json", + "DEBUG:root:Uploaded a file", + ] + self.assertEqual(expected_log_messages, captured.output) mock_upload_json_str_to_s3.assert_called_once_with( bucket="aind-ephys-data-dev-u5u0i5", object_key="ecephys_642478_2023-01-17_13-56-29/subject.json", @@ -153,47 +154,39 @@ def test_write_root_file_with_record_info_none( ), s3_client=mock_s3_client, ) - mock_log_debug.assert_called_once_with("Uploaded a file") - mock_log_info.assert_called_once_with( - "Writing docdb record info to s3://aind-ephys-data-dev-u5u0i5/" - "ecephys_642478_2023-01-17_13-56-29/subject.json" - ) @patch("boto3.client") - @patch("logging.debug") - @patch("logging.info") def test_copy_file_from_root_to_subdir( self, - mock_log_info: MagicMock, - mock_log_debug: MagicMock, mock_s3_client: MagicMock, ): """Tests _copy_file_from_root_to_subdir method.""" mock_s3_client.copy_object.return_value = "Copied an object" - self.basic_job._copy_file_from_root_to_subdir( - s3_client=mock_s3_client, - core_schema_file_name="subject.json", - core_schema_info_in_root={ - "last_modified": datetime( - 2024, 5, 15, 17, 41, 28, tzinfo=timezone.utc - ), - "e_tag": '"7ce612b2f26be2efe806990cb4eb4266"', - "version_id": "version_id", - }, - prefix="ecephys_642478_2023-01-17_13-56-29", - ) - mock_log_debug.assert_called_once_with("Copied an object") - mock_log_info.assert_called_once_with( - "Copying s3://aind-ephys-data-dev-u5u0i5/" + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._copy_file_from_root_to_subdir( + s3_client=mock_s3_client, + core_schema_file_name="subject.json", + core_schema_info_in_root={ + "last_modified": datetime( + 2024, 5, 15, 17, 41, 28, tzinfo=timezone.utc + ), + "e_tag": '"7ce612b2f26be2efe806990cb4eb4266"', + "version_id": "version_id", + }, + prefix="ecephys_642478_2023-01-17_13-56-29", + ) + expected_log_messages = [ + "INFO:root:Copying " + "s3://aind-ephys-data-dev-u5u0i5/" "ecephys_642478_2023-01-17_13-56-29/subject.json to " "s3://aind-ephys-data-dev-u5u0i5/" "ecephys_642478_2023-01-17_13-56-29/original_metadata/" - "subject.20240515.json" - ) + "subject.20240515.json", + "DEBUG:root:Copied an object", + ] + self.assertEqual(expected_log_messages, captured.output) @patch("boto3.client") - @patch("logging.debug") - @patch("logging.info") @patch( "aind_data_asset_indexer.aind_bucket_indexer." "download_json_file_from_s3" @@ -215,8 +208,6 @@ def test_resolve_schema_information_case_1( mock_write_file_with_record_info: MagicMock, mock_copy_file_to_subdir: MagicMock, mock_download_json_file: MagicMock, - mock_log_info: MagicMock, - mock_log_debug: MagicMock, mock_s3_client: MagicMock, ): """Tests _resolve_schema_information. Case 1: @@ -253,12 +244,8 @@ def test_resolve_schema_information_case_1( ) mock_copy_file_to_subdir.assert_not_called() mock_download_json_file.assert_not_called() - mock_log_debug.assert_not_called() - mock_log_info.assert_not_called() @patch("boto3.client") - @patch("logging.debug") - @patch("logging.info") @patch( "aind_data_asset_indexer.aind_bucket_indexer." "download_json_file_from_s3" @@ -280,8 +267,6 @@ def test_resolve_schema_information_case_2( mock_write_file_with_record_info: MagicMock, mock_copy_file_to_subdir: MagicMock, mock_download_json_file: MagicMock, - mock_log_info: MagicMock, - mock_log_debug: MagicMock, mock_s3_client: MagicMock, ): """Tests _resolve_schema_information. Case 2: @@ -325,12 +310,8 @@ def test_resolve_schema_information_case_2( ), ) mock_download_json_file.assert_not_called() - mock_log_debug.assert_not_called() - mock_log_info.assert_not_called() @patch("boto3.client") - @patch("logging.debug") - @patch("logging.info") @patch( "aind_data_asset_indexer.aind_bucket_indexer." "download_json_file_from_s3" @@ -352,8 +333,6 @@ def test_resolve_schema_information_case_3( mock_write_file_with_record_info: MagicMock, mock_copy_file_to_subdir: MagicMock, mock_download_json_file: MagicMock, - mock_log_info: MagicMock, - mock_log_debug: MagicMock, mock_s3_client: MagicMock, ): """Tests _resolve_schema_information. Case 3: @@ -382,12 +361,8 @@ def test_resolve_schema_information_case_3( ), ) mock_download_json_file.assert_not_called() - mock_log_debug.assert_not_called() - mock_log_info.assert_not_called() @patch("boto3.client") - @patch("logging.debug") - @patch("logging.info") @patch( "aind_data_asset_indexer.aind_bucket_indexer." "download_json_file_from_s3" @@ -411,8 +386,6 @@ def test_resolve_schema_information_case_4( mock_write_file_with_record_info: MagicMock, mock_copy_file_to_subdir: MagicMock, mock_download_json_file: MagicMock, - mock_log_info: MagicMock, - mock_log_debug: MagicMock, mock_s3_client: MagicMock, ): """Tests _resolve_schema_information. Case 4: @@ -465,12 +438,8 @@ def test_resolve_schema_information_case_4( ), ) mock_download_json_file.assert_not_called() - mock_log_debug.assert_not_called() - mock_log_info.assert_not_called() @patch("boto3.client") - @patch("logging.debug") - @patch("logging.info") @patch( "aind_data_asset_indexer.aind_bucket_indexer." "download_json_file_from_s3" @@ -492,8 +461,6 @@ def test_resolve_schema_information_case_5( mock_write_file_with_record_info: MagicMock, mock_copy_file_to_subdir: MagicMock, mock_download_json_file: MagicMock, - mock_log_info: MagicMock, - mock_log_debug: MagicMock, mock_s3_client: MagicMock, ): """Tests _resolve_schema_information. Case 5: @@ -512,27 +479,29 @@ def test_resolve_schema_information_case_5( "version_id": "version_id", } } - docdb_fields_to_update = self.basic_job._resolve_schema_information( - prefix="ecephys_642478_2023-01-17_13-56-29", - s3_client=mock_s3_client, - core_schema_info_in_root=core_schema_info_in_root, - list_of_schemas_in_copy_subdir=["subject.json"], - docdb_record=dict(), - ) + with self.assertLogs(level="DEBUG") as captured: + docdb_fields_to_update = ( + self.basic_job._resolve_schema_information( + prefix="ecephys_642478_2023-01-17_13-56-29", + s3_client=mock_s3_client, + core_schema_info_in_root=core_schema_info_in_root, + list_of_schemas_in_copy_subdir=["subject.json"], + docdb_record=dict(), + ) + ) + expected_log_messages = [ + "INFO:root:DocDb field is null. Deleting file " + "s3://aind-ephys-data-dev-u5u0i5/" + "ecephys_642478_2023-01-17_13-56-29/subject.json", + "DEBUG:root:Deleting an object", + ] + self.assertEqual(expected_log_messages, captured.output) self.assertEqual(dict(), docdb_fields_to_update) mock_write_file_with_record_info.assert_not_called() mock_copy_file_to_subdir.assert_not_called() mock_download_json_file.assert_not_called() - mock_log_debug.assert_called_once_with("Deleting an object") - mock_log_info.assert_called_once_with( - "DocDb field is null. Deleting file " - "s3://aind-ephys-data-dev-u5u0i5/" - "ecephys_642478_2023-01-17_13-56-29/subject.json" - ) @patch("boto3.client") - @patch("logging.debug") - @patch("logging.info") @patch( "aind_data_asset_indexer.aind_bucket_indexer." "download_json_file_from_s3" @@ -554,8 +523,6 @@ def test_resolve_schema_information_case_6( mock_write_file_with_record_info: MagicMock, mock_copy_file_to_subdir: MagicMock, mock_download_json_file: MagicMock, - mock_log_info: MagicMock, - mock_log_debug: MagicMock, mock_s3_client: MagicMock, ): """Tests _resolve_schema_information. Case 6: @@ -596,13 +563,8 @@ def test_resolve_schema_information_case_6( "subject.json" ), ) - mock_log_debug.assert_not_called() - mock_log_info.assert_not_called() @patch("boto3.client") - @patch("logging.debug") - @patch("logging.info") - @patch("logging.warning") @patch( "aind_data_asset_indexer.aind_bucket_indexer." "download_json_file_from_s3" @@ -624,9 +586,6 @@ def test_resolve_schema_information_case_6_corrupt_download( mock_write_file_with_record_info: MagicMock, mock_copy_file_to_subdir: MagicMock, mock_download_json_file: MagicMock, - mock_log_warn: MagicMock, - mock_log_info: MagicMock, - mock_log_debug: MagicMock, mock_s3_client: MagicMock, ): """Tests _resolve_schema_information. Case 6 with corrupt download: @@ -636,6 +595,7 @@ def test_resolve_schema_information_case_6_corrupt_download( """ mock_download_json_file.return_value = None + mock_s3_client.delete_object.return_value = "Delete object" core_schema_info_in_root = { "subject.json": { "last_modified": datetime( @@ -645,13 +605,23 @@ def test_resolve_schema_information_case_6_corrupt_download( "version_id": "version_id", } } - docdb_fields_to_update = self.basic_job._resolve_schema_information( - prefix="ecephys_642478_2023-01-17_13-56-29", - s3_client=mock_s3_client, - core_schema_info_in_root=core_schema_info_in_root, - list_of_schemas_in_copy_subdir=[], - docdb_record=dict(), - ) + with self.assertLogs(level="DEBUG") as captured: + docdb_fields_to_update = ( + self.basic_job._resolve_schema_information( + prefix="ecephys_642478_2023-01-17_13-56-29", + s3_client=mock_s3_client, + core_schema_info_in_root=core_schema_info_in_root, + list_of_schemas_in_copy_subdir=[], + docdb_record=dict(), + ) + ) + expected_log_messages = [ + "WARNING:root:Something went wrong downloading or parsing " + "s3://aind-ephys-data-dev-u5u0i5/" + "ecephys_642478_2023-01-17_13-56-29/subject.json", + "DEBUG:root:Delete object", + ] + self.assertEqual(expected_log_messages, captured.output) self.assertEqual(dict(), docdb_fields_to_update) mock_write_file_with_record_info.assert_not_called() mock_copy_file_to_subdir.assert_called_once_with( @@ -662,21 +632,12 @@ def test_resolve_schema_information_case_6_corrupt_download( "subject.json" ), ) - mock_log_info.assert_not_called() - mock_log_warn.assert_called_once_with( - "Something went wrong downloading or parsing " - "s3://aind-ephys-data-dev-u5u0i5/" - "ecephys_642478_2023-01-17_13-56-29/subject.json" - ) mock_s3_client.delete_object.assert_called_once_with( Bucket="aind-ephys-data-dev-u5u0i5", Key="ecephys_642478_2023-01-17_13-56-29/subject.json", ) - mock_log_debug.assert_called_once() @patch("boto3.client") - @patch("logging.debug") - @patch("logging.info") @patch( "aind_data_asset_indexer.aind_bucket_indexer." "download_json_file_from_s3" @@ -698,8 +659,6 @@ def test_resolve_schema_information_case_7( mock_write_file_with_record_info: MagicMock, mock_copy_file_to_subdir: MagicMock, mock_download_json_file: MagicMock, - mock_log_info: MagicMock, - mock_log_debug: MagicMock, mock_s3_client: MagicMock, ): """Tests _resolve_schema_information. Case 7: @@ -709,27 +668,28 @@ def test_resolve_schema_information_case_7( """ core_schema_info_in_root = dict() - docdb_fields_to_update = self.basic_job._resolve_schema_information( - prefix="ecephys_642478_2023-01-17_13-56-29", - s3_client=mock_s3_client, - core_schema_info_in_root=core_schema_info_in_root, - list_of_schemas_in_copy_subdir=["subject.json"], - docdb_record=dict(), - ) + with self.assertLogs(level="DEBUG") as captured: + docdb_fields_to_update = ( + self.basic_job._resolve_schema_information( + prefix="ecephys_642478_2023-01-17_13-56-29", + s3_client=mock_s3_client, + core_schema_info_in_root=core_schema_info_in_root, + list_of_schemas_in_copy_subdir=["subject.json"], + docdb_record=dict(), + ) + ) + expected_log_messages = [ + "INFO:root:Field is null in docdb record and no file in root " + "folder at s3://aind-ephys-data-dev-u5u0i5/" + "ecephys_642478_2023-01-17_13-56-29/subject.json" + ] + self.assertEqual(expected_log_messages, captured.output) self.assertEqual(dict(), docdb_fields_to_update) mock_write_file_with_record_info.assert_not_called() mock_copy_file_to_subdir.assert_not_called() mock_download_json_file.assert_not_called() - mock_log_debug.assert_not_called() - mock_log_info.assert_called_once_with( - "Field is null in docdb record and no file in root folder at " - "s3://aind-ephys-data-dev-u5u0i5/" - "ecephys_642478_2023-01-17_13-56-29/subject.json" - ) @patch("boto3.client") - @patch("logging.debug") - @patch("logging.info") @patch( "aind_data_asset_indexer.aind_bucket_indexer." "download_json_file_from_s3" @@ -751,8 +711,6 @@ def test_resolve_schema_information_case_8( mock_write_file_with_record_info: MagicMock, mock_copy_file_to_subdir: MagicMock, mock_download_json_file: MagicMock, - mock_log_info: MagicMock, - mock_log_debug: MagicMock, mock_s3_client: MagicMock, ): """Tests _resolve_schema_information. Case 8: @@ -762,86 +720,86 @@ def test_resolve_schema_information_case_8( """ core_schema_info_in_root = dict() - docdb_fields_to_update = self.basic_job._resolve_schema_information( - prefix="ecephys_642478_2023-01-17_13-56-29", - s3_client=mock_s3_client, - core_schema_info_in_root=core_schema_info_in_root, - list_of_schemas_in_copy_subdir=[], - docdb_record=dict(), - ) + with self.assertLogs(level="DEBUG") as captured: + docdb_fields_to_update = ( + self.basic_job._resolve_schema_information( + prefix="ecephys_642478_2023-01-17_13-56-29", + s3_client=mock_s3_client, + core_schema_info_in_root=core_schema_info_in_root, + list_of_schemas_in_copy_subdir=[], + docdb_record=dict(), + ) + ) + expected_log_messages = [ + "INFO:root:Field is null in docdb record and no file in root " + "folder at s3://aind-ephys-data-dev-u5u0i5/" + "ecephys_642478_2023-01-17_13-56-29/subject.json" + ] + self.assertEqual(expected_log_messages, captured.output) self.assertEqual(dict(), docdb_fields_to_update) mock_write_file_with_record_info.assert_not_called() mock_copy_file_to_subdir.assert_not_called() mock_download_json_file.assert_not_called() - mock_log_debug.assert_not_called() - mock_log_info.assert_called_once_with( - "Field is null in docdb record and no file in root folder at " - "s3://aind-ephys-data-dev-u5u0i5/" - "ecephys_642478_2023-01-17_13-56-29/subject.json" - ) @patch("aind_data_asset_indexer.aind_bucket_indexer.MongoClient") @patch("boto3.client") - @patch("logging.warning") def test_process_docdb_record_invalid_location( self, - mock_log_warn: MagicMock, mock_s3_client: MagicMock, mock_docdb_client: MagicMock, ): """Tests _process_docdb_record method when the location in the record is not a valid s3 url""" - self.basic_job._process_docdb_record( - docdb_client=mock_docdb_client, - s3_client=mock_s3_client, - docdb_record={ - "_id": "abc-123", - "name": "prefix1_2024-01-01_01-01-01", - "location": "no_s3/bucket/prefix1_2024-01-01_01-01-01", - }, - ) - mock_log_warn.assert_called_once_with( - "Record location no_s3/bucket/prefix1_2024-01-01_01-01-01 or name " + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._process_docdb_record( + docdb_client=mock_docdb_client, + s3_client=mock_s3_client, + docdb_record={ + "_id": "abc-123", + "name": "prefix1_2024-01-01_01-01-01", + "location": "no_s3/bucket/prefix1_2024-01-01_01-01-01", + }, + ) + expected_log_messages = [ + "WARNING:root:Record location " + "no_s3/bucket/prefix1_2024-01-01_01-01-01 or name " "prefix1_2024-01-01_01-01-01 not valid for bucket " "aind-ephys-data-dev-u5u0i5!" - ) + ] + self.assertEqual(expected_log_messages, captured.output) @patch("aind_data_asset_indexer.aind_bucket_indexer.MongoClient") @patch("boto3.client") - @patch("logging.warning") def test_process_docdb_record_invalid_prefix( self, - mock_log_warn: MagicMock, mock_s3_client: MagicMock, mock_docdb_client: MagicMock, ): """Tests _process_docdb_record method when the location in the record has invalid prefix""" - self.basic_job._process_docdb_record( - docdb_client=mock_docdb_client, - s3_client=mock_s3_client, - docdb_record={ - "_id": "abc-123", - "name": "prefix1", - "location": "s3://bucket/prefix1", - }, - ) - mock_log_warn.assert_called_once_with( - "Record location s3://bucket/prefix1 or name prefix1 not valid " - "for bucket aind-ephys-data-dev-u5u0i5!" - ) + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._process_docdb_record( + docdb_client=mock_docdb_client, + s3_client=mock_s3_client, + docdb_record={ + "_id": "abc-123", + "name": "prefix1", + "location": "s3://bucket/prefix1", + }, + ) + expected_log_messages = [ + "WARNING:root:Record location s3://bucket/prefix1 or name prefix1 " + "not valid for bucket aind-ephys-data-dev-u5u0i5!" + ] + self.assertEqual(expected_log_messages, captured.output) @patch("aind_data_asset_indexer.aind_bucket_indexer.does_s3_object_exist") @patch("aind_data_asset_indexer.aind_bucket_indexer.MongoClient") @patch("boto3.client") - @patch("logging.warning") - @patch("logging.info") def test_process_docdb_record_s3_file_missing( self, - mock_log_info: MagicMock, - mock_log_warn: MagicMock, mock_s3_client: MagicMock, mock_docdb_client: MagicMock, mock_does_s3_object_exist: MagicMock, @@ -862,20 +820,21 @@ def test_process_docdb_record_s3_file_missing( ) mock_does_s3_object_exist.return_value = False - self.basic_job._process_docdb_record( - docdb_client=mock_docdb_client, - s3_client=mock_s3_client, - docdb_record=self.example_md_record, - ) - mock_log_warn.assert_called_once_with( - "File not found in S3 at " + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._process_docdb_record( + docdb_client=mock_docdb_client, + s3_client=mock_s3_client, + docdb_record=self.example_md_record, + ) + expected_log_messages = [ + "WARNING:root:File not found in S3 at " "s3://aind-ephys-data-dev-u5u0i5/" "ecephys_642478_2023-01-17_13-56-29/metadata.nd.json! " - "Removing metadata record from DocDb." - ) - mock_log_info.assert_called_once_with( - {"n": 1, "ok": 1.0, "operationTime": Timestamp(1715812466, 1)} - ) + "Removing metadata record from DocDb.", + "DEBUG:root:" + "{'n': 1, 'ok': 1.0, 'operationTime': Timestamp(1715812466, 1)}", + ] + self.assertEqual(expected_log_messages, captured.output) @patch( "aind_data_asset_indexer.aind_bucket_indexer.AindIndexBucketJob." @@ -894,14 +853,10 @@ def test_process_docdb_record_s3_file_missing( @patch("aind_data_asset_indexer.aind_bucket_indexer.does_s3_object_exist") @patch("aind_data_asset_indexer.aind_bucket_indexer.MongoClient") @patch("boto3.client") - @patch("logging.debug") - @patch("logging.info") @patch("aind_data_asset_indexer.aind_bucket_indexer.datetime") def test_process_docdb_record_valid_metadata_nd_json_file( self, mock_datetime: MagicMock, - mock_log_info: MagicMock, - mock_log_debug: MagicMock, mock_s3_client: MagicMock, mock_docdb_client: MagicMock, mock_does_s3_object_exist: MagicMock, @@ -950,16 +905,20 @@ def test_process_docdb_record_valid_metadata_nd_json_file( # Assume the subject is null in docdb mock_docdb_record["subject"] = None - self.basic_job._process_docdb_record( - docdb_client=mock_docdb_client, - s3_client=mock_s3_client, - docdb_record=mock_docdb_record, - ) - mock_log_info.assert_called_once_with( - "New files found in s3://aind-ephys-data-dev-u5u0i5/" + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._process_docdb_record( + docdb_client=mock_docdb_client, + s3_client=mock_s3_client, + docdb_record=mock_docdb_record, + ) + expected_log_messages = [ + "INFO:root:New files found in " + "s3://aind-ephys-data-dev-u5u0i5/" "ecephys_642478_2023-01-17_13-56-29 but not in original_metadata. " - "Updating DocDb record with new info." - ) + "Updating DocDb record with new info.", + "DEBUG:root:Updated docdb", + ] + self.assertEqual(expected_log_messages, captured.output) expected_docdb_record_to_write = deepcopy(mock_docdb_record) expected_docdb_record_to_write[ "last_modified" @@ -974,7 +933,6 @@ def test_process_docdb_record_valid_metadata_nd_json_file( prefix="ecephys_642478_2023-01-17_13-56-29", docdb_record_contents=expected_docdb_record_to_write, ) - mock_log_debug.assert_called_once_with("Updated docdb") @patch( "aind_data_asset_indexer.aind_bucket_indexer.AindIndexBucketJob." @@ -1027,10 +985,8 @@ def test_dask_task_to_process_record_list( ) @patch("aind_data_asset_indexer.aind_bucket_indexer.MongoClient") @patch("boto3.client") - @patch("logging.error") def test_dask_task_to_process_record_list_error( self, - mock_log_error: MagicMock, mock_boto3_client: MagicMock, mock_docdb_client: MagicMock, mock_process_docdb_record: MagicMock, @@ -1051,7 +1007,18 @@ def test_dask_task_to_process_record_list_error( Exception("Error processing record"), None, ] - self.basic_job._dask_task_to_process_record_list(record_list=records) + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._dask_task_to_process_record_list( + record_list=records + ) + expected_log_messages = [ + "ERROR:root:Error processing docdb " + "5ca4a951-d374-4f4b-8279-d570a35b2286, " + "s3://aind-ephys-data-dev-u5u0i5/" + "ecephys_567890_2000-01-01_04-00-00: " + "Exception('Error processing record')" + ] + self.assertEqual(expected_log_messages, captured.output) mock_process_docdb_record.assert_has_calls( [ call( @@ -1071,11 +1038,6 @@ def test_dask_task_to_process_record_list_error( ), ] ) - mock_log_error.assert_called_once_with( - "Error processing docdb 5ca4a951-d374-4f4b-8279-d570a35b2286, s3:" - "//aind-ephys-data-dev-u5u0i5/ecephys_567890_2000-01-01_04-00-00: " - "Exception('Error processing record')" - ) mock_s3_client.close.assert_called_once_with() mock_mongo_client.close.assert_called_once_with() @@ -1093,10 +1055,8 @@ def test_process_records(self, mock_dask_bag_map_parts: MagicMock): @patch("aind_data_asset_indexer.aind_bucket_indexer.does_s3_object_exist") @patch("aind_data_asset_indexer.aind_bucket_indexer.MongoClient") @patch("boto3.client") - @patch("logging.warning") def test_process_prefix_invalid_prefix( self, - mock_log_warn: MagicMock, mock_s3_client: MagicMock, mock_docdb_client: MagicMock, mock_does_s3_object_exist: MagicMock, @@ -1104,16 +1064,18 @@ def test_process_prefix_invalid_prefix( """Tests _process_prefix method when the prefix is invalid.""" location_to_id_map = dict() - self.basic_job._process_prefix( - s3_prefix="ecephys_642478", - docdb_client=mock_docdb_client, - s3_client=mock_s3_client, - location_to_id_map=location_to_id_map, - ) - mock_log_warn.assert_called_once_with( - "Prefix ecephys_642478 not valid in bucket " - f"{self.basic_job.job_settings.s3_bucket}! Skipping." - ) + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._process_prefix( + s3_prefix="ecephys_642478", + docdb_client=mock_docdb_client, + s3_client=mock_s3_client, + location_to_id_map=location_to_id_map, + ) + expected_log_messages = [ + "WARNING:root:Prefix ecephys_642478 not valid in bucket " + "aind-ephys-data-dev-u5u0i5! Skipping." + ] + self.assertEqual(expected_log_messages, captured.output) mock_does_s3_object_exist.assert_not_called() @patch( @@ -1131,10 +1093,8 @@ def test_process_prefix_invalid_prefix( @patch("aind_data_asset_indexer.aind_bucket_indexer.does_s3_object_exist") @patch("aind_data_asset_indexer.aind_bucket_indexer.MongoClient") @patch("boto3.client") - @patch("logging.warning") def test_process_prefix_no_record_no_file_build_no( self, - mock_log_warn: MagicMock, mock_s3_client: MagicMock, mock_docdb_client: MagicMock, mock_does_s3_object_exist: MagicMock, @@ -1150,17 +1110,19 @@ def test_process_prefix_no_record_no_file_build_no( mock_build_metadata_record_from_prefix.return_value = None location_to_id_map = dict() - self.basic_job._process_prefix( - s3_prefix="ecephys_642478_2023-01-17_13-56-29", - docdb_client=mock_docdb_client, - s3_client=mock_s3_client, - location_to_id_map=location_to_id_map, - ) - mock_log_warn.assert_called_once_with( - "Unable to build metadata record for: " - f"s3://{self.basic_job.job_settings.s3_bucket}/" - f"ecephys_642478_2023-01-17_13-56-29!" - ) + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._process_prefix( + s3_prefix="ecephys_642478_2023-01-17_13-56-29", + docdb_client=mock_docdb_client, + s3_client=mock_s3_client, + location_to_id_map=location_to_id_map, + ) + expected_log_messages = [ + "WARNING:root:Unable to build metadata record for: " + "s3://aind-ephys-data-dev-u5u0i5/" + "ecephys_642478_2023-01-17_13-56-29!" + ] + self.assertEqual(expected_log_messages, captured.output) mock_cond_copy_then_sync_core_json_files.assert_not_called() mock_upload_metadata_json_str_to_s3.assert_not_called() @@ -1179,10 +1141,8 @@ def test_process_prefix_no_record_no_file_build_no( @patch("aind_data_asset_indexer.aind_bucket_indexer.does_s3_object_exist") @patch("aind_data_asset_indexer.aind_bucket_indexer.MongoClient") @patch("boto3.client") - @patch("logging.info") def test_process_prefix_no_record_no_file_build_yes( self, - mock_log_info: MagicMock, mock_s3_client: MagicMock, mock_docdb_client: MagicMock, mock_does_s3_object_exist: MagicMock, @@ -1204,27 +1164,24 @@ def test_process_prefix_no_record_no_file_build_yes( ) location_to_id_map = dict() - self.basic_job._process_prefix( - s3_prefix=expected_prefix, - docdb_client=mock_docdb_client, - s3_client=mock_s3_client, - location_to_id_map=location_to_id_map, - ) - mock_log_info.assert_has_calls( - [ - call( - "Uploading metadata record for: " - f"s3://aind-ephys-data-dev-u5u0i5/{expected_prefix}" - ), - call(self.example_put_object_response1), - ] - ) + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._process_prefix( + s3_prefix=expected_prefix, + docdb_client=mock_docdb_client, + s3_client=mock_s3_client, + location_to_id_map=location_to_id_map, + ) + expected_log_messages = [ + f"INFO:root:Uploading metadata record for: " + f"s3://aind-ephys-data-dev-u5u0i5/{expected_prefix}", + f"DEBUG:root:{self.example_put_object_response1}", + ] + self.assertEqual(expected_log_messages, captured.output) mock_cond_copy_then_sync_core_json_files.assert_called_once_with( metadata_json=json.dumps(self.example_md_record), bucket=self.basic_job.job_settings.s3_bucket, prefix=expected_prefix, s3_client=mock_s3_client, - log_flag=True, copy_original_md_subdir="original_metadata", ) mock_upload_metadata_json_str_to_s3.assert_called_once_with( @@ -1249,10 +1206,8 @@ def test_process_prefix_no_record_no_file_build_yes( @patch("aind_data_asset_indexer.aind_bucket_indexer.does_s3_object_exist") @patch("aind_data_asset_indexer.aind_bucket_indexer.MongoClient") @patch("boto3.client") - @patch("logging.warning") def test_process_prefix_no_record_yes_file_bad_file( self, - mock_log_warn: MagicMock, mock_s3_client: MagicMock, mock_docdb_client: MagicMock, mock_does_s3_object_exist: MagicMock, @@ -1268,17 +1223,19 @@ def test_process_prefix_no_record_yes_file_bad_file( mock_download_json_file_from_s3.return_value = None location_to_id_map = dict() - self.basic_job._process_prefix( - s3_prefix="ecephys_642478_2023-01-17_13-56-29", - docdb_client=mock_docdb_client, - s3_client=mock_s3_client, - location_to_id_map=location_to_id_map, - ) - mock_log_warn.assert_called_once_with( - f"Unable to download file from S3 for:" - f" s3://{self.basic_job.job_settings.s3_bucket}/" - f"ecephys_642478_2023-01-17_13-56-29/metadata.nd.json!" - ) + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._process_prefix( + s3_prefix="ecephys_642478_2023-01-17_13-56-29", + docdb_client=mock_docdb_client, + s3_client=mock_s3_client, + location_to_id_map=location_to_id_map, + ) + expected_log_messages = [ + "WARNING:root:Unable to download file from S3 for: " + "s3://aind-ephys-data-dev-u5u0i5/" + "ecephys_642478_2023-01-17_13-56-29/metadata.nd.json!" + ] + self.assertEqual(expected_log_messages, captured.output) mock_cond_copy_then_sync_core_json_files.assert_not_called() mock_upload_metadata_json_str_to_s3.assert_not_called() @@ -1297,10 +1254,8 @@ def test_process_prefix_no_record_yes_file_bad_file( @patch("aind_data_asset_indexer.aind_bucket_indexer.does_s3_object_exist") @patch("aind_data_asset_indexer.aind_bucket_indexer.MongoClient") @patch("boto3.client") - @patch("logging.info") def test_process_prefix_no_record_yes_file_good_file( self, - mock_log_info: MagicMock, mock_s3_client: MagicMock, mock_docdb_client: MagicMock, mock_does_s3_object_exist: MagicMock, @@ -1331,28 +1286,31 @@ def test_process_prefix_no_record_yes_file_good_file( mock_download_json_file_from_s3.return_value = self.example_md_record location_to_id_map = dict() - self.basic_job._process_prefix( - s3_prefix="ecephys_642478_2023-01-17_13-56-29", - docdb_client=mock_docdb_client, - s3_client=mock_s3_client, - location_to_id_map=location_to_id_map, - ) - mock_log_info.assert_called_once_with( - { - "n": 1, - "nModified": 0, - "upserted": "488bbe42-832b-4c37-8572-25eb87cc50e2", - "ok": 1.0, - "operationTime": Timestamp(1715819252, 1), - "updatedExisting": False, - } - ) + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._process_prefix( + s3_prefix="ecephys_642478_2023-01-17_13-56-29", + docdb_client=mock_docdb_client, + s3_client=mock_s3_client, + location_to_id_map=location_to_id_map, + ) + expected_log_messages = [ + "INFO:root:Adding record to docdb for: " + "s3://aind-ephys-data-dev-u5u0i5/" + "ecephys_642478_2023-01-17_13-56-29", + "DEBUG:root:" + "{'n': 1, " + "'nModified': 0, " + "'upserted': '488bbe42-832b-4c37-8572-25eb87cc50e2', " + "'ok': 1.0, " + "'operationTime': Timestamp(1715819252, 1), " + "'updatedExisting': False}", + ] + self.assertEqual(expected_log_messages, captured.output) mock_cond_copy_then_sync_core_json_files.assert_called_once_with( metadata_json=json.dumps(self.example_md_record), bucket=self.basic_job.job_settings.s3_bucket, prefix="ecephys_642478_2023-01-17_13-56-29", s3_client=mock_s3_client, - log_flag=True, copy_original_md_subdir="original_metadata", ) mock_upload_metadata_json_str_to_s3.assert_not_called() @@ -1372,10 +1330,8 @@ def test_process_prefix_no_record_yes_file_good_file( @patch("aind_data_asset_indexer.aind_bucket_indexer.does_s3_object_exist") @patch("aind_data_asset_indexer.aind_bucket_indexer.MongoClient") @patch("boto3.client") - @patch("logging.warning") def test_process_prefix_no_record_yes_file_good_file_no__id( self, - mock_log_warn: MagicMock, mock_s3_client: MagicMock, mock_docdb_client: MagicMock, mock_does_s3_object_exist: MagicMock, @@ -1397,19 +1353,21 @@ def test_process_prefix_no_record_yes_file_good_file_no__id( mock_download_json_file_from_s3.return_value = mocked_downloaded_record location_to_id_map = dict() - self.basic_job._process_prefix( - s3_prefix="ecephys_642478_2023-01-17_13-56-29", - docdb_client=mock_docdb_client, - s3_client=mock_s3_client, - location_to_id_map=location_to_id_map, - ) + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._process_prefix( + s3_prefix="ecephys_642478_2023-01-17_13-56-29", + docdb_client=mock_docdb_client, + s3_client=mock_s3_client, + location_to_id_map=location_to_id_map, + ) + expected_log_messages = [ + "WARNING:root:Metadata record for s3://aind-ephys-data-dev-u5u0i5/" + "ecephys_642478_2023-01-17_13-56-29 does not have an _id field!" + ] + self.assertEqual(expected_log_messages, captured.output) mock_collection.assert_not_called() mock_cond_copy_then_sync_core_json_files.assert_not_called() mock_upload_metadata_json_str_to_s3.assert_not_called() - mock_log_warn.assert_called_once_with( - "Metadata record for s3://aind-ephys-data-dev-u5u0i5/" - "ecephys_642478_2023-01-17_13-56-29 does not have an _id field!" - ) @patch( "aind_data_asset_indexer.aind_bucket_indexer." @@ -1426,10 +1384,8 @@ def test_process_prefix_no_record_yes_file_good_file_no__id( @patch("aind_data_asset_indexer.aind_bucket_indexer.does_s3_object_exist") @patch("aind_data_asset_indexer.aind_bucket_indexer.MongoClient") @patch("boto3.client") - @patch("logging.warning") def test_process_prefix_no_record_yes_file_good_file_bad_location( self, - mock_log_warn: MagicMock, mock_s3_client: MagicMock, mock_docdb_client: MagicMock, mock_does_s3_object_exist: MagicMock, @@ -1457,30 +1413,30 @@ def test_process_prefix_no_record_yes_file_good_file_bad_location( mock_download_json_file_from_s3.return_value = mocked_downloaded_record location_to_id_map = dict() - self.basic_job._process_prefix( - s3_prefix="ecephys_642478_2023-01-17_13-56-29", - docdb_client=mock_docdb_client, - s3_client=mock_s3_client, - location_to_id_map=location_to_id_map, - ) + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._process_prefix( + s3_prefix="ecephys_642478_2023-01-17_13-56-29", + docdb_client=mock_docdb_client, + s3_client=mock_s3_client, + location_to_id_map=location_to_id_map, + ) + expected_log_messages = [ + "WARNING:root:Location field s3://aind-ephys-data-dev-u5u0i5/" + "ecephys_642478_2020-01-10_10-10-10 or name field " + "ecephys_642478_2023-01-17_13-56-29 does not match actual " + "location of record s3://aind-ephys-data-dev-u5u0i5/" + "ecephys_642478_2023-01-17_13-56-29!" + ] + self.assertEqual(expected_log_messages, captured.output) mock_collection.assert_not_called() mock_cond_copy_then_sync_core_json_files.assert_not_called() mock_upload_metadata_json_str_to_s3.assert_not_called() - mock_log_warn.assert_called_once_with( - "Location field s3://aind-ephys-data-dev-u5u0i5/" - "ecephys_642478_2020-01-10_10-10-10 or name field " - "ecephys_642478_2023-01-17_13-56-29 does not match actual location" - " of record s3://aind-ephys-data-dev-u5u0i5/" - "ecephys_642478_2023-01-17_13-56-29!" - ) @patch("aind_data_asset_indexer.aind_bucket_indexer.does_s3_object_exist") @patch("aind_data_asset_indexer.aind_bucket_indexer.MongoClient") @patch("boto3.client") - @patch("logging.info") def test_process_prefix_yes_record_yes_file( self, - mock_log_info: MagicMock, mock_s3_client: MagicMock, mock_docdb_client: MagicMock, mock_does_s3_object_exist: MagicMock, @@ -1496,17 +1452,19 @@ def test_process_prefix_yes_record_yes_file( location_to_id_map = { location_key: "488bbe42-832b-4c37-8572-25eb87cc50e2" } - self.basic_job._process_prefix( - s3_prefix="ecephys_642478_2023-01-17_13-56-29", - docdb_client=mock_docdb_client, - s3_client=mock_s3_client, - location_to_id_map=location_to_id_map, - ) - mock_log_info.assert_called_once_with( - f"Metadata record for s3://{expected_bucket}/" - f"ecephys_642478_2023-01-17_13-56-29/metadata.nd.json already " - f"exists in DocDb. Skipping." - ) + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._process_prefix( + s3_prefix="ecephys_642478_2023-01-17_13-56-29", + docdb_client=mock_docdb_client, + s3_client=mock_s3_client, + location_to_id_map=location_to_id_map, + ) + expected_log_messages = [ + "INFO:root:Metadata record for s3://aind-ephys-data-dev-u5u0i5/" + "ecephys_642478_2023-01-17_13-56-29/metadata.nd.json already " + "exists in DocDb. Skipping." + ] + self.assertEqual(expected_log_messages, captured.output) @patch( "aind_data_asset_indexer.aind_bucket_indexer." @@ -1580,10 +1538,8 @@ def test_dask_task_to_process_prefix_list( ) @patch("aind_data_asset_indexer.aind_bucket_indexer.MongoClient") @patch("boto3.client") - @patch("logging.error") def test_dask_task_to_process_prefix_list_error( self, - mock_log_error: MagicMock, mock_boto3_client: MagicMock, mock_docdb_client: MagicMock, mock_process_prefix: MagicMock, @@ -1614,7 +1570,16 @@ def test_dask_task_to_process_prefix_list_error( Exception("Error processing prefix"), None, ] - self.basic_job._dask_task_to_process_prefix_list(prefix_list=prefixes) + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._dask_task_to_process_prefix_list( + prefix_list=prefixes + ) + expected_log_messages = [ + "ERROR:root:Error processing s3://aind-ephys-data-dev-u5u0i5/" + "ecephys_567890_2000-01-01_04-00-00: " + "Exception('Error processing prefix')" + ] + self.assertEqual(expected_log_messages, captured.output) mock_process_prefix.assert_has_calls( [ call( @@ -1637,11 +1602,6 @@ def test_dask_task_to_process_prefix_list_error( ), ] ) - mock_log_error.assert_called_once_with( - "Error processing s3://aind-ephys-data-dev-u5u0i5/" - "ecephys_567890_2000-01-01_04-00-00: " - "Exception('Error processing prefix')" - ) mock_s3_client.close.assert_called_once_with() mock_mongo_client.close.assert_called_once_with() @@ -1668,7 +1628,6 @@ def test_process_prefixes(self, mock_dask_bag_map_parts: MagicMock): "aind_data_asset_indexer.aind_bucket_indexer.AindIndexBucketJob." "_process_records" ) - @patch("logging.info") @patch("aind_data_asset_indexer.aind_bucket_indexer.MongoClient") @patch("aind_data_asset_indexer.aind_bucket_indexer.paginate_docdb") @patch("boto3.client") @@ -1677,7 +1636,6 @@ def test_run_job( mock_boto3_client: MagicMock, mock_paginate: MagicMock, mock_docdb_client: MagicMock, - mock_log_info: MagicMock, mock_process_records: MagicMock, mock_iterate_prefixes: MagicMock, mock_process_prefixes: MagicMock, @@ -1706,19 +1664,18 @@ def test_run_job( ] ] ) - - self.basic_job.run_job() + with self.assertLogs(level="DEBUG") as captured: + self.basic_job.run_job() + expected_log_messages = [ + "INFO:root:Starting to scan through DocDb.", + "INFO:root:Finished scanning through DocDb.", + "INFO:root:Starting to scan through S3.", + "INFO:root:Finished scanning through S3.", + ] + self.assertEqual(expected_log_messages, captured.output) mock_mongo_client.close.assert_called_once() mock_s3_client.close.assert_called_once() - mock_log_info.assert_has_calls( - [ - call("Starting to scan through DocDb."), - call("Finished scanning through DocDb."), - call("Starting to scan through S3."), - call("Finished scanning through S3."), - ] - ) mock_process_records.assert_called_once_with( records=[ self.example_md_record, diff --git a/tests/test_codeocean_bucket_indexer.py b/tests/test_codeocean_bucket_indexer.py index 4b17fe9..1b7b944 100644 --- a/tests/test_codeocean_bucket_indexer.py +++ b/tests/test_codeocean_bucket_indexer.py @@ -131,18 +131,19 @@ def test_get_external_data_asset_records_error(self, mock_get: MagicMock): self.assertIsNone(response) @patch("requests.get") - @patch("logging.error") def test_get_external_data_asset_records_read_timeout( - self, mock_error: MagicMock, mock_get: MagicMock + self, mock_get: MagicMock ): """Tests the _get_external_data_asset_records method when the read times out.""" mock_get.side_effect = ReadTimeout() - response = self.basic_job._get_external_data_asset_records() + with self.assertLogs(level="DEBUG") as captured: + response = self.basic_job._get_external_data_asset_records() + expected_log_messages = [ + "ERROR:root:Read timed out at http://some_url:8080/created_after/0" + ] + self.assertEqual(expected_log_messages, captured.output) self.assertIsNone(response) - mock_error.assert_called_once_with( - "Read timed out at http://some_url:8080/created_after/0" - ) def test_map_external_list_to_dict(self): """Tests _map_external_list_to_dict method""" @@ -185,16 +186,10 @@ def test_get_co_links_from_record_legacy(self): @patch("aind_data_asset_indexer.codeocean_bucket_indexer.MongoClient") @patch("requests.get") @patch("aind_data_asset_indexer.codeocean_bucket_indexer.paginate_docdb") - @patch("logging.info") - @patch("logging.debug") - @patch("logging.error") @patch("aind_data_asset_indexer.codeocean_bucket_indexer.datetime") def test_update_external_links_in_docdb( self, mock_datetime: MagicMock, - mock_error: MagicMock, - mock_debug: MagicMock, - mock_info: MagicMock, mock_paginate: MagicMock, mock_get: MagicMock, mock_docdb_client: MagicMock, @@ -239,9 +234,17 @@ def test_update_external_links_in_docdb( ] ] - self.basic_job._update_external_links_in_docdb( - docdb_client=mock_docdb_client - ) + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._update_external_links_in_docdb( + docdb_client=mock_docdb_client + ) + expected_log_messages = [ + "INFO:root:No code ocean data asset ids found for " + "s3://bucket2/prefix3. Removing external links from record.", + "INFO:root:Updating 2 records", + "DEBUG:root:{'message': 'success'}", + ] + self.assertEqual(expected_log_messages, captured.output) expected_bulk_write_calls = [ call( requests=[ @@ -277,31 +280,13 @@ def test_update_external_links_in_docdb( ) ] - mock_error.assert_not_called() - mock_info.assert_has_calls( - [ - call( - "No code ocean data asset ids found for " - "s3://bucket2/prefix3. " - "Removing external links from record." - ), - call("Updating 2 records"), - ] - ) - mock_debug.assert_called_once_with({"message": "success"}) mock_collection.bulk_write.assert_has_calls(expected_bulk_write_calls) @patch("aind_data_asset_indexer.codeocean_bucket_indexer.MongoClient") @patch("requests.get") @patch("aind_data_asset_indexer.codeocean_bucket_indexer.paginate_docdb") - @patch("logging.info") - @patch("logging.debug") - @patch("logging.error") def test_update_external_links_in_docdb_error( self, - mock_error: MagicMock, - mock_debug: MagicMock, - mock_info: MagicMock, mock_paginate: MagicMock, mock_get: MagicMock, mock_docdb_client: MagicMock, @@ -315,19 +300,16 @@ def test_update_external_links_in_docdb_error( mock_db = MagicMock() mock_docdb_client.__getitem__.return_value = mock_db - - self.basic_job._update_external_links_in_docdb( - docdb_client=mock_docdb_client - ) - - mock_error.assert_called_once_with( - "There was an error retrieving external links!" - ) - mock_info.assert_not_called() - mock_debug.assert_not_called() + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._update_external_links_in_docdb( + docdb_client=mock_docdb_client + ) + expected_log_messages = [ + "ERROR:root:There was an error retrieving external links!" + ] + self.assertEqual(expected_log_messages, captured.output) mock_paginate.assert_not_called() - @patch("logging.info") @patch("aind_data_asset_indexer.codeocean_bucket_indexer.MongoClient") @patch("boto3.client") @patch("aind_data_asset_indexer.utils.get_dict_of_file_info") @@ -338,7 +320,6 @@ def test_process_codeocean_record( mock_get_dict_of_file_info: MagicMock, mock_s3_client: MagicMock, mock_docdb_client: MagicMock, - mock_log_info: MagicMock, ): """Tests _process_codeocean_record method""" # Assume user didn't attach any metadata files @@ -353,20 +334,18 @@ def test_process_codeocean_record( "message": "success" } - self.basic_job._process_codeocean_record( - codeocean_record=self.example_codeocean_records[1], - docdb_client=mock_docdb_client, - s3_client=mock_s3_client, - ) - mock_log_info.assert_has_calls( - [ - call( - "Uploading metadata record for: " - "s3://some_co_bucket/666666cc-66cc-6c66-666c-6c66c6666666" - ), - call({"message": "success"}), - ] - ) + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._process_codeocean_record( + codeocean_record=self.example_codeocean_records[1], + docdb_client=mock_docdb_client, + s3_client=mock_s3_client, + ) + expected_messages = [ + "INFO:root:Uploading metadata record for: " + "s3://some_co_bucket/666666cc-66cc-6c66-666c-6c66c6666666", + "DEBUG:root:{'message': 'success'}", + ] + self.assertEqual(expected_messages, captured.output) mock_download_json_file.assert_not_called() self.assertEqual( "ecephys_712815_2024-05-22_12-26-32_sorted_2024-06-12_19-45-59", @@ -380,7 +359,6 @@ def test_process_codeocean_record( ) @patch("aind_data_schema.core.metadata.Metadata.model_construct") - @patch("logging.warning") @patch("aind_data_asset_indexer.codeocean_bucket_indexer.MongoClient") @patch("boto3.client") @patch("aind_data_asset_indexer.utils.get_dict_of_file_info") @@ -391,7 +369,6 @@ def test_process_codeocean_record_warning( mock_get_dict_of_file_info: MagicMock, mock_s3_client: MagicMock, mock_docdb_client: MagicMock, - mock_log_warn: MagicMock, mock_model_construct: MagicMock, ): """Tests _process_codeocean_record when there is an issue building the @@ -404,16 +381,18 @@ def test_process_codeocean_record_warning( # Suppose there is an error using model_construct mock_model_construct.side_effect = Exception("Something went wrong") - self.basic_job._process_codeocean_record( - codeocean_record=self.example_codeocean_records[1], - docdb_client=mock_docdb_client, - s3_client=mock_s3_client, - ) - mock_download_json_file.assert_not_called() - mock_log_warn.assert_called_once_with( - "Unable to build metadata record for: " + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._process_codeocean_record( + codeocean_record=self.example_codeocean_records[1], + docdb_client=mock_docdb_client, + s3_client=mock_s3_client, + ) + expected_log_messages = [ + "WARNING:root:Unable to build metadata record for: " "s3://some_co_bucket/666666cc-66cc-6c66-666c-6c66c6666666!" - ) + ] + self.assertEqual(expected_log_messages, captured.output) + mock_download_json_file.assert_not_called() @patch( "aind_data_asset_indexer.codeocean_bucket_indexer." @@ -457,10 +436,8 @@ def test_dask_task_to_process_record_list( ) @patch("aind_data_asset_indexer.codeocean_bucket_indexer.MongoClient") @patch("boto3.client") - @patch("logging.error") def test_dask_task_to_process_record_list_error( self, - mock_log_error: MagicMock, mock_boto3_client: MagicMock, mock_docdb_client: MagicMock, mock_process_codeocean_record: MagicMock, @@ -476,7 +453,16 @@ def test_dask_task_to_process_record_list_error( Exception("Error processing record"), None, ] - self.basic_job._dask_task_to_process_record_list(record_list=records) + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._dask_task_to_process_record_list( + record_list=records + ) + expected_log_messages = [ + "ERROR:root:Error processing " + "s3://some_co_bucket/11ee1e1e-11e1-1111-1111-e11eeeee1e11: " + "Exception('Error processing record')" + ] + self.assertEqual(expected_log_messages, captured.output) mock_process_codeocean_record.assert_has_calls( [ call( @@ -491,11 +477,6 @@ def test_dask_task_to_process_record_list_error( ), ] ) - mock_log_error.assert_called_once_with( - "Error processing s3://some_co_bucket/" - "11ee1e1e-11e1-1111-1111-e11eeeee1e11: " - "Exception('Error processing record')" - ) mock_s3_client.close.assert_called_once_with() mock_mongo_client.close.assert_called_once_with() @@ -508,10 +489,9 @@ def test_process_codeocean_records( self.basic_job._process_codeocean_records(example_records) mock_dask_bag_map_parts.assert_called() - @patch("logging.info") @patch("aind_data_asset_indexer.codeocean_bucket_indexer.MongoClient") def test_dask_task_to_delete_record_list( - self, mock_docdb_client: MagicMock, mock_log_info: MagicMock + self, mock_docdb_client: MagicMock ): """Tests _dask_task_to_delete_record_list""" mock_db = MagicMock() @@ -522,15 +502,19 @@ def test_dask_task_to_delete_record_list( "message": "success" } records_to_delete = [r["_id"] for r in self.example_docdb_records] - self.basic_job._dask_task_to_delete_record_list( - record_list=records_to_delete - ) - mock_log_info.assert_called_once_with({"message": "success"}) + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._dask_task_to_delete_record_list( + record_list=records_to_delete + ) + expected_log_messages = [ + "INFO:root:Removing 2 records", + "DEBUG:root:{'message': 'success'}", + ] + self.assertEqual(expected_log_messages, captured.output) - @patch("logging.error") @patch("aind_data_asset_indexer.codeocean_bucket_indexer.MongoClient") def test_dask_task_to_delete_record_list_error( - self, mock_docdb_client: MagicMock, mock_log_error: MagicMock + self, mock_docdb_client: MagicMock ): """Tests _dask_task_to_delete_record_list""" mock_db = MagicMock() @@ -541,12 +525,16 @@ def test_dask_task_to_delete_record_list_error( "Error deleting records" ) records_to_delete = [r["_id"] for r in self.example_docdb_records] - self.basic_job._dask_task_to_delete_record_list( - record_list=records_to_delete - ) - mock_log_error.assert_called_once_with( - "Error deleting records: Exception('Error deleting records')" - ) + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._dask_task_to_delete_record_list( + record_list=records_to_delete + ) + expected_log_messages = [ + "INFO:root:Removing 2 records", + "ERROR:root:Error deleting records: " + "Exception('Error deleting records')", + ] + self.assertEqual(expected_log_messages, captured.output) @patch("dask.bag.map_partitions") def test_delete_records_from_docdb( @@ -577,10 +565,8 @@ def test_delete_records_from_docdb( "aind_data_asset_indexer.codeocean_bucket_indexer." "get_all_processed_codeocean_asset_records" ) - @patch("logging.info") def test_run_job( self, - mock_log_info: MagicMock, mock_get_all_co_records: MagicMock, mock_docdb_client: MagicMock, mock_paginate_docdb: MagicMock, @@ -596,7 +582,21 @@ def test_run_job( [(r["location"], r) for r in self.example_codeocean_records] ) mock_paginate_docdb.return_value = [self.example_docdb_records] - self.basic_job.run_job() + with self.assertLogs(level="DEBUG") as captured: + self.basic_job.run_job() + expected_log_messages = [ + "INFO:root:Starting to scan through CodeOcean.", + "INFO:root:Finished scanning through CodeOcean.", + "INFO:root:Starting to scan through DocDb.", + "INFO:root:Adding links to records.", + "INFO:root:Finished adding links to records", + "INFO:root:Finished scanning through DocDB.", + "INFO:root:Starting to add records to DocDB.", + "INFO:root:Finished adding records to DocDB.", + "INFO:root:Starting to delete records from DocDB.", + "INFO:root:Finished deleting records from DocDB.", + ] + self.assertEqual(expected_log_messages, captured.output) mock_update_external_links_in_docdb.assert_called_once_with( docdb_client=mock_mongo_client @@ -607,20 +607,6 @@ def test_run_job( mock_delete_records_from_docdb.assert_called_once_with( record_list=["efg-456"] ) - mock_log_info.assert_has_calls( - [ - call("Starting to scan through CodeOcean."), - call("Finished scanning through CodeOcean."), - call("Starting to scan through DocDb."), - call("Adding links to records."), - call("Finished adding links to records"), - call("Finished scanning through DocDB."), - call("Starting to add records to DocDB."), - call("Finished adding records to DocDB."), - call("Starting to delete records from DocDB."), - call("Finished deleting records from DocDB."), - ] - ) mock_mongo_client.close.assert_called_once() diff --git a/tests/test_index_aind_buckets.py b/tests/test_index_aind_buckets.py index 5667862..e9794a0 100644 --- a/tests/test_index_aind_buckets.py +++ b/tests/test_index_aind_buckets.py @@ -14,10 +14,7 @@ class TestIndexAindBucketsJob(unittest.TestCase): "aind_data_asset_indexer.aind_bucket_indexer.AindIndexBucketJob." "run_job" ) - @patch("logging.info") - def test_run_job( - self, mock_log_info: MagicMock, mock_sub_run_job: MagicMock - ): + def test_run_job(self, mock_sub_run_job: MagicMock): """Tests run_job method.""" job_settings = AindIndexBucketsJobSettings( @@ -30,15 +27,16 @@ def test_run_job( doc_db_collection_name="some_docdb_collection_name", ) job = IndexAindBucketsJob(job_settings=job_settings) - job.run_job() - mock_log_info.assert_has_calls( - [ - call("Processing bucket1"), - call("Finished processing bucket1"), - call("Processing bucket2"), - call("Finished processing bucket2"), - ] - ) + with self.assertLogs(level="DEBUG") as captured: + job.run_job() + expected_log_messages = [ + "INFO:root:Processing bucket1", + "INFO:root:Finished processing bucket1", + "INFO:root:Processing bucket2", + "INFO:root:Finished processing bucket2", + ] + self.assertEqual(expected_log_messages, captured.output) + mock_sub_run_job.assert_has_calls([call(), call()]) diff --git a/tests/test_populate_aind_buckets.py b/tests/test_populate_aind_buckets.py index 7414e73..14f7636 100644 --- a/tests/test_populate_aind_buckets.py +++ b/tests/test_populate_aind_buckets.py @@ -16,25 +16,22 @@ class TestPopulateAindBucketsJob(unittest.TestCase): "aind_data_asset_indexer.populate_s3_with_metadata_files." "AindPopulateMetadataJsonJob.run_job" ) - @patch("logging.info") - def test_run_job( - self, mock_log_info: MagicMock, mock_sub_run_job: MagicMock - ): + def test_run_job(self, mock_sub_run_job: MagicMock): """Tests run_job method.""" job_settings = PopulateAindBucketsJobSettings( s3_buckets=["bucket1", "bucket2"] ) job = PopulateAindBucketsJob(job_settings=job_settings) - job.run_job() - mock_log_info.assert_has_calls( - [ - call("Processing bucket1"), - call("Finished processing bucket1"), - call("Processing bucket2"), - call("Finished processing bucket2"), - ] - ) + with self.assertLogs(level="DEBUG") as captured: + job.run_job() + expected_log_messages = [ + "INFO:root:Processing bucket1", + "INFO:root:Finished processing bucket1", + "INFO:root:Processing bucket2", + "INFO:root:Finished processing bucket2", + ] + self.assertEqual(expected_log_messages, captured.output) mock_sub_run_job.assert_has_calls([call(), call()]) diff --git a/tests/test_populate_s3_with_metadata_files.py b/tests/test_populate_s3_with_metadata_files.py index ebdfc0d..a89d20a 100644 --- a/tests/test_populate_s3_with_metadata_files.py +++ b/tests/test_populate_s3_with_metadata_files.py @@ -51,12 +51,8 @@ def load_utils_json_file(filename: str) -> dict: "build_metadata_record_from_prefix" ) @patch("boto3.client") - @patch("logging.warning") - @patch("logging.info") def test_process_prefix_not_none( self, - mock_log_info: MagicMock, - mock_log_warn: MagicMock, mock_s3_client: MagicMock, mock_build_record: MagicMock, mock_cond_copy_then_sync_core_json_files: MagicMock, @@ -67,10 +63,18 @@ def test_process_prefix_not_none( expected_bucket = "aind-ephys-data-dev-u5u0i5" expected_prefix = "ecephys_642478_2023-01-17_13-56-29" mock_build_record.return_value = json.dumps(self.example_md_record) - self.basic_job._process_prefix( - s3_client=mock_s3_client, - prefix=expected_prefix, - ) + mock_upload_record.return_value = "Uploaded record" + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._process_prefix( + s3_client=mock_s3_client, + prefix=expected_prefix, + ) + expected_log_messages = [ + f"INFO:root:Uploading metadata record for: " + f"s3://{expected_bucket}/{expected_prefix}", + "DEBUG:root:Uploaded record", + ] + self.assertEqual(expected_log_messages, captured.output) mock_build_record.assert_called_once_with( prefix=expected_prefix, s3_client=mock_s3_client, @@ -81,7 +85,6 @@ def test_process_prefix_not_none( bucket=expected_bucket, prefix=expected_prefix, s3_client=mock_s3_client, - log_flag=True, copy_original_md_subdir="original_metadata", ) mock_upload_record.assert_called_once_with( @@ -90,8 +93,6 @@ def test_process_prefix_not_none( s3_client=mock_s3_client, metadata_json=json.dumps(self.example_md_record), ) - mock_log_info.assert_called() - mock_log_warn.assert_not_called() @patch( "aind_data_asset_indexer.populate_s3_with_metadata_files." @@ -106,12 +107,8 @@ def test_process_prefix_not_none( "build_metadata_record_from_prefix" ) @patch("boto3.client") - @patch("logging.warning") - @patch("logging.info") def test_process_prefix_none( self, - mock_log_info: MagicMock, - mock_log_warn: MagicMock, mock_s3_client: MagicMock, mock_build_record: MagicMock, mock_cond_copy_then_sync_core_json_files: MagicMock, @@ -121,10 +118,17 @@ def test_process_prefix_none( build_metadata_record_from_prefix.""" mock_build_record.return_value = None - self.basic_job._process_prefix( - s3_client=mock_s3_client, - prefix="ecephys_642478_2023-01-17_13-56-29", - ) + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._process_prefix( + s3_client=mock_s3_client, + prefix="ecephys_642478_2023-01-17_13-56-29", + ) + expected_log_messages = [ + "WARNING:root:Unable to build metadata record for: " + "s3://aind-ephys-data-dev-u5u0i5/" + "ecephys_642478_2023-01-17_13-56-29!" + ] + self.assertEqual(expected_log_messages, captured.output) mock_build_record.assert_called_once_with( prefix="ecephys_642478_2023-01-17_13-56-29", s3_client=mock_s3_client, @@ -132,12 +136,6 @@ def test_process_prefix_none( ) mock_cond_copy_then_sync_core_json_files.assert_not_called() mock_upload_record.assert_not_called() - mock_log_info.assert_not_called() - mock_log_warn.assert_called_once_with( - "Unable to build metadata record for: " - "s3://aind-ephys-data-dev-u5u0i5/" - "ecephys_642478_2023-01-17_13-56-29!" - ) @patch( "aind_data_asset_indexer.populate_s3_with_metadata_files." @@ -152,31 +150,27 @@ def test_process_prefix_none( "build_metadata_record_from_prefix" ) @patch("boto3.client") - @patch("logging.warning") - @patch("logging.info") def test_process_prefix_invalid_prefix( self, - mock_log_info: MagicMock, - mock_log_warn: MagicMock, mock_s3_client: MagicMock, mock_build_record: MagicMock, mock_cond_copy_then_sync_core_json_files: MagicMock, mock_upload_record: MagicMock, ): """Tests _process_prefix method when the prefix is invalid.""" - - self.basic_job._process_prefix( - s3_client=mock_s3_client, - prefix="ecephys_642478", - ) + with self.assertLogs(level="DEBUG") as captured: + self.basic_job._process_prefix( + s3_client=mock_s3_client, + prefix="ecephys_642478", + ) + expected_log_messages = [ + "WARNING:root:Prefix ecephys_642478 not valid in bucket " + "aind-ephys-data-dev-u5u0i5! Skipping." + ] + self.assertEqual(expected_log_messages, captured.output) mock_build_record.assert_not_called() mock_cond_copy_then_sync_core_json_files.assert_not_called() mock_upload_record.assert_not_called() - mock_log_info.assert_not_called() - mock_log_warn.assert_called_once_with( - "Prefix ecephys_642478 not valid in bucket " - "aind-ephys-data-dev-u5u0i5! Skipping." - ) @patch( "aind_data_asset_indexer.populate_s3_with_metadata_files." diff --git a/tests/test_utils.py b/tests/test_utils.py index cfe011a..3b34ad6 100644 --- a/tests/test_utils.py +++ b/tests/test_utils.py @@ -1,7 +1,6 @@ """Tests methods in utils module""" import json -import logging import os import unittest from copy import deepcopy @@ -14,7 +13,6 @@ from requests import Response from aind_data_asset_indexer.utils import ( - _log_message, build_docdb_location_to_id_map, build_metadata_record_from_prefix, compute_md5_hash, @@ -144,46 +142,6 @@ def load_json_file(filename: str) -> dict: ) cls.example_co_search_data_assets = example_co_search_data_assets - @patch("logging.log") - def test__log_message_true(self, mock_log: MagicMock): - """Tests _log_message method when log_flag is True or not provided""" - message = "This is a test message" - valid_log_levels = [ - logging.DEBUG, - logging.INFO, - logging.WARNING, - logging.ERROR, - logging.CRITICAL, - ] - invalid_log_levels = [logging.NOTSET, -1, 1, 100] - _log_message(message) - _log_message(message, log_flag=True) - for log_level in valid_log_levels: - _log_message(message, log_level) - mock_log.assert_has_calls( - [ - call(logging.INFO, message), - call(logging.INFO, message), - call(logging.DEBUG, message), - call(logging.INFO, message), - call(logging.WARNING, message), - call(logging.ERROR, message), - call(logging.CRITICAL, message), - ] - ) - for log_level in invalid_log_levels: - with self.assertRaises(ValueError): - _log_message(message, log_level) - - @patch("logging.log") - def test__log_message_false(self, mock_log: MagicMock): - """Tests _log_message method when log_flag is False""" - message = "This is a test message" - _log_message(message, log_flag=False) - _log_message(message, log_level=logging.WARNING, log_flag=False) - _log_message(message, log_level=logging.NOTSET, log_flag=False) - mock_log.assert_not_called() - def test_compute_md5_hash(self): """Tests compute_md5_hash method""" md5_hash = compute_md5_hash(json.dumps(self.example_metadata_nd)) @@ -202,6 +160,7 @@ def test_is_dict_corrupt(self): self.assertTrue(is_dict_corrupt(bad_contents2)) self.assertTrue(is_dict_corrupt(bad_contents3)) self.assertTrue(is_dict_corrupt(bad_contents4)) + # noinspection PyTypeChecker self.assertTrue(is_dict_corrupt(bad_contents5)) def test_create_object_key(self): @@ -907,10 +866,8 @@ def test_build_metadata_record_from_prefix_error( @patch("aind_data_asset_indexer.utils.upload_json_str_to_s3") @patch("aind_data_asset_indexer.utils.get_dict_of_file_info") @patch("boto3.client") - @patch("aind_data_asset_indexer.utils._log_message") def test_sync_core_json_files( self, - mock_log_message: MagicMock, mock_s3_client: MagicMock, mock_get_dict_of_file_info: MagicMock, mock_upload_core_record: MagicMock, @@ -968,12 +925,37 @@ def test_sync_core_json_files( } mock_upload_core_record.return_value = "mock_upload_response" mock_s3_client.delete_object.return_value = "mock_delete_response" - sync_core_json_files( - metadata_json=json.dumps(md_json_from_docdb), - bucket=expected_bucket, - prefix=pfx, - s3_client=mock_s3_client, - ) + with self.assertLogs(level="DEBUG") as captured: + sync_core_json_files( + metadata_json=json.dumps(md_json_from_docdb), + bucket=expected_bucket, + prefix=pfx, + s3_client=mock_s3_client, + ) + expected_log_messages = [ + f"INFO:root:Uploading new data_description to " + f"{s3_loc}/data_description.json", + "DEBUG:root:mock_upload_response", + f"INFO:root:acquisition not found in metadata.nd.json for " + f"{pfx} nor in {s3_loc}/acquisition.json! Skipping.", + f"INFO:root:instrument not found in metadata.nd.json for " + f"{pfx} nor in {s3_loc}/instrument.json! Skipping.", + f"INFO:root:Uploading updated procedures to " + f"{s3_loc}/procedures.json", + "DEBUG:root:mock_upload_response", + f"INFO:root:processing is up-to-date in " + f"{s3_loc}/processing.json. Skipping.", + f"INFO:root:quality_control not found in metadata.nd.json for " + f"{pfx} nor in {s3_loc}/quality_control.json! Skipping.", + f"INFO:root:rig not found in metadata.nd.json for {pfx} but " + f"{s3_loc}/rig.json exists! Deleting.", + "DEBUG:root:mock_delete_response", + f"INFO:root:session not found in metadata.nd.json for " + f"{pfx} nor in {s3_loc}/session.json! Skipping.", + f"INFO:root:subject is up-to-date in " + f"{s3_loc}/subject.json. Skipping.", + ] + self.assertEqual(expected_log_messages, captured.output) mock_get_dict_of_file_info.assert_called_once() # assert that only new or updated core jsons were uploaded to s3 mock_upload_core_record.assert_has_calls( @@ -999,55 +981,13 @@ def test_sync_core_json_files( Bucket=expected_bucket, Key=f"{pfx}/rig.json", ) - # assert correct logs for all actions - expected_logs = [ - ( - f"acquisition not found in metadata.nd.json for {pfx} nor in " - f"{s3_loc}/acquisition.json! Skipping." - ), - ( - f"Uploading new data_description to {s3_loc}/" - "data_description.json" - ), - "mock_upload_response", - ( - f"instrument not found in metadata.nd.json for {pfx} nor in " - f"{s3_loc}/instrument.json! Skipping." - ), - f"Uploading updated procedures to {s3_loc}/procedures.json", - "mock_upload_response", - ( - f"processing is up-to-date in {s3_loc}/processing.json. " - "Skipping." - ), - ( - f"quality_control not found in metadata.nd.json for {pfx} nor " - f"in {s3_loc}/quality_control.json! Skipping." - ), - ( - f"rig not found in metadata.nd.json for {pfx} but {s3_loc}/" - "rig.json exists! Deleting." - ), - "mock_delete_response", - ( - f"session not found in metadata.nd.json for {pfx} nor in " - f"{s3_loc}/session.json! Skipping." - ), - f"subject is up-to-date in {s3_loc}/subject.json. Skipping.", - ] - actual_log_messages = [ - c[1]["message"] for c in mock_log_message.call_args_list - ] - self.assertCountEqual(expected_logs, actual_log_messages) @patch("aind_data_asset_indexer.utils.upload_json_str_to_s3") @patch("aind_data_asset_indexer.utils.get_dict_of_file_info") @patch("aind_data_asset_indexer.utils.does_s3_metadata_copy_exist") @patch("boto3.client") - @patch("aind_data_asset_indexer.utils._log_message") def test_cond_copy_then_sync_core_json_files( self, - mock_log_message: MagicMock, mock_s3_client: MagicMock, mock_does_s3_metadata_copy_exist: MagicMock, mock_get_dict_of_file_info: MagicMock, @@ -1060,6 +1000,7 @@ def test_cond_copy_then_sync_core_json_files( # example_md_record only has processing and subject fields # assume /original_metadata already exists mock_does_s3_metadata_copy_exist.return_value = True + mock_upload_core_record.return_value = "Some Message" mock_get_dict_of_file_info.return_value = { f"{pfx}/acquisition.json": None, f"{pfx}/data_description.json": None, @@ -1083,12 +1024,40 @@ def test_cond_copy_then_sync_core_json_files( "version_id": "XS0p7m6wWNTHG_F3P76D7AUXtE23BakR", }, } - cond_copy_then_sync_core_json_files( - metadata_json=json.dumps(self.example_metadata_nd), - bucket=bucket, - prefix=pfx, - s3_client=mock_s3_client, - ) + with self.assertLogs(level="DEBUG") as captured: + cond_copy_then_sync_core_json_files( + metadata_json=json.dumps(self.example_metadata_nd), + bucket=bucket, + prefix=pfx, + s3_client=mock_s3_client, + ) + expected_output_messages = [ + f"WARNING:root:Copy of original metadata already exists at " + f"s3://{bucket}/{pfx}/original_metadata", + f"INFO:root:data_description not found in metadata.nd.json for " + f"{pfx} nor in s3://{bucket}/{pfx}/data_description.json! " + f"Skipping.", + f"INFO:root:acquisition not found in metadata.nd.json for " + f"{pfx} nor in s3://{bucket}/{pfx}/acquisition.json! Skipping.", + f"INFO:root:instrument not found in metadata.nd.json for " + f"{pfx} nor in s3://{bucket}/{pfx}/instrument.json! Skipping.", + f"INFO:root:procedures not found in metadata.nd.json for " + f"{pfx} nor in s3://{bucket}/{pfx}/procedures.json! Skipping.", + f"INFO:root:Uploading updated processing to " + f"s3://{bucket}/{pfx}/processing.json", + "DEBUG:root:Some Message", + f"INFO:root:quality_control not found in metadata.nd.json for " + f"{pfx} nor in s3://{bucket}/{pfx}/quality_control.json! " + f"Skipping.", + f"INFO:root:rig not found in metadata.nd.json for " + f"{pfx} nor in s3://{bucket}/{pfx}/rig.json! Skipping.", + f"INFO:root:session not found in metadata.nd.json for " + f"{pfx} nor in s3://{bucket}/{pfx}/session.json! Skipping.", + f"INFO:root:Uploading updated subject to " + f"s3://{bucket}/{pfx}/subject.json", + "DEBUG:root:Some Message", + ] + self.assertEqual(expected_output_messages, captured.output) # assert that an existing /original_metadata folder was detected mock_does_s3_metadata_copy_exist.assert_called_once_with( bucket=bucket, @@ -1096,11 +1065,6 @@ def test_cond_copy_then_sync_core_json_files( copy_subdir="original_metadata", s3_client=mock_s3_client, ) - self.assertEqual( - "Copy of original metadata already exists at " - f"s3://{bucket}/{pfx}/original_metadata", - mock_log_message.call_args_list[0][1]["message"], - ) # assert that the original core jsons were not copied mock_s3_client.copy_object.assert_not_called() # assert that core jsons were overwritten @@ -1123,21 +1087,13 @@ def test_cond_copy_then_sync_core_json_files( ] ) mock_s3_client.delete_object.assert_not_called() - response_logs = [ - c[1]["log_level"] - for c in mock_log_message.call_args_list - if "log_level" in c[1] - ] - self.assertEqual([], response_logs) @patch("aind_data_asset_indexer.utils.upload_json_str_to_s3") @patch("aind_data_asset_indexer.utils.get_dict_of_file_info") @patch("aind_data_asset_indexer.utils.does_s3_metadata_copy_exist") @patch("boto3.client") - @patch("aind_data_asset_indexer.utils._log_message") def test_cond_copy_then_sync_core_json_files_mismatch( self, - mock_log_message: MagicMock, mock_s3_client: MagicMock, mock_does_s3_metadata_copy_exist: MagicMock, mock_get_dict_of_file_info: MagicMock, @@ -1148,6 +1104,10 @@ def test_cond_copy_then_sync_core_json_files_mismatch( bucket = "aind-ephys-data-dev-u5u0i5" pfx = "ecephys_642478_2023-01-17_13-56-29" + mock_s3_client.copy_object.return_value = "Copy object" + mock_s3_client.delete_object.return_value = "Delete object" + mock_upload_core_record.return_value = "Uploaded json" + # example_md_record only has processing and subject fields # assume rig.json exists but is corrupt # assume /original_metadata does not exist @@ -1181,13 +1141,66 @@ def test_cond_copy_then_sync_core_json_files_mismatch( "version_id": "XS0p7m6wWNTHG_F3P76D7AUXtE23BakR", }, } - - cond_copy_then_sync_core_json_files( - metadata_json=json.dumps(self.example_metadata_nd), - bucket=bucket, - prefix=pfx, - s3_client=mock_s3_client, - ) + with self.assertLogs(level="DEBUG") as captured: + cond_copy_then_sync_core_json_files( + metadata_json=json.dumps(self.example_metadata_nd), + bucket=bucket, + prefix=pfx, + s3_client=mock_s3_client, + ) + expected_log_messages = [ + f"INFO:root:Source file " + f"s3://{bucket}/{pfx}/data_description.json does not exist. " + f"Skipping copy.", + f"INFO:root:Source file " + f"s3://{bucket}/{pfx}/acquisition.json does not exist. " + f"Skipping copy.", + f"INFO:root:Source file " + f"s3://{bucket}/{pfx}/instrument.json does not exist. " + f"Skipping copy.", + f"INFO:root:Source file " + f"s3://{bucket}/{pfx}/procedures.json does not exist. " + f"Skipping copy.", + f"INFO:root:Copying {pfx}/processing.json to " + f"{pfx}/original_metadata/processing.20231104.json in " + f"s3://{bucket}", + "DEBUG:root:Copy object", + f"INFO:root:Source file " + f"s3://{bucket}/{pfx}/quality_control.json does not exist. " + f"Skipping copy.", + f"INFO:root:Copying {pfx}/rig.json to " + f"{pfx}/original_metadata/rig.20220505.json in s3://{bucket}", + "DEBUG:root:Copy object", + f"INFO:root:Source file " + f"s3://{bucket}/{pfx}/session.json does not exist. Skipping copy.", + f"INFO:root:Copying {pfx}/subject.json to " + f"{pfx}/original_metadata/subject.20240202.json in s3://{bucket}", + "DEBUG:root:Copy object", + f"INFO:root:data_description not found in metadata.nd.json for " + f"{pfx} nor in s3://{bucket}/{pfx}/data_description.json! " + f"Skipping.", + f"INFO:root:acquisition not found in metadata.nd.json for " + f"{pfx} nor in s3://{bucket}/{pfx}/acquisition.json! Skipping.", + f"INFO:root:instrument not found in metadata.nd.json for " + f"{pfx} nor in s3://{bucket}/{pfx}/instrument.json! Skipping.", + f"INFO:root:procedures not found in metadata.nd.json for " + f"{pfx} nor in s3://{bucket}/{pfx}/procedures.json! Skipping.", + f"INFO:root:Uploading updated processing to " + f"s3://{bucket}/{pfx}/processing.json", + "DEBUG:root:Uploaded json", + f"INFO:root:quality_control not found in metadata.nd.json for " + f"{pfx} nor in s3://{bucket}/{pfx}/quality_control.json! " + f"Skipping.", + f"INFO:root:rig not found in metadata.nd.json for {pfx} but " + f"s3://{bucket}/{pfx}/rig.json exists! Deleting.", + "DEBUG:root:Delete object", + f"INFO:root:session not found in metadata.nd.json for " + f"{pfx} nor in s3://{bucket}/{pfx}/session.json! Skipping.", + f"INFO:root:Uploading updated subject to " + f"s3://{bucket}/{pfx}/subject.json", + "DEBUG:root:Uploaded json", + ] + self.assertEqual(expected_log_messages, captured.output) # assert that the original core jsons were copied, including # corrupt rig.json mock_s3_client.copy_object.assert_has_calls( @@ -1198,7 +1211,7 @@ def test_cond_copy_then_sync_core_json_files_mismatch( "Bucket": bucket, "Key": f"{pfx}/processing.json", }, - Key=(f"{pfx}/original_metadata/processing.20231104.json"), + Key=f"{pfx}/original_metadata/processing.20231104.json", ), call( Bucket=bucket, @@ -1206,7 +1219,7 @@ def test_cond_copy_then_sync_core_json_files_mismatch( "Bucket": bucket, "Key": f"{pfx}/rig.json", }, - Key=(f"{pfx}/original_metadata/rig.20220505.json"), + Key=f"{pfx}/original_metadata/rig.20220505.json", ), call( Bucket=bucket, @@ -1214,7 +1227,7 @@ def test_cond_copy_then_sync_core_json_files_mismatch( "Bucket": bucket, "Key": f"{pfx}/subject.json", }, - Key=(f"{pfx}/original_metadata/subject.20240202.json"), + Key=f"{pfx}/original_metadata/subject.20240202.json", ), ] ) @@ -1241,12 +1254,6 @@ def test_cond_copy_then_sync_core_json_files_mismatch( mock_s3_client.delete_object.assert_called_once_with( Bucket=bucket, Key=f"{pfx}/rig.json" ) - response_logs = [ - c[1]["log_level"] - for c in mock_log_message.call_args_list - if "log_level" in c[1] - ] - self.assertEqual([], response_logs) @patch("pymongo.MongoClient") def test_does_metadata_record_exist_in_docdb_true( @@ -1461,9 +1468,8 @@ def test_get_all_processed_codeocean_asset_records( @patch( "aind_codeocean_api.codeocean.CodeOceanClient.search_all_data_assets" ) - @patch("logging.warning") def test_get_all_processed_codeocean_asset_records_warning( - self, mock_log_warn: MagicMock, mock_search_all_data_assets: MagicMock + self, mock_search_all_data_assets: MagicMock ): """Tests get_all_processed_codeocean_asset_records method when 10,000 records are returned""" @@ -1484,14 +1490,16 @@ def test_get_all_processed_codeocean_asset_records_warning( mock_response2, ] co_client = CodeOceanClient(domain="some_domain", token="some_token") - get_all_processed_codeocean_asset_records( - co_client=co_client, - co_data_asset_bucket="some_co_bucket", - ) - mock_log_warn.assert_called_once_with( - "Number of records exceeds 10,000! " + with self.assertLogs(level="DEBUG") as captured: + get_all_processed_codeocean_asset_records( + co_client=co_client, + co_data_asset_bucket="some_co_bucket", + ) + expected_log_messages = [ + "WARNING:root:Number of records exceeds 10,000! " "This can lead to possible data loss." - ) + ] + self.assertEqual(expected_log_messages, captured.output) if __name__ == "__main__":