Artificial-Pancreas / iAPS

MIT License
176 stars 720 forks source link

[Bug] Dexcom BG readings fail to upload to Nightscout due to non-unique _id field #280

Closed LiroyvH closed 11 months ago

LiroyvH commented 1 year ago

My environment: Dexcom G6 (Anubis), iPhone 13 Mini with iOS 17.1, iAPS-dev, Nightscout self-hosted on private server.

- Problem: I, seemingly out of the blue, started encountering issues with iAPS no longer being able to send glucose values ("entries") to Nightscout. Treatments and manual BG entries work fine, openAPS info works fine, but sending glucose values results, according to iAPS's logfiles, in a 500 Internal Server Error. Other apps, such as xDrip4iOS, would have no problem at all uploading glucose values; so a problem with Nightscout itself appeared to be ruled out. Several users reported this issue with iAPS, though only a very small fraction.

- Digging & Potential solution: Upon further inspection (a packet capture (tcpdump) + analyzing it), it turns out the 500 error by Nightscout included a note containing the exact error triggering the Error 500. It appears that MongoDB threw an error "11000", which means: "Trying to write a value/index that is not unique". The only field in the "entries" collection that must be unique is the _id field, meaning somehow the exact same _id already existed in the database and thus Mongo rejected to insert our entry.

iAPS generates the ID for Dexcom G6 as follows: https://github.com/Artificial-Pancreas/iAPS/blob/a0daab8e9118baecc2ad2173be495d1c2aa6b033/FreeAPS/Sources/APS/CGM/DexcomSourceG6.swift#L156 which results in <Dexcom TransmitterID> + <a 6-digit number> being set for the _id, eg: "8ABCDE 123456". Apparently this 6-digit number isn't always unique, at least not in some scenarios (see below), to the TransmitterID. What I did was replace that line (156) to read: _id: UUID().uuidString, instead to ensure it's random and unique.

- (partial) Victory: Nightscout uploads of BG entries are now working again! The _id value appears to be unique again and Mongo accepts them. However, something still isn't right as I still see "internal server error" scrolling by in the logs, but Nightscout is being updated. (And no, I killed any other app talking to Nightscout and I confirmed the values come from iAPS. :P) So what I did isn't the final solution, it just fixed it at one location. (I did notice in my packet traces (tcpdump) that iAPS sent the values twice. I thought it was just trying again because it got an error back, but maybe it always does it and 1 out of the 2 is now succeeding due to my code changes whilst the other still fails. I haven't got the time to debug that now; but can re-analyse traffic later if needs be. Not sure why it would send the "entries" value twice if it's not in error condition.)

- Potential causes & conditions to trigger it: During troubleshooting this issue and sending a flood of my thoughts on Discord to brainstorm, @bjornoleh asked whether or not the DexcomG6 might have a 6-digit number with each reading. I'm not sure if it does - but it did point me to the DexcomSourceG6.swift file, where I found the ID being set in a different way than in BloodGlucose.swift.

If the Dexcom, or something related to it, indeed generates 6-digit unique ID's, then this will lead to non-unique ID's in the following situations: 1.) Anubis users whom reset their Anubis may get the same ID's being used again. Their Transmitter ID will also not be unique, so the _id field subsequently isn't unique and Nightscout starts rejecting entries. (Or well, Mongo is.) The same goes for users whom are still using G5's or very old pre-Firefly G6 transmitters that have reset capability. 2.) Dexcom has recently started to recycle Transmitter ID's, so it could happen that other non-Anubis users eventually run in to this as well.

Whatever the cause, the _id field is for some reason not unique whilst it should be, but changing the code the way I did solved the main problem and consistently and continuously made Nightscout integration work completely again instead of only treatments. I, however, don't know if this is the best or permanent solution - especially not as I still see "Internal Server Error" in the logs whilst entries are being uploaded. Hence opening an issue for tracking rather than submitting this code as "the fix". (Note: G5, G6, G7 and by the looks of it something in HealthKit may all be using non-unique _id's under certain conditions as they share the same code.).

