-vss not working with Catalina

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
    
  • 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 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

1 Like

Fascinating!

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)

  1. 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.

  2. 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?

  3. 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)

3 Likes

Brilliant!! That fixed it :smiley:
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 :roll_eyes:.

Thanks again!
Brian

2 Likes

Awesome!

Summoning @gchen for that

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 :slight_smile:

1 Like

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.

Did you read this topic? This specifically:

I did do that but with the CLI 2.5.0 executable:

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

Try it with giving full disk access to the Web Edition:

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 :slight_smile:. 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.

Ok, let’s take a step back here.

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:

When I run the duplicacy_osx_x64_2.5.0 from /usr/local/bin and also from ~/.duplicacy-web/bin I also see an Error 77 message.

Something to note, when I ran the CLI versions for the first time I was presented with a message saying:

“Apple cannot check for malicious software. This software needs to be updated. Contact the developer for more information.”

Compare this to the message I get when I first run Duplicacy Web Edition:

“Duplicacy Web Edition” is an app downloaded form the Internet. Are you sure you want to open it?

I’m not sure if this may the issue. I would also like to say I appreciate the great product support on the forums.

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.

1 Like

Can you try the notarized version at https://acrosync.com/duplicacy/duplicacy_osx_x64_2.5.0_notarized?

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 @saspus disabling 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.

1 Like

Thanks for sharing. Granting the Terminal.app to full disk access or using Platypus to create a script wrapper app and giving it full disk access are better options than disabling SIP.

I just ran into this same issue, because I was running Duplicacy from a script via launchd (which means that, except for disabling SIP, none of the solutions suggested above would be applicable, I think).

For those who are in a similar situation, I finally managed to make it work using the fdautil shipped with LaunchControl, which was written specifically for granting Full Disk Access to launchd entries. (The instructions for how to use the util are in the Help section of the app, not anywhere online).

1 Like

And here is today’s Arq’s announcement:

NEW: Filesystem Snapshots for Perfect Backups

Arq 7 uses filesystem “snapshots”, so each backup record is a perfectly consistent copy of your files, even if files are being modified during the backup process. For macOS we worked with Apple to get special access to the APFS API to deliver this.

It is definitely doable…