p7zip error 2 when compressing pvm file

[zeff013]

In the event, when Keka is compressing pvm file (Parallels Desktop virtual machine ~20G size) and there is not enough free space on macOS Mojave encrypted apfs volume, but more than enough purgeable space - purgeable space won't be freed-up automatically and Keka will fail with fatal error 2 (no free space available).

This will not happen, when compressing non-pvm files. I have tried this with centos-everything.iso, which is over 10G. Keka compressed it successfully and macOS freed up purgeable space automatically.

Not sure whose fault it is:

Parallel's, for creating pvm in some erroneous form of collection of folders and files, which leads to Keka not being able to compress it correctly.

Keka's, for not being able send correct command to macOS to free up purgeable space, when compressing large amount of files.

macOS's, for not being able to timely understand that purgeable space need to be cleaned up.

[zeff013]

I did another test - coping pvm files from another volume to macOS Mojave encrypted apfs volume, which has not enough free space, but has enough purgeable space - everything went smoothly.

From this I tend to draw conclusion, that Keka is not handling compression of large pvm files well enough and might fail on other large collections of files and folders, when it needs to free-up purgeable space on ssd in order to store resulting archive successfully.

[gingerbeardman]

I'm wondering how you can let macOS know that you need X space ahead of time? And how much would X be in this instance? What proportion of 20GB?

[zeff013]

For example just tell macOS to free up the same amount of purgeable space, which is occupied by original files, you are going to compress.
I'm always using "store" compression for pvm files, so it should be very easy.
I understand that it is hard to predict the target size on normal compression settings, and I think there is no point to be very precise in freeing up space.

This is what was happening, when macOS it self was coping files: it was always freeing up space with some margin.
I had 7GB of free space and 280GB of purgeable space.
I have copied several pvm files, which were 20GB, 20GB and 40GB in size.
At first macOS freed up just 50GB of purgeable space for the first two files.
But when I started to copy 40GB file, it freed up 220GB of purgeable space.

[aonez]

Thanks for the feedback @zeff013! This seems to me like an OS thing. The cause might be similar to #362, where the reason seems to be that macOS denies access to the source file during an operation and that operation fails, rather than a space issue. Would be interesting to replicate the issue and see if always fails at the same time.

I don't use the purgeable feature at the moment.

[gingerbeardman]

@aonez have you turned it off? Or do you use a macOS version from before it was introduced.

I use High Sierra and I'd like to turn it off.

[aonez]

@gingerbeardman I understand this purgeable thing appears only if you enable "Optimize Mac Storage" in iCloud settings, which I don't use. I like my files to be local if no sync is needed.

[zeff013]

Yes, I confirm issue replication as "always" and "each time at the same time".

When I was trying to compress the same pvm file, operation was failing at the same moment in time each and every attempt.
I noticed that Keka was writing compressed data in 8GB chunks to disk and when it was time to write another chunk, but there was not enough free space (only space, that needs purging) - operation was failing with the mentioned code.

What is probably also worth mentioning - when Keka was trying to write another chunk and there was not enough free space, the already created archive file was disappearing and only after a minute or so of keep trying, Keka was throwing the error and failing.

I have "Optimize Mac Storage" enabled, but the thing is that "purgeable" appears for any file deleted from home folder.
In theory this might be connected with TimeMachine.
On practice, when I delete any file in my home folder - it goes to purgeable space immediately each and every time.
In theory, TimeMachine still might do a backup of deleted file, if I will not request macOS to purge it and make space available for something else.

[ghost]

I get this error pls fix

[sunford]

Got the same error with any file!

[aonez]

@Nikita11790 same error with PVM files?
@sunford fails on compression and extraction? With any format?

[sunford]

Compression, any type of file.

[aonez]

@sunford please close Keka, remove it’s preferences and try again:

https://github.com/aonez/Keka/wiki/Uninstall-Keka#2-delete-the-preferences

[sunford]

rm: /Users/user/Applications/Keka.app: No such file or directory
MacBook:~ user$
I installed from Appstore 1.1.23 (3418)