LiroyvH commented 1 year ago

Update: I ran another tcpdump and analyzed the traffic to see why, despite successful uploads to Nightscout, I'm still seeing Internal Server Errors (500) in the logs.

It turns out that iAPS is attempting to backfill all the old readings, including the ones with a non-unique _id, to Nightscout; which thus fails with an Internal Server Error for obvious reasons. By the looks of it, iAPS is then treating the upload as having failed completely, including the values that actually made it to Nightscout just fine, rather than only partially. By the looks of it, it is now also trying to re-upload readings that were actually accepted by Nightscout. (Which of course are then rejected on the next attempt because they already exist because they've already been inserted successfully. :X)

So in order to get a fully working solution here, we must likely: 1.) Implement the code changes described above for G5, G6, G7 and any other place generating potentially non-unique ID's 2.) Don't upload old-style ID's to Nightscout OR Expunge, one-time, all pending uploads to Nightscout from before these code changes, so on first run of a new version containing these changes. (Or simply expunge them when encountering a 500. I dunno what the best solution is, but it must be done - iAPS must stop trying to send the non-unique readings to Nightscout.) By the looks of it, it seems to be storing them in "glucose.json". Or at least, the values there seem quite similar to what it's attempting to upload. (It has 284 entries vs +/- 200 I saw it attempted to upload.)

I could PR 1 if you wish, but I cannot PR 2 as I have no idea how to achieve that on first run of new version.

That should sort it once and for all for everyone. :)

LiroyvH commented 1 year ago

PR to make the _id field unique is here: https://github.com/Artificial-Pancreas/iAPS/pull/285 The fix for the issue where, if someone has already ran in to this issue, the problem keeps occurring due to a logic flaw in the Nightscout handling is not included in that PR and still needs a fix.

avouspierre commented 12 months ago

Fix blood glucose with a ID not compliance with UUID. Avoid to have a internat server error with NS but data are not uploaded.

LiroyvH commented 12 months ago

