justinzeus/scholarr
1
0
Fork 0
Code Issues 1 Pull requests 18 Projects Releases Packages Wiki Activity Actions

after audit

Browse source
This commit is contained in:
Justin Visser 2026-03-01 18:14:22 +01:00
parent e8e20637e6
commit a5165dc3ba
80 changed files with 8489 additions and 7302 deletions
Download patch file Download diff file Expand all files Collapse all files

18
app/api/routers/run_manual.py
View file

@ -138,9 +138,11 @@ async def recover_integrity_error(
original_exc: IntegrityError,
) -> dict[str, Any]:
if idempotency_key is None:
logger.exception(
structured_log(
logger,
"exception",
"api.runs.manual_integrity_error",
extra={"user_id": user_id},
user_id=user_id,
)
raise ApiException(status_code=500, code="manual_run_failed", message="Manual run failed.") from original_exc
existing_run = await run_service.get_manual_run_by_idempotency_key(
@ -149,9 +151,11 @@ async def recover_integrity_error(
idempotency_key=idempotency_key,
)
if existing_run is None:
logger.exception(
structured_log(
logger,
"exception",
"api.runs.manual_integrity_error",
extra={"user_id": user_id},
user_id=user_id,
)
raise ApiException(status_code=500, code="manual_run_failed", message="Manual run failed.") from original_exc
if existing_run.status in (RunStatus.RUNNING, RunStatus.RESOLVING):
@ -230,8 +234,10 @@ def raise_manual_blocked_safety(*, exc, user_id: int) -> None:
def raise_manual_failed(*, exc: Exception, user_id: int) -> None:
logger.exception(
structured_log(
logger,
"exception",
"api.runs.manual_failed",
extra={"user_id": user_id},
user_id=user_id,
)
raise ApiException(status_code=500, code="manual_run_failed", message="Manual run failed.") from exc

41
app/api/routers/runs.py
View file

@ -37,7 +37,8 @@ from app.api.schemas import (
RunsListEnvelope,
)
from app.db.models import RunStatus, RunTriggerType, User
from app.db.session import get_db_session
from app.db.session import get_db_session, get_session_factory
from app.logging_utils import structured_log
from app.services.ingestion import application as ingestion_service
from app.services.runs import application as run_service
from app.services.runs.events import event_generator
@ -47,6 +48,14 @@ from app.settings import settings
logger = logging.getLogger(__name__)
_background_tasks: set[asyncio.Task[Any]] = set()
def _drop_finished_task(task: asyncio.Task[Any]) -> None:
_background_tasks.discard(task)
try:
task.result()
except Exception:
structured_log(logger, "exception", "runs.background_task_failed")
router = APIRouter(prefix="/runs", tags=["api-runs"])
ACTIVE_RUN_STATUSES = {RunStatus.RUNNING, RunStatus.RESOLVING}
@ -234,7 +243,7 @@ def _spawn_background_execution(
)
)
_background_tasks.add(task)
task.add_done_callback(_background_tasks.discard)
task.add_done_callback(_drop_finished_task)
@router.post(
@ -247,15 +256,16 @@ async def run_manual(
current_user: User = Depends(get_api_current_user),
ingest_service: ingestion_service.ScholarIngestionService = Depends(get_ingestion_service),
):
safety_state = await load_safety_state(db_session, user_id=current_user.id)
user_id = int(current_user.id)
safety_state = await load_safety_state(db_session, user_id=user_id)
if not settings.ingestion_manual_run_allowed:
raise_manual_runs_disabled(user_id=current_user.id, safety_state=safety_state)
raise_manual_runs_disabled(user_id=user_id, safety_state=safety_state)
idempotency_key = normalize_idempotency_key(request.headers.get(IDEMPOTENCY_HEADER))
reused_payload = await reused_manual_run_payload(
db_session,
request=request,
user_id=current_user.id,
user_id=user_id,
idempotency_key=idempotency_key,
safety_state=safety_state,
)
@ -291,12 +301,12 @@ async def run_manual(
"new_publication_count": 0,
"reused_existing_run": False,
"idempotency_key": idempotency_key,
"safety_state": await load_safety_state(db_session, user_id=current_user.id),
"safety_state": await load_safety_state(db_session, user_id=user_id),
},
)
except ingestion_service.RunBlockedBySafetyPolicyError as exc:
await db_session.rollback()
raise_manual_blocked_safety(exc=exc, user_id=current_user.id)
raise_manual_blocked_safety(exc=exc, user_id=user_id)
except ingestion_service.RunAlreadyInProgressError as exc:
await db_session.rollback()
raise ApiException(
@ -309,13 +319,13 @@ async def run_manual(
return await recover_integrity_error(
db_session,
request=request,
user_id=current_user.id,
user_id=user_id,
idempotency_key=idempotency_key,
original_exc=exc,
)
except Exception as exc:
await db_session.rollback()
raise_manual_failed(exc=exc, user_id=current_user.id)
raise_manual_failed(exc=exc, user_id=user_id)
@router.get(
@ -454,14 +464,15 @@ async def clear_queue_item(
@router.get("/{run_id}/stream")
async def stream_run_events(
run_id: int,
db_session: AsyncSession = Depends(get_db_session),
current_user: User = Depends(get_api_current_user),
):
run = await run_service.get_run_for_user(
db_session,
user_id=current_user.id,
run_id=run_id,
)
session_factory = get_session_factory()
async with session_factory() as db_session:
run = await run_service.get_run_for_user(
db_session,
user_id=current_user.id,
run_id=run_id,
)
if run is None:
raise ApiException(
status_code=404,

6
app/api/schemas/admin.py
View file

@ -34,8 +34,8 @@ class AdminUsersListEnvelope(BaseModel):
class AdminUserCreateRequest(BaseModel):
email: str
password: str
email: str = Field(max_length=254)
password: str = Field(max_length=128)
is_admin: bool = False
model_config = ConfigDict(extra="forbid")
@ -55,7 +55,7 @@ class AdminUserEnvelope(BaseModel):
class AdminResetPasswordRequest(BaseModel):
new_password: str
new_password: str = Field(max_length=128)
model_config = ConfigDict(extra="forbid")

12
app/api/schemas/auth.py
View file

@ -1,6 +1,6 @@
from __future__ import annotations
from pydantic import BaseModel, ConfigDict
from pydantic import BaseModel, ConfigDict, Field
from app.api.schemas.common import ApiMeta
@ -44,8 +44,8 @@ class CsrfBootstrapEnvelope(BaseModel):
class LoginRequest(BaseModel):
email: str
password: str
email: str = Field(max_length=254)
password: str = Field(max_length=128)
model_config = ConfigDict(extra="forbid")
@ -66,8 +66,8 @@ class LoginEnvelope(BaseModel):
class ChangePasswordRequest(BaseModel):
current_password: str
new_password: str
confirm_password: str
current_password: str = Field(max_length=128)
new_password: str = Field(max_length=128)
confirm_password: str = Field(max_length=128)
model_config = ConfigDict(extra="forbid")

2
app/db/session.py
View file

@ -85,7 +85,7 @@ async def check_database() -> bool:
result = await conn.execute(text("SELECT 1"))
return result.scalar_one() == 1
except Exception:
logger.exception("db.healthcheck_failed")
structured_log(logger, "exception", "db.healthcheck_failed")
return False

12
app/http/middleware.py
View file

@ -74,13 +74,13 @@ class RequestLoggingMiddleware(BaseHTTPMiddleware):
response = await call_next(request)
except Exception:
duration_ms = int((time.perf_counter() - start) * 1000)
logger.exception(
structured_log(
logger,
"exception",
"request.failed",
extra={
"method": request.method,
"path": request.url.path,
"duration_ms": duration_ms,
},
method=request.method,
path=request.url.path,
duration_ms=duration_ms,
)
raise
else:

9
app/main.py
View file

@ -73,8 +73,13 @@ async def lifespan(_: FastAPI):
)
await session.commit()
structured_log(logger, "info", "app.startup_orphaned_runs_cleaned")
except Exception as e:
logger.error(f"Failed to clean orphaned runs at startup: {e}")
except Exception as exc:
structured_log(
logger,
"error",
"app.startup_orphaned_runs_cleanup_failed",
error=str(exc),
)
await scheduler_service.start()
yield

26
app/security/csrf.py
View file

@ -6,9 +6,10 @@ from urllib.parse import parse_qs
from starlette.middleware.base import BaseHTTPMiddleware
from starlette.requests import Request
from starlette.responses import JSONResponse, PlainTextResponse, Response
from starlette.responses import PlainTextResponse, Response
from starlette.types import Message
from app.api.responses import error_response
from app.logging_utils import structured_log
CSRF_SESSION_KEY = "csrf_token"
@ -88,7 +89,10 @@ class CSRFMiddleware(BaseHTTPMiddleware):
content_type = request.headers.get("content-type", "")
if not content_type.startswith("application/x-www-form-urlencoded"):
return None
parsed = parse_qs(body.decode("utf-8"), keep_blank_values=True)
try:
parsed = parse_qs(body.decode("utf-8"), keep_blank_values=True)
except (UnicodeDecodeError, ValueError):
return None
values = parsed.get(CSRF_FORM_FIELD)
if not values:
return None
@ -114,19 +118,11 @@ class CSRFMiddleware(BaseHTTPMiddleware):
message: str,
) -> Response:
if request.url.path.startswith("/api/"):
request_state = getattr(request, "state", None)
request_id = getattr(request_state, "request_id", None) if request_state else None
return JSONResponse(
{
"error": {
"code": code,
"message": message,
"details": None,
},
"meta": {
"request_id": request_id,
},
},
return error_response(
request,
status_code=403,
code=code,
message=message,
details=None,
)
return PlainTextResponse(message, status_code=403)

35
app/services/arxiv/rate_limit.py
View file

@ -75,24 +75,31 @@ async def _run_serialized_fetch(
runtime_state,
source_path=source_path,
)
response = await fetch()
runtime_state.next_allowed_at = datetime.now(UTC) + timedelta(seconds=_min_interval_seconds())
if wait_seconds > 0:
await asyncio.sleep(wait_seconds)
response = await fetch()
async with session_factory() as db_session, db_session.begin():
runtime_state = await _load_runtime_state_for_update(db_session)
hit_rate_limit = _record_post_response_state(
runtime_state,
response_status=int(response.status_code),
source_path=source_path,
)
structured_log(
logger,
"info",
"arxiv.request_completed",
status_code=int(response.status_code),
wait_seconds=wait_seconds,
cooldown_remaining_seconds=_cooldown_remaining_seconds(
runtime_state.cooldown_until, now_utc=datetime.now(UTC)
),
source_path=source_path,
)
return response, hit_rate_limit
structured_log(
logger,
"info",
"arxiv.request_completed",
status_code=int(response.status_code),
wait_seconds=wait_seconds,
cooldown_remaining_seconds=_cooldown_remaining_seconds(
runtime_state.cooldown_until, now_utc=datetime.now(UTC)
),
source_path=source_path,
)
return response, hit_rate_limit
async def _acquire_arxiv_lock(db_session: AsyncSession) -> None:
@ -144,8 +151,6 @@ async def _wait_for_allowed_slot_or_raise(
source_path=source_path,
cooldown_remaining_seconds=0.0,
)
if wait_seconds > 0:
await asyncio.sleep(wait_seconds)
return wait_seconds

3
app/services/crossref/application.py
View file

@ -350,7 +350,8 @@ async def _fetch_items(
),
timeout=timeout,
)
except Exception:
except Exception as exc:
structured_log(logger, "warning", "crossref.fetch_failed", error=str(exc))
return []

10
app/services/dbops/near_duplicate_repair.py
View file

@ -6,12 +6,14 @@ from typing import Any
from sqlalchemy.ext.asyncio import AsyncSession
from app.db.models import DataRepairJob
from app.services.dbops.application import (
REPAIR_STATUS_COMPLETED,
REPAIR_STATUS_FAILED,
REPAIR_STATUS_PLANNED,
REPAIR_STATUS_RUNNING,
)
from app.services.publications import dedup as dedup_service
REPAIR_STATUS_PLANNED = "planned"
REPAIR_STATUS_RUNNING = "running"
REPAIR_STATUS_COMPLETED = "completed"
REPAIR_STATUS_FAILED = "failed"
NEAR_DUP_JOB_NAME = "repair_publication_near_duplicates"
NEAR_DUP_DEFAULT_MAX_CLUSTERS = 25

277
app/services/ingestion/application.py
View file

@ -1,6 +1,5 @@
from __future__ import annotations
import asyncio
import logging
from datetime import UTC, datetime
from typing import Any
@ -17,21 +16,28 @@ from app.db.models import (
)
from app.logging_utils import structured_log
from app.services.ingestion import queue as queue_service
from app.services.ingestion import safety as run_safety_service
from app.services.ingestion.constants import RUN_LOCK_NAMESPACE
from app.services.ingestion.enrichment import EnrichmentRunner
from app.services.ingestion.pagination import PaginationEngine
from app.services.ingestion.preflight import check_scholar_reachable
from app.services.ingestion.run_completion import (
complete_run_for_user,
int_or_default,
log_run_completed,
run_execution_summary,
)
from app.services.ingestion.run_enrichment import (
inline_enrich_and_finalize,
spawn_background_enrichment_task,
)
from app.services.ingestion.run_guards import (
load_user_settings_for_run,
run_preflight_guard,
)
from app.services.ingestion.scholar_processing import run_scholar_iteration
from app.services.ingestion.types import (
RunAlertSummary,
RunAlreadyInProgressError,
RunBlockedBySafetyPolicyError,
RunBlockedBySafetyPolicyError, # noqa: F401 (re-exported)
RunFailureSummary,
RunProgress,
)
@ -42,8 +48,6 @@ from app.settings import settings
logger = logging.getLogger(__name__)
ACTIVE_RUN_INDEX_NAME = "uq_crawl_runs_user_active"
_background_tasks: set[asyncio.Task[Any]] = set()
def _is_active_run_integrity_error(exc: IntegrityError) -> bool:
original_error = getattr(exc, "orig", None)
@ -97,34 +101,6 @@ def _threshold_kwargs(
}
def _log_run_completed(
*,
run: CrawlRun,
user_id: int,
scholars: list[ScholarProfile],
progress: RunProgress,
failure_summary: RunFailureSummary,
alert_summary: RunAlertSummary,
) -> None:
structured_log(
logger,
"info",
"ingestion.run_completed",
user_id=user_id,
crawl_run_id=run.id,
status=run.status.value,
scholar_count=len(scholars),
succeeded_count=progress.succeeded_count,
failed_count=progress.failed_count,
partial_count=progress.partial_count,
new_publication_count=run.new_pub_count,
blocked_failure_count=alert_summary.blocked_failure_count,
network_failure_count=alert_summary.network_failure_count,
retries_scheduled_count=failure_summary.retries_scheduled_count,
alert_flags=alert_summary.alert_flags,
)
class ScholarIngestionService:
def __init__(self, *, source: ScholarSource) -> None:
self._source = source
@ -138,78 +114,6 @@ class ScholarIngestionService:
)
return max(policy_minimum, int_or_default(value, policy_minimum))
async def _load_user_settings_for_run(
self,
db_session: AsyncSession,
*,
user_id: int,
trigger_type: RunTriggerType,
):
user_settings = await user_settings_service.get_or_create_settings(db_session, user_id=user_id)
await self._enforce_safety_gate(
db_session, user_settings=user_settings, user_id=user_id, trigger_type=trigger_type
)
return user_settings
async def _enforce_safety_gate(
self,
db_session: AsyncSession,
*,
user_settings,
user_id: int,
trigger_type: RunTriggerType,
) -> None:
now_utc = datetime.now(UTC)
previous = run_safety_service.get_safety_event_context(user_settings, now_utc=now_utc)
if run_safety_service.clear_expired_cooldown(user_settings, now_utc=now_utc):
await db_session.commit()
await db_session.refresh(user_settings)
structured_log(
logger,
"info",
"ingestion.cooldown_cleared",
user_id=user_id,
reason=previous.get("cooldown_reason"),
cooldown_until=previous.get("cooldown_until"),
)
now_utc = datetime.now(UTC)
if run_safety_service.is_cooldown_active(user_settings, now_utc=now_utc):
await self._raise_safety_blocked_start(
db_session,
user_settings=user_settings,
user_id=user_id,
trigger_type=trigger_type,
now_utc=now_utc,
)
async def _raise_safety_blocked_start(
self,
db_session: AsyncSession,
*,
user_settings,
user_id: int,
trigger_type: RunTriggerType,
now_utc: datetime,
) -> None:
safety_state = run_safety_service.register_cooldown_blocked_start(user_settings, now_utc=now_utc)
await db_session.commit()
structured_log(
logger,
"warning",
"ingestion.safety_policy_blocked_run_start",
user_id=user_id,
trigger_type=trigger_type.value,
reason=safety_state.get("cooldown_reason"),
cooldown_until=safety_state.get("cooldown_until"),
cooldown_remaining_seconds=safety_state.get("cooldown_remaining_seconds"),
blocked_start_count=((safety_state.get("counters") or {}).get("blocked_start_count")),
)
raise RunBlockedBySafetyPolicyError(
code="scrape_cooldown_active",
message="Scrape safety cooldown is active; run start is temporarily blocked.",
safety_state=safety_state,
)
async def _load_target_scholars(
self,
db_session: AsyncSession,
@ -232,49 +136,6 @@ class ScholarIngestionService:
await queue_service.clear_job_for_scholar(db_session, user_id=user_id, scholar_profile_id=sid)
return scholars
async def _run_preflight_guard(
self,
db_session: AsyncSession,
*,
user_settings: Any,
user_id: int,
scholars: list[ScholarProfile],
) -> None:
if not scholars:
return
result = await check_scholar_reachable(
self._source,
scholar_id=scholars[0].scholar_id,
)
if result.passed:
return
now_utc = datetime.now(UTC)
safety_state, _ = run_safety_service.apply_run_safety_outcome(
user_settings,
run_id=0,
blocked_failure_count=1,
network_failure_count=0,
blocked_failure_threshold=1,
network_failure_threshold=1,
blocked_cooldown_seconds=settings.ingestion_safety_cooldown_blocked_seconds,
network_cooldown_seconds=settings.ingestion_safety_cooldown_network_seconds,
now_utc=now_utc,
)
await db_session.commit()
structured_log(
logger,
"warning",
"ingestion.cooldown_entered_preflight",
user_id=user_id,
block_reason=result.block_reason,
cooldown_until=safety_state.get("cooldown_until"),
)
raise RunBlockedBySafetyPolicyError(
code="scrape_cooldown_active",
message=f"Preflight detected Scholar block ({result.block_reason}). Cooldown activated.",
safety_state=safety_state,
)
async def _initialize_run_for_user(
self,
db_session: AsyncSession,
@ -287,7 +148,7 @@ class ScholarIngestionService:
threshold_kwargs: dict[str, Any],
idempotency_key: str | None,
) -> tuple[Any, CrawlRun, list[ScholarProfile], dict[int, int]]:
user_settings = await self._load_user_settings_for_run(
user_settings = await load_user_settings_for_run(
db_session,
user_id=user_id,
trigger_type=trigger_type,
@ -301,8 +162,9 @@ class ScholarIngestionService:
user_id=user_id,
filtered_scholar_ids=filtered_scholar_ids,
)
await self._run_preflight_guard(
await run_preflight_guard(
db_session,
self._source,
user_settings=user_settings,
user_id=user_id,
scholars=scholars,
@ -486,7 +348,7 @@ class ScholarIngestionService:
if intended_final_status not in (RunStatus.CANCELED,):
run.status = RunStatus.RESOLVING
await db_session.commit()
_log_run_completed(
log_run_completed(
run=run,
user_id=user_id,
scholars=attached_scholars,
@ -495,19 +357,22 @@ class ScholarIngestionService:
alert_summary=alert_summary,
)
if intended_final_status not in (RunStatus.CANCELED,):
task = asyncio.create_task(
self._background_enrich(
session_factory,
run_id=run.id,
intended_final_status=intended_final_status,
openalex_api_key=getattr(user_settings, "openalex_api_key", None),
)
spawn_background_enrichment_task(
session_factory,
self._enrichment,
run_id=run.id,
intended_final_status=intended_final_status,
openalex_api_key=getattr(user_settings, "openalex_api_key", None),
)
_background_tasks.add(task)
task.add_done_callback(_background_tasks.discard)
except Exception as exc:
await db_session.rollback()
logger.exception("ingestion.background_run_failed", extra={"run_id": run_id, "user_id": user_id})
structured_log(
logger,
"exception",
"ingestion.background_run_failed",
run_id=run_id,
user_id=user_id,
)
await self._fail_run_in_background(session_factory, run_id, exc)
async def _prepare_execute_run(
@ -530,47 +395,21 @@ class ScholarIngestionService:
return run, user_settings, list(scholars_result.scalars().all())
async def _fail_run_in_background(self, session_factory: Any, run_id: int, exc: Exception) -> None:
async with session_factory() as cleanup_session:
run_to_fail = await cleanup_session.get(CrawlRun, run_id)
if run_to_fail:
run_to_fail.status = RunStatus.FAILED
run_to_fail.end_dt = datetime.now(UTC)
run_to_fail.error_log["terminal_exception"] = str(exc)
await cleanup_session.commit()
async def _background_enrich(
self,
session_factory: Any,
*,
run_id: int,
intended_final_status: RunStatus,
openalex_api_key: str | None = None,
) -> None:
try:
async with session_factory() as session:
await self._enrichment.enrich_pending_publications(
session,
run_id=run_id,
openalex_api_key=openalex_api_key,
)
run = await session.get(CrawlRun, run_id)
if run is not None and run.status == RunStatus.RESOLVING:
run.status = intended_final_status
await session.commit()
logger.info(
"ingestion.background_enrichment_complete",
extra={"run_id": run_id, "final_status": str(intended_final_status)},
)
async with session_factory() as cleanup_session:
run_to_fail = await cleanup_session.get(CrawlRun, run_id)
if run_to_fail:
run_to_fail.status = RunStatus.FAILED
run_to_fail.end_dt = datetime.now(UTC)
run_to_fail.error_log["terminal_exception"] = str(exc)
await cleanup_session.commit()
except Exception:
logger.exception("ingestion.background_enrichment_failed", extra={"run_id": run_id})
try:
async with session_factory() as fallback_session:
run = await fallback_session.get(CrawlRun, run_id)
if run is not None and run.status == RunStatus.RESOLVING:
run.status = intended_final_status
await fallback_session.commit()
except Exception:
logger.exception("ingestion.background_enrichment_fallback_failed", extra={"run_id": run_id})
structured_log(
logger,
"exception",
"ingestion.fail_run_cleanup_failed",
run_id=run_id,
)
async def run_for_user(
self,
@ -626,7 +465,7 @@ class ScholarIngestionService:
alert_network_failure_threshold=alert_network_failure_threshold,
alert_retry_scheduled_threshold=alert_retry_scheduled_threshold,
)
progress, failure_summary, alert_summary = await self._run_iteration_and_complete(
progress, failure_summary, alert_summary, intended_final_status = await self._run_iteration_and_complete(
db_session,
run=run,
scholars=scholars,
@ -639,10 +478,14 @@ class ScholarIngestionService:
idempotency_key=idempotency_key,
)
user_settings = await user_settings_service.get_or_create_settings(db_session, user_id=user_id)
await self._inline_enrich_and_finalize(
db_session, run=run, user_settings=user_settings, intended_final_status=run.status
await inline_enrich_and_finalize(
db_session,
self._enrichment,
run=run,
user_settings=user_settings,
intended_final_status=intended_final_status,
)
_log_run_completed(
log_run_completed(
run=run,
user_id=user_id,
scholars=scholars,
@ -665,7 +508,7 @@ class ScholarIngestionService:
auto_queue_continuations: bool,
queue_delay_seconds: int,
idempotency_key: str | None,
) -> tuple[RunProgress, RunFailureSummary, RunAlertSummary]:
) -> tuple[RunProgress, RunFailureSummary, RunAlertSummary, RunStatus]:
progress = await run_scholar_iteration(
db_session,
pagination=self._pagination,
@ -691,27 +534,7 @@ class ScholarIngestionService:
if intended_final_status not in (RunStatus.CANCELED,):
run.status = RunStatus.RESOLVING
await db_session.commit()
return progress, failure_summary, alert_summary
async def _inline_enrich_and_finalize(
self,
db_session: AsyncSession,
*,
run: CrawlRun,
user_settings: Any,
intended_final_status: RunStatus,
) -> None:
try:
await self._enrichment.enrich_pending_publications(
db_session,
run_id=run.id,
openalex_api_key=getattr(user_settings, "openalex_api_key", None),
)
except Exception:
logger.exception("ingestion.enrichment_failed", extra={"run_id": run.id})
if run.status == RunStatus.RESOLVING:
run.status = intended_final_status
await db_session.commit()
return progress, failure_summary, alert_summary, intended_final_status
async def _try_acquire_user_lock(
self,

26
app/services/ingestion/enrichment.py
View file

@ -96,7 +96,7 @@ class EnrichmentRunner:
for p in batch:
if await self.run_is_canceled(db_session, run_id=run_id):
logger.info("ingestion.enrichment_aborted", extra={"run_id": run_id})
structured_log(logger, "info", "ingestion.enrichment_aborted", run_id=run_id)
return False, arxiv_lookup_allowed
p.openalex_last_attempt_at = now
arxiv_lookup_allowed = await self._discover_identifiers_for_enrichment(
@ -112,9 +112,9 @@ class EnrichmentRunner:
candidates=openalex_works,
)
if match:
p.year = match.publication_year or p.year
p.citation_count = match.cited_by_count or p.citation_count
p.pdf_url = match.oa_url or p.pdf_url
p.year = match.publication_year if match.publication_year is not None else p.year
p.citation_count = match.cited_by_count if match.cited_by_count is not None else p.citation_count
p.pdf_url = match.oa_url if match.oa_url is not None else p.pdf_url
p.openalex_enriched = True
return True, arxiv_lookup_allowed
@ -162,7 +162,7 @@ class EnrichmentRunner:
for i in range(0, len(publications), batch_size):
if await self.run_is_canceled(db_session, run_id=run_id):
logger.info("ingestion.enrichment_aborted", extra={"run_id": run_id})
structured_log(logger, "info", "ingestion.enrichment_aborted", run_id=run_id)
return
batch = publications[i : i + batch_size]
titles = _sanitize_titles(batch)
@ -181,6 +181,8 @@ class EnrichmentRunner:
continue
except Exception as e:
structured_log(logger, "warning", "ingestion.openalex_enrichment_failed", error=str(e), run_id=run_id)
for p in batch:
p.openalex_last_attempt_at = now
continue
should_continue, arxiv_lookup_allowed = await self._enrich_batch(
db_session,
@ -302,9 +304,13 @@ class EnrichmentRunner:
{"title.search": "|".join(titles)}, limit=batch_size * 3
)
except Exception as e:
logger.warning(
structured_log(
logger,
"warning",
"ingestion.openalex_enrichment_failed",
extra={"error": str(e), "batch_size": len(batch), "scholar_id": scholar.id},
error=str(e),
batch_size=len(batch),
scholar_id=scholar.id,
)
openalex_works = []
@ -320,11 +326,11 @@ class EnrichmentRunner:
title=p.title,
title_url=p.title_url,
cluster_id=p.cluster_id,
year=match.publication_year or p.year,
citation_count=match.cited_by_count,
year=match.publication_year if match.publication_year is not None else p.year,
citation_count=match.cited_by_count if match.cited_by_count is not None else p.citation_count,
authors_text=p.authors_text,
venue_text=p.venue_text,
pdf_url=match.oa_url or p.pdf_url,
pdf_url=match.oa_url if match.oa_url is not None else p.pdf_url,
)
enriched.append(new_p)
else:

12
app/services/ingestion/page_fetch.py
View file

@ -49,13 +49,13 @@ class PageFetcher:
error="source_does_not_support_pagination",
)
except Exception as exc:
logger.exception(
structured_log(
logger,
"exception",
"ingestion.fetch_unexpected_error",
extra={
"scholar_id": scholar_id,
"cstart": cstart,
"page_size": page_size,
},
scholar_id=scholar_id,
cstart=cstart,
page_size=page_size,
)
return FetchResult(
requested_url=(

6
app/services/ingestion/pagination.py
View file

@ -353,6 +353,9 @@ class PaginationEngine:
page_attempt_log=next_attempt_log,
)
if self._handle_page_state_transition(state=state):
return
if next_parsed_page.publications:
await self._upsert_page_publications(
db_session,
@ -364,9 +367,6 @@ class PaginationEngine:
upsert_publications_fn=upsert_publications_fn,
)
if self._handle_page_state_transition(state=state):
return
@staticmethod
def _result_from_pagination_state(
*,

7
app/services/ingestion/publication_upsert.py
View file

@ -8,7 +8,6 @@ from sqlalchemy import select
from sqlalchemy.ext.asyncio import AsyncSession
from app.db.models import CrawlRun, Publication, ScholarProfile, ScholarPublication
from app.services.doi.normalize import first_doi_from_texts
from app.services.ingestion.fingerprints import (
build_publication_fingerprint,
build_publication_url,
@ -106,8 +105,9 @@ def update_existing_publication(
) -> None:
if candidate.cluster_id and publication.cluster_id is None:
publication.cluster_id = candidate.cluster_id
publication.title_raw = candidate.title
publication.title_normalized = normalize_title(candidate.title)
if not publication.title_raw:
publication.title_raw = candidate.title
publication.title_normalized = normalize_title(candidate.title)
if candidate.year is not None:
publication.year = candidate.year
if candidate.citation_count is not None:
@ -118,7 +118,6 @@ def update_existing_publication(
publication.venue_text = candidate.venue_text
if candidate.title_url:
publication.pub_url = build_publication_url(candidate.title_url)
first_doi_from_texts(candidate.title_url, candidate.venue_text, candidate.title)
async def resolve_publication(

8
app/services/ingestion/queue_runner.py
View file

@ -229,7 +229,13 @@ class QueueJobRunner:
error=str(exc),
)
await recovery_session.commit()
logger.exception("scheduler.queue_item_run_failed", extra={"queue_item_id": job.id, "user_id": job.user_id})
structured_log(
logger,
"exception",
"scheduler.queue_item_run_failed",
queue_item_id=job.id,
user_id=job.user_id,
)
async def _load_request_delay_for_user(self, user_id: int, *, floor: int) -> int:
session_factory = get_session_factory()

28
app/services/ingestion/run_completion.py
View file

@ -427,3 +427,31 @@ def run_execution_summary(
partial_count=progress.partial_count,
new_publication_count=run.new_pub_count,
)
def log_run_completed(
*,
run: CrawlRun,
user_id: int,
scholars: list[ScholarProfile],
progress: RunProgress,
failure_summary: RunFailureSummary,
alert_summary: RunAlertSummary,
) -> None:
structured_log(
logger,
"info",
"ingestion.run_completed",
user_id=user_id,
crawl_run_id=run.id,
status=run.status.value,
scholar_count=len(scholars),
succeeded_count=progress.succeeded_count,
failed_count=progress.failed_count,
partial_count=progress.partial_count,
new_publication_count=run.new_pub_count,
blocked_failure_count=alert_summary.blocked_failure_count,
network_failure_count=alert_summary.network_failure_count,
retries_scheduled_count=failure_summary.retries_scheduled_count,
alert_flags=alert_summary.alert_flags,
)

110
app/services/ingestion/run_enrichment.py Normal file
View file

@ -0,0 +1,110 @@
from __future__ import annotations
import asyncio
import logging
from typing import Any
from sqlalchemy.ext.asyncio import AsyncSession
from app.db.models import CrawlRun, RunStatus
from app.logging_utils import structured_log
from app.services.ingestion.enrichment import EnrichmentRunner
logger = logging.getLogger(__name__)
_background_tasks: set[asyncio.Task[Any]] = set()
async def background_enrich(
session_factory: Any,
enrichment_runner: EnrichmentRunner,
*,
run_id: int,
intended_final_status: RunStatus,
openalex_api_key: str | None = None,
) -> None:
try:
async with session_factory() as session:
await enrichment_runner.enrich_pending_publications(
session,
run_id=run_id,
openalex_api_key=openalex_api_key,
)
run = await session.get(CrawlRun, run_id)
if run is not None and run.status == RunStatus.RESOLVING:
run.status = intended_final_status
await session.commit()
structured_log(
logger,
"info",
"ingestion.background_enrichment_complete",
run_id=run_id,
final_status=str(intended_final_status),
)
except Exception:
structured_log(
logger,
"exception",
"ingestion.background_enrichment_failed",
run_id=run_id,
)
try:
async with session_factory() as fallback_session:
run = await fallback_session.get(CrawlRun, run_id)
if run is not None and run.status == RunStatus.RESOLVING:
run.status = intended_final_status
await fallback_session.commit()
except Exception:
structured_log(
logger,
"exception",
"ingestion.background_enrichment_fallback_failed",
run_id=run_id,
)
async def inline_enrich_and_finalize(
db_session: AsyncSession,
enrichment_runner: EnrichmentRunner,
*,
run: CrawlRun,
user_settings: Any,
intended_final_status: RunStatus,
) -> None:
try:
await enrichment_runner.enrich_pending_publications(
db_session,
run_id=run.id,
openalex_api_key=getattr(user_settings, "openalex_api_key", None),
)
except Exception:
structured_log(
logger,
"exception",
"ingestion.enrichment_failed",
run_id=run.id,
)
if run.status == RunStatus.RESOLVING:
run.status = intended_final_status
await db_session.commit()
def spawn_background_enrichment_task(
session_factory: Any,
enrichment_runner: EnrichmentRunner,
*,
run_id: int,
intended_final_status: RunStatus,
openalex_api_key: str | None,
) -> None:
task = asyncio.create_task(
background_enrich(
session_factory,
enrichment_runner,
run_id=run_id,
intended_final_status=intended_final_status,
openalex_api_key=openalex_api_key,
)
)
_background_tasks.add(task)
task.add_done_callback(_background_tasks.discard)

135
app/services/ingestion/run_guards.py Normal file
View file

@ -0,0 +1,135 @@
from __future__ import annotations
import logging
from datetime import UTC, datetime
from typing import Any
from sqlalchemy.ext.asyncio import AsyncSession
from app.db.models import (
RunTriggerType,
ScholarProfile,
)
from app.logging_utils import structured_log
from app.services.ingestion import safety as run_safety_service
from app.services.ingestion.preflight import check_scholar_reachable
from app.services.ingestion.types import RunBlockedBySafetyPolicyError
from app.services.scholar.source import ScholarSource
from app.services.settings import application as user_settings_service
from app.settings import settings
logger = logging.getLogger(__name__)
async def load_user_settings_for_run(
db_session: AsyncSession,
*,
user_id: int,
trigger_type: RunTriggerType,
):
user_settings = await user_settings_service.get_or_create_settings(db_session, user_id=user_id)
await enforce_safety_gate(db_session, user_settings=user_settings, user_id=user_id, trigger_type=trigger_type)
return user_settings
async def enforce_safety_gate(
db_session: AsyncSession,
*,
user_settings,
user_id: int,
trigger_type: RunTriggerType,
) -> None:
now_utc = datetime.now(UTC)
previous = run_safety_service.get_safety_event_context(user_settings, now_utc=now_utc)
if run_safety_service.clear_expired_cooldown(user_settings, now_utc=now_utc):
await db_session.commit()
await db_session.refresh(user_settings)
structured_log(
logger,
"info",
"ingestion.cooldown_cleared",
user_id=user_id,
reason=previous.get("cooldown_reason"),
cooldown_until=previous.get("cooldown_until"),
)
now_utc = datetime.now(UTC)
if run_safety_service.is_cooldown_active(user_settings, now_utc=now_utc):
await raise_safety_blocked_start(
db_session,
user_settings=user_settings,
user_id=user_id,
trigger_type=trigger_type,
now_utc=now_utc,
)
async def raise_safety_blocked_start(
db_session: AsyncSession,
*,
user_settings,
user_id: int,
trigger_type: RunTriggerType,
now_utc: datetime,
) -> None:
safety_state = run_safety_service.register_cooldown_blocked_start(user_settings, now_utc=now_utc)
await db_session.commit()
structured_log(
logger,
"warning",
"ingestion.safety_policy_blocked_run_start",
user_id=user_id,
trigger_type=trigger_type.value,
reason=safety_state.get("cooldown_reason"),
cooldown_until=safety_state.get("cooldown_until"),
cooldown_remaining_seconds=safety_state.get("cooldown_remaining_seconds"),
blocked_start_count=((safety_state.get("counters") or {}).get("blocked_start_count")),
)
raise RunBlockedBySafetyPolicyError(
code="scrape_cooldown_active",
message="Scrape safety cooldown is active; run start is temporarily blocked.",
safety_state=safety_state,
)
async def run_preflight_guard(
db_session: AsyncSession,
source: ScholarSource,
*,
user_settings: Any,
user_id: int,
scholars: list[ScholarProfile],
) -> None:
if not scholars:
return
result = await check_scholar_reachable(
source,
scholar_id=scholars[0].scholar_id,
)
if result.passed:
return
now_utc = datetime.now(UTC)
safety_state, _ = run_safety_service.apply_run_safety_outcome(
user_settings,
run_id=0,
blocked_failure_count=1,
network_failure_count=0,
blocked_failure_threshold=1,
network_failure_threshold=1,
blocked_cooldown_seconds=settings.ingestion_safety_cooldown_blocked_seconds,
network_cooldown_seconds=settings.ingestion_safety_cooldown_network_seconds,
now_utc=now_utc,
)
await db_session.commit()
structured_log(
logger,
"warning",
"ingestion.cooldown_entered_preflight",
user_id=user_id,
block_reason=result.block_reason,
cooldown_until=safety_state.get("cooldown_until"),
)
raise RunBlockedBySafetyPolicyError(
code="scrape_cooldown_active",
message=f"Preflight detected Scholar block ({result.block_reason}). Cooldown activated.",
safety_state=safety_state,
)

18
app/services/ingestion/scheduler.py
View file

@ -125,9 +125,10 @@ class SchedulerService:
except asyncio.CancelledError:
raise
except Exception:
logger.exception(
structured_log(
logger,
"exception",
"scheduler.tick_failed",
extra={},
)
await asyncio.sleep(float(self._tick_seconds))
@ -263,7 +264,12 @@ class SchedulerService:
return None
except Exception:
await session.rollback()
logger.exception("scheduler.run_failed", extra={"user_id": candidate.user_id})
structured_log(
logger,
"exception",
"scheduler.run_failed",
user_id=candidate.user_id,
)
return None
async def _run_candidate(self, candidate: _AutoRunCandidate) -> None:
@ -300,4 +306,8 @@ class SchedulerService:
processed_count=processed,
)
except Exception:
logger.exception("scheduler.pdf_queue_drain_failed", extra={})
structured_log(
logger,
"exception",
"scheduler.pdf_queue_drain_failed",
)

308
app/services/ingestion/scholar_outcomes.py Normal file
View file

@ -0,0 +1,308 @@
from __future__ import annotations
import logging
from datetime import UTC, datetime
from typing import Any
from sqlalchemy.ext.asyncio import AsyncSession
from app.db.models import (
CrawlRun,
RunStatus,
ScholarProfile,
)
from app.logging_utils import structured_log
from app.services.ingestion.run_completion import build_failure_debug_context
from app.services.ingestion.types import (
PagedParseResult,
ScholarProcessingOutcome,
)
from app.services.scholar.parser import ParseState
logger = logging.getLogger(__name__)
def assert_valid_paged_parse_result(
*,
scholar_id: str,
paged_parse_result: PagedParseResult,
) -> None:
parsed_page = paged_parse_result.parsed_page
if parsed_page.state in {ParseState.OK, ParseState.NO_RESULTS} and any(
code.startswith("layout_") for code in parsed_page.warnings
):
raise RuntimeError(f"Layout warning marked as terminal for scholar_id={scholar_id}.")
for publication in paged_parse_result.publications:
if not publication.title.strip():
raise RuntimeError(f"Malformed publication title for scholar_id={scholar_id}.")
if publication.citation_count is not None and int(publication.citation_count) < 0:
raise RuntimeError(f"Negative citation count for scholar_id={scholar_id}.")
def apply_first_page_profile_metadata(
*,
scholar: ScholarProfile,
paged_parse_result: PagedParseResult,
run_dt: datetime,
) -> None:
first_page = paged_parse_result.first_page_parsed_page
if first_page.profile_name and not (scholar.display_name or "").strip():
scholar.display_name = first_page.profile_name
if first_page.profile_image_url:
scholar.profile_image_url = first_page.profile_image_url
scholar.last_initial_page_checked_at = run_dt
def build_result_entry(
*,
scholar: ScholarProfile,
start_cstart: int,
paged_parse_result: PagedParseResult,
) -> dict[str, Any]:
parsed_page = paged_parse_result.parsed_page
return {
"scholar_profile_id": scholar.id,
"scholar_id": scholar.scholar_id,
"state": parsed_page.state.value,
"state_reason": parsed_page.state_reason,
"outcome": "failed",
"attempt_count": len(paged_parse_result.attempt_log),
"publication_count": len(paged_parse_result.publications),
"start_cstart": start_cstart,
"articles_range": parsed_page.articles_range,
"warnings": parsed_page.warnings,
"has_show_more_button": parsed_page.has_show_more_button,
"pages_fetched": paged_parse_result.pages_fetched,
"pages_attempted": paged_parse_result.pages_attempted,
"has_more_remaining": paged_parse_result.has_more_remaining,
"pagination_truncated_reason": paged_parse_result.pagination_truncated_reason,
"continuation_cstart": paged_parse_result.continuation_cstart,
"skipped_no_change": paged_parse_result.skipped_no_change,
"initial_page_fingerprint_sha256": paged_parse_result.first_page_fingerprint_sha256,
}
def skipped_no_change_outcome(
*,
scholar: ScholarProfile,
run_dt: datetime,
paged_parse_result: PagedParseResult,
result_entry: dict[str, Any],
) -> ScholarProcessingOutcome:
first_page = paged_parse_result.first_page_parsed_page
scholar.last_run_status = RunStatus.SUCCESS
scholar.last_run_dt = run_dt
result_entry["state"] = first_page.state.value
result_entry["state_reason"] = "no_change_initial_page_signature"
result_entry["outcome"] = "success"
result_entry["publication_count"] = 0
result_entry["warnings"] = first_page.warnings
result_entry["debug"] = {
"state_reason": "no_change_initial_page_signature",
"first_page_fingerprint_sha256": paged_parse_result.first_page_fingerprint_sha256,
"attempt_log": paged_parse_result.attempt_log,
"page_logs": paged_parse_result.page_logs,
}
return ScholarProcessingOutcome(
result_entry=result_entry,
succeeded_count_delta=1,
failed_count_delta=0,
partial_count_delta=0,
discovered_publication_count=0,
)
async def upsert_publications_outcome(
db_session: AsyncSession,
*,
run: CrawlRun,
scholar: ScholarProfile,
run_dt: datetime,
paged_parse_result: PagedParseResult,
result_entry: dict[str, Any],
) -> ScholarProcessingOutcome:
parsed_page = paged_parse_result.parsed_page
publications = paged_parse_result.publications
had_page_failure = parsed_page.state not in {ParseState.OK, ParseState.NO_RESULTS}
has_partial_set = len(publications) > 0 and had_page_failure
if (not had_page_failure) or has_partial_set:
return await _upsert_success_or_exception(
db_session,
run=run,
scholar=scholar,
run_dt=run_dt,
paged_parse_result=paged_parse_result,
result_entry=result_entry,
has_partial_publication_set=has_partial_set,
)
return _parse_failure_outcome(
scholar=scholar,
run_dt=run_dt,
paged_parse_result=paged_parse_result,
result_entry=result_entry,
)
async def _upsert_success_or_exception(
db_session: AsyncSession,
*,
run: CrawlRun,
scholar: ScholarProfile,
run_dt: datetime,
paged_parse_result: PagedParseResult,
result_entry: dict[str, Any],
has_partial_publication_set: bool,
) -> ScholarProcessingOutcome:
try:
return _upsert_success(
run=run,
scholar=scholar,
run_dt=run_dt,
paged_parse_result=paged_parse_result,
result_entry=result_entry,
has_partial_publication_set=has_partial_publication_set,
)
except Exception as exc:
return _upsert_exception_outcome(
run=run,
scholar=scholar,
run_dt=run_dt,
paged_parse_result=paged_parse_result,
result_entry=result_entry,
exc=exc,
)
def _upsert_success(
*,
run: CrawlRun,
scholar: ScholarProfile,
run_dt: datetime,
paged_parse_result: PagedParseResult,
result_entry: dict[str, Any],
has_partial_publication_set: bool,
) -> ScholarProcessingOutcome:
discovered_count = paged_parse_result.discovered_publication_count
is_partial = (
paged_parse_result.has_more_remaining
or paged_parse_result.pagination_truncated_reason is not None
or has_partial_publication_set
)
scholar.last_run_status = RunStatus.PARTIAL_FAILURE if is_partial else RunStatus.SUCCESS
scholar.last_run_dt = run_dt
if not is_partial and paged_parse_result.first_page_fingerprint_sha256:
scholar.last_initial_page_fingerprint_sha256 = paged_parse_result.first_page_fingerprint_sha256
result_entry["outcome"] = "partial" if is_partial else "success"
if is_partial:
result_entry["debug"] = build_failure_debug_context(
fetch_result=paged_parse_result.fetch_result,
parsed_page=paged_parse_result.parsed_page,
attempt_log=paged_parse_result.attempt_log,
page_logs=paged_parse_result.page_logs,
)
return ScholarProcessingOutcome(
result_entry=result_entry,
succeeded_count_delta=1,
failed_count_delta=0,
partial_count_delta=1 if is_partial else 0,
discovered_publication_count=discovered_count,
)
def _upsert_exception_outcome(
*,
run: CrawlRun,
scholar: ScholarProfile,
run_dt: datetime,
paged_parse_result: PagedParseResult,
result_entry: dict[str, Any],
exc: Exception,
) -> ScholarProcessingOutcome:
scholar.last_run_status = RunStatus.FAILED
scholar.last_run_dt = run_dt
result_entry["state"] = "ingestion_error"
result_entry["state_reason"] = "publication_upsert_exception"
result_entry["outcome"] = "failed"
result_entry["error"] = str(exc)
result_entry["debug"] = build_failure_debug_context(
fetch_result=paged_parse_result.fetch_result,
parsed_page=paged_parse_result.parsed_page,
attempt_log=paged_parse_result.attempt_log,
page_logs=paged_parse_result.page_logs,
exception=exc,
)
structured_log(
logger,
"exception",
"ingestion.scholar_failed",
crawl_run_id=run.id,
scholar_profile_id=scholar.id,
scholar_id=scholar.scholar_id,
)
return ScholarProcessingOutcome(result_entry, 0, 1, 0, 0)
def _parse_failure_outcome(
*,
scholar: ScholarProfile,
run_dt: datetime,
paged_parse_result: PagedParseResult,
result_entry: dict[str, Any],
) -> ScholarProcessingOutcome:
scholar.last_run_status = RunStatus.FAILED
scholar.last_run_dt = run_dt
result_entry["debug"] = build_failure_debug_context(
fetch_result=paged_parse_result.fetch_result,
parsed_page=paged_parse_result.parsed_page,
attempt_log=paged_parse_result.attempt_log,
page_logs=paged_parse_result.page_logs,
)
structured_log(
logger,
"warning",
"ingestion.scholar_parse_failed",
scholar_profile_id=scholar.id,
scholar_id=scholar.scholar_id,
state=paged_parse_result.parsed_page.state.value,
state_reason=paged_parse_result.parsed_page.state_reason,
status_code=paged_parse_result.fetch_result.status_code,
)
return ScholarProcessingOutcome(result_entry, 0, 1, 0, 0)
def unexpected_scholar_exception_outcome(
*,
run: CrawlRun,
scholar: ScholarProfile,
start_cstart: int,
exc: Exception,
) -> ScholarProcessingOutcome:
scholar.last_run_status = RunStatus.FAILED
scholar.last_run_dt = datetime.now(UTC)
structured_log(
logger,
"exception",
"ingestion.scholar_unexpected_failure",
crawl_run_id=run.id,
scholar_profile_id=scholar.id,
scholar_id=scholar.scholar_id,
)
return ScholarProcessingOutcome(
result_entry={
"scholar_profile_id": scholar.id,
"scholar_id": scholar.scholar_id,
"state": "ingestion_error",
"state_reason": "scholar_processing_exception",
"outcome": "failed",
"attempt_count": 0,
"publication_count": 0,
"start_cstart": start_cstart,
"warnings": [],
"error": str(exc),
"debug": {"exception_type": type(exc).__name__, "exception_message": str(exc)},
},
succeeded_count_delta=0,
failed_count_delta=1,
partial_count_delta=0,
discovered_publication_count=0,
)

299
app/services/ingestion/scholar_processing.py
View file

@ -6,6 +6,7 @@ import random
from datetime import UTC, datetime
from typing import Any
from sqlalchemy.exc import InterfaceError, OperationalError
from sqlalchemy.ext.asyncio import AsyncSession
from app.db.models import (
@ -21,7 +22,15 @@ from app.services.ingestion.constants import (
)
from app.services.ingestion.pagination import PaginationEngine
from app.services.ingestion.publication_upsert import upsert_profile_publications
from app.services.ingestion.run_completion import apply_outcome_to_progress, build_failure_debug_context
from app.services.ingestion.run_completion import apply_outcome_to_progress
from app.services.ingestion.scholar_outcomes import (
apply_first_page_profile_metadata,
assert_valid_paged_parse_result,
build_result_entry,
skipped_no_change_outcome,
unexpected_scholar_exception_outcome,
upsert_publications_outcome,
)
from app.services.ingestion.types import (
PagedParseResult,
RunProgress,
@ -33,254 +42,6 @@ from app.services.scholar.state_detection import is_hard_challenge_reason
logger = logging.getLogger(__name__)
def assert_valid_paged_parse_result(
*,
scholar_id: str,
paged_parse_result: PagedParseResult,
) -> None:
parsed_page = paged_parse_result.parsed_page
if parsed_page.state in {ParseState.OK, ParseState.NO_RESULTS} and any(
code.startswith("layout_") for code in parsed_page.warnings
):
raise RuntimeError(f"Layout warning marked as terminal for scholar_id={scholar_id}.")
for publication in paged_parse_result.publications:
if not publication.title.strip():
raise RuntimeError(f"Malformed publication title for scholar_id={scholar_id}.")
if publication.citation_count is not None and int(publication.citation_count) < 0:
raise RuntimeError(f"Negative citation count for scholar_id={scholar_id}.")
def apply_first_page_profile_metadata(
*,
scholar: ScholarProfile,
paged_parse_result: PagedParseResult,
run_dt: datetime,
) -> None:
first_page = paged_parse_result.first_page_parsed_page
if first_page.profile_name and not (scholar.display_name or "").strip():
scholar.display_name = first_page.profile_name
if first_page.profile_image_url:
scholar.profile_image_url = first_page.profile_image_url
scholar.last_initial_page_checked_at = run_dt
def build_result_entry(
*,
scholar: ScholarProfile,
start_cstart: int,
paged_parse_result: PagedParseResult,
) -> dict[str, Any]:
parsed_page = paged_parse_result.parsed_page
return {
"scholar_profile_id": scholar.id,
"scholar_id": scholar.scholar_id,
"state": parsed_page.state.value,
"state_reason": parsed_page.state_reason,
"outcome": "failed",
"attempt_count": len(paged_parse_result.attempt_log),
"publication_count": len(paged_parse_result.publications),
"start_cstart": start_cstart,
"articles_range": parsed_page.articles_range,
"warnings": parsed_page.warnings,
"has_show_more_button": parsed_page.has_show_more_button,
"pages_fetched": paged_parse_result.pages_fetched,
"pages_attempted": paged_parse_result.pages_attempted,
"has_more_remaining": paged_parse_result.has_more_remaining,
"pagination_truncated_reason": paged_parse_result.pagination_truncated_reason,
"continuation_cstart": paged_parse_result.continuation_cstart,
"skipped_no_change": paged_parse_result.skipped_no_change,
"initial_page_fingerprint_sha256": paged_parse_result.first_page_fingerprint_sha256,
}
def skipped_no_change_outcome(
*,
scholar: ScholarProfile,
run_dt: datetime,
paged_parse_result: PagedParseResult,
result_entry: dict[str, Any],
) -> ScholarProcessingOutcome:
first_page = paged_parse_result.first_page_parsed_page
scholar.last_run_status = RunStatus.SUCCESS
scholar.last_run_dt = run_dt
result_entry["state"] = first_page.state.value
result_entry["state_reason"] = "no_change_initial_page_signature"
result_entry["outcome"] = "success"
result_entry["publication_count"] = 0
result_entry["warnings"] = first_page.warnings
result_entry["debug"] = {
"state_reason": "no_change_initial_page_signature",
"first_page_fingerprint_sha256": paged_parse_result.first_page_fingerprint_sha256,
"attempt_log": paged_parse_result.attempt_log,
"page_logs": paged_parse_result.page_logs,
}
return ScholarProcessingOutcome(
result_entry=result_entry,
succeeded_count_delta=1,
failed_count_delta=0,
partial_count_delta=0,
discovered_publication_count=0,
)
async def upsert_publications_outcome(
db_session: AsyncSession,
*,
run: CrawlRun,
scholar: ScholarProfile,
run_dt: datetime,
paged_parse_result: PagedParseResult,
result_entry: dict[str, Any],
) -> ScholarProcessingOutcome:
parsed_page = paged_parse_result.parsed_page
publications = paged_parse_result.publications
had_page_failure = parsed_page.state not in {ParseState.OK, ParseState.NO_RESULTS}
has_partial_set = len(publications) > 0 and had_page_failure
if (not had_page_failure) or has_partial_set:
return await _upsert_success_or_exception(
db_session,
run=run,
scholar=scholar,
run_dt=run_dt,
paged_parse_result=paged_parse_result,
result_entry=result_entry,
has_partial_publication_set=has_partial_set,
)
return _parse_failure_outcome(
scholar=scholar,
run_dt=run_dt,
paged_parse_result=paged_parse_result,
result_entry=result_entry,
)
async def _upsert_success_or_exception(
db_session: AsyncSession,
*,
run: CrawlRun,
scholar: ScholarProfile,
run_dt: datetime,
paged_parse_result: PagedParseResult,
result_entry: dict[str, Any],
has_partial_publication_set: bool,
) -> ScholarProcessingOutcome:
try:
return _upsert_success(
run=run,
scholar=scholar,
run_dt=run_dt,
paged_parse_result=paged_parse_result,
result_entry=result_entry,
has_partial_publication_set=has_partial_publication_set,
)
except Exception as exc:
return _upsert_exception_outcome(
run=run,
scholar=scholar,
run_dt=run_dt,
paged_parse_result=paged_parse_result,
result_entry=result_entry,
exc=exc,
)
def _upsert_success(
*,
run: CrawlRun,
scholar: ScholarProfile,
run_dt: datetime,
paged_parse_result: PagedParseResult,
result_entry: dict[str, Any],
has_partial_publication_set: bool,
) -> ScholarProcessingOutcome:
discovered_count = paged_parse_result.discovered_publication_count
is_partial = (
paged_parse_result.has_more_remaining
or paged_parse_result.pagination_truncated_reason is not None
or has_partial_publication_set
)
scholar.last_run_status = RunStatus.PARTIAL_FAILURE if is_partial else RunStatus.SUCCESS
scholar.last_run_dt = run_dt
if not is_partial and paged_parse_result.first_page_fingerprint_sha256:
scholar.last_initial_page_fingerprint_sha256 = paged_parse_result.first_page_fingerprint_sha256
result_entry["outcome"] = "partial" if is_partial else "success"
if is_partial:
result_entry["debug"] = build_failure_debug_context(
fetch_result=paged_parse_result.fetch_result,
parsed_page=paged_parse_result.parsed_page,
attempt_log=paged_parse_result.attempt_log,
page_logs=paged_parse_result.page_logs,
)
return ScholarProcessingOutcome(
result_entry=result_entry,
succeeded_count_delta=1,
failed_count_delta=0,
partial_count_delta=1 if is_partial else 0,
discovered_publication_count=discovered_count,
)
def _upsert_exception_outcome(
*,
run: CrawlRun,
scholar: ScholarProfile,
run_dt: datetime,
paged_parse_result: PagedParseResult,
result_entry: dict[str, Any],
exc: Exception,
) -> ScholarProcessingOutcome:
scholar.last_run_status = RunStatus.FAILED
scholar.last_run_dt = run_dt
result_entry["state"] = "ingestion_error"
result_entry["state_reason"] = "publication_upsert_exception"
result_entry["outcome"] = "failed"
result_entry["error"] = str(exc)
result_entry["debug"] = build_failure_debug_context(
fetch_result=paged_parse_result.fetch_result,
parsed_page=paged_parse_result.parsed_page,
attempt_log=paged_parse_result.attempt_log,
page_logs=paged_parse_result.page_logs,
exception=exc,
)
logger.exception(
"ingestion.scholar_failed",
extra={
"crawl_run_id": run.id,
"scholar_profile_id": scholar.id,
"scholar_id": scholar.scholar_id,
},
)
return ScholarProcessingOutcome(result_entry, 0, 1, 0, 0)
def _parse_failure_outcome(
*,
scholar: ScholarProfile,
run_dt: datetime,
paged_parse_result: PagedParseResult,
result_entry: dict[str, Any],
) -> ScholarProcessingOutcome:
scholar.last_run_status = RunStatus.FAILED
scholar.last_run_dt = run_dt
result_entry["debug"] = build_failure_debug_context(
fetch_result=paged_parse_result.fetch_result,
parsed_page=paged_parse_result.parsed_page,
attempt_log=paged_parse_result.attempt_log,
page_logs=paged_parse_result.page_logs,
)
structured_log(
logger,
"warning",
"ingestion.scholar_parse_failed",
scholar_profile_id=scholar.id,
scholar_id=scholar.scholar_id,
state=paged_parse_result.parsed_page.state.value,
state_reason=paged_parse_result.parsed_page.state_reason,
status_code=paged_parse_result.fetch_result.status_code,
)
return ScholarProcessingOutcome(result_entry, 0, 1, 0, 0)
async def sync_continuation_queue(
db_session: AsyncSession,
*,
@ -396,6 +157,8 @@ async def process_scholar(
queue_delay_seconds=queue_delay_seconds,
)
return outcome
except (OperationalError, InterfaceError):
raise
except Exception as exc:
return unexpected_scholar_exception_outcome(
run=run,
@ -492,44 +255,6 @@ async def _resolve_scholar_outcome(
)
def unexpected_scholar_exception_outcome(
*,
run: CrawlRun,
scholar: ScholarProfile,
start_cstart: int,
exc: Exception,
) -> ScholarProcessingOutcome:
scholar.last_run_status = RunStatus.FAILED
scholar.last_run_dt = datetime.now(UTC)
logger.exception(
"ingestion.scholar_unexpected_failure",
extra={
"crawl_run_id": run.id,
"scholar_profile_id": scholar.id,
"scholar_id": scholar.scholar_id,
},
)
return ScholarProcessingOutcome(
result_entry={
"scholar_profile_id": scholar.id,
"scholar_id": scholar.scholar_id,
"state": "ingestion_error",
"state_reason": "scholar_processing_exception",
"outcome": "failed",
"attempt_count": 0,
"publication_count": 0,
"start_cstart": start_cstart,
"warnings": [],
"error": str(exc),
"debug": {"exception_type": type(exc).__name__, "exception_message": str(exc)},
},
succeeded_count_delta=0,
failed_count_delta=1,
partial_count_delta=0,
discovered_publication_count=0,
)
def _is_hard_challenge_outcome(outcome: ScholarProcessingOutcome) -> bool:
entry = outcome.result_entry
return str(entry.get("state", "")) == ParseState.BLOCKED_OR_CAPTCHA.value and is_hard_challenge_reason(

27
app/services/openalex/client.py
View file

@ -8,6 +8,7 @@ from tenacity import (
wait_exponential,
)
from app.logging_utils import structured_log
from app.services.openalex.types import OpenAlexWork
logger = logging.getLogger(__name__)
@ -82,7 +83,13 @@ class OpenAlexClient:
raise OpenAlexBudgetExhaustedError("Daily API budget exhausted; retrying won't help until midnight UTC")
raise OpenAlexRateLimitError("Rate limit exceeded fetching OpenAlex work by DOI")
if response.status_code >= 400:
logger.warning("OpenAlex API error: %s %s", response.status_code, response.text[:500])
structured_log(
logger,
"warning",
"openalex.api_error",
status_code=response.status_code,
response_preview=response.text[:500],
)
raise OpenAlexClientError(f"API Error {response.status_code}")
data = response.json()
@ -130,7 +137,14 @@ class OpenAlexClient:
raise OpenAlexBudgetExhaustedError("Daily API budget exhausted; retrying won't help until midnight UTC")
raise OpenAlexRateLimitError("Rate limit exceeded fetching OpenAlex works list")
if response.status_code >= 400:
logger.warning("OpenAlex API error (filters=%s): %s %s", filters, response.status_code, response.text[:500])
structured_log(
logger,
"warning",
"openalex.api_error_with_filters",
filters=filters,
status_code=response.status_code,
response_preview=response.text[:500],
)
raise OpenAlexClientError(f"API Error {response.status_code}")
data = response.json()
@ -140,8 +154,13 @@ class OpenAlexClient:
for raw_work in results:
try:
parsed_works.append(OpenAlexWork.from_api_dict(raw_work))
except Exception as e:
logger.warning("Failed to parse OpenAlex raw dict: %s", e)
except Exception as exc:
structured_log(
logger,
"warning",
"openalex.parse_failed",
error=str(exc),
)
continue
return parsed_works

1
app/services/publications/pdf_queue_common.py
View file

@ -4,6 +4,7 @@ from datetime import UTC, datetime
from app.db.models import PublicationPdfJob, PublicationPdfJobEvent
PDF_STATUS_UNTRACKED = "untracked"
PDF_STATUS_QUEUED = "queued"
PDF_STATUS_RUNNING = "running"
PDF_STATUS_RESOLVED = "resolved"

11
app/services/publications/pdf_queue_queries.py
View file

@ -16,14 +16,13 @@ from app.db.models import (
)
from app.services.publication_identifiers import application as identifier_service
from app.services.publication_identifiers.types import DisplayIdentifier
from app.services.publications.pdf_queue_common import (
PDF_STATUS_QUEUED,
PDF_STATUS_RUNNING,
PDF_STATUS_UNTRACKED,
)
from app.services.publications.types import PublicationListItem
PDF_STATUS_UNTRACKED = "untracked"
PDF_STATUS_QUEUED = "queued"
PDF_STATUS_RUNNING = "running"
PDF_STATUS_RESOLVED = "resolved"
PDF_STATUS_FAILED = "failed"
def _bounded_limit(limit: int, *, max_value: int = 500) -> int:
return max(1, min(int(limit), max_value))

2
app/services/publications/pdf_queue_resolution.py
View file

@ -251,7 +251,7 @@ def _drop_finished_task(task: asyncio.Task[None]) -> None:
try:
task.result()
except Exception:
logger.exception("publications.pdf_queue.task_failed")
structured_log(logger, "exception", "publications.pdf_queue.task_failed")
def schedule_rows(

14
app/services/publications/queries.py
View file

@ -16,6 +16,12 @@ from app.db.models import (
ScholarPublication,
)
from app.services.publications.modes import MODE_LATEST, MODE_UNREAD
from app.services.publications.pdf_queue_common import (
PDF_STATUS_FAILED,
PDF_STATUS_QUEUED,
PDF_STATUS_RESOLVED,
PDF_STATUS_RUNNING,
)
from app.services.publications.types import PublicationListItem, UnreadPublicationItem
@ -29,10 +35,10 @@ def _normalized_citation_count(value: object) -> int:
def _pdf_status_sort_rank():
return case(
(Publication.pdf_url.is_not(None), 4),
(PublicationPdfJob.status == "resolved", 4),
(PublicationPdfJob.status == "running", 3),
(PublicationPdfJob.status == "queued", 2),
(PublicationPdfJob.status == "failed", 0),
(PublicationPdfJob.status == PDF_STATUS_RESOLVED, 4),
(PublicationPdfJob.status == PDF_STATUS_RUNNING, 3),
(PublicationPdfJob.status == PDF_STATUS_QUEUED, 2),
(PublicationPdfJob.status == PDF_STATUS_FAILED, 0),
else_=1,
)

24
app/services/runs/events.py
View file

@ -4,6 +4,8 @@ import logging
from collections.abc import AsyncGenerator
from typing import Any
from app.logging_utils import structured_log
logger = logging.getLogger(__name__)
@ -17,7 +19,13 @@ class RunEventPublisher:
self._subscribers[run_id] = set()
queue: asyncio.Queue[Any] = asyncio.Queue()
self._subscribers[run_id].add(queue)
logger.debug(f"New subscriber for run {run_id}. Total: {len(self._subscribers[run_id])}")
structured_log(
logger,
"debug",
"runs.event_subscriber_added",
run_id=run_id,
subscriber_count=len(self._subscribers[run_id]),
)
return queue
def unsubscribe(self, run_id: int, queue: asyncio.Queue) -> None:
@ -37,7 +45,12 @@ class RunEventPublisher:
try:
queue.put_nowait(message)
except asyncio.QueueFull:
logger.warning(f"Subscriber queue full for run {run_id}, dropping message")
structured_log(
logger,
"warning",
"runs.event_subscriber_queue_full",
run_id=run_id,
)
run_events = RunEventPublisher()
@ -54,7 +67,12 @@ async def event_generator(run_id: int) -> AsyncGenerator[str, None]:
data_str = json.dumps(message["data"])
yield f"event: {event_type}\ndata: {data_str}\n\n"
except asyncio.CancelledError:
logger.debug(f"Client disconnected from SSE stream for run {run_id}")
structured_log(
logger,
"debug",
"runs.event_stream_disconnected",
run_id=run_id,
)
raise
finally:
run_events.unsubscribe(run_id, queue)

5
app/services/scholar/profile_rows.py
View file

@ -131,7 +131,10 @@ def parse_citation_count(parts: list[str]) -> int | None:
text = normalize_space(" ".join(parts))
if not text:
return 0
digits = re.sub(r"\D+", "", text)
match = re.search(r"[\d,]+", text)
if not match:
return None
digits = match.group(0).replace(",", "")
if not digits:
return None
return int(digits)

2
app/services/unpaywall/application.py
View file

@ -393,7 +393,7 @@ async def resolve_publication_oa_outcomes(
return {}
email = _email_for_request(request_email)
if email is None:
logger.debug("unpaywall.resolve_skipped_missing_email")
structured_log(logger, "debug", "unpaywall.resolve_skipped_missing_email")
return {}
import httpx