Skip to content

Commit df488bd

Browse files
authored
Merge pull request #28 from RenaCode/fix/restart-mountu-po-serii-eagain
Restart montowania po serii odmów EAGAIN przy podpinaniu obrazu
2 parents fbfd52d + e273049 commit df488bd

8 files changed

Lines changed: 346 additions & 4 deletions

File tree

‎mac-app/Sources/CloudMachineAgent/DriveCommands.swift‎

Lines changed: 12 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -115,9 +115,20 @@ struct AttachImage: AsyncParsableCommand {
115115
"Time Machine now has NO DESTINATION. Check: %@", "cloudmachine-agent drive-status"))
116116
throw ExitCode(1)
117117
}
118-
let result = await BackupImageService.attach()
118+
var result = await BackupImageService.attach()
119119
print(result.message)
120120

121+
// A series of EAGAINs from `hdiutil` ends in a restart of the mount - see
122+
// `AttachStall`. Its result replaces the attach's: a restart that brought
123+
// the image up is a success of this tick.
124+
if let restart = await AttachStall.afterAttach(result) {
125+
print(
126+
L10n.tr(
127+
"The image kept being refused - the Google Drive mount was restarted: %@", restart.message
128+
))
129+
result = restart
130+
}
131+
121132
// Three cases, not two. This command runs under launchd every 900 s, so
122133
// its exit code ends up as an entry in `launchd-gdrive-attach.err.log` -
123134
// the place a person looks when asking "is the backup working". "Image
Lines changed: 156 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,156 @@
1+
import Foundation
2+
3+
/// The way out of an attach that `hdiutil` keeps turning away with "Resource
4+
/// temporarily unavailable" - by restarting the Drive mount, which until now
5+
/// only a restart of the Mac did.
6+
///
7+
/// 24-26 Oct 2026: the mount wedged during a backup, and from then on every
8+
/// attach of the `gdrive-attach` agent (every 15-20 min, 5 `hdiutil` attempts
9+
/// each) failed with EAGAIN for 26 h. rclone was idle (queue 0, nothing in
10+
/// use) and answered about its queue, so neither "rclone busy" nor "rclone
11+
/// does not answer" describes it - the only signal was the series of EAGAINs.
12+
/// After the restart of the Mac a fresh rclone let the image attach within
13+
/// minutes. 37 h without a backup.
14+
///
15+
/// The restart itself is `MountRestart` - the same path as the button in the
16+
/// window, with all its refusals: not while Time Machine is backing up, not
17+
/// before the queue has drained. This type only decides WHEN:
18+
/// - a series: `minFailures` EAGAINs in a row, spanning at least
19+
/// `minDuration`, in the same boot session - one or two refusals just after
20+
/// a start-up are normal (26.10 08:27, a minute after rclone came up);
21+
/// - at most one restart per `cooldown`: if a fresh rclone does not help, a
22+
/// second one will not either, and restarting it hourly would only cut
23+
/// the upload short.
24+
public enum AttachStall {
25+
26+
public static let minFailures = 3
27+
public static let minDuration: TimeInterval = 30 * 60
28+
public static let cooldown: TimeInterval = 6 * 3600
29+
30+
public static var recordURL: URL {
31+
CMPaths.appSupportDir.appendingPathComponent("attach-stall")
32+
}
33+
34+
/// The series so far. `restartedAt == 0` = no restart in this boot session.
35+
public struct Record: Equatable {
36+
public var bootTime: TimeInterval
37+
public var firstFailureAt: TimeInterval
38+
public var failures: Int
39+
public var restartedAt: TimeInterval
40+
41+
public var text: String {
42+
"\(Int(bootTime)) \(Int(firstFailureAt)) \(failures) \(Int(restartedAt))"
43+
}
44+
45+
public init(
46+
bootTime: TimeInterval, firstFailureAt: TimeInterval, failures: Int,
47+
restartedAt: TimeInterval
48+
) {
49+
self.bootTime = bootTime
50+
self.firstFailureAt = firstFailureAt
51+
self.failures = failures
52+
self.restartedAt = restartedAt
53+
}
54+
55+
public init?(text: String) {
56+
let parts = text.split(whereSeparator: \.isWhitespace).compactMap { TimeInterval($0) }
57+
guard parts.count == 4 else { return nil }
58+
self.init(
59+
bootTime: parts[0], firstFailureAt: parts[1], failures: Int(parts[2]),
60+
restartedAt: parts[3])
61+
}
62+
}
63+
64+
/// A record from another boot session describes a mount that no longer
65+
/// exists - it starts from scratch, like `ShutdownPrep.isActive`.
66+
static func current(_ record: Record?, bootTime: TimeInterval) -> Record? {
67+
guard let record, abs(record.bootTime - bootTime) <= 1 else { return nil }
68+
return record
69+
}
70+
71+
/// One more EAGAIN in the series.
72+
static func addingFailure(to record: Record?, bootTime: TimeInterval, now: TimeInterval)
73+
-> Record
74+
{
75+
guard var series = current(record, bootTime: bootTime) else {
76+
return Record(bootTime: bootTime, firstFailureAt: now, failures: 1, restartedAt: 0)
77+
}
78+
if series.failures == 0 { series.firstFailureAt = now }
79+
series.failures += 1
80+
return series
81+
}
82+
83+
/// Any other outcome of the attach ends the series; the time of the last
84+
/// restart stays, so the cooldown holds across a short success.
85+
static func endingSeries(_ record: Record?, bootTime: TimeInterval, now: TimeInterval)
86+
-> Record?
87+
{
88+
guard let series = current(record, bootTime: bootTime), series.restartedAt > 0 else {
89+
return nil
90+
}
91+
return Record(
92+
bootTime: bootTime, firstFailureAt: now, failures: 0, restartedAt: series.restartedAt)
93+
}
94+
95+
static func shouldRestart(_ record: Record?, bootTime: TimeInterval, now: TimeInterval) -> Bool {
96+
guard let series = current(record, bootTime: bootTime) else { return false }
97+
guard series.failures >= minFailures, now - series.firstFailureAt >= minDuration else {
98+
return false
99+
}
100+
return series.restartedAt == 0 || now - series.restartedAt >= cooldown
101+
}
102+
103+
/// After a restart that ran (whatever its outcome) a new series starts, and
104+
/// the cooldown with it. A refusal (`didNotRun`) touched nothing and counts
105+
/// for nothing - the next failure asks again.
106+
static func afterRestart(_ record: Record, restart: CMActionResult, now: TimeInterval) -> Record {
107+
guard !restart.didNotRun else { return record }
108+
return Record(bootTime: record.bootTime, firstFailureAt: now, failures: 0, restartedAt: now)
109+
}
110+
111+
/// What the attach agent does with the outcome of `BackupImageService.attach`.
112+
/// The time and the restart are replaceable so the decision can be tested
113+
/// without launchd.
114+
static func handle(
115+
_ attach: CMActionResult, record: Record?, bootTime: TimeInterval, now: TimeInterval,
116+
restart: () async -> CMActionResult
117+
) async -> (record: Record?, restart: CMActionResult?) {
118+
// "Busy with another operation" says nothing about the mount - the
119+
// series neither grows nor ends.
120+
if attach.didNotRun { return (record, nil) }
121+
guard attach.attachTemporarilyUnavailable else {
122+
return (endingSeries(record, bootTime: bootTime, now: now), nil)
123+
}
124+
let series = addingFailure(to: record, bootTime: bootTime, now: now)
125+
guard shouldRestart(series, bootTime: bootTime, now: now) else { return (series, nil) }
126+
let restarted = await restart()
127+
return (afterRestart(series, restart: restarted, now: now), restarted)
128+
}
129+
130+
// MARK: - Live
131+
132+
/// Called by `attach-image` after every attach. Returns the restart's
133+
/// result when one was attempted.
134+
public static func afterAttach(_ attach: CMActionResult) async -> CMActionResult? {
135+
// No boot time - no way to tell this session's series from an old one.
136+
// Doing nothing is the old behaviour, not a new risk.
137+
guard let boot = ShutdownPrep.bootTime() else { return nil }
138+
let stored = (try? String(contentsOf: recordURL, encoding: .utf8)).flatMap(Record.init(text:))
139+
let outcome = await handle(
140+
attach, record: stored, bootTime: boot, now: Date().timeIntervalSince1970,
141+
restart: {
142+
CMLogger.log(
143+
"Attach refused with EAGAIN \(minFailures)+ times over \(Int(minDuration / 60))+ min - restarting the Drive mount"
144+
)
145+
let result = await MountRestart.perform()
146+
CMLogger.log("Mount restart after the stalled attach: \(result.message)")
147+
return result
148+
})
149+
if let record = outcome.record {
150+
try? record.text.write(to: recordURL, atomically: true, encoding: .utf8)
151+
} else {
152+
try? FileManager.default.removeItem(at: recordURL)
153+
}
154+
return outcome.restart
155+
}
156+
}

