From e27304912f8453590570931c9f626c5d3bb84eb4 Mon Sep 17 00:00:00 2001 From: Marcin Beczynski Date: Mon, 26 Oct 2026 09:35:18 +0100 Subject: [PATCH] Restart the Drive mount after a series of EAGAIN-refused attaches 24-26 Oct 2026: after the mount wedged during a backup, every attach of the gdrive-attach agent failed with "hdiutil: attach failed - Resource temporarily unavailable" for 26 h, while rclone sat idle (queue 0) and answered about its queue. Only a restart of the Mac - a fresh rclone - let the image attach. 37 h without a backup. AttachStall counts EAGAIN refusals per boot session and, after 3 in a row spanning at least 30 min, runs MountRestart (same refusals as the button: not during a backup, not before the queue drains). At most one restart per 6 h; a refused restart (didNotRun) does not start the cooldown. hdiutil's EAGAIN is recognized once, where it runs, and carried as CMActionResult.attachTemporarilyUnavailable. Co-Authored-By: Claude Opus 5.5 --- .../CloudMachineAgent/DriveCommands.swift | 13 +- .../CloudMachineCore/AttachStall.swift | 156 ++++++++++++++++++ .../CloudMachineCore/BackupImageService.swift | 12 +- .../CloudMachineCore/CMActionResult.swift | 10 +- .../CloudMachineCore/L10nPolish+Safety.swift | 2 + .../CloudMachineCore/MountRestart.swift | 4 +- .../AttachStallTests.swift | 152 +++++++++++++++++ .../OpenRemoteControlTests.swift | 1 + 8 files changed, 346 insertions(+), 4 deletions(-) create mode 100644 mac-app/Sources/CloudMachineCore/AttachStall.swift create mode 100644 mac-app/Tests/CloudMachineAppTests/AttachStallTests.swift diff --git a/mac-app/Sources/CloudMachineAgent/DriveCommands.swift b/mac-app/Sources/CloudMachineAgent/DriveCommands.swift index cfc50f3..59f0e0d 100644 --- a/mac-app/Sources/CloudMachineAgent/DriveCommands.swift +++ b/mac-app/Sources/CloudMachineAgent/DriveCommands.swift @@ -115,9 +115,20 @@ struct AttachImage: AsyncParsableCommand { "Time Machine now has NO DESTINATION. Check: %@", "cloudmachine-agent drive-status")) throw ExitCode(1) } - let result = await BackupImageService.attach() + var result = await BackupImageService.attach() print(result.message) + // A series of EAGAINs from `hdiutil` ends in a restart of the mount - see + // `AttachStall`. Its result replaces the attach's: a restart that brought + // the image up is a success of this tick. + if let restart = await AttachStall.afterAttach(result) { + print( + L10n.tr( + "The image kept being refused - the Google Drive mount was restarted: %@", restart.message + )) + result = restart + } + // Three cases, not two. This command runs under launchd every 900 s, so // its exit code ends up as an entry in `launchd-gdrive-attach.err.log` - // the place a person looks when asking "is the backup working". "Image diff --git a/mac-app/Sources/CloudMachineCore/AttachStall.swift b/mac-app/Sources/CloudMachineCore/AttachStall.swift new file mode 100644 index 0000000..155755f --- /dev/null +++ b/mac-app/Sources/CloudMachineCore/AttachStall.swift @@ -0,0 +1,156 @@ +import Foundation + +/// The way out of an attach that `hdiutil` keeps turning away with "Resource +/// temporarily unavailable" - by restarting the Drive mount, which until now +/// only a restart of the Mac did. +/// +/// 24-26 Oct 2026: the mount wedged during a backup, and from then on every +/// attach of the `gdrive-attach` agent (every 15-20 min, 5 `hdiutil` attempts +/// each) failed with EAGAIN for 26 h. rclone was idle (queue 0, nothing in +/// use) and answered about its queue, so neither "rclone busy" nor "rclone +/// does not answer" describes it - the only signal was the series of EAGAINs. +/// After the restart of the Mac a fresh rclone let the image attach within +/// minutes. 37 h without a backup. +/// +/// The restart itself is `MountRestart` - the same path as the button in the +/// window, with all its refusals: not while Time Machine is backing up, not +/// before the queue has drained. This type only decides WHEN: +/// - a series: `minFailures` EAGAINs in a row, spanning at least +/// `minDuration`, in the same boot session - one or two refusals just after +/// a start-up are normal (26.10 08:27, a minute after rclone came up); +/// - at most one restart per `cooldown`: if a fresh rclone does not help, a +/// second one will not either, and restarting it hourly would only cut +/// the upload short. +public enum AttachStall { + + public static let minFailures = 3 + public static let minDuration: TimeInterval = 30 * 60 + public static let cooldown: TimeInterval = 6 * 3600 + + public static var recordURL: URL { + CMPaths.appSupportDir.appendingPathComponent("attach-stall") + } + + /// The series so far. `restartedAt == 0` = no restart in this boot session. + public struct Record: Equatable { + public var bootTime: TimeInterval + public var firstFailureAt: TimeInterval + public var failures: Int + public var restartedAt: TimeInterval + + public var text: String { + "\(Int(bootTime)) \(Int(firstFailureAt)) \(failures) \(Int(restartedAt))" + } + + public init( + bootTime: TimeInterval, firstFailureAt: TimeInterval, failures: Int, + restartedAt: TimeInterval + ) { + self.bootTime = bootTime + self.firstFailureAt = firstFailureAt + self.failures = failures + self.restartedAt = restartedAt + } + + public init?(text: String) { + let parts = text.split(whereSeparator: \.isWhitespace).compactMap { TimeInterval($0) } + guard parts.count == 4 else { return nil } + self.init( + bootTime: parts[0], firstFailureAt: parts[1], failures: Int(parts[2]), + restartedAt: parts[3]) + } + } + + /// A record from another boot session describes a mount that no longer + /// exists - it starts from scratch, like `ShutdownPrep.isActive`. + static func current(_ record: Record?, bootTime: TimeInterval) -> Record? { + guard let record, abs(record.bootTime - bootTime) <= 1 else { return nil } + return record + } + + /// One more EAGAIN in the series. + static func addingFailure(to record: Record?, bootTime: TimeInterval, now: TimeInterval) + -> Record + { + guard var series = current(record, bootTime: bootTime) else { + return Record(bootTime: bootTime, firstFailureAt: now, failures: 1, restartedAt: 0) + } + if series.failures == 0 { series.firstFailureAt = now } + series.failures += 1 + return series + } + + /// Any other outcome of the attach ends the series; the time of the last + /// restart stays, so the cooldown holds across a short success. + static func endingSeries(_ record: Record?, bootTime: TimeInterval, now: TimeInterval) + -> Record? + { + guard let series = current(record, bootTime: bootTime), series.restartedAt > 0 else { + return nil + } + return Record( + bootTime: bootTime, firstFailureAt: now, failures: 0, restartedAt: series.restartedAt) + } + + static func shouldRestart(_ record: Record?, bootTime: TimeInterval, now: TimeInterval) -> Bool { + guard let series = current(record, bootTime: bootTime) else { return false } + guard series.failures >= minFailures, now - series.firstFailureAt >= minDuration else { + return false + } + return series.restartedAt == 0 || now - series.restartedAt >= cooldown + } + + /// After a restart that ran (whatever its outcome) a new series starts, and + /// the cooldown with it. A refusal (`didNotRun`) touched nothing and counts + /// for nothing - the next failure asks again. + static func afterRestart(_ record: Record, restart: CMActionResult, now: TimeInterval) -> Record { + guard !restart.didNotRun else { return record } + return Record(bootTime: record.bootTime, firstFailureAt: now, failures: 0, restartedAt: now) + } + + /// What the attach agent does with the outcome of `BackupImageService.attach`. + /// The time and the restart are replaceable so the decision can be tested + /// without launchd. + static func handle( + _ attach: CMActionResult, record: Record?, bootTime: TimeInterval, now: TimeInterval, + restart: () async -> CMActionResult + ) async -> (record: Record?, restart: CMActionResult?) { + // "Busy with another operation" says nothing about the mount - the + // series neither grows nor ends. + if attach.didNotRun { return (record, nil) } + guard attach.attachTemporarilyUnavailable else { + return (endingSeries(record, bootTime: bootTime, now: now), nil) + } + let series = addingFailure(to: record, bootTime: bootTime, now: now) + guard shouldRestart(series, bootTime: bootTime, now: now) else { return (series, nil) } + let restarted = await restart() + return (afterRestart(series, restart: restarted, now: now), restarted) + } + + // MARK: - Live + + /// Called by `attach-image` after every attach. Returns the restart's + /// result when one was attempted. + public static func afterAttach(_ attach: CMActionResult) async -> CMActionResult? { + // No boot time - no way to tell this session's series from an old one. + // Doing nothing is the old behaviour, not a new risk. + guard let boot = ShutdownPrep.bootTime() else { return nil } + let stored = (try? String(contentsOf: recordURL, encoding: .utf8)).flatMap(Record.init(text:)) + let outcome = await handle( + attach, record: stored, bootTime: boot, now: Date().timeIntervalSince1970, + restart: { + CMLogger.log( + "Attach refused with EAGAIN \(minFailures)+ times over \(Int(minDuration / 60))+ min - restarting the Drive mount" + ) + let result = await MountRestart.perform() + CMLogger.log("Mount restart after the stalled attach: \(result.message)") + return result + }) + if let record = outcome.record { + try? record.text.write(to: recordURL, atomically: true, encoding: .utf8) + } else { + try? FileManager.default.removeItem(at: recordURL) + } + return outcome.restart + } +} diff --git a/mac-app/Sources/CloudMachineCore/BackupImageService.swift b/mac-app/Sources/CloudMachineCore/BackupImageService.swift index 24fe2d6..9d65be9 100644 --- a/mac-app/Sources/CloudMachineCore/BackupImageService.swift +++ b/mac-app/Sources/CloudMachineCore/BackupImageService.swift @@ -608,12 +608,22 @@ public enum BackupImageService { return CMActionResult( succeeded: false, message: L10n.tr( - "Could not attach the image: %@", result?.stderr ?? L10n.tr("unknown error"))) + "Could not attach the image: %@", result?.stderr ?? L10n.tr("unknown error")), + attachTemporarilyUnavailable: isTemporarilyUnavailable(stderr: result?.stderr ?? "")) } InstallationTraces.rememberImage() return CMActionResult(succeeded: true, message: L10n.tr("Attached: %@", targetPath.path)) } + /// `hdiutil attach` turned away with EAGAIN. On 25-26 Oct 2026 every attach + /// ended like this for 26 h, with rclone idle (queue 0) and answering; only + /// a fresh rclone - a restart of the Mac - let the image attach. The text is + /// `strerror(EAGAIN)`, which `hdiutil` prints in English whatever the system + /// language. + static func isTemporarilyUnavailable(stderr: String) -> Bool { + stderr.contains("Resource temporarily unavailable") + } + /// Detaches the image and WAITS until everything has reached Google Drive. /// /// The wait is not extra caution. The detach itself writes APFS metadata to diff --git a/mac-app/Sources/CloudMachineCore/CMActionResult.swift b/mac-app/Sources/CloudMachineCore/CMActionResult.swift index 2d5ce6a..1607d41 100644 --- a/mac-app/Sources/CloudMachineCore/CMActionResult.swift +++ b/mac-app/Sources/CloudMachineCore/CMActionResult.swift @@ -22,13 +22,21 @@ public struct CMActionResult { /// silently - meaning nobody notices until something fails. public var didNotRun: Bool + /// `true` if `hdiutil attach` was turned away with "Resource temporarily + /// unavailable" on every attempt - the failure that the mount restart in + /// `AttachStall` answers. Recognized once, where `hdiutil` runs, so callers + /// do not match on `message`. + public var attachTemporarilyUnavailable: Bool + public init( - succeeded: Bool, message: String, isSudoAuthFailure: Bool = false, didNotRun: Bool = false + succeeded: Bool, message: String, isSudoAuthFailure: Bool = false, didNotRun: Bool = false, + attachTemporarilyUnavailable: Bool = false ) { self.succeeded = succeeded self.message = message self.isSudoAuthFailure = isSudoAuthFailure self.didNotRun = didNotRun + self.attachTemporarilyUnavailable = attachTemporarilyUnavailable } /// What the caller should do with this result - in particular, which exit diff --git a/mac-app/Sources/CloudMachineCore/L10nPolish+Safety.swift b/mac-app/Sources/CloudMachineCore/L10nPolish+Safety.swift index 1ff9078..b840486 100644 --- a/mac-app/Sources/CloudMachineCore/L10nPolish+Safety.swift +++ b/mac-app/Sources/CloudMachineCore/L10nPolish+Safety.swift @@ -79,6 +79,8 @@ extension L10nPolish { "Montowanie zostało zatrzymane, ale nie wróciło na czas na prywatnym gnieździe. Agenci dalej próbują (backup-health przeładowuje agenta, którego launchd nie potrafi uruchomić). Sprawdź: cloudmachine-agent drive-status; jeśli dalej nie działa, zrestartuj Maca.", "The mount runs on the private socket now, but the image did not attach: %@ The attach agent retries every 15 minutes.": "Montowanie działa już na prywatnym gnieździe, ale obraz się nie podłączył: %@ Agent podłączania próbuje co 15 minut.", + "The image kept being refused - the Google Drive mount was restarted: %@": + "Obraz był wciąż odrzucany - montowanie Dysku Google zostało zrestartowane: %@", "CloudMachine: Drive remote control is open": "CloudMachine: sterowanie Dyskiem jest otwarte", "Any web page can send it commands, including deleting the backup. Open CloudMachine and restart the mount, or run prepare-shutdown and restart the Mac.": diff --git a/mac-app/Sources/CloudMachineCore/MountRestart.swift b/mac-app/Sources/CloudMachineCore/MountRestart.swift index 48b70b7..9d7e645 100644 --- a/mac-app/Sources/CloudMachineCore/MountRestart.swift +++ b/mac-app/Sources/CloudMachineCore/MountRestart.swift @@ -64,7 +64,9 @@ public enum MountRestart { static func run(_ steps: Steps) async -> CMActionResult { if let reason = refusal(backupRunning: await steps.backupRunning(), mounted: steps.mounted()) { - return CMActionResult(succeeded: false, message: reason) + // `didNotRun`: nothing was touched, so `AttachStall` does not count a + // refusal as the restart its cooldown waits after. + return CMActionResult(succeeded: false, message: reason, didNotRun: true) } let drained = await steps.detachAndDrain() diff --git a/mac-app/Tests/CloudMachineAppTests/AttachStallTests.swift b/mac-app/Tests/CloudMachineAppTests/AttachStallTests.swift new file mode 100644 index 0000000..14f88b0 --- /dev/null +++ b/mac-app/Tests/CloudMachineAppTests/AttachStallTests.swift @@ -0,0 +1,152 @@ +import XCTest + +@testable import CloudMachineCore + +/// When a series of refused attaches ends in a restart of the mount - and +/// when it must not. +final class AttachStallTests: XCTestCase { + + private let boot: TimeInterval = 1_792_999_292 + private let start: TimeInterval = 1_793_000_000 + /// The attach agent's tick. + private let tick: TimeInterval = 15 * 60 + + private let refused = CMActionResult( + succeeded: false, + message: + "Could not attach the image: hdiutil: attach failed - Resource temporarily unavailable", + attachTemporarilyUnavailable: true) + private let attached = CMActionResult(succeeded: true, message: "Attached") + + private final class Restarts: @unchecked Sendable { + var count = 0 + } + + /// Runs the attach outcomes one tick apart, carrying the record along. + private func ticks( + _ outcomes: [CMActionResult], from record: AttachStall.Record? = nil, + restartResult: CMActionResult = CMActionResult(succeeded: true, message: "restarted") + ) async -> (record: AttachStall.Record?, restarts: Int) { + let restarts = Restarts() + var record = record + for (i, outcome) in outcomes.enumerated() { + record = await AttachStall.handle( + outcome, record: record, bootTime: boot, now: start + Double(i) * tick, + restart: { + restarts.count += 1 + return restartResult + } + ).record + } + return (record, restarts.count) + } + + func testRecognizesTheHdiutilRefusal() { + XCTAssertTrue( + BackupImageService.isTemporarilyUnavailable( + stderr: + "hdiutil: WARNING: 'hdiutil attach -nobrowse -mountpoint ...' is deprecated.\nhdiutil: attach failed - Resource temporarily unavailable\n" + )) + XCTAssertFalse( + BackupImageService.isTemporarilyUnavailable( + stderr: "hdiutil: attach failed - RPC version wrong")) + } + + /// KNOWN BAD SAMPLE, 25-26 Oct 2026: every attach refused for 26 h, and + /// nothing but a restart of the Mac helped. Three ticks (30 min) are enough. + func testASeriesOfRefusalsRestartsTheMount() async { + let result = await ticks([refused, refused]) + XCTAssertEqual(result.restarts, 0) + let third = await ticks([refused, refused, refused]) + XCTAssertEqual(third.restarts, 1) + } + + /// Refusals just after a start-up are normal (26.10 08:27) - three of them + /// in quick succession are not yet a series. + func testThreeQuickRefusalsAreNotASeries() async { + let quick = AttachStall.addingFailure( + to: AttachStall.addingFailure( + to: AttachStall.addingFailure(to: nil, bootTime: boot, now: start), bootTime: boot, + now: start + 60), bootTime: boot, now: start + 120) + XCTAssertEqual(quick.failures, 3) + XCTAssertFalse(AttachStall.shouldRestart(quick, bootTime: boot, now: start + 120)) + } + + /// A success between the refusals ends the series. + func testASuccessEndsTheSeries() async { + let result = await ticks([refused, refused, attached, refused, refused]) + XCTAssertEqual(result.restarts, 0) + } + + /// Other failures (the buffer not ready, an orphaned mount point) are not + /// what a fresh rclone fixes. + func testOtherFailuresEndTheSeries() async { + let other = CMActionResult(succeeded: false, message: "Drive is not mounted.") + let result = await ticks([refused, refused, other, refused, refused]) + XCTAssertEqual(result.restarts, 0) + } + + /// "Busy with another operation" says nothing about the mount: it neither + /// ends the series nor adds to it. + func testBusyNeitherEndsNorExtendsTheSeries() async { + let busy = CMActionResult(succeeded: false, message: "busy", didNotRun: true) + let result = await ticks([refused, busy, refused, busy, refused]) + XCTAssertEqual(result.restarts, 1) + XCTAssertEqual(result.record?.failures, 0) + } + + /// If a fresh rclone did not help, another one within the cooldown will + /// not either - and every restart cuts the upload short. + func testAtMostOneRestartPerCooldown() async { + let hours = Int(AttachStall.cooldown / tick) + let result = await ticks(Array(repeating: refused, count: hours - 1)) + XCTAssertEqual(result.restarts, 1) + let longer = await ticks(Array(repeating: refused, count: hours + 3)) + XCTAssertEqual(longer.restarts, 2) + } + + /// The cooldown holds across a short success, or restarts would follow + /// every flap. + func testCooldownSurvivesASuccess() async { + let result = await ticks([refused, refused, refused, attached, refused, refused, refused]) + XCTAssertEqual(result.restarts, 1) + } + + /// A refusal of the restart (Time Machine backing up, tmutil silent) + /// touched nothing - the next refused attach asks again, no cooldown. + func testRefusedRestartDoesNotStartTheCooldown() async { + let refusedRestart = CMActionResult(succeeded: false, message: "backing up", didNotRun: true) + let result = await ticks( + [refused, refused, refused, refused], restartResult: refusedRestart) + XCTAssertEqual(result.restarts, 2) + XCTAssertEqual(result.record?.restartedAt, 0) + } + + /// A restart that ran and failed (the queue did not drain) still starts the + /// cooldown: running the same drain every tick would not change its answer. + func testFailedRestartStartsTheCooldown() async { + let failed = CMActionResult(succeeded: false, message: "not drained") + let result = await ticks( + [refused, refused, refused, refused, refused, refused, refused], + restartResult: failed) + XCTAssertEqual(result.restarts, 1) + } + + /// A record from before a restart of the Mac describes a mount that is gone. + func testARecordFromAnotherBootIsIgnored() async { + let old = AttachStall.Record( + bootTime: boot - 86_400, firstFailureAt: start - 7200, failures: 9, restartedAt: start - 600) + let result = await ticks([refused], from: old) + XCTAssertEqual(result.restarts, 0) + XCTAssertEqual(result.record?.failures, 1) + XCTAssertEqual(result.record?.restartedAt, 0) + } + + func testRecordTextRoundTrips() { + let record = AttachStall.Record( + bootTime: boot, firstFailureAt: start, failures: 4, restartedAt: start + 900) + XCTAssertEqual(AttachStall.Record(text: record.text), record) + XCTAssertNil(AttachStall.Record(text: "garbage")) + XCTAssertNil(AttachStall.Record(text: "1 2 3")) + } +} diff --git a/mac-app/Tests/CloudMachineAppTests/OpenRemoteControlTests.swift b/mac-app/Tests/CloudMachineAppTests/OpenRemoteControlTests.swift index 756be90..4655408 100644 --- a/mac-app/Tests/CloudMachineAppTests/OpenRemoteControlTests.swift +++ b/mac-app/Tests/CloudMachineAppTests/OpenRemoteControlTests.swift @@ -184,6 +184,7 @@ final class OpenRemoteControlTests: XCTestCase { let calls = Calls() let result = await MountRestart.run(steps(calls, backupRunning: running)) XCTAssertFalse(result.succeeded) + XCTAssertTrue(result.didNotRun, "a refusal touched nothing - AttachStall must not count it") XCTAssertEqual(calls.log, []) } let calls = Calls()