@avouspierre Just to be sure, this stops the uploading of any value with a non-compliant/potentially non-unique _id to Nightscout? (I'm not sure what the "100" is referring to, so just checking as in theory you can have up to 288 I suppose).

avouspierre commented 12 months ago

@LiroyvH probably you saw the 100 in the code without analyzing the context of this value ☺️. IAPS splits the array of BG in a json inputs of 100 values to send to NS via post URL call. So all BG values are sent in 3 calls to NS.

LiroyvH commented 12 months ago

@avouspierre Yup, I'm not so good with Swift (or any coding language for that matter :P) so a bit difficult to see/find context sometimes. Thanks for explaining! :) I think that should work fine to remedy the problem then. :)

JohnKitching commented 12 months ago

I'm seeing this with a Libre2 direct too. I've stopped paying for NS so I assumed it was the end of my service but carbs, insulin etc are still being uploaded.

antoinekh commented 12 months ago

I'm seeing this with a Libre2 direct too. I've stopped paying for NS so I assumed it was the end of my service but carbs, insulin etc are still being uploaded.

Same with libre2

LiroyvH commented 12 months ago

@JohnKitching @antoinekh Pls check iAPS logs (grep for Nightscout) and let me know what the error is, if any.

Are you both using paid services that you recently cancelled? Also what NS version?

JohnKitching commented 12 months ago

NS 14.2.6 (via T1Pal)

I've got a few of these: 2023-11-02T07:47:43+0000 [Nightscout] NightscoutManager.swift - uploadTreatments(_:fileToSave:) - 665 - DEV: The network connection was lost.

and a few of these: 2023-11-02T00:04:16+0000 [Nightscout] NightscoutManager.swift - uploadTreatments(_:fileToSave:) - 663 - DEV: Treatments uploaded but BG isn't in NS

antoinekh commented 11 months ago

Nightscout version 14.2.4 Selfhosted on fly.io https://antoinegcm.fly.dev/

2023-11-02T07:00:59+0100 [Nightscout] FetchTreatmentsManager.swift - subscribe() - 27 - DEV: Start fetching carbs and temptargets 2023-11-02T07:00:59+0100 [Nightscout] NightscoutManager.swift - uploadTreatments(:fileToSave:) - 665 - DEV: The network connection was lost. 2023-11-02T07:00:59+0100 [Nightscout] FetchGlucoseManager.swift - subscribe() - 183 - DEV: FetchGlucoseManager callback sensor 2023-11-02T07:01:57+0100 [Nightscout] FetchGlucoseManager.swift - subscribe() - 178 - DEV: FetchGlucoseManager timer heartbeat 2023-11-02T07:01:57+0100 [Nightscout] FetchTreatmentsManager.swift - subscribe() - 26 - DEV: FetchTreatmentsManager heartbeat 2023-11-02T07:01:57+0100 [Nightscout] FetchTreatmentsManager.swift - subscribe() - 27 - DEV: Start fetching carbs and temptargets 2023-11-02T07:01:59+0100 [Nightscout] FetchGlucoseManager.swift - subscribe() - 183 - DEV: FetchGlucoseManager callback sensor 2023-11-02T07:03:04+0100 [Nightscout] FetchGlucoseManager.swift - subscribe() - 183 - DEV: FetchGlucoseManager callback sensor 2023-11-02T07:03:07+0100 [Nightscout] NightscoutManager.swift - uploadGlucose(:fileToSave:) - 633 - DEV: Glucose uploaded 2023-11-02T07:03:14+0100 [Nightscout] NightscoutManager.swift - uploadStatus() - 410 - DEV: Status uploaded 2023-11-02T07:03:14+0100 [Nightscout] NightscoutManager.swift - uploadStatus() - 410 - DEV: Status uploaded 2023-11-02T07:03:15+0100 [Nightscout] NightscoutManager.swift - uploadTreatments(:fileToSave:) - 663 - DEV: Treatments uploaded 2023-11-02T07:03:59+0100 [Nightscout] FetchGlucoseManager.swift - subscribe() - 178 - DEV: FetchGlucoseManager timer heartbeat 2023-11-02T07:03:59+0100 [Nightscout] FetchTreatmentsManager.swift - subscribe() - 26 - DEV: FetchTreatmentsManager heartbeat 2023-11-02T07:03:59+0100 [Nightscout] FetchTreatmentsManager.swift - subscribe() - 27 - DEV: Start fetching carbs and temptargets 2023-11-02T07:04:58+0100 [Nightscout] NightscoutManager.swift - uploadTreatments(:fileToSave:) - 665 - DEV: The network connection was lost. 2023-11-02T07:05:07+0100 [Nightscout] FetchGlucoseManager.swift - subscribe() - 178 - DEV: FetchGlucoseManager timer heartbeat 2023-11-02T07:05:07+0100 [Nightscout] FetchTreatmentsManager.swift - subscribe() - 26 - DEV: FetchTreatmentsManager heartbeat 2023-11-02T07:05:07+0100 [Nightscout] FetchTreatmentsManager.swift - subscribe() - 27 - DEV: Start fetching carbs and temptargets 2023-11-02T07:05:07+0100 [Nightscout] FetchGlucoseManager.swift - subscribe() - 183 - DEV: FetchGlucoseManager callback sensor 2023-11-02T07:05:34+0100 [Nightscout] NightscoutManager.swift - uploadTreatments(_:fileToSave:) - 663 - DEV: Treatments uploaded 2023-11-02T07:06:08+0100 [Nightscout] FetchGlucoseManager.swift - subscribe() - 178 - DEV: FetchGlucoseManager timer heartbeat 2023-11-02T07:06:08+0100 [Nightscout] FetchTreatmentsManager.swift - subscribe() - 26 - DEV: FetchTreatmentsManager heartbeat 2023-11-02T07:06:08+0100 [Nightscout] FetchTreatmentsManager.swift - subscribe() - 27 - DEV: Start fetching carbs and temptargets 2023-11-02T07:06:08+0100 [Nightscout] FetchGlucoseManager.swift - subscribe() - 183 - DEV: FetchGlucoseManager callback sensor

LiroyvH commented 11 months ago

@JohnKitching You don't see any "Glucose uploaded"? Only the network connection loss?

@antoinekh According to that log: 2023-11-02T07:03:07+0100 [Nightscout] NightscoutManager.swift - uploadGlucose(:fileToSave:) - 633 - DEV: Glucose uploaded

So that looks like it was functioning OK to send glucose values. You don't see any? I do see you also have multiple of the "network connection lost" errors. I've seen them in mine as well (local server at home, even works with internet down when at home :P), maybe I should look in to those a bit more sometime as I couldn't imagine it losing connection. Maybe a time-out that triggers too quickly.

antoinekh commented 11 months ago

@LiroyvH No nothing on nightscout, as you can see https://antoinegcm.fly.dev/ I have tried also to remove all nightscout data, but still the same, Insulin and Carbs ok but no Insulin

LiroyvH commented 11 months ago

@antoinekh Are you 100% sure this is not a (Mongo-)storage or other resource issue over at Fly? (Eg: storage full). Because Nightscout is accepting your values judging by your logs, it just doesn't seem to write them.

antoinekh commented 11 months ago

@antoinekh Are you 100% sure this is not a (Mongo-)storage or other resource issue over at Fly? (Eg: storage full). Because Nightscout is accepting your values judging by your logs, it just doesn't seem to write them.

Yes I am sure as I can still write some other data to nightscout (Carbs and Insulin). Data size is only full at 12%.

I have removed all the data to be sure

JohnKitching commented 11 months ago

I don’t seem any BGs in NS despite the log saying it had uploaded them.

On 3 Nov 2023, at 13:00, Liroy van Hoewijk @.***> wrote:



@JohnKitchinghttps://github.com/JohnKitching You don't see any "Glucose uploaded"? Only the network connection loss?

@antoinekhhttps://github.com/antoinekh According to that log: 2023-11-02T07:03:07+0100 [Nightscout] NightscoutManager.swift - uploadGlucose(:fileToSave:) - 633 - DEV: Glucose uploaded

So that looks like it was functioning OK to send glucose values. You don't see any? I do see you also have multiple of the "network connection lost" errors. I've seen them in mine as well (local server at home, even works with internet down when at home :P), maybe I should look in to those a bit more sometime as I couldn't imagine it losing connection. Maybe a time-out that triggers too quickly.

— Reply to this email directly, view it on GitHubhttps://github.com/Artificial-Pancreas/iAPS/issues/280#issuecomment-1792399186, or unsubscribehttps://github.com/notifications/unsubscribe-auth/ALRAFBKW3ZFDWPP2DA3XXSDYCTTIBAVCNFSM6AAAAAA6QCANKKVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTOOJSGM4TSMJYGY. You are receiving this because you were mentioned.Message ID: @.***>

LiroyvH commented 11 months ago

@antoinekh that's some weird shit right there haha. Can you show me the glucose.json and uploaded-glucose.json? You can replace your BG values and any identifying information with random garbage if you wish. Please put them in a code view or quote. (3 backticks ` at start and end).

@JohnKitching Ok, so the exact same error.

Question to you both @antoinekh @JohnKitching Which version/branch are you sporting? Thanks

LiroyvH commented 11 months ago

@antoinekh @JohnKitching Nevermind, I think I see the problem now. Pushed potential fix to dev branch https://github.com/Artificial-Pancreas/iAPS/pull/300. (Not merged yet)

antoinekh commented 11 months ago

@antoinekh @JohnKitching Nevermind, I think I see the problem now. Pushed potential fix to dev branch #300. (Not merged yet)

Does this will fix previous glucose data?

LiroyvH commented 11 months ago

@antoinekh No I don't think it will. At best it would only have synced the past 24 hours anyway - sorry.

antoinekh commented 11 months ago

@LiroyvH I just tested the last dev and this fix the issue, thanks a lot !