[aonez]

Sorry @sunford that code was wrong (fixed already). Only remove the preferences file:

rm ~/Library/Containers/com.aone.keka

What macOS version are you running?

[sunford]

I use 10.15.1 (19B88)
now it shows: rm: /Users/user/Library/Containers/com.aone.keka: is a directory
I removed all files from this directory by hand but it didn't help and I got "code 2" error.

[aonez]

Remove the entire folder. If it fails again please enable the verbose mode and let me know what says the console:

https://github.com/aonez/Keka/wiki/Console-verbose

[aonez]

@sunford does that help? You can also manually remove all the items in the list at Keka - Preferences - File Access. I’m pretty sure this is causing the issue for you.

[sunford]

No, there aren't any items in this list.

[sunford]

What is "code 2" means?

[aonez]

@sunford this is the generic error, can mean anything. Can you enable the verbose mode?

defaults write com.aone.keka DevLog true;
defaults write com.aone.keka DevLogReader true;

Then open the Console.app, filter by Keka in the search field and try to compress some file.

I can also make a custom build for you if you are willing to test.

[aonez]

@sunford please check #494 (comment) and let's follow your issue in that ticket #494

[VaslD]

I'm using Keka 1.1.25 (3432) on macOS Catalina (10.15.3) and I just ran into this error.

I've been using Keka to migrate my entire /Applications folder, 7-zipping apps (.app folders) one by one onto ~/Desktop and then transfer individual archives to an external drive. Probably not the best way to migrate but not the point. According to Finder I had 300+ GB available left (on an internal 512 GB SSD came with this Mac) so space should've never been an issue whether purgeable was taken into account or not. Everything went smoothly for hours but for a ~2GB app folder Keka failed (at about 1/3 on the progress bar) with p7zip error 2.

The configuration for archive is slowest, with Solid and Exclude resource forks checked, everything else left as-is. Keka was launched from Ctrl+Click > Services > Send to Keka.

Then I moved all completed archives, left Desktop clean, put the source app/folder on Desktop, turned on logging in Keka Help menu and ran the same compression again, the log is attached below but it doesn't really say much from what I can tell.

2020-03-05 13:00:45.367 Cancelling auto-quit
2020-03-05 13:00:45.370 Set tarball: 0. Tarball active: 0. Extension: 7z
2020-03-05 13:00:46.939 Binary used: keka7z
2020-03-05 13:00:46.940 Arguments: (
    a,
    "-t7z",
    "-mx9",
    "-ms=on",
    "-xr!.DS_Store",
    "-xr!.localized",
    "-xr!._*",
    "-xr!.FBC*",
    "-xr!.Spotlight-V100",
    "-xr!.Trash",
    "-xr!.Trashes",
    "-xr!.background",
    "-xr!.TemporaryItems",
    "-xr!.fseventsd",
    "-xr!.com.apple.timemachine.*",
    "-xr!.VolumeIcon.icns",
    "/Users/ABCDE/Desktop/Affinity Photo.7z",
    "/Users/ABCDE/Desktop/Affinity Photo.app"
)
2020-03-05 13:00:46.966 Compression output: 

7-Zip [64] 16.02 : Copyright (c) 1999-2016 Igor Pavlov : 2016-05-21
p7zip Version 16.02 (locale=utf8,Utf16=on,HugeFiles=on,64 bits,12 CPUs x64)
Modified by aONe for Keka

Scanning the drive:
  0M Scan 
2020-03-05 13:00:47.106 Compression output: 
����������          ����������
2020-03-05 13:00:47.147 Compression output: 
511 folders, 12578 files, 1728141350 bytes (1649 MiB)

Creating archive: /Users/ABCDE/Desktop/Affinity Photo.7z

Items to compress: 13089

  0%