‎mac-app/Sources/CloudMachineCore/BackupImageService.swift‎

Lines changed: 11 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -608,12 +608,22 @@ public enum BackupImageService {
608608
return CMActionResult(
609609
succeeded: false,
610610
message: L10n.tr(
611-
"Could not attach the image: %@", result?.stderr ?? L10n.tr("unknown error")))
611+
"Could not attach the image: %@", result?.stderr ?? L10n.tr("unknown error")),
612+
attachTemporarilyUnavailable: isTemporarilyUnavailable(stderr: result?.stderr ?? ""))
612613
}
613614
InstallationTraces.rememberImage()
614615
return CMActionResult(succeeded: true, message: L10n.tr("Attached: %@", targetPath.path))
615616
}
616617

618+
/// `hdiutil attach` turned away with EAGAIN. On 25-26 Oct 2026 every attach
619+
/// ended like this for 26 h, with rclone idle (queue 0) and answering; only
620+
/// a fresh rclone - a restart of the Mac - let the image attach. The text is
621+
/// `strerror(EAGAIN)`, which `hdiutil` prints in English whatever the system
622+
/// language.
623+
static func isTemporarilyUnavailable(stderr: String) -> Bool {
624+
stderr.contains("Resource temporarily unavailable")
625+
}
626+
617627
/// Detaches the image and WAITS until everything has reached Google Drive.
618628
///
619629
/// The wait is not extra caution. The detach itself writes APFS metadata to

