add structured logging and admin diagnostics to serve

- bincio.serve logger wired into uvicorn output: rebuild steps, upload
  errors, strava-zip progress all now appear in the server log
- _trigger_rebuild: capture stdout/stderr, log errors instead of silently
  discarding; exceptions logged with traceback instead of swallowed
- upload handler: log per-file errors with traceback; include error detail
  in the SSE event sent back to the browser
- strava-zip handler: log imported/error counts on completion
- GET /api/admin/users/{handle}/diag: snapshot of a user's data dir
  (file counts, sizes, index activity counts, pending uploads)
- POST /api/admin/users/{handle}/rebuild-sync: blocking rebuild that
  returns full stdout/stderr — for debugging without SSH log access
- Admin page: Diag button per user opens a modal showing the diag JSON
This commit is contained in:
Davide Scaini
2026-04-14 22:53:31 +02:00
parent fcc70a8d90
commit 1e30f85bdc
3 changed files with 216 additions and 20 deletions
+8 -1
View File
@@ -76,4 +76,11 @@ def serve(data_dir: str, site_dir: Optional[str], host: str, port: int,
console.print(f" Users: [dim]unlimited[/dim]") console.print(f" Users: [dim]unlimited[/dim]")
console.print() console.print()
uvicorn.run(srv.app, host=host, port=port, log_level="info") log_config = uvicorn.config.LOGGING_CONFIG.copy()
# Make bincio.serve logger emit at INFO through uvicorn's handler
log_config["loggers"]["bincio.serve"] = {
"handlers": ["default"],
"level": "INFO",
"propagate": False,
}
uvicorn.run(srv.app, host=host, port=port, log_level="info", log_config=log_config)
+169 -15
View File
@@ -9,6 +9,7 @@ Run via `bincio serve` CLI command.
from __future__ import annotations from __future__ import annotations
import json import json
import logging
import re import re
import secrets import secrets
import shutil import shutil
@@ -19,6 +20,8 @@ import uuid
from pathlib import Path from pathlib import Path
from typing import Any, Optional from typing import Any, Optional
log = logging.getLogger("bincio.serve")
from fastapi import Cookie, FastAPI, File, Form, HTTPException, Request, Response, UploadFile from fastapi import Cookie, FastAPI, File, Form, HTTPException, Request, Response, UploadFile
from fastapi.responses import RedirectResponse, StreamingResponse from fastapi.responses import RedirectResponse, StreamingResponse
from fastapi.middleware.cors import CORSMiddleware from fastapi.middleware.cors import CORSMiddleware
@@ -246,37 +249,52 @@ def _trigger_rebuild(handle: str) -> None:
# Fast: only update data, skip Astro build. # Fast: only update data, skip Astro build.
# Serialised with the same lock: merge_all wipes and recreates # Serialised with the same lock: merge_all wipes and recreates
# _merged/activities/ — concurrent runs would corrupt each other. # _merged/activities/ — concurrent runs would corrupt each other.
log.info("rebuild[%s]: merge-only (no webroot)", _handle)
with _rebuild_lock: with _rebuild_lock:
subprocess.run( result = subprocess.run(
[uv, "run", "bincio", "render", [uv, "run", "bincio", "render",
"--data-dir", _data_dir, "--data-dir", _data_dir,
"--site-dir", _site_dir, "--site-dir", _site_dir,
"--handle", _handle, "--handle", _handle,
"--no-build"], "--no-build"],
stdout=subprocess.DEVNULL, capture_output=True,
stderr=subprocess.DEVNULL, text=True,
) )
if result.returncode != 0:
log.error("rebuild[%s]: merge failed (rc=%d):\n%s\n%s",
_handle, result.returncode, result.stdout, result.stderr)
else:
log.info("rebuild[%s]: merge done", _handle)
else: else:
# Full build + rsync — serialised so concurrent uploads don't race # Full build + rsync — serialised so concurrent uploads don't race
log.info("rebuild[%s]: full build + rsync to %s", _handle, _webroot)
with _rebuild_lock: with _rebuild_lock:
result = subprocess.run( result = subprocess.run(
[uv, "run", "bincio", "render", [uv, "run", "bincio", "render",
"--data-dir", _data_dir, "--data-dir", _data_dir,
"--site-dir", _site_dir, "--site-dir", _site_dir,
"--handle", _handle], "--handle", _handle],
stdout=subprocess.DEVNULL, capture_output=True,
stderr=subprocess.DEVNULL, text=True,
) )
if result.returncode == 0: if result.returncode != 0:
# Rsync built site to nginx webroot log.error("rebuild[%s]: build failed (rc=%d):\n%s\n%s",
subprocess.run( _handle, result.returncode, result.stdout, result.stderr)
else:
log.info("rebuild[%s]: build done, rsyncing", _handle)
rsync = subprocess.run(
["rsync", "-a", "--delete", ["rsync", "-a", "--delete",
f"{_site_dir}/dist/", _webroot + "/"], f"{_site_dir}/dist/", _webroot + "/"],
stdout=subprocess.DEVNULL, capture_output=True,
stderr=subprocess.DEVNULL, text=True,
) )
if rsync.returncode != 0:
log.error("rebuild[%s]: rsync failed (rc=%d):\n%s\n%s",
_handle, rsync.returncode, rsync.stdout, rsync.stderr)
else:
log.info("rebuild[%s]: rsync done", _handle)
except Exception: except Exception:
pass # rebuild failure must never affect the calling request log.exception("rebuild[%s]: unexpected error", _handle)
threading.Thread(target=_run, daemon=True).start() threading.Thread(target=_run, daemon=True).start()
@@ -551,6 +569,127 @@ async def admin_rebuild(
return JSONResponse({"ok": True}) return JSONResponse({"ok": True})
@app.post("/api/admin/users/{handle}/rebuild-sync")
async def admin_rebuild_sync(
handle: str,
bincio_session: Optional[str] = Cookie(default=None),
) -> JSONResponse:
"""Run merge+rebuild synchronously and return full output. Admin only.
Unlike /rebuild (fire-and-forget), this blocks until done and returns stdout/stderr.
Use for debugging when you need to see what went wrong.
"""
_require_admin(bincio_session)
user_dir = _get_data_dir() / handle
if not user_dir.is_dir():
raise HTTPException(404, f"No data directory for user '{handle}'")
if site_dir is None:
raise HTTPException(503, "Server has no --site-dir configured; rebuild not available")
uv = shutil.which("uv") or str(Path.home() / ".local" / "bin" / "uv")
cmd = [uv, "run", "bincio", "render",
"--data-dir", str(data_dir),
"--site-dir", str(site_dir),
"--handle", handle,
"--no-build"]
if webroot:
cmd = [uv, "run", "bincio", "render",
"--data-dir", str(data_dir),
"--site-dir", str(site_dir),
"--handle", handle]
result = subprocess.run(cmd, capture_output=True, text=True, timeout=300)
resp: dict[str, Any] = {
"ok": result.returncode == 0,
"returncode": result.returncode,
"stdout": result.stdout,
"stderr": result.stderr,
}
if result.returncode == 0 and webroot:
rsync = subprocess.run(
["rsync", "-a", "--delete", f"{site_dir}/dist/", str(webroot) + "/"],
capture_output=True, text=True, timeout=120,
)
resp["rsync_returncode"] = rsync.returncode
resp["rsync_stdout"] = rsync.stdout
resp["rsync_stderr"] = rsync.stderr
resp["ok"] = rsync.returncode == 0
return JSONResponse(resp)
@app.get("/api/admin/users/{handle}/diag")
async def admin_diag(
handle: str,
bincio_session: Optional[str] = Cookie(default=None),
) -> JSONResponse:
"""Return a diagnostic snapshot of a user's data directory. Admin only."""
_require_admin(bincio_session)
user_dir = _get_data_dir() / handle
if not user_dir.is_dir():
raise HTTPException(404, f"No data directory for user '{handle}'")
def _count(path: Path, glob: str = "*") -> int:
return sum(1 for f in path.glob(glob) if f.is_file()) if path.exists() else 0
def _size_mb(path: Path) -> float:
if not path.exists():
return 0.0
return sum(f.stat().st_size for f in path.rglob("*") if f.is_file()) / 1_048_576
activities_dir = user_dir / "activities"
merged_dir = user_dir / "_merged"
originals_dir = user_dir / "originals"
uploads_dir = user_dir / "_uploads"
merged_index = merged_dir / "index.json"
root_index = user_dir / "index.json"
merged_activity_count: int | None = None
if merged_index.exists():
try:
idx = json.loads(merged_index.read_text())
merged_activity_count = len(idx.get("activities", []))
except Exception:
merged_activity_count = -1
root_activity_count: int | None = None
if root_index.exists():
try:
idx = json.loads(root_index.read_text())
root_activity_count = len(idx.get("activities", []))
except Exception:
root_activity_count = -1
return JSONResponse({
"handle": handle,
"user_dir": str(user_dir),
"activities": {
"json_files": _count(activities_dir, "*.json"),
"geojson_files": _count(activities_dir, "*.geojson"),
"size_mb": round(_size_mb(activities_dir), 2),
},
"originals": {
"exists": originals_dir.exists(),
"size_mb": round(_size_mb(originals_dir), 2),
"strava_originals": _count(originals_dir / "strava", "*.json") if (originals_dir / "strava").exists() else 0,
},
"merged": {
"exists": merged_dir.exists(),
"activity_count_in_index": merged_activity_count,
"size_mb": round(_size_mb(merged_dir), 2),
},
"root_index": {
"exists": root_index.exists(),
"activity_count": root_activity_count,
},
"pending_uploads": _count(uploads_dir),
"dedup_cache_exists": (user_dir / ".bincio_cache.json").exists(),
"athlete_json_exists": (user_dir / "athlete.json").exists(),
})
def _wipe_user_activities(user_dir: Path) -> int: def _wipe_user_activities(user_dir: Path) -> int:
"""Delete all extracted activity files and caches for a user. """Delete all extracted activity files and caches for a user.
@@ -937,9 +1076,10 @@ async def upload_activity(
added += 1 added += 1
any_added = True any_added = True
yield f"data: {json.dumps({'type': 'progress', 'n': n, 'total': total_files, 'name': name, 'status': 'imported'})}\n\n" yield f"data: {json.dumps({'type': 'progress', 'n': n, 'total': total_files, 'name': name, 'status': 'imported'})}\n\n"
except Exception: except Exception as exc:
errors += 1 errors += 1
yield f"data: {json.dumps({'type': 'progress', 'n': n, 'total': total_files, 'name': name, 'status': 'error'})}\n\n" log.error("upload[%s]: failed to process %s: %s", user.handle, name, exc, exc_info=True)
yield f"data: {json.dumps({'type': 'progress', 'n': n, 'total': total_files, 'name': name, 'status': 'error', 'detail': str(exc)})}\n\n"
finally: finally:
if not kept: if not kept:
staged.unlink(missing_ok=True) staged.unlink(missing_ok=True)
@@ -999,18 +1139,32 @@ async def upload_strava_zip(
from bincio.extract.strava_zip import strava_zip_iter from bincio.extract.strava_zip import strava_zip_iter
from bincio.render.merge import merge_all from bincio.render.merge import merge_all
log.info("strava-zip[%s]: received %s, privacy=%s", user.handle, file.filename, privacy)
def event_stream(): def event_stream():
any_imported = False any_imported = False
imported_count = 0
error_count = 0
try: try:
for event in strava_zip_iter(zip_path, dd, privacy=privacy): for event in strava_zip_iter(zip_path, dd, privacy=privacy):
yield f"data: {json.dumps(event)}\n\n" yield f"data: {json.dumps(event)}\n\n"
if event.get("type") == "progress" and event.get("status") == "imported": if event.get("type") == "progress":
any_imported = True status = event.get("status")
if status == "imported":
any_imported = True
imported_count += 1
elif status == "error":
error_count += 1
log.warning("strava-zip[%s]: error on %s: %s",
user.handle, event.get("name"), event.get("detail", ""))
if event.get("type") == "done": if event.get("type") == "done":
log.info("strava-zip[%s]: done — imported=%d errors=%d",
user.handle, imported_count, error_count)
if any_imported: if any_imported:
merge_all(dd) merge_all(dd)
_trigger_rebuild(user.handle) _trigger_rebuild(user.handle)
except Exception as exc: except Exception as exc:
log.error("strava-zip[%s]: fatal error: %s", user.handle, exc, exc_info=True)
yield f"data: {json.dumps({'type': 'error', 'message': str(exc)})}\n\n" yield f"data: {json.dumps({'type': 'error', 'message': str(exc)})}\n\n"
finally: finally:
zip_path.unlink(missing_ok=True) zip_path.unlink(missing_ok=True)
+39 -4
View File
@@ -31,6 +31,15 @@ import Base from '../../layouts/Base.astro';
</table> </table>
</div> </div>
<!-- Diag modal -->
<dialog id="diag-dialog" class="rounded-xl bg-zinc-900 border border-zinc-700 p-6 text-white max-w-2xl w-full backdrop:bg-black/60">
<div class="flex items-center justify-between mb-4">
<h3 class="font-semibold text-sm">Data directory snapshot — <span id="diag-handle" class="text-zinc-400 font-mono"></span></h3>
<button id="diag-close" class="text-zinc-500 hover:text-zinc-200 text-xs px-2 py-1 rounded bg-zinc-800">Close</button>
</div>
<pre id="diag-output" class="text-xs font-mono bg-zinc-950 rounded p-4 overflow-auto max-h-96 text-green-300 whitespace-pre-wrap"></pre>
</dialog>
<!-- Confirmation dialog --> <!-- Confirmation dialog -->
<dialog id="confirm-dialog" class="rounded-xl bg-zinc-900 border border-zinc-700 p-6 text-white max-w-sm w-full backdrop:bg-black/60"> <dialog id="confirm-dialog" class="rounded-xl bg-zinc-900 border border-zinc-700 p-6 text-white max-w-sm w-full backdrop:bg-black/60">
<p class="text-sm text-zinc-300 mb-1">Reset all data for <strong id="confirm-handle" class="text-white"></strong>?</p> <p class="text-sm text-zinc-300 mb-1">Reset all data for <strong id="confirm-handle" class="text-white"></strong>?</p>
@@ -44,10 +53,15 @@ import Base from '../../layouts/Base.astro';
</Base> </Base>
<script> <script>
const overviewEl = document.getElementById('disk-overview')!; const overviewEl = document.getElementById('disk-overview')!;
const tbodyEl = document.getElementById('user-list')!; const tbodyEl = document.getElementById('user-list')!;
const dialog = document.getElementById('confirm-dialog') as HTMLDialogElement; const dialog = document.getElementById('confirm-dialog') as HTMLDialogElement;
const confirmH = document.getElementById('confirm-handle')!; const confirmH = document.getElementById('confirm-handle')!;
const diagDialog = document.getElementById('diag-dialog') as HTMLDialogElement;
const diagHandle = document.getElementById('diag-handle')!;
const diagOutput = document.getElementById('diag-output')!;
document.getElementById('diag-close')!.addEventListener('click', () => diagDialog.close());
diagDialog.addEventListener('click', e => { if (e.target === diagDialog) diagDialog.close(); });
const confirmOk = document.getElementById('confirm-ok')!; const confirmOk = document.getElementById('confirm-ok')!;
const confirmCancel = document.getElementById('confirm-cancel')!; const confirmCancel = document.getElementById('confirm-cancel')!;
@@ -117,6 +131,11 @@ import Base from '../../layouts/Base.astro';
<td class="px-4 py-3 text-right text-zinc-400 tabular-nums">${u.images_mb > 0 ? fmt(u.images_mb) : '—'}</td> <td class="px-4 py-3 text-right text-zinc-400 tabular-nums">${u.images_mb > 0 ? fmt(u.images_mb) : '—'}</td>
<td class="px-4 py-3 text-right"> <td class="px-4 py-3 text-right">
<div class="flex gap-2 justify-end"> <div class="flex gap-2 justify-end">
<button
class="diag-btn text-xs px-3 py-1.5 rounded-lg bg-zinc-800 hover:bg-zinc-700 text-zinc-400 hover:text-zinc-200 transition-colors"
data-handle="${u.handle}"
title="Show diagnostic snapshot of this user's data directory"
>Diag</button>
<button <button
class="rebuild-btn text-xs px-3 py-1.5 rounded-lg bg-zinc-800 hover:bg-zinc-700 text-zinc-400 hover:text-zinc-200 transition-colors" class="rebuild-btn text-xs px-3 py-1.5 rounded-lg bg-zinc-800 hover:bg-zinc-700 text-zinc-400 hover:text-zinc-200 transition-colors"
data-handle="${u.handle}" data-handle="${u.handle}"
@@ -138,6 +157,22 @@ import Base from '../../layouts/Base.astro';
`; `;
}).join(''); }).join('');
tbodyEl.querySelectorAll<HTMLButtonElement>('.diag-btn').forEach(btn => {
btn.addEventListener('click', async () => {
const h = btn.dataset.handle!;
diagHandle.textContent = h;
diagOutput.textContent = 'Loading…';
diagDialog.showModal();
try {
const r = await fetch(`/api/admin/users/${h}/diag`, { credentials: 'include' });
const d = await r.json();
diagOutput.textContent = JSON.stringify(d, null, 2);
} catch (err) {
diagOutput.textContent = String(err);
}
});
});
tbodyEl.querySelectorAll<HTMLButtonElement>('.rebuild-btn').forEach(btn => { tbodyEl.querySelectorAll<HTMLButtonElement>('.rebuild-btn').forEach(btn => {
btn.addEventListener('click', async () => { btn.addEventListener('click', async () => {
const h = btn.dataset.handle!; const h = btn.dataset.handle!;