refactor: reduce log noise, improve event naming and console readability

Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
This commit is contained in:
Justin Visser 2026-02-26 22:05:18 +01:00
parent db0ac6a228
commit fa56168fb1
8 changed files with 24 additions and 44 deletions

View file

@ -232,7 +232,7 @@ async def requeue_pdf_lookup(
message="Publication not found.", message="Publication not found.",
) )
status, message = _requeue_response_state(queued=result.queued) status, message = _requeue_response_state(queued=result.queued)
structured_log(logger, "info", "api.admin.db.pdf_queue_requeue_requested", admin_user_id=int(admin_user.id), publication_id=int(publication_id), queued=bool(result.queued)) structured_log(logger, "info", "api.admin.db.pdf_requeued", admin_user_id=int(admin_user.id), publication_id=int(publication_id), queued=bool(result.queued))
return success_payload( return success_payload(
request, request,
data={ data={
@ -340,7 +340,7 @@ async def trigger_publication_near_duplicate_repair(
code="invalid_near_duplicate_repair_request", code="invalid_near_duplicate_repair_request",
message=str(exc), message=str(exc),
) from exc ) from exc
structured_log(logger, "info", "api.admin.db.publication_near_duplicate_repair_triggered", admin_user_id=int(admin_user.id), dry_run=bool(payload.dry_run), selected_cluster_count=len(payload.selected_cluster_keys), job_id=int(result["job_id"]), status=result["status"]) structured_log(logger, "info", "api.admin.db.dedup_repair_triggered", admin_user_id=int(admin_user.id), dry_run=bool(payload.dry_run), selected_cluster_count=len(payload.selected_cluster_keys), job_id=int(result["job_id"]), status=result["status"])
return success_payload(request, data=result) return success_payload(request, data=result)

View file

@ -575,7 +575,7 @@ async def clear_scholar_image_customization(
profile=profile, profile=profile,
upload_dir=settings.scholar_image_upload_dir, upload_dir=settings.scholar_image_upload_dir,
) )
structured_log(logger, "info", "api.scholars.image_customization_cleared", user_id=current_user.id, scholar_profile_id=updated.id) structured_log(logger, "info", "api.scholars.image_cleared", user_id=current_user.id, scholar_profile_id=updated.id)
return success_payload( return success_payload(
request, request,
data=_serialize_scholar(updated), data=_serialize_scholar(updated),

View file

@ -108,6 +108,14 @@ class JsonLogFormatter(logging.Formatter):
return value return value
_CONSOLE_SHORT_KEYS = {
"user_id": "user",
"scholar_id": "scholar",
"crawl_run_id": "run",
"run_id": "run",
}
class ConsoleLogFormatter(logging.Formatter): class ConsoleLogFormatter(logging.Formatter):
def __init__(self, *, redact_fields: set[str]) -> None: def __init__(self, *, redact_fields: set[str]) -> None:
super().__init__() super().__init__()
@ -140,7 +148,8 @@ class ConsoleLogFormatter(logging.Formatter):
for key in sorted(payload.keys()): for key in sorted(payload.keys()):
if key in {"timestamp", "level", "logger", "event", "exception"}: if key in {"timestamp", "level", "logger", "event", "exception"}:
continue continue
parts.append(f"{key}={payload[key]}") display_key = _CONSOLE_SHORT_KEYS.get(key, key)
parts.append(f"{display_key}={payload[key]}")
if "exception" in payload: if "exception" in payload:
parts.append(f"exception={payload['exception']}") parts.append(f"exception={payload['exception']}")

View file

@ -153,7 +153,7 @@ class ScholarIngestionService:
await db_session.commit() await db_session.commit()
await db_session.refresh(user_settings) await db_session.refresh(user_settings)
structured_log( structured_log(
logger, "info", "ingestion.safety_cooldown_cleared", logger, "info", "ingestion.cooldown_cleared",
user_id=user_id, user_id=user_id,
reason=previous.get("cooldown_reason"), reason=previous.get("cooldown_reason"),
cooldown_until=previous.get("cooldown_until"), cooldown_until=previous.get("cooldown_until"),
@ -962,7 +962,7 @@ class ScholarIngestionService:
) )
elif pre_apply_state.get("cooldown_active") and not safety_state.get("cooldown_active"): elif pre_apply_state.get("cooldown_active") and not safety_state.get("cooldown_active"):
structured_log( structured_log(
logger, "info", "ingestion.safety_cooldown_cleared", logger, "info", "ingestion.cooldown_cleared",
user_id=user_id, user_id=user_id,
crawl_run_id=int(run.id), crawl_run_id=int(run.id),
reason=pre_apply_state.get("cooldown_reason"), reason=pre_apply_state.get("cooldown_reason"),
@ -1319,7 +1319,7 @@ class ScholarIngestionService:
effective_delay = self._effective_request_delay_seconds(request_delay_seconds) effective_delay = self._effective_request_delay_seconds(request_delay_seconds)
if effective_delay != _int_or_default(request_delay_seconds, effective_delay): if effective_delay != _int_or_default(request_delay_seconds, effective_delay):
structured_log( structured_log(
logger, "warning", "ingestion.request_delay_coerced_to_policy_floor", logger, "warning", "ingestion.delay_coerced",
user_id=user_id, user_id=user_id,
requested_request_delay_seconds=_int_or_default(request_delay_seconds, 0), requested_request_delay_seconds=_int_or_default(request_delay_seconds, 0),
effective_request_delay_seconds=effective_delay, effective_request_delay_seconds=effective_delay,
@ -2596,13 +2596,6 @@ class ScholarIngestionService:
db_session.add(link) db_session.add(link)
discovered_count += 1 discovered_count += 1
structured_log(
logger, "debug", "ingestion.publication_discovered",
scholar_profile_id=scholar.id,
publication_id=publication.id,
crawl_run_id=run.id,
)
await self._commit_discovered_publication( await self._commit_discovered_publication(
db_session, db_session,
run=run, run=run,
@ -2720,11 +2713,6 @@ class ScholarIngestionService:
) )
db_session.add(publication) db_session.add(publication)
await db_session.flush() await db_session.flush()
structured_log(
logger, "debug", "ingestion.publication_created",
publication_id=publication.id,
cluster_id=publication.cluster_id,
)
return publication return publication
@staticmethod @staticmethod

View file

@ -514,9 +514,9 @@ async def _run_resolution_task(
) )
if arxiv_rate_limited and arxiv_lookup_allowed: if arxiv_rate_limited and arxiv_lookup_allowed:
arxiv_lookup_allowed = False arxiv_lookup_allowed = False
structured_log(logger, "warning", "publications.pdf_queue.arxiv_batch_disabled", detail="arXiv temporarily disabled for remaining batch after rate limit") structured_log(logger, "warning", "pdf_queue.arxiv_batch_disabled", detail="arXiv temporarily disabled for remaining batch after rate limit")
except OpenAlexBudgetExhaustedError: except OpenAlexBudgetExhaustedError:
structured_log(logger, "warning", "publications.pdf_queue.budget_exhausted", detail="Stopping PDF resolution batch — OpenAlex daily budget exhausted") structured_log(logger, "warning", "pdf_queue.budget_exhausted", detail="Stopping PDF resolution batch — OpenAlex daily budget exhausted")
break break

View file

@ -45,7 +45,7 @@ async def resolve_publication_pdf_outcome_for_row(
except ArxivRateLimitError: except ArxivRateLimitError:
arxiv_rate_limited = True arxiv_rate_limited = True
arxiv_outcome = None arxiv_outcome = None
structured_log(logger, "warning", "publications.pdf_resolution.arxiv_rate_limited", publication_id=int(row.publication_id)) structured_log(logger, "warning", "pdf_resolution.arxiv_rate_limited", publication_id=int(row.publication_id))
if arxiv_outcome and arxiv_outcome.pdf_url: if arxiv_outcome and arxiv_outcome.pdf_url:
return PipelineOutcome(arxiv_outcome, None, arxiv_rate_limited=arxiv_rate_limited) return PipelineOutcome(arxiv_outcome, None, arxiv_rate_limited=arxiv_rate_limited)
@ -94,7 +94,7 @@ async def _openalex_outcome(
# Re-raise so the caller's batch loop can stop hitting the API. # Re-raise so the caller's batch loop can stop hitting the API.
raise raise
except Exception as exc: except Exception as exc:
structured_log(logger, "warning", "publications.pdf_resolution.openalex_failed", error=str(exc)) structured_log(logger, "warning", "pdf_resolution.openalex_failed", error=str(exc))
return None return None
@ -107,12 +107,12 @@ async def _arxiv_outcome(
from app.services.domains.arxiv.application import discover_arxiv_id_for_publication from app.services.domains.arxiv.application import discover_arxiv_id_for_publication
if not allow_lookup: if not allow_lookup:
structured_log(logger, "info", "publications.pdf_resolution.arxiv_skipped", publication_id=int(row.publication_id), skip_reason="batch_arxiv_cooldown_active") structured_log(logger, "info", "pdf_resolution.arxiv_skipped", publication_id=int(row.publication_id), skip_reason="batch_arxiv_cooldown_active")
return None return None
skip_reason = arxiv_skip_reason_for_item(item=row) skip_reason = arxiv_skip_reason_for_item(item=row)
if skip_reason is not None: if skip_reason is not None:
structured_log(logger, "info", "publications.pdf_resolution.arxiv_skipped", publication_id=int(row.publication_id), skip_reason=skip_reason) structured_log(logger, "info", "pdf_resolution.arxiv_skipped", publication_id=int(row.publication_id), skip_reason=skip_reason)
return None return None
try: try:
@ -130,7 +130,7 @@ async def _arxiv_outcome(
except ArxivRateLimitError: except ArxivRateLimitError:
raise # propagate so orchestration can switch to non-arXiv fallback raise # propagate so orchestration can switch to non-arXiv fallback
except Exception as exc: except Exception as exc:
structured_log(logger, "warning", "publications.pdf_resolution.arxiv_failed", error=str(exc)) structured_log(logger, "warning", "pdf_resolution.arxiv_failed", error=str(exc))
return None return None

View file

@ -101,13 +101,6 @@ class LiveScholarSource:
cstart=cstart, cstart=cstart,
pagesize=pagesize, pagesize=pagesize,
) )
structured_log(
logger, "debug", "scholar_source.fetch_started",
scholar_id=scholar_id,
requested_url=requested_url,
cstart=cstart,
pagesize=pagesize,
)
return await self._fetch_with_global_throttle(requested_url) return await self._fetch_with_global_throttle(requested_url)
async def fetch_author_search_html( async def fetch_author_search_html(
@ -120,19 +113,9 @@ class LiveScholarSource:
query=query, query=query,
start=start, start=start,
) )
structured_log(
logger, "debug", "scholar_source.search_fetch_started",
query=query,
requested_url=requested_url,
start=start,
)
return await self._fetch_with_global_throttle(requested_url) return await self._fetch_with_global_throttle(requested_url)
async def fetch_publication_html(self, publication_url: str) -> FetchResult: async def fetch_publication_html(self, publication_url: str) -> FetchResult:
structured_log(
logger, "debug", "scholar_source.publication_fetch_started",
requested_url=publication_url,
)
return await self._fetch_with_global_throttle(publication_url) return await self._fetch_with_global_throttle(publication_url)
async def _fetch_with_global_throttle(self, requested_url: str) -> FetchResult: async def _fetch_with_global_throttle(self, requested_url: str) -> FetchResult:

View file

@ -82,7 +82,7 @@ def test_structured_log_console_formatter(caplog) -> None:
output = formatter.format(record) output = formatter.format(record)
assert "export.failed" in output assert "export.failed" in output
assert "scholar_id=7" in output assert "scholar=7" in output
def test_structured_log_strips_metric_fields(caplog) -> None: def test_structured_log_strips_metric_fields(caplog) -> None: