|
| 1 | +// SPDX-License-Identifier: Apache-2.0 |
| 2 | +package com.hedera.services.bdd.spec.utilops.streams; |
| 3 | + |
| 4 | +import static com.hedera.services.bdd.spec.transactions.TxnUtils.doIfNotInterrupted; |
| 5 | +import static java.util.Objects.requireNonNull; |
| 6 | +import static java.util.concurrent.TimeUnit.MILLISECONDS; |
| 7 | + |
| 8 | +import com.hedera.services.bdd.junit.hedera.ExternalPath; |
| 9 | +import com.hedera.services.bdd.junit.hedera.NodeSelector; |
| 10 | +import com.hedera.services.bdd.spec.HapiSpec; |
| 11 | +import com.hedera.services.bdd.spec.utilops.UtilOp; |
| 12 | +import edu.umd.cs.findbugs.annotations.NonNull; |
| 13 | +import java.io.BufferedReader; |
| 14 | +import java.nio.file.Files; |
| 15 | +import java.nio.file.NoSuchFileException; |
| 16 | +import java.time.Duration; |
| 17 | +import java.time.Instant; |
| 18 | +import java.time.LocalDateTime; |
| 19 | +import java.time.ZoneId; |
| 20 | +import java.time.format.DateTimeFormatter; |
| 21 | +import java.util.concurrent.atomic.AtomicLong; |
| 22 | +import java.util.function.Supplier; |
| 23 | +import org.apache.logging.log4j.LogManager; |
| 24 | +import org.apache.logging.log4j.Logger; |
| 25 | +import org.junit.jupiter.api.Assertions; |
| 26 | + |
| 27 | +/** |
| 28 | + * A {@link UtilOp} that validates that a node's log contains two patterns appearing in order |
| 29 | + * within a specified timeframe, with a time gap between them that falls within {@code [minGap, maxGap]}. |
| 30 | + * |
| 31 | + * <p>This is useful for asserting that a state transition (e.g. quiescence) lasted a meaningful |
| 32 | + * duration, distinguishing real transitions from transient flickers that resolve in milliseconds. |
| 33 | + */ |
| 34 | +public class LogContainmentPairTimeframeOp extends UtilOp { |
| 35 | + private static final Logger log = LogManager.getLogger(LogContainmentPairTimeframeOp.class); |
| 36 | + private static final DateTimeFormatter LOG_TIMESTAMP_FORMAT = |
| 37 | + DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss.SSS"); |
| 38 | + |
| 39 | + private final NodeSelector selector; |
| 40 | + private final ExternalPath path; |
| 41 | + private final String firstPattern; |
| 42 | + private final String secondPattern; |
| 43 | + private final Supplier<Instant> startTimeSupplier; |
| 44 | + private final Duration timeframe; |
| 45 | + private final Duration waitTimeout; |
| 46 | + private final Duration minGap; |
| 47 | + private final Duration maxGap; |
| 48 | + |
| 49 | + // State for incremental reading |
| 50 | + private final AtomicLong linesProcessed = new AtomicLong(0L); |
| 51 | + // Persists across polls so a firstPattern match on one poll can pair with a secondPattern on the next |
| 52 | + private Instant candidateFirstTime = null; |
| 53 | + |
| 54 | + public LogContainmentPairTimeframeOp( |
| 55 | + @NonNull final NodeSelector selector, |
| 56 | + @NonNull final ExternalPath path, |
| 57 | + @NonNull final Supplier<Instant> startTimeSupplier, |
| 58 | + @NonNull final Duration timeframe, |
| 59 | + @NonNull final Duration waitTimeout, |
| 60 | + @NonNull final String firstPattern, |
| 61 | + @NonNull final String secondPattern, |
| 62 | + @NonNull final Duration minGap, |
| 63 | + @NonNull final Duration maxGap) { |
| 64 | + if (path != ExternalPath.APPLICATION_LOG |
| 65 | + && path != ExternalPath.BLOCK_NODE_COMMS_LOG |
| 66 | + && path != ExternalPath.SWIRLDS_LOG) { |
| 67 | + throw new IllegalArgumentException(path + " is not a log"); |
| 68 | + } |
| 69 | + this.path = requireNonNull(path); |
| 70 | + this.selector = requireNonNull(selector); |
| 71 | + this.startTimeSupplier = requireNonNull(startTimeSupplier); |
| 72 | + this.timeframe = requireNonNull(timeframe); |
| 73 | + this.waitTimeout = requireNonNull(waitTimeout); |
| 74 | + this.firstPattern = requireNonNull(firstPattern); |
| 75 | + this.secondPattern = requireNonNull(secondPattern); |
| 76 | + this.minGap = requireNonNull(minGap); |
| 77 | + this.maxGap = requireNonNull(maxGap); |
| 78 | + if (minGap.compareTo(maxGap) > 0) { |
| 79 | + throw new IllegalArgumentException("minGap (" + minGap + ") must be <= maxGap (" + maxGap + ")"); |
| 80 | + } |
| 81 | + } |
| 82 | + |
| 83 | + @Override |
| 84 | + protected boolean submitOp(@NonNull final HapiSpec spec) throws Throwable { |
| 85 | + final Instant startTime = startTimeSupplier.get(); |
| 86 | + if (startTime == null) { |
| 87 | + throw new IllegalStateException("Start time supplier returned null"); |
| 88 | + } |
| 89 | + final Instant endTime = startTime.plus(timeframe); |
| 90 | + final Instant timeoutDeadline = Instant.now().plus(waitTimeout); |
| 91 | + |
| 92 | + log.info( |
| 93 | + "Starting paired log check: StartTime={}, Timeframe={}, Timeout={}, " |
| 94 | + + "FirstPattern='{}', SecondPattern='{}', MinGap={}, MaxGap={}", |
| 95 | + startTime, |
| 96 | + timeframe, |
| 97 | + waitTimeout, |
| 98 | + firstPattern, |
| 99 | + secondPattern, |
| 100 | + minGap, |
| 101 | + maxGap); |
| 102 | + |
| 103 | + while (Instant.now().isBefore(timeoutDeadline)) { |
| 104 | + final var result = new SearchResult(); |
| 105 | + spec.targetNetworkOrThrow().nodesFor(selector).forEach(node -> { |
| 106 | + searchNodeLog(node.getExternalPath(path), startTime, endTime, result); |
| 107 | + }); |
| 108 | + |
| 109 | + if (result.matched) { |
| 110 | + log.info( |
| 111 | + "Found matching pair: '{}' at {} and '{}' at {} (gap={})", |
| 112 | + firstPattern, |
| 113 | + result.firstTime, |
| 114 | + secondPattern, |
| 115 | + result.secondTime, |
| 116 | + Duration.between(result.firstTime, result.secondTime)); |
| 117 | + return false; // Success |
| 118 | + } |
| 119 | + |
| 120 | + if (Instant.now().isBefore(timeoutDeadline)) { |
| 121 | + doIfNotInterrupted(() -> MILLISECONDS.sleep(1000)); |
| 122 | + } |
| 123 | + } |
| 124 | + |
| 125 | + Assertions.fail(String.format( |
| 126 | + "Did not find a matching pair of log patterns within the timeframe. " |
| 127 | + + "StartTime=%s, Timeframe=%s, Timeout=%s, FirstPattern='%s', SecondPattern='%s', " |
| 128 | + + "MinGap=%s, MaxGap=%s", |
| 129 | + startTime, timeframe, waitTimeout, firstPattern, secondPattern, minGap, maxGap)); |
| 130 | + |
| 131 | + return false; |
| 132 | + } |
| 133 | + |
| 134 | + private void searchNodeLog( |
| 135 | + @NonNull final java.nio.file.Path logPath, |
| 136 | + @NonNull final Instant startTime, |
| 137 | + @NonNull final Instant endTime, |
| 138 | + @NonNull final SearchResult result) { |
| 139 | + if (result.matched) { |
| 140 | + return; |
| 141 | + } |
| 142 | + long newLinesRead = 0; |
| 143 | + try (BufferedReader reader = Files.newBufferedReader(logPath)) { |
| 144 | + try (var linesStream = reader.lines().skip(linesProcessed.get())) { |
| 145 | + final var iterator = linesStream.iterator(); |
| 146 | + while (iterator.hasNext()) { |
| 147 | + final String line = iterator.next(); |
| 148 | + newLinesRead++; |
| 149 | + |
| 150 | + final Instant logInstant; |
| 151 | + try { |
| 152 | + if (line.length() < 23) continue; |
| 153 | + final String timestamp = line.substring(0, 23); |
| 154 | + final LocalDateTime logTime = LocalDateTime.parse(timestamp, LOG_TIMESTAMP_FORMAT); |
| 155 | + logInstant = logTime.atZone(ZoneId.systemDefault()).toInstant(); |
| 156 | + } catch (Exception e) { |
| 157 | + continue; |
| 158 | + } |
| 159 | + |
| 160 | + if (!logInstant.isAfter(startTime) || !logInstant.isBefore(endTime)) { |
| 161 | + continue; |
| 162 | + } |
| 163 | + |
| 164 | + // Check for firstPattern — always update candidate to the latest match |
| 165 | + if (line.contains(firstPattern)) { |
| 166 | + candidateFirstTime = logInstant; |
| 167 | + } |
| 168 | + // Check for secondPattern only if we have a candidate firstPattern |
| 169 | + if (candidateFirstTime != null && line.contains(secondPattern)) { |
| 170 | + final Duration gap = Duration.between(candidateFirstTime, logInstant); |
| 171 | + if (gap.compareTo(minGap) >= 0 && gap.compareTo(maxGap) <= 0) { |
| 172 | + result.matched = true; |
| 173 | + result.firstTime = candidateFirstTime; |
| 174 | + result.secondTime = logInstant; |
| 175 | + break; |
| 176 | + } |
| 177 | + // Gap didn't qualify — reset candidate so we look for the next pair |
| 178 | + candidateFirstTime = null; |
| 179 | + } |
| 180 | + } |
| 181 | + } |
| 182 | + } catch (NoSuchFileException nsfe) { |
| 183 | + log.warn("Log file not found: {}. Will retry.", logPath); |
| 184 | + } catch (Exception e) { |
| 185 | + log.error("Error reading log file {}", logPath, e); |
| 186 | + throw new RuntimeException("Error during log processing for " + logPath, e); |
| 187 | + } |
| 188 | + linesProcessed.addAndGet(newLinesRead); |
| 189 | + } |
| 190 | + |
| 191 | + /** Mutable holder for the search result across nodes. */ |
| 192 | + private static class SearchResult { |
| 193 | + boolean matched; |
| 194 | + Instant firstTime; |
| 195 | + Instant secondTime; |
| 196 | + } |
| 197 | +} |
0 commit comments