Skip to content

Commit 2cc69b0

Browse files
bewestCopilot
bewest
and
Copilot
committed
docs: impact analysis for AAPS profile sync (c-r-m PR #8475)
Documents the cross-project root cause analysis for AAPS users reporting that profile updates do not appear on Nightscout. Covers: - AAPS V1 has no nsUpdate path for profiles (only nsAdd) - c-r-m websocket dbAdd had no profile dedup branch (now fixed in PR #8475) - Demonstrated bug pre-fix and fix verification via regression tests - Secondary AAPS-side timing race in confirmLastProfileStore(now), with simulation in tools/aaps/profile_sync_race_simulation.js - c-r-m fix is sufficient for users; AAPS update is recommended defense-in-depth Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
1 parent 18a533d commit 2cc69b0

1 file changed

Lines changed: 305 additions & 0 deletions

File tree

‎docs/aaps-profile-sync-impact-analysis-2026-04-20.md‎

Lines changed: 305 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,305 @@
1+
# AAPS Profile Sync to Nightscout: Impact Analysis
2+
3+
**Date**: 2026-04-20
4+
**Audience**: cgm-remote-monitor maintainers, AndroidAPS maintainers
5+
**Reporter**: Nightscout ecosystem alignment workspace
6+
**c-r-m PR**: [nightscout/cgm-remote-monitor#8475](https://github.com/nightscout/cgm-remote-monitor/pull/8475)
7+
**Worktree**: `/home/bewest/src/worktrees/nightscout/cgm-pr-8447` (branch `wip/test-improvements`)
8+
**Fix commit (c-r-m)**: `85f7e6ac` — fix(websocket): dedup AAPS profile dbAdd by startDate; warn on insert errors
9+
**AAPS reference**: tag `3.4.2.2` (commit `5b1a2fec02`)
10+
11+
---
12+
13+
## TL;DR
14+
15+
AAPS users report that **editing a profile in AAPS does not appear to update the profile shown in Nightscout**, while a full initial profile sync works.
16+
17+
The root cause is a two-side mismatch:
18+
19+
1. **AAPS V1 NSClient never issues a profile UPDATE** — every change is sent as `dbAdd`. There is no `nsUpdate("profile", …)` path.
20+
2. **c-r-m's websocket `dbAdd` handler has no dedup branch for the `profile` collection** — it falls through to a generic `insertOne` and silently swallows any error.
21+
22+
Result: each AAPS profile edit creates a *new* MongoDB document. Which document the UI shows is then determined by `ctx.profile.last()` ordering, which is non-deterministic on `startDate` ties.
23+
24+
A secondary (narrower) issue exists in AAPS: `confirmLastProfileStore(now)` uses wallclock-now instead of the `lastChange` value that was just synced, which causes a lost-edit race when the user re-edits within the 60s socket ack window.
25+
26+
**The c-r-m fix in this report makes profile updates work for all AAPS users without an AAPS update.** The AAPS-side fix is a recommended defense-in-depth improvement that addresses the rapid-re-edit race.
27+
28+
---
29+
30+
## Symptom
31+
32+
| Action in AAPS | Expected on NS | Actual |
33+
|---|---|---|
34+
| Initial full profile push | Profile appears | ✅ Works |
35+
| Edit existing profile (e.g. change a CR) | Profile updates | ❌ Update not visible / inconsistent |
36+
| Re-edit same profile multiple times | Latest version visible | ❌ Older version may be displayed |
37+
38+
---
39+
40+
## Code Path Traced
41+
42+
### AAPS side (V1 NSClient)
43+
44+
`plugins/sync/src/main/kotlin/app/aaps/plugins/sync/nsclient/DataSyncSelectorV1.kt:786-805`
45+
46+
```kotlin
47+
private suspend fun processChangedProfileStore() {
48+
if (isPaused) return
49+
val lastSync = preferences.get(NsclientLongKey.ProfileStoreLastSyncedId)
50+
val lastChange = preferences.get(LongNonKey.LocalProfileLastChange)
51+
if (lastChange == 0L) return
52+
if (lastChange > lastSync) {
53+
if (activePlugin.activeProfileSource.profile?.allProfilesValid != true) return
54+
val profileStore = activePlugin.activeProfileSource.profile
55+
val profileJson = profileStore?.getData() ?: return
56+
if (JsonHelper.safeGetLongAllowNull(profileJson, "date") == null)
57+
profileJson.put("date", profileStore.getStartDate())
58+
val dataPair = DataSyncSelector.PairProfileStore(profileJson, dateUtil.now())
59+
activePlugin.activeNsClient?.nsAdd("profile", dataPair, "")
60+
synchronized(dataPair) { dataPair.waitMillis(60000) }
61+
val now = dateUtil.now()
62+
val cont = dataPair.confirmed
63+
if (cont) confirmLastProfileStore(now)
64+
}
65+
}
66+
```
67+
68+
Observations:
69+
70+
- `nsAdd` is the **only** sync method called for profiles — there is no `nsUpdate` branch anywhere in V1 (or V3 — see `DataSyncSelectorV3.kt:725`).
71+
- `PairProfileStore` is the only `Pair*` ack type that does not record an NS-assigned id. See `NSClientAddAckWorker.kt:164-168`:
72+
```kotlin
73+
is PairProfileStore -> {
74+
dataPair.confirmed = true
75+
}
76+
```
77+
Compare to every other Pair (treatments, food, devicestatus, etc.) which calls `storeDataForDb.addToNsId…` to track the server-assigned `_id`.
78+
- `confirmLastProfileStore(now)` uses `dateUtil.now()` after the ack instead of the `lastChange` value captured at send time.
79+
80+
### c-r-m side (websocket)
81+
82+
`lib/server/websocket.js:370-534` (pre-fix)
83+
84+
`processSingleDbAdd` has explicit dedup branches for `treatments` (lines 380-472) and `devicestatus` (lines 474-513), but **no branch for `profile`** — profile falls through to the generic `else`:
85+
86+
```js
87+
} else {
88+
try {
89+
var genericInsertResult = await mongoCollection.insertOne(data.data);
90+
var genericDoc = data.data;
91+
genericDoc._id = genericInsertResult.insertedId;
92+
ctx.bus.emit('data-update', { type: data.collection, op: 'update', changes: ... });
93+
ctx.bus.emit('data-received');
94+
return [genericDoc];
95+
} catch (err) {
96+
if (err != null && err.message) {
97+
console.log(data.collection + ' insertion error: ', err.message); // <-- silent
98+
return [];
99+
}
100+
throw err;
101+
}
102+
}
103+
```
104+
105+
Each AAPS profile edit therefore inserts a new document. If the source `JSONObject` retains an `_id` from a previously-imported profile, the resulting `E11000 duplicate key` error is logged at `console.log` level (often invisible in production) and the call returns `[]`.
106+
107+
`lib/server/profile.js:120` (pre-fix):
108+
109+
```js
110+
function last (fn) {
111+
return runWithCallback(function () {
112+
return api().find().sort({startDate: -1}).limit(1).toArray();
113+
}, fn);
114+
}
115+
```
116+
117+
When multiple profile documents share the same `startDate`, MongoDB's tiebreaker is undefined, so which profile the UI displays becomes effectively random.
118+
119+
---
120+
121+
## Demonstration
122+
123+
### Bug demonstration (pre-fix)
124+
125+
We added regression tests in `tests/websocket.shape-handling.test.js` and ran them against the pre-fix `lib/server/websocket.js` (via `git checkout HEAD~1 -- lib/server/websocket.js`):
126+
127+
```
128+
1) repeated AAPS profile dbAdd with same startDate REPLACES instead of duplicating:
129+
Uncaught AssertionError: expected '69e676370c32c9251e86ff9c' to be '69e676370c32c9251e86ff9b'
130+
```
131+
132+
Two `dbAdd` calls with identical `startDate` produced two distinct `_id` values, proving a duplicate document was created instead of an update.
133+
134+
### Fix verification (post-fix)
135+
136+
After the fix is applied, the same tests pass: the second `dbAdd` returns the same `_id` as the first, and the document content is updated in place. Full test suite: 878 passing, 1 pending, 3 pre-existing unrelated failures (security tests on `release/dev`).
137+
138+
### AAPS race demonstration
139+
140+
`tools/aaps/profile_sync_race_simulation.js` (this workspace) simulates `processChangedProfileStore` with the buggy `confirmLastProfileStore(now)` and the proposed `confirmLastProfileStore(lastChangeAtSend)`:
141+
142+
```
143+
=== BUGGY: confirmLastProfileStore(dateUtil.now()) ===
144+
edits made: [ 1000, 1500 ]
145+
edits sent: [ 1000 ]
146+
LOST edits: [ 1500 ]
147+
148+
=== FIXED: confirmLastProfileStore(lastChangeAtSend) ===
149+
edits made: [ 1000, 1500 ]
150+
edits sent: [ 1000, 1500 ]
151+
LOST edits: none
152+
```
153+
154+
Scenario: user edits at T=1000, sync poll at T=1100 sends the profile, user re-edits at T=1500 (during the 60s ack window), ack returns at T=2000. The buggy code sets `lastSync=2000`, so the T=1500 edit is permanently unsyncable until a future edit timestamp exceeds 2000.
155+
156+
---
157+
158+
## Fix #1 (c-r-m) — REQUIRED, lands the user-visible repair
159+
160+
**Worktree commit `85f7e6ac` on branch `wip/test-improvements`.**
161+
162+
### `lib/server/websocket.js` — add a `profile` dedup branch
163+
164+
Inserted between the `devicestatus` branch and the generic `else`:
165+
166+
```js
167+
} else if (data.collection === 'profile') {
168+
var profileQuery = null;
169+
if (data.data.NSCLIENT_ID) {
170+
profileQuery = { NSCLIENT_ID: data.data.NSCLIENT_ID };
171+
} else if (data.data.startDate) {
172+
profileQuery = { startDate: data.data.startDate };
173+
}
174+
175+
if (profileQuery) {
176+
try {
177+
var existingProfile = await mongoCollection.findOne(profileQuery);
178+
if (existingProfile) {
179+
console.log(LOG_DEDUP + 'Profile match on ' + Object.keys(profileQuery).join(',')
180+
+ '; replacing existing _id=' + existingProfile._id);
181+
var replacementDoc = Object.assign({}, data.data);
182+
replacementDoc._id = existingProfile._id;
183+
await mongoCollection.replaceOne({ _id: existingProfile._id }, replacementDoc);
184+
ctx.bus.emit('data-update', { type: 'profile', op: 'update',
185+
changes: ctx.ddata.processRawDataForRuntime([replacementDoc]) });
186+
ctx.bus.emit('data-received');
187+
return [replacementDoc];
188+
}
189+
} catch (err) {
190+
console.warn('profile dedup lookup error: ', err && err.message ? err.message : err);
191+
return [];
192+
}
193+
}
194+
195+
try {
196+
var profileInsertResult = await mongoCollection.insertOne(data.data);
197+
/* … emit + return … */
198+
} catch (err) {
199+
if (err != null && err.message) {
200+
console.warn('profile insertion error: ', err.message);
201+
return [];
202+
}
203+
throw err;
204+
}
205+
}
206+
```
207+
208+
Also upgraded the generic `else` `console.log` → `console.warn` so MongoDB write failures are visible in production logs.
209+
210+
### `lib/server/profile.js` — deterministic tie-breaker in `last()`
211+
212+
```js
213+
function last (fn) {
214+
return runWithCallback(function () {
215+
return api().find().sort({startDate: -1, _id: -1}).limit(1).toArray();
216+
}, fn);
217+
}
218+
```
219+
220+
This makes the choice between any pre-existing duplicate profiles deterministic (newest insert wins) without requiring a data migration.
221+
222+
### `tests/websocket.shape-handling.test.js` — regression coverage
223+
224+
Three new tests under `dbAdd profile collection (AAPS V1 sync)`:
225+
226+
1. First AAPS-shaped profile dbAdd inserts a new document.
227+
2. Repeated dbAdd with same `startDate` returns the **same** `_id` and replaces in place (proven to fail without the fix).
228+
3. dbAdd with a distinct `startDate` inserts and `ctx.profile.last()` returns the newest by content.
229+
230+
---
231+
232+
## Fix #2 (AndroidAPS) — RECOMMENDED, addresses rapid-re-edit race
233+
234+
`plugins/sync/src/main/kotlin/app/aaps/plugins/sync/nsclient/DataSyncSelectorV1.kt:786-805`
235+
236+
```diff
237+
private suspend fun processChangedProfileStore() {
238+
if (isPaused) return
239+
val lastSync = preferences.get(NsclientLongKey.ProfileStoreLastSyncedId)
240+
val lastChange = preferences.get(LongNonKey.LocalProfileLastChange)
241+
if (lastChange == 0L) return
242+
if (lastChange > lastSync) {
243+
if (activePlugin.activeProfileSource.profile?.allProfilesValid != true) return
244+
val profileStore = activePlugin.activeProfileSource.profile
245+
val profileJson = profileStore?.getData() ?: return
246+
if (JsonHelper.safeGetLongAllowNull(profileJson, "date") == null)
247+
profileJson.put("date", profileStore.getStartDate())
248+
- val dataPair = DataSyncSelector.PairProfileStore(profileJson, dateUtil.now())
249+
+ val syncedChange = lastChange
250+
+ val dataPair = DataSyncSelector.PairProfileStore(profileJson, syncedChange)
251+
activePlugin.activeNsClient?.nsAdd("profile", dataPair, "")
252+
synchronized(dataPair) { dataPair.waitMillis(60000) }
253+
- val now = dateUtil.now()
254+
val cont = dataPair.confirmed
255+
- if (cont) confirmLastProfileStore(now)
256+
+ if (cont) confirmLastProfileStore(syncedChange)
257+
}
258+
}
259+
```
260+
261+
**Why:** sets `ProfileStoreLastSyncedId` to the watermark that was actually synced. If the user re-edits during the 60s ack window, that newer `lastChange` exceeds `lastSync` and the next poll re-sends. With the current code, `lastSync` jumps past the unsynced `lastChange` and the edit is silently dropped.
262+
263+
The same pattern appears in V3 (`DataSyncSelectorV3.kt:712-728`) and should be considered there as well.
264+
265+
### Suggested test
266+
A `DataSyncSelectorV1Test` does not currently exist (only V3 has a test). The simulation in `tools/aaps/profile_sync_race_simulation.js` of the workspace can be ported to a JUnit test using mocked `dateUtil` and `preferences`.
267+
268+
---
269+
270+
## Why fix #1 (c-r-m) is sufficient for users
271+
272+
| Symptom | Fixed by c-r-m alone? |
273+
|---|---|
274+
| Profile edit creates duplicate document | ✅ Yes — dedup branch replaces in place |
275+
| User sees stale profile due to non-deterministic `last()` | ✅ Yes — secondary `_id` sort + dedup eliminates duplicates going forward |
276+
| Mongo errors on profile insert silently swallowed | ✅ Yes — `console.warn` |
277+
| Rapid re-edit within 60s loses an edit | ❌ No — requires AAPS-side fix |
278+
279+
**No AAPS update is required for users to see the primary symptom resolved.** As soon as their Nightscout server runs the patched c-r-m, AAPS profile edits will update the existing profile document instead of creating duplicates.
280+
281+
---
282+
283+
## Recommended PRs
284+
285+
1. **c-r-m PR** — base `release/dev` ← branch `wip/test-improvements`
286+
- Either the full branch (which also restores the `/test` endpoint env support and includes the cgm-pr-8447 fixes) or just `85f7e6ac` cherry-picked.
287+
- Title suggestion: `fix(websocket): dedup AAPS profile dbAdd by startDate; warn on insert errors`
288+
2. **AndroidAPS PR** — change `confirmLastProfileStore(now)` → `confirmLastProfileStore(syncedChange)` in V1, mirror in V3 if appropriate, add `DataSyncSelectorV1Test` covering the rapid-re-edit race.
289+
290+
---
291+
292+
## Open questions worth flagging upstream
293+
294+
- **Should `PairProfileStore` track `nightscoutId`?** Every other `Pair*` does. Tracking would let AAPS use stable `_id` references and allow the c-r-m server to do `_id`-based dedup rather than `startDate`-based. It would also unblock a future `nsUpdate` path for profiles.
295+
- **The `createdAt % 1000 == 0L` heuristic in `NsIncomingDataProcessor.processProfile:283-295`** ("whole second means edited in NS") is fragile — any AAPS-originated profile whose epoch happens to land on a whole second will be re-imported as if NS-edited. Worth replacing with explicit provenance.
296+
- **V3 path** uses REST POST and `lib/server/profile.js:save()` (which now does `replaceOne` upsert by `_id`), but `createProfileStore` does not include `_id`, so V3 may exhibit the same insert-on-edit behavior via REST. Worth verifying separately.
297+
298+
---
299+
300+
## References
301+
302+
- c-r-m fix: commit `85f7e6ac` on `wip/test-improvements`
303+
- c-r-m files: `lib/server/websocket.js`, `lib/server/profile.js`, `tests/websocket.shape-handling.test.js`
304+
- AAPS files: `plugins/sync/src/main/kotlin/app/aaps/plugins/sync/nsclient/DataSyncSelectorV1.kt`, `…/workers/NSClientAddAckWorker.kt`, `…/nsShared/NsIncomingDataProcessor.kt`, `plugins/main/src/main/kotlin/app/aaps/plugins/main/profile/ProfilePlugin.kt`
305+
- Workspace simulation: `tools/aaps/profile_sync_race_simulation.js`

0 commit comments

Comments
 (0)