Nat! bio photo

Nat!

Senior Mull.

Twitter RSS

Github

Observing the stupid at work

Watch how TimeMachine's backupd performs its only task, backing up stuff, like an utter moron. Kindly witness the timestamps...

I massaged the log output heavily for readability.

14:35:30 backupd: Node requires deep traversal:/Volumes/Source reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
14:42:55 backupd: Node requires deep traversal:/Volumes/Installer reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
14:43:07 backupd: Node requires deep traversal:/Volumes/Users reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
14:49:37 backupd: Node requires deep traversal:/Volumes/Old Applications reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
14:50:05 backupd: Node requires deep traversal:/Volumes/Musik reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
14:50:18 backupd: Node requires deep traversal:/Volumes/Applications reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
14:51:23 backupd: Node requires deep traversal:/Volumes/Tiger reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
15:00:08 backupd: Node requires deep traversal:/Volumes/Free reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
15:00:08 backupd: Node requires deep traversal:/Volumes/Unix reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|

ugh ugh, kFSEDBEventFlagReasonEventDBUntrustable means 25 minutes of scanning.

15:00:13 backupd: Starting pre-backup thinning: 72.73 GB requested (including padding), 52.98 GB available

So the disk is pretty full, and more space is needed. So obviously some 
older backups should be deleted..

15:07:22 backupd: Deleted backup /Volumes/Backup of 
Aden/Backups.backupdb/Aden/2008-05-21-004709: 53.05 GB now available

It deleted one and it found out it's still not enough. 
Should delete another one...

15:07:22 backupd: Stopping backup.

No! Wait!

15:07:28 backupd: Backup canceled.

OMG.

15:07:34 backupd: Ejected Time Machine disk image.
15:07:34 backupd: Compacting backup disk image to recover free space
15:08:10 backupd: Completed backup disk image compaction
15:08:10 backupd: Starting standard backup
15:08:10 backupd: Network volume mounted at: /Volumes/Time Capsule
15:08:13 backupd: Disk image /Volumes/Time Capsule/Aden_000d932edfde.sparsebundle mounted at: /Volumes/Backup of Aden
15:08:13 backupd: Backing up to: /Volumes/Backup of Aden/Backups.backupdb
15:08:13 backupd: Querying receipt database for system packages
15:08:15 backupd: Using system path cache.
15:08:23 backupd: Event store UUIDs don't match for volume: Leopard
15:08:23 backupd: Event store UUIDs don't match for volume: Source
15:08:23 backupd: Event store UUIDs don't match for volume: Installer
15:08:23 backupd: Event store UUIDs don't match for volume: Users
15:08:23 backupd: Event store UUIDs don't match for volume: Old Applications
15:08:23 backupd: Event store UUIDs don't match for volume: Musik
15:08:23 backupd: Event store UUIDs don't match for volume: Applications
15:08:23 backupd: Event store UUIDs don't match for volume: Tiger
15:08:23 backupd: Event store UUIDs don't match for volume: Free
15:08:23 backupd: Event store UUIDs don't match for volume: Unix

Oh noes, it figures out how much space it needs again ?

15:08:23 backupd: Node requires deep traversal:/ reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
15:17:34 backupd: Node requires deep traversal:/Volumes/Source reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
15:24:52 backupd: Node requires deep traversal:/Volumes/Installer reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
15:25:04 backupd: Node requires deep traversal:/Volumes/Users reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
15:31:35 backupd: Node requires deep traversal:/Volumes/Old Applications reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
15:32:03 backupd: Node requires deep traversal:/Volumes/Musik reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
15:32:16 backupd: Node requires deep traversal:/Volumes/Applications reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
15:33:25 backupd: Node requires deep traversal:/Volumes/Tiger reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
15:42:06 backupd: Node requires deep traversal:/Volumes/Free reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
15:42:06 backupd: Node requires deep traversal:/Volumes/Unix reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|

Here we go again. (Removing a lot of output further on)

15:42:11 backupd: Starting pre-backup thinning: 72.73 GB requested (including padding), 53.05 GB available
15:50:21 backupd: Deleted backup /Volumes/Backup of 
Aden/Backups.backupdb/Aden/2008-05-20-003027: 53.27 GB now available
15:50:21 backupd: Stopping backup.
15:50:27 backupd: Backup canceled.
15:50:33 backupd: Ejected Time Machine disk image.
15:50:33 backupd: Compacting backup disk image to recover free space
15:51:12 backupd: Completed backup disk image compaction
15:51:12 backupd: Starting standard backup
15:51:12 backupd: Network volume mounted at: /Volumes/Time Capsule
15:51:15 backupd: Disk image /Volumes/Time Capsule/Aden_000d932edfde.sparsebundle mounted at: /Volumes/Backup of Aden
15:51:15 backupd: Backing up to: /Volumes/Backup of Aden/Backups.backupdb
15:51:26 backupd: Node requires deep traversal:/ reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
16:25:04 backupd: Node requires deep traversal:/Volumes/Unix reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
16:25:09 backupd: Starting pre-backup thinning: 72.73 GB requested (including padding), 53.27 GB available
16:31:25 backupd: Deleted backup /Volumes/Backup of 
Aden/Backups.backupdb/Aden/2008-05-19-004747: 53.47 GB now available
16:31:25 backupd: Stopping backup.
16:31:30 backupd: Backup canceled.
16:31:36 backupd: Ejected Time Machine disk image.
16:31:36 backupd: Compacting backup disk image to recover free space
16:32:15 backupd: Completed backup disk image compaction
16:32:15 backupd: Starting standard backup
16:32:15 backupd: Network volume mounted at: /Volumes/Time Capsule
16:32:17 backupd: Disk image /Volumes/Time Capsule/Aden_000d932edfde.sparsebundle mounted at: /Volumes/Backup of Aden
16:32:17 backupd: Backing up to: /Volumes/Backup of Aden/Backups.backupdb
16:32:27 backupd: Node requires deep traversal:/ reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
17:06:10 backupd: Node requires deep traversal:/Volumes/Unix reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
17:06:15 backupd: Starting pre-backup thinning: 72.73 GB requested (including padding), 53.47 GB available
17:14:00 backupd: Deleted backup /Volumes/Backup of 
Aden/Backups.backupdb/Aden/2008-05-18-014306: 53.54 GB now available

