search

AAPS-Omnipod / AndroidAPS

GNU Affero General Public License v3.0
21 stars 19 forks source link

IndexOutOfBoundsException on TBR via SMS #13

Closed samspycher closed 3 years ago

samspycher commented 3 years ago

When running on a basal of 0.2 IE/h, and setting this temporary basal via SMS:

BASAL 120% 10

The treatment will fail, showing this log output:

11:27:15.370 [IntentService[DataService]] D/PUMPQUEUE: [CommandQueue.add():164]: Adding: CommandTempBasalPercent - TEMP BASAL 120% 10 min
11:27:15.372 [IntentService[DataService]] D/PUMPQUEUE: [CommandQueue.notifyAboutNewCommand():203]: Starting new thread
11:27:15.373 [IntentService[DataService]] D/DATASERVICE: [DataService.onHandleIntent():106]: onHandleIntent exit Intent { act=android.provider.Telephony.SMS_RECEIVED cmp=info.nightscout.androidaps/.services.DataService (has extras) }
11:27:15.379 [Thread-6271] D/PUMPQUEUE: [QueueThread.run():129]: connection time 0s
11:27:15.379 [Thread-6271] D/PUMPQUEUE: [QueueThread.run():135]: performing TEMP BASAL 120% 10 min
11:27:15.380 [Thread-6271] W/PUMP: [OmnipodPumpPlugin.setTempBasalPercent():903]: setTempBasalPercent [MedtronicPumpPlugin] - You are trying to use setTempBasalPercent with percent other then 0% (120). This will start setTempBasalAbsolute, with calculated value (0.25). Re
sult might not be 100% correct.
11:27:15.380 [Thread-6271] I/PUMP: [OmnipodPumpPlugin.setTempBasalAbsolute():538]: setTempBasalAbsolute: rate: [0.25, 10], duration={}
11:27:15.381 [Thread-6271] D/PUMP: [OmnipodPumpPlugin.executeCommand():960]: Executing command: [SET_TEMPORARY_BASAL]
11:27:15.382 [Thread-6271] D/PUMPCOMM: [OmnipodManager.logStartingCommandExecution():685]: Starting command execution for action: setTemporaryBasal [rate=0.25, duration=PT600S, acknowledgementBeep=true, completionBeep=true]
11:27:15.382 [Thread-6271] D/PUMPCOMM: [OmnipodManager.logStartingCommandExecution():685]: Starting command execution for action: verifyCommand
11:27:15.383 [Thread-6271] D/PUMPCOMM: [OmnipodManager.logCommandExecutionFinished():689]: Command execution finished for action: verifyCommand
11:27:15.384 [Thread-6271] D/PUMPCOMM: [OmnipodManager.logCommandExecutionFinished():689]: Command execution finished for action: setTemporaryBasal
11:27:15.389 [Thread-6271] E/PUMP: [AapsOmnipodManager.handleException():764]: Caught an unexpected non-OmnipodException from OmnipodManager
java.lang.IndexOutOfBoundsException: Index: 0, Size: 0
        at java.util.ArrayList.get(ArrayList.java:437) ~[na:0.0]
        at info.nightscout.androidaps.plugins.pump.omnipod.driver.communication.message.command.TempBasalExtraCommand.<init>(TempBasalExtraCommand.java:40) ~[na:0.0]
        at info.nightscout.androidaps.plugins.pump.omnipod.driver.communication.action.SetTempBasalAction.execute(SetTempBasalAction.java:41) ~[na:0.0]
        at info.nightscout.androidaps.plugins.pump.omnipod.driver.communication.action.SetTempBasalAction.execute(SetTempBasalAction.java:16) ~[na:0.0]
        at info.nightscout.androidaps.plugins.pump.omnipod.rileylink.manager.OmnipodRileyLinkCommunicationManager.executeAction(OmnipodRileyLinkCommunicationManager.java:94) ~[na:0.0]
        at info.nightscout.androidaps.plugins.pump.omnipod.driver.manager.OmnipodManager.lambda$setTemporaryBasal$5$OmnipodManager(OmnipodManager.java:287) ~[na:0.0]
        at info.nightscout.androidaps.plugins.pump.omnipod.driver.manager.-$$Lambda$OmnipodManager$imAs4GNoYz_Pw23FTcnmfDWYTSA.get(Unknown Source:10) ~[na:0.0]
        at info.nightscout.androidaps.plugins.pump.omnipod.driver.manager.OmnipodManager.executeAndVerify(OmnipodManager.java:597) ~[na:0.0]
        at info.nightscout.androidaps.plugins.pump.omnipod.driver.manager.OmnipodManager.setTemporaryBasal(OmnipodManager.java:287) ~[na:0.0]
        at info.nightscout.androidaps.plugins.pump.omnipod.manager.AapsOmnipodManager.lambda$setTemporaryBasal$6$AapsOmnipodManager(AapsOmnipodManager.java:445) ~[na:0.0]
        at info.nightscout.androidaps.plugins.pump.omnipod.manager.-$$Lambda$AapsOmnipodManager$4zwoB9PNwt5zCaqcI-knfgdEWXw.run(Unknown Source:6) ~[na:0.0]
        at info.nightscout.androidaps.plugins.pump.omnipod.manager.AapsOmnipodManager.executeCommand(AapsOmnipodManager.java:738) ~[na:0.0]
        at info.nightscout.androidaps.plugins.pump.omnipod.manager.AapsOmnipodManager.setTemporaryBasal(AapsOmnipodManager.java:445) ~[na:0.0]
        at info.nightscout.androidaps.plugins.pump.omnipod.OmnipodPumpPlugin.lambda$setTempBasalAbsolute$5$OmnipodPumpPlugin(OmnipodPumpPlugin.java:555) ~[na:0.0]
        at info.nightscout.androidaps.plugins.pump.omnipod.-$$Lambda$OmnipodPumpPlugin$GDIYGbL8KRgqj8P8L0afZroOxc0.get(Unknown Source:6) ~[na:0.0]
        at info.nightscout.androidaps.plugins.pump.omnipod.OmnipodPumpPlugin.executeCommand(OmnipodPumpPlugin.java:964) ~[na:0.0]
        at info.nightscout.androidaps.plugins.pump.omnipod.OmnipodPumpPlugin.setTempBasalAbsolute(OmnipodPumpPlugin.java:555) ~[na:0.0]
        at info.nightscout.androidaps.plugins.pump.omnipod.OmnipodPumpPlugin.setTempBasalPercent(OmnipodPumpPlugin.java:904) ~[na:0.0]
        at info.nightscout.androidaps.queue.commands.CommandTempBasalPercent.execute(CommandTempBasalPercent.kt:22) ~[na:0.0]
        at info.nightscout.androidaps.queue.QueueThread.run(QueueThread.java:137) ~[na:0.0]
