Error when running SuperDuper via shell script

[kbradnam]

Hi again,

I have a UNIX shell script which I run daily and this in turn just runs a few separate applescripts, each of which performs some specific backup task using SuperDuper.

I've noticed that the last of four backup applescripts fails on Mondays. This last script tells SuperDuper to backup all files on a volume using the Erase & Copy mode (the rest of the week it just adds new files).

The last few lines of SuperDuper log show:

13/15/3295253471-1649948923.cache: Operation not permitted
|05:51:16 PM|Error| rm: /Volumes/Home_backup/vince/Library/Caches/Safari/13/15/3526366423-1952403445.cache: Operation not permitted
|05:51:16 PM|Error| rm: /Volumes/Home_backup/vince/Library/Caches/Safari/13/15/4252024027-2937615615.cache: Operation not permitted
|05:51:16 PM|Error| rm: fts_read: Operation not permitted

At this point the script stops (presumably because it can't erase the target backup volume). But the odd thing is that this only occurs when I run the applescript as the last of four applescripts in a UNIX shell script. When I just run the apple script on its own (by double clicking in the finder) it seems to work ok, and it then deletes the files that it couldn't remove before.

I need to do more testing, because the second time I run the script by hand, there has obviously already been a lot of files deleted from the first failed attempt, so it is not exactly a fair comparison.

Any thoughts on this Dave?

Keith

[dnanian]

Well, there's one rather significant issue here: if it's using "rm" to delete the files, the volume was busy when it ran and it couldn't be quick erased (with Disk Utility). Do you know why that would be?

[kbradnam]

Hmm, disk utility won't let the target backup disk unmount. I'm not running anything which would be using the disk. I'll play around some more to see if I can narrow down the problem.

Thanks - as ever - for a quick reply.

Keith

[dnanian]

It might be useful to us "lsof" (list open files) to see what, if anything, is holding a file open over there...

[kbradnam]

Hi again,

I can repeat this problem quite easily now (which is a good starting point I suppose). I tried your suggestion of using 'lsof' to see if any files were open but that didn't reveal anything open on the problem disk.

I think the problem partly concerns the fact that SuperDuper can't unmount the target disk partition. Indeed I have found that I cannot eject it using Disk Utility. The only way I can eject it is with the UNIX command 'hdiutil eject -force' (and only when using the -force option).

After I unmount it this way, I can then use Disk Utility to mount and unmount it at leisure. So the remaining issues and areas of confusion are:

1) SuperDuper log reveals that it can't unmount but then tries the slower approach to erase the target partition before backup. It stops at a point when the log file reveals the following:
|03:49:19 PM|Error| rm: fts_read: Operation not permitted

But this isn't always in the same place in the log file. Sometimes it removes nearly all data and then complains, sometimes it complains after removing some data straight away.

2) I only seem to see this problem when the problem partition is removed as part of an apple-script launched SuperDuper *and* that apple-script is the last in a batch of four. When I launch the last apple-script directly, it runs ok.

Any suggestions on where I can look?

Keith

[dnanian]

Well, this is certainly interesting and curious, Keith. Very strange that lsof doesn't show anything open on the drive... why would it not want to unmount? Hm.

hdiutil eject -force wasn't available in Jaguar, so we weren't able to use it as a way to force an unmount. Doing so as a matter of course worries me a bit since the drive won't unmount for a reason, usually... but, at the same time, we go ahead and 'slow erase', which means we're really doing it anyway... so perhaps that's a workaround we can use.

I *think* that you're getting an error from rm because the drive is attempting to unmount in the middle of the slow erase -- or, rather, is finally getting around to unmounting, or trying to. That's a decent guess, I think, since the operation might be continuing asynchronously after the failure.

I can only suggest that it's a weird bug in OSX. We can try to work around it in the v2.0 timeframe by using hdiutil eject -force as part of the primary transcript. If you're feeling adventurous, you can edit the existing transcript for your case and rework the appropriate line to do the hdiutil yourself as the 'recovery', rather than the slow erase... might work for you, or be worth trying.