Pipeline resilience: try/finally + startup recovery for stuck images
CI / Lint & Format (push) Failing after 8s
CI / Tests (push) Has been skipped
CI / Security Scan (push) Failing after 7s
CI / Docker Build (push) Has been skipped

- process_image_pipeline: wrapped in try/finally to guarantee processing_status
  is always updated, even on unexpected crashes/timeouts
- init_db: recovery query that marks images stuck in 'processing' for >10min
  as ERROR on startup
- Clean rewrite of pipeline.py for consistent indentation
This commit is contained in:
2026-06-25 13:46:47 -04:00
parent 92cf23dbb3
commit eda4faeb78
2 changed files with 177 additions and 158 deletions
+24 -3
View File
@@ -2,8 +2,10 @@
Configuration SQLAlchemy — session async Configuration SQLAlchemy — session async
""" """
import logging import logging
from datetime import datetime, timezone, timedelta
from sqlalchemy.ext.asyncio import create_async_engine, AsyncSession, async_sessionmaker from sqlalchemy.ext.asyncio import create_async_engine, AsyncSession, async_sessionmaker
from sqlalchemy.orm import DeclarativeBase from sqlalchemy.orm import DeclarativeBase
from sqlalchemy import select, text
from app.config import settings from app.config import settings
logger = logging.getLogger(__name__) logger = logging.getLogger(__name__)
@@ -44,9 +46,9 @@ async def get_db() -> AsyncSession:
async def init_db(): async def init_db():
"""Crée toutes les tables, applique les migrations, et initialise un client par défaut si nécessaire.""" """Crée toutes les tables, applique les migrations, et initialise un client par défaut si nécessaire."""
import secrets import secrets
from sqlalchemy import select, text
from app.dependencies.auth import hash_api_key from app.dependencies.auth import hash_api_key
from app.models.client import APIClient, ClientPlan from app.models.client import APIClient, ClientPlan
from app.models.image import Image, ProcessingStatus
async with engine.begin() as conn: async with engine.begin() as conn:
from app.models import image # noqa: F401 from app.models import image # noqa: F401
@@ -59,7 +61,7 @@ async def init_db():
"ALTER TABLE api_clients ADD COLUMN IF NOT EXISTS ai_provider VARCHAR(64)" "ALTER TABLE api_clients ADD COLUMN IF NOT EXISTS ai_provider VARCHAR(64)"
)) ))
except Exception: except Exception:
pass # SQLite ne supporte pas ADD COLUMN IF NOT EXISTS pass
try: try:
await conn.execute(text( await conn.execute(text(
@@ -68,8 +70,27 @@ async def init_db():
except Exception: except Exception:
pass pass
# Vérifier s'il y a déjà des clients # Vérifier s'il y a déjà des clients + recovery des images bloquées
async with AsyncSessionLocal() as session: async with AsyncSessionLocal() as session:
# Recovery : marquer les images bloquées en "processing" depuis > 10 min comme ERROR
cutoff = datetime.now(timezone.utc) - timedelta(minutes=10)
stuck_query = select(Image).where(
Image.processing_status == ProcessingStatus.PROCESSING,
Image.processing_started_at < cutoff,
)
stuck_result = await session.execute(stuck_query)
stuck_images = stuck_result.scalars().all()
for img in stuck_images:
img.processing_status = ProcessingStatus.ERROR
img.processing_error = "[Recovery] Pipeline interrompu (timeout ou crash worker)"
img.processing_done_at = datetime.now(timezone.utc)
if stuck_images:
await session.commit()
logger.warning(
"init_db.recovery",
extra={"stuck_images_recovered": len(stuck_images)},
)
result = await session.execute(select(APIClient).limit(1)) result = await session.execute(select(APIClient).limit(1))
if result.scalar_one_or_none() is None: if result.scalar_one_or_none() is None:
# Table vide -> Création du client bootstrap # Table vide -> Création du client bootstrap
+153 -155
View File
@@ -21,7 +21,6 @@ from app.metrics import (
hub_pipeline_duration, hub_pipeline_step_duration, hub_pipeline_errors, hub_pipeline_duration, hub_pipeline_step_duration, hub_pipeline_errors,
hub_ai_tokens_consumed hub_ai_tokens_consumed
) )
import asyncio
logger = logging.getLogger(__name__) logger = logging.getLogger(__name__)
@@ -44,20 +43,17 @@ async def _publish_event(
payload["data"] = data payload["data"] = data
raw = json.dumps(payload) raw = json.dumps(payload)
# Publier sur le channel dédié à l'image
await redis.publish(f"pipeline:{image_id}", raw) await redis.publish(f"pipeline:{image_id}", raw)
# Buffer de reconnexion (10 derniers événements, TTL 60s)
buffer_key = f"pipeline:buffer:{image_id}" buffer_key = f"pipeline:buffer:{image_id}"
await redis.rpush(buffer_key, raw) await redis.rpush(buffer_key, raw)
await redis.ltrim(buffer_key, -10, -1) await redis.ltrim(buffer_key, -10, -1)
await redis.expire(buffer_key, 60) await redis.expire(buffer_key, 60)
# Publier sur le channel admin pour le monitoring global
if event in ("pipeline.started", "pipeline.done", "pipeline.error"): if event in ("pipeline.started", "pipeline.done", "pipeline.error"):
await redis.publish("pipeline:admin", raw) await redis.publish("pipeline:admin", raw)
except Exception: except Exception:
pass # Pub/Sub non critique — ne doit pas bloquer le pipeline pass
async def process_image_pipeline( async def process_image_pipeline(
@@ -70,10 +66,9 @@ async def process_image_pipeline(
3. Vision AI — description + tags (async) 3. Vision AI — description + tags (async)
4. Sauvegarde finale en BDD 4. Sauvegarde finale en BDD
Le statut est mis à jour à chaque étape pour permettre le polling. Try/finally garantit que le statut est TOUJOURS mis à jour,
Publie des événements Redis sur le channel pipeline:{image_id}. même en cas de crash inattendu (timeout, OOM, etc.).
""" """
# ── Chargement de l'image ─────────────────────────────────
result = await db.execute(select(Image).where(Image.id == image_id)) result = await db.execute(select(Image).where(Image.id == image_id))
image = result.scalar_one_or_none() image = result.scalar_one_or_none()
@@ -81,7 +76,6 @@ async def process_image_pipeline(
logger.warning("pipeline.image_not_found", extra={"image_id": image_id}) logger.warning("pipeline.image_not_found", extra={"image_id": image_id})
return return
# ── Démarrage ─────────────────────────────────────────────
image.processing_status = ProcessingStatus.PROCESSING image.processing_status = ProcessingStatus.PROCESSING
image.processing_started_at = datetime.now(timezone.utc) image.processing_started_at = datetime.now(timezone.utc)
t_start = time.time() t_start = time.time()
@@ -93,172 +87,176 @@ async def process_image_pipeline(
errors: list[str] = [] errors: list[str] = []
file_path = image.file_path file_path = image.file_path
# ════════════════════════════════════════════════════════════
# ÉTAPE 1 — Extraction EXIF
# ════════════════════════════════════════════════════════════
try: try:
logger.info("pipeline.step.start", extra={"image_id": image_id, "step": "exif", "step_num": "1/3"}) # ════════════════════════════════════════════════════════
t0 = time.time() # ÉTAPE 1 — Extraction EXIF
# ════════════════════════════════════════════════════════
# Maintenant async et utilise le backend try:
exif = await extract_exif(file_path) logger.info("pipeline.step.start", extra={"image_id": image_id, "step": "exif", "step_num": "1/3"})
t0 = time.time()
image.exif_raw = exif.get("raw") exif = await extract_exif(file_path)
image.exif_make = exif.get("make")
image.exif_model = exif.get("model")
image.exif_lens = exif.get("lens")
image.exif_taken_at = exif.get("taken_at")
image.exif_gps_lat = exif.get("gps_lat")
image.exif_gps_lon = exif.get("gps_lon")
image.exif_altitude = exif.get("altitude")
image.exif_iso = exif.get("iso")
image.exif_aperture = exif.get("aperture")
image.exif_shutter = exif.get("shutter")
image.exif_focal = exif.get("focal")
image.exif_flash = exif.get("flash")
image.exif_orientation = exif.get("orientation")
image.exif_software = exif.get("software")
await db.commit() image.exif_raw = exif.get("raw")
elapsed = int((time.time() - t0) * 1000) image.exif_make = exif.get("make")
hub_pipeline_step_duration.labels(step="exif").observe(time.time() - t0) image.exif_model = exif.get("model")
image.exif_lens = exif.get("lens")
logger.info("pipeline.step.done", extra={"image_id": image_id, "step": "exif", "duration_ms": elapsed, "camera": image.exif_make}) image.exif_taken_at = exif.get("taken_at")
await _publish_event(redis, image_id, "step.completed", { image.exif_gps_lat = exif.get("gps_lat")
"step": "exif", "duration_ms": elapsed, "camera": image.exif_make, image.exif_gps_lon = exif.get("gps_lon")
}) image.exif_altitude = exif.get("altitude")
image.exif_iso = exif.get("iso")
image.exif_aperture = exif.get("aperture")
image.exif_shutter = exif.get("shutter")
image.exif_focal = exif.get("focal")
image.exif_flash = exif.get("flash")
image.exif_orientation = exif.get("orientation")
image.exif_software = exif.get("software")
except Exception as e: await db.commit()
msg = f"EXIF : {str(e)}" elapsed = int((time.time() - t0) * 1000)
errors.append(msg) hub_pipeline_step_duration.labels(step="exif").observe(time.time() - t0)
hub_pipeline_errors.labels(step="exif").inc()
logger.error("pipeline.step.error", extra={"image_id": image_id, "step": "exif", "error": str(e)})
# ════════════════════════════════════════════════════════════ logger.info("pipeline.step.done", extra={"image_id": image_id, "step": "exif", "duration_ms": elapsed, "camera": image.exif_make})
# ÉTAPE 2 — OCR await _publish_event(redis, image_id, "step.completed", {
# ════════════════════════════════════════════════════════════ "step": "exif", "duration_ms": elapsed, "camera": image.exif_make,
try: })
logger.info("pipeline.step.start", extra={"image_id": image_id, "step": "ocr", "step_num": "2/3"})
t0 = time.time()
# Maintenant async et utilise le backend
ocr = await extract_text(file_path)
# Fallback AI si OCR classique échoue ou ne trouve rien except Exception as e:
if not ocr.get("has_text", False): msg = f"EXIF : {str(e)}"
logger.info("pipeline.ocr.fallback", extra={"image_id": image_id, "reason": "tesseract_empty"}) errors.append(msg)
ai_ocr = await extract_text_with_ai(file_path) hub_pipeline_errors.labels(step="exif").inc()
logger.error("pipeline.step.error", extra={"image_id": image_id, "step": "exif", "error": str(e)})
if ai_ocr.get("has_text"): # ════════════════════════════════════════════════════════
ocr = ai_ocr # ÉTAPE 2 — OCR
logger.info("pipeline.ocr.fallback_success", extra={"image_id": image_id, "chars": len(ocr.get("text", ""))}) # ════════════════════════════════════════════════════════
else: try:
logger.info("pipeline.ocr.fallback_empty", extra={"image_id": image_id}) logger.info("pipeline.step.start", extra={"image_id": image_id, "step": "ocr", "step_num": "2/3"})
t0 = time.time()
image.ocr_text = ocr.get("text") ocr = await extract_text(file_path)
image.ocr_language = ocr.get("language")
image.ocr_confidence = ocr.get("confidence")
image.ocr_has_text = ocr.get("has_text", False)
await db.commit() if not ocr.get("has_text", False):
elapsed = int((time.time() - t0) * 1000) logger.info("pipeline.ocr.fallback", extra={"image_id": image_id, "reason": "tesseract_empty"})
hub_pipeline_step_duration.labels(step="ocr").observe(time.time() - t0) ai_ocr = await extract_text_with_ai(file_path)
logger.info("pipeline.step.done", extra={"image_id": image_id, "step": "ocr", "duration_ms": elapsed, "has_text": image.ocr_has_text}) if ai_ocr.get("has_text"):
await _publish_event(redis, image_id, "step.completed", { ocr = ai_ocr
"step": "ocr", "duration_ms": elapsed, "has_text": image.ocr_has_text, logger.info("pipeline.ocr.fallback_success", extra={"image_id": image_id, "chars": len(ocr.get("text", ""))})
}) else:
logger.info("pipeline.ocr.fallback_empty", extra={"image_id": image_id})
except Exception as e: image.ocr_text = ocr.get("text")
msg = f"OCR : {str(e)}" image.ocr_language = ocr.get("language")
errors.append(msg) image.ocr_confidence = ocr.get("confidence")
hub_pipeline_errors.labels(step="ocr").inc() image.ocr_has_text = ocr.get("has_text", False)
logger.error("pipeline.step.error", extra={"image_id": image_id, "step": "ocr", "error": str(e)})
# ════════════════════════════════════════════════════════════ await db.commit()
# ÉTAPE 3 — Vision AI (description + tags) elapsed = int((time.time() - t0) * 1000)
# ════════════════════════════════════════════════════════════ hub_pipeline_step_duration.labels(step="ocr").observe(time.time() - t0)
try:
logger.info("pipeline.step.start", extra={"image_id": image_id, "step": "ai", "step_num": "3/3"})
t0 = time.time()
# Charger les préférences AI du client logger.info("pipeline.step.done", extra={"image_id": image_id, "step": "ocr", "duration_ms": elapsed, "has_text": image.ocr_has_text})
provider_override = None await _publish_event(redis, image_id, "step.completed", {
model_override = None "step": "ocr", "duration_ms": elapsed, "has_text": image.ocr_has_text,
if image.client_id: })
from app.models.client import APIClient
client_result = await db.execute( except Exception as e:
select(APIClient).where(APIClient.id == image.client_id) msg = f"OCR : {str(e)}"
errors.append(msg)
hub_pipeline_errors.labels(step="ocr").inc()
logger.error("pipeline.step.error", extra={"image_id": image_id, "step": "ocr", "error": str(e)})
# ════════════════════════════════════════════════════════
# ÉTAPE 3 — Vision AI (description + tags)
# ════════════════════════════════════════════════════════
try:
logger.info("pipeline.step.start", extra={"image_id": image_id, "step": "ai", "step_num": "3/3"})
t0 = time.time()
provider_override = None
model_override = None
if image.client_id:
from app.models.client import APIClient
client_result = await db.execute(
select(APIClient).where(APIClient.id == image.client_id)
)
owner = client_result.scalar_one_or_none()
if owner:
provider_override = owner.ai_provider
model_override = owner.ai_model
ai = await analyze_image(
file_path=file_path,
ocr_hint=image.ocr_text,
provider_override=provider_override,
model_override=model_override,
) )
owner = client_result.scalar_one_or_none()
if owner:
provider_override = owner.ai_provider
model_override = owner.ai_model
ai = await analyze_image( image.ai_description = ai.get("description")
file_path=file_path, image.ai_tags = ai.get("tags", [])
ocr_hint=image.ocr_text, image.ai_confidence = ai.get("confidence")
provider_override=provider_override, image.ai_model_used = ai.get("model")
model_override=model_override, image.ai_processed_at = datetime.now(timezone.utc)
) image.ai_prompt_tokens = ai.get("prompt_tokens")
image.ai_output_tokens = ai.get("output_tokens")
image.ai_description = ai.get("description") await db.commit()
image.ai_tags = ai.get("tags", []) elapsed = int((time.time() - t0) * 1000)
image.ai_confidence = ai.get("confidence") hub_pipeline_step_duration.labels(step="ai").observe(time.time() - t0)
image.ai_model_used = ai.get("model")
image.ai_processed_at = datetime.now(timezone.utc)
image.ai_prompt_tokens = ai.get("prompt_tokens")
image.ai_output_tokens = ai.get("output_tokens")
await db.commit() if image.ai_prompt_tokens or image.ai_output_tokens:
elapsed = int((time.time() - t0) * 1000) total_tokens = (image.ai_prompt_tokens or 0) + (image.ai_output_tokens or 0)
hub_pipeline_step_duration.labels(step="ai").observe(time.time() - t0) hub_ai_tokens_consumed.labels(
client_id=image.client_id,
# Token metrics model=image.ai_model_used or "unknown"
if image.ai_prompt_tokens or image.ai_output_tokens: ).inc(total_tokens)
total_tokens = (image.ai_prompt_tokens or 0) + (image.ai_output_tokens or 0)
hub_ai_tokens_consumed.labels(
client_id=image.client_id,
model=image.ai_model_used or "unknown"
).inc(total_tokens)
logger.info("pipeline.step.done", extra={"image_id": image_id, "step": "ai", "duration_ms": elapsed, "tags_count": len(image.ai_tags or [])}) logger.info("pipeline.step.done", extra={"image_id": image_id, "step": "ai", "duration_ms": elapsed, "tags_count": len(image.ai_tags or [])})
await _publish_event(redis, image_id, "step.completed", { await _publish_event(redis, image_id, "step.completed", {
"step": "ai", "duration_ms": elapsed, "tags_count": len(image.ai_tags or []), "step": "ai", "duration_ms": elapsed, "tags_count": len(image.ai_tags or []),
}) })
except Exception as e: except Exception as e:
msg = f"AI Vision : {str(e)}" msg = f"AI Vision : {str(e)}"
errors.append(msg) errors.append(msg)
hub_pipeline_errors.labels(step="ai").inc() hub_pipeline_errors.labels(step="ai").inc()
logger.error("pipeline.step.error", extra={"image_id": image_id, "step": "ai", "error": str(e)}) logger.error("pipeline.step.error", extra={"image_id": image_id, "step": "ai", "error": str(e)})
# ════════════════════════════════════════════════════════════ finally:
# FINALISATION # ════════════════════════════════════════════════════════
# ════════════════════════════════════════════════════════════ # FINALISATION — toujours exécuté, même après un crash
image.processing_done_at = datetime.now(timezone.utc) # ════════════════════════════════════════════════════════
try:
image.processing_done_at = datetime.now(timezone.utc)
if errors: if errors:
if image.ai_description: if image.ai_description:
image.processing_status = ProcessingStatus.DONE image.processing_status = ProcessingStatus.DONE
image.processing_error = f"Avertissements : {'; '.join(errors)}" image.processing_error = f"Avertissements : {'; '.join(errors)}"
else: else:
image.processing_status = ProcessingStatus.ERROR image.processing_status = ProcessingStatus.ERROR
image.processing_error = "; ".join(errors) image.processing_error = "; ".join(errors)
else: else:
image.processing_status = ProcessingStatus.DONE image.processing_status = ProcessingStatus.DONE
image.processing_error = None image.processing_error = None
await db.commit() await db.commit()
hub_pipeline_duration.observe(time.time() - t_start) hub_pipeline_duration.observe(time.time() - t_start)
logger.info("pipeline.completed", extra={
"image_id": image_id,
"status": image.processing_status.value,
"errors": len(errors),
})
if errors: logger.info("pipeline.completed", extra={
await _publish_event(redis, image_id, "pipeline.error", {"errors": errors}) "image_id": image_id,
else: "status": image.processing_status.value,
await _publish_event(redis, image_id, "pipeline.done") "errors": len(errors),
})
if errors:
await _publish_event(redis, image_id, "pipeline.error", {"errors": errors})
else:
await _publish_event(redis, image_id, "pipeline.done")
except Exception as final_error:
# Si même la finalisation échoue, log seulement — ne pas laisser l'image bloquée
logger.critical("pipeline.finalization_failed", extra={
"image_id": image_id,
"error": str(final_error),
})