Track preflight and postflight test timeouts

Sources/Runner/PreflightPostflightTimeoutTrackingTestRunnerStream.swift

@@ -0,0 +1,128 @@
+import AtomicModels
+import DateProvider
+import Foundation
+import Logging
+import RunnerModels
+import Timer
+
+/// Tracks hangs that happen before starting any tests. or after fninishing any test, including in between test invocations.
+public final class PreflightPostflightTimeoutTrackingTestRunnerStream: TestRunnerStream {
+    private let dateProvider: DateProvider
+    private let onPreflightTimeout: () -> ()
+    private let onPostflightTimeout: (TestName) -> ()
+    private let lastEventInfo = AtomicValue<LastEventInfo?>(nil)
+    private let maximumPreflightDuration: TimeInterval
+    private let maximumPostflightDuration: TimeInterval
+    private let pollPeriod: DispatchTimeInterval
+    private var trackingTimer: DispatchBasedTimer?
+
+    struct LastEventInfo {
+        let finishedTestName: TestName?
+        let timestamp: Date
+    }
+
+    public init(
+        dateProvider: DateProvider,
+        onPreflightTimeout: @escaping () -> (),
+        onPostflightTimeout: @escaping (TestName) -> (),
+        maximumPreflightDuration: TimeInterval,
+        maximumPostflightDuration: TimeInterval,
+        pollPeriod: DispatchTimeInterval
+    ) {
+        self.dateProvider = dateProvider
+        self.onPreflightTimeout = onPreflightTimeout
+        self.onPostflightTimeout = onPostflightTimeout
+        self.maximumPreflightDuration = maximumPreflightDuration
+        self.maximumPostflightDuration = maximumPostflightDuration
+        self.pollPeriod = pollPeriod
+    }
+
+    public func openStream() {
+        lastEventInfo.set(
+            LastEventInfo(
+                finishedTestName: nil,
+                timestamp: dateProvider.currentDate()
+            )
+        )
+        startPreflightTimeoutTracking()
+    }
+
+    public func testStarted(testName: TestName) {
+        stopAnyTracking()
+    }
+
+    public func caughtException(testException: TestException) {}
+
+    public func testStopped(testStoppedEvent: TestStoppedEvent) {
+        lastEventInfo.set(
+            LastEventInfo(
+                finishedTestName: testStoppedEvent.testName,
+                timestamp: dateProvider.currentDate()
+            )
+        )
+        startPostflightTimeoutTracking()
+    }
+
+    public func closeStream() {
+        lastEventInfo.set(nil)
+        stopAnyTracking()
+    }
+
+    private func startPreflightTimeoutTracking() {
+        startMonitoringForHangs()
+    }
+
+    private func startPostflightTimeoutTracking() {
+        startMonitoringForHangs()
+    }
+
+    private func stopAnyTracking() {
+        stopMonitoringForHangs()
+    }
+
+    // MARK: - Logic
+
+    private func startMonitoringForHangs() {
+        trackingTimer = DispatchBasedTimer.startedTimer(
+            repeating: pollPeriod,
+            leeway: pollPeriod,
+            handler: { [weak self] timer in
+                guard let strongSelf = self else { return timer.stop() }
+                strongSelf.processTimerFireEvent()
+            }
+        )
+    }
+
+    private func stopMonitoringForHangs() {
+        trackingTimer?.stop()
+        trackingTimer = nil
+    }
+
+    private func processTimerFireEvent() {
+        guard let eventInfo = lastEventInfo.currentValue() else {
+            return stopAnyTracking()
+        }
+
+        if let lastFinishedTestName = eventInfo.finishedTestName {
+            // some tests finished - postflight
+            validatePostflightTimeout(since: eventInfo.timestamp, testName: lastFinishedTestName)
+        } else {
+            // no tests finished yet - preflight
+            validatePreflightTimeout(since: eventInfo.timestamp)
+        }
+    }
+
+    private func validatePreflightTimeout(since date: Date) {
+        if dateProvider.currentDate().timeIntervalSince(date) > maximumPostflightDuration {
+            stopAnyTracking()
+            onPreflightTimeout()
+        }
+    }
+
+    private func validatePostflightTimeout(since date: Date, testName: TestName) {
+        if dateProvider.currentDate().timeIntervalSince(date) > maximumPostflightDuration {
+            stopAnyTracking()
+            onPostflightTimeout(testName)
+        }
+    }
+}

Sources/Runner/Runner.swift

@@ -230,6 +230,20 @@ public final class Runner {
                         streamClosedCallback.set(result: ())
                     }
                 ),
