TimeMachine only connects if cpu is busy

[Simon Edelmann]

Hello, this is one more attempt to debug the bug I (and some others) encounter, using TimeMachine with Unraid.

 

Short description

My Mac should backup itself regularly via TimeMachine to the Unraid server. The issue is that after the initial backup, incremental backups sometimes works and sometimes doesn't. If it doesn't work, TimeMachine is getting stuck on connecting. But I noticed a strange coincidence:

Whenever I put load on my Unraid's CPU, TimeMachine connects perfectly.

Whenever there is no load on my Unraid's CPU, TimeMachine does not connect.

Does anyone has an idea why this could happen?

 

My current workaround is to put load on one CPU core via this command:

cat /dev/zero > /dev/null

Then I manually start the TimeMachine backup. As soon as TimeMachine has connected, I stop the load via Ctrl+C.

 

# # # # # # # # # #

 

Below I will add detailed information about my setup. Also the diagnostics file is attached.

 

Hardware

I am using a (Intel) MacBook Pro from 2018 using the newest MacOS Ventura 13.2.

My Unraid server is quite small: only 2x4TB + 1TB SSD, an Intel J5040 CPU and 16GB RAM. It is running Unraid 6.11.5 and is mainly used for backups of various webspaces/VPS/etc. as well as my Mac.

 

SMB Settings

Enable SMB: Yes

Hide dot files: No

SMB Multi Channel: Yes

Mac interop.: Yes

NetBIOS: No

WSD: Yes

 

/boot/config/smb-fruit.conf

vfs objects = acl_xattr fruit streams_xattr
fruit:encoding = native
fruit:metadata = stream
fruit:posix_rename = yes

 

Share settings (excerpt)

Use cache pool: Yes

Enable copy-on-write: Yes

SMB Export: Yes/Time Machine

Time Machine volume limit: 1000000

Security: Private

 

Time Machine logs

2023-02-02 13:16:43  Starting manual backup
2023-02-02 13:16:43  Attempting to mount 'smb://simon@NAS._smb._tcp.local/timemachine'
2023-02-02 13:16:44  Initial network volume options for 'timemachine' {disablePrimaryReconnect: 0, disableSecondaryReconnect: 0, reconnectTimeOut: 0, QoS: 0x0, attributes: 0x1C}
2023-02-02 13:16:44  Configured network volume options for 'timemachine' {disablePrimaryReconnect: 0, disableSecondaryReconnect: 0, reconnectTimeOut: 30, QoS: 0x20, attributes: 0x1C}
2023-02-02 13:16:44  Mounted 'smb://simon@NAS._smb._tcp.local/timemachine' at '/Volumes/.timemachine/NAS._smb._tcp.local/66074A41-37F0-44B7-BE6A-9A15AA8C9EE6/timemachine' (365.01 GB of 1.05 TB available)
2023-02-02 13:16:45  Skipping periodic backup verification: not needed for an APFS sparsebundle
2023-02-02 13:16:45  'MacBook Pro von Simon.sparsebundle' does not need resizing - current logical size is 996.15 GB (996,147,200,000 bytes), size limit is 996.15 GB (996,147,200,000 bytes)
2023-02-02 13:16:45  Mountpoint '/Volumes/.timemachine/NAS._smb._tcp.local/66074A41-37F0-44B7-BE6A-9A15AA8C9EE6/timemachine' is still valid
2023-02-02 13:16:45  Checking for runtime corruption on '/Volumes/.timemachine/NAS._smb._tcp.local/66074A41-37F0-44B7-BE6A-9A15AA8C9EE6/timemachine/MacBook Pro von Simon.sparsebundle'
2023-02-02 13:17:31  Failed to attach using DiskImages2 to url '/Volumes/.timemachine/NAS._smb._tcp.local/66074A41-37F0-44B7-BE6A-9A15AA8C9EE6/timemachine/MacBook Pro von Simon.sparsebundle', error: Error Domain=NSPOSIXErrorDomain Code=19 "Operation not supported by device" UserInfo={DIErrorVerboseInfo=Failed to initialize IO manager: Failed opening folder for entries reading}
2023-02-02 13:17:31  Failed to unmount '/Volumes/.timemachine/NAS._smb._tcp.local/66074A41-37F0-44B7-BE6A-9A15AA8C9EE6/timemachine', Disk Management error: {
2023-02-02 13:17:31  Failed to unmount '/Volumes/.timemachine/NAS._smb._tcp.local/66074A41-37F0-44B7-BE6A-9A15AA8C9EE6/timemachine', error: Error Domain=com.apple.diskmanagement Code=0 "No error" UserInfo={NSDebugDescription=No error, NSLocalizedDescription=Kein Fehler.}
2023-02-02 13:17:31  Waiting 60 seconds and trying again.
2023-02-02 13:17:31  Cancelling backup because volume '/Volumes/.timemachine/NAS._smb._tcp.local/66074A41-37F0-44B7-BE6A-9A15AA8C9EE6/timemachine' was unmounted.
2023-02-02 13:17:31  Requested backup cancellation or termination
2023-02-02 13:17:32  Backup cancelled (22: BACKUP_CANCELED)
2023-02-02 13:17:32  Failed to unmount '/Volumes/.timemachine/NAS._smb._tcp.local/66074A41-37F0-44B7-BE6A-9A15AA8C9EE6/timemachine', Disk Management error: {
2023-02-02 13:17:32  Failed to unmount '/Volumes/.timemachine/NAS._smb._tcp.local/66074A41-37F0-44B7-BE6A-9A15AA8C9EE6/timemachine', error: Error Domain=com.apple.diskmanagement Code=0 "No error" UserInfo={NSDebugDescription=No error, NSLocalizedDescription=Kein Fehler.}
2023-02-02 13:17:32  Cleared pending cancellation request

nas-diagnostics-20230202-1315.zip

 

Edit: Updated the workaround

Edited April 18, 2023 by Simon Edelmann
Updated workaround

[Jazer]

I dont have this experience... sometimes it takes 2 or 3 attempts to connect it succeeds and starts the backup.

 

What wonders me is ...

Backup cancelled (22: BACKUP_CANCELED)

which seems to be a manual cancelation... I don't see these entry in my log.

[Simon Edelmann]

That‘s interesting… I‘ve tried multiple times in a row already and it never worked until I put load on the server. (I recognised that, because only working backups were happening at night when a rsync script was running on the server.)

 

The manual backup cancellation might be there, because I tried to get a clean log for this post by stopping+manually starting the backup. (Which is strange though, as I didn‘t manually stopped this attempt, but only the attempt before.)