updated import script to have 8h standing import job

This commit is contained in:
Bryan Van Deusen
2025-12-21 19:43:48 -05:00
parent 2b21686127
commit 4789e19972
2 changed files with 316 additions and 249 deletions
+1 -1
View File
@@ -24,4 +24,4 @@ COPY entrypoint.sh /entrypoint.sh
RUN chmod +x /entrypoint.sh RUN chmod +x /entrypoint.sh
EXPOSE 5000 EXPOSE 5000
ENTRYPOINT ["/entrypoint.sh"] ENTRYPOINT ["/entrypoint.sh
+230 -163
View File
@@ -1,72 +1,174 @@
# image_import_worker.py # image_import_worker.py
import os import os
import time import time
import logging
from dataclasses import dataclass
from typing import Callable, Optional
from sqlalchemy.exc import OperationalError from sqlalchemy.exc import OperationalError
from app import create_app from app import create_app
from app.utils.image_importer import import_images_task from app.utils.image_importer import import_images_task
# -----------------------------
# Config
# -----------------------------
THUMBNAIL_FLAG = "/import/thumbnail.flag" THUMBNAIL_FLAG = "/import/thumbnail.flag"
TRIGGER_FLAG = "/import/trigger.flag" TRIGGER_FLAG = "/import/trigger.flag"
SOURCE_DIR = "/import" SOURCE_DIR = "/import"
DEST_DIR = "/images" DEST_DIR = "/images"
CHECK_INTERVAL = 10 # seconds
# Verbosity controls (set via environment) CHECK_INTERVAL = int(os.getenv("CHECK_INTERVAL", "10")) # seconds (polling for flags)
# Run a periodic import even without trigger.flag
IMPORT_EVERY_SECONDS = int(os.getenv("IMPORT_EVERY_SECONDS", str(8 * 60 * 60))) # default 8h
# Verbosity controls (thumb regen)
THUMBS_VERBOSE = os.getenv("THUMBS_VERBOSE", "0").lower() in ("1", "true", "yes") THUMBS_VERBOSE = os.getenv("THUMBS_VERBOSE", "0").lower() in ("1", "true", "yes")
THUMBS_LOG_EVERY = int(os.getenv("THUMBS_LOG_EVERY", "50")) # log every N images if verbose THUMBS_LOG_EVERY = int(os.getenv("THUMBS_LOG_EVERY", "50"))
THUMBS_BATCH_SIZE = int(os.getenv("THUMBS_BATCH_SIZE", "500")) # DB chunk size per commit THUMBS_BATCH_SIZE = int(os.getenv("THUMBS_BATCH_SIZE", "500"))
MAX_RETRIES = int(os.getenv("MAX_RETRIES", "3"))
# -----------------------------
# Logging
# -----------------------------
logging.basicConfig(
level=os.getenv("LOG_LEVEL", "INFO").upper(),
format="%(asctime)s %(levelname)s %(message)s",
)
log = logging.getLogger("image-import-worker")
app = create_app() app = create_app()
def monitor_and_import(): @dataclass(frozen=True)
with app.app_context(): class FlagJob:
print("[Image Importer] Monitoring for trigger flags... (CHECK_INTERVAL=%ss)" % CHECK_INTERVAL, flush=True) name: str
flag_path: str
while True: @property
did_work = False def run_path(self) -> str:
return self.flag_path + ".run"
# ------------------------------------------------------------------ @property
# THUMBNAIL REGEN (PRIORITIZED) — chunked loop, detailed progress def err_path(self) -> str:
# ------------------------------------------------------------------ return self.flag_path + ".err"
if os.path.exists(THUMBNAIL_FLAG):
print("[Image Importer] Thumbnail regeneration flag detected.", flush=True)
RUN_FLAG = THUMBNAIL_FLAG + ".run"
ERR_FLAG = THUMBNAIL_FLAG + ".err"
# Claim atomically so only one worker runs def claim_job(job: FlagJob) -> bool:
"""
Atomically claim a job by renaming <flag> -> <flag>.run.
Returns True if claimed, False otherwise.
"""
try: try:
os.replace(THUMBNAIL_FLAG, RUN_FLAG) os.replace(job.flag_path, job.run_path)
print(f"[Image Importer] Claimed thumbnail job -> {RUN_FLAG}", flush=True) log.info("[%s] Claimed job -> %s", job.name, job.run_path)
return True
except FileNotFoundError:
return False
except Exception as e: except Exception as e:
print(f"[Image Importer] Could not claim thumbnail job: {e}", flush=True) log.warning("[%s] Could not claim job: %s", job.name, e)
time.sleep(CHECK_INTERVAL) return False
continue
max_retries = 3
def complete_job(job: FlagJob) -> None:
"""Remove the .run file on success."""
try:
os.remove(job.run_path)
log.info("[%s] Cleared run flag.", job.name)
except FileNotFoundError:
# If something else cleaned it up, thats fine.
log.info("[%s] Run flag already cleared.", job.name)
except Exception as e:
log.warning("[%s] Could not remove run flag: %s", job.name, e)
def fail_job(job: FlagJob) -> None:
"""Move the .run file to .err on failure."""
try:
os.replace(job.run_path, job.err_path)
log.error("[%s] Marked failure -> %s", job.name, job.err_path)
except FileNotFoundError:
log.error("[%s] Could not mark failure: run flag missing.", job.name)
except Exception as e:
log.error("[%s] Could not mark failure: %s", job.name, e)
def db_ping() -> None:
"""Validate DB session connection quickly."""
from sqlalchemy import text
from app import db
db.session.execute(text("SELECT 1"))
def recover_db_session(dispose_engine: bool = False) -> None:
"""Rollback session and optionally dispose engine pool to force fresh connections."""
try:
from app import db
db.session.rollback()
if dispose_engine:
db.engine.dispose()
except Exception:
pass
def run_with_retries(
job: FlagJob,
fn: Callable[[], None],
*,
dispose_engine_on_operational_error: bool = False,
max_retries: int = MAX_RETRIES,
) -> bool:
attempt = 0 attempt = 0
while attempt < max_retries: while attempt < max_retries:
try: try:
# Catch stale pool conns early
db_ping()
fn()
return True
except OperationalError as e:
attempt += 1
log.warning("[%s] DB error (attempt %d/%d): %s", job.name, attempt, max_retries, e)
recover_db_session(dispose_engine=dispose_engine_on_operational_error)
if attempt >= max_retries:
return False
sleep_time = 2 ** attempt
log.info("[%s] Retrying in %ss...", job.name, sleep_time)
time.sleep(sleep_time)
except Exception as e:
log.exception("[%s] Unexpected error: %s", job.name, e)
recover_db_session(dispose_engine=True)
return False
return False
def do_import() -> None:
result = import_images_task(SOURCE_DIR, DEST_DIR)
log.info("[Import] %s", result)
def do_thumbnail_regen() -> None:
from pathlib import Path from pathlib import Path
from sqlalchemy import text
from app import db from app import db
from app.models import ImageRecord from app.models import ImageRecord
from app.utils.image_importer import generate_thumbnail, generate_video_thumbnail from app.utils.image_importer import generate_thumbnail, generate_video_thumbnail
# Early diagnostics
db.session.execute(text("SELECT 1"))
total = db.session.query(ImageRecord).count() total = db.session.query(ImageRecord).count()
print(f"[Thumbs] Starting regen; ImageRecord count = {total}", flush=True) log.info("[Thumbs] Starting regen; ImageRecord count = %d", total)
images_root = Path("/images").resolve() images_root = Path(DEST_DIR).resolve()
batch_size = THUMBS_BATCH_SIZE batch_size = THUMBS_BATCH_SIZE
processed = 0 # total processed rows processed = 0
writes = 0 # files written/overwritten writes = 0
path_updates = 0 # DB thumb_path changes path_updates = 0
failures = 0 failures = 0
last_id = 0 last_id = 0
t_start = time.time() t_start = time.time()
@@ -98,7 +200,6 @@ def monitor_and_import():
ext = (img.format or "").lower() ext = (img.format or "").lower()
is_video = ext in ("mp4", "mov") or img.filepath.lower().endswith((".mp4", ".mov")) is_video = ext in ("mp4", "mov") or img.filepath.lower().endswith((".mp4", ".mov"))
# Determine output path for videos if needed
if is_video: if is_video:
out_path = img.thumb_path out_path = img.thumb_path
if not out_path: if not out_path:
@@ -108,7 +209,7 @@ def monitor_and_import():
batch_failures += 1 batch_failures += 1
failures += 1 failures += 1
if THUMBS_VERBOSE: if THUMBS_VERBOSE:
print(f"[Thumbs] SKIP (not under /images): id={img.id} {img.filepath}", flush=True) log.info("[Thumbs] SKIP (not under %s): id=%s %s", images_root, img.id, img.filepath)
continue continue
out_path = str((images_root / "thumbs" / rel).with_suffix(".jpg")) out_path = str((images_root / "thumbs" / rel).with_suffix(".jpg"))
@@ -116,172 +217,138 @@ def monitor_and_import():
else: else:
new_path = generate_thumbnail(img.filepath, overwrite=True) new_path = generate_thumbnail(img.filepath, overwrite=True)
# Count file writes: our helpers return the path on success
if new_path: if new_path:
writes += 1 writes += 1
batch_writes += 1 batch_writes += 1
# Update DB if path changed
if new_path and new_path != img.thumb_path: if new_path and new_path != img.thumb_path:
img.thumb_path = new_path img.thumb_path = new_path
path_updates += 1 path_updates += 1
batch_updates += 1 batch_updates += 1
# Optional per-file log
if THUMBS_VERBOSE and (processed <= 10 or processed % THUMBS_LOG_EVERY == 0): if THUMBS_VERBOSE and (processed <= 10 or processed % THUMBS_LOG_EVERY == 0):
kind = "video" if is_video else "image" kind = "video" if is_video else "image"
print(f"[Thumbs] #{processed} ({kind}) id={img.id} name='{img.filename}' -> {new_path or 'None'}", flush=True) log.info("[Thumbs] #%d (%s) id=%s name='%s' -> %s", processed, kind, img.id, img.filename, new_path or "None")
except Exception as e: except Exception as e:
failures += 1 failures += 1
batch_failures += 1 batch_failures += 1
print(f"[Thumbs] Failed for id={img.id} name='{img.filename}': {e}", flush=True) log.warning("[Thumbs] Failed for id=%s name='%s': %s", img.id, img.filename, e)
# Commit AFTER each chunk; safe for Postgres (no server-side cursor)
db.session.commit() db.session.commit()
last_id = rows[-1].id last_id = rows[-1].id
db.session.expunge_all() # keep memory stable db.session.expunge_all()
# Batch progress
bt = time.time() - bt0 bt = time.time() - bt0
rate = batch_processed / bt if bt > 0 else 0 rate = batch_processed / bt if bt > 0 else 0
print( log.info(
f"[Thumbs] Batch {batch_start_id}-{batch_end_id}: " "[Thumbs] Batch %s-%s: processed=%d writes=%d db_updates=%d failures=%d (%.1f items/s) "
f"processed={batch_processed}, writes={batch_writes}, " "— totals: processed=%d writes=%d db_updates=%d failures=%d (last_id=%d)",
f"db_updates={batch_updates}, failures={batch_failures} " batch_start_id, batch_end_id,
f"({rate:.1f} items/s) — totals: processed={processed}, writes={writes}, " batch_processed, batch_writes, batch_updates, batch_failures, rate,
f"db_updates={path_updates}, failures={failures} (last_id={last_id})", processed, writes, path_updates, failures, last_id,
flush=True
) )
# Final summary
elapsed = time.time() - t_start elapsed = time.time() - t_start
overall_rate = processed / elapsed if elapsed > 0 else 0 overall_rate = processed / elapsed if elapsed > 0 else 0
print( log.info(
f"[Image Importer] Thumbnail regen COMPLETE in {elapsed:.1f}s — " "[Thumbs] COMPLETE in %.1fs — processed=%d writes=%d db_updates=%d failures=%d (%.1f items/s).",
f"processed={processed}, writes={writes}, db_updates={path_updates}, failures={failures} " elapsed, processed, writes, path_updates, failures, overall_rate,
f"({overall_rate:.1f} items/s).",
flush=True
) )
# Success — remove the .run flag and exit
try:
os.remove(RUN_FLAG)
print("[Image Importer] Thumbnail .run flag cleared.", flush=True)
except Exception as e:
print(f"[Image Importer] Could not remove .run flag: {e}", flush=True)
break # success
except OperationalError as e: def handle_flag_job(job: FlagJob, fn: Callable[[], None], *, dispose_engine_on_operational_error: bool = False) -> bool:
attempt += 1 """
print(f"[Image Importer] DB error during thumbnail regen (attempt {attempt}): {e}", flush=True) If <flag> exists, claim it and run fn with retries. Returns True if it did anything.
# Recover the session for the next attempt """
try: if not os.path.exists(job.flag_path):
from app import db return False
db.session.rollback()
except Exception:
pass
time.sleep(2 ** attempt)
if attempt >= max_retries:
try:
os.replace(RUN_FLAG, ERR_FLAG)
print(f"[Image Importer] Moved thumbnail flag to {ERR_FLAG}", flush=True)
except Exception as re:
print(f"[Image Importer] Could not mark error flag: {re}", flush=True)
except Exception as e:
print(f"[Image Importer] Unexpected error during thumbnail regen: {e}", flush=True)
try:
os.replace(RUN_FLAG, ERR_FLAG)
print(f"[Image Importer] Moved thumbnail flag to {ERR_FLAG}", flush=True)
except Exception as re:
print(f"[Image Importer] Could not mark error flag: {re}", flush=True)
break
did_work = True # handled a job (success or fail) log.info("[%s] Flag detected: %s", job.name, job.flag_path)
# ------------------------------------------------------------------ if not claim_job(job):
# IMPORT TRIGGER (robust: claim -> run -> clear/err; rollback on fail) return True # it existed, but someone else may have claimed it; still counts as "did work"
# ------------------------------------------------------------------
if os.path.exists(TRIGGER_FLAG):
print("[Image Importer] Import flag found. Starting import...", flush=True)
RUN_FLAG = TRIGGER_FLAG + ".run" ok = run_with_retries(
ERR_FLAG = TRIGGER_FLAG + ".err" job,
fn,
# Claim atomically so only one worker takes it dispose_engine_on_operational_error=dispose_engine_on_operational_error,
try: )
os.replace(TRIGGER_FLAG, RUN_FLAG) if ok:
print(f"[Image Importer] Claimed import job -> {RUN_FLAG}", flush=True) complete_job(job)
except Exception as e:
print(f"[Image Importer] Could not claim import job: {e}", flush=True)
time.sleep(CHECK_INTERVAL)
continue
max_retries = 3
attempt = 0
while attempt < max_retries:
try:
from sqlalchemy import text
from app import db
# Fast DB ping to catch stale pool conns
db.session.execute(text("SELECT 1"))
# Run the import
result = import_images_task(SOURCE_DIR, DEST_DIR)
print(f"[Image Importer] {result}", flush=True)
# Success — remove the .run flag and exit
try:
os.remove(RUN_FLAG)
print("[Image Importer] Import .run flag cleared.", flush=True)
except Exception as e:
print(f"[Image Importer] Could not remove import .run flag: {e}", flush=True)
break # success
except OperationalError as e:
attempt += 1
print(f"[Image Importer] DB error during import (attempt {attempt}): {e}", flush=True)
# IMPORTANT: rollback failed transaction & drop pool to force clean conns
try:
from app import db
db.session.rollback()
db.engine.dispose()
except Exception:
pass
if attempt >= max_retries:
try:
os.replace(RUN_FLAG, ERR_FLAG)
print(f"[Image Importer] Moved import flag to {ERR_FLAG}", flush=True)
except Exception as re:
print(f"[Image Importer] Could not mark import error flag: {re}", flush=True)
else: else:
sleep_time = 2 ** attempt fail_job(job)
print(f"[Image Importer] Retrying in {sleep_time} seconds...", flush=True)
time.sleep(sleep_time)
except Exception as e: return True
print(f"[Image Importer] Unexpected error during import: {e}", flush=True)
# Make sure the session is usable next time
def monitor_and_import() -> None:
thumbnail_job = FlagJob(name="Thumbs", flag_path=THUMBNAIL_FLAG)
import_job = FlagJob(name="Import", flag_path=TRIGGER_FLAG)
# next time we should run periodic import (monotonic avoids wall-clock jumps)
next_periodic_import = time.monotonic() + IMPORT_EVERY_SECONDS
with app.app_context():
log.info(
"[Worker] Started. Poll=%ss, periodic import every=%ss (%.2fh).",
CHECK_INTERVAL,
IMPORT_EVERY_SECONDS,
IMPORT_EVERY_SECONDS / 3600.0,
)
while True:
did_work = False
# 1) Thumbnail regen is prioritized
did_work |= handle_flag_job(thumbnail_job, do_thumbnail_regen)
# 2) Flag-triggered import
did_work |= handle_flag_job(
import_job,
do_import,
dispose_engine_on_operational_error=True, # matches your original logic for import
)
# 3) Periodic import (every 8h by default) — uses the same .run lock convention
now = time.monotonic()
if now >= next_periodic_import:
next_periodic_import = now + IMPORT_EVERY_SECONDS
# Dont run if an import is already in progress/failed state
if os.path.exists(import_job.run_path):
log.info("[Import] Periodic run skipped (import already running).")
elif os.path.exists(import_job.err_path):
log.info("[Import] Periodic run skipped (import in error state: %s).", import_job.err_path)
else:
# Create/claim an import run lock without needing trigger.flag
# (We create the .run file atomically by replacing a temp file.)
tmp = import_job.run_path + ".tmp"
try: try:
from app import db with open(tmp, "w") as f:
db.session.rollback() f.write("periodic\n")
db.engine.dispose() os.replace(tmp, import_job.run_path)
except Exception: log.info("[Import] Periodic run claimed -> %s", import_job.run_path)
pass
try: ok = run_with_retries(
os.replace(RUN_FLAG, ERR_FLAG) import_job,
print(f"[Image Importer] Moved import flag to {ERR_FLAG}", flush=True) do_import,
except Exception as re: dispose_engine_on_operational_error=True,
print(f"[Image Importer] Could not mark import error flag: {re}", flush=True) )
break if ok:
complete_job(import_job)
else:
fail_job(import_job)
did_work = True did_work = True
except Exception as e:
log.warning("[Import] Could not start periodic run: %s", e)
try:
if os.path.exists(tmp):
os.remove(tmp)
except Exception:
pass
# ------------------------------------------------------------------
# IDLE SLEEP
# ------------------------------------------------------------------
if not did_work: if not did_work:
time.sleep(CHECK_INTERVAL) time.sleep(CHECK_INTERVAL)