2020-03-05 13:00:47.347 Compression output: 
����    ����  0% 3139 + Affinity Photo.app/Contents/F . zh-Hans.lproj/NoiseEffect.nib
2020-03-05 13:00:47.547 Compression output: 
�������������������������������������������������������������������������                                                                         �������������������������������������������������������������������������  0% 6331 + Affinity Photo.app/Contents/R . roj/images/clipping_before.jpg
2020-03-05 13:00:47.747 Compression output: 
��������������������������������������������������������������������������                                                                          ��������������������������������������������������������������������������  0% 10418 + Affinity Photo.app/Contents/Resources/es.lproj/adjustments.strings
2020-03-05 13:00:47.957 Compression output: 
�������������������������������������������������������������������������������                                                                               �������������������������������������������������������������������������������  0% 11648 + Affinity Photo.app/Contents/Resources/raster_brushes.propcol
2020-03-05 13:00:48.165 Compression output: 
�������������������������������������������������������������������������                                                                         �������������������������������������������������������������������������  0% 12525 + Affinity Photo.app/Contents/_CodeSignature/CodeResources
2020-03-05 13:02:03.638 Compression output: 
�����������������������������������������������������������������������                                                                       �����������������������������������������������������������������������
2020-03-05 13:02:03.638 Compression output: 


System ERROR:

2020-03-05 13:02:03.938 done: 1
2020-03-05 13:02:03.944 Notify /Users/ABCDE/Desktop/Affinity Photo.7z with code 0
2020-03-05 13:02:04.051 Notification didDeliverNotification
2020-03-05 13:02:04.052 {
    code = 0;
    path = "/Users/ABCDE/Desktop/Affinity Photo.7z";
    type = 1;
}
2020-03-05 13:02:09.836 Cancelling auto-quit

Also, I see 7-Zip on Windows has printed their 7z.exe version as 19.00. The latest Keka still uses 16.02. That's kinda way behind unless there's a reason preventing an upgrade. Maybe related?

Edit: Also to add, Keka I used was from DMG downloaded from home page. I cannot try the MAS version, not a fan of Apple IDs.

[aonez]

@VaslD checking that one, I'll be back.

[aonez]

@VaslD this has to do with the sandbox protection of macOS. Not sure why yet but the compression of the Affinity Photo.app contents triggers a read/write in /private/tmp. Giving access to this folder in the File Access panel works around the issue (you can use shift + command + . to see hidden folders).

I need to investigate further, but those are the errors:

error	11:21:59.402585 +0100	sandboxd	Sandbox: keka7z(34173) deny(1) file-read-data /private/tmp
Violation:       deny(1) file-read-data /private/tmp 
Process:         keka7z [34173]
Path:            /Applications/Keka.app/Contents/Resources/keka7z
Load Address:    0x10ce25000
Identifier:      keka7z
Version:         ??? (???)
Code Type:       x86_64 (Native)
Parent Process:  Keka [1770]
Responsible:     /Applications/Keka.app/Contents/MacOS/Keka [1770]
User ID:         501

Date/Time:       2020-03-09 11:21:59.400 GMT+1
OS Version:      Mac OS X 10.14.6 (18G3020)
Report Version:  8


MetaData: {"vnode-type":"DIRECTORY","profile-flags":0,"build":"Mac OS X 10.14.6 (18G3020)","target":"\/private\/tmp","path":"\/private\/tmp","responsible-process-path":"\/Applications\/Keka.app\/Contents\/MacOS\/Keka","uid":501,"file-mode":1023,"operation":"file-read-data","file-flags":0,"platform-policy":false,"platform_binary":"no","hardware":"Mac","flags":5,"summary":"deny(1) file-read-data \/private\/tmp","process-path":"\/Applications\/Keka.app\/Contents\/Resources\/keka7z","normalized_target":["private","tmp"],"rdev":0,"primary-filter":"path","profile-in-collection":false,"team-id":"4FG648TM2A","signing-id":"com.aone.keka.keka7z","primary-filter-value":"\/private\/tmp","process":"keka7z","pid":34173,"errno":1,"responsible-process-pid":1770,"action":"deny","platform-binary":false,"container":"\/Users\/aone\/Library\/Containers\/com.aone.keka\/Data"}

