Spaces:
Sleeping
Sleeping
| #!/usr/bin/env python3 | |
| """ | |
| Render a NotePilot session trace (.accompy_traces/*.json) as a readable report. | |
| python scripts/trace_report.py # latest trace, summary + markers | |
| python scripts/trace_report.py path/to/trace.json # a specific trace | |
| python scripts/trace_report.py --full # add the complete timeline | |
| python scripts/trace_report.py --around 6 # +/- seconds of context per marker | |
| python scripts/trace_report.py --window 40 55 # timeline for a time range (seconds) | |
| python scripts/trace_report.py --types tracker,accomp.fire # filter the timeline | |
| python scripts/trace_report.py mic.json --baseline keyboard.json # scorecard vs ground truth | |
| python scripts/trace_report.py --engine classic # score the classic shadow stream of a follower session | |
| python scripts/trace_report.py --gt-window 500 # ground-truth match window in ms (default 400) | |
| python scripts/trace_report.py --full --no-frames # hide the follower's per-frame events | |
| The trace is what the browser recorded during one run (static/trace.js): every | |
| note the detector heard, every tracker decision (matches AND rejections), tempo | |
| estimates, accompaniment notes with their timing error, holds, and the markers | |
| the player dropped with F8. Follower-engine sessions (meta.micEngine == | |
| 'follower') add follow.* events: decimated per-frame beliefs, advances, holds, | |
| mode changes, accompaniment fires and bleed-lag samples. Stdlib only. | |
| The ACCOMPANIMENT section measures the part the listener actually hears -- the | |
| accompaniment's own notes, from accomp.fire against meta.lh: which ones never | |
| sounded, how long it went silent, where it lurched, and its seconds-per-beat | |
| against the score. Every other number here describes what the ENGINE heard, and | |
| those two came apart badly on 20260916-202657 (88% recall and a two-bar hole). | |
| """ | |
| import argparse | |
| import bisect | |
| import json | |
| import math | |
| import os | |
| import statistics | |
| import sys | |
| import time | |
| from collections import Counter, defaultdict | |
| NOTE_NAMES = ["C", "C#", "D", "D#", "E", "F", "F#", "G", "G#", "A", "A#", "B"] | |
| # FOLLOWER_DEFAULTS of static/follower.js at FOLLOWER_VERSION_KNOWN, regenerated with | |
| # node -e "import('./static/follower.js').then(m=>console.log(JSON.stringify(m.FOLLOWER_DEFAULTS)))" | |
| # Only used to show which engine options a session overrode; the engine itself is | |
| # the authority, so an unknown key is simply printed. A session run by another | |
| # engine version prints a one-line warning instead of every option whose default | |
| # moved (the spec's §5 table drifted 35 keys from the engine within a week). | |
| FOLLOWER_VERSION_KNOWN = "2026-09-18.1" | |
| FOLLOWER_DEFAULTS_KNOWN = { | |
| "harmonicWeights": [1, 0.8, 0.55, 0.42, 0.32, 0.25], "upperFrom": 7, "upperAlpha": 0.5, | |
| "upperWeight": 1, "soloUpperFrom": 0, "soloUpperAlpha": 0.5, "soloUpperWeight": 1, | |
| "wrongUpper": True, "bassTailFrom": 7, "bassTailAlpha": 0.5, "bassTailWeight": 0.35, | |
| "bassTailBins": 0.33, "bassTailWrong": False, "bassTailToH": 10, "trebleTailWeight": 0.22, | |
| "wrongTailScale": 1, "bassTailBinsHi": 0.7, "judgeMaxMidi": 93, "lowCutHz": 150, | |
| "rigResponse": None, "compress": 0.5, "gateTrustDb": 8, "nfMargin": 2, "nfDown": 0.3, | |
| "nfUp": 1.002, "floorInitFrames": 20, "nfSmoothBins": 4, "xTilt": 0, "xMin": 12, "xPeakMin": | |
| 4, "gateDb": 3, "rangeDb": 12, "voicedMin": 0.3, "beta": 6, "lambda": 0.35, "lambdaWrong": | |
| 0.5, "lambdaWrongAlt": 0, "lambdaWrongHeld": 0, "wrongPartialMax": 5, "bassWrongPartialMax": | |
| 5, "wrongPartialGuardBins": 0, "wrongHoldMax": 2, "candidateFrac": 0.2, "wrongMinMidi": 36, | |
| "wrongMaxMidi": 84, "wrongBandSemis": 18, "prev2Gain": 0, "accDecayMs": 1500, | |
| "accReleaseMs": 200, "bleedCapAfterMs": 180, "bleedCapPeak": 1, "bleedCapSlack": 0.4, | |
| "bleedLagMs": 58, "outputLatencyMs": 33, "bleedLagMinMs": 0, "bleedLagMaxMs": 250, | |
| "bleedProbePreMs": 100, "bleedProbePostMs": 100, "bleedProbeMinMs": 150, "bleedCorrMin": | |
| 0.35, "bleedRiseMin": 1.4, "bleedLagHistory": 16, "bleedLagMinSamples": 2, | |
| "bleedLagClusterMs": 25, "bleedLagStep": 0.5, "bleedMinBand": 4, "onsetThresh": 5, | |
| "onsetRefractoryMs": 60, "onsetBonus": 1, "onsetThreshRepeat": 2.5, "softOnsetPenalty": | |
| -1.5, "hazardSpawnEveryMs": 120, "skipPenalty": -2.5, "skipMax": 1, "skipMaxLost": 8, | |
| "skipPenaltyLost": -0.5, "durSigma": 0.35, "survivalFloor": -6, "skipDurSigma": 0.2, | |
| "outOfBankSkip": True, "repeatRiseRatio": 1.6, "onsetMin": 0.5, "onsetMinWithAttack": 0.35, | |
| "attackRecentMs": 60, "bleedOnsetWindowMs": [-30, 90], "bleedMaskOn": 0, "bleedMaskFrac": | |
| 0.65, "bleedUnmaskFrac": 0.45, "bleedMaskEnergyMin": 0.005, "bleedMaskMaxRows": 16, | |
| "bleedMinReliableShare": 0.35, "bleedRefMinRows": 4, "bleedRefSlack": 1, "distinctKeptMin": | |
| 0.5, "tempoAlpha": 0.3, "tempoMinRatio": 0.5, "tempoMaxRatio": 2, "ioiMinMs": 150, | |
| "ioiMaxMs": 3000, "beam": 16, "maxPerState": 3, "maxPerStateAhead": 5, "pruneNats": 12, | |
| "committedFloorNats": 4, "epsWrong": 0.005, "commitP": 0.55, "commitMargin": 0.2, | |
| "nConfirm": 2, "minAgeMs": 30, "minEvNats": 2.5, "minEvNatsSoft": 5, "gMin": 0.1, | |
| "minCommitGapMs": 70, "gMinDistinct": 0.04, "pitchMarginNats": 0.4, "pitchBiasNats": 0.25, | |
| "pitchBiasAfter": 4, "pitchAltMax": 8, "pitchReleaseFrames": 8, "pitchMinMidi": 54, | |
| "pitchMinShare": 0.05, "straddleFrac": 0.2, "pitchKeptMin": 0.5, "retryMs": 60, | |
| "silenceLostMs": 4000, "lostMinMs": 2500, "lostFactor": 2.5, "wrongDwellMs": 2500, | |
| "wrongDwellP": 0.5, "backtrackP": 0.7, "backtrackMs": 300, "onsetBiasMs": 8, | |
| "accompFallback": False, "prevCapSlack": 1.3, "prevCapDecay": 0.99, | |
| "previousOnsetPrevMin": 0.4, "previousOnsetNewMax": 0.01, "nwCapAfterMs": 120, | |
| "repeatRiseWindowMs": 150, "repeatSpawnWindowMs": 60, "repeatSkipOverdue": 0.6, | |
| "inaudiblePenalty": 0.6, "distinctOn": 0.3, "distinctMin": 0.02, "distinctCore": True, | |
| "chordVoices": False, "chordVoiceMin": 0.1, "f0UnresolvedBins": 0.3, "attackBlankMs": 25, | |
| "repeatRiseBonus": 1.5, "onsetConfirmMs": 400, "onsetRiseDb": 3, "onsetRiseWindowMs": 90, | |
| "onsetRiseLambda": 0.5, "lostConfirmMs": 300, "maxCommitAgeMs": 500, "lostMinNewShare": | |
| 0.25, "lostMinEvNats": 5, "futureMarginRatio": 0.5, "resyncMaxJump": 128, "resyncContext": | |
| 16, "resyncStepPenaltyNats": 0.5, "resyncMarginNats": 1.5, "resyncNeighbourhood": 1, | |
| "resyncPenaltyNats": 1, "resyncMinNewShare": 0.02, "resyncCollectOnsets": 2, | |
| "resyncProbeMinMs": 60, "resyncProbeMaxMs": 200, "resyncProbeFrames": 3, | |
| "resyncArmLostEpisodes": 2, "resyncArmOnsets": 8, "resyncGapMs": 2500, | |
| "resyncMaxPerSession": 24, "resyncObsMaxAgeMs": 8000, "resyncLandBack": 1, "resyncTempoMax": | |
| 2, "resyncTempoSlackBeats": 4, "denseIoiMs": 250, "denseMinEvNats": 2.5, | |
| "denseMinEvNatsSoft": 5, "denseMinCommitGapMs": 70, "lostDenseMinMs": 600, | |
| } | |
| # --- the analyser's bank, and which score events fall outside it -------------- | |
| # | |
| # static/salience.js covers MIDI 33..96 in 64 semitone rows. Two different | |
| # things can put a score event "outside" it and they have different | |
| # consequences, so they are counted separately (the measurement is in that | |
| # file's MIN_MIDI note and in follower.js's _markBank): | |
| # | |
| # BELOW the bank the event is still followable. A MIDI-32 note's partials | |
| # 2-6 (103.8-311.5 Hz) land squarely inside, and harmonicTemplate(32) is | |
| # non-zero on 34 of the 64 rows; what is lost is pitch specificity, which | |
| # at 0.128 FFT bins per semitone down there the bank never had. Liebestraum's | |
| # five MIDI-32 solo events are of this kind. | |
| # | |
| # UNHEARABLE means no template can represent the event at all -- every one of | |
| # its pitches is high enough that none of its first six partials lands in any | |
| # row, so its template is the zero vector and no evidence can ever speak for | |
| # it. Measured against salience.js's own toneResponse at both 48 kHz and | |
| # 44.1 kHz with win 2048: MIDI 97 still leaks into row 96 (cos 0.973 with | |
| # 96's own template, i.e. it is representable only AS a 96) and MIDI 98 | |
| # (2349.3 Hz) is exactly all zeros. So the cliff is maxMidi + 2, not maxMidi. | |
| # The follower steps over these instead of waiting for them | |
| # (FOLLOWER_DEFAULTS.outOfBankSkip) and logs one `follow.hold` with reason | |
| # `out-of-bank` per event; this census is recomputed from meta.rh so that | |
| # traces recorded before that existed still report it. | |
| BANK_MIN_MIDI = 33 | |
| BANK_MAX_MIDI = 96 | |
| # How far BEFORE a key a hold naming that key's score index may sit and still be | |
| # taken as its explanation. The out-of-bank hold is the reason this is not zero: | |
| # _spawn's hazard branch queues the index at r >= 0.6 of the PREVIOUS event's | |
| # IOI, so on the measured sim trace event 5's hold was written at t = 2168 ms for | |
| # a key played at t = 4973.9 ms -- 2.8 s early. 8 s covers that with room for a | |
| # slow piece without letting a hold from the other end of the session in. | |
| HOLD_INDEX_LOOKBACK_MS = 8000 | |
| def event_pitches(ev): | |
| if not isinstance(ev, list) or not ev: | |
| return [] | |
| raw = ev[0] if isinstance(ev[0], list) else [ev[0]] | |
| out = [] | |
| for p in raw: | |
| try: | |
| out.append(int(p)) | |
| except (TypeError, ValueError): | |
| pass | |
| return out | |
| def bank_census(events, lo=BANK_MIN_MIDI, hi=BANK_MAX_MIDI): | |
| """(below, above, unhearable, unhearable_indices) over a score event list.""" | |
| below = above = 0 | |
| unhearable = [] | |
| for i, ev in enumerate(events or []): | |
| ps = event_pitches(ev) | |
| if not ps: | |
| continue | |
| if min(ps) < lo: | |
| below += 1 | |
| if max(ps) > hi: | |
| above += 1 | |
| # Every voice past the cliff -> nothing of the event reaches the bank. | |
| if min(ps) > hi + 1: | |
| unhearable.append(i) | |
| return below, above, len(unhearable), unhearable | |
| def pn(midi): | |
| try: | |
| midi = int(midi) | |
| except (TypeError, ValueError): | |
| return "?" | |
| return f"{NOTE_NAMES[midi % 12]}{midi // 12 - 1}" | |
| def secs(ms): | |
| return f"{(ms or 0) / 1000:8.3f}" | |
| def signed_ms(v): | |
| return " n/a" if v is None else f"{v:+5d}ms" | |
| def num(v, fmt=".2f", none="-"): | |
| return format(v, fmt) if isinstance(v, (int, float)) and not isinstance(v, bool) else none | |
| def engine_tag(ev): | |
| """' [follower]' / ' [classic]' when the event says which engine produced it.""" | |
| return f" [{ev['engine']}]" if ev.get("engine") else "" | |
| def fmt_event(ev): | |
| """One compact line per event. Rejections and anomalies are visually loud.""" | |
| t = ev.get("type", "?") | |
| if t == "session.start": | |
| return "SESSION START" | |
| if t == "session.stop": | |
| return f"SESSION STOP ({ev.get('reason')})" | |
| if t == "mark": | |
| return f">>> MARK #{ev.get('id')} {ev.get('note') or ''}".rstrip() | |
| if t == "input.midi": | |
| dup = " (DROPPED as duplicate)" if ev.get("duplicate") else "" | |
| return f"midi in {ev.get('name')}{dup}" | |
| if t == "mic.note" and ev.get("engine") == "follower": | |
| # A follower commit: the expected lead pitch, what the frame peaked at, and the belief behind it. | |
| rep = " repeat" if ev.get("repeatLike") else "" | |
| drv = "onset" if ev.get("onsetDriven") else "soft" | |
| return (f"mic heard {ev.get('name'):<5} peak {ev.get('heardName') or '-':<5} p {num(ev.get('p'))} " | |
| f"margin {num(ev.get('margin'))} ev {num(ev.get('ev'), '.1f')} {drv}{rep} " | |
| f"onset {ev.get('sinceOnsetMs')}ms ago lag {ev.get('lagMs')}ms{engine_tag(ev)}") | |
| if t in ("mic.note", "mic.classic"): | |
| freq = f" {ev['freq']:.1f}Hz" if isinstance(ev.get("freq"), (int, float)) else "" | |
| cal = " (calibration)" if ev.get("calibrating") else "" | |
| how = "RESCUE" if ev.get("matched") else "yin" | |
| if ev.get("stage"): | |
| how += f" s{ev.get('stage')}@{ev.get('identifyMs')}ms" | |
| yin = f" yin={ev.get('yinName')}({ev.get('yinClarity')})" if ev.get("yinName") else "" | |
| rise = f" share={ev.get('shareRatio')}" if ev.get("shareRatio") is not None else "" | |
| above = f" x{ev.get('aboveFloor')}" if ev.get("aboveFloor") is not None else "" | |
| label = "mic heard " if t == "mic.note" else "mic shadow " | |
| return f"{label} {ev.get('name'):<5}{freq} [{how}{yin}{rise}{above}]{cal}{engine_tag(ev)}" | |
| if t == "mic.drop" and ev.get("engine") == "follower": | |
| return (f"mic HELD {(ev.get('reason') or ''):<18} expected {ev.get('expName') or '-':<5} #{ev.get('index')} " | |
| f"p {num(ev.get('p'))} margin {num(ev.get('margin'))} ev {num(ev.get('ev'), '.1f')}{engine_tag(ev)}") | |
| if t in ("mic.drop", "mic.classic.drop"): | |
| yin = f" yin={ev.get('yinName')}({ev.get('yinClarity')})" if ev.get("yinName") else " yin=none" | |
| rise = f" share={ev.get('shareRatio')}" if ev.get("shareRatio") is not None else "" | |
| st = f" s{ev.get('stage')}@{ev.get('identifyMs')}ms" if ev.get("stage") else "" | |
| label = "mic DROP " if t == "mic.drop" else "mic shadow DROP" | |
| return f"{label} {ev.get('reason'):<12} expected {ev.get('expName') or '-':<5}{yin}{rise}{st} x{ev.get('aboveFloor')}{engine_tag(ev)}" | |
| if t == "skip": | |
| held = f" after {ev['heldMs']}ms stuck" if ev.get("heldMs") else "" | |
| return f"SKIP {ev.get('reason'):<7} past #{ev.get('fromIndex')} [{ev.get('expectedName')}] -> #{ev.get('toIndex')}{held}" | |
| if t == "skip.defer": | |
| # The one-event auto-skip stood down, and the two reasons are different | |
| # failures, so they carry different fields. | |
| # resync-armed: the engine was searching wide. Before resync existed | |
| # the crawl WAS the recovery; it closed 10 of a | |
| # 98-event gap on 20260916-113517 and each of its seeks | |
| # rebuilt the beam under the search that could have | |
| # closed the whole gap. | |
| # accomp-behind: the note it would step over is not yet due on the | |
| # accompaniment's clock, so skipping would open another | |
| # nine-beat hole in the left hand (20260916-202657: | |
| # destination beat 146 against a clock at 137.86). | |
| head = (f"SKIP defer #{ev.get('index')} held {ev.get('heldMs')}ms " | |
| f"({ev.get('soundMs')}ms of sound) -- ") | |
| if ev.get("reason") == "accomp-behind": | |
| return (head + f"accomp-behind: event at beat {bt(ev.get('destBeat'))} is " | |
| f"{num(ev.get('aheadBeats'), '.2f')} beats ahead of the " | |
| f"accompaniment clock at {bt(ev.get('accompBeat'))}") | |
| return head + f"{ev.get('reason')} for another {ev.get('armedForMs')}ms" | |
| if t == "follow.resync": | |
| # A WIDE JUMP, never a detection. Its own type on purpose: an advance is | |
| # "the player played this note", a resync is "the player is not here at | |
| # all", and the precision figure must only ever be computed from the | |
| # first. Refusals are logged too, with the reason, so a session that | |
| # should have jumped and did not says why. | |
| if not ev.get("accepted"): | |
| return (f"follow RESYNC refused by the app ({ev.get('reason')}) -> #{ev.get('toIndex')} " | |
| f"from #{ev.get('fromIndex')} onsets {ev.get('onsetsConfirmed')} margin {num(ev.get('marginNats'), '.2f')} nats") | |
| return (f"follow RESYNC #{ev.get('fromIndex')}->#{ev.get('toIndex')} (+{ev.get('jump')} events) beat {ev.get('beat')} " | |
| f"{ev.get('onsetsConfirmed')} onsets over {ev.get('contextMs')}ms margin {num(ev.get('marginNats'), '.2f')} " | |
| f"lead {num(ev.get('leadNats'), '.2f')} nats newShare {num(ev.get('meanNewShare'))} " | |
| f"[{ev.get('mode')}] #{ev.get('nInSession')} this session") | |
| if t == "follow.resyncScan": | |
| # Every ARMED wide scan, fired or refused. `refused` null = it fired. | |
| state = "FIRED" if ev.get("refused") in (None, "") else f"refused({ev.get('refused')})" | |
| return (f"follow scan #{ev.get('fromIndex')} -> #{ev.get('toIndex')} (+{ev.get('distance')}) {state} " | |
| f"{ev.get('contextOnsets')} onsets over {ev.get('contextMs')}ms, window {ev.get('windowSize')} " | |
| f"margin {num(ev.get('marginNats'), '.2f')} lead {num(ev.get('leadNats'), '.2f')} newShare {num(ev.get('meanNewShare'))} " | |
| f"[{ev.get('mode')} lost×{ev.get('lostEpisodes')} onsets/accept {ev.get('onsetsSinceAccept')}]") | |
| if t == "mic.distance": | |
| return f"MIC DISTANCE {(ev.get('band') or '?').upper()} {num(ev.get('aboveRoomDb'), '+.1f')} dB over the room -- {ev.get('headline')}" | |
| if t == "mic.chord": | |
| return f"mic heard [{ev.get('name')}] chord" | |
| if t == "mic.classic.chord": | |
| return f"mic shadow [{ev.get('name')}] chord{engine_tag(ev)}" | |
| if t == "mic.engine": | |
| return f"mic engine -> {ev.get('engine')}" | |
| if t == "follow.frame": | |
| inf = "" if ev.get("inf") else " (quiet)" | |
| return (f"frame #{ev.get('k')} {ev.get('mode') or '':<9} pos {ev.get('pos')} best #{ev.get('best')} p {num(ev.get('p'))} " | |
| f"cur {num(ev.get('pcur'))} next {num(ev.get('pnext'))} wrong {num(ev.get('pw'))} " | |
| f"{num(ev.get('db'), '.0f')}dB onset {num(ev.get('on'), '.1f')} peak {pn(ev.get('peak'))}{inf}") | |
| if t == "follow.advance": | |
| acc = "ACCEPTED" if ev.get("accepted") else "REJECTED by tracker" | |
| ex = ev.get("explained") or {} | |
| rep = " repeat" if ev.get("repeatLike") else "" | |
| drv = "onset" if ev.get("onsetDriven") else "soft" | |
| hyps = " ".join(f"#{h.get('i')}(w{num(h.get('w'))} ev{num(h.get('ev'), '.1f')})" for h in (ev.get("hyps") or [])[:4]) | |
| return (f"follow ADV #{ev.get('fromIndex')}->#{ev.get('toIndex')} beat {ev.get('beat')} {acc} p {num(ev.get('p'))} " | |
| f"margin {num(ev.get('margin'))} ev {num(ev.get('ev'), '.1f')} {drv}{rep} lag {ev.get('lagMs')}ms " | |
| f"(onset {ev.get('sinceOnsetMs')}ms ago) tempo {num(ev.get('bps'), '.2f')}bps " | |
| f"explained bleed {num(ex.get('bleed'))} prev {num(ex.get('prev'))} new {num(ex.get('new'))} other {num(ex.get('other'))} " | |
| f"peak {pn(ev.get('heardMidi'))} hyps {hyps}") | |
| if t == "follow.hold": | |
| seen = " onset seen" if ev.get("onsetSeen") else "" | |
| return (f"follow hold {(ev.get('reason') or ''):<13} #{ev.get('index')} (pos {ev.get('pos')}) p {num(ev.get('p'))} " | |
| f"margin {num(ev.get('margin'))} ev {num(ev.get('ev'), '.1f')} dwell {ev.get('dwellMs')}ms{seen}") | |
| if t == "follow.guard": | |
| # The app refused to deliver an advance (deliverFollowerAdvance safety net): never expected from a healthy engine. | |
| return f"follow GUARD #{ev.get('toIndex')} refused: {ev.get('reason')} (onset evidence {ev.get('sinceOnsetEvidenceMs')}ms ago, {ev.get('mode')})" | |
| if t == "follow.state": | |
| return f"follow STATE {ev.get('mode')} ({ev.get('reason')}) pos {ev.get('pos')} p {num(ev.get('p'))}" | |
| if t == "follow.recover": | |
| # The WRONG-dwell watchdog. Its own event since follower 2026-09-15.10: | |
| # it used to share out.state with the BACKTRACK signal and the mode | |
| # change, both of which overwrite it later in the same observe(). | |
| return f"follow RECOVER ({ev.get('reason')}) pos {ev.get('pos')} p(wrong) {num(ev.get('pw'))}" | |
| if t == "follow.seek": | |
| return f"follow seek position {ev.get('position')} stamped at {ev.get('atMs')}ms" | |
| if t == "follow.accomp.seed": | |
| items = ev.get("list") or [] | |
| names = ", ".join(" ".join(pn(p) for p in (x.get("pitches") or [])) + f"@{x.get('atMs')}ms" for x in items) | |
| return f"follow accomp seed {len(items)} already ringing [{names}]" | |
| if t == "follow.accomp": | |
| names = " ".join(pn(p) for p in (ev.get("pitches") or [])) | |
| return f"follow accomp beat {ev.get('beat')} [{names}] at {ev.get('atMs')}ms for {ev.get('durMs')}ms" | |
| if t == "follow.bleed": | |
| names = " ".join(pn(p) for p in (ev.get("pitches") or [])) | |
| # stateMs (since app tag 20260915-ff9) is the engine's own estimate right | |
| # after this sample: the difference between the two is what the frames | |
| # around this fire were actually fitted against. | |
| state = f", engine now {ev.get('stateMs')}ms" if ev.get("stateMs") is not None else "" | |
| return f"follow bleed [{names}] heard {ev.get('lagMs')}ms after the fire (x{num(ev.get('strength'), '.1f')}{state})" | |
| if t == "follow.bleedlag": | |
| if ev.get("phase") == "init": | |
| return (f"bleed lag assumed {ev.get('assumedMs')}ms ({ev.get('source')}: output {ev.get('outputMs')}ms " | |
| f"+ analysis {ev.get('analysisMs')}ms, saved {ev.get('savedMs')}) device {ev.get('device')}") | |
| return (f"bleed lag session end: assumed {ev.get('assumedMs')}ms ({ev.get('source')}), measured median " | |
| f"{ev.get('measuredMedianMs')}ms over {len(ev.get('samples') or [])} samples, engine finished at " | |
| f"{ev.get('engineMs')}ms, {'saved for next session' if ev.get('persisted') else 'not saved'}") | |
| if t == "mic.silence": | |
| return "mic silence" | |
| if t == "mic.display": | |
| if ev.get("state") == "silence": | |
| return f"mic display cleared ({ev.get('source')})" | |
| hz = f" {ev.get('freq'):.1f}Hz" if isinstance(ev.get("freq"), (int, float)) else "" | |
| want = " ".join(pn(p) for p in (ev.get("expected") or [])) | |
| return f"mic display {ev.get('text') or '-'}{hz} ({ev.get('source')}; want {want or '-'})" | |
| if t == "mic.gate": | |
| return (f"mic gate {ev.get('state')} rms {num(ev.get('rms'), '.4f')} " | |
| f"{num(ev.get('db'), '.1f')}dB gate {ev.get('gateUnits')} " | |
| f"peak {pn(ev.get('peak'))}") | |
| if t == "mic.onset": | |
| cands = ev.get("candidates") or [] | |
| top = " ".join( | |
| f"#{c.get('i')}({c.get('conf'):.2f} ch{c.get('chroma'):.2f} tm{c.get('timing'):.2f})" for c in cands[:3] | |
| ) | |
| flag = "" if ev.get("bestIndex") == ev.get("currentIndex") else " <- best != current" | |
| return (f"follower {ev.get('mode'):<9} conf {ev.get('confidence'):.2f} best #{ev.get('bestIndex')} " | |
| f"cur #{ev.get('currentIndex')} delay {ev.get('suggestedDelayMs')}ms {top}{flag}") | |
| if t == "tracker": | |
| res = ev.get("result") | |
| exp = ev.get("expectedName") or "-" | |
| got = ev.get("inputName") or "-" | |
| pos = f"pos {ev.get('posBefore')}->{ev.get('posAfter')}" | |
| tag = engine_tag(ev) | |
| if res == "match": | |
| return f"tracker {ev.get('src'):<9} {got:<8} == {exp:<8} MATCH beat {ev.get('beat')} {pos}{tag}" | |
| return f"tracker {ev.get('src'):<9} {got:<8} != {exp:<8} REJECT (expected beat {ev.get('expectedBeat')}) {pos}{tag}" | |
| if t == "tempo": | |
| return f"tempo beat {ev.get('beat')} detected {ev.get('detectedBpm')}bpm accomp {ev.get('accompBpm')}bpm" | |
| if t == "accomp.sync": | |
| drift = signed_ms(ev.get("driftMs")) | |
| hold = " holding" if ev.get("holding") else "" | |
| return (f"accomp sync beat {ev.get('beat')} clock was {ev.get('clockBeatBefore')} drift {drift}" | |
| f" comp {ev.get('compMs')}ms lhIdx {ev.get('lhIdxBefore')}{hold}") | |
| if t == "accomp.fire": | |
| err = ev.get("errMs") | |
| loud = " <<< LATE" if isinstance(err, int) and err > 80 else (" <<< EARLY" if isinstance(err, int) and err < -80 else "") | |
| lead = " lead" if ev.get("lead") else "" | |
| hold = " HOLDING" if ev.get("holding") else "" | |
| return (f"accomp FIRE beat {ev.get('beat'):<6} [{ev.get('names')}] err {signed_ms(err)}" | |
| f" clock {ev.get('clockBeat')} lhIdx {ev.get('lhIdx')}{lead}{hold}{loud}") | |
| if t == "accomp.hold": | |
| return f"accomp HOLD waiting at beat {ev.get('allowedBeat')} (last confirmed {ev.get('lastConfirmed')})" | |
| if t == "accomp.release": | |
| return f"accomp go released at beat {ev.get('allowedBeat')}" | |
| if t == "accomp.pause": | |
| return f"accomp pause clock {ev.get('clockBeat')} lhIdx {ev.get('lhIdx')}" | |
| if t == "accomp.resume": | |
| return f"accomp resume beat {ev.get('beat')}" | |
| if t == "latency": | |
| if ev.get("kind") == "gate": | |
| return f"noise gate -> {ev.get('ms')} ({ev.get('source') or 'manual'})" | |
| return f"latency {ev.get('kind')} -> {ev.get('ms')}ms (effective {ev.get('effectiveMs')}ms)" | |
| # What the latency calibration actually played. Without this a run that ends | |
| # "No usable latency samples" cannot be told apart offline from one whose | |
| # probe was scheduled silent (solo channel down) or fell back to a sine. | |
| if t == "calibration.probe": | |
| how = ev.get("source") or "?" | |
| lvl = f" vel {ev.get('velocity')}" if ev.get("velocity") is not None else (f" amp {ev.get('amp')}" if ev.get("amp") is not None else "") | |
| boost = f" x{ev.get('boost')}" if (ev.get("boost") or 1) != 1 else "" | |
| return f"cal probe round {ev.get('round')} {ev.get('name') or pn(ev.get('midi'))} via {how}{lvl}{boost} floor {ev.get('noiseFloor')}" | |
| # The gate guard firing mid-session: the app noticed the gate was muting the | |
| # playing and said so (and lowered it) while the take was still running. | |
| if t == "gate.guard": | |
| to = ev.get("to") | |
| return (f"GATE GUARD {ev.get('loudGated')}/{ev.get('loud')} frames over the room muted at gate {ev.get('gate')}" | |
| + (f" -> lowered to {to}" if to else " -> already at the minimum")) | |
| # Failures. The app used to die silently between the click and the recorder; | |
| # now every one of these lands in the trace, so print them loudly. | |
| if t == "error": | |
| where = ev.get("source") or "?" | |
| line = f":{ev.get('line')}" if ev.get("line") is not None else "" | |
| return f"!! ERROR {ev.get('kind')} {ev.get('message')} ({where}{line})" | |
| if t in ("start.error", "samples.error", "meta.error", "start.abort"): | |
| detail = ev.get("message") or ev.get("reason") or "" | |
| return f"!! {t:<10} {detail}" | |
| if t == "follower.init": | |
| if ev.get("ok"): | |
| return f"follower init ok v{ev.get('version')} tag {ev.get('tag')} sr {ev.get('sr')}" | |
| if ev.get("error"): | |
| return f"!! follower init FAILED ({ev.get('where') or 'construct'}): {ev.get('error')}" | |
| return f"follower init not active (engine {ev.get('engine')}, input {ev.get('inputMode')})" | |
| extra = {k: v for k, v in ev.items() if k not in ("t", "type")} | |
| return f"{t:<12} {json.dumps(extra)[:110]}" | |
| def load(path): | |
| with open(path, encoding="utf-8") as fh: | |
| return json.load(fh) | |
| def pct(values, q): | |
| if not values: | |
| return None | |
| vals = sorted(values) | |
| idx = min(len(vals) - 1, max(0, int(round(q * (len(vals) - 1))))) | |
| return vals[idx] | |
| # Sound-with-no-advance intervals. A follower session fails in one of two ways: | |
| # it advances on something that was not played (precision), or it stops advancing | |
| # while the player keeps playing (recall). The second one is invisible in an | |
| # aggregate -- 29% recall reads like "a bit deaf" when what actually happened was | |
| # 16 s of perfect tracking followed by 45 s of nothing -- so the intervals get | |
| # their own section, longest first. | |
| def stall_intervals(tr, by): | |
| frames = by["follow.frame"] | |
| if not frames: | |
| return [] | |
| advs = [e for e in by["follow.advance"] if e.get("accepted")] | |
| holds = by["follow.hold"] | |
| keys = by["input.key"] | |
| edges = [frames[0].get("t", 0)] + [e.get("t", 0) for e in advs] + [frames[-1].get("t", 0)] | |
| out = [] | |
| for a, b in zip(edges, edges[1:]): | |
| if b <= a: | |
| continue | |
| fr = [e for e in frames if a <= e.get("t", 0) < b] | |
| if not fr: | |
| continue | |
| inf = [e for e in fr if e.get("inf")] | |
| # Frames are decimated unless the session recorded verbose ones, so the | |
| # informative SHARE of the logged frames is the estimator of how much of | |
| # the interval was sound. Verbose traces make this exact. | |
| sound_ms = (b - a) * len(inf) / len(fr) | |
| pws = [e.get("pw") for e in inf if isinstance(e.get("pw"), (int, float))] | |
| hr = Counter(e.get("reason") for e in holds if a <= e.get("t", 0) < b) | |
| modes = Counter(e.get("mode") for e in fr if e.get("mode")) | |
| pos = Counter(e.get("pos") for e in (inf or fr) if isinstance(e.get("pos"), int)) | |
| out.append({ | |
| "t0": a, "t1": b, "durMs": b - a, "soundMs": sound_ms, | |
| "frames": len(fr), "inf": len(inf), | |
| "pw": statistics.median(pws) if pws else None, | |
| "holds": hr, "modes": modes, | |
| "pos": pos.most_common(1)[0][0] if pos else None, | |
| "keys": sum(1 for k in keys if a <= k.get("t", 0) < b), | |
| }) | |
| out.sort(key=lambda x: -x["soundMs"]) | |
| return out | |
| def stall_lines(tr, by, min_sound_ms=3000): | |
| """The always-printed one-liner, plus a block per interval worth calling a stall. | |
| min_sound_ms is 3 s because a legitimate gap is one note plus the engine's | |
| patience: the longest WRONG episode the engine recovered from on its own in | |
| 20260915-081347 was 854 ms, and the stall that killed the session was 45 s. | |
| """ | |
| stalls = stall_intervals(tr, by) | |
| if not stalls: | |
| return [] | |
| rh = (tr.get("meta") or {}).get("rh") or [] | |
| def keys_txt(n): | |
| return f"{n} key{'' if n == 1 else 's'} typed" | |
| def expected(st): | |
| if st["pos"] is None: | |
| return "" | |
| if not (0 <= st["pos"] < len(rh)): | |
| return f" waiting for #{st['pos']}" | |
| ev = rh[st["pos"]] | |
| names = " ".join(pn(x) for x in (ev[0] if isinstance(ev, list) and ev else [])) | |
| beat = ev[1] if isinstance(ev, list) and len(ev) > 1 else "?" | |
| return f" waiting for #{st['pos']} [{names}] at beat {beat}" | |
| worst = stalls[0] | |
| lines = [f" longest stretch with sound and no advance: ~{worst['soundMs'] / 1000:.1f}s of sound over " | |
| f"{worst['durMs'] / 1000:.1f}s ({worst['t0'] / 1000:.1f}s-{worst['t1'] / 1000:.1f}s), " | |
| f"{keys_txt(worst['keys'])}{expected(worst)}"] | |
| for st in stalls[:3]: | |
| if st["soundMs"] < min_sound_ms: | |
| break | |
| top_hold = st["holds"].most_common(1) | |
| hold_txt = (f"{top_hold[0][0]} ({top_hold[0][1]} of {sum(st['holds'].values())} holds)" | |
| if top_hold else "no holds logged — nothing ever became a candidate") | |
| lines.append(f" STALL {st['t0'] / 1000:.1f}s-{st['t1'] / 1000:.1f}s ~{st['soundMs'] / 1000:.1f}s of sound, " | |
| f"{keys_txt(st['keys'])}, no advance{expected(st)}") | |
| lines.append(f" dominant hold: {hold_txt}; median P(wrong) {num(st['pw'])}; " | |
| f"modes {'/'.join(f'{m}:{n}' for m, n in st['modes'].most_common(3))}") | |
| if isinstance(st["pw"], (int, float)) and st["pw"] >= 0.5: | |
| # WRONG saturating is not a detector failure, it is a beam that cannot | |
| # get back: P(wrong) has a floor and no ceiling, so the committed state | |
| # sits committedFloorNats under it and every child spawns from there. | |
| lines.append(f" -> the WRONG-note absorber held the posterior for this whole stretch " | |
| f"(median {st['pw']:.2f}): the beam never got a hypothesis back into contention.") | |
| lines.append(f" look at it: python scripts/trace_report.py --window " | |
| f"{st['t0'] / 1000:.0f} {st['t1'] / 1000:.0f} --full") | |
| return lines | |
| # Engine options that are data, not settings: printing them inline would bury | |
| # the line they belong on under 64 numbers. Each gets its own summary instead. | |
| BULKY_OPTIONS = {"rigResponse"} | |
| # ── MIC DISTANCE ──────────────────────────────────────────────────────────── | |
| # One number decides whether a mic session can work at all: how far a note at | |
| # playing volume stands over the room. The bands below are the app's | |
| # (app.js MIC_DISTANCE_GREEN_DB / MIC_DISTANCE_AMBER_DB) and both are read off | |
| # these traces, not quoted from anywhere: | |
| # meta.rig.noteLevel, 20*log10(bodyRms/roomRms) -- a REAL sampled note against | |
| # the room, the only reading taken on a signal music actually produces: | |
| # 20260916-112827 0.01042/0.00618 = +4.5 dB -> follower recall 88-90%, precision 100% | |
| # 20260916-114628 0.00578/0.00439 = +2.4 dB | |
| # 20260916-113517 NO READING: the note failed the app's 1.0 dB bar, i.e. the | |
| # room was as loud as the note -> recall 7% over 143 notes | |
| # Sessions from before the reference note existed have only the sweep's gate | |
| # ceiling, which is ~10 dB high whenever meta.rig.sineAmp is null (see the note | |
| # in rig_response_line): 20260916-102711 27.1 -> ~17 dB (93% recall), | |
| # 20260916-100410 23.4 -> ~13 dB (best session on record), 20260916-101536 | |
| # 3.4 -> ~-7 dB (fan on, poor). Hence green >= 10, amber >= 3, red below. | |
| MIC_DISTANCE_GREEN_DB = 10.0 | |
| MIC_DISTANCE_AMBER_DB = 3.0 | |
| def mic_distance_verdict(m): | |
| """(band, dB or None, how it was measured) for this session, or None. | |
| Prefers the app's own recorded verdict (meta.micDistance, present from | |
| follower tag 20260916-ff21 on), then the reference note, then the sweep's | |
| gate ceiling as a clearly-labelled estimate. | |
| """ | |
| md = m.get("micDistance") if isinstance(m.get("micDistance"), dict) else None | |
| if md and md.get("band"): | |
| db = md.get("aboveRoomDb") | |
| how = "refused reference note (the room is as loud as the note)" if md.get("refused") else "reference note" | |
| return md["band"], db, how | |
| rig = m.get("rig") if isinstance(m.get("rig"), dict) else {} | |
| note = rig.get("noteLevel") if isinstance(rig.get("noteLevel"), dict) else None | |
| db = None | |
| how = None | |
| if note: | |
| if isinstance(note.get("aboveRoomDb"), (int, float)): | |
| db, how = float(note["aboveRoomDb"]), "reference note" | |
| elif note.get("bodyRms") and note.get("roomRms"): | |
| db, how = 20 * math.log10(note["bodyRms"] / note["roomRms"]), "reference note" | |
| if db is None: | |
| cap = rig.get("gateCap") if isinstance(rig.get("gateCap"), dict) else None | |
| head = cap.get("headroomDb") if cap else None | |
| if isinstance(head, (int, float)): | |
| if rig.get("sineAmp") is None: | |
| db, how = float(head) - 10.0, "sweep gate ceiling, corrected -10 dB for the old 0.18 oscillator (ESTIMATE)" | |
| else: | |
| db, how = float(head), "sweep gate ceiling (tones, not a played note)" | |
| # A rig where the reference note was ATTEMPTED AND REFUSED records | |
| # noteLevel: null while the sweep still ran (the sweep's own tones are far | |
| # louder than a played note, so it survives what the note could not). That is | |
| # not missing data -- it is the loudest possible reading, and it outranks | |
| # whatever the tones came back at. This is 20260916-113517 exactly: gate | |
| # ceiling +1.6 dB from the tones, no reading at all from a real note, 7%. | |
| refused = rig.get("sineAmp") is not None and note is None and "noteLevel" in rig | |
| if refused: | |
| extra = f"; the sweep's tones came back {db:+.1f} dB over the room" if db is not None else "" | |
| return "red", db, "reference note REFUSED -- the room is as loud as a played note" + extra | |
| if db is None: | |
| return None | |
| band = "green" if db >= MIC_DISTANCE_GREEN_DB else ("amber" if db >= MIC_DISTANCE_AMBER_DB else "red") | |
| return band, db, how | |
| def mic_distance_lines(m): | |
| v = mic_distance_verdict(m) | |
| if not v: | |
| return [] | |
| band, db, how = v | |
| shown = "no usable reading" if db is None else f"{db:+.1f} dB over the room" | |
| head = { | |
| "green": "MIC DISTANCE GREEN", | |
| "amber": "MIC DISTANCE AMBER", | |
| "red": "MIC DISTANCE RED ", | |
| }[band] | |
| out = [f" {head} {shown} [{how}]"] | |
| if band == "red": | |
| out.append(" a session recorded in this state followed 7% of 143 notes " | |
| "(20260916-113517). The fix is the MICROPHONE, closer -- not the volume.") | |
| elif band == "amber": | |
| out.append(" 4.5 dB gave 88% recall on this rig; 13 dB and above gave its best runs. " | |
| "Moving the microphone closer is worth ~6 dB per halving of distance.") | |
| return out | |
| def rig_response_line(m, fo): | |
| """What playback response the session's templates were built against. | |
| The follower's templates are a harmonic comb pushed through a model of the | |
| speaker -> room -> mic channel, and that channel is what decides which notes | |
| survive: in 20260915-204851 E3 (2nd partial on a +8.5 dB resonance) is never | |
| skipped and A3 (2nd partial past it) always is, at the same level. There is | |
| no built-in curve: unless a session passes `rigResponse` that model is the | |
| single 150 Hz one-pole corner in salience.js harmonicTemplate(), and the app | |
| deliberately does not pass the sweep's curve (the sweep above | |
| FOLLOWER_DEFAULTS.rigResponse measured it at 6/28 replay hits -> 8/9). So | |
| this line reports what the sweep SAW on this rig, which is diagnosis, and | |
| says plainly whether any of it reached a template, which is normally no. | |
| """ | |
| rig = m.get("rig") if isinstance(m.get("rig"), dict) else None | |
| opts = (fo or {}).get("options") or {} | |
| # The key the ENGINE reads (follower.js ScoreFollower): an object with `db`, | |
| # not a bare array. Reading anything else here reports on nobody. | |
| passed = opts.get("rigResponse") | |
| rows = passed.get("db") if isinstance(passed, dict) else None | |
| n_passed = len(rows) if isinstance(rows, list) else 0 | |
| if rig is None: | |
| if n_passed: | |
| return [f" rig response: {n_passed} rows reached the engine, but meta.rig is missing " | |
| f"(trace written by an app build that passed the curve without recording it)"] | |
| return [" rig response: not recorded -- trace predates the calibration sweep; " | |
| "templates used the built-in 150 Hz high-pass model"] | |
| if rig.get("source") != "measured": | |
| return [" rig response: never measured on this rig " | |
| f"({rig.get('device') or 'unknown device'}).", | |
| " No measured curve: templates use the built-in 150 Hz high-pass model. " | |
| "Run Calculate", | |
| " Latency in the mic panel (it ends with a ~3 s tone sweep) to measure this rig's."] | |
| when = time.strftime("%Y-%m-%d %H:%M", time.localtime((rig.get("at") or 0) / 1000)) if rig.get("at") else "?" | |
| line = (f" rig response: measured {when} on {rig.get('device') or '?'} -- " | |
| f"{rig.get('rows')}/{rig.get('total')} rows, span {rig.get('spanDb')} dB, " | |
| f"peak {num(rig.get('peakDb'), '+.1f')} dB at {pn(rig.get('peakMidi'))}, " | |
| f"dip {num(rig.get('dipDb'), '+.1f')} dB at {pn(rig.get('dipMidi'))}") | |
| if rig.get("snrDb") is not None: | |
| line += f", tone SNR {rig['snrDb']} dB" | |
| out = [line] | |
| # The sweep's OTHER reading, and the one that has actually moved a session: | |
| # the broadband level its solo-range tones came back at, which is the only | |
| # thing that can tell the noise gate where the notes are (app.js | |
| # RIG_GATE_HEADROOM_DB). | |
| cap = rig.get("gateCap") if isinstance(rig.get("gateCap"), dict) else None | |
| if cap: | |
| head = "" if cap.get("headroomDb") is None else f", {cap['headroomDb']} dB over the room" | |
| out.append(f" gate ceiling {cap.get('units')}: quietest of {cap.get('nTones')} solo-range " | |
| f"tones came back at {1000 * (cap.get('quietestRms') or 0):.1f}{head}") | |
| # WAS THE CALIBRATION LEVELLED LIKE THE MUSIC? Until 2026-09-16 both | |
| # calibration paths played a raw oscillator at amplitude 0.18, which came | |
| # back off this rig's mic at 0.03573 against 0.01077 for a real vel-0.5 | |
| # sampled note -- 10.4 dB raw, 15.1 dB once the room (0.00889) is taken out | |
| # of both in power. Every quantity the calibration derived, the gate ceiling | |
| # above included, was therefore measured on a signal that no piece of music | |
| # produces. The app now measures one REAL note per calibration and levels | |
| # the sweep against it, and records the residual it achieved. | |
| # | |
| # `sineAmp` absent is the tell for a trace from before that landed: read its | |
| # gate ceiling and its quietest-tone level as ~10 dB high. | |
| note = rig.get("noteLevel") if isinstance(rig.get("noteLevel"), dict) else None | |
| if note and note.get("bodyRms"): | |
| body = 1000 * note["bodyRms"] | |
| room = note.get("roomRms") | |
| over = f", {20 * math.log10(note['bodyRms'] / room):+.1f} dB over the room" if room else "" | |
| out.append(f" reference note: {pn(note.get('midi'))} at velocity " | |
| f"{note.get('velocity')} came back at {body:.1f}{over} " | |
| f"-- the level the gate ceiling is held under") | |
| if rig.get("sineAmp") is None: | |
| out.append(" (test tones played at the OLD fixed 0.18 oscillator: ~10 dB louder than " | |
| "any played note, so the gate ceiling above is ~10 dB high)") | |
| elif rig.get("sineMatchDb") is not None: | |
| d = rig["sineMatchDb"] | |
| how = "level with" if abs(d) < 0.05 else (f"{d} dB OVER" if d > 0 else f"{-d} dB under") | |
| flag = "" if abs(d) <= 3 else " <- the tones are still not levelled like the music" | |
| out.append(f" test tones played {how} a real note " | |
| f"(amplitude {rig['sineAmp']}, trim {num(rig.get('sineTrimDb'), '+.1f')} dB){flag}") | |
| # Expected, not a warning: the app does not pass the curve (see the | |
| # docstring). Say so anyway, because a rig line that only quotes a +8 dB | |
| # resonance reads as if the templates knew about it. | |
| if fo is not None and not n_passed: | |
| out.append(" (measured only -- no `rigResponse` in the engine options, " | |
| "so templates used the built-in 150 Hz high-pass model)") | |
| return out | |
| def print_meta(tr): | |
| m = tr.get("meta") or {} | |
| lat = m.get("latency") or {} | |
| print("=" * 96) | |
| print(f"SESSION {m.get('score') or '(unnamed score)'} started {tr.get('startedAt')} " | |
| f"{(tr.get('durationMs') or 0) / 1000:.1f}s ended: {tr.get('reason')}") | |
| print(f" input {m.get('inputMode')} follow {m.get('followMode')} adaptive tempo {m.get('adaptiveTempo')} " | |
| f"start {round((m.get('initialBps') or 0) * 60)}bpm @ beat {m.get('startBeat')}") | |
| # Two shapes. Sessions recorded after the compensation was rebuilt carry | |
| # detectionMs + detectionSource + outputUsedMs and compensate by those two | |
| # alone; older ones carry base + mic + output and SUMMED ALL THREE, which | |
| # double-counted the detection lag (the latency test measures one too) -- | |
| # say so, or an old number read next to a new one looks like a regression. | |
| meas_out = lat.get("measuredOutputMs") | |
| meas_out_txt = f"{meas_out:.0f}ms" if isinstance(meas_out, (int, float)) else "not reported" | |
| if lat.get("detectionMs") is not None: | |
| print(f" latency comp: detection {lat.get('detectionMs')}ms ({lat.get('detectionSource')}) " | |
| f"+ output {lat.get('outputUsedMs')}ms = {lat.get('effectiveMs')}ms at the start of the session" | |
| f" (latency test: {lat.get('baseMs')}ms; browser-measured output: {meas_out_txt})") | |
| else: | |
| print(f" latency comp: base {lat.get('baseMs')}ms + mic {lat.get('micMs')}ms + output {lat.get('outputMs')}ms " | |
| f"= {lat.get('effectiveMs')}ms (browser-measured output: {lat.get('measuredOutputMs')})") | |
| print(" pre-2026-09-16 formula: `base` is the latency test's own detection lag and was summed " | |
| "ON TOP of the engine's, so this session compensated roughly twice the delay it had") | |
| sinks = m.get("sinks") or {} | |
| print(f" outputs: solo={sinks.get('solo')} accompaniment={sinks.get('accompaniment')} mic={m.get('micId')}") | |
| if m.get("inputMode") == "mic": | |
| print(f" noise gate: {m.get('noiseGate') if m.get('noiseGate') is not None else 'unknown (older trace)'}") | |
| # Only traces recorded since the engine switch exists carry micEngine; older | |
| # traces (implicitly classic) render exactly as before. | |
| if "micEngine" in m and m.get("inputMode") == "mic": | |
| print(f" mic engine: {m.get('micEngine') or 'classic'}") | |
| fo = m.get("follower") | |
| if isinstance(fo, dict): | |
| opts = fo.get("options") or {} | |
| defaults = FOLLOWER_DEFAULTS_KNOWN | |
| tuned = {k: v for k, v in opts.items() | |
| if k not in BULKY_OPTIONS and (k not in defaults or defaults[k] != v)} | |
| print(f" follower: version {fo.get('version')} tag {fo.get('tag') or '-'} win {fo.get('win')} hop {fo.get('hop')} sr {fo.get('sr')}" | |
| f" midi {fo.get('minMidi')}..{fo.get('maxMidi')}") | |
| if fo.get("version") != FOLLOWER_VERSION_KNOWN: | |
| # Another engine version: its defaults are unknown here, so the diff would list every moved default. | |
| print(f" options: not compared (engine {fo.get('version')}, report knows the defaults of {FOLLOWER_VERSION_KNOWN}; " | |
| f"{len(opts)} options logged)") | |
| elif tuned: | |
| print(f" options: {json.dumps(tuned, sort_keys=True)}") | |
| if m.get("inputMode") == "mic" or m.get("rig") is not None: | |
| # The verdict goes ABOVE the rig curve: a reader who gets no further than | |
| # the header still learns whether this session had a chance. | |
| for line in mic_distance_lines(m): | |
| print(line) | |
| for line in rig_response_line(m, fo if isinstance(fo, dict) else None): | |
| print(line) | |
| print(f" score: {len(m.get('rh') or [])} solo events, {len(m.get('lh') or [])} accompaniment events") | |
| # Score events outside the analyser's bank, per session (see bank_census). | |
| lo = fo.get("minMidi") if isinstance(fo, dict) and isinstance(fo.get("minMidi"), int) else BANK_MIN_MIDI | |
| hi = fo.get("maxMidi") if isinstance(fo, dict) and isinstance(fo.get("maxMidi"), int) else BANK_MAX_MIDI | |
| below, above, n_unhear, unhear = bank_census(m.get("rh") or [], lo, hi) | |
| # The engine's own classification when the trace carries it (app.js records | |
| # ScoreFollower.bankCensus in follower.init/meta.follower from FOLLOWER_VERSION | |
| # 2026-09-16.1). It is the authority: it tests each event's actual template | |
| # rather than asking whether a pitch number is inside 33..96, so it is right | |
| # at both ends -- below the bank a note is still heard through its partials, | |
| # and above it the cliff is maxMidi + 2. The recompute above stays as the | |
| # fallback, because it works on every trace ever recorded. | |
| census_src = "recomputed from the score" | |
| bc = fo.get("bankCensus") if isinstance(fo, dict) else None | |
| if isinstance(bc, dict) and isinstance(bc.get("unheard"), int): | |
| below = bc.get("below", below) | |
| above = bc.get("above", above) | |
| n_unhear = bc["unheard"] | |
| unhear = [i for i in (bc.get("unheardIndices") or []) if isinstance(i, int)] | |
| census_src = "as the engine classified it" | |
| # PRINTED EVERY SESSION, including the all-zero case. It used to be | |
| # suppressed when a score was entirely inside the bank, which reads the same | |
| # as a report too old to know about the bank at all -- and "is this piece in | |
| # range?" is a question about the session being read, not about whether the | |
| # answer happens to be interesting. Twinkle says so in one line; Liebestraum | |
| # says 5 below. | |
| if below or above or n_unhear: | |
| idx = ", ".join(str(i) for i in unhear[:12]) + (" ..." if len(unhear) > 12 else "") | |
| print(f" out of bank (MIDI {lo}..{hi}, {census_src}): {below} solo event(s) with a pitch below, {above} above; " | |
| f"{n_unhear} UNHEARABLE (no template can represent them)" + (f" -- #{idx}" if unhear else "")) | |
| if n_unhear: | |
| print(" the follower steps over those instead of waiting for them (outOfBankSkip); " | |
| "each is logged once as follow.hold reason out-of-bank") | |
| elif below: | |
| print(" the ones below the bank are still followed, through their partials " | |
| "(a MIDI-32 note's 2nd-6th are 103.8-311.5 Hz, inside the bank)") | |
| else: | |
| print(f" out of bank (MIDI {lo}..{hi}, {census_src}): none -- " | |
| f"every one of the {len(m.get('rh') or [])} solo events is representable") | |
| if m.get("notes"): | |
| print(f" PLAYER NOTES: {m['notes']}") | |
| print("=" * 96) | |
| # --- ACCOMPANIMENT QUALITY --------------------------------------------------- | |
| # | |
| # EVERY OTHER NUMBER IN THIS REPORT DESCRIBES WHAT THE ENGINE HEARD. None of | |
| # them describes what the room heard, and on 20260916-202657_03-musicxml- | |
| # liebestraum-no the two came apart completely: 88% recall, 96% precision, | |
| # 241/241 single notes -- and the user's verdict was "at measure 23 I just | |
| # can't hear the left hand play the notes any more, and magically teleports to | |
| # measure 25". Measured from that trace: | |
| # | |
| # t=144.7s accompaniment plays beat 137 (meta.lh #69) <- last note heard | |
| # t=145.5s auto-skip moves the soloist 241 -> 242, beat 146; | |
| # accomp.sync logs driftBeats -8.14 and _lhIdx goes 70 -> 80 | |
| # t=150.7s accompaniment resumes at beat 147 (meta.lh #80) | |
| # | |
| # Ten accompaniment notes -- beats 138, 139, 142, 142.5, 143, 143.5, 144, | |
| # 144.5, 145, 145.5, the left-hand arpeggio of measures 23-24 -- were deleted | |
| # by the Accompanist's "skip LH events now in the past" loop and never | |
| # sounded: 10 of the 88 notes in the covered range, 11%, and six seconds of | |
| # silence where the score asks for a note every beat. NOTHING in this report | |
| # saw it, because nothing measured the accompaniment part itself. | |
| # | |
| # So this section reconstructs what the left hand actually played, from | |
| # accomp.fire against meta.lh (the accompaniment part, [[pitches], beat]), and | |
| # reports the four things a listener would have complained about: notes that | |
| # never sounded, silences, lurches in the accompaniment's own beat, and | |
| # seconds-per-beat against the score's tempo. Each is tied to the trace event | |
| # that plausibly caused it -- a skip, a resync, or a large accomp.sync drift -- | |
| # when one sits in the same window. | |
| # | |
| # A fix is judged HERE. Detection recall going up while dropped notes stay at | |
| # 11% is not an improvement to the music. | |
| # How much further than the score's own spacing the accompaniment's beat may | |
| # jump between two consecutive notes before it is a lurch rather than a nudge. | |
| # The routine correction is the beat clock being re-anchored by a few tens of | |
| # milliseconds (accomp.sync driftBeats median 0.01 over the reference traces); | |
| # the event this exists to catch is +9. One whole beat is far above the former | |
| # and far below the latter. | |
| ACC_LURCH_BEATS = 1.0 | |
| # A catch-up dump: consecutive notes fired at less than half the spacing the | |
| # score gives them, three or more in a row. Two in a row is an ordinary | |
| # re-anchor landing on a pair of grace-spaced notes; the failure mode worth a | |
| # line is the accompaniment machine-gunning the bars it missed. | |
| ACC_BURST_RATIO = 0.5 | |
| ACC_BURST_MIN_NOTES = 3 | |
| # An accomp.sync whose driftBeats is at least this is the tracker telling the | |
| # accompaniment it is a whole beat or more out of place -- the moment a hole | |
| # gets opened (202657 logs -8.14 there). Below it the sync is the normal | |
| # per-note correction and there are hundreds of them. | |
| ACC_SYNC_JUMP_BEATS = 1.0 | |
| # A cause is credited to a window if it fired inside it or just before it. The | |
| # sync that opened the 202657 hole is logged 0.1 ms after the skip and 857 ms | |
| # after the last note that sounded, so the window starting at that note already | |
| # contains both; the pre-roll is for a skip that lands just before the note it | |
| # strands. | |
| ACC_CAUSE_PREROLL_MS = 500 | |
| ACC_TOP = 5 | |
| def bt(b): | |
| """Beat numbers read as music: 147, 147.5, not 147.0.""" | |
| return f"{b:g}" if isinstance(b, (int, float)) and not isinstance(b, bool) else "?" | |
| def lh_score(tr): | |
| """meta.lh as [(pitches, beat)], junk dropped. | |
| Written by app.js as [[midi...], beat] per accompaniment event, so a | |
| two-note left-hand chord is ONE event and counts as one note here -- that | |
| is what a listener hears go missing. | |
| """ | |
| out = [] | |
| for item in ((tr.get("meta") or {}).get("lh") or []): | |
| if not isinstance(item, (list, tuple)) or len(item) < 2: | |
| continue | |
| ps, b = item[0], item[1] | |
| if not isinstance(b, (int, float)) or isinstance(b, bool): | |
| continue | |
| ps = [p for p in (ps if isinstance(ps, (list, tuple)) else [ps]) | |
| if isinstance(p, (int, float)) and not isinstance(p, bool)] | |
| out.append((sorted(int(p) for p in ps), float(b))) | |
| return out | |
| def resolve_lh_indices(fires, lh): | |
| """Which meta.lh event each accomp.fire played, as a list parallel to `fires`. | |
| `lhIdx` has been on accomp.fire since the Accompanist grew one and is | |
| authoritative. Older traces carry only `beat` and `pitches`, so those are | |
| matched to the score by pitch first, then beat distance, preferring an | |
| index at or after the last one resolved (the accompaniment walks forward). | |
| """ | |
| out, last = [], -1 | |
| for e in fires: | |
| i = e.get("lhIdx") | |
| if isinstance(i, int) and not isinstance(i, bool) and 0 <= i < len(lh): | |
| out.append(i) | |
| last = max(last, i) | |
| continue | |
| b = e.get("beat") | |
| if not isinstance(b, (int, float)) or isinstance(b, bool) or not lh: | |
| out.append(None) | |
| continue | |
| ps = sorted(int(p) for p in (e.get("pitches") or []) | |
| if isinstance(p, (int, float)) and not isinstance(p, bool)) | |
| floor = last | |
| j = min(range(len(lh)), key=lambda k: (0 if lh[k][0] == ps else 1, | |
| abs(lh[k][1] - b), 0 if k >= floor else 1, k)) | |
| out.append(j) | |
| last = max(last, j) | |
| return out | |
| def accomp_causes(ev): | |
| """(t, text) for every trace event that can move the accompaniment's place. | |
| These are the things that reposition it: an auto- or manual skip, an | |
| accepted resync, an accomp.sync arriving a whole beat or more out of place | |
| (the Accompanist TOLD the soloist is elsewhere, which is where _lhIdx jumps) | |
| -- and, from static/app.js FOLLOWER_VERSION_TAG 20260916-ff33 on, the | |
| Accompanist's own confession: `accomp.pass` names every unplayed note it | |
| stepped over and whether it re-anchored (sounded the last of them at the new | |
| position) or simply let them go. On a trace that carries it, that event is | |
| the direct answer to a DROPPED run and no cause has to be inferred. | |
| """ | |
| out = [] | |
| for e in ev: | |
| t, ty = e.get("t"), e.get("type") | |
| if not isinstance(t, (int, float)): | |
| continue | |
| if ty == "skip": | |
| held = f", held {e['heldMs']:.0f}ms" if isinstance(e.get("heldMs"), (int, float)) else "" | |
| out.append((t, f"skip({e.get('reason') or '?'}) #{e.get('fromIndex')} -> #{e.get('toIndex')} " | |
| f"to beat {bt(e.get('beat'))}{held}")) | |
| elif ty == "follow.resync" and e.get("accepted"): | |
| out.append((t, f"resync #{e.get('fromIndex')} -> #{e.get('toIndex')} (+{e.get('jump')} events)")) | |
| elif ty == "accomp.pass": | |
| n = e.get("count") | |
| where = f"beats {bt(e.get('fromBeat'))}..{bt(e.get('toBeat'))}" | |
| # The wording comes from the event's own jumpBeats, NOT from its | |
| # cause: every ordinary pass has cause 'sync' (both callers of | |
| # _passLhTo use it), so keying off the cause printed a 10-note, | |
| # 5.5-beat hole as "let go (small correction)" whenever the | |
| # re-anchor guards refused -- exactly the blindness §4 exists to | |
| # remove. A pass under one beat really is the per-note correction. | |
| jump = e.get("jumpBeats") | |
| small = (isinstance(jump, (int, float)) and not isinstance(jump, bool) | |
| and abs(jump) < ACC_SYNC_JUMP_BEATS) | |
| how = (f"RE-ANCHORED at beat {bt(e.get('anchorBeat'))}" if e.get("reanchored") | |
| else "let go (small correction)" if small | |
| else f"LET GO, no re-anchor (jump {num(jump, '.2f')} beats)") | |
| out.append((t, f"accomp.pass({e.get('cause') or '?'}) {n} unplayed note(s) #{e.get('fromIdx')}..#{(e.get('toIdx') or 0) - 1} " | |
| f"{where} -- {how}")) | |
| elif ty == "follow.seek": | |
| out.append((t, f"seek to score event #{e.get('position')}")) | |
| elif ty == "accomp.sync": | |
| d = e.get("driftBeats") | |
| if isinstance(d, (int, float)) and not isinstance(d, bool) and abs(d) >= ACC_SYNC_JUMP_BEATS: | |
| out.append((t, f"accomp.sync drift {d:+.2f} beats -- soloist at beat {bt(e.get('beat'))}, " | |
| f"accompaniment clock at {num(e.get('clockBeatBefore'), '.2f')}, " | |
| f"lhIdx {e.get('lhIdxBefore')}")) | |
| return out | |
| def causes_near(causes, t0, t1): | |
| return [c for c in causes if t0 - ACC_CAUSE_PREROLL_MS <= c[0] <= t1] | |
| # ── "is the left hand with me?" ───────────────────────────────────────────── | |
| # The accompaniment's own timing error, in the only frame of reference the | |
| # player has: the sound in the room. | |
| # | |
| # The `clock drift` line below it CANNOT answer this, and reading it as if it | |
| # could is what hid a 152 ms error for a week. Two reasons. (1) Its zero is | |
| # wrong: a confirmed note is already `detection lag` old when it arrives, and | |
| # the accompaniment's own sound is `output latency` away, so a clock that is | |
| # CORRECTLY compensated reads ahead by the sum -- 0 there means the | |
| # accompaniment is late by that much. (2) In leader mode the clock is clamped | |
| # at the next solo checkpoint and simply stops, so 95% of the samples are the | |
| # clamp, not the compensation (on 20260916-212337, median +9 ms while the notes | |
| # were sounding 152 ms early). | |
| # | |
| # What is measured here instead, per accompaniment note that sounded: | |
| # audible instant = accomp.fire.t + the browser's measured output latency | |
| # the soloist's own sound at that beat | |
| # = (follow.advance.t - follow.advance.lagMs), the engine's | |
| # own measured detection lag, interpolated in beat | |
| # Negative = the accompaniment sounded EARLY. Stretches where the soloist | |
| # stopped are dropped rather than interpolated across (a stall is a different | |
| # failure and the ACCOMPANIMENT section names it). | |
| AUDIBLE_MAX_BEAT_GAP = 2.0 # bracketing solo notes further apart than this: no honest ideal | |
| # ...nor when they took this much longer in real time than their own beats. The | |
| # median barely notices it (-151 ms at 1.5, -157 at 3.0 on 20260916-212337), so | |
| # it is not load-bearing; it is the p10 that stalls poison, because a note the | |
| # accompaniment played while the soloist was stuck is early against an ideal | |
| # that never happened. 2.0 is where the tail stops moving (p10 -241 at both 2.0 | |
| # and 2.2, -543 at 2.5). | |
| AUDIBLE_MAX_GAP_RATIO = 2.0 | |
| def accompaniment_audible_offsets(tr, by): | |
| """[(beat, offset_ms)] per accomp.fire, + = sounded late. Empty when the | |
| session carries no measured detection lag (classic engine, older traces).""" | |
| lat = (tr.get("meta") or {}).get("latency") or {} | |
| out_ms = lat.get("measuredOutputMs") | |
| if not isinstance(out_ms, (int, float)) or isinstance(out_ms, bool): | |
| out_ms = lat.get("outputUsedMs") | |
| if not isinstance(out_ms, (int, float)) or isinstance(out_ms, bool): | |
| return [] | |
| pts, bpss = [], [] | |
| for a in by["follow.advance"]: | |
| if not a.get("accepted"): | |
| continue | |
| beat, lag = a.get("beat"), a.get("lagMs") | |
| if not isinstance(beat, (int, float)) or not isinstance(lag, (int, float)): | |
| continue | |
| t = a["t"] - lag | |
| if pts and (beat <= pts[-1][0] or t <= pts[-1][1]): | |
| continue # keep it monotone in both beat and time | |
| pts.append((beat, t)) | |
| bpss.append(a.get("bps") if isinstance(a.get("bps"), (int, float)) else 1.0) | |
| if len(pts) < 2: | |
| return [] | |
| beats = [p[0] for p in pts] | |
| rows = [] | |
| for f in by["accomp.fire"]: | |
| b = f.get("beat") | |
| if not isinstance(b, (int, float)) or b <= beats[0] or b > beats[-1]: | |
| continue | |
| i = bisect.bisect_left(beats, b) | |
| if i == 0 or i >= len(pts): | |
| continue | |
| b0, t0 = pts[i - 1] | |
| b1, t1 = pts[i] | |
| if b1 - b0 > AUDIBLE_MAX_BEAT_GAP: | |
| continue | |
| bps = bpss[i] or 1.0 | |
| expected_ms = (b1 - b0) / max(0.2, bps) * 1000 | |
| if t1 - t0 > AUDIBLE_MAX_GAP_RATIO * expected_ms: | |
| continue # the soloist stopped in this gap | |
| ideal = t0 + (b - b0) / (b1 - b0) * (t1 - t0) | |
| rows.append((b, (f["t"] + out_ms) - ideal)) | |
| return rows | |
| def accompaniment_lines(tr, by): | |
| """The ACCOMPANIMENT section: what the left hand actually played.""" | |
| ev = tr.get("events") or [] | |
| fires = by["accomp.fire"] | |
| lh = lh_score(tr) | |
| out = ["", "ACCOMPANIMENT what the left hand actually played (accomp.fire vs meta.lh)"] | |
| if not fires: | |
| out.append(" no accompaniment notes fired in this session" | |
| + ("" if lh else ", and no meta.lh was recorded")) | |
| return out | |
| if not lh: | |
| # Traces recorded before meta.lh was saved, and sessions with no | |
| # accompaniment part selected. The fire stream alone still shows | |
| # silences; only "dropped" and "lurch" need the score. | |
| out.append(f" {len(fires)} notes fired, but this trace carries no meta.lh -- " | |
| "dropped notes and lurches cannot be computed from it") | |
| idxs = resolve_lh_indices(fires, lh) | |
| beats = [e.get("beat") if isinstance(e.get("beat"), (int, float)) and not isinstance(e.get("beat"), bool) | |
| else None for e in fires] | |
| resolved = [i for i in idxs if i is not None] | |
| played = set(resolved) | |
| bps_seen = [e["bps"] for e in fires | |
| if isinstance(e.get("bps"), (int, float)) and not isinstance(e.get("bps"), bool) and e["bps"] > 0] | |
| meta = tr.get("meta") or {} | |
| nominal_bps = statistics.median(bps_seen) if bps_seen else ( | |
| meta.get("initialBps") if isinstance(meta.get("initialBps"), (int, float)) else None) | |
| causes = accomp_causes(ev) | |
| # -- DROPPED NOTES -- | |
| # Over the range the accompaniment actually covered: from the first note it | |
| # played to the last. Notes past the end were never reached (the session | |
| # stopped) and are reported separately as a tail, so they cannot inflate | |
| # the headline percentage. | |
| if lh and resolved: | |
| lo, hi = min(resolved), max(resolved) | |
| covered = hi - lo + 1 | |
| missing = [i for i in range(lo, hi + 1) if i not in played] | |
| runs = [] | |
| for i in missing: | |
| if runs and runs[-1][1] == i - 1: | |
| runs[-1][1] = i | |
| else: | |
| runs.append([i, i]) | |
| out.append(f" covered meta.lh #{lo}..#{hi} (beats {bt(lh[lo][1])}..{bt(lh[hi][1])}): " | |
| f"{covered} accompaniment notes in the score there, {len(played)} sounded") | |
| if missing: | |
| out.append(f" DROPPED: {len(missing)} of {covered} notes ({100.0 * len(missing) / covered:.1f}%) " | |
| f"NEVER SOUNDED, in {len(runs)} run{'s' if len(runs) != 1 else ''}") | |
| # Worst first: a two-bar hole and twelve scattered singles are not | |
| # the same complaint, and it is the hole the user can hear. | |
| ranked = sorted(runs, key=lambda r: (-(r[1] - r[0] + 1), r[0])) | |
| for a, b in ranked[:ACC_TOP]: | |
| nxt = next((k for k, i in enumerate(idxs) if i is not None and i > b), None) | |
| t0 = fires[nxt - 1].get("t") if nxt else None | |
| t1 = fires[nxt].get("t") if nxt is not None else None | |
| when = (f"silent t={t0 / 1000:.1f}s..{t1 / 1000:.1f}s ({(t1 - t0) / 1000:.1f}s)" | |
| if isinstance(t0, (int, float)) and isinstance(t1, (int, float)) | |
| else "no note followed it in this session") | |
| tag = "WORST RUN: " if [a, b] == ranked[0] and len(ranked) > 1 else "" | |
| where = (f"1 note #{a} beat {bt(lh[a][1])}" if a == b else | |
| f"{b - a + 1} notes #{a}..#{b} beats {bt(lh[a][1])}..{bt(lh[b][1])}") | |
| out.append(f" {tag}{where} {when}") | |
| for ct, ctext in causes_near(causes, | |
| t0 if isinstance(t0, (int, float)) else 0.0, | |
| t1 if isinstance(t1, (int, float)) else float("inf"))[:3]: | |
| out.append(f" cause? t={ct / 1000:.1f}s {ctext}") | |
| if len(ranked) > ACC_TOP: | |
| out.append(f" ... and {len(ranked) - ACC_TOP} more run(s)") | |
| else: | |
| out.append(" DROPPED: none -- every accompaniment note in the covered range sounded") | |
| # The tail: the soloist went on and the left hand did not. | |
| solo_beats = [e.get("beat") for e in by["tracker"] | |
| if e.get("result") == "match" and isinstance(e.get("beat"), (int, float)) | |
| and not isinstance(e.get("beat"), bool)] | |
| if solo_beats and max(solo_beats) > lh[hi][1] + 1e-9: | |
| tail = [i for i in range(hi + 1, len(lh)) if lh[i][1] <= max(solo_beats) + 1e-9] | |
| if tail: | |
| out.append(f" TAIL: the soloist reached beat {bt(max(solo_beats))} but the accompaniment's last " | |
| f"note was beat {bt(lh[hi][1])} -- {len(tail)} further note(s) were never reached") | |
| # -- SILENCES -- | |
| # In seconds AND in beats, because they answer different questions: six | |
| # seconds says what the listener endured, ten beats says how much music | |
| # went by. The score's own spacing to the next note is printed beside each | |
| # one so a deliberate wait at a checkpoint (long in seconds, one beat of | |
| # score, nothing dropped) reads differently from a hole. | |
| gaps = [] | |
| for k in range(1, len(fires)): | |
| t0, t1 = fires[k - 1].get("t"), fires[k].get("t") | |
| if not isinstance(t0, (int, float)) or not isinstance(t1, (int, float)): | |
| continue | |
| i0, i1 = idxs[k - 1], idxs[k] | |
| db = (beats[k] - beats[k - 1]) if beats[k] is not None and beats[k - 1] is not None else None | |
| want = (lh[i0 + 1][1] - lh[i0][1]) if (lh and i0 is not None and i0 + 1 < len(lh)) else None | |
| lost = (sum(1 for i in range(i0 + 1, i1) if i not in played) | |
| if lh and i0 is not None and i1 is not None and i1 > i0 else 0) | |
| gaps.append({"k": k, "t0": t0, "t1": t1, "dt": t1 - t0, "db": db, "want": want, "lost": lost}) | |
| if gaps: | |
| out.append(" SILENCES (longest gaps between consecutive accompaniment notes):") | |
| for g in sorted(gaps, key=lambda g: -g["dt"])[:ACC_TOP]: | |
| k = g["k"] | |
| want, over = "", 0.0 | |
| if g["want"] is not None: | |
| want = (f"; score's own gap to the next note {bt(round(g['want'], 3))} beat" | |
| f"{'' if abs(g['want'] - 1) < 1e-9 else 's'}") | |
| if nominal_bps: | |
| # The part of the silence the music does not account for. | |
| # A 6 s gap over a 6-beat rest at 60 bpm is the piece; a 6 s | |
| # gap over a 1-beat step is the hole. | |
| over = g["dt"] / 1000 - g["want"] / nominal_bps | |
| if over > 1.0: | |
| want += f" -> {over:.1f}s of it is NOT in the score" | |
| lost = f" [{g['lost']} note(s) DROPPED across it]" if g["lost"] else "" | |
| out.append(f" {g['dt'] / 1000:5.2f}s" | |
| + (f" / {g['db']:g} beats" if g["db"] is not None else "") | |
| + f" t={g['t0'] / 1000:.1f}s..{g['t1'] / 1000:.1f}s " | |
| + f"beat {bt(beats[k - 1])} -> {bt(beats[k])}{want}{lost}") | |
| suspicious = bool(g["lost"]) or over > 1.0 | |
| if suspicious: | |
| for ct, ctext in causes_near(causes, g["t0"], g["t1"])[:2]: | |
| out.append(f" cause? t={ct / 1000:.1f}s {ctext}") | |
| # -- LURCHES -- | |
| # The same failure seen in beat space: the accompaniment's own position | |
| # moving further than the score moves it. Backwards counts too -- a | |
| # re-anchor that lands behind is just as audible as one that lands ahead. | |
| lurches = [g for g in gaps if g["db"] is not None and g["want"] is not None | |
| and (g["db"] > g["want"] + ACC_LURCH_BEATS or g["db"] < 0)] | |
| if lh: | |
| out.append(f" LURCHES (its own beat jumping more than {ACC_LURCH_BEATS:g} beat past the score's " | |
| f"spacing, or backwards): {len(lurches)}") | |
| for g in sorted(lurches, key=lambda g: -abs(g["db"] - g["want"]))[:ACC_TOP]: | |
| k = g["k"] | |
| out.append(f" t={g['t1'] / 1000:.1f}s beat {bt(beats[k - 1])} -> {bt(beats[k])} " | |
| f"({g['db'] - g['want']:+g} beats past the score's {bt(round(g['want'], 3))}), " | |
| f"{g['lost']} note(s) jumped over") | |
| for ct, ctext in causes_near(causes, g["t0"], g["t1"])[:2]: | |
| out.append(f" cause? t={ct / 1000:.1f}s {ctext}") | |
| # The other half of a lurch is the catch-up dump: playing the bars it | |
| # missed at machine-gun speed instead of picking up where the soloist is. | |
| fast = [g for g in gaps if g["want"] and g["want"] > 0 and nominal_bps | |
| and g["dt"] / 1000 < ACC_BURST_RATIO * (g["want"] / nominal_bps)] | |
| bursts, cur = [], None | |
| for g in fast: | |
| if cur is not None and g["k"] == cur[-1]["k"] + 1: | |
| cur.append(g) | |
| else: | |
| cur = [g] | |
| bursts.append(cur) | |
| bursts = [b for b in bursts if len(b) + 1 >= ACC_BURST_MIN_NOTES] | |
| if bursts: | |
| out.append(f" BURSTS (notes dumped faster than half the score's own spacing): {len(bursts)}") | |
| for b in sorted(bursts, key=lambda b: -len(b))[:ACC_TOP]: | |
| span_ms = b[-1]["t1"] - b[0]["t0"] | |
| span_beats = sum(g["want"] for g in b) | |
| out.append(f" t={b[0]['t0'] / 1000:.1f}s..{b[-1]['t1'] / 1000:.1f}s {len(b) + 1} notes, " | |
| f"beats {bt(beats[b[0]['k'] - 1])}..{bt(beats[b[-1]['k']])} -- " | |
| f"{span_beats:g} beats of score in {span_ms / 1000:.2f}s " | |
| f"({span_ms / 1000 / span_beats:.2f}s/beat against the score's {1 / nominal_bps:.2f})") | |
| for ct, ctext in causes_near(causes, b[0]["t0"], b[-1]["t1"])[:2]: | |
| out.append(f" cause? t={ct / 1000:.1f}s {ctext}") | |
| elif lh and nominal_bps: | |
| out.append(" BURSTS: none") | |
| # -- TIMING -- | |
| # Seconds per beat over the gaps the accompaniment walked NORMALLY: the | |
| # score's own spacing, nothing dropped across it. Lurches and dumps are | |
| # excluded on purpose -- they would swamp the statistic and they are | |
| # already reported above. What is left is genuine rushing or dragging, | |
| # which is the other thing the user said ("I hear the left hand rush too | |
| # much"), and it has to stay distinguishable from a lurch. | |
| spb = [(g["dt"] / 1000) / g["want"] for g in gaps | |
| if g["want"] and g["want"] > 0 and not g["lost"] | |
| and g["db"] is not None and abs(g["db"] - g["want"]) < 1e-6] | |
| if spb and nominal_bps: | |
| want_spb = 1.0 / nominal_bps | |
| med = statistics.median(spb) | |
| drift = 100.0 * (med - want_spb) / want_spb | |
| verdict = ("on tempo" if abs(drift) < 2 | |
| else (f"RUSHING {abs(drift):.1f}%" if drift < 0 else f"dragging {drift:.1f}%")) | |
| out.append(f" TIMING: {med:.3f} s/beat median over {len(spb)} clean gaps against the score's " | |
| f"{want_spb:.3f} ({nominal_bps * 60:.0f} bpm) -- {verdict}; " | |
| f"p10 {pct(spb, .1):.3f} p90 {pct(spb, .9):.3f}") | |
| else: | |
| out.append(" TIMING: no gap was clean enough to measure seconds-per-beat on") | |
| return out | |
| def analyse(tr): | |
| ev = tr.get("events") or [] | |
| by = defaultdict(list) | |
| for e in ev: | |
| by[e.get("type")].append(e) | |
| out = [] | |
| counts = Counter(e.get("type") for e in ev) | |
| out.append("EVENT COUNTS " + " ".join(f"{k}={v}" for k, v in sorted(counts.items()))) | |
| # ── failures ── | |
| # First thing after the counts, because a session that failed to start is | |
| # not worth reading any other statistic from. These events only exist since | |
| # the app grew global error capture; older traces simply have none. | |
| fails = [e for e in ev if e.get("type") in | |
| ("error", "start.error", "samples.error", "meta.error", "start.abort")] | |
| # `error` is what the app logs on both follower.init failure paths (the | |
| # engine itself and the describe step); `describeError` is the older key, | |
| # kept so traces recorded before that rename still surface here. | |
| fails += [e for e in by["follower.init"] if e.get("error") or e.get("describeError")] | |
| if fails: | |
| out.append("") | |
| out.append(f"!! FAILURES {len(fails)} — this session did not run cleanly") | |
| for e in fails[:12]: | |
| out.append(f" {secs(e.get('t', 0))} {fmt_event(e)}") | |
| if len(fails) > 12: | |
| out.append(f" ... and {len(fails) - 12} more") | |
| if any(e.get("type") == "start.error" for e in fails): | |
| out.append(" start.error means startPlaying threw: the session was torn down, " | |
| "so the numbers below cover a stillborn run.") | |
| # ── tracker ── | |
| tk = by["tracker"] | |
| matches = [e for e in tk if e.get("result") == "match"] | |
| rejects = [e for e in tk if e.get("result") == "reject"] | |
| out.append("") | |
| out.append(f"TRACKER {len(matches)} matches, {len(rejects)} rejections" | |
| + (f" ({100 * len(matches) / len(tk):.0f}% match rate)" if tk else "")) | |
| # NOT EVERY TRACKER MOVE IS A DETECTION. A skip and a resync both move the | |
| # tracker and both log a `tracker` event, so they sit inside the match count | |
| # above; the precision figure in the scorecard is computed from `mic.note` | |
| # alone and neither of them writes one. Spell the split out here so the match | |
| # rate cannot be read as "the engine heard this many notes". | |
| not_heard = [e for e in matches if e.get("resync") or str(e.get("src") or "").startswith("skip")] | |
| if not_heard: | |
| kinds = Counter("resync" if e.get("resync") else str(e.get("src")) for e in not_heard) | |
| out.append(f" of those, {len(not_heard)} were not detections: " | |
| + ", ".join(f"{k}x{v}" for k, v in kinds.most_common()) | |
| + " (the precision figure below is computed from mic.note only, which neither writes)") | |
| if rejects: | |
| pairs = Counter((e.get("expectedName"), e.get("inputName")) for e in rejects) | |
| out.append(" most common rejections (expected -> played):") | |
| for (exp, got), n in pairs.most_common(6): | |
| out.append(f" {exp:<10} got {got:<10} x{n}") | |
| # stuck streaks: >=3 consecutive rejections at the same position | |
| streak, start_e = [], None | |
| stuck = [] | |
| for e in tk: | |
| if e.get("result") == "reject" and (not streak or streak[-1].get("posBefore") == e.get("posBefore")): | |
| streak.append(e) | |
| else: | |
| if len(streak) >= 3: | |
| stuck.append(streak) | |
| streak = [e] if e.get("result") == "reject" else [] | |
| if len(streak) >= 3: | |
| stuck.append(streak) | |
| if stuck: | |
| out.append(" STUCK spots (3+ rejections in a row at one position):") | |
| for s in stuck: | |
| out.append(f" t={s[0]['t'] / 1000:.2f}s..{s[-1]['t'] / 1000:.2f}s pos {s[0].get('posBefore')} expected " | |
| f"{s[0].get('expectedName')} played {[x.get('inputName') for x in s][:6]}") | |
| # ── detector -> tracker latency (mic) ── | |
| heard = by["mic.note"] | |
| if heard and tk: | |
| gaps = [] | |
| j = 0 | |
| for h in heard: | |
| while j < len(tk) and tk[j]["t"] < h["t"]: | |
| j += 1 | |
| if j < len(tk) and tk[j]["t"] - h["t"] <= 400: | |
| gaps.append(tk[j]["t"] - h["t"]) | |
| if gaps: | |
| out.append(f" mic heard -> tracker decision: median {statistics.median(gaps):.0f}ms, p95 {pct(gaps, .95):.0f}ms") | |
| # ── follower beliefs (frame-based engine) ── | |
| frames = by["follow.frame"] | |
| if frames: | |
| # Tracking criterion of spec §4.10: P(committed) + P(next) >= 0.5 while | |
| # TRACKING. P(next) alone is ~0 between commits (the mass sits on the | |
| # note that is sounding), so it says nothing about tracking quality. | |
| # `pcom` is logged since 20260915-ff3; older traces derive P(committed) | |
| # from `p` when the best hypothesis IS the committed state. | |
| def ptrack(e): | |
| pcur = e.get("pcur") | |
| if not isinstance(pcur, (int, float)): | |
| return None | |
| pcom = e.get("pcom") | |
| if not isinstance(pcom, (int, float)): | |
| pcom = e.get("p") if e.get("best") == (e.get("pos") or 0) - 1 and isinstance(e.get("p"), (int, float)) else 0 | |
| return pcom + pcur | |
| inf = [e for e in frames if e.get("inf")] | |
| ptr = [v for v in (ptrack(e) for e in frames) if v is not None] | |
| tracking = [e for e in inf if e.get("mode") == "TRACKING"] | |
| unsure = sum(1 for e in tracking if (ptrack(e) or 0) < 0.5) | |
| out.append("") | |
| out.append(f"FOLLOWER {len(frames)} frames logged, {len(inf)} informative; P(committed)+P(next) median {statistics.median(ptr):.2f}" | |
| + (f", below 0.5 on {unsure} of {len(tracking)} informative TRACKING frames ({100 * unsure / len(tracking):.0f}%)" | |
| if tracking else "")) | |
| # THE NOISE GATE, against the frames it threw away. `g` is the worklet's | |
| # own verdict (pitch-processor.js: rms < threshold), and a gated frame is | |
| # not merely ignored -- follower.js drops it from `informative` AND slams | |
| # its per-bin noise floor half-way to it; worse, the CLASSIC attack | |
| # detector shares the same threshold and returns before it can fire, so | |
| # `frame.attack` -- the follower's onset cue, and an advance needs fresh | |
| # onset evidence -- dries up with it. Attack frames in three consecutive | |
| # runs on one rig: 70 of 4629 at gate 3, 18 of 8019 at gate 11, 1 of 4399 | |
| # at gate 12. | |
| # | |
| # THE BAR IS THE ROOM, and it is NOT `fl`. `fl` is the analyser's level | |
| # floor, seeded from the first frame and rising 0.25 dB/s (salience.js | |
| # floorRiseDbPerSec), so an analyser that started before the mic | |
| # delivered audio seeds it on digital silence and never catches up: | |
| # 20260916-102711 opens at fl -174.9 and ends at -162.5, ~120 dB under | |
| # the room, which made "5 dB over the floor" mean "every frame" and the | |
| # printed denominator meaningless. So the room is the HIGHER of `fl` and | |
| # the 10th percentile of `db` (the same statistic app.js's auto-gate | |
| # reads off its ambient sample), which keeps `fl` in play on a session | |
| # where it is the better estimate and ignores it when it is a seed. | |
| # Over the reference traces the percentile wins every time, and the | |
| # resulting share separates cleanly: 0 %, 0 %, 0 %, 2 % on the sessions | |
| # that followed the music (gates 2/3/4/8) against 60 %, 67 %, 68 % on | |
| # the three where the gate ate it (gates 12, 15, 11) -- nothing in | |
| # between, so the 30 % bar is nowhere near either population. | |
| meta = tr.get("meta") or {} | |
| gated = [e for e in frames if e.get("g")] | |
| dbs = sorted(e["db"] for e in frames if isinstance(e.get("db"), (int, float))) | |
| if frames and dbs: | |
| room_db = dbs[int(0.10 * (len(dbs) - 1))] | |
| fls = sorted(e["fl"] for e in frames if isinstance(e.get("fl"), (int, float))) | |
| if fls: | |
| room_db = max(room_db, fls[len(fls) // 2]) | |
| bar = room_db + 3 | |
| loud = [e for e in frames if isinstance(e.get("db"), (int, float)) and e["db"] > bar] | |
| if loud: | |
| gl = sum(1 for e in loud if e.get("g")) | |
| out.append(f" noise gate {meta.get('noiseGate', '?')}: {len(gated)} of {len(frames)} frames " | |
| f"({100 * len(gated) / len(frames):.0f}%) called silence -- " | |
| f"including {gl} of the {len(loud)} frames standing >3 dB over the room " | |
| f"({room_db:.0f} dB, {100 * gl / len(loud):.0f}%)") | |
| if gl > 0.3 * len(loud): | |
| out.append(" THE GATE IS ON TOP OF THE PLAYING. Re-run Calculate Latency in the mic " | |
| "panel: the gate is now held under a representative played note, not over the room.") | |
| # What the in-app guard (app.js gateGuardCheck) did about it while the | |
| # user was still playing. Its absence from a session that trips the bar | |
| # above means the guard did not run -- an old build, or the classic | |
| # engine, which streams no frames. | |
| for e in by["gate.guard"]: | |
| to = e.get("to") | |
| out.append(f" gate guard @{e['t'] / 1000:.1f}s: {e.get('loudGated')} of {e.get('loud')} frames over the room " | |
| f"(room {e.get('roomDb')} dB, gate {e.get('gate')} = {e.get('gateDb')} dB) were muted -- " | |
| + (f"gate lowered to {to} in-session" if to else "gate already at the minimum")) | |
| states = by["follow.state"] | |
| if states: | |
| out.append(" mode changes: " + " ".join(f"{e['t'] / 1000:.1f}s {e.get('mode')}({e.get('reason')})" for e in states[:12]) | |
| + (" ..." if len(states) > 12 else "")) | |
| # The WRONG-dwell watchdog, on its own line: before follower | |
| # 2026-09-15.10 it wrote out.state and was overwritten by the BACKTRACK | |
| # signal and the mode change, so it is absent from older traces whether | |
| # or not it fired. | |
| recovers = by["follow.recover"] | |
| if recovers: | |
| out.append(f" WRONG-dwell recoveries: {len(recovers)} at " | |
| + " ".join(f"{e['t'] / 1000:.1f}s(pos {e.get('pos')}, pw {num(e.get('pw'))})" for e in recovers[:12]) | |
| + (" ..." if len(recovers) > 12 else "")) | |
| advs = [e for e in by["follow.advance"] if e.get("accepted")] | |
| rejected = sum(1 for e in by["follow.advance"] if not e.get("accepted")) | |
| if advs: | |
| lags = [e.get("lagMs") for e in advs if isinstance(e.get("lagMs"), (int, float))] | |
| ps = [e.get("p") for e in advs if isinstance(e.get("p"), (int, float))] | |
| bps = [e.get("bps") for e in advs if isinstance(e.get("bps"), (int, float))] | |
| reps = sum(1 for e in advs if e.get("repeatLike")) | |
| soft = sum(1 for e in advs if not e.get("onsetDriven")) | |
| out.append(f" advances: {len(advs)} accepted ({reps} repeats, {soft} without onset), {rejected} refused by the tracker; " | |
| f"posterior median {statistics.median(ps):.2f}" if ps else f" advances: {len(advs)} accepted, {rejected} refused") | |
| if lags: | |
| out.append(f" detection lag: median {statistics.median(lags):.0f}ms, p90 {pct(lags, .9):.0f}ms") | |
| if bps: | |
| out.append(f" tempo track: min {min(bps) * 60:.0f} median {statistics.median(bps) * 60:.0f} max {max(bps) * 60:.0f} bpm") | |
| # RESYNCS, ON THEIR OWN LINE AND NEVER FOLDED INTO `advances`. A resync is | |
| # the engine saying "the player is not one note ahead, they are ninety | |
| # notes ahead" and jumping the accompaniment there (Nakamura 2015 §III-B). | |
| # It must stay separately countable, because precision -- the figure that | |
| # says the accompaniment never plays notes nobody played -- is only | |
| # meaningful when it is computed from ordinary advances alone. | |
| resyncs = [e for e in by["follow.resync"] if e.get("accepted")] | |
| refused_resync = [e for e in by["follow.resync"] if not e.get("accepted")] | |
| if resyncs or refused_resync: | |
| if resyncs: | |
| jumps = [e.get("jump") for e in resyncs if isinstance(e.get("jump"), (int, float))] | |
| span = f", jump {min(jumps)}..{max(jumps)} events (median {statistics.median(jumps):.0f})" if jumps else "" | |
| out.append(f" RESYNCS: {len(resyncs)} accepted{span}") | |
| for e in resyncs[:8]: | |
| out.append(f" t={e['t'] / 1000:.1f}s #{e.get('fromIndex')} -> #{e.get('toIndex')} " | |
| f"(+{e.get('jump')}) {e.get('onsetsConfirmed')} onsets " | |
| f"margin {num(e.get('marginNats'), '.2f')} nats [{e.get('mode')}]") | |
| if len(resyncs) > 8: | |
| out.append(f" ... and {len(resyncs) - 8} more") | |
| if refused_resync: | |
| why = Counter(e.get("reason") for e in refused_resync) | |
| out.append(f" resyncs refused by the app: {len(refused_resync)} (" | |
| + ", ".join(f"{k}:{v}" for k, v in why.most_common()) + ")") | |
| scans = by["follow.resyncScan"] | |
| if scans: | |
| why = Counter((e.get("refused") or "fired") for e in scans) | |
| out.append(f" wide scans (armed): {len(scans)} -- " + ", ".join(f"{k}:{v}" for k, v in why.most_common())) | |
| deferred = by["skip.defer"] | |
| if deferred: | |
| # Split by reason: an accompaniment-behind stand-down is not the | |
| # wide-search one, and crediting it to the search hides the gate | |
| # that keeps the left hand whole. | |
| why = Counter(e.get("reason") for e in deferred) | |
| explain = { | |
| "resync-armed": "the one-event crawl resets the beam the wide search is accumulating on", | |
| "accomp-behind": "the note is not yet due on the accompaniment's clock", | |
| } | |
| out.append(f" auto-skips held back: {len(deferred)}") | |
| for k, v in why.most_common(): | |
| tail = explain.get(k) | |
| out.append(f" {k}: {v}" + (f" ({tail})" if tail else "")) | |
| holds = Counter(e.get("reason") for e in by["follow.hold"]) | |
| if holds: | |
| out.append(" holds by reason: " + ", ".join(f"{k}:{v}" for k, v in holds.most_common())) | |
| bleed = [e.get("lagMs") for e in by["follow.bleed"] if isinstance(e.get("lagMs"), (int, float))] | |
| lag_events = by["follow.bleedlag"] | |
| assumed = next((e for e in lag_events if e.get("phase") == "init"), None) | |
| if bleed: | |
| # Assumed vs measured: the engine fits the accompaniment's bleed as a | |
| # template component switched on at fireTime + bleedLagMs, so the gap | |
| # between these two numbers is how far the model was from the sound. | |
| line = (f" bleed lag (speaker -> mic, measured on accompaniment fires): median {statistics.median(bleed):.0f}ms " | |
| f"over {len(bleed)} samples, range {min(bleed):.0f}..{max(bleed):.0f}ms") | |
| if assumed: | |
| line += f"; session ASSUMED {assumed.get('assumedMs')}ms ({assumed.get('source')})" | |
| out.append(line) | |
| states = [e.get("stateMs") for e in by["follow.bleed"] if isinstance(e.get("stateMs"), (int, float))] | |
| if states: | |
| errs = [abs(st - s2) for st, s2 in zip(states, bleed)] | |
| shown = ' -> '.join(f'{v:.0f}' for v in states[:8]) + (' -> ...' if len(states) > 8 else '') | |
| out.append(f" engine estimate after each fire: {shown}ms over {len(states)} fires " | |
| f"(worst miss against the sample it was folding in: {max(errs):.0f}ms — that is how far " | |
| f"the modelled bleed sat from the sound while those frames were fitted)") | |
| elif assumed: | |
| out.append(f" bleed lag: assumed {assumed.get('assumedMs')}ms ({assumed.get('source')}), never measured " | |
| f"(no accompaniment fire produced a band rise)") | |
| final = next((e for e in lag_events if e.get("phase") == "final"), None) | |
| if final and final.get("persisted"): | |
| out.append(f" saved for the next session on this device pair: {final.get('measuredMedianMs')}ms " | |
| f"(engine finished at {final.get('engineMs')}ms)") | |
| elif final: | |
| out.append(f" NOT saved ({len(final.get('samples') or [])} samples, 3 needed) — " | |
| f"the next run on this device starts from the assumption again") | |
| out.append("") | |
| out += stall_lines(tr, by) | |
| # ── follower beliefs (old chroma follower; older traces only) ── | |
| on = by["mic.onset"] | |
| if on: | |
| confs = [e.get("confidence") for e in on if isinstance(e.get("confidence"), (int, float))] | |
| disagree = sum(1 for e in on if e.get("bestIndex") != e.get("currentIndex")) | |
| out.append("") | |
| out.append(f"FOLLOWER {len(on)} onsets, confidence median {statistics.median(confs):.2f} " | |
| f"(p10 {pct(confs, .1):.2f}), best!=current on {disagree} ({100 * disagree / len(on):.0f}%)") | |
| # ── tempo ── | |
| tp = by["tempo"] | |
| if tp: | |
| det = [e.get("detectedBpm") for e in tp if isinstance(e.get("detectedBpm"), int)] | |
| out.append("") | |
| out.append(f"TEMPO detected {det[0]} -> {det[-1]} bpm min {min(det)} max {max(det)} ({len(det)} samples)") | |
| jumps = [(tp[i]["t"], det[i - 1], det[i]) for i in range(1, len(det)) | |
| if det[i - 1] and abs(det[i] - det[i - 1]) / det[i - 1] > 0.25] | |
| if jumps: | |
| out.append(f" JUMPS >25% between consecutive notes: {len(jumps)}") | |
| for t, a, b in jumps[:8]: | |
| out.append(f" t={t / 1000:.2f}s {a} -> {b} bpm") | |
| # ── accompaniment timing ── | |
| fires = by["accomp.fire"] | |
| if fires: | |
| errs = [e.get("errMs") for e in fires if isinstance(e.get("errMs"), int)] | |
| out.append("") | |
| # Simulator traces (follower_sim.mjs --out) fire on the true timeline and | |
| # carry no errMs; only the count is meaningful there. | |
| if errs: | |
| out.append(f"ACCOMP {len(fires)} notes fired. timing error vs beat clock: median {statistics.median(errs):+.0f}ms, " | |
| f"p95 {pct([abs(x) for x in errs], .95):.0f}ms, worst late {max(errs):+d}ms, worst early {min(errs):+d}ms, " | |
| f"{sum(1 for x in errs if abs(x) > 80)} beyond +/-80ms") | |
| else: | |
| out.append(f"ACCOMP {len(fires)} notes fired.") | |
| # THE line to read for "is the left hand with me?" -- see | |
| # accompaniment_audible_offsets for why the clock-drift line under it cannot | |
| # answer that question. | |
| offsets = [ms for _, ms in accompaniment_audible_offsets(tr, by)] | |
| if offsets: | |
| med = statistics.median(offsets) | |
| verdict = "with you" if abs(med) <= 25 else ("EARLY" if med < 0 else "LATE") | |
| out.append(f" audible offset vs your own playing (- = accompaniment early): median {med:+.0f}ms {verdict}, " | |
| f"p10 {pct(offsets, .1):+.0f}ms, p90 {pct(offsets, .9):+.0f}ms, " | |
| f"|err| p90 {pct([abs(x) for x in offsets], .9):.0f}ms ({len(offsets)} of {len(fires)} notes measurable)") | |
| syncs = by["accomp.sync"] | |
| drifts = [e.get("driftMs") for e in syncs if isinstance(e.get("driftMs"), int)] | |
| if drifts: | |
| out.append(f" clock drift when your note arrived (+ = accompaniment ahead of you): median {statistics.median(drifts):+.0f}ms, " | |
| f"p90 |{pct([abs(x) for x in drifts], .9):.0f}|ms, max ahead {max(drifts):+d}ms, max behind {min(drifts):+d}ms") | |
| # Its zero is not 0: a correctly compensated clock reads ahead by | |
| # (detection lag + output latency) at the moment a note is confirmed. | |
| advs = [e.get("lagMs") for e in by["follow.advance"] if e.get("accepted") and isinstance(e.get("lagMs"), (int, float))] | |
| lat = (tr.get("meta") or {}).get("latency") or {} | |
| om = lat.get("measuredOutputMs") | |
| if advs and isinstance(om, (int, float)) and not isinstance(om, bool): | |
| out.append(f" (a clock that is exactly right reads +{statistics.median(advs) + om:.0f}ms here: " | |
| f"detection lag {statistics.median(advs):.0f} + output {om:.0f}. In leader mode it is clamped at the " | |
| f"next checkpoint, so most samples are the clamp -- use the line above it.)") | |
| # ── holds ── | |
| holds = [] | |
| open_hold = None | |
| for e in ev: | |
| if e.get("type") == "accomp.hold": | |
| open_hold = e | |
| elif e.get("type") in ("accomp.release", "accomp.sync") and open_hold is not None: | |
| holds.append((open_hold["t"], e["t"] - open_hold["t"], open_hold.get("allowedBeat"))) | |
| open_hold = None | |
| if holds: | |
| durs = [d for _, d, _ in holds] | |
| out.append(f" holds (waiting for you at a checkpoint): {len(holds)}, median {statistics.median(durs):.0f}ms, " | |
| f"longest {max(durs):.0f}ms at beat {max(holds, key=lambda h: h[1])[2]}") | |
| # ── "played by itself": accompaniment fires with no confirmed solo note for a while ── | |
| last_match_t = None | |
| runs, cur = [], None | |
| for e in ev: | |
| if e.get("type") == "tracker" and e.get("result") == "match": | |
| last_match_t = e["t"] | |
| if cur: | |
| runs.append(cur) | |
| cur = None | |
| elif e.get("type") == "accomp.fire": | |
| unattended = last_match_t is None or (e["t"] - last_match_t) > 2500 | |
| if unattended and not e.get("holding"): | |
| if cur is None: | |
| cur = {"start": e["t"], "end": e["t"], "n": 0, "beats": [e.get("beat"), e.get("beat")], "lead": e.get("lead")} | |
| cur["end"] = e["t"] | |
| cur["n"] += 1 | |
| cur["beats"][1] = e.get("beat") | |
| if cur: | |
| runs.append(cur) | |
| runs = [r for r in runs if r["n"] >= 2] | |
| if runs: | |
| out.append("") | |
| out.append(f"UNATTENDED RUNS accompaniment kept firing with no confirmed solo note for >2.5s: {len(runs)}") | |
| for r in runs[:10]: | |
| out.append(f" t={r['start'] / 1000:.2f}s..{r['end'] / 1000:.2f}s {r['n']} notes, beats {r['beats'][0]}..{r['beats'][1]}" | |
| f"{' (lead mode)' if r['lead'] else ''}") | |
| out.append(" (each is a place to check: was it supposed to play through, or did it run off on its own?)") | |
| out += accompaniment_lines(tr, by) | |
| # ── mic duplicates / unevaluated detections ── | |
| dups = sum(1 for e in by["input.midi"] if e.get("duplicate")) | |
| if dups: | |
| out.append("") | |
| out.append(f"MIDI {dups} notes dropped by the duplicate guard") | |
| return "\n".join(out) | |
| def metrics(tr, win=400): | |
| """Headline numbers for one session, for side-by-side comparison. `win` is | |
| the ground-truth window (ms) used to pair typed keys with follower advances.""" | |
| ev = tr.get("events") or [] | |
| by = defaultdict(list) | |
| for e in ev: | |
| by[e.get("type")].append(e) | |
| m = tr.get("meta") or {} | |
| tk = by["tracker"] | |
| matches = [e for e in tk if e.get("result") == "match"] | |
| rejects = [e for e in tk if e.get("result") == "reject"] | |
| is_mic = m.get("inputMode") == "mic" | |
| follower = is_mic and m.get("micEngine") == "follower" | |
| keys = len(by["input.key"]) | |
| midi_in = sum(1 for e in by["input.midi"] if not e.get("duplicate")) | |
| # Detections (what the input path produced) and typed keys (the loopback | |
| # rig's ground truth) are reported separately: summing them hid the ratio. | |
| detections = len(by["mic.note"]) + len(by["mic.chord"]) if is_mic else midi_in | |
| inputs = detections if is_mic else keys + midi_in | |
| # rescue-path signature: worklet emits the expected note with clarity == MIN_ACCEPTED_CLARITY | |
| rescues = [e for e in by["mic.note"] if e.get("matched") or abs((e.get("clarity") or 0) - 0.30) < 1e-6] | |
| # follower-only rows | |
| advs = [e for e in by["follow.advance"] if e.get("accepted")] | |
| adv_lat = [] | |
| if follower: | |
| for k in by["input.key"]: | |
| hit = next((a for a in advs if 0 <= a["t"] - k["t"] <= win), None) | |
| if hit: | |
| adv_lat.append(hit["t"] - k["t"]) | |
| hold_reasons = Counter(e.get("reason") for e in by["follow.hold"]) | |
| bleed = [e.get("lagMs") for e in by["follow.bleed"] if isinstance(e.get("lagMs"), (int, float))] | |
| commit_p = [e.get("p") for e in advs if isinstance(e.get("p"), (int, float))] | |
| # Under the follower the classic detector runs as a shadow; its drops are the | |
| # only "attacks dropped" that exist (mic.drop there means a held onset). | |
| classic_drops = by["mic.classic.drop"] if follower else by["mic.drop"] | |
| visual = by["mic.display"] | |
| gate_transitions = by["mic.gate"] | |
| gate_opens = sum(1 for e in gate_transitions if e.get("state") == "open") | |
| gate_closes = sum(1 for e in gate_transitions if e.get("state") == "closed") | |
| def matched_after(n): | |
| return any(0 <= t["t"] - n["t"] <= 120 and t.get("result") == "match" for t in tk) | |
| rescue_matches = sum(1 for n in rescues if matched_after(n)) | |
| near_miss = sum(1 for e in matches if e.get("inputName") != e.get("expectedName")) | |
| fires = [e.get("errMs") for e in by["accomp.fire"] if isinstance(e.get("errMs"), int)] | |
| drifts = [abs(e.get("driftMs")) for e in by["accomp.sync"] if isinstance(e.get("driftMs"), int)] | |
| audible = [ms for _, ms in accompaniment_audible_offsets(tr, by)] | |
| holds, open_hold = [], None | |
| for e in ev: | |
| if e.get("type") == "accomp.hold": | |
| open_hold = e | |
| elif e.get("type") in ("accomp.release", "accomp.sync") and open_hold is not None: | |
| holds.append(e["t"] - open_hold["t"]); open_hold = None | |
| last_match, runs, cur = None, 0, False | |
| for e in ev: | |
| if e.get("type") == "tracker" and e.get("result") == "match": | |
| last_match, cur = e["t"], False | |
| elif e.get("type") == "accomp.fire" and not e.get("holding"): | |
| if (last_match is None or e["t"] - last_match > 2500): | |
| if not cur: | |
| runs += 1; cur = True | |
| det = [e.get("detectedBpm") for e in by["tempo"] if isinstance(e.get("detectedBpm"), int)] | |
| solo = len(m.get("rh") or []) | |
| return { | |
| "input mode": m.get("inputMode"), | |
| "mic engine": (m.get("micEngine") or "classic") if is_mic else "-", | |
| "duration (s)": f"{(tr.get('durationMs') or 0) / 1000:.1f}", | |
| "solo notes in score": solo, | |
| "keys typed": keys if keys else "-", | |
| "detections": detections, | |
| "tracker matches": len(matches), | |
| "tracker rejections": len(rejects), | |
| "match rate": f"{100 * len(matches) / len(tk):.0f}%" if tk else "n/a", | |
| "inputs per match": f"{inputs / len(matches):.1f}" if matches else "n/a", | |
| "score progress": f"{100 * len(matches) / solo:.0f}%" if solo else "n/a", | |
| "matches via rescue path": rescue_matches if by["mic.note"] else "-", | |
| "matches via near-miss": near_miss, | |
| "genuine matches": len(matches) - rescue_matches - near_miss, | |
| "mic silence events": len(by["mic.silence"]) if m.get("inputMode") == "mic" else "-", | |
| "visible note/silence changes": (f"{len(visual)} ({sum(1 for e in visual if e.get('state') == 'note')} note, " | |
| f"{sum(1 for e in visual if e.get('state') == 'silence')} clear)" if visual else "-"), | |
| "frame gate crossings": (f"{len(gate_transitions)} ({gate_opens} open, {gate_closes} closed)" if gate_transitions else "-"), | |
| "detections by stage": (f"s1:{sum(1 for e in by['mic.note'] if e.get('stage') == 1)} s2:{sum(1 for e in by['mic.note'] if e.get('stage') == 2)}") if by["mic.note"] and any(e.get("stage") for e in by["mic.note"]) else "-", | |
| "attacks dropped (why)": (f"{len(classic_drops)} " + ",".join(f"{k}:{v}" for k, v in Counter(e.get('reason') for e in classic_drops).most_common(4))) if classic_drops else ("0" if is_mic and not follower else "-"), | |
| "detections <=250ms after accomp note": sum(1 for e in by["mic.note"] if any(0 <= e["t"] - f["t"] <= 250 for f in by["accomp.fire"])) if by["mic.note"] else "-", | |
| "advances (follower)": len(advs) if follower else "-", | |
| "holds by reason": (",".join(f"{k}:{v}" for k, v in hold_reasons.most_common(4)) or "0") if follower else "-", | |
| "advance latency median/p90": f"{statistics.median(adv_lat):.0f}/{pct(adv_lat, .9):.0f}" if adv_lat else "-", | |
| "posterior at commit median": f"{statistics.median(commit_p):.2f}" if commit_p else "-", | |
| "bleed lag median (follow.bleed)": f"{statistics.median(bleed):.0f}" if bleed else "-", | |
| "repeat commits": sum(1 for e in advs if e.get("repeatLike")) if follower else "-", | |
| "accomp notes fired": len(fires), | |
| "fire timing err p95 (ms)": f"{pct([abs(x) for x in fires], .95):.0f}" if fires else "n/a", | |
| "clock drift p90 (ms)": f"{pct(drifts, .9):.0f}" if drifts else "n/a", | |
| # The one the listener can hear. Negative = the accompaniment sounded | |
| # early; see accompaniment_audible_offsets. | |
| "audible offset median/|p90| (ms)": ( | |
| f"{statistics.median(audible):+.0f}/{pct([abs(x) for x in audible], .9):.0f}" if audible else "n/a"), | |
| "holds": len(holds), | |
| "hold median (ms)": f"{statistics.median(holds):.0f}" if holds else "n/a", | |
| "hold longest (ms)": f"{max(holds):.0f}" if holds else "n/a", | |
| "unattended runs": runs, | |
| "tempo range (bpm)": f"{min(det)}-{max(det)}" if det else "n/a", | |
| } | |
| def same_pitch(a, b): | |
| """Ground-truth match: same MIDI, or an octave off (the rig loses fundamentals).""" | |
| return a == b or abs((a or 0) - (b or 0)) == 12 | |
| def session_bank(tr): | |
| """(lo, hi, unheard_indices_set_or_None) for this session's analyser bank. | |
| The engine's own census (meta.follower.bankCensus, recorded from | |
| FOLLOWER_VERSION 2026-09-16.1) is the authority; it tests each event's actual | |
| template. `None` for the set means the engine did not say, and the caller | |
| falls back to the pitch test -- which is only right above the bank, where | |
| the cliff is hi + 1, and which cannot see judgeMaxMidi at all (from | |
| FOLLOWER_VERSION 2026-09-16.10 the fit is masked above that row, so an | |
| event can be unheard while its pitch sits inside the bank). One more | |
| reason the engine's own census wins whenever the trace carries it. | |
| """ | |
| m = tr.get("meta") or {} | |
| fo = m.get("follower") if isinstance(m.get("follower"), dict) else {} | |
| lo = fo.get("minMidi") if isinstance(fo.get("minMidi"), int) else BANK_MIN_MIDI | |
| hi = fo.get("maxMidi") if isinstance(fo.get("maxMidi"), int) else BANK_MAX_MIDI | |
| bc = fo.get("bankCensus") | |
| if isinstance(bc, dict) and isinstance(bc.get("unheard"), int): | |
| idx = [i for i in (bc.get("unheardIndices") or []) if isinstance(i, int)] | |
| # unheardIndices is capped at 64 by the engine; a truncated list is not a set. | |
| if len(idx) == bc["unheard"]: | |
| return lo, hi, set(idx) | |
| _, _, _, unhear = bank_census(m.get("rh") or [], lo, hi) | |
| return lo, hi, set(unhear) | |
| def key_score_indices(keys, score, lookahead=8): | |
| """Best-effort score index for each typed key, by walking the score forward. | |
| The ground-truth rig types the solo part in order, so a key is the first | |
| not-yet-consumed event whose LEAD pitch (the last of an event's pitches, as | |
| leadPitchFromEvent does it) is the key's. `lookahead` lets a few events be | |
| passed over -- a skipped or an extra press must not slide the whole rest of | |
| the score by one. `None` where no event matches. | |
| """ | |
| out, cursor = [], 0 | |
| for k in keys: | |
| midi = k.get("midi") | |
| idx = None | |
| for j in range(cursor, min(len(score), cursor + lookahead)): | |
| ps = event_pitches(score[j]) | |
| if ps and ps[-1] == midi: | |
| idx = j | |
| break | |
| out.append(idx) | |
| if idx is not None: | |
| cursor = idx + 1 | |
| return out | |
| def struggle_points(tr, min_presses=2, gap_ms=2500): | |
| """Repeated presses of the same key are an implicit "this isn't working". | |
| The player should not have to press F8: if they play a note, nothing | |
| happens, and they play it again, that IS the report. Every keypress is | |
| already in the trace as input.key, so this reads their frustration | |
| directly off the input stream and says what the engine was doing at the | |
| time. A run ends when the pitch changes or the player waits `gap_ms`. | |
| """ | |
| ev = tr.get("events") or [] | |
| keys = [e for e in ev if e.get("type") in ("input.key", "input.midi") and not e.get("duplicate")] | |
| if not keys: | |
| return None | |
| advances = [e for e in ev if e.get("type") in ("follow.advance", "tracker") and e.get("result", "match") == "match"] | |
| skips = [e for e in ev if e.get("type") == "skip"] | |
| # WHEN THE TRACKER MOVED. Two presses of the same pitch are only a re-try if | |
| # the first one did NOTHING; if the tracker advanced in between, the second | |
| # press is the next note of the score. Without this the heuristic fired on | |
| # every repeated note in the piece: on the good baseline | |
| # .accompy_traces/20260916-102711 (precision 100%, recall 93%, nothing wrong | |
| # with it at all) it reported "18 places you played the same note again" and | |
| # "18 of 42 keypresses (43%) were re-tries", because Twinkle's solo part is | |
| # meta.rh = [[60],[60],[67],[67],[69],[69], ...] -- 18 genuine repeated pairs, | |
| # struck 1.00 s apart at 60 bpm, well inside gap_ms = 2500. | |
| moved = sorted( | |
| e["t"] for e in ev | |
| if e.get("type") == "skip" | |
| or (e.get("type") == "follow.advance" and e.get("accepted")) | |
| or (e.get("type") == "tracker" and e.get("result", "match") == "match") | |
| ) | |
| def tracker_moved_between(t0, t1): | |
| i = bisect.bisect_right(moved, t0) | |
| return i < len(moved) and moved[i] < t1 | |
| runs, cur = [], [keys[0]] | |
| for k in keys[1:]: | |
| if (k.get("midi") == cur[-1].get("midi") and k["t"] - cur[-1]["t"] <= gap_ms | |
| and not tracker_moved_between(cur[-1]["t"], k["t"])): | |
| cur.append(k) | |
| else: | |
| runs.append(cur); cur = [k] | |
| runs.append(cur) | |
| runs = [r for r in runs if len(r) >= min_presses] | |
| if not runs: | |
| return None | |
| holds = [e for e in ev if e.get("type") == "follow.hold"] | |
| frames = [e for e in ev if e.get("type") == "follow.frame"] | |
| score = (tr.get("meta") or {}).get("rh") or [] | |
| out = ["", f"STRUGGLE POINTS ({len(runs)} places you played the same note again -- implicit F8)"] | |
| wasted = sum(len(r) - 1 for r in runs) | |
| out.append(f" {wasted} of {len(keys)} keypresses ({100 * wasted / len(keys):.0f}%) were re-tries") | |
| for r in sorted(runs, key=len, reverse=True)[:12]: | |
| t0, t1 = r[0]["t"], r[-1]["t"] | |
| name = r[0].get("name") or pn(r[0].get("midi")) | |
| # How did it end? | |
| adv = next((a for a in advances if t1 <= a["t"] <= t1 + 1500), None) | |
| skp = next((x for x in skips if t0 <= x["t"] <= t1 + 3000), None) | |
| if skp: | |
| ending = f"SKIPPED ({skp.get('reason')})" | |
| elif adv: | |
| ending = f"heard after {(adv['t'] - t0) / 1000:.1f}s" | |
| else: | |
| ending = "never registered" | |
| win_holds = [h for h in holds if t0 - 200 <= h["t"] <= t1 + 800] | |
| reasons = Counter(h.get("reason") for h in win_holds) | |
| win_fr = [f for f in frames if t0 - 200 <= f["t"] <= t1 + 800] | |
| pw = [f.get("pw") for f in win_fr if isinstance(f.get("pw"), (int, float))] | |
| pos = next((f.get("pos") for f in win_fr if f.get("pos") is not None), None) | |
| exp = "" | |
| if pos is not None and 0 <= pos < len(score): | |
| exp = " ".join(pn(x) for x in score[pos][0]) | |
| out.append(f" {t0 / 1000:6.2f}s {name:<5} x{len(r):<2} over {(t1 - t0) / 1000:4.1f}s -> {ending}") | |
| detail = [] | |
| if exp: | |
| detail.append(f"score wanted {exp} (#{pos})") | |
| if reasons: | |
| detail.append("holds " + ", ".join(f"{k}:{v}" for k, v in reasons.most_common(3))) | |
| if pw: | |
| detail.append(f"P(wrong) median {statistics.median(pw):.2f}") | |
| if detail: | |
| out.append(" " + "; ".join(detail)) | |
| return "\n".join(out) | |
| def ground_truth(tr, engine=None, win=400): | |
| """When the session has typed keys (loopback rig), score the mic input path | |
| against them: each key should yield exactly one detection of that pitch. | |
| `engine` picks which stream is scored. A follower session carries two: the | |
| follower's own commits (mic.note/mic.drop) and the classic detector's | |
| shadow output (mic.classic/mic.classic.drop), so `--engine classic` scores | |
| the shadow of the same audio. Old traces have neither field and score as | |
| before.""" | |
| ev = tr.get("events") or [] | |
| m = tr.get("meta") or {} | |
| keys = [e for e in ev if e.get("type") == "input.key"] | |
| if not keys or m.get("inputMode") != "mic": | |
| return None | |
| session_engine = m.get("micEngine") or "classic" | |
| eng = engine or session_engine | |
| shadow = eng == "classic" and session_engine == "follower" | |
| note_type, drop_type = ("mic.classic", "mic.classic.drop") if shadow else ("mic.note", "mic.drop") | |
| notes = [e for e in ev if e.get("type") == note_type] | |
| drops = [e for e in ev if e.get("type") == drop_type] | |
| # A follow.hold explains a follower miss; the classic shadow does not hold, | |
| # so holds are not attributed to it. | |
| holds = [] if shadow else [e for e in ev if e.get("type") == "follow.hold"] | |
| # Holds by the score index they name, as well as by time. A hold is NOT | |
| # always near the key it is about: the out-of-bank hold is queued by _spawn's | |
| # hazard branch at r >= 0.6 of the PREVIOUS event's IOI, so it is written | |
| # seconds before the note it names. Measured on a sim trace (Twinkle with | |
| # events 5/22/23/45 replaced by MIDI 100/100/103/101): event 5 is played at | |
| # t = 4973.9 ms and its `follow.hold reason=out-of-bank` is written at | |
| # t = 2168 ms -- 2.8 s early. Matching on time alone therefore attributed | |
| # none of them, blamed those four keys on the gate and on unrelated hold | |
| # reasons, and left the 2168 ms hold free to be charged to the in-bank key | |
| # at 2046.9 ms instead. | |
| holds_by_index = defaultdict(list) | |
| for h in holds: | |
| if isinstance(h.get("index"), int): | |
| holds_by_index[h["index"]].append(h) | |
| # Which score events this analyser bank structurally cannot represent, and | |
| # which key is which event. A key aimed at such an event was never going to | |
| # be detected by anything: counting it as "the gate never fired" is a lie | |
| # about the gate, and counting it in recall is a lie about the engine. | |
| lo, hi, unheard = session_bank(tr) | |
| score = m.get("rh") or [] | |
| key_idx = key_score_indices(keys, score) | |
| def out_of_bank(k, ix): | |
| if ix is not None and ix in unheard: | |
| return True | |
| midi = k.get("midi") | |
| return isinstance(midi, int) and midi > hi + 1 | |
| used = set() | |
| hit = wrong = missed_dropped = missed_silent = missed_held = missed_oob = 0 | |
| oob_logged = 0 | |
| drop_reasons = Counter() | |
| held_reasons = Counter() | |
| lat = [] | |
| for k, ix in zip(keys, key_idx): | |
| cands = [n for n in notes if 0 <= n["t"] - k["t"] <= win and id(n) not in used] | |
| if cands: | |
| # Prefer the first detection of the right pitch inside the window, | |
| # else the first at all: a late detection of key N must not be | |
| # consumed by key N+1 when N+1's own detection is also there. | |
| n = next((c for c in cands if same_pitch(c.get("midi"), k.get("midi"))), cands[0]) | |
| used.add(id(n)) | |
| if same_pitch(n.get("midi"), k.get("midi")): hit += 1; lat.append(n["t"] - k["t"]) | |
| else: wrong += 1 | |
| elif out_of_bank(k, ix): | |
| missed_oob += 1 | |
| if ix is not None and any(h.get("reason") == "out-of-bank" for h in holds_by_index.get(ix, ())): | |
| oob_logged += 1 | |
| else: | |
| d = [x for x in drops if 0 <= x["t"] - k["t"] <= win] | |
| # By index first (a hold can be logged well before its own note -- | |
| # see the out-of-bank measurement above), then by the time window as | |
| # before. The index match is still bounded, just generously: a hold | |
| # from the other end of the session is not this key's explanation. | |
| h = ([x for x in holds_by_index.get(ix, ()) if -HOLD_INDEX_LOOKBACK_MS <= x["t"] - k["t"] <= win] | |
| if ix is not None else []) | |
| h = h or [x for x in holds if 0 <= x["t"] - k["t"] <= win] | |
| if d: missed_dropped += 1; drop_reasons[d[0].get("reason")] += 1 | |
| elif h: missed_held += 1; held_reasons[h[0].get("reason")] += 1 | |
| else: missed_silent += 1 | |
| false_pos = sum(1 for n in notes if id(n) not in used and not n.get("calibrating")) | |
| total = len(keys) | |
| hearable = total - missed_oob | |
| # Only follower sessions (or an explicit --engine) get an engine label, so | |
| # older traces render exactly as before. | |
| label = "" | |
| if shadow: | |
| label = " engine: classic (shadow stream of a follower session)" | |
| elif engine or "micEngine" in m: | |
| label = f" engine: {eng}" + ("" if eng == session_engine else f" (session ran {session_engine})") | |
| lines = [] | |
| lines.append("") | |
| lines.append(f"MIC DETECTOR vs GROUND TRUTH (typed keys = what should have been heard) {total} keys{label}") | |
| lines.append(f" detected correctly {hit:>4} ({100 * hit / total:.0f}% recall)" | |
| + (f" latency median {statistics.median(lat):.0f}ms, p90 {pct(lat, .9):.0f}ms" if lat else "")) | |
| lines.append(f" detected WRONG pitch {wrong:>4}") | |
| lines.append(f" missed: attack dropped {missed_dropped:>4} " + ", ".join(f"{k}:{v}" for k, v in drop_reasons.most_common())) | |
| if holds or session_engine == "follower" and not shadow: | |
| lines.append(f" missed: held {missed_held:>4} " + ", ".join(f"{k}:{v}" for k, v in held_reasons.most_common())) | |
| lines.append(f" missed: no attack {missed_silent:>4} (gate/attack detector never fired)") | |
| if missed_oob: | |
| lines.append(f" missed: outside the bank {missed_oob:>2} -- no template can represent it " | |
| f"(MIDI {lo}..{hi}; {oob_logged} of them logged as follow.hold out-of-bank)") | |
| lines.append(f" FALSE detections {false_pos:>4} (a note with no key behind it -- these advance the tracker by themselves)") | |
| prec = hit / (hit + wrong + false_pos) if (hit + wrong + false_pos) else 0 | |
| # The window is only spelled out when it is not the default, so old reports read the same. | |
| lines.append(f" precision {100 * prec:.0f}% recall {100 * hit / total:.0f}% (keyboard = 100% / 100%)" | |
| + (f" window {win}ms" if win != 400 else "")) | |
| # Recall BOTH ways when some keys were unhearable: over every key (the line | |
| # above, which is what the engine owes the pianist) and over the keys it | |
| # could in principle have heard (which is what the engine's own behaviour can | |
| # be judged on). Neither one alone is the truth. | |
| if missed_oob and hearable > 0: | |
| lines.append(f" recall excluding the {missed_oob} unhearable: {100 * hit / hearable:.0f}% ({hit}/{hearable})") | |
| return "\n".join(lines) | |
| def print_scorecard(tr, base, win=400): | |
| a, b = metrics(tr, win), metrics(base, win) | |
| ma, mb = tr.get("meta") or {}, base.get("meta") or {} | |
| print() | |
| # A scorecard only means something when the two sessions ran under the same | |
| # settings. A setting missing on one side (e.g. a keyboard baseline has no | |
| # noise gate) is a different input mode, which the card shows already. | |
| def differs(key): | |
| return ma.get(key) is not None and mb.get(key) is not None and ma.get(key) != mb.get(key) | |
| if differs("latency"): | |
| print(f"WARNING: latency settings differ: this session {json.dumps(ma.get('latency'), sort_keys=True)} " | |
| f"vs baseline {json.dumps(mb.get('latency'), sort_keys=True)}") | |
| if differs("noiseGate"): | |
| print(f"WARNING: noise gate differs: this session {ma.get('noiseGate')} vs baseline {mb.get('noiseGate')}") | |
| if differs("micEngine"): | |
| print(f"WARNING: mic engine differs: this session {ma.get('micEngine')} vs baseline {mb.get('micEngine')}") | |
| print("SCORECARD this session baseline (ground truth)") | |
| print("-" * 78) | |
| for k in a: | |
| print(f" {k:<28} {str(a[k]):>14} {str(b.get(k, '')):>14}") | |
| print("-" * 78) | |
| def print_window(events, t_from, t_to, title, types=None, highlight_t=None): | |
| print() | |
| print(f"--- {title} [{t_from / 1000:.2f}s .. {t_to / 1000:.2f}s] ---") | |
| for e in events: | |
| if e["t"] < t_from or e["t"] > t_to: | |
| continue | |
| if types and e.get("type") not in types: | |
| continue | |
| line = fmt_event(e) | |
| mark = ">>>" if e.get("type") == "mark" else " " | |
| print(f"{mark}{secs(e['t'])} {line}") | |
| NOTE_NAMES = ["C", "C#", "D", "D#", "E", "F", "F#", "G", "G#", "A", "A#", "B"] | |
| def _pn(midi): | |
| return f"{NOTE_NAMES[midi % 12]}{midi // 12 - 1}" | |
| def listen_log(tr, t0=None, t1=None, around_misses=True): | |
| """THE LISTENING-vs-REGISTERING LOG, one line per analysed frame (~11 ms). | |
| The status line in the app reads `... peak D#4`, and `peak` is simply the | |
| loudest row the analyser saw. So "it says D# and does nothing" splits into two | |
| very different faults, and this table tells them apart: | |
| * peak is the note you played, but `p` stays low -> it HEARD you and | |
| refused to register. The hold reason says why. | |
| * peak is some other note entirely -> it never heard you; | |
| the problem is upstream of the engine. | |
| Columns: peak = what the UI displayed; want = the note the score expects | |
| next; p = posterior for that note (it commits near commitP); ev = evidence | |
| in nats; on = onset strength; dB = frame level; gate = whether the frame | |
| cleared the noise gate at all; hold = the refusal reason for that frame. | |
| """ | |
| events = tr.get("events") or [] | |
| frames = [e for e in events if e.get("type") == "follow.frame"] | |
| if not frames: | |
| return "" | |
| holds = {} | |
| for e in events: | |
| if e.get("type") == "follow.hold": | |
| holds.setdefault(round(e.get("t", 0)), e.get("reason")) | |
| notes = {round(e.get("t", 0)): (e.get("name") or "") for e in events if e.get("type") == "mic.note"} | |
| keys = {round(e.get("t", 0)): (e.get("name") or "") for e in events if e.get("type") == "input.key"} | |
| score = ((tr.get("meta") or {}).get("rh")) or [] | |
| windows = [] | |
| if t0 is not None: | |
| windows = [(t0 * 1000.0, t1 * 1000.0)] | |
| elif around_misses: | |
| # Frames around each note that was struck and NOT registered: the exact | |
| # moments the user is asking about. | |
| got = sorted(notes.keys()) | |
| for kt in sorted(keys.keys()): | |
| if not any(kt <= g <= kt + 700 for g in got): | |
| windows.append((kt - 150.0, kt + 900.0)) | |
| windows = windows[:6] | |
| if not windows: | |
| return "" | |
| out = ["", "LISTEN LOG (one line per frame; 'peak' is what the app showed next to Listening...)"] | |
| if t0 is None: | |
| out.append(" showing the first few notes you played that were NEVER registered") | |
| out.append(" time | peak | want | p | ev | on | dB | gate | hold") | |
| shown = 0 | |
| for (a0, a1) in windows: | |
| out.append(" " + "-" * 74) | |
| for e in frames: | |
| t = e.get("t", 0) | |
| if not (a0 <= t <= a1): | |
| continue | |
| pk = e.get("peak") | |
| pkname = _pn(pk) if isinstance(pk, int) else "-" | |
| pos = e.get("pos") | |
| want = "" | |
| if isinstance(pos, int) and 0 <= pos < len(score): | |
| ev0 = score[pos] | |
| ps = ev0[0] if isinstance(ev0[0], list) else [ev0[0]] | |
| want = "+".join(_pn(x) for x in ps if isinstance(x, int)) | |
| hold = holds.get(round(t), "") | |
| mark = "" | |
| if round(t) in keys: | |
| mark = f" <- you played {keys[round(t)]}" | |
| if round(t) in notes: | |
| mark = f" <== REGISTERED {notes[round(t)]}" | |
| out.append( | |
| f" {t/1000:8.2f} | {pkname:>5} | {want:<5} | {(e.get('p') or 0):4.2f} | " | |
| f"{(e.get('ev') if e.get('ev') is not None else 0):5.1f} | {(e.get('on') or 0):4.1f} | " | |
| f"{(e.get('db') if e.get('db') is not None else 0):5.1f} | " | |
| f"{'ok' if e.get('inf') else 'UNDER':>5} | {hold}{mark}") | |
| shown += 1 | |
| if shown > 4000: | |
| out.append(" ... truncated at 4000 frames; use --listen-log T0 T1 for a specific window") | |
| return "\n".join(out) | |
| return "\n".join(out) | |
| def heard_timeline(tr, bucket_ms=500, top=2): | |
| """What the DETECTOR was seeing, second by second, next to what it committed. | |
| The app shows a live 'Listening...' readout that wobbles between candidate | |
| pitches; the user asked to be able to check that against the recording | |
| afterwards. Everything needed is already in the trace -- `follow.frame` | |
| carries the 64-row salience (MIDI 33..96) per frame -- so this is rendered | |
| from existing recordings and needs no engine change. | |
| Read it as: the loudest pitch(es) the analyser actually saw in each window, | |
| then what (if anything) the engine was willing to commit there. A row with a | |
| strong pitch and no commit is the engine refusing evidence it did have. | |
| """ | |
| events = tr.get("events") or [] | |
| frames = [e for e in events if e.get("type") == "follow.frame" and e.get("sal")] | |
| if not frames: | |
| return "" | |
| notes = [e for e in events if e.get("type") == "mic.note"] | |
| keys = [e for e in events if e.get("type") == "input.key"] | |
| accs = [e for e in events if e.get("type") == "accomp.fire"] | |
| end = max(e.get("t", 0) for e in frames) | |
| out = ["", "WHAT THE DETECTOR HEARD (the live 'Listening...' readout, per " | |
| f"{bucket_ms} ms -- play the recording alongside this)", | |
| " time | loudest pitches the analyser saw | committed | you typed | accompaniment"] | |
| t = 0.0 | |
| while t <= end: | |
| win = [e for e in frames if t <= e.get("t", 0) < t + bucket_ms] | |
| if win: | |
| # Only the frames the engine itself judged INFORMATIVE. Whitened | |
| # salience saturates on room noise, so ranking every frame prints a | |
| # confident-looking chord over silence -- which is exactly the | |
| # misreading this table exists to prevent. | |
| live = [e for e in win if e.get("inf")] | |
| db = max((e.get("db") for e in win if e.get("db") is not None), default=None) | |
| lvl = f" [{db:.0f}dB]" if db is not None else "" | |
| if live: | |
| acc = [0.0] * 64 | |
| for e in live: | |
| sal = e.get("sal") or [] | |
| for i, v in enumerate(sal[:64]): | |
| if v and v > acc[i]: | |
| acc[i] = v | |
| ranked = sorted(range(64), key=lambda i: -acc[i])[:top] | |
| seen = " ".join(f"{_pn(33 + i)}:{acc[i]:.0f}" for i in ranked if acc[i] > 0) or "-" | |
| else: | |
| seen = "(under the gate -- room only)" | |
| else: | |
| seen, lvl = "-", "" | |
| got = " ".join(e.get("name") or "?" for e in notes if t <= e.get("t", 0) < t + bucket_ms) | |
| typed = " ".join(e.get("name") or "?" for e in keys if t <= e.get("t", 0) < t + bucket_ms) | |
| played = " ".join(str(e.get("names") or "") for e in accs if t <= e.get("t", 0) < t + bucket_ms) | |
| if seen != "-" or got or typed or played: | |
| out.append(f" {t/1000:7.1f}s | {seen + lvl:<34} | {got:<9} | {typed:<9} | {played}") | |
| t += bucket_ms | |
| if len(out) <= 3: | |
| return "" | |
| return "\n".join(out) | |
| def main(): | |
| ap = argparse.ArgumentParser(description=__doc__, formatter_class=argparse.RawDescriptionHelpFormatter) | |
| ap.add_argument("path", nargs="?", default=os.path.join(".accompy_traces", "latest.json")) | |
| ap.add_argument("--full", action="store_true", help="print the complete timeline") | |
| ap.add_argument("--around", type=float, default=4.0, help="seconds of context on each side of a marker") | |
| ap.add_argument("--listen-log", nargs=2, type=float, metavar=("T0","T1"), | |
| help="per-frame listening log for a time window (seconds); default: around missed notes") | |
| ap.add_argument("--window", nargs=2, type=float, metavar=("FROM", "TO"), help="print the timeline for a time range (s)") | |
| ap.add_argument("--types", help="comma-separated event types to include in timelines") | |
| ap.add_argument("--no-silence", action="store_true", help="hide mic.silence events in timelines") | |
| ap.add_argument("--baseline", help="a known-good trace (e.g. a keyboard session) to print a side-by-side scorecard against") | |
| ap.add_argument("--engine", choices=("classic", "follower"), | |
| help="which mic stream to score against the typed keys (default: the session's engine; " | |
| "'classic' on a follower session scores the classic detector's shadow output)") | |
| ap.add_argument("--gt-window", type=int, default=400, metavar="MS", | |
| help="ground-truth window: a detection counts for a key if it lands within MS after it (default 400)") | |
| ap.add_argument("--no-frames", action="store_true", help="hide follow.frame events in timelines") | |
| args = ap.parse_args() | |
| if not os.path.exists(args.path): | |
| sys.exit(f"No trace at {args.path}. Play a session, press End, then F9 to save one.") | |
| tr = load(args.path) | |
| events = tr.get("events") or [] | |
| types = set(args.types.split(",")) if args.types else None | |
| if args.no_silence: | |
| events = [e for e in events if e.get("type") != "mic.silence"] | |
| if args.no_frames: | |
| events = [e for e in events if e.get("type") != "follow.frame"] | |
| print_meta(tr) | |
| print(analyse(tr)) | |
| gt = ground_truth(tr, engine=args.engine, win=args.gt_window) | |
| if gt: | |
| print(gt) | |
| if args.baseline: | |
| if not os.path.exists(args.baseline): | |
| sys.exit(f"No baseline trace at {args.baseline}") | |
| print_scorecard(tr, load(args.baseline), win=args.gt_window) | |
| markers = tr.get("markers") or [] | |
| if markers: | |
| print() | |
| print(f"MARKERS ({len(markers)})") | |
| for m in markers: | |
| print(f" #{m.get('id')} t={m.get('t', 0) / 1000:.2f}s {m.get('note') or ''}") | |
| for m in markers: | |
| t = m.get("t", 0) | |
| print_window(events, t - args.around * 1000, t + args.around * 1000, | |
| f"MARKER #{m.get('id')} {m.get('note') or ''}".rstrip(), types) | |
| else: | |
| print() | |
| print("MARKERS none (press F8 to mark a moment; repeated keypresses are detected automatically below)") | |
| sp = struggle_points(tr) | |
| if sp: | |
| print(sp) | |
| hb = heard_timeline(tr) | |
| if hb: | |
| print(hb) | |
| ll = listen_log(tr, *(args.listen_log if args.listen_log else (None, None))) | |
| if ll: | |
| print(ll) | |
| if args.window: | |
| print_window(events, args.window[0] * 1000, args.window[1] * 1000, "WINDOW", types) | |
| if args.full: | |
| print_window(events, 0, float("inf"), "FULL TIMELINE", types) | |
| if __name__ == "__main__": | |
| main() | |