Two hours later, 0.5 GB have been recovered of the needed 20GB. 
So I'd expect only 4 days more to go...

17:14:00 backupd: Stopping backup.
17:14:06 backupd: Backup canceled.
17:14:13 backupd: Ejected Time Machine disk image.
17:14:13 backupd: Compacting backup disk image to recover free space
17:14:52 backupd: Completed backup disk image compaction
17:14:52 backupd: Starting standard backup
17:14:52 backupd: Network volume mounted at: /Volumes/Time Capsule
17:14:55 backupd: Disk image /Volumes/Time Capsule/Aden_000d932edfde.sparsebundle mounted at: /Volumes/Backup of Aden
17:14:55 backupd: Backing up to: /Volumes/Backup of Aden/Backups.backupdb
17:15:04 backupd: Node requires deep traversal:/ reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
17:49:00 backupd: Node requires deep traversal:/Volumes/Unix reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|
17:49:05 backupd: Starting pre-backup thinning: 72.73 GB requested (including padding), 53.54 GB available
17:55:13 backupd: Deleted backup /Volumes/Backup of 
Aden/Backups.backupdb/Aden/2008-05-30-001331: 53.60 GB now available
17:55:13 backupd: Stopping backup.
17:55:19 backupd: Backup canceled.
17:55:25 backupd: Ejected Time Machine disk image.
17:55:25 backupd: Compacting backup disk image to recover free space
17:56:06 backupd: Completed backup disk image compaction
17:56:06 backupd: Starting standard backup
17:56:06 backupd: Network volume mounted at: /Volumes/Time Capsule
17:56:09 backupd: Disk image /Volumes/Time Capsule/Aden_000d932edfde.sparsebundle mounted at: /Volumes/Backup of Aden
17:56:09 backupd: Backing up to: /Volumes/Backup of Aden/Backups.backupdb
17:56:18 backupd: Node requires deep traversal:/ reason:kFSEDBEventFlagMustScanSubDirs|kFSEDBEventFlagReasonEventDBUntrustable|

(Removing even more output further on)

18:30:08 backupd: Starting pre-backup thinning: 72.73 GB requested (including padding), 53.60 GB available
18:38:20 backupd: Deleted backup /Volumes/Backup of 
Aden/Backups.backupdb/Aden/2008-05-29-021844: 53.67 GB now available
19:13:07 backupd: Starting pre-backup thinning: 72.73 GB requested (including padding), 53.67 GB available
19:15:46 backupd: Deleted backup /Volumes/Backup of 
Aden/Backups.backupdb/Aden/2008-05-28-010002: 53.73 GB now available
19:23:19 backupd: Deleted backup /Volumes/Backup of 
Aden/Backups.backupdb/Aden/2008-05-27-221015: 53.79 GB now available

wohoo, deleted two!

19:58:16 backupd: Starting pre-backup thinning: 72.73 GB requested (including padding), 53.79 GB available
20:00:06 backupd: Deleted backup /Volumes/Backup of 
Aden/Backups.backupdb/Aden/2008-06-11-142433: 53.83 GB now available
20:00:52 backupd: Deleted backup /Volumes/Backup of 
Aden/Backups.backupdb/Aden/2008-06-11-130026: 53.85 GB now available
20:00:52 backupd: Removed all 2 expired backups, more space is needed - deleting oldest backups to make room
20:06:26 backupd: Deleted backup /Volumes/Backup of 
Aden/Backups.backupdb/Aden/2008-03-25-000709: 54.24 GB now available
20:06:26 backupd: Deleted 3 backups: oldest backup is now 01.04.2008
20:41:38 backupd: Starting pre-backup thinning: 72.73 GB requested (including padding), 54.24 GB available
20:41:38 backupd: No expired backups exist - deleting oldest backups to make room
20:46:05 backupd: Deleted backup /Volumes/Backup of 
Aden/Backups.backupdb/Aden/2008-04-01-015143: 54.52 GB now available
20:49:50 backupd: Deleted backup /Volumes/Backup of 
Aden/Backups.backupdb/Aden/2008-04-08-003544: 54.78 GB now available
20:49:50 backupd: Deleted 2 backups: oldest backup is now 23.04.2008
21:24:38 backupd: Starting pre-backup thinning: 72.73 GB requested (including padding), 54.78 GB available
21:24:38 backupd: No expired backups exist - deleting oldest backups to make room
23:23:02 backupd: Deleted backup /Volumes/Backup of 
Aden/Backups.backupdb/Aden/2008-04-23-120205: 56.29 GB now available
23:23:02 backupd: Deleted 1 backups: oldest backup is now 30.04.2008
...
ad nauseam