Merge pull request #227 from AllenNeuralDynamics/refactor-logging-formatting

Refactor logging statements to use lazy formatting for consistency

Author: bruno-f-cruz

docs/build.py

@@ -140,18 +140,18 @@ def copy_assets() -> None:
         dest: Path = DOCS_DIR / file_or_dir
 
         if src.exists():
-            log.info(f"Copying {file_or_dir} to docs...")
+            log.info("Copying %s to docs...", file_or_dir)
 
             if src.is_file():
-                log.info(f"Copying file {src} to {dest}")
+                log.info("Copying file %s to %s", src, dest)
                 shutil.copy(src, dest)
             else:
                 if dest.exists():
                     shutil.rmtree(dest)
                 shutil.copytree(src, dest)
-            log.info(f"{file_or_dir} copied successfully.")
+            log.info("%s copied successfully.", file_or_dir)
         else:
-            log.warning(f"Source: {file_or_dir} not found, skipping.")
+            log.warning("Source: %s not found, skipping.", file_or_dir)
 
 
 def find_service_settings_classes(src_dir: Path) -> List[Tuple[str, Optional[str]]]:  # noqa: C901
@@ -201,7 +201,7 @@ def find_service_settings_classes(src_dir: Path) -> List[Tuple[str, Optional[str
                     service_settings.append((node.name, yml_section))
 
         except Exception as e:
-            log.warning(f"Failed to parse {py_file}: {e}")
+            log.warning("Failed to parse %s: %s", py_file, e)
 
     return sorted(service_settings, key=lambda x: x[0])
 
@@ -239,7 +239,7 @@ def generate_service_settings_table() -> None:
     with open(output_path, "w", encoding="utf-8") as f:
         f.write("\n".join(content))
 
-    log.info(f"Service settings documentation written to {output_path}")
+    log.info("Service settings documentation written to %s", output_path)
 
 
 def main() -> None:

src/clabe/cache_manager.py

@@ -163,7 +163,7 @@ def get_instance(
                             cache_data = CacheData.model_validate_json(f.read())
                             instance.caches = cache_data.caches
                     except Exception as e:
-                        logger.warning(f"Cache file {cache_path} is corrupted: {e}. Creating new instance.")
+                        logger.warning("Cache file %s is corrupted: %s. Creating new instance.", cache_path, e)
 
                 cls._instance = instance
 
@@ -306,7 +306,7 @@ def cli_cmd(self):
         if not manager.caches:
             logger.info("No caches available.")
         for name, cache in manager.caches.items():
-            logger.info(f"Cache '{name}': {cache.values}")
+            logger.info("Cache '%s': %s", name, cache.values)
 
 
 class _ResetCacheCli(BaseSettings):

src/clabe/constants.py

@@ -22,7 +22,7 @@
 
 for i, p in enumerate(KNOWN_CONFIG_FILES):
     if Path(p).exists():
-        logger.debug(f"Found config file: {p} with rank priority {i}")
+        logger.debug("Found config file: %s with rank priority %s", p, i)
 
 
 class ByAnimalFiles(enum.StrEnum):

src/clabe/pickers/_by_animal_modifier.py

@@ -135,12 +135,12 @@ def inject(self, rig: TRig) -> TRig:
         """
         target_file = self._subject_db_path / f"{self._model_name}.json"
         if not target_file.exists():
-            logger.warning(f"File not found: {target_file}. Using default.")
+            logger.warning("File not found: %s. Using default.", target_file)
         else:
             target = rgetattr(rig, self._model_path)
             self._tp = TypeAdapter(type(target))
             deserialized = self._tp.validate_json(target_file.read_text(encoding="utf-8"))
-            logger.info(f"Loading {self._model_name} from: {target_file}. Deserialized: {deserialized}")
+            logger.info("Loading %s from: %s. Deserialized: %s", self._model_name, target_file, deserialized)
             self._process_before_inject(deserialized)
             rsetattr(rig, self._model_path, deserialized)
         return rig
@@ -165,11 +165,11 @@ def dump(self) -> None:
 
         try:
             to_inject = self._process_before_dump()
-            logger.info(f"Saving {self._model_name} to: {target_file}. Serialized: {to_inject}")
+            logger.info("Saving %s to: %s. Serialized: %s", self._model_name, target_file, to_inject)
             target_folder.mkdir(parents=True, exist_ok=True)
             target_file.write_text(tp.dump_json(to_inject, indent=2).decode("utf-8"), encoding="utf-8")
         except Exception as e:
-            logger.error(f"Failed to process before dumping modifier: {e}")
+            logger.error("Failed to process before dumping modifier: %s", e)
             raise
 
 

src/clabe/xml_rpc/_client.py

@@ -62,7 +62,7 @@ def __init__(self, settings: XmlRpcClientSettings):
             self, timeout=settings.timeout, poll_interval=settings.poll_interval, monitor=settings.monitor
         )
 
-        logger.info(f"RPC client initialized for server: {settings.server_url}")
+        logger.info("RPC client initialized for server: %s", settings.server_url)
 
     def _call_with_auth(self, method_name: str, *args, **kwargs):
         """
@@ -108,7 +108,7 @@ def submit_command(self, cmd_args: list[str] | str) -> JobSubmissionResponse:
             cmd_args = [cmd_args]
         result = self._call_with_auth("run", cmd_args)
         response = JobSubmissionResponse(**result)
-        logger.info(f"Submitted command {cmd_args} with job ID: {response.job_id}")
+        logger.info("Submitted command %s with job ID: %s", cmd_args, response.job_id)
         return response
 
     def get_result(self, job_id: str) -> JobResult:
@@ -297,12 +297,12 @@ def upload_file(
         file_data = local_path.read_bytes()
         data_base64 = base64.b64encode(file_data).decode("utf-8")
 
-        logger.info(f"Uploading file {local_path} as {remote_filename} ({file_size} bytes)")
+        logger.info("Uploading file %s as %s (%s bytes)", local_path, remote_filename, file_size)
 
         result = self._call_with_auth("upload_file", remote_filename, data_base64, overwrite)
         response = FileUploadResponse(**result)
 
-        logger.info(f"Successfully uploaded {remote_filename}")
+        logger.info("Successfully uploaded %s", remote_filename)
         return response
 
     def upload_model(self, model: BaseModel, remote_filename: str, overwrite: bool = True) -> FileUploadResponse:
@@ -346,12 +346,12 @@ class MyModel(BaseModel):
         # Encode for transport
         data_base64 = base64.b64encode(json_bytes).decode("utf-8")
 
-        logger.info(f"Uploading model as {remote_filename} ({data_size} bytes)")
+        logger.info("Uploading model as %s (%s bytes)", remote_filename, data_size)
 
         result = self._call_with_auth("upload_file", remote_filename, data_base64, overwrite)
         response = FileUploadResponse(**result)
 
-        logger.info(f"Successfully uploaded model as {remote_filename}")
+        logger.info("Successfully uploaded model as %s", remote_filename)
         return response
 
     def download_file(self, remote_filename: str, local_path: Optional[Union[str, Path]] = None) -> Path:
@@ -376,7 +376,7 @@ def download_file(self, remote_filename: str, local_path: Optional[Union[str, Pa
         else:
             local_path = Path(local_path)
 
-        logger.info(f"Downloading file {remote_filename} to {local_path}")
+        logger.info("Downloading file %s to %s", remote_filename, local_path)
 
         result = self._call_with_auth("download_file", remote_filename)
 
@@ -396,7 +396,7 @@ def download_file(self, remote_filename: str, local_path: Optional[Union[str, Pa
         file_data = response.data
         local_path.write_bytes(file_data)
 
-        logger.info(f"Successfully downloaded {remote_filename} ({response.size} bytes)")
+        logger.info("Successfully downloaded %s (%s bytes)", remote_filename, response.size)
         return local_path
 
     def list_files(self) -> list[FileInfo]:
@@ -432,10 +432,10 @@ def delete_file(self, remote_filename: str) -> FileDeleteResponse:
             print(f"Deleted: {result.filename}")
             ```
         """
-        logger.info(f"Deleting file {remote_filename}")
+        logger.info("Deleting file %s", remote_filename)
         result = self._call_with_auth("delete_file", remote_filename)
         response = FileDeleteResponse(**result)
-        logger.info(f"Successfully deleted {remote_filename}")
+        logger.info("Successfully deleted %s", remote_filename)
         return response
 
     def delete_all_files(self) -> FileBulkDeleteResponse:
@@ -454,7 +454,7 @@ def delete_all_files(self) -> FileBulkDeleteResponse:
         logger.info("Deleting all files from server")
         result = self._call_with_auth("delete_all_files")
         response = FileBulkDeleteResponse(**result)
-        logger.info(f"Successfully deleted {response.deleted_count} files")
+        logger.info("Successfully deleted %s files", response.deleted_count)
         return response
 
     def ping(self) -> bool:
@@ -477,7 +477,7 @@ def ping(self) -> bool:
             self.list_jobs()
             return True
         except (RuntimeError, ConnectionError, ValueError) as e:
-            logger.warning(f"Server ping failed: {e}")
+            logger.warning("Server ping failed: %s", e)
             return False
 
     def __enter__(self):

src/clabe/xml_rpc/_executor.py

@@ -81,7 +81,7 @@ def __init__(
         self.poll_interval = poll_interval
         self.monitor = monitor
 
-        logger.info(f"RPC executor initialized for server: {client.settings.server_url}")
+        logger.info("RPC executor initialized for server: %s", client.settings.server_url)
 
     def run(self, command: Command[Any]) -> CommandResult:
         """
@@ -105,13 +105,13 @@ def run(self, command: Command[Any]) -> CommandResult:
             print(f"Output: {result.stdout}")
             ```
         """
-        logger.info(f"Executing command via RPC: {command.cmd}")
+        logger.info("Executing command via RPC: %s", command.cmd)
 
         job_result = self.client.run_command(command.cmd, timeout=self.timeout)
 
         result = CommandResult(stdout=job_result.stdout, stderr=job_result.stderr, exit_code=job_result.returncode or 0)
         result.check_returncode()
-        logger.info(f"RPC command completed with exit code: {result.exit_code}")
+        logger.info("RPC command completed with exit code: %s", result.exit_code)
         return result
 
     async def run_async(self, command: Command[Any]) -> CommandResult:
@@ -136,7 +136,7 @@ async def run_async(self, command: Command[Any]) -> CommandResult:
             print(f"Output: {result.stdout}")
             ```
         """
-        logger.info(f"Executing command asynchronously via RPC: {command.cmd}")
+        logger.info("Executing command asynchronously via RPC: %s", command.cmd)
         submission = self.client.submit_command(command.cmd)
         if submission.job_id is None:
             raise RuntimeError("Job submission failed: no job ID returned")
@@ -146,7 +146,7 @@ async def run_async(self, command: Command[Any]) -> CommandResult:
         result = CommandResult(stdout=job_result.stdout, stderr=job_result.stderr, exit_code=job_result.returncode or 0)
         result.check_returncode()
 
-        logger.info(f"RPC async command completed with exit code: {result.exit_code}")
+        logger.info("RPC async command completed with exit code: %s", result.exit_code)
         return result
 
     async def _wait_for_result_async(self, job_id: str):

tests/assets/experiment_import_mocks.py

@@ -3,7 +3,7 @@
 
 @experiment(name="first_experiment")
 def first_experiment(launcher: Launcher) -> None:  # pragma: no cover - behavior not important
-    launcher.logger.info(f"running first_experiment with mock_constant={mock_constant}")
+    launcher.logger.info("running first_experiment with mock_constant=%s", mock_constant)
 
 
 @experiment(name="second_experiment")