Skip to content

Commit 0434abd

Browse files
mbeczynskiclaude
andcommitted
fix(vm-guard): decide on the unsent backlog (vfs/queue), not the cache size
27.10.2026 12:24 the guard paused the first full backup at 116 GiB and never resumed it: it read diskCache.bytesUsed, the whole cache on disk, which keeps uploaded bands for reading until --vfs-cache-max-size and does not fall when the upload catches up. At 12:37 the real backlog was 30 GiB (966 bands in vfs/queue) with the cache still at 116. The reading now also carries the sum of vfs/queue sizes; pause and resume use it, and a missing queue answer counts as unknown (do nothing), never as zero. vm-status shows both numbers. Regression test with the 27.10 values. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
1 parent bd9e758 commit 0434abd

6 files changed

Lines changed: 97 additions & 17 deletions

File tree

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

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -154,8 +154,8 @@ extension L10nPolish {
154154
"nieznany",
155155
"Unpacking the image failed: %@":
156156
"Rozpakowanie obrazu nie powiodło się: %@",
157-
"Upload buffer: %@ GiB, queued %@, uploading %@":
158-
"Bufor wysyłki: %@ GiB, w kolejce %@, wysyłane %@",
157+
"Still to upload: %@ GiB in %@ bands, uploading %@ (cache on disk %@ GiB)":
158+
"Do wysłania: %@ GiB w %@ pasmach, wysyłane %@ (cache na dysku %@ GiB)",
159159
"Upload buffer: no answer from rclone (rc %@)":
160160
"Bufor wysyłki: brak odpowiedzi rclone (rc %@)",
161161
"When Time Machine has created its empty image, stop the backup (tmutil stopbackup) and run: cloudmachine-agent vm-prepare-bundle":

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

Lines changed: 9 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -4,7 +4,8 @@ import Foundation
44
/// than rclone uploads to Google Drive (750 GB a day at most), and the buffer
55
/// is the machine's 200 GB disk. One `step()` per launchd run (every 60 s).
66
///
7-
/// Pause when the buffer holds more than `highGiB` or the disk has less than
7+
/// Pause when more than `highGiB` is still to upload (`unsentBytes` - not the
8+
/// cache size, see `VMLayout.BufferStats`) or the disk has less than
89
/// `minFreeGiB` free. Resume below `lowGiB` - and ONLY if this guard paused
910
/// the backup (the marker file); a backup the person stopped stays stopped.
1011
/// No answer from the machine or from tmutil means: do nothing.
@@ -42,8 +43,10 @@ public struct VMGuard: Sendable {
4243
reading: VMLayout.Reading?, backupRunning: Bool?, pausedByGuard: Bool,
4344
thresholds: Thresholds
4445
) -> Action {
45-
guard let reading else { return .nothing }
46-
let usedGiB = reading.buffer.bytesUsed / gib
46+
// No queue = unknown backlog: the cache size would stand in for it, and
47+
// it is exactly the number that kept the backup paused on 27.10.
48+
guard let reading, let unsent = reading.buffer.unsentBytes else { return .nothing }
49+
let usedGiB = unsent / gib
4750
let freeGiB = reading.freeBytes / gib
4851
if usedGiB > Int64(thresholds.highGiB) || freeGiB < Int64(thresholds.minFreeGiB) {
4952
return backupRunning == true ? .pause : .nothing
@@ -109,14 +112,14 @@ public struct VMGuard: Sendable {
109112
let paused = probes.markerExists()
110113
let action = Self.decide(
111114
reading: reading, backupRunning: running, pausedByGuard: paused, thresholds: thresholds)
112-
let used = reading.buffer.bytesUsed / Self.gib
115+
let used = (reading.buffer.unsentBytes ?? -1) / Self.gib
113116
let free = reading.freeBytes / Self.gib
114117
let queued = reading.buffer.uploadsQueued
115118
switch action {
116119
case .pause:
117120
if await probes.tmutil("stopbackup") {
118121
probes.setMarker(true)
119-
probes.log("VM guard: PAUSE - buffer \(used) GiB, queue \(queued), free \(free) GiB")
122+
probes.log("VM guard: PAUSE - unsent \(used) GiB, queue \(queued), free \(free) GiB")
120123
} else {
121124
probes.log("VM guard: tmutil stopbackup FAILED - buffer \(used) GiB, free \(free) GiB")
122125
}
@@ -126,7 +129,7 @@ public struct VMGuard: Sendable {
126129
// for good with nobody left to resume it.
127130
if await probes.tmutil("startbackup") {
128131
probes.setMarker(false)
129-
probes.log("VM guard: RESUME - buffer \(used) GiB, free \(free) GiB")
132+
probes.log("VM guard: RESUME - unsent \(used) GiB, free \(free) GiB")
130133
} else {
131134
probes.log("VM guard: tmutil startbackup FAILED - will try again on the next run")
132135
}

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

Lines changed: 37 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -165,11 +165,38 @@ public enum VMLayout {
165165
return nil
166166
}
167167

168-
/// What rclone's `vfs/stats` says about the upload buffer.
168+
/// What rclone says about the upload buffer.
169+
///
170+
/// `bytesUsed` is the whole cache on disk, uploaded bands included: rclone
171+
/// keeps them for reading until the cache reaches `--vfs-cache-max-size`.
172+
/// It does NOT fall when the upload catches up - on 27.10.2026 it stayed at
173+
/// 116 GiB for 13 minutes while the real backlog was 30 GiB, and a guard
174+
/// deciding on it never resumed the backup. Decisions use `unsentBytes`,
175+
/// the sum of `vfs/queue`.
169176
public struct BufferStats: Equatable, Sendable {
170177
public var bytesUsed: Int64
171178
public var uploadsQueued: Int
172179
public var uploadsInProgress: Int
180+
/// Bytes still to upload; `nil` = `vfs/queue` did not answer.
181+
public var unsentBytes: Int64?
182+
183+
public init(
184+
bytesUsed: Int64, uploadsQueued: Int, uploadsInProgress: Int, unsentBytes: Int64? = nil
185+
) {
186+
self.bytesUsed = bytesUsed
187+
self.uploadsQueued = uploadsQueued
188+
self.uploadsInProgress = uploadsInProgress
189+
self.unsentBytes = unsentBytes
190+
}
191+
}
192+
193+
/// Sum of the item sizes in `vfs/queue`; `nil` when it is not that JSON.
194+
static func unsentBytes(vfsQueueJSON: String) -> Int64? {
195+
guard let data = vfsQueueJSON.data(using: .utf8),
196+
let object = try? JSONSerialization.jsonObject(with: data) as? [String: Any],
197+
let queue = object["queue"] as? [[String: Any]]
198+
else { return nil }
199+
return queue.reduce(Int64(0)) { $0 + ((($1["size"] as? NSNumber)?.int64Value) ?? 0) }
173200
}
174201

175202
static func bufferStats(vfsStatsJSON: String) -> BufferStats? {
@@ -191,23 +218,29 @@ public enum VMLayout {
191218
public var freeBytes: Int64
192219
}
193220

194-
/// The script prints `vfs/stats` JSON on one line, then `CMFREE <bytes>`.
221+
/// The script prints `vfs/stats` JSON on one line, `CMQUEUE <vfs/queue JSON>`
222+
/// on the next, then `CMFREE <bytes>`.
195223
static let readingScript =
196224
"curl -s -m 20 -X POST http://\(Guest.rcAddress)/vfs/stats | tr -d '\\n'; echo; "
225+
+ "printf 'CMQUEUE '; curl -s -m 20 -X POST http://\(Guest.rcAddress)/vfs/queue | tr -d '\\n'; echo; "
197226
+ "echo CMFREE $(df -B1 --output=avail \(Guest.cacheDir) | tail -1 | tr -dc 0-9)"
198227

199228
/// `nil` unless BOTH parts are there: half an answer is no answer.
200229
static func reading(scriptOutput: String) -> Reading? {
201230
var stats: BufferStats?
202231
var free: Int64?
232+
var unsent: Int64?
203233
for line in scriptOutput.split(separator: "\n") {
204-
if line.hasPrefix("CMFREE ") {
234+
if line.hasPrefix("CMQUEUE ") {
235+
unsent = unsentBytes(vfsQueueJSON: String(line.dropFirst("CMQUEUE ".count)))
236+
} else if line.hasPrefix("CMFREE ") {
205237
free = Int64(line.dropFirst("CMFREE ".count).trimmingCharacters(in: .whitespaces))
206238
} else if line.hasPrefix("{") {
207239
stats = bufferStats(vfsStatsJSON: String(line))
208240
}
209241
}
210-
guard let stats, let free else { return nil }
242+
guard var stats, let free else { return nil }
243+
stats.unsentBytes = unsent
211244
return Reading(buffer: stats, freeBytes: free)
212245
}
213246

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

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -100,9 +100,10 @@ public enum VMStatus {
100100
if let reading = report.reading {
101101
out.append(
102102
L10n.tr(
103-
"Upload buffer: %@ GiB, queued %@, uploading %@",
104-
"\(reading.buffer.bytesUsed / VMGuard.gib)", "\(reading.buffer.uploadsQueued)",
105-
"\(reading.buffer.uploadsInProgress)"))
103+
"Still to upload: %@ GiB in %@ bands, uploading %@ (cache on disk %@ GiB)",
104+
reading.buffer.unsentBytes.map { "\($0 / VMGuard.gib)" } ?? "?",
105+
"\(reading.buffer.uploadsQueued)", "\(reading.buffer.uploadsInProgress)",
106+
"\(reading.buffer.bytesUsed / VMGuard.gib)"))
106107
out.append(L10n.tr("Free in machine: %@ GiB", "\(reading.freeBytes / VMGuard.gib)"))
107108
} else {
108109
out.append(

‎mac-app/Tests/CloudMachineAppTests/VMGuardDecisionTests.swift‎

Lines changed: 33 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -13,12 +13,43 @@ final class VMGuardDecisionTests: XCTestCase {
1313
private let thresholds = VMGuard.Thresholds()
1414
private let gib: Int64 = 1 << 30
1515

16-
private func reading(usedGiB: Int64, freeGiB: Int64 = 150, queued: Int = 3) -> VMLayout.Reading {
16+
/// `usedGiB` is what is still to upload; the cache on disk is bigger on
17+
/// purpose (116 GiB, as on 27.10) so no rule can lean on it by accident.
18+
private func reading(
19+
usedGiB: Int64, freeGiB: Int64 = 150, queued: Int = 3, cacheGiB: Int64 = 116
20+
) -> VMLayout.Reading {
1721
VMLayout.Reading(
18-
buffer: .init(bytesUsed: usedGiB * gib, uploadsQueued: queued, uploadsInProgress: 1),
22+
buffer: .init(
23+
bytesUsed: cacheGiB * gib, uploadsQueued: queued, uploadsInProgress: 1,
24+
unsentBytes: usedGiB * gib),
1925
freeBytes: freeGiB * gib)
2026
}
2127

28+
/// 27.10.2026 12:24-12:37: paused at 116 GiB of cache, then the backlog fell
29+
/// to 30 GiB while the cache stayed at 116 - the guard deciding on the
30+
/// cache never resumed. The backlog is what counts.
31+
func testResumesOnTheBacklogWhileTheCacheStaysFull() {
32+
XCTAssertEqual(
33+
VMGuard.decide(
34+
reading: reading(usedGiB: 30, cacheGiB: 116), backupRunning: false, pausedByGuard: true,
35+
thresholds: thresholds), .resume)
36+
XCTAssertEqual(
37+
VMGuard.decide(
38+
reading: reading(usedGiB: 30, cacheGiB: 116), backupRunning: true, pausedByGuard: false,
39+
thresholds: thresholds), .nothing, "a full cache alone must not pause")
40+
}
41+
42+
func testUnknownBacklogDoesNothing() {
43+
var r = reading(usedGiB: 0)
44+
r.buffer.unsentBytes = nil
45+
for paused in [false, true] {
46+
XCTAssertEqual(
47+
VMGuard.decide(
48+
reading: r, backupRunning: true, pausedByGuard: paused, thresholds: thresholds),
49+
.nothing)
50+
}
51+
}
52+
2253
// MARK: - The decision
2354

2455
func testDefaultsAreTheOnesTheFirstBackupRanWith() {

‎mac-app/Tests/CloudMachineAppTests/VMLayoutTests.swift‎

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -200,4 +200,16 @@ final class VMLayoutTests: XCTestCase {
200200
XCTAssertFalse(VMStatus.targets(urls: urls, address: "192.168.64.11"))
201201
XCTAssertFalse(VMStatus.targets(urls: [], address: "192.168.64.10"))
202202
}
203+
204+
func testReadingCarriesTheUnsentBacklogFromVfsQueue() {
205+
let stats = #"{"diskCache":{"bytesUsed":124554051584,"uploadsQueued":2,"uploadsInProgress":1}}"#
206+
let queue = #"{"queue":[{"name":"bands/a","size":33554432},{"name":"bands/b","size":1048576}]}"#
207+
let r = VMLayout.reading(scriptOutput: "\(stats)\nCMQUEUE \(queue)\nCMFREE 1\n")
208+
XCTAssertEqual(r?.buffer.unsentBytes, 33_554_432 + 1_048_576)
209+
XCTAssertEqual(r?.buffer.bytesUsed, 124_554_051_584)
210+
let noQueue = VMLayout.reading(scriptOutput: "\(stats)\nCMQUEUE \nCMFREE 1\n")
211+
XCTAssertNotNil(noQueue, "stats and free space still make a reading")
212+
XCTAssertNil(noQueue?.buffer.unsentBytes, "an empty queue answer is unknown, not zero")
213+
XCTAssertEqual(VMLayout.unsentBytes(vfsQueueJSON: #"{"queue":[]}"#), 0)
214+
}
203215
}

0 commit comments

Comments
 (0)