diff --git a/app/src/main/assets/logback.xml b/app/src/main/assets/logback.xml index 41ed7bdefe..82ab67b00a 100644 --- a/app/src/main/assets/logback.xml +++ b/app/src/main/assets/logback.xml @@ -15,7 +15,7 @@ 120 - %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n + %d{HH:mm:ss.SSS} [%thread] %-5level [%file:%line]: %msg%n @@ -24,7 +24,7 @@ %logger{0} - [%thread] %-5level %logger{36} - %msg%n + [%thread] %-5level [%file:%line]: %msg%n diff --git a/app/src/main/java/de/jotomo/ruffyscripter/commands/BolusCommand.java b/app/src/main/java/de/jotomo/ruffyscripter/commands/BolusCommand.java index acf88c36c0..d5197452e3 100644 --- a/app/src/main/java/de/jotomo/ruffyscripter/commands/BolusCommand.java +++ b/app/src/main/java/de/jotomo/ruffyscripter/commands/BolusCommand.java @@ -39,25 +39,8 @@ public class BolusCommand implements Command { try { enterBolusMenu(scripter); - boolean bolusAmountInputSuccess = false; - int bolusAmountInputRetries = 2; - // see SetTbrCommand.execute for an explanation why we're looping here - while (!bolusAmountInputSuccess) { - try { - inputBolusAmount(scripter); - // TODO v2 this call can probably be removed by now - SystemClock.sleep(750); - verifyDisplayedBolusAmount(scripter); - bolusAmountInputSuccess = true; - } catch (CommandException e) { - if (bolusAmountInputRetries >= 0) { - log.warn("Failed to set bolus amount, retrying", e); - bolusAmountInputRetries--; - } else { - throw e; - } - } - } + inputBolusAmount(scripter); + verifyDisplayedBolusAmount(scripter); // confirm bolus scripter.verifyMenuIsDisplayed(MenuType.BOLUS_ENTER); @@ -87,6 +70,35 @@ public class BolusCommand implements Command { "Bolus delivery did not complete as expected. " + "Check pump manually, the bolus might not have been delivered."); + // read last bolus record; those menus display static data and therefore + // only a single menu update is sent + scripter.navigateToMenu(MenuType.MY_DATA_MENU); + scripter.verifyMenuIsDisplayed(MenuType.MY_DATA_MENU); + scripter.pressCheckKey(); + if (scripter.currentMenu.getType() != MenuType.BOLUS_DATA) { + scripter.waitForMenuUpdate(); + } + + if (!scripter.currentMenu.attributes().contains(MenuAttribute.BOLUS)) { + throw new CommandException().success(false).enacted(true) + .message("Bolus was delivered, but unable to confirm it with history record"); + } + + double lastBolusInHistory = (double) scripter.currentMenu.getAttribute(MenuAttribute.BOLUS); + if (Math.abs(bolus - lastBolusInHistory) > 0.05) { + throw new CommandException().success(false).enacted(true) + .message("Last bolus shows " + lastBolusInHistory + + " U delievered, but " + bolus + " U were requested"); + } + log.debug("Bolus record in history confirms delivered bolus"); + + // leave menu to go back to main menu + scripter.pressCheckKey(); + scripter.waitForMenuToBeLeft(MenuType.BOLUS_DATA); + scripter.verifyMenuIsDisplayed(MenuType.MAIN_MENU, + "Bolus was correctly delivered and checked against history, but we " + + "did not return the main menu successfully."); + return new CommandResult().success(true).enacted(true) .message(String.format(Locale.US, "Delivered %02.1f U", bolus)); } catch (CommandException e) { @@ -112,6 +124,9 @@ public class BolusCommand implements Command { scripter.pressUpKey(); SystemClock.sleep(100); } + // Give the pump time to finish any scrolling that might still be going on, can take + // up to 1100ms. Plus some extra time to be sure + SystemClock.sleep(2000); } private void verifyDisplayedBolusAmount(RuffyScripter scripter) { @@ -121,6 +136,14 @@ public class BolusCommand implements Command { if (Math.abs(displayedBolus - bolus) > 0.05) { throw new CommandException().message("Failed to set correct bolus. Expected: " + bolus + ", actual: " + displayedBolus); } + + // check again to ensure the displayed value hasn't change due to due scrolling taking extremely long + SystemClock.sleep(2000); + double refreshedDisplayedBolus = readDisplayedBolusAmount(scripter); + if (Math.abs(displayedBolus - refreshedDisplayedBolus) > 0.05) { + throw new CommandException().message("Failed to set bolus: bolus changed after input stopped from " + + displayedBolus + " -> " + refreshedDisplayedBolus); + } } private double readDisplayedBolusAmount(RuffyScripter scripter) { diff --git a/app/src/main/java/de/jotomo/ruffyscripter/commands/Command.java b/app/src/main/java/de/jotomo/ruffyscripter/commands/Command.java index c18ce48c07..33d10fc223 100644 --- a/app/src/main/java/de/jotomo/ruffyscripter/commands/Command.java +++ b/app/src/main/java/de/jotomo/ruffyscripter/commands/Command.java @@ -5,6 +5,13 @@ import java.util.List; import de.jotomo.ruffyscripter.PumpState; import de.jotomo.ruffyscripter.RuffyScripter; +/** + * Interface for all commands to be executed by the pump. + * + * Note on cammond methods and timing: a method shall wait before and after executing + * as necessary to not cause timing issues, so the caller can just call methods in + * sequence, letting the methods take care of waits. + */ public interface Command { CommandResult execute(RuffyScripter ruffyScripter, PumpState initialPumpState); List validateArguments(); diff --git a/app/src/main/java/de/jotomo/ruffyscripter/commands/CommandException.java b/app/src/main/java/de/jotomo/ruffyscripter/commands/CommandException.java index 4e6637f84f..5c25ba914c 100644 --- a/app/src/main/java/de/jotomo/ruffyscripter/commands/CommandException.java +++ b/app/src/main/java/de/jotomo/ruffyscripter/commands/CommandException.java @@ -23,6 +23,11 @@ public class CommandException extends RuntimeException { return this; } + @Override + public String getMessage() { + return message; + } + public CommandException message(String message) { this.message = message; return this; diff --git a/app/src/main/java/de/jotomo/ruffyscripter/commands/SetTbrCommand.java b/app/src/main/java/de/jotomo/ruffyscripter/commands/SetTbrCommand.java index ec29a6091a..4ffd154acf 100644 --- a/app/src/main/java/de/jotomo/ruffyscripter/commands/SetTbrCommand.java +++ b/app/src/main/java/de/jotomo/ruffyscripter/commands/SetTbrCommand.java @@ -57,34 +57,8 @@ public class SetTbrCommand implements Command { public CommandResult execute(RuffyScripter scripter, PumpState initialPumpState) { try { enterTbrMenu(scripter); - - boolean tbrPercentInputSuccess = false; - int tbrPercentInputRetries = 2; - // Setting TBR percentage/duration works most of the time. Occassionnally though, - // button presses don't take, e.g. we press down 10 times to go from 100% to 0% - // but the pump ends on 30%. In that case restarting inputing the TBR, so we start - // again and push down 3 times. - // Either our timings are of, or the pump sometimes is sluggish. I suspect the later, - // based on an error when switching from TBR_SET to TBR_DURATION took more than 1.1s - // and 4 menu updates were sent before the menu was finally switched. This happened - // around the time when a running TBR was about to run out. So maybe the pump was busy - // updating its history records. - while (!tbrPercentInputSuccess) { - try { - inputTbrPercentage(scripter); - // TODO v2 this can probably be removed by now - SystemClock.sleep(750); - verifyDisplayedTbrPercentage(scripter); - tbrPercentInputSuccess = true; - } catch (CommandException e) { - if (tbrPercentInputRetries >= 0) { - log.warn("Setting TBR percentage failed, retrying", e); - tbrPercentInputRetries--; - } else { - throw e; - } - } - } + inputTbrPercentage(scripter); + verifyDisplayedTbrPercentage(scripter); if (percentage == 100) { cancelTbrAndConfirmCancellationWarning(scripter); @@ -95,25 +69,8 @@ public class SetTbrCommand implements Command { scripter.waitForMenuUpdate(); scripter.verifyMenuIsDisplayed(MenuType.TBR_DURATION); - boolean tbrDurationSuccess = false; - int tbrDurationRetries = 2; - // see above why we loop here - while (!tbrDurationSuccess) { - try { - inputTbrDuration(scripter); - // TODO v2 this can probably be removed by now - SystemClock.sleep(750); - verifyDisplayedTbrDuration(scripter); - tbrDurationSuccess = true; - } catch (CommandException e) { - if (tbrDurationRetries >= 0) { - log.warn("Setting TBR duration failed, retrying", e); - tbrDurationRetries--; - } else { - throw e; - } - } - } + inputTbrDuration(scripter); + verifyDisplayedTbrDuration(scripter); // confirm TBR scripter.pressCheckKey(); @@ -167,15 +124,27 @@ public class SetTbrCommand implements Command { SystemClock.sleep(100); log.debug("Push #" + (i + 1)); } + // Give the pump time to finish any scrolling that might still be going on, can take + // up to 1100ms. Plus some extra time to be sure + SystemClock.sleep(2000); } private void verifyDisplayedTbrPercentage(RuffyScripter scripter) { scripter.verifyMenuIsDisplayed(MenuType.TBR_SET); long displayedPercentage = readDisplayedTbrPercentage(scripter); - if (displayedPercentage != this.percentage) { + if (displayedPercentage != percentage) { log.debug("Final displayed TBR percentage: " + displayedPercentage); throw new CommandException().message("Failed to set TBR percentage"); } + + // check again to ensure the displayed value hasn't change due to due scrolling taking extremely long + SystemClock.sleep(2000); + long refreshedDisplayedTbrPecentage = readDisplayedTbrPercentage(scripter); + if (displayedPercentage != refreshedDisplayedTbrPecentage) { + throw new CommandException().message("Failed to set TBR percentage: " + + "percentage changed after input stopped from " + + displayedPercentage + " -> " + refreshedDisplayedTbrPecentage); + } } private long readDisplayedTbrPercentage(RuffyScripter scripter) { @@ -220,6 +189,9 @@ public class SetTbrCommand implements Command { SystemClock.sleep(100); log.debug("Push #" + (i + 1)); } + // Give the pump time to finish any scrolling that might still be going on, can take + // up to 1100ms. Plus some extra time to be sure + SystemClock.sleep(2000); } private void verifyDisplayedTbrDuration(RuffyScripter scripter) { @@ -229,6 +201,15 @@ public class SetTbrCommand implements Command { log.debug("Final displayed TBR duration: " + displayedDuration); throw new CommandException().message("Failed to set TBR duration"); } + + // check again to ensure the displayed value hasn't change due to due scrolling taking extremely long + SystemClock.sleep(2000); + long refreshedDisplayedTbrDuration = readDisplayedTbrDuration(scripter); + if (displayedDuration != refreshedDisplayedTbrDuration) { + throw new CommandException().message("Failed to set TBR duration: " + + "duration changed after input stopped from " + + displayedDuration + " -> " + refreshedDisplayedTbrDuration); + } } private long readDisplayedTbrDuration(RuffyScripter scripter) { @@ -253,14 +234,14 @@ public class SetTbrCommand implements Command { // A "TBR CANCELLED alert" is only raised by the pump when the remaining time is // greater than 60s (displayed as 0:01, the pump goes from there to finished. // We could read the remaining duration from MAIN_MENU, but by the time we're here, - // the pmup could have moved from 0:02 to 0:01, so instead, check if a "TBR CANCELLED alert" + // the pumup could have moved from 0:02 to 0:01, so instead, check if a "TBR CANCELLED" alert // is raised and if so dismiss it - long inTwoSeconds = System.currentTimeMillis() + 5 * 1000; + long inFiveSeconds = System.currentTimeMillis() + 5 * 1000; boolean alertProcessed = false; - while (System.currentTimeMillis() < inTwoSeconds && !alertProcessed) { + while (System.currentTimeMillis() < inFiveSeconds && !alertProcessed) { if (scripter.currentMenu.getType() == MenuType.WARNING_OR_ERROR) { - // Check the raised alarm is TBR CANCELLED, so we're not accidentally cancelled - // a different that might be raised at the same time. + // Check the raised alarm is TBR CANCELLED, so we're not accidentally cancelling + // a different alarm that might be raised at the same time. // Note that the message is permanently displayed, while the error code is blinking. // A wait till the error code can be read results in the code hanging, despite // menu updates coming in, so just check the message. @@ -271,10 +252,10 @@ public class SetTbrCommand implements Command { .message("An alert other than the expected TBR CANCELLED was raised by the pump: " + errorMsg + ". Please check the pump."); } - // confirm "TBR CANCELLED alert" + // confirm "TBR CANCELLED" alert scripter.verifyMenuIsDisplayed(MenuType.WARNING_OR_ERROR); scripter.pressCheckKey(); - // dismiss "TBR CANCELLED alert" + // dismiss "TBR CANCELLED" alert scripter.verifyMenuIsDisplayed(MenuType.WARNING_OR_ERROR); scripter.pressCheckKey(); scripter.waitForMenuToBeLeft(MenuType.WARNING_OR_ERROR); @@ -297,7 +278,7 @@ public class SetTbrCommand implements Command { scripter.verifyMenuIsDisplayed(MenuType.MAIN_MENU); // new TBR set; percentage and duration must be displayed ... if (!scripter.currentMenu.attributes().contains(MenuAttribute.TBR) || - !scripter.currentMenu.attributes().contains(MenuAttribute.TBR)) { + !scripter.currentMenu.attributes().contains(MenuAttribute.RUNTIME)) { throw new CommandException().message("Setting TBR failed, according to MAIN_MENU no TBR is active"); } Double mmTbrPercentage = (Double) scripter.currentMenu.getAttribute(MenuAttribute.TBR); diff --git a/app/src/main/java/info/nightscout/androidaps/plugins/ConfigBuilder/ConfigBuilderPlugin.java b/app/src/main/java/info/nightscout/androidaps/plugins/ConfigBuilder/ConfigBuilderPlugin.java index 0629011397..31907f16dc 100644 --- a/app/src/main/java/info/nightscout/androidaps/plugins/ConfigBuilder/ConfigBuilderPlugin.java +++ b/app/src/main/java/info/nightscout/androidaps/plugins/ConfigBuilder/ConfigBuilderPlugin.java @@ -578,9 +578,10 @@ public class ConfigBuilderPlugin implements PluginBase, PumpInterface, Constrain result.comment = "Temp basal set correctly"; result.success = true; if (Config.logCongigBuilderActions) - log.debug("applyAPSRequest: Temp basal set correctly " + - "(no pump request needed, pump is still running request TBR for " - + getTempBasalRemainingMinutesFromHistory() + " more minutes)"); + log.debug("applyAPSRequest: Temp basal set correctly " + + "(no pump request needed, pump is still running requested rate of " + + request.rate + " for " + + (int) getTempBasalRemainingMinutesFromHistory() + " more minutes)"); } else { if (Config.logCongigBuilderActions) log.debug("applyAPSRequest: setTempBasalAbsolute()");