Refactor logging statements to use f-strings for improved readability and consistency across the codebase. This change enhances the clarity of log messages by directly embedding variable values, making it easier to trace and debug application behavior.

python/ebook_search/search.py

@@ -106,12 +106,7 @@ async def search_ebooks(
         return SearchResponse(query=query, results=[], rank_label="Hybrid")
 
     phrase_matching_enabled = config.phrase_matching_enabled if phrase_matching is None else phrase_matching
-    logger.info(
-        "ebook_search_start query_length=%s rerank=%s phrase_matching=%s",
-        len(query),
-        rerank,
-        phrase_matching_enabled,
-    )
+    logger.info(f"ebook_search_start query_length={len(query)} {rerank=} {phrase_matching_enabled=}")
     timings: list[RuntimeStep] = []
     if phrase_matching_enabled:
         phrase_matches, timing = await async_timed_result(
@@ -149,16 +144,10 @@ async def search_ebooks(
     timings.append(timing)
     response = replace(response, timings=tuple(timings), phrase_matches=tuple(phrase_matches))
     logger.info(
-        "ebook_search_complete vector_candidates=%s lexical_candidates=%s "
-        "fused_candidates=%s phrase_matching=%s phrase_matches=%s returned=%s rank_label=%s runtime_ms=%.1f",
-        len(retrieval.vector_results),
-        len(retrieval.lexical_results),
-        len(fused),
-        phrase_matching_enabled,
-        len(phrase_matches),
-        len(response.results),
-        response.rank_label,
-        response.total_runtime_ms,
+        f"ebook_search_complete vector_candidates={len(retrieval.vector_results)} "
+        f"lexical_candidates={len(retrieval.lexical_results)} fused_candidates={len(fused)} {phrase_matching_enabled=} "
+        f"phrase_matches={len(phrase_matches)} returned={len(response.results)} {response.rank_label=} "
+        f"{response.total_runtime_ms=:.1f}"
     )
     return response
 
@@ -179,13 +168,13 @@ async def query_phrase_matches(
         async with AsyncSession(engine) as session:
             return await detect_protected_phrases_for_query(session, query, config)
     except SQLAlchemyError as error:
-        logger.warning("ebook_protected_phrase_detection_unavailable error=%s", error)
+        logger.warning(f"ebook_protected_phrase_detection_unavailable {error=}")
         return []
 
 
 def skip_phrase_mention_boosts(candidates: list[SearchResult]) -> list[SearchResult]:
     """Return candidates unchanged when phrase matching is disabled."""
-    logger.info("ebook_phrase_boost_skipped candidates=%s", len(candidates))
+    logger.info(f"ebook_phrase_boost_skipped candidates={len(candidates)}")
     return candidates
 
 
@@ -205,7 +194,7 @@ async def apply_phrase_mention_boosts(
         async with AsyncSession(engine) as session:
             phrase_hits = await phrase_hits_for_chunks(session, chunk_ids=chunk_ids, phrase_ids=phrase_ids)
     except SQLAlchemyError as error:
-        logger.warning("ebook_phrase_boost_unavailable error=%s", error)
+        logger.warning(f"ebook_phrase_boost_unavailable {error=}")
         return candidates
 
     if not phrase_hits:
@@ -259,9 +248,8 @@ async def parallel_retrieval(
     )
 
     logger.info(
-        "ebook_parallel_retrieval_complete vector_candidates=%s lexical_candidates=%s",
-        len(vector_results),
-        len(lexical_results),
+        f"ebook_parallel_retrieval_complete vector_candidates={len(vector_results)} "
+        f"lexical_candidates={len(lexical_results)}"
     )
     return RetrievalResponse(
         vector_results=vector_results,
@@ -279,7 +267,7 @@ def skip_rerank(
     config: EbookSearchConfig,
 ) -> SearchResponse:
     """Return fused hybrid results without reranking."""
-    logger.info("ebook_rerank_skipped candidates=%s", len(candidates))
+    logger.info(f"ebook_rerank_skipped candidates={len(candidates)}")
     return SearchResponse(query=query, results=candidates[: config.top_k], rank_label="Hybrid")
 
 
@@ -292,9 +280,8 @@ async def apply_rerank(
     """Rerank already-fused hybrid candidates."""
     reranked = await rerank_chunks(client, query, candidates[: config.rerank.candidates], config.rerank)
     logger.info(
-        "ebook_rerank_complete input_candidates=%s returned=%s",
-        min(len(candidates), config.rerank.candidates),
-        len(reranked),
+        f"ebook_rerank_complete input_candidates={min(len(candidates), config.rerank.candidates)} "
+        f"returned={len(reranked)}"
     )
     return SearchResponse(
         query=query,
@@ -352,10 +339,7 @@ async def vector_candidates(
         rows = (await session.execute(statement)).mappings()
         results = [search_result_from_row(row) for row in rows]
         logger.info(
-            "ebook_vector_search_complete model=%s dimension=%s candidates=%s",
-            config.embedding_model,
-            model.dimension,
-            len(results),
+            f"ebook_vector_search_complete {config.embedding_model=} {model.dimension=} candidates={len(results)}"
         )
         return results
 
@@ -365,7 +349,7 @@ def bm25_candidates(query: str, config: EbookSearchConfig) -> list[SearchResult]
     try:
         corpus = load_bm25_corpus(config)
     except BM25CorpusUnavailableError as error:
-        logger.warning("ebook_bm25_index_unavailable_skipping error=%s", error)
+        logger.warning(f"ebook_bm25_index_unavailable_skipping {error=}")
         return []
 
     if not corpus.records:
@@ -380,12 +364,7 @@ def bm25_candidates(query: str, config: EbookSearchConfig) -> list[SearchResult]
     ]
 
     max_score = results[0].bm25_score if results else 0.0
-    logger.info(
-        "ebook_bm25_search_complete corpus=%s candidates=%s max_score=%.6f",
-        len(corpus.records),
-        len(results),
-        max_score,
-    )
+    logger.info(f"ebook_bm25_search_complete corpus={len(corpus.records)} candidates={len(results)} {max_score=:.6f}")
     return results