Merge branch 'master' into documentation

etc/test_itemized.out

@@ -1,7 +1,7 @@
 1 RESULT fail system device_config_acked STABLE 0/10 Timeout waiting for config acked
 1 RESULT fail pointset pointset_request_extraneous STABLE 0/10 Failed waiting until pointset event contains correct points
 1 RESULT fail pointset pointset_remove_point STABLE 0/10 Failed waiting until pointset state matches config
-1 RESULT fail pointset pointset_remove_point STABLE 0/10 Failed waiting until config update synchronized
+1 RESULT fail pointset pointset_remove_point STABLE 0/10 Timeout waiting for initial device state
 1 RESULT fail system too_much_state ALPHA 0/10 Failed check that No more than 6 state updates in 60s
 1 RESULT fail enumeration.features enumerate_features PREVIEW 0/10 Failed check that feature enumeration matches metadata: missing { enumeration }, extra { unknown }
 1 RESULT pass system valid_serial_no STABLE 10/10 Sequence complete
@@ -21,7 +21,7 @@
 0 RESULT pass system broken_config STABLE 10/10 Sequence complete
 1 CPBLTY skip system broken_config.logging ALPHA 0/0 Never executed
 0 CPBLTY skip system broken_config.status ALPHA 0/0 Never executed
-0 RESULT fail system broken_config STABLE 0/8 Failed waiting until config update synchronized
+0 RESULT fail system broken_config STABLE 0/8 Timeout waiting for initial device state
 1 CPBLTY fail system broken_config.status ALPHA 0/1 Failed waiting until (status) system status level is >= `WARNING` (400)
 0 CPBLTY pass system broken_config.logging ALPHA 1/1 Capability supported
 0 RESULT pass system broken_config STABLE 9/10 Sequence complete

validator/src/main/java/com/google/daq/mqtt/sequencer/SequenceBase.java

@@ -262,6 +262,7 @@ public class SequenceBase {
   private static final String NOT_MARKER = " n0t ";
   private static final String NOT_REPLACEMENT = " not ";
   private static final String NOT_MISSING = " ";
+  private static final Duration STATE_CONFIG_HOLDOFF = Duration.ofMillis(1000);
   protected static Metadata deviceMetadata;
   protected static String projectId;
   protected static String cloudRegion;
@@ -281,7 +282,7 @@ public class SequenceBase {
   private static MessageBundle stashedBundle;
   private static boolean enableAllTargets = true;
   private static boolean useAlternateClient;
-  private static boolean shouldGateConfigUpdate;
+  private static boolean skipConfigSync;
 
   static {
     // Sanity check to make sure ALPHA version is increased if forced by increased BETA.
@@ -355,7 +356,7 @@ private static void setupSequencer() {
       checkNotNull(exeConfig.udmi_version, "udmi_version not defined");
       logLevel = Level.valueOf(checkNotNull(exeConfig.log_level, "log_level not defined"))
           .value();
-      shouldGateConfigUpdate = traceLogLevel();
+      skipConfigSync = traceLogLevel();
       key_file = checkNotNull(exeConfig.key_file, "key_file not defined");
     } catch (Exception e) {
       e.printStackTrace();
@@ -1276,7 +1277,9 @@ private void updateConfig(String reason, boolean force) {
   private void updateConfig(String reason, boolean force, boolean waitForState) {
     assertConfigIsNotPending();
 
-    ifNotTrueThen(shouldGateConfigUpdate, this::rateLimitConfig);
+    ensureStateConfigHoldoff();
+
+    ifTrueThen(!skipConfigSync, this::rateLimitConfig);
 
     if (doPartialUpdates && !force) {
       updateConfig(reason, waitForState, SubFolder.SYSTEM, augmentConfig(deviceConfig.system));
@@ -1293,7 +1296,8 @@ private void updateConfig(String reason, boolean force, boolean waitForState) {
       updateConfig(reason, waitForState, UPDATE, deviceConfig);
     }
 
-    ifNotTrueThen(shouldGateConfigUpdate, () -> waitForUpdateConfigSync(reason, waitForState));
+    ifTrueThen(configIsPending() && !skipConfigSync,
+        () -> waitForUpdateConfigSync(reason, waitForState));
 
     assertConfigIsNotPending();
 
@@ -1314,7 +1318,7 @@ private boolean updateConfig(String reason, boolean waitForSync, SubFolder subBl
       trace(format("Updated check %s_%s: %s", CONFIG_SUBTYPE, subBlock, updated));
       if (updated) {
         String topic = subBlock + "/config";
-        ifTrueThen(shouldGateConfigUpdate, this::rateLimitConfig);
+        ifTrueThen(skipConfigSync, this::rateLimitConfig);
         final String transactionId =
             requireNonNull(reflector().publish(getDeviceId(), topic, actualizedData),
                 "no transactionId returned for publish");
@@ -1323,20 +1327,29 @@ private boolean updateConfig(String reason, boolean waitForSync, SubFolder subBl
         recordRawMessage(data, LOCAL_PREFIX + subBlock.value());
         sentConfig.put(subBlock, actualizedData);
         configTransactions.add(transactionId);
-        ifTrueThen(shouldGateConfigUpdate, () -> waitForUpdateConfigSync(reason, waitForSync));
+        ifTrueThen(skipConfigSync, () -> waitForUpdateConfigSync(reason, waitForSync));
       }
       return updated;
     } catch (Exception e) {
       throw new RuntimeException("While updating config block " + subBlock, e);
     }
   }
 
+  /**
+   * Ensure the update is noticeably after the last state update, for synchronization tracking.
+   */
+  private void ensureStateConfigHoldoff() {
+    configStateStart = ofNullable(catchToNull(() -> deviceState.timestamp)).orElse(new Date(0));
+    Instant syncDelayTarget = configStateStart.toInstant().plus(STATE_CONFIG_HOLDOFF);
+    long betweenMs = between(getNowInstant(), syncDelayTarget).toMillis();
+    ifTrueThen(betweenMs > 0, () -> safeSleep(betweenMs));
+  }
+
   private void waitForUpdateConfigSync(String reason, boolean waitForSync) {
     if (!waitForSync) {
       waitForConfigIsNotPending();
     } else if (configIsPending()) {
-      configStateStart = catchToNull(() -> deviceState.timestamp);
-      debug(format("Saving pre-config state timestamp " + isoConvert(configStateStart)));
+      debug(format("Using pre-config state timestamp " + isoConvert(configStateStart)));
       lastConfigUpdate = CleanDateFormat.clean(Instant.now());
       String debugReason = reason == null ? "" : (", because " + reason);
       debug(format("Update lastConfigUpdate %s%s", lastConfigUpdate, debugReason));
@@ -2131,16 +2144,16 @@ private String configIsPending(boolean debugOut) {
     Date configLastStart = catchToNull(() -> deviceConfig.system.operation.last_start);
     boolean lastStartSynced = stateLastStart == null || stateLastStart.equals(configLastStart);
 
-    Date current = catchToNull(() -> deviceState.timestamp);
-    final boolean stateUpdated =
-        !deviceSupportsState() || !dateEquals(configStateStart, current) || pretendStateUpdated;
-
     Date stateLastConfig = catchToNull(() -> deviceState.system.last_config);
 
     Date lastConfig = catchToNull(() -> deviceConfig.timestamp);
     final boolean lastConfigSynced = stateLastConfig == null || stateLastConfig.equals(lastConfig);
     final boolean transactionsClean = configTransactions.isEmpty();
 
+    Date current = catchToNull(() -> deviceState.timestamp);
+    final boolean stateUpdated = !deviceSupportsState() || !dateEquals(configStateStart, current)
+        || pretendStateUpdated || lastConfigSynced;
+
     List<String> failures = new ArrayList<>();
     ifNotTrueThen(stateUpdated, () -> failures.add("device state not updated since config issued"));
     ifNotTrueThen(lastStartSynced, () -> failures.add("last_start not synced in config"));