+                PreflightPostflightTimeoutTrackingTestRunnerStream(
+                    dateProvider: dateProvider,
+                    onPreflightTimeout: {
+                        Logger.debug("Detected preflight timeout", testRunnerRunningInvocationContainer.currentValue()?.subprocessInfo)
+                        testRunnerRunningInvocationContainer.currentValue()?.cancel()
+                    },
+                    onPostflightTimeout: { testName in
+                        Logger.debug("Detected postflight timeout, last finished test was \(testName)", testRunnerRunningInvocationContainer.currentValue()?.subprocessInfo)
+                        testRunnerRunningInvocationContainer.currentValue()?.cancel()
+                    },
+                    maximumPreflightDuration: configuration.testTimeoutConfiguration.testRunnerMaximumSilenceDuration,
+                    maximumPostflightDuration: configuration.testTimeoutConfiguration.testRunnerMaximumSilenceDuration,
+                    pollPeriod: testTimeoutCheckInterval
+                )
             ]
         )
 

Tests/RunnerTests/PreflightPostflightTimeoutTrackingTestRunnerStreamTests.swift

@@ -0,0 +1,120 @@
+import DateProviderTestHelpers
+import Foundation
+import Runner
+import RunnerModels
+import XCTest
+
+final class PreflightPostflightTimeoutTrackingTestRunnerStreamTests: XCTestCase {
+    lazy var dateProvider = DateProviderFixture(Date(timeIntervalSince1970: 100))
+    lazy var preflightExpectation = XCTestExpectation(description: "preflight callback called")
+    lazy var postflightExpectation = XCTestExpectation(description: "postflight callback called")
+
+    lazy var testStream = PreflightPostflightTimeoutTrackingTestRunnerStream(
+        dateProvider: dateProvider,
+        onPreflightTimeout: { [weak self] in self?.preflightExpectation.fulfill() },
+        onPostflightTimeout: { [weak self] _ in self?.postflightExpectation.fulfill() },
+        maximumPreflightDuration: 5.0,
+        maximumPostflightDuration: 0.01,
+        pollPeriod: .milliseconds(1)
+    )
+
+    func test___preflight_is_called___when_stream_opens_and_test_does_not_start() {
+        postflightExpectation.isInverted = true
+
+        testStream.openStream()
+        dateProvider.result += 5
+
+        wait(for: [preflightExpectation, postflightExpectation], timeout: 5)
+    }
+
+    func test___preflight_is_not_called___when_stream_opens_and_test_starts() {
+        preflightExpectation.isInverted = true
+        postflightExpectation.isInverted = true
+
+        testStream.openStream()
+        testStream.testStarted(testName: TestName(className: "class", methodName: "test"))
+        dateProvider.result += 5
+
+        wait(for: [preflightExpectation, postflightExpectation], timeout: 5)
+    }
+
+    func test___preflight_is_not_called___when_stream_closes() {
+        preflightExpectation.isInverted = true
+        postflightExpectation.isInverted = true
+
+        testStream.openStream()
+        testStream.closeStream()
+        dateProvider.result += 5
+
+        wait(for: [preflightExpectation, postflightExpectation], timeout: 5)
+    }
+
+    func test___postflight_is_called___when_test_finished_but_next_does_not_start() {
+        preflightExpectation.isInverted = true
+
+        testStream.openStream()
+        testStream.testStarted(
+            testName: TestName(className: "class", methodName: "test1")
+        )
+        testStream.testStopped(
+            testStoppedEvent: TestStoppedEvent(
+                testName: TestName(className: "class", methodName: "test1"),
+                result: .success,
+                testDuration: 1,
+                testExceptions: [],
+                testStartTimestamp: dateProvider.currentDate().timeIntervalSince1970)
+        )
+
+        dateProvider.result += 5
+
+        wait(for: [preflightExpectation, postflightExpectation], timeout: 5)
+    }
+
+    func test___postflight_is_not_called___when_test_finished_and_next_starts() {
+        preflightExpectation.isInverted = true
+        postflightExpectation.isInverted = true
+
+        testStream.openStream()
+        testStream.testStarted(
+            testName: TestName(className: "class", methodName: "test1")
+        )
+        testStream.testStopped(
+            testStoppedEvent: TestStoppedEvent(
+                testName: TestName(className: "class", methodName: "test1"),
+                result: .success,
+                testDuration: 1,
+                testExceptions: [],
+                testStartTimestamp: dateProvider.currentDate().timeIntervalSince1970)
+        )
+        testStream.testStarted(
+            testName: TestName(className: "class", methodName: "test2")
+        )
+
+        dateProvider.result += 5
+
+        wait(for: [preflightExpectation, postflightExpectation], timeout: 5)
+    }
+
+    func test___postflight_is_not_called___when_test_finished_stream_closed() {
+        preflightExpectation.isInverted = true
+        postflightExpectation.isInverted = true
+
+        testStream.openStream()
+        testStream.testStarted(
+            testName: TestName(className: "class", methodName: "test1")
+        )
+        testStream.testStopped(
+            testStoppedEvent: TestStoppedEvent(
+                testName: TestName(className: "class", methodName: "test1"),
+                result: .success,
+                testDuration: 1,
+                testExceptions: [],
+                testStartTimestamp: dateProvider.currentDate().timeIntervalSince1970)
+        )
+        testStream.closeStream()
+
+        dateProvider.result += 5
+
+        wait(for: [preflightExpectation, postflightExpectation], timeout: 5)
+    }
+}