11:27:15.417 [Thread-6271] I/PUMP: [OmnipodPumpPlugin.setTempBasalAbsolute():557]: setTempBasalAbsolute - setTBR. Response: false
11:27:15.418 [Thread-6271] D/PUMPQUEUE: [CommandTempBasalPercent.execute():23]: Result percent: 120 durationInMinutes: 10 success: false enacted: false
11:27:15.418 [RxCachedThreadScheduler-18] D/GLUCOSE: [GlucoseStatus.getGlucoseStatusData():129]: BgReading{date=1601717180000, date=03.10.20 11:26, value=120.0, direction=Flat, raw=120.0} minutesago=0 avgdelta=NaN
11:27:15.418 [RxCachedThreadScheduler-18] D/GLUCOSE: [GlucoseStatus.getGlucoseStatusData():170]: Glucose: 120 mg/dl Noise: 0 Delta: 0 mg/dlShort avg. delta:  0,00 mg/dl Long avg. delta: 0,00 mg/dl
11:27:15.419 [Thread-6271] D/SMS: [SmsCommunicatorPlugin.sendSMS():952]: Sending SMS to +41774367755: Das Starten der TBR ist fehlgeschlagen.
LastConn: 3 min ago
LastBolus: 2,55U @09:51
Reserv: 75U
Batt: 75

Contrasting this with an immediately following, succesful execution of the same TBR but for 20 minutes:

