From 4d72783bc4f89f77a6a76dea0577940a4921650d Mon Sep 17 00:00:00 2001 From: Trevor Date: Thu, 19 Dec 2024 09:36:46 -0800 Subject: [PATCH] Fix flaky tests due to incorrect logging check delay (#1054) --- bin/container | 4 -- etc/schema_itemized.out | 4 +- .../daq/mqtt/sequencer/SequenceBase.java | 39 ++++++++++--------- 3 files changed, 21 insertions(+), 26 deletions(-) diff --git a/bin/container b/bin/container index 1906391b17..779833b0cb 100755 --- a/bin/container +++ b/bin/container @@ -119,10 +119,6 @@ if [[ -n $build ]]; then echo Building Dockerfile.$target echo docker build -f Dockerfile.$target -t $udmi_ref . docker build -f Dockerfile.$target -t $udmi_ref -t $target . - - echo Cleaning dangling images... - images=$(docker images -f "dangling=true" -q) - [[ -n $images ]] && docker rmi $images fi if [[ -n $push ]]; then diff --git a/etc/schema_itemized.out b/etc/schema_itemized.out index 343320e28d..cdc7cef61e 100644 --- a/etc/schema_itemized.out +++ b/etc/schema_itemized.out @@ -13,9 +13,7 @@ 1 writeback_success 1 writeback_success 1 pointset_publish_interval -1 system_min_loglevel RESULT pass schemas device_state_alpha ALPHA 10/10 Schema validation passed -0 system_min_loglevel RESULT pass schemas events_system_alpha ALPHA 10/10 Schema validation passed -0 system_min_loglevel RESULT pass schemas state_update_alpha ALPHA 10/10 Schema validation passed +1 system_min_loglevel 1 system_mode_restart 1 config_logging 1 broken_config RESULT fail schemas device_state_stable STABLE 10/10 Schema violations found diff --git a/validator/src/main/java/com/google/daq/mqtt/sequencer/SequenceBase.java b/validator/src/main/java/com/google/daq/mqtt/sequencer/SequenceBase.java index 8874d6278d..ac33c1de4d 100644 --- a/validator/src/main/java/com/google/daq/mqtt/sequencer/SequenceBase.java +++ b/validator/src/main/java/com/google/daq/mqtt/sequencer/SequenceBase.java @@ -241,7 +241,7 @@ public class SequenceBase { private static final ObjectDiffEngine RECV_STATE_DIFFERNATOR = new ObjectDiffEngine(); private static final Set configTransactions = new ConcurrentSkipListSet<>(); private static final AtomicReference stateTransaction = new AtomicReference<>(); - private static final int MINIMUM_TEST_SEC = 15; + private static final Duration MINIMUM_TEST_TIME = Duration.ofSeconds(15); private static final Date RESET_LAST_START = new Date(73642); private static final Date stateCutoffThreshold = Date.from(Instant.now()); private static final String FAKE_DEVICE_ID = "TAP-1"; @@ -312,7 +312,7 @@ public class SequenceBase { private int maxAllowedStatusLevel; private String extraField; private String updatedExtraField; - private Instant lastConfigUpdate; + private Instant lastConfigIssued; private boolean enforceSerial; private String testName; private String testSummary; @@ -340,7 +340,7 @@ public class SequenceBase { private Date configStateStart; protected boolean pretendStateUpdated; private Boolean stateSupported; - private Instant lastConfigMark = getNowInstant(); + private Instant lastConfigApplied = getNowInstant(); private static void setupSequencer() { exeConfig = ofNullable(exeConfig).orElseGet(SequenceRunner::ensureExecutionConfig); @@ -920,7 +920,7 @@ private void waitForConfigSync() { processNextMessage(); return configIsPending(false); }); - Duration between = between(lastConfigUpdate, CleanDateFormat.clean(Instant.now())); + Duration between = between(lastConfigIssued, CleanDateFormat.clean(Instant.now())); debug(format("Config sync took %ss", between.getSeconds())); } finally { waitingForConfigSync.set(false); @@ -965,7 +965,7 @@ private void recordResult(SequenceResult result, Description description, String private void recordSchemaValidations(Description description) { // Ensure that enough time has passed to capture event messages for schema validation. - info(format("waiting %ds for more messages...", waitTimeRemainingSec())); + info(format("Waiting %ds for more messages...", waitTimeRemainingSec())); whileDoing("minimum test time", () -> messageEvaluateLoop(() -> waitTimeRemainingSec() > 0)); validationResults.entrySet().stream() @@ -1302,8 +1302,8 @@ private void updateConfig(String reason, boolean force, boolean waitForState) { assertConfigIsNotPending(); // Rate-limit from the point the config was _applied_, not when it was _sent_. - lastConfigMark = getNowInstant(); - debug(format("New lastConfigMark at %s", isoConvert(lastConfigMark))); + lastConfigApplied = getNowInstant(); + debug(format("New lastConfigApplied at %s", isoConvert(lastConfigApplied))); captureConfigChange(reason); } @@ -1350,17 +1350,18 @@ private void waitForUpdateConfigSync(String reason, boolean waitForSync) { waitForConfigIsNotPending(); } else if (configIsPending()) { debug(format("Using pre-config state timestamp " + isoConvert(configStateStart))); - lastConfigUpdate = CleanDateFormat.clean(Instant.now()); + lastConfigIssued = CleanDateFormat.clean(Instant.now()); String debugReason = reason == null ? "" : (", because " + reason); - debug(format("Update lastConfigUpdate %s%s", lastConfigUpdate, debugReason)); + debug(format("Update lastConfigIssued %s%s", lastConfigIssued, debugReason)); waitForConfigSync(); } } private void rateLimitConfig() { // Add a forced sleep to make sure configs aren't sent too quickly - long delayMs = CONFIG_BARRIER.toMillis() - between(lastConfigMark, getNowInstant()).toMillis(); - debug(format("Delay from lastConfigMark %s is %sms", lastConfigMark, delayMs)); + long delayMs = + CONFIG_BARRIER.toMillis() - between(lastConfigApplied, getNowInstant()).toMillis(); + debug(format("Delay from lastConfigApplied %s is %sms", lastConfigApplied, delayMs)); ifTrueThen(delayMs > 0, () -> { debug(format("Rate-limiting config by %dms", delayMs)); safeSleep(delayMs); @@ -1602,7 +1603,7 @@ protected void checkWasNotLogged(String category, Level minLevel) { ifTrueThen(deviceSupportsState(), () -> waitUntil("last_config synchronized", this::lastConfigUpdated)); }); - final Instant endTime = lastConfigUpdate.plusSeconds(LOG_TIMEOUT_SEC); + final Instant endTime = lastConfigApplied.plusSeconds(LOG_TIMEOUT_SEC); if (endTime.isAfter(getNowInstant())) { debug(format("Waiting until %s for logs to arrive...", isoConvert(endTime))); } @@ -1614,7 +1615,7 @@ protected void checkWasNotLogged(String category, Level minLevel) { format("log level `%s` (or greater) category `%s` was not logged", minLevel, category), () -> { if (!entries.isEmpty()) { - warning(format("Filtered entries between %s and %s:", isoConvert(lastConfigUpdate), + warning(format("Filtered entries between %s and %s:", isoConvert(lastConfigApplied), isoConvert(endTime))); entries.forEach(entry -> error("Forbidden entry: " + entryMessage(entry))); } @@ -1637,9 +1638,9 @@ private void processLogMessages() { logEntryQueue.addAll(ofNullable(systemEvent.logentries).orElse(ImmutableList.of())); }); List toRemove = logEntryQueue.stream() - .filter(entry -> entry.timestamp.toInstant().isBefore(lastConfigUpdate)).toList(); + .filter(entry -> entry.timestamp.toInstant().isBefore(lastConfigIssued)).toList(); if (!toRemove.isEmpty()) { - debug("Flushing log entries before lastConfigUpdate " + lastConfigUpdate); + debug("Flushing log entries before lastConfigIssued " + lastConfigIssued); } toRemove.forEach(entry -> debug("Flushing entry: " + entryMessage(entry))); logEntryQueue.removeAll(toRemove); @@ -1770,7 +1771,8 @@ private void recordBullet(String step) { } private long waitTimeRemainingSec() { - return Math.max(0, MINIMUM_TEST_SEC - (System.currentTimeMillis() - startCaptureTime) / 1000); + return Math.max(0, + MINIMUM_TEST_TIME.toMillis() - (System.currentTimeMillis() - startCaptureTime)) / 1000; } private String timeSinceStart() { @@ -2670,8 +2672,7 @@ protected void starting(@NotNull Description description) { startCaptureTime = 0; startTestTimeMs = System.currentTimeMillis(); - notice("starting test " + testName + " " + START_END_MARKER); - + notice("Starting test " + testName + " " + START_END_MARKER); } catch (IllegalArgumentException e) { putSequencerResult(description, ERRR); recordCompletion(ERRR, description, friendlyStackTrace(e)); @@ -2697,7 +2698,7 @@ protected void finished(Description description) { ifTrueThen(testResult == PASS && shouldValidateSchema(SubFolder.VALIDATION), () -> recordSchemaValidations(description)); - notice("ending test " + testName + " after " + timeSinceStart() + " " + START_END_MARKER); + notice("Ending test " + testName + " after " + timeSinceStart() + " " + START_END_MARKER); testName = null; if (deviceConfig != null) { deviceConfig.system.testing = null;