Thanks for such a comprehensive and useful reply. It sent me down a very informative path.
I haven’t solved the issue, but I have a lot more information.
For ease of reading, I’ll summarise what I’ve found here and explain how I got there below that:
- I’m sure that the problem is a result of the update to MacOS 10.15.4 that was applied (on my machine) on 27th March at 09:50.
- It doesn’t fail on my machine when Duplicacy is run from the command line, but it does when called from Web Edition.
- The relevant snapshot is created without issue. The failure occurs on mounting that snapshot in the filesystem.
- It looks like, when called from Web Edition, the
mountattempt is to/private/tmp/snp_nnnnnnn, whereas when run from the command line, themountoccurs on/tmp/snp_nnnnnnn. - It appears to me to be a problem with the changes to the Sandbox policies that came with the 10.15.4 update.
What I did to come to those conclusions:
I started out following your suggestions.
- I tried your list of commands, and everything worked perfectly correctly. No failure at all:-(
- So I moved on to your prophylactics. Ran First Aid on first the partition, then the container and finally each volume. All perfectly OK. BTW, I don’t think one needs to do the volumes after the container: it looked like First Aid on the container did a tree-walk of all volumes and checked each one out. But I did them separately for completeness.
- I also did the “
deletelocalsnapshots /” thing. This removed all but one of the snapshots and allowed me to remove the final one separately.
None of that changed things. It still failed with Error 77. Not only that, but, when it fails, it leaves behind the directory of the form /tmp/snp_nnnnnnn in which it fails to mount the snapshot.
Then I tried running from the command line. I did this initially because I wanted to see whether the previous version of Duplicacy, duplicacy_osx_x64_2.4.0 would fail. It didn’t.
Nor did the current version, duplicacy_osx_x64_2.4.1, either. Both ran with -vss as arguments and did the right thing.
So I went back and verified: the Web Edition still fails, on exactly the same backup.
At this point I started digging in the MacOS Console Log (which seems to be more comprehensive than the syslog), re-running Duplicacy with -verbose and even -debug and then comparing the timestamped records in the Console Log with those in the Duplicacy output.
What I observed was:
-
In a successful run, the (significant) Console log entries look like this:
default 14:16:27.604863+1000 kernel fs_insert_snapshot_metadata:254: snap_name='com.apple.TimeMachine.2020-04-05-141627.local' snap_xid 8057969 extentref oid 917407 sblock oid 915526 default 14:16:27.670779+1000 kernel handle_snapshot_mount:490: mounting snapshot w/snap_xid 8057966 and sblock oid 0xde67a default 14:16:27.670804+1000 kernel handle_mount:329: vol-uuid: 023BA78F-896D-465B-93FC-174A1E95FE94 block size: 4096 block count: 122086923 (unencrypted; flags: 0x1; features: 1.0.12) default 14:16:27.671188+1000 kernel apfs_vfsop_mount:1489: mounted volume: Macintosh HD -
whereas in a failing one, they look like:
default 14:43:31.180979+1000 kernel fs_insert_snapshot_metadata:254: snap_name='com.apple.TimeMachine.2020-04-05-144331.local' snap_xid 8059163 extentref oid 911201 sblock oid 1115909 error 14:43:31.304968+1000 kernel Sandbox: mount_apfs(6531) System Policy: deny(1) fs-snapshot-mount /private/tmp/snp_021295157 default 14:43:31.304981+1000 kernel apfs_vfsop_mount:1406: handle_*_mount failed, err: 1 default 14:43:31.304985+1000 kernel apfs_vfsop_mount:1460: apfs_vfsop_mount failed, err: 1 -
Sometimes, but not every time, the failing one also tries to create a snapshot on volume
/Volumes/Recovery, but that fails with the messageerror: Error Domain=NSPOSIXErrorDomain Code=45 "Operation not supported". I don’t know whether that’s significant or not. -
Similarly, there is a lot of snapshot cleaning up and
filecoordinationddoes a lot of arbitration, but I think that’s all just secondary to snapshot creation. -
What may be more significant is that the Duplicacy output of the successful runs shows that the snapshot is mounted in
/tmp/snp_nnnnnnn, where the Console log of the failures shows an attempt to mount in/private/tmp/snp_nnnnnnn.- While I know that they are the same directory in practice (
/tmpis symlinked to/private/tmp) it’s possible that something at a deeper level treats them separately. - It’s also possible that all I’m seeing there is an artefact of the way the different logs are being written:-}
- While I know that they are the same directory in practice (
-
I also observed that the VSS Snapshot is actually created (it’s still there afterwards). The error occurs when Duplicacy attempts to mount the snapshot in the temporary directory.
The report of Sandbox and System Policy being invoked sent me looking at extended attributes and into the Sandbox directory (/System/Library/Sandbox). While I don’t pretend to understand the semantics of the *.sb files, what I did observe was that:
- a number of the most-obviously significant files in the
Profilessub-directory (such assystem.sbandapplication.sb) were updated in that directory on 27th March at 9:50am. - The last functional VSS copy from Duplicacy is timestamped at
2020-03-27 09:15(that particular schedule runs hourly). - So the issue definitely started when that update (10.15.4) was applied.
I can supply logs if you’d like to look deeper.
Brian
.