11:28:23.911 [IntentService[DataService]] D/PUMPQUEUE: [CommandQueue.add():164]: Adding: CommandTempBasalPercent - TEMP BASAL 120% 20 min
11:28:23.912 [IntentService[DataService]] D/PUMPQUEUE: [CommandQueue.notifyAboutNewCommand():203]: Starting new thread
11:28:23.913 [IntentService[DataService]] D/DATASERVICE: [DataService.onHandleIntent():106]: onHandleIntent exit Intent { act=android.provider.Telephony.SMS_RECEIVED cmp=info.nightscout.androidaps/.services.DataService (has extras) }
11:28:23.916 [Thread-6278] D/PUMPQUEUE: [QueueThread.run():129]: connection time 0s
11:28:23.917 [Thread-6278] D/PUMPQUEUE: [QueueThread.run():135]: performing TEMP BASAL 120% 20 min
11:28:23.918 [Thread-6278] W/PUMP: [OmnipodPumpPlugin.setTempBasalPercent():903]: setTempBasalPercent [MedtronicPumpPlugin] - You are trying to use setTempBasalPercent with percent other then 0% (120). This will start setTempBasalAbsolute, with calculated value (0.25). Result might not be 100% correct.
11:28:23.919 [Thread-6278] I/PUMP: [OmnipodPumpPlugin.setTempBasalAbsolute():538]: setTempBasalAbsolute: rate: [0.25, 20], duration={}
11:28:23.919 [Thread-6278] D/PUMP: [OmnipodPumpPlugin.executeCommand():960]: Executing command: [SET_TEMPORARY_BASAL]
11:28:23.921 [Thread-6278] D/PUMPCOMM: [OmnipodManager.logStartingCommandExecution():685]: Starting command execution for action: setTemporaryBasal [rate=0.25, duration=PT1200S, acknowledgementBeep=true, completionBeep=true]
11:28:23.922 [Thread-6278] D/PUMPCOMM: [OmnipodManager.logStartingCommandExecution():685]: Starting command execution for action: verifyCommand
11:28:23.923 [Thread-6278] D/PUMPBTCOMM: [OmnipodRileyLinkCommunicationManager.exchangeMessages():110]: Exchanging OmnipodMessage: responseClass=[StatusResponse, AapsPodStateManager{podState=PodState{address=520344976, lot=45761, tid=1061467, piVersion=2.9.0, pmVersion=2.9.0, packetNumber=27, messageNumber=10, lastSuccessfulCommunication=2020-10-03T11:23:59.310+02:00, lastFailedCommunication=null, lastUpdatedFromResponse=2020-10-03T11:23:59.310+02:00, timeZone=Europe/Zurich, activatedAt=2020-10-02T20:21:05.624+02:00, timeActive=PT54240S, faultEvent=null, reservoirLevel=null, totalTicksDelivered=193, suspended=false, nonceState=NonceState{table=[851640061, 1938708229, -1488188853, -1162969252, 548495536, 1274614357, -1948069283, -284668558, -516423874, -2055248077, -30682507, -1820065374, -730433744, 1921734405, -1094608832, 2075397411, -249309962, 2104637873, 0, 0, 0], index=3}, podProgressStatus=ABOVE_FIFTY_UNITS, lastDeliveryStatus=NORMAL, activeAlerts=AlertSet{alertSlots=[]}, basalSchedule=BasalSchedule{entries=[BasalScheduleEntry{rate=0.2, startTime=0s}, BasalScheduleEntry{rate=0.15, startTime=18000s}, BasalScheduleEntry{rate=0.2, startTime=28800s}, BasalScheduleEntry{rate=0.25, startTime=50400s}, BasalScheduleEntry{rate=0.3, startTime=54000s}, BasalScheduleEntry{rate=0.5, startTime=75600s}, BasalScheduleEntry{rate=0.4, startTime=82800s}]}, lastBolusStartTime=2020-10-03T09:51:05.844+02:00, lastBolusAmount=2.55, lastBolusDuration=PT102.227S, lastBolusCertain=true, tempBasalAmount=null, tempBasalStartTime=null, tempBasalDuration=null, tempBasalCertain=true, expirationAlertTimeBeforeShutdown=PT10800S, lowReservoirAlertUnits=20, configuredAlerts={SLOT2=SHUTDOWN_IMMINENT_ALARM, SLOT4=LOW_RESERVOIR_ALERT, SLOT7=EXPIRATION_ADVISORY_ALERT}}}, OmnipodMessage{address=520344976, messageBlocks=[SetInsulinScheduleCommand{schedule=TempBasalDeliverySchedule{secondsRemaining=1800, firstSegmentPulses=2, basalTable=BasalDeliveryTable{entries=[BasalTableEntry{segments=1, pulses=2, alternateSegmentPulse=false}]}}, nonce=1274614357}, TempBasalExtraCommand{acknowledgementBeep=true, completionBeep=true, programReminderInterval=PT0S, remainingPulses=2.5, delayUntilNextPulse=720.0, rateEntries=[RateEntry{totalPulses=2.5, delayBetweenPulsesInSeconds=720.0}]}], encoded=1F03D59028201A0E4BF9125501007D01384000020002160EC0000019044AA2000019044AA2000148, sequenceNumber=10}, null, null, true], podStateManager={}, message={}, addressOverride={}, ackAddressOverride={}, automaticallyResyncNonce={}
11:28:23.927 [Thread-6278] I/PUMPBTCOMM: [RileyLinkCommunicationManager.sendAndListen():75]: Sent:1F 03 D5 90 BB 1F 03 D5 90 28 20 1A 0E 4B F9 12 55 01 00 7D 01 38 40 00 02 00 02 16 0E C0 00 00 19 04 4A A2 D6
...
11:28:31.298 [Thread-6278] I/PUMP: [OmnipodPumpPlugin.setTempBasalAbsolute():557]: setTempBasalAbsolute - setTBR. Response: true
11:28:31.299 [RxCachedThreadScheduler-18] D/GLUCOSE: [GlucoseStatus.getGlucoseStatusData():129]: BgReading{date=1601717180000, date=03.10.20 11:26, value=120.0, direction=Flat, raw=120.0} minutesago=0 avgdelta=NaN
11:28:31.299 [RxCachedThreadScheduler-18] D/GLUCOSE: [GlucoseStatus.getGlucoseStatusData():170]: Glucose: 120 mg/dl Noise: 0 Delta: 0 mg/dlShort avg. delta:  0,00 mg/dl Long avg. delta: 0,00 mg/dl
11:28:31.300 [RxCachedThreadScheduler-28] D/NSCLIENT: [NSClientPlugin.lambda$onStart$4$NSClientPlugin():166]: QUEUE Resend started: newdata
11:28:31.300 [RxCachedThreadScheduler-28] D/NSCLIENT: [NSClientPlugin.lambda$onStart$4$NSClientPlugin():166]: DBADD treatments Sent 1601717311287
11:28:31.300 [RxCachedThreadScheduler-28] D/NSCLIENT: [NSClientPlugin.lambda$onStart$4$NSClientPlugin():166]: QUEUE Resend ended: newdata
11:28:31.300 [Thread-6278] D/PUMPQUEUE: [CommandTempBasalPercent.execute():23]: Result percent: 120 durationInMinutes: 20 success: true enacted: true
11:28:31.303 [Thread-6278] D/SMS: [SmsCommunicatorPlugin.sendSMS():952]: Sending SMS to +41764128283: TBR mit -1,00 IE/h fur -1 min wurde erfolgreich gestartet.
LastConn: 0 min ago
LastBolus: 2,55U @09:51
Reserv: 75U
Batt: 75
samspycher commented 3 years ago

