David Schlachter

Filename encoding errors in macOS Time Machine backups

Time Machine is great when it works, but opaque when it fails. This post discusses how I identified a filesystem text encoding issue that caused backups to fail.

The first indication that something was wrong was a failed backup notification (accompanied by a vague error message in System Preferences):

Time Machine error message notification

In recent macOS versions, detailed error logs for Time Machine can be viewed using log (1), e.g. by running
     log stream --style syslog --predicate 'senderImagePath contains[cd] "TimeMachine"' --info
and then starting a backup manually. In my case this gave the following pertinent messages (full log at end of post):

2020-03-29 10:20:01.112647-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogError] Error: (-48) SrcErr:NO Copying /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/🦑/2020-03-29-101901/Macintosh HD/Users/david/Music/Swing iTunes/iTunes/iTunes Music/Music/Ella Fitzgerald/In the Groove to /Volumes/Copies de sauvegarde Time Machine/Backups.backupdb/🦑/2020-03-29-101902.inProgress/A21933C8-ACFC-4ED7-A047-D41303290007/Macintosh HD/Users/david/Music/Swing iTunes/iTunes/iTunes Music/Music/Ella Fitzgerald

2020-03-29 10:20:01.112999-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogError] Stopping backup.

2020-03-29 10:20:01.117727-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogError] Error: (-8062) SrcErr:NO Copying /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/🦑/2020-03-29-101901/Macintosh HD/Users/david/Music/Swing iTunes/iTunes/iTunes Music/Music/Ella Fitzgerald/In the Groove/15 Careless.sync-conflict-20200120-110321-FHHUZ2Y.mp3 to /Volumes/Copies de sauvegarde Time Machine/Backups.backupdb/🦑/2020-03-29-101902.inProgress/A21933C8-ACFC-4ED7-A047-D41303290007/Macintosh HD/Users/david/Music/Swing iTunes/iTunes/iTunes Music/Music/Ella Fitzgerald

Note that a particular file is identified in the messages. I quickly tested that the file opened and (being audio) played. I also checked that permissions and any xattrs and ACLs looked okay, though I wouldn't expect this to affect Time Machine.

I recalled having issues with illegal characters in file names causing backup failures in the past. To check this file for similar errors, I wanted to check that the filename was composed purely of ASCII characters, as it appeared to be ("15 Careless.sync-conflict-20200120-110321-FHHUZ2Y.mp3").

To do so, I converted the filename to hexadecimal [1], wrote this to a file [2], and inspected the output with xxd (1):

The filename looked okay. I decided to go up a directory level out of curiosity. By chance I noticed that tab completion of the parent directory ("In the Groove") didn't work. This prompted me to do a similar check on the directory name (convert to hex and verify that it's all ASCII):

Unexpectedly, there appeared to be two directories named "In the Groove"! Comparison with xxd showed that one was prepended by the hex byte sequence 2e 2f ef, which is the UTF-8 byte order mark [3].

Both directories contained the same contents:

To resolve the problem, I simply deleted the directories (rm -rf *Groove*) since they only contained an old syncthing conflict file. Had I wanted to delete only one of them, I'm not sure how I would have deleted a folder whose name begins with an unprintable character. In that case I would have moved the file somewhere safe, deleted both directories, and recreated one.

It's unclear to me how a byte order mark would have gotten into the directory name, but it could have been due to an encoding issue expanding a ZIP file containing the directory, an issue with iTunes setting metadata and then the folder name based on copy-pasted text, or perhaps an issue with normalization and encoding in syncthing. In any case, Time Machine was unable to parse these directories and failed mysteriously. With the directories gone, backup proceeded without problems.

Full error log

Included to help anybody searching with terms in their error logs. For reference, I back up to a ZFS volume on a FreeBSD 12.1-RELEASE server running samba.

