Merge remote-tracking branch 'origin/develop' into read-maxtbr-clean

app/src/main/assets/logback.xml

@@ -15,7 +15,7 @@
             <maxHistory>120</maxHistory>
 	</rollingPolicy>
     <encoder>
-      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
+      <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level [%file:%line]: %msg%n</pattern>
     </encoder>
   </appender>
 
@@ -24,7 +24,7 @@
 		  <pattern>%logger{0}</pattern>
 	  </tagEncoder>
     <encoder>
-      <pattern>[%thread] %-5level %logger{36} - %msg%n</pattern>
+      <pattern>[%thread] %-5level [%file:%line]: %msg%n</pattern>
     </encoder>
   </appender>
   

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;
+            inputBolusAmount(scripter);
-            int bolusAmountInputRetries = 2;
+            verifyDisplayedBolusAmount(scripter);
-            // 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;
-                    }
-                }
-            }
 
             // 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) {

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<String> validateArguments();

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;

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);
-
+            inputTbrPercentage(scripter);
-            boolean tbrPercentInputSuccess = false;
+            verifyDisplayedTbrPercentage(scripter);
-            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;
-                    }
-                }
-            }
 
             if (percentage == 100) {
                 cancelTbrAndConfirmCancellationWarning(scripter);
@@ -95,25 +69,8 @@ public class SetTbrCommand implements Command {
                 scripter.waitForMenuUpdate();
                 scripter.verifyMenuIsDisplayed(MenuType.TBR_DURATION);
 
-                boolean tbrDurationSuccess = false;
+                inputTbrDuration(scripter);
-                int tbrDurationRetries = 2;
+                verifyDisplayedTbrDuration(scripter);
-                // 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;
-                        }
-                    }
-                }
 
                 // 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
+                // Check the raised alarm is TBR CANCELLED, so we're not accidentally cancelling
-                // a different that might be raised at the same time.
+                // 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);

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 " +
+                log.debug("applyAPSRequest: Temp basal set correctly "
-                        "(no pump request needed, pump is still running request TBR for "
+                        + "(no pump request needed, pump is still running requested rate of "
-                        + getTempBasalRemainingMinutesFromHistory() + " more minutes)");
+                        + request.rate + " for "
+                        + (int) getTempBasalRemainingMinutesFromHistory() + " more minutes)");
         } else {
             if (Config.logCongigBuilderActions)
                 log.debug("applyAPSRequest: setTempBasalAbsolute()");