avi/S.H.O.N.A.R._Desktop_Companion
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions

Instrumentation only: TRACE log lines for the tone-mismatch + progress investigation — reprocess (rid, requested tone, prior tone/status), summarize-start (rid, job, tone the worker actually read), progress (every distinct pct the provider emits), store_summary (rid, tone saved). rid minted per click joins all lines; zero behavior change.

Browse source
This commit is contained in:
avi 2026-09-18 10:49:28 -05:00
commit 768b75915a
2 changed files with 51 additions and 0 deletions
Download patch file Download diff file Expand all files Collapse all files

38
backend/shonar/services/processing.py
View file

@ -49,6 +49,27 @@ from shonar.storage import get_storage
logger = logging.getLogger("shonar.processing")
# --- tone/request-integrity trace (pure logging; remove when the
# tone-mismatch investigation closes) ---------------------------------------
# POST /reprocess mints an rid per request and stashes it here keyed by
# (recording, job); the worker and store_summary read it back so all the
# lines for one click share the same rid= and can be grepped together.
# Single-process inline queue makes this safe; it carries no behavior.
_trace_rid: dict = {}
def trace_request(recording_id, job_type, tone):
"""Called from POST /reprocess. Returns the rid for the request log."""
rid = uuid.uuid4().hex[:8]
_trace_rid[(str(recording_id), str(job_type))] = rid
logger.info("TRACE reprocess rid=%s rec=%s job=%s tone=%r",
rid, recording_id, job_type, tone)
return rid
def trace_peek(recording_id, job_type):
return _trace_rid.get((str(recording_id), str(job_type)), "-")
def _accepts_on_progress(provider) -> bool:
"""True when the provider's transcribe() accepts on_progress=."""
@ -109,6 +130,10 @@ def _async_progress_writer(job_id):
if int(pct) == last:
return
last = int(pct)
# TRACE (logging only): every distinct progress value the provider
# emits, with wall time — proves whether/when the 99 is emitted and
# written vs. the UI only ever showing 0%.
logger.info("TRACE progress job=%s pct=%s", job_id, pct)
async def _write() -> None:
from sqlalchemy import update
@ -481,6 +506,13 @@ async def run_summarize(ctx: dict, recording_id: str) -> None:
job.stage = "summarizing"
rec.processing_status = ProcessingStatus.processing
await session.commit() # visible before the long LLM call
# TRACE (logging only): the tone the worker actually reads from the
# row NOW — differs from the reprocess line's tone if a later click
# overwrote it before pickup.
logger.info("TRACE summarize-start rid=%s job=%s rec=%s type=%s "
"tone=%r attempt=%s",
trace_peek(rec.id, job.job_type), job.id, rec.id,
job.job_type, job.tone, job.attempt)
fallback_note: str | None = None
result_provider = provider.name # overwritten only on the rescue path
try:
@ -585,6 +617,12 @@ async def store_summary(
model: str,
tone: str | None = None,
) -> None:
# TRACE (logging only): the tone arriving at storage. Compare with the
# summarize-start line's tone for the same rid: a mismatch here means
# the value changed between worker pickup and the DB write.
logger.info("TRACE store_summary rid=%s rec=%s tone=%r provider=%s",
trace_peek(rec.id, "summarize"), rec.id, tone,
provider_name)
existing = (
await session.scalars(
select(Summary)