Merge branch 'stable' into develop

* stable:
  Typos.
  SetTbrCommand: remove retry logic, add extra checks for final bolus.
  BolusCommand: remove retry logic, add extra checks for final bolus.
  Command doc.
  Logging: Print filename and line instead of logger name.
  CommandException: provide message for printing.
  ConfigBuilder.applyAPSResult: log request rate.

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;
-            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;
-                    }
-                }
-            }
 
             // confirm bolus
             scripter.verifyMenuIsDisplayed(MenuType.BOLUS_ENTER);
@@ -112,6 +95,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 +107,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);
-
-            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;
-                    }
-                }
-            }
 
             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;
-                        }
-                    }
-                }
 
                 // 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) {

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()");