Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
LiroyvH opened this issue Oct 25, 2023 · 21 comments

Comments

@LiroyvH
Copy link
Contributor

LiroyvH commented Oct 25, 2023

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:

_id: newGlucoseSample.syncIdentifier,
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
Copy link
Contributor Author

LiroyvH commented Oct 26, 2023

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
Copy link
Contributor Author

LiroyvH commented Oct 27, 2023

PR to make the _id field unique is here: #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 added a commit that referenced this issue Oct 28, 2023
Fix #280 with checking the compliance of ID as uuid. Not perfect (lost data in NS) but avoid the 500 error.
Fix for G7 sensor.
@avouspierre
Copy link
Collaborator

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
Copy link
Contributor Author

LiroyvH commented Oct 28, 2023

@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
Copy link
Collaborator

@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
Copy link
Contributor Author

LiroyvH commented Oct 30, 2023

@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
Copy link

JohnKitching commented Nov 1, 2023

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
Copy link

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
Copy link
Contributor Author

LiroyvH commented Nov 1, 2023

@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
Copy link

JohnKitching commented Nov 2, 2023

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
Copy link

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
Copy link
Contributor Author

LiroyvH commented Nov 3, 2023

@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
Copy link

@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
Copy link
Contributor Author

LiroyvH commented Nov 3, 2023

@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
Copy link

@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
Copy link

JohnKitching commented Nov 3, 2023 via email

@LiroyvH
Copy link
Contributor Author

LiroyvH commented Nov 3, 2023

@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
Copy link
Contributor Author

LiroyvH commented Nov 3, 2023

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

@antoinekh
Copy link

@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
Copy link
Contributor Author

LiroyvH commented Nov 3, 2023

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

@antoinekh
Copy link

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

@LiroyvH LiroyvH changed the title Dexcom BG readings fail to upload to Nightscout due to seemingly non-unique _id field [BUG] Dexcom BG readings fail to upload to Nightscout due to non-unique _id field Nov 8, 2023
@LiroyvH LiroyvH changed the title [BUG] Dexcom BG readings fail to upload to Nightscout due to non-unique _id field [Bug] Dexcom BG readings fail to upload to Nightscout due to non-unique _id field Nov 8, 2023
@Jon-b-m Jon-b-m closed this as completed Nov 10, 2023
Jon-b-m pushed a commit that referenced this issue Nov 22, 2023
Fix #280 with checking the compliance of ID as uuid. Not perfect (lost data in NS) but avoid the 500 error.
Fix for G7 sensor.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

5 participants