Backup errors out at 7%

Hi, I"m having this same error show up. Backups stopped accumulating November 2 (so about 8 weeks ago) not sure if this is a problem with one of the updates

What I see if I try to run the backup manually, it starts of, it gets past preparing, then I see updates saying “transferring…” it gets to 7 or so % and then errors out.

Is there a way to diagnose what is going wrong here?

Maybe a stupid response, but are you sure your backup disk has enough space available?

Where are you backing up to? An external disk, a network share? If an external disk, as Dirk mentioned, is there enough space, and you might run some disk checking software.

Hi @john_schneider ,

It looks like you are backing up to a NAS location. Can you please confirm if backups to a USB drive also have the same failure? Or is the NAS the only location impacted?

@Dirk_De_Taey and @Rugby - thanks yes, there is about 7T of space available

@noris - it’s a NAS, yes. an SMB mount running off of a TruNAS server. the most recent build that had a successful backup is build-1133. I went digging into the logs and it’s failing to copy the file (see below) I got into Emacs to follow the directory links from the root of the file path and in the directory I was able to create and save a file, so access isn’t the issue.

Any pointers on what I might try?

LOGS LOGS LOGS LOGS

01/05 15:08:49 Trace: [broker/backups] doing backup now
01/05 15:08:49 Warn: AddTopLevel: capturelayer(1960)
01/05 15:08:49 Trace: [broker/backups] computing list of files to back up
01/05 15:08:49 Warn: AddTopLevel: dialog_manual_backups(2983)
01/05 15:08:49 Debug: [broker/backups] preparing sync on FileBrowser.Entry: \\freenas.local, Roon : \RoonBackups
01/05 15:08:49 Debug: [broker/filebrowser/volumeshare] Use volume, user: broker/backups/startbackup, id: \\freenas.local\Roon
01/05 15:08:49 Trace: [backup] preparing backup on dir AttachedDir:/Users/mlcondit/Library/RoonMounts/RoonStorage_c4ef7bfa2da2a20479e3d5c69fb3fe294df94007/RoonBackups
01/05 15:08:49 Info: [stats] 38792mb Virtual, 796mb Physical, 472mb Managed
01/05 15:08:50 Trace: [backup] getbackupdirs, rootdir: AttachedDir:/Users/mlcondit/Library/RoonMounts/RoonStorage_c4ef7bfa2da2a20479e3d5c69fb3fe294df94007/RoonBackups, machineid: e89963b3-33cd-e775-232c-848cea3f7e65
01/05 15:08:50 Debug: [broker/backups] successful sync prepare on FileBrowser.Entry: \\freenas.local, Roon : \RoonBackups
01/05 15:08:50 Info: [loadstatus] IsBackupInProgress False => True
01/05 15:08:50 Trace: [broker/backups] [a7c7a6a2-491c-4fe8-a515-cb011a76834b] paused media thread
01/05 15:08:50 Trace: [zone AppleTV] Suspend
01/05 15:08:50 Info: [zone AppleTV] Canceling Pending Sleep
01/05 15:08:50 Trace: [zone Fly Tying] Suspend
01/05 15:08:50 Info: [zone Fly Tying] Canceling Pending Sleep
01/05 15:08:50 Trace: [zone bluenode airplay] Suspend
01/05 15:08:50 Info: [zone bluenode airplay] Canceling Pending Sleep
01/05 15:08:50 Trace: [zone denon] Suspend
01/05 15:08:50 Info: [zone denon] Canceling Pending Sleep
01/05 15:08:50 Trace: [zone Richy] Suspend
01/05 15:08:50 Info: [zone Richy] Canceling Pending Sleep
01/05 15:08:50 Trace: [zone bluestream roon] Suspend
01/05 15:08:50 Info: [zone bluestream roon] Canceling Pending Sleep
01/05 15:08:50 Trace: [zone Bedroom  speaker] Suspend
01/05 15:08:50 Info: [zone Bedroom  speaker] Canceling Pending Sleep
01/05 15:08:50 Trace: [leveldb] closing /Users/mlcondit/Library/Roon/Database/Core/bb7bc5a59d57421dbb718b063ddd86bb/transport/zone_1601bffd7c92ee900f9f82f8ce255c94235d.db temporarily
01/05 15:08:50 Trace: [leveldb] closing /Users/mlcondit/Library/Roon/Database/Core/bb7bc5a59d57421dbb718b063ddd86bb/transport/zone_16012cdd53bd8d7275eb3fda9f718fb0e1ad.db temporarily
01/05 15:08:50 Trace: [leveldb] closing /Users/mlcondit/Library/Roon/Database/Core/bb7bc5a59d57421dbb718b063ddd86bb/transport/zone_160195828476e09cbae2311aa13af66757b4.db temporarily
01/05 15:08:50 Trace: [leveldb] closing /Users/mlcondit/Library/Roon/Database/Core/bb7bc5a59d57421dbb718b063ddd86bb/transport/zone_16019d2e5e84c6c2295db623cbad7281cc28.db temporarily
01/05 15:08:50 Trace: [leveldb] closing /Users/mlcondit/Library/Roon/Database/Core/bb7bc5a59d57421dbb718b063ddd86bb/transport/zone_1601d7186075ebbc9005f46be5bedcb3223d.db temporarily
01/05 15:08:50 Trace: [leveldb] closing /Users/mlcondit/Library/Roon/Database/Core/bb7bc5a59d57421dbb718b063ddd86bb/transport/zone_1601623c28e89da7fb83da7cf73bbe52556c.db temporarily
01/05 15:08:50 Trace: [leveldb] closing /Users/mlcondit/Library/Roon/Database/Core/bb7bc5a59d57421dbb718b063ddd86bb/transport/zone_1601b13d80f41dcebb3cfbfa4aded160881b.db temporarily
01/05 15:08:50 Trace: [broker/backups] [a7c7a6a2-491c-4fe8-a515-cb011a76834b] paused transport thread
01/05 15:08:50 Trace: [leveldb] closing /Users/mlcondit/Library/Roon/Database/Core/bb7bc5a59d57421dbb718b063ddd86bb/broker_4.db temporarily
01/05 15:08:50 Info: [broker/database/vacuum] ==================================================================================================
01/05 15:08:50 Info: [broker/database/vacuum] ===[ Validating Database ]========================================================================
01/05 15:08:50 Info: [broker/database/vacuum] ==================================================================================================
01/05 15:08:50 Info: [broker/database/vacuum] Validating /Users/mlcondit/Library/Roon/Database/Core/bb7bc5a59d57421dbb718b063ddd86bb/broker_4.db
01/05 15:08:50 Warn: AddTopLevel: win_backup_in_progress(23)
01/05 15:08:50 Info: [broker/database/vacuum] processed 11 playlist entries
01/05 15:08:50 Info: [broker/database/vacuum] processed 3277 profile entries (skipped 0 entries)
01/05 15:08:50 Info: [broker/database/vacuum] processed 534 radio entries
01/05 15:08:51 Warn: [mobile] /hello => ServiceUnavailable
01/05 15:08:51 Debug: [easyhttp] [4201] POST to https://roonmobile.roonlabs.net/1/cores/announce returned after 888 ms, status code: 200
01/05 15:08:52 Info: [broker/database/vacuum] processed 527567 music entries
01/05 15:08:53 Info: [broker/database/vacuum] validated tinysooid db in 640ms, visited 932873 entries
01/05 15:08:53 Info: [broker/database/vacuum] processed 177205 image entries
01/05 15:08:53 Info: [broker/database/vacuum] finished validation in 3002ms
01/05 15:08:53 Info: [broker/database/vacuum] ==================================================================================================
01/05 15:08:53 Info: [broker/database/vacuum] ==================================================================================================
01/05 15:08:53 Info: [broker/database/vacuum] ==================================================================================================
01/05 15:08:53 Trace: [leveldb] closing /Users/mlcondit/Library/Roon/Database/Core/bb7bc5a59d57421dbb718b063ddd86bb/clientdata.db temporarily
01/05 15:08:53 Trace: [broker/backups] [a7c7a6a2-491c-4fe8-a515-cb011a76834b] paused misc thread
01/05 15:08:56 Trace: [leveldb] re-opening /Users/mlcondit/Library/Roon/Database/Core/bb7bc5a59d57421dbb718b063ddd86bb/broker_4.db
01/05 15:08:56 Trace: [leveldb] re-opening /Users/mlcondit/Library/Roon/Database/Core/bb7bc5a59d57421dbb718b063ddd86bb/clientdata.db
01/05 15:08:56 Trace: [leveldb] re-opening /Users/mlcondit/Library/Roon/Database/Core/bb7bc5a59d57421dbb718b063ddd86bb/transport/zone_1601bffd7c92ee900f9f82f8ce255c94235d.db
01/05 15:08:56 Trace: [leveldb] re-opening /Users/mlcondit/Library/Roon/Database/Core/bb7bc5a59d57421dbb718b063ddd86bb/transport/zone_16012cdd53bd8d7275eb3fda9f718fb0e1ad.db
01/05 15:08:56 Trace: [leveldb] re-opening /Users/mlcondit/Library/Roon/Database/Core/bb7bc5a59d57421dbb718b063ddd86bb/transport/zone_160195828476e09cbae2311aa13af66757b4.db
01/05 15:08:56 Trace: [leveldb] re-opening /Users/mlcondit/Library/Roon/Database/Core/bb7bc5a59d57421dbb718b063ddd86bb/transport/zone_16019d2e5e84c6c2295db623cbad7281cc28.db
01/05 15:08:56 Trace: [leveldb] re-opening /Users/mlcondit/Library/Roon/Database/Core/bb7bc5a59d57421dbb718b063ddd86bb/transport/zone_1601d7186075ebbc9005f46be5bedcb3223d.db
01/05 15:08:56 Trace: [leveldb] re-opening /Users/mlcondit/Library/Roon/Database/Core/bb7bc5a59d57421dbb718b063ddd86bb/transport/zone_1601623c28e89da7fb83da7cf73bbe52556c.db
01/05 15:08:56 Trace: [leveldb] re-opening /Users/mlcondit/Library/Roon/Database/Core/bb7bc5a59d57421dbb718b063ddd86bb/transport/zone_1601b13d80f41dcebb3cfbfa4aded160881b.db
01/05 15:08:56 Info: [loadstatus] IsBackupInProgress True => False
01/05 15:08:58 Info: [mobile] GOT HTTP API /hello
01/05 15:08:58 Trace: [mobile] Got Hello Request body={"coreId":"356aa34a-fdb8-4c41-8499-1b728ae0d5df"}
01/05 15:08:58 Debug: [easyhttp] [4202] POST to https://roonmobile.roonlabs.net/1/cores/announce returned after 2169 ms, status code: 200
01/05 15:08:59 Trace: [broker/backups] [a7c7a6a2-491c-4fe8-a515-cb011a76834b] checked 634 files, planning to upload 252 files
01/05 15:08:59 Debug: [broker/backups] syncing on FileBrowser.Entry: \\freenas.local, Roon : \RoonBackups - 249 files to upload, 634 manifest entries
01/05 15:08:59 Trace: [backup] uploading files. bytes transferred: 0/237867664 (0%)
01/05 15:08:59 Trace: [backup] uploading files. bytes transferred: 33/237867664 (0%)
01/05 15:08:59 Trace: [backup] uploading files. bytes transferred: 607/237867664 (0%)
01/05 15:08:59 Trace: [backup] uploading files. bytes transferred: 2835469/237867664 (1%)
01/05 15:08:59 Trace: [backup] uploading files. bytes transferred: 5670737/237867664 (2%)
01/05 15:08:59 Trace: [backup] uploading files. bytes transferred: 5692316/237867664 (2%)
01/05 15:09:01 Trace: [backup] uploading files. bytes transferred: 6711268/237867664 (2%)
01/05 15:09:03 Trace: [backup] uploading files. bytes transferred: 8827835/237867664 (3%)
01/05 15:09:04 Warn: [backup] failed to sync: putfile hash: AttachedDir:/Users/mlcondit/Library/RoonMounts/RoonStorage_c4ef7bfa2da2a20479e3d5c69fb3fe294df94007/RoonBackups/e89963b3-33cd-e775-232c-848cea3f7e65/8e/1c/8e1c64c0e9327e71d053c1942a781caf71ced89b69dae3b6b433853d70dfee4d: Result[Status=UnexpectedError, ErrorText=System.IO.IOException: file move failed: -1 errno=5
   at Base.IO.LongPathFile.Move(String srcpath, String dstpath)
   at Roon.FileSystem.AttachedFileSystem.<>c__DisplayClass15_0.<PutFile>b__0()
   at System.Threading.Tasks.Task`1.InnerInvoke()
   at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionContext executionContext, ContextCallback callback, Object state)
--- End of stack trace from previous location ---
   at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)
--- End of stack trace from previous location ---
   at Roon.FileSystem.AttachedFileSystem.PutFile(Stream srcfile, IFileSystemDir parent_, String destname, Boolean overwrite, CancellationToken canceltoken)]
01/05 15:09:04 Warn: [broker/backups] failed sync on FileBrowser.Entry: \\freenas.local, Roon : \RoonBackups: Result[Status=UnexpectedError]
01/05 15:09:04 Debug: [broker/backups] on done, auto: False
01/05 15:09:04 Debug: [broker/filebrowser/volumeshare] Use dispose, id: \\freenas.local\Roon

Hi @john_schneider ,

Can you please confirm if a local storage option (USB/local HDD) also exhibits this behavior?

Sorry for delay, I was traveling.
I hooked up a USB drive to my iMAC and the backup succeeded.
So I would suspect there is some kind issue that arose due to a system update.
The MacOS has been updated but I don’t recall if it was November or later
I have a workaround. I can backup locally and copy it over to the NAS

It would be nice to know why this just stopped working though

Thanks

Are you able to back up directly to your iMac if you create a shared folder there? To create the folder, you can use similar instructions to this: