me@obsidian ~ % duplicacy backup -vss
Running script /Users/alex/.duplicacy/scripts/pre-backup
Storage set to sftp://me@redacted//Backups/duplicacy
Last backup at revision 1676 found
Shadow copy created and mounted at /tmp/snp_043824422
...
Backup for /Users/me at revision 1677 completed
4 files were not included due to access errors
Shadow copy unmounted and deleted at /tmp/snp_043824422
What errors are you seeing? Anything in the console?
The log when it was failing (one of many - it was like this for some days):
Running backup command from /Users/brian/.duplicacy-web/repositories/localhost/11 to back up /Users
Options: [-log backup -storage MacBook-Duplicacy-4T -vss -vss-timeout 200 -stats]
2020-04-03 00:30:01.080 INFO REPOSITORY_SET Repository set to /Users
2020-04-03 00:30:01.081 INFO STORAGE_SET Storage set to /Volumes/Duplicacy-4TB/Duplicacy
2020-04-03 00:30:02.045 INFO BACKUP_START Last backup at revision 138 found
2020-04-03 00:30:02.612 ERROR VSS_CREATE Error while mounting snapshot: exit status 77
Error while mounting snapshot: exit status 77
After I removed the VSS option:
Running backup command from /Users/brian/.duplicacy-web/repositories/localhost/11 to back up /Users
Options: [-log backup -storage MacBook-Duplicacy-4T -stats]
2020-04-03 00:30:56.681 INFO REPOSITORY_SET Repository set to /Users
2020-04-03 00:30:56.681 INFO STORAGE_SET Storage set to /Volumes/Duplicacy-4TB/Duplicacy
2020-04-03 00:30:57.053 INFO BACKUP_START Last backup at revision 138 found
2020-04-03 00:30:57.053 INFO BACKUP_INDEXING Indexing /Users
2020-04-03 00:30:57.053 INFO SNAPSHOT_FILTER Parsing filter file /Users/brian/.duplicacy-web/repositories/localhost/11/.duplicacy/filters
2020-04-03 00:30:57.054 INFO SNAPSHOT_FILTER Loaded 43 include/exclude pattern(s)
ā¦ and so on
A couple of points:
I realised that I hadnāt mentioned the MacOS version, so I edited the post to include that. I may not have done that before you read it. Are you on MacOS 10.15.4?
Looking at your log, I see both that you donāt have a -vss-timeout option set and that youāre running directly from the command line (Iām using the web edition). Iāll try both those tomorrow morning when Iām more awake.
Iāve just tried with duplciacy-web, same story, works fine.
Duplicacy simply calls mount on a snapshot it just created; Iām not sure what does error code 77 mean
// Mount snapshot as readonly and hide from GUI i.e. Finder
_, err = CommandWithTimeout(timeoutInSeconds,
"/sbin/mount", "-t", "apfs", "-o", "nobrowse,-r,-s="+snapshotName, "/", snapshotPath)
if err != nil {
LOG_ERROR("VSS_CREATE", "Error while mounting snapshot: %v", err)
return top
}
Check the following:
Do you have access to /tmp folder?
Run tmutil snapshot. Does it succeed? It would return timestamp for the snapshot.
List snapshots tmutil listlocalsnapshots /. Do you see your snapshot from above there?
create temp folder mkdir /tmp/test
Mount snapshot there: mount -t apfs -o "nobrowse,-r,-s=com.apple.TimeMachine.2020-04-03-201431.local" / /tmp/test. Substitute correct date from above. Does it succeed or you get the same error 77?
unmount the snapshot umount /tmp/test
delete the snapshot tmutil deletelocalsnapshots 2020-04-03-215916 ā put whatever date tmutil snapshot returned above command returned.
Where does it fail?
As a prophylactic I would boot into recovery partition and run first aid on a partition, then on a APFS container and then on a volume. If still fails ā I would nuke all local time machine snapshots and try again.
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 mount attempt is to /private/tmp/snp_nnnnnnn, whereas when run from the command line, the mount occurs 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
Sometimes, but not every time, the failing one also tries to create a snapshot on volume /Volumes/Recovery, but that fails with the message error: 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 filecoordinationd does 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 (/tmp is 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:-}
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 Profiles sub-directory (such as system.sb and application.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
First ā it just occurred to me that the fact that it works for me is another indirect confirmation of what you suspect: that it may indeed have to do with permissions/policies/security/sandboxing: I have both secure boot and SIP disabledā¦ since forever, and I completely forgot about that.
So, this is our culprit:
Sandbox: mount_apfs(6531) System Policy: deny(1) fs-snapshot-mount /private/tmp/snp_021295157
I diffed the whole Profiles folder with what I had on another Mac with 10.15.1 and did not see any relevant changes at a first glance.
I have a few ideas to try (will try in the evening)
the duplicacy_web is signed, while the duplicacy CLI is not signed at all. Iām not sure, but maybe it inherits restrictions of a parent process when launched as such:
me@obsidian ~ % codesign --verify --verbose ~/.duplicacy-web/bin/duplicacy_osx_x64_2.4.1
/Users/me/.duplicacy-web/bin/duplicacy_osx_x64_2.4.1: code object is not signed at all
In architecture: x86_64
me@obsidian ~ % codesign --verify --verbose /Applications/Duplicacy\ Web\ Edition.app/
/Applications/Duplicacy Web Edition.app/: valid on disk
/Applications/Duplicacy Web Edition.app/: satisfies its Designated Requirement
Wondering what will happen if we sign the Duplicacy command line with default entitlements ā will it start failing? (I can try that tomorrow only ā I cannot turn back security on my Mac to test this, Iāll need to find another one or configure VM). If that is the case gchen will need to adjust entitlements.
Assuming the issue is with restrictions on access to filesystem snapshots (and it is indeed quite sensitive from security perspective access): Will the behavior change if you add Duplicacy Web to System Preferences -> Security and Privacy -> Full Disk Access?
In case the issue with the mount point (as opposed to access to the snaphot in the first place ā Instead of using /private/tmp/ or /tmp why not do it right and use mktemp to generate temp file path (it will end up in /var/folders/ and should be fully accessible`). (If I find a place to run macOS with full security on Iāll try that later ā or you can try that. But I suspect the item 2 above should help)
Brilliant!! That fixed it
A simple change to the Doco, or, in the longer term, a change to the installer to prompt the Preferences change (if that is possible).
Whatās the process to initiate those?
Thatās the problem with ātemporarilyā lifting security constraints - we forget that weāve done it .
Yeaā¦ except in my case the lift was intentionally permanent (I mess with .kexts a lot) and its not that I forgot to revert it back ā I forgot that my config is special in any wayā¦ Iāt my ānormalā. Itās like herd immunity ā if majority of users keep it enabled malware canāt spread so those like me who have to have it disabled are also protected
Iām having this same issue but with CLI 2.5.0 on macOS Catalina 10.15.4. Iām able to do backups fine without VSS but when I use it I similarly get an Error 77. I also get the same information in the logs that @pdp8user is seeing.
Is there something I can do I my end to get it working?
Some additional information:
When I first launched the application I received a message saying that the application canāt be opened because Apple cannot check it for malicious software. This software needs to be updated. Contact the developer for more information. I was able to open it after going to the Security control panel and clicking allow after reading that the app was blocked because āit is not from an identified developerā.
When I run the codesign command, I get a āvalid on diskā and āsatisfies itās Designated Requirementā message.
I have both the Web Edition and the CLI version on my Mac.
I confirmed that SIP is turned on and secure boot is enabled to allow full security.
I was also able to make and list Time Machine snapshots by doing the following:
This is the command Iām running and output Iām seeing:
White:Test2 indoracer$ duplicacy -log backup -vss
2020-04-12 03:21:58.478 INFO STORAGE_SET Storage set to gcd://Backups/Duplicacy
2020-04-12 03:22:06.323 INFO BACKUP_START Last backup at revision 1 found
2020-04-12 03:22:06.912 ERROR VSS_CREATE Error while mounting snapshot: exit status 77
You may have to do it with both the Web & CLI editions.
Iām certainly running with SIP turned on. Mine was working on the CLI without setting Full Disk Access for it, but that was before the update to 2.5.0 . It will be interesting to see whether I have to add that when the update comes through. The Web edition normally updates itself automatically, so Iāll keep a close eye on things.
Do you have the same issue with the standalone command line executable when you run it from the command line manually, outside of duplciacy_web or from duplicacy_web?
You have added āduplicacyā which does not match either of executables.
If you run it from duplicacy_web ā you need to add duplicacy_web into the whitelist.
I did make sure the Duplicacy Web Edition has full disk access as well as the CLI version. @saspus asked why there was a discrepancy in the filenames of the executable. I renamed the original executable to duplicacy. I can confirm that adding the vss option to a backup on the Web Edition results in a successful backup:
Options: [-log backup -storage Desktop -vss -stats]
2020-04-12 12:55:39.067 INFO REPOSITORY_SET Repository set to /Users/indoracer/Desktop/Duplicacy/Test2 copy
2020-04-12 12:55:39.067 INFO STORAGE_SET Storage set to /Users/indoracer/Desktop/Duplicacy/Backup
2020-04-12 12:55:39.080 INFO BACKUP_START Last backup at revision 3 found
2020-04-12 12:55:39.374 INFO VSS_DONE Shadow copy created and mounted at /tmp/snp_778725703
2020-04-12 12:55:39.374 INFO BACKUP_INDEXING Indexing /Users/indoracer/Desktop/Duplicacy/Test2 copy
2020-04-12 12:55:39.374 INFO SNAPSHOT_FILTER Parsing filter file /Users/indoracer/.duplicacy-web/repositories/localhost/0/.duplicacy/filters
2020-04-12 12:55:39.374 INFO SNAPSHOT_FILTER Loaded 0 include/exclude pattern(s)
2020-04-12 12:55:39.516 INFO UPLOAD_FILE Uploaded t1 copy.txt (3)
2020-04-12 12:55:39.516 INFO UPLOAD_FILE Uploaded t2 copy.txt (12)
2020-04-12 12:55:39.517 INFO BACKUP_END Backup for /Users/indoracer/Desktop/Duplicacy/Test2 copy at revision 4 completed
2020-04-12 12:55:39.517 INFO BACKUP_STATS Files: 5 total, 6K bytes; 2 new, 15 bytes
2020-04-12 12:55:39.517 INFO BACKUP_STATS File chunks: 3 total, 6K bytes; 0 new, 0 bytes, 0 bytes uploaded
2020-04-12 12:55:39.517 INFO BACKUP_STATS Metadata chunks: 3 total, 1K bytes; 3 new, 1K bytes, 716 bytes uploaded
2020-04-12 12:55:39.517 INFO BACKUP_STATS All chunks: 6 total, 7K bytes; 3 new, 1K bytes, 716 bytes uploaded
2020-04-12 12:55:39.517 INFO BACKUP_STATS Total running time: 00:00:01
2020-04-12 12:55:39.674 INFO VSS_DELETE Shadow copy unmounted and deleted at /tmp/snp_778725703
It didnāt however fix this issue with the CLI version Iām seeing.
Iām still having issues with the CLI version although Iām able to make a successful backup with vss enabled with the Web Edition.
I have renamed duplicacy_osx_x64_2.5.0 to duplicacy and moved it to my /usr/local/bin directory. I also moved a freshly downloaded duplicacy_osx_x64_2.5.0 (to make sure the re-naming wasnāt causing an issue) to the /usr/local/bin directory and have made sure to grant both of them Full Disk Access:
The CLI is signed but not notarized while the web GUI is notarized. Maybe that is why you got the ācannot check for malicious softwareā warning. Iāll upload a notarized version of the CLI for you to test.
It runs without any warning message which is great, however, Iām still getting an exit status 77 error message:
indoracer@White Test1 % chmod 755 /Users/indoracer/Downloads/duplicacy_osx_x64_2.5.0_notarized
indoracer@White Test1 % /Users/indoracer/Downloads/duplicacy_osx_x64_2.5.0_notarized -log backup -vss
2020-04-12 21:27:07.615 INFO STORAGE_SET Storage set to /Users/indoracer/Desktop/Duplicacy/Backup/
2020-04-12 21:27:07.659 INFO BACKUP_START Last backup at revision 3 found
2020-04-12 21:27:08.094 ERROR VSS_CREATE Error while mounting snapshot: exit status 77
This message shows up in my console:
kernel (Sandbox)
Sandbox: mount_apfs(3920) System Policy: deny(1) fs-snapshot-mount /private/tmp/snp_468036566
Please note I did grant the notarized application full disk access permissions as is suggested in an earlier reply.
Interesting indeed! It works for me, whereas the non-notarized version of 2.5.0 comes up with the āmalicious softwareā warning.
brian@brianmacbook-3 ~/.d/r/l/11> /Users/brian/Software/Duplicacy/duplicacy_osx_x64_2.5.0_notarized backup -vss
Repository set to /Users
Storage set to /Volumes/Duplicacy-4TB/Duplicacy
Last backup at revision 159 found
Shadow copy created and mounted at /tmp/snp_735424385
Indexing /Users
I did not do anything in the way of granting permissions, except to make the downloaded file executable with chmod.
Iām using MacOS 10.15.4
I may have understood the cause of the issue. As mentioned by @saspusdisabling SIP may fix the problem on MacOS 10.5.4. As you mentioned in a prior post, It appears that something changed with sandboxing between the 10.15.3 and 10.15.4.
I ran the CLI version with vss on MacOS 10.15.3 on a second machine with success. When I upgraded that machine to 10.15.4 it gave an error when running the same command.
@gchen After disabling SIP (System Integrity Protection) on my first computer running 10.15.4, I was successfully able to run the CLI version with vss. For me, giving full disk permissions to the application didnāt resolve the vss issue.
Iām working through the same thing right now and my understanding (one source) is that simple binary executables (the CLI app) canāt be added to the Full Disk Access list. Terminal.app can be added to enable on demand backups, or you could use Platypus to create a wrapper app to run a script to run duplicacy with the arguments youāve selected.
My current work around is the Platypus app. The downside is that even when set to background and no icon, it steals focus on launch.