Fix loop runs lost when calculation chain is replaced (#5066) - #5087
Fix loop runs lost when calculation chain is replaced (#5066)#5087zibra wants to merge 10 commits into
Conversation
The loop was invoked only when the finished calculation chain was started by a new BG. A chain started by a new BG can be cancelled and replaced by a chain started by another DB change before it reaches PostCalculationWorker. The replacement chain had triggeredByNewBG=false, so the loop run for that BG was lost. With 1-minute CGM data (Libre 3) this could repeat for hours and no loop run happened at all. Now the loop is invoked after any completed MAIN calculation when the newest BG was not used for a loop run yet. The existing timestamp check against Loop.lastBgTriggeredRun still prevents duplicate runs. Issue nightscout#5066, nightscout#3372 Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Three failure points could stop BG processing forever while the rest of the app kept working (SMS, pump queue, notifications): - An exception inside the debounced newHistoryData task was swallowed by the ScheduledExecutorService. scheduledData was never cleared, so no calculation was ever scheduled again. Now the task logs the error and always clears the state in a finally block. - historyWorker was created after the DB observers were registered. A DB change arriving in that window set scheduledData while nothing was scheduled, with the same permanent result. Now the executor is created first. - The flow collectors (GV, CA, BS, BCR, TB, EB, EPS, preferences, units) had no error handling. One exception cancelled the collection forever. The GV collector is the only entry point for BG-triggered loop runs. Now a shared onEachSafe wrapper logs the error and keeps collecting. Issue nightscout#5066, nightscout#3372 Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
Safety net for any remaining case where the calculation chain dies while BG values keep coming. Every KeepAlive tick (about 5 minutes) checks: when the newest BG is fresh (under 9 minutes old) but is more than 10 minutes newer than the last BG that triggered a loop run, force a full recalculation. The new IobCobCalculator.forceRecalculation() starts the calculation directly and bypasses the debounce path, so it also works when that path is stuck. The forced calculation ends with a loop run because the newest BG was not used for a loop run yet. Fires a LoopWatchdogFired analytics event so remaining cases stay visible. Issue nightscout#5066, nightscout#3372 Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
|
Thanks @zibra for providing those fixes. I wonder whether almost no one realizes the severity of this problem, or why is this not included into dev with high priority? @MilosKozak |
|
I hit the same user-visible symptom as #5066 on a fork tracking (Disclosure per CONTRIBUTING.md: the log correlation and code tracing below were done with AI assistance. I am deliberately not proposing a patch — everything below is verifiable from the repo and the log.) What my log shows77-minute window, BG arriving every ~60 s, 78
Zero Why the calculation never landsPer-bucket cost on this device is ~25 s: Dominated by The part that surprised me, and that affects change 3I had assumed the runs were being cancelled and discarding their work. They mostly are not — only 5 of ~78 cycles took the What they publish, though, is a clone taken ~50 s earlier — and Same shape at 11:01:14 (+26 ms) and 11:01:24 (+2.3 s). This is why I think change 3 cannot recover my case. // No stopCalculation and no cache invalidation needed: history did not change,
// and the REPLACE policy inside runCalculation cancels a running chain anyway.That holds for WorkManager's bookkeeping but not for the coroutine: the in-flight worker is not actually stopped at that instant, and it will publish its stale clone over whatever the forced chain sets up. The watchdog's precondition is also exactly satisfied in this state — One more thing that looks independently wrong
override fun clone(): AutosensDataStore =
AutosensDataStoreObject().also {
synchronized(dataLock) {
it.bgReadings = this.bgReadings.toMutableList()
it.autosensDataTable = LongSparseArray<AutosensData>(...).apply { putAll(...) }
it.bucketedData = this.bucketedData?.toMutableList()
}
}Since Why this reads as one root cause rather than four bugsEvery one of these is the same structural thing: the pipeline uses cancel-and-replace as its only concurrency primitive, and every piece of state it needs lives inside the run that gets replaced. What gets dropped at that boundary differs:
It stays latent while a full pass is short relative to the input interval. 1-minute CGM breaks that assumption from both sides at once — 5× more restarts, and (via Happy to test any candidate on the same setup and report back, or to attach the full logs if useful. Details and file/line references are in #5101, which I will correct to match these measurements (my original framing there over-weighted the cancellation path). |
A cancelled calculation worker keeps running until its next isStopped check, up to one full bucket (tens of seconds on slow devices with a lot of data). stopCalculation() returns as soon as WorkManager marks the work CANCELLED, so the caller invalidates the store and starts a new chain while the old worker is still alive. The old worker then published its stale clone over the new state (lost update). Re-check the chain generation right before the publish and skip it when the worker was replaced. Also correct the comment on forceRecalculation() which claimed the running chain is cancelled immediately. Based on log analysis by JetFoxy in PR nightscout#5087 / issue nightscout#5101. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_014wDqc1Bv4AWZ7hcCrQEBx6
clone() did not copy referenceTime, and the calculation publishes the clone back as the live store. The live store then lost its bucket grid anchor after every calculation. On the next load the grid was re-anchored to the newest BG. With a 1-minute CGM source the anchor moved with every reading, so all bucket timestamps shifted and every cached autosensDataTable entry became unreachable. The calculation then recomputed the same wall-clock buckets forever and never reached 'now' (issue nightscout#5066, nightscout#5101). Found by JetFoxy in PR nightscout#5087 review. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_014wDqc1Bv4AWZ7hcCrQEBx6
|
@JetFoxy thank you very much for the detailed log analysis and code tracing — this is exactly the kind of input that moves a fix like this forward. I checked all four points against the code and they are correct. I pushed three new commits based on them: 1. Stale publish guard (9f2e635) — 2. 3. Watchdog rate limit (15d981b) — the KeepAlive loop watchdog now fires at most once per 15 minutes, so it cannot add a new cancel-and-replace participant every 5 minutes while a slow forced recalculation is still running. Out of scope for this PR, left for #5101: the O(buckets × table) cost of I will be testing now this version with real devices. |
When the calculation never completes (for example the state fixed in the previous commits), the watchdog precondition stays true on every KeepAlive tick. Firing every 5 minutes would only add more cancel-and-replace churn while a slow forced recalculation is still running. Fire at most once per 15 minutes. Suggested by JetFoxy in PR nightscout#5087 review. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_014wDqc1Bv4AWZ7hcCrQEBx6
|
…e-alarm' into fix/loop-trigger-lost-5066
|
Thanks for turning that around so fast — I read all three commits and they match what I measured. Two follow-ups, one of which I think matters before this is considered done. The publish guard trades one all-or-nothing behaviour for another
In the steady state that is harmless — with So for that scenario the guard neither fixes nor worsens the outcome, it just changes the mechanism. What would actually break the deadlock is making progress survive supersession — e.g. merging the computed buckets into the live store instead of replacing it wholesale. The buckets a catch-up pass computes are hours in the past; the invalidation that superseded it only removed entries newer than The new The unbounded
|
…5066 Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_012uQfwAT4RUr4Y27MBRDJ6K # Conflicts: # core/keys/src/androidMain/res/values/strings.xml # core/keys/src/main/kotlin/app/aaps/core/keys/BooleanKey.kt # implementation/src/androidHostTest/kotlin/app/aaps/implementation/queue/CommandQueueImplementationTest.kt # implementation/src/androidMain/kotlin/app/aaps/implementation/receivers/KeepAliveWorker.kt # implementation/src/commonMain/kotlin/app/aaps/implementation/queue/CommandQueueImplementation.kt # plugins/main/src/commonMain/kotlin/app/aaps/plugins/main/iob/iobCobCalculator/IobCobCalculatorPlugin.kt # plugins/main/src/commonMain/kotlin/app/aaps/plugins/main/iob/iobCobCalculator/data/AutosensDataStoreObject.kt # workflow/src/androidHostTest/kotlin/app/aaps/workflow/PostCalculationRunnerTest.kt # workflow/src/commonMain/kotlin/app/aaps/workflow/PostCalculationRunner.kt # workflow/src/commonMain/kotlin/app/aaps/workflow/PrepareGraphDataRunner.kt # workflow/src/main/kotlin/app/aaps/workflow/CalculationWorkflowImpl.kt
|
I pushed 17dd2bb to The commit takes four of the six changes and leaves the watchdog out. Below is what is different and why, so you can see where I disagreed instead of having to diff it. Taken as proposed
Taken with changes1. Once the anchor lives for the whole process, a new sensor can start on a different 5 minute phase. 2. That event only asks its listeners to refresh, and the graph data in 3. The debounce body needs three more things next to the
One more thing, which this PR cannot fix from inside the
|
|
Thanks for the detailed writeup of where you disagreed — that was much more useful than a diff would have been, and the two extra I have moved the two remaining items into #5101 and re-scoped it to just those, with the original root-cause writeup folded into a details block for context. While writing it up I traced the NS id write-back myself to make sure I was describing it correctly, and it is exactly as you said:
On the uncapped On testingOne honest limitation: I cannot run stock What I am doing instead is running your four changes ported onto the branch that produced the original log, on that same setup (1-minute Libre via Juggluco, Nightscout connected). The port is semantic rather than a cherry-pick, since that branch predates the multiplatform move and still has the workers and the single thread executor debounce — which also means the
That last one is the behaviour change I would most like to see confirmed on real data rather than reasoned about, given it is a fivefold drop in loop runs for exactly the users who reported the problem. If a detection-only watchdog in |
|
One consequence of the loop-rate change that I think needs a decision before this reaches users, because it collides with a preference default. The 5 minute floor also becomes an SMB floor
override fun actualBg(): InMemoryGlucoseValue? {
val lastBg = lastBg() ?: return null // lastBg() -> bucketedData[0]
return if (lastBg.timestamp > System.currentTimeMillis() - T.mins(9).msecs()) lastBg else null
}With the anchor now stable,
ApsMaxSmbFrequency(
key = "smbinterval",
defaultValue = 3,
min = 1,
max = 10,and the gate itself has only a 6 second tolerance, which assumes another attempt comes along soon: val SMBInterval = min(10, max(1, profile.SMBInterval)) * 60.0
if (lastBolusAge > SMBInterval - 6.0) { ... } else { "Waiting ...s to microbolus again." }So on a 1 minute source every value from 1 to 4 is now unreachable and silently behaves as 5. For the default that is SMB roughly every 5 minutes where it used to be every 3. Before/after for a 1 minute sourceThe comparison is against a healthy pre-fix install, not against the stuck state:
That is about 40% fewer SMB opportunities for anyone on a 1 minute source who left the default, in the same release that fixes their loop gaps. Running the loop more often than once per 5 minutes is a fairly common setup among these users, so this is not a corner case. 5 minute sources are unaffected: their readings advance the grid once per reading either way. A second, weaker pointEven at This one is probably fine as it stands: Unrelated, but it came out of the same checkThe minute-spaced That means Options, as I see them
I do not have a recommendation I am confident in; the trade-off is clinical rather than technical. Happy to measure the actual SMB cadence on the 1 minute setup once I have the ported build running, which would at least turn "about 40% fewer" into a real number. |



Problem
Fixes #5066, related to #3372.
The loop can stop running for minutes to hours while BG values keep coming every minute. The app itself stays alive: SMS commands, pump communication and notifications still work. Bringing the app to the foreground or restarting it helps.
Log analysis in #5066 (thanks @kameamea) shows the mechanism: with 1-minute CGM data (Libre 3 via Juggluco) the calculation chain is cancelled again and again by
stopCalculation(... onEventNewHistoryData)before it reaches the worker that invokes the loop. In one 32-minute window: 32 new BG values, 67stopCalculationcalls, 66PrepareBasalDataWorker ... FAILURE {Error : stopped}, 0 loop runs.Root cause
The loop was invoked only when the finished calculation chain was started by a new BG (
triggeredByNewBG=true). When a BG-triggered chain is cancelled and replaced by a chain started by another DB change (treatment, temp basal, profile switch from NS sync), the replacement chain carriestriggeredByNewBG=false. The loop run for that BG is then lost.Loop.lastBgTriggeredRunis never updated, so nothing recovers it. With 5-minute CGM data this race is rare; with 1-minute data it can win for hours.Three more silent failure points were found with the same symptom profile (loop dead, everything else alive, restart fixes it). Each one could stop all future calculations for the rest of the process lifetime.
Changes
1. Do not lose the loop trigger when a chain is replaced (
workflow)PostCalculationWorkernow invokes the loop after any completed MAIN calculation when the newest BG was not used for a loop run yet. The existing timestamp check againstLoop.lastBgTriggeredRunstill prevents duplicate runs. ThetriggeredByNewBGfield was removed fromPostCalculationDatabecause it is no longer needed there.2. Fix silent failures in
IobCobCalculatorPlugin(plugins:main)newHistoryDatatask was swallowed by the executor andscheduledDatawas never cleared, so no calculation was ever scheduled again. The task now logs the error and always clears the state in afinallyblock.historyWorkerwas created after the DB observers were registered. A DB change arriving in that window caused the same permanent stop. The executor is now created first.onEachSafewrapper now logs the error and keeps collecting.3. Loop watchdog in
KeepAliveWorker(core:interfaces,implementation)Safety net for any remaining case. Every KeepAlive tick (about 5 minutes): when the newest BG is fresh (under 9 minutes old) but more than 10 minutes newer than the last BG that triggered a loop run, force a full recalculation through the new
IobCobCalculator.forceRecalculation(). It starts the calculation directly and bypasses the debounce path, so it also works when that path is stuck. ALoopWatchdogFiredanalytics event keeps remaining cases visible.Tests
PostCalculationWorkerTest: 2 new cases (skip loop when newest BG already used, skip when no actual BG).KeepAliveWorkerTest: 5 new watchdog cases (fires on lost trigger, skips on small gap, stale BG, app start, client mode).:app:compileFullDebugKotlinand both test classes pass.Runtime behavior is being verified on a device with 1-minute Libre 3 data where the problem reproduced.
🤖 Generated with Claude Code