‎mac-app/Sources/CloudMachineCore/CMActionResult.swift‎

Lines changed: 9 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -22,13 +22,21 @@ public struct CMActionResult {
2222
/// silently - meaning nobody notices until something fails.
2323
public var didNotRun: Bool
2424

25+
/// `true` if `hdiutil attach` was turned away with "Resource temporarily
26+
/// unavailable" on every attempt - the failure that the mount restart in
27+
/// `AttachStall` answers. Recognized once, where `hdiutil` runs, so callers
28+
/// do not match on `message`.
29+
public var attachTemporarilyUnavailable: Bool
30+
2531
public init(
26-
succeeded: Bool, message: String, isSudoAuthFailure: Bool = false, didNotRun: Bool = false
32+
succeeded: Bool, message: String, isSudoAuthFailure: Bool = false, didNotRun: Bool = false,
33+
attachTemporarilyUnavailable: Bool = false
2734
) {
2835
self.succeeded = succeeded
2936
self.message = message
3037
self.isSudoAuthFailure = isSudoAuthFailure
3138
self.didNotRun = didNotRun
39+
self.attachTemporarilyUnavailable = attachTemporarilyUnavailable
3240
}
3341

3442
/// What the caller should do with this result - in particular, which exit

‎mac-app/Sources/CloudMachineCore/L10nPolish+Safety.swift‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -79,6 +79,8 @@ extension L10nPolish {
7979
"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.",
8080
"The mount runs on the private socket now, but the image did not attach: %@ The attach agent retries every 15 minutes.":
8181
"Montowanie działa już na prywatnym gnieździe, ale obraz się nie podłączył: %@ Agent podłączania próbuje co 15 minut.",
82+
"The image kept being refused - the Google Drive mount was restarted: %@":
83+
"Obraz był wciąż odrzucany - montowanie Dysku Google zostało zrestartowane: %@",
8284
"CloudMachine: Drive remote control is open":
8385
"CloudMachine: sterowanie Dyskiem jest otwarte",
8486
"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.":

‎mac-app/Sources/CloudMachineCore/MountRestart.swift‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -64,7 +64,9 @@ public enum MountRestart {
6464

6565
static func run(_ steps: Steps) async -> CMActionResult {
6666
if let reason = refusal(backupRunning: await steps.backupRunning(), mounted: steps.mounted()) {
67-
return CMActionResult(succeeded: false, message: reason)
67+
// `didNotRun`: nothing was touched, so `AttachStall` does not count a
68+
// refusal as the restart its cooldown waits after.
69+
return CMActionResult(succeeded: false, message: reason, didNotRun: true)
6870
}
6971

7072
let drained = await steps.detachAndDrain()
Lines changed: 152 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,152 @@
1+
import XCTest
2+
3+
@testable import CloudMachineCore
4+
5+
/// When a series of refused attaches ends in a restart of the mount - and
6+
/// when it must not.
7+
final class AttachStallTests: XCTestCase {
8+
9+
private let boot: TimeInterval = 1_792_999_292
10+
private let start: TimeInterval = 1_793_000_000
11+
/// The attach agent's tick.
12+
private let tick: TimeInterval = 15 * 60
13+
14+
private let refused = CMActionResult(
15+
succeeded: false,
16+
message:
17+
"Could not attach the image: hdiutil: attach failed - Resource temporarily unavailable",
18+
attachTemporarilyUnavailable: true)
19+
private let attached = CMActionResult(succeeded: true, message: "Attached")
20+
21+
private final class Restarts: @unchecked Sendable {
22+
var count = 0
23+
}
24+
25+
/// Runs the attach outcomes one tick apart, carrying the record along.
26+
private func ticks(
27+
_ outcomes: [CMActionResult], from record: AttachStall.Record? = nil,
28+
restartResult: CMActionResult = CMActionResult(succeeded: true, message: "restarted")
29+
) async -> (record: AttachStall.Record?, restarts: Int) {
30+
let restarts = Restarts()
31+
var record = record
32+
for (i, outcome) in outcomes.enumerated() {
33+
record = await AttachStall.handle(
34+
outcome, record: record, bootTime: boot, now: start + Double(i) * tick,
35+
restart: {
36+
restarts.count += 1
37+
return restartResult
38+
}
39+
).record
40+
}
41+
return (record, restarts.count)
42+
}
43+
44+
func testRecognizesTheHdiutilRefusal() {
45+
XCTAssertTrue(
46+
BackupImageService.isTemporarilyUnavailable(
47+
stderr:
48+
"hdiutil: WARNING: 'hdiutil attach -nobrowse -mountpoint ...' is deprecated.\nhdiutil: attach failed - Resource temporarily unavailable\n"
49+
))
50+
XCTAssertFalse(
51+
BackupImageService.isTemporarilyUnavailable(
52+
stderr: "hdiutil: attach failed - RPC version wrong"))
53+
}
54+
55+
/// KNOWN BAD SAMPLE, 25-26 Oct 2026: every attach refused for 26 h, and
56+
/// nothing but a restart of the Mac helped. Three ticks (30 min) are enough.
57+
func testASeriesOfRefusalsRestartsTheMount() async {
58+
let result = await ticks([refused, refused])
59+
XCTAssertEqual(result.restarts, 0)
60+
let third = await ticks([refused, refused, refused])
61+
XCTAssertEqual(third.restarts, 1)
62+
}
63+
64+
/// Refusals just after a start-up are normal (26.10 08:27) - three of them
65+
/// in quick succession are not yet a series.
66+
func testThreeQuickRefusalsAreNotASeries() async {
67+
let quick = AttachStall.addingFailure(
68+
to: AttachStall.addingFailure(
69+
to: AttachStall.addingFailure(to: nil, bootTime: boot, now: start), bootTime: boot,
70+
now: start + 60), bootTime: boot, now: start + 120)
71+
XCTAssertEqual(quick.failures, 3)
72+
XCTAssertFalse(AttachStall.shouldRestart(quick, bootTime: boot, now: start + 120))
73+
}
74+
75+
/// A success between the refusals ends the series.
76+
func testASuccessEndsTheSeries() async {
77+
let result = await ticks([refused, refused, attached, refused, refused])
78+
XCTAssertEqual(result.restarts, 0)
79+
}
80+
81+
/// Other failures (the buffer not ready, an orphaned mount point) are not
82+
/// what a fresh rclone fixes.
83+
func testOtherFailuresEndTheSeries() async {
84+
let other = CMActionResult(succeeded: false, message: "Drive is not mounted.")
85+
let result = await ticks([refused, refused, other, refused, refused])
86+
XCTAssertEqual(result.restarts, 0)
87+
}
88+
89+
/// "Busy with another operation" says nothing about the mount: it neither
90+
/// ends the series nor adds to it.
91+
func testBusyNeitherEndsNorExtendsTheSeries() async {
92+
let busy = CMActionResult(succeeded: false, message: "busy", didNotRun: true)
93+
let result = await ticks([refused, busy, refused, busy, refused])
94+
XCTAssertEqual(result.restarts, 1)
95+
XCTAssertEqual(result.record?.failures, 0)
96+
}
97+
98+
/// If a fresh rclone did not help, another one within the cooldown will
99+
/// not either - and every restart cuts the upload short.
100+
func testAtMostOneRestartPerCooldown() async {
101+
let hours = Int(AttachStall.cooldown / tick)
102+
let result = await ticks(Array(repeating: refused, count: hours - 1))
103+
XCTAssertEqual(result.restarts, 1)
104+
let longer = await ticks(Array(repeating: refused, count: hours + 3))
105+
XCTAssertEqual(longer.restarts, 2)
106+
}
107+
108+
/// The cooldown holds across a short success, or restarts would follow
109+
/// every flap.
110+
func testCooldownSurvivesASuccess() async {
111+
let result = await ticks([refused, refused, refused, attached, refused, refused, refused])
112+
XCTAssertEqual(result.restarts, 1)
113+
}
114+
115+
/// A refusal of the restart (Time Machine backing up, tmutil silent)
116+
/// touched nothing - the next refused attach asks again, no cooldown.
117+
func testRefusedRestartDoesNotStartTheCooldown() async {
118+
let refusedRestart = CMActionResult(succeeded: false, message: "backing up", didNotRun: true)
119+
let result = await ticks(
120+
[refused, refused, refused, refused], restartResult: refusedRestart)
121+
XCTAssertEqual(result.restarts, 2)
122+
XCTAssertEqual(result.record?.restartedAt, 0)
123+
}
124+
125+
/// A restart that ran and failed (the queue did not drain) still starts the
126+
/// cooldown: running the same drain every tick would not change its answer.
127+
func testFailedRestartStartsTheCooldown() async {
128+
let failed = CMActionResult(succeeded: false, message: "not drained")
129+
let result = await ticks(
130+
[refused, refused, refused, refused, refused, refused, refused],
131+
restartResult: failed)
132+
XCTAssertEqual(result.restarts, 1)
133+
}
134+
135+
/// A record from before a restart of the Mac describes a mount that is gone.
136+
func testARecordFromAnotherBootIsIgnored() async {
137+
let old = AttachStall.Record(
138+
bootTime: boot - 86_400, firstFailureAt: start - 7200, failures: 9, restartedAt: start - 600)
139+
let result = await ticks([refused], from: old)
140+
XCTAssertEqual(result.restarts, 0)
141+
XCTAssertEqual(result.record?.failures, 1)
142+
XCTAssertEqual(result.record?.restartedAt, 0)
143+
}
144+
145+
func testRecordTextRoundTrips() {
146+
let record = AttachStall.Record(
147+
bootTime: boot, firstFailureAt: start, failures: 4, restartedAt: start + 900)
148+
XCTAssertEqual(AttachStall.Record(text: record.text), record)
149+
XCTAssertNil(AttachStall.Record(text: "garbage"))
150+
XCTAssertNil(AttachStall.Record(text: "1 2 3"))
151+
}
152+
}

0 commit comments

Comments
 (0)