2020-03-29 10:18:33.592991-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Starting manual backup
2020-03-29 10:18:33.619075-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Network destination already mounted at: /Volumes/com.apple.TimeMachine.TimeMachine Home-5F34470C-C469-4EAA-9A2C-56E1874DE48E
2020-03-29 10:18:34.972623-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Unmounted '/Volumes/Copies de sauvegarde Time Machine' (disk4s2)
2020-03-29 10:18:36.035715-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Ejected disk4 from '/Volumes/com.apple.TimeMachine.TimeMachine Home-5F34470C-C469-4EAA-9A2C-56E1874DE48E/🦑.sparsebundle'
2020-03-29 10:18:36.956648-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Checking size of '/Volumes/com.apple.TimeMachine.TimeMachine Home-5F34470C-C469-4EAA-9A2C-56E1874DE48E/🦑.sparsebundle'
2020-03-29 10:18:45.521295-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Checking for runtime corruption on '/Volumes/com.apple.TimeMachine.TimeMachine Home-5F34470C-C469-4EAA-9A2C-56E1874DE48E/🦑.sparsebundle'
2020-03-29 10:18:49.733485-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Runtime corruption check passed for '/Volumes/com.apple.TimeMachine.TimeMachine Home-5F34470C-C469-4EAA-9A2C-56E1874DE48E/🦑.sparsebundle'
2020-03-29 10:18:51.840780-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Ejected disk4 from '/Volumes/com.apple.TimeMachine.TimeMachine Home-5F34470C-C469-4EAA-9A2C-56E1874DE48E/🦑.sparsebundle'
2020-03-29 10:18:56.886495-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] '/Volumes/com.apple.TimeMachine.TimeMachine Home-5F34470C-C469-4EAA-9A2C-56E1874DE48E/🦑.sparsebundle' mounted at '/Volumes/Copies de sauvegarde Time Machine'
2020-03-29 10:18:58.611254-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Backing up to /dev/disk4s2: /Volumes/Copies de sauvegarde Time Machine/Backups.backupdb
2020-03-29 10:19:01.101109-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogError] Failed to remove attribute 'com.apple.backupd.SnapshotVolumeFSEventStoreUUID' from 'file:///', error: Error Domain=NSPOSIXErrorDomain Code=1 "Operation not permitted"
2020-03-29 10:19:01.102608-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogError] Failed to remove attribute 'com.apple.backupd.SnapshotVolumeLastFSEventID' from 'file:///', error: Error Domain=NSPOSIXErrorDomain Code=1 "Operation not permitted"
2020-03-29 10:19:01.103236-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogError] Failed to remove attribute 'com.apple.backupd.SnapshotVolumeUUID' from 'file:///', error: Error Domain=NSPOSIXErrorDomain Code=1 "Operation not permitted"
2020-03-29 10:19:01.106684-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogError] Failed to remove attribute 'com.apple.backupd.PreviousSnapshotVolumeUUID' from 'file:///', error: Error Domain=NSPOSIXErrorDomain Code=1 "Operation not permitted"
2020-03-29 10:19:01.106993-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogError] Failed to remove attribute 'com.apple.backupd.PreviousSnapshotVolumeName' from 'file:///', error: Error Domain=NSPOSIXErrorDomain Code=1 "Operation not permitted"
2020-03-29 10:19:01.107470-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogError] Failed to remove attribute 'com.apple.backupd.VolumeBytesUsed' from 'file:///', error: Error Domain=NSPOSIXErrorDomain Code=1 "Operation not permitted"
2020-03-29 10:19:01.107642-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogError] Failed to remove attribute 'com.apple.backupd.VolumeIsCaseSensitive' from 'file:///', error: Error Domain=NSPOSIXErrorDomain Code=1 "Operation not permitted"
2020-03-29 10:19:01.107785-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogError] Failed to remove attribute 'com.apple.backupd.fstypename' from 'file:///', error: Error Domain=NSPOSIXErrorDomain Code=1 "Operation not permitted"
2020-03-29 10:19:01.107924-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogError] Failed to remove attribute 'com.apple.backupd.VolumeIsEncrypted' from 'file:///', error: Error Domain=NSPOSIXErrorDomain Code=1 "Operation not permitted"
2020-03-29 10:19:01.384594-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogError] Failed to write unlock record UUIDs as extended attribute for disk '/', error: Error Domain=NSPOSIXErrorDomain Code=1 "Operation not permitted"
2020-03-29 10:19:01.985700-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Created Time Machine local snapshot with name 'com.apple.TimeMachine.2020-03-29-101901' on disk '/'
2020-03-29 10:19:01.998386-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Declared stable snapshot: com.apple.TimeMachine.2020-03-29-101901
2020-03-29 10:19:02.586745-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Mounted stable snapshot: com.apple.TimeMachine.2020-03-29-101901 at path: /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/🦑/2020-03-29-101901/Macintosh HD source: Macintosh HD
2020-03-29 10:19:03.137686-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Initial backup of source: "Macintosh HD" (device: /dev/disk1s1 mount: '/' fsUUID: 332C80AC-4C3D-4F85-9605-1613FE2C1501 eventDBUUID: 95B95361-F524-460F-9AB9-F8B8FA168D54)
2020-03-29 10:19:03.166162-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Found 1352481 files (63,19 Go) needing backup
2020-03-29 10:19:03.194044-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] 76,52 Go required (including padding), 199,9 Go available
2020-03-29 10:20:01.112647-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogError] Error: (-48) SrcErr:NO Copying /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/🦑/2020-03-29-101901/Macintosh HD/Users/david/Music/Swing iTunes/iTunes/iTunes Music/Music/Ella Fitzgerald/In the Groove to /Volumes/Copies de sauvegarde Time Machine/Backups.backupdb/🦑/2020-03-29-101902.inProgress/A21933C8-ACFC-4ED7-A047-D41303290007/Macintosh HD/Users/david/Music/Swing iTunes/iTunes/iTunes Music/Music/Ella Fitzgerald
2020-03-29 10:20:01.112999-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogError] Stopping backup.
2020-03-29 10:20:01.117727-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogError] Error: (-8062) SrcErr:NO Copying /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/🦑/2020-03-29-101901/Macintosh HD/Users/david/Music/Swing iTunes/iTunes/iTunes Music/Music/Ella Fitzgerald/In the Groove/15 Careless.sync-conflict-20200120-110321-FHHUZ2Y.mp3 to /Volumes/Copies de sauvegarde Time Machine/Backups.backupdb/🦑/2020-03-29-101902.inProgress/A21933C8-ACFC-4ED7-A047-D41303290007/Macintosh HD/Users/david/Music/Swing iTunes/iTunes/iTunes Music/Music/Ella Fitzgerald
2020-03-29 10:20:01.137964-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Copied 95 items (339,9 Mo) from volume Macintosh HD. Linked 276.
2020-03-29 10:20:01.934561-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogError] Copy stage failed with error:11
2020-03-29 10:20:02.351206-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Unmounted local snapshot: com.apple.TimeMachine.2020-03-29-101901 at path: /Volumes/com.apple.TimeMachine.localsnapshots/Backups.backupdb/🦑/2020-03-29-101901/Macintosh HD source: Macintosh HD
2020-03-29 10:20:02.627881-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogError] Backup failed with error 11: 11
2020-03-29 10:20:11.773867-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Unmounted '/Volumes/Copies de sauvegarde Time Machine' (disk4s2)
2020-03-29 10:20:13.411412-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Ejected disk4 from '/Volumes/com.apple.TimeMachine.TimeMachine Home-5F34470C-C469-4EAA-9A2C-56E1874DE48E/🦑.sparsebundle'
2020-03-29 10:20:13.461824-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogInfo] Unmounted '/Volumes/com.apple.TimeMachine.TimeMachine Home-5F34470C-C469-4EAA-9A2C-56E1874DE48E'
2020-03-29 10:20:13.504259-0400 localhost backupd[398]: (TimeMachine) [com.apple.TimeMachine:TMLogError] Failed to remove directory '(null)', error: 14 Bad address