error	11:21:59.408328 +0100	sandboxd	Sandbox: keka7z(34173) deny(1) file-write-create /private/tmp/7zt.D754CAC0.tmp
Violation:       deny(1) file-write-create /private/tmp/7zt.D754CAC0.tmp 
Process:         keka7z [34173]
Path:            /Applications/Keka.app/Contents/Resources/keka7z
Load Address:    0x10ce25000
Identifier:      keka7z
Version:         ??? (???)
Code Type:       x86_64 (Native)
Parent Process:  Keka [1770]
Responsible:     /Applications/Keka.app/Contents/MacOS/Keka [1770]
User ID:         501

Date/Time:       2020-03-09 11:21:59.407 GMT+1
OS Version:      Mac OS X 10.14.6 (18G3020)
Report Version:  8


MetaData: {"vnode-type":"REGULAR-FILE","profile-flags":0,"build":"Mac OS X 10.14.6 (18G3020)","target":"\/private\/tmp\/7zt.D754CAC0.tmp","path":"\/private\/tmp\/7zt.D754CAC0.tmp","responsible-process-path":"\/Applications\/Keka.app\/Contents\/MacOS\/Keka","suffix":"7zt.D754CAC0.tmp","uid":501,"operation":"file-write-create","file-flags":0,"platform-policy":false,"platform_binary":"no","hardware":"Mac","flags":5,"summary":"deny(1) file-write-create \/private\/tmp\/7zt.D754CAC0.tmp","process-path":"\/Applications\/Keka.app\/Contents\/Resources\/keka7z","normalized_target":["private","tmp","7zt.D754CAC0.tmp"],"rdev":0,"primary-filter":"path","profile-in-collection":false,"team-id":"4FG648TM2A","signing-id":"com.aone.keka.keka7z","primary-filter-value":"\/private\/tmp\/7zt.D754CAC0.tmp","process":"keka7z","pid":34173,"errno":1,"responsible-process-pid":1770,"action":"deny","platform-binary":false,"container":"\/Users\/aone\/Library\/Containers\/com.aone.keka\/Data"}

[VaslD]

Thank you for the quick workaround. It did the trick.

But it somewhat doesn't make sense. I can zip a folder from/to anywhere from places where I didn't put in File Access panel. In fact I only have ~/Downloads in File Access. I guess it was there only because of some first-install tips and I extracted Keka in Downloads or something. After I moved Keka to /Applications, I've been using it to zip apps (/Applications), documents (~/Documents), Homebrew stuff (somewhere in /usr/local) and Xcode stuff (somewhere in ~/Library/Developer), and I never gotten anything that said about File Access.

Before I added /private/tmp to File Access, I even went there and zipped a com.apple.* folder just wanted to see how special this tmp folder is, and it also worked! That's before I added the path in File Access.

I admit I don't know how sandboxing works on macOS under-the-hood but what I've seen so far and what I just described ain't logical. ☹️

[aonez]

@zeff013 do you still have the offending pvm files?

@VaslD already have this fixed for 1.1.26, without needing to add any folder to the file access list. Thanks a lot for all your feedback!

[zeff013]

Yes, I still have the offending PVM files, but I'm not able to reproduce the behaviour at the moment.
Last year I've used Storage Management.app to optimise local drive and get rid of purgeable space on the disk (by deleting those PVM files through the mentioned app and then restoring them from external backup drive).
For some reason macOS behaviour was different when deleting files through Finder.app and Storage Management.app.
At the moment I've got the following situation with space Available: 297,59 GB (62,58 GB purgeable). I'm not able to increase purgeable portion by downloading or creating some large files on my Mac and then deleting them with Finder.app.
Seems like macOS's behaviour has changed in this regards since last year.
When purgeable space is not (almost) equal to space available - p7zip error 2 is not reproducible with any files.

[aonez]

Thanks for the followup @zeff013. Glad to hear that :)

[zeff013]

Should I close this issue?

[aonez]

Sure let's close it. Reopen if happens again in the future. Thanks!