Looking at the code, the offending value is confirmed to be duration, and this exception will happen with any value lower than 15 minutes, because:

  1. TempBasalExtraCommand creates rateEntries of type RateEntry with the static method RateEntry.createEntries,
  2. createEntries declares a remainingSegments int with int remainingSegments = (int) Math.round(duration.getStandardSeconds() / 1800.0); which puts this int at 0 for any duration less than 900s.
  3. The method then loops over the condition while (remainingSegments > 0) to actually create entries, leaving with 0 entries created in the case where remainingSegments is already 0 and duration is less than 15m / 900s.
  4. TempBasalExtraCommand then immediately calls the first non-existing entry, which results in the IndexOutOfBoundsException

I am not sure what to do here, because I am unaware of what the intent is for TBR durations.

@bartsopers thank you for your thoughts on this!

bartsopers commented 3 years ago

@samspycher good find! I'll have a look at it later this weekend as I currently don't have any access to a computer

bartsopers commented 3 years ago

I look at the code and I think this is a core issue: SmsCommunicatorPlugin does not take PumpType.tbrSettings into account, which I think it should.

I would suggest opening an issue for this in the main AAPS repo. Meanwhile, my proposal would be to validate the duration argument in two places:

@samspycher please let me know whether you agree with the proposed workaround. In case you are interested in fixing this yourself, I would be more than happy to review a PR. Otherwise I hope to be able to fix it later this week.

bartsopers commented 3 years ago

Fixed by @samspycher in AAPS core