View Full Version : Error when running SuperDuper via shell script
02-28-2005, 09:05 PM
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?
02-28-2005, 09:07 PM
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?
02-28-2005, 09:19 PM
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.
02-28-2005, 09:40 PM
It might be useful to us "lsof" (list open files) to see what, if anything, is holding a file open over there...
03-01-2005, 07:05 PM
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?
03-01-2005, 08:09 PM
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.
03-02-2005, 07:36 PM
Looking through the logs, it is always about 4-5 seconds after trying to unmount the target backup disk (and failing) that an 'rm: ... operation not permitted' error appears in the log files.
It is always on a different file that this error occurs, and always when I rerun the same script for a second time it will work without failing. This must be because most of the files are already erased by that point and so whilst it does still complain about not being able to unmount the target drive, it manages to complete the slow erase. So maybe it is like you say and the OS does finally start to unmount the disk, only 4-5 second after it said it couldn't.
I wonder if you could test by telling SuperDuper to sleep for 10 seconds after it tries unmounting?
Anyway, let me know what transcript file I need to change and I'll try the force eject method.
P.S. I take it then, that the default behaviour for the erase & copy and backup is to unmount the drive and then just erase the entire disk?
03-02-2005, 08:18 PM
Yes -- "erase then copy" erases, then copies. ;)
The transcript you'd change is "BuildTranscript.plist". The specific part is under "shouldEraseTarget", around line 40.
Note to lurkers -- skip this part. It's scary. You don't need to know this stuff to use SD! Nothing to see here. Move along!
What I'd basically do is:
Force the unmount
Perform the same erase logic with diskutil
Finally, I'd remove the slow erase logic, and replace with a relatively friendly error. So, the appropriate section would look something like (NOTE: UNTESTED, but should be right):
JNLD=$(diskutil info SDTargetVolumeMount.'Path | grep -q -F Journaled; echo $?);diskutil force unmount "SDTargetVolume.Device";diskutil mount "SDTargetVolume.Device";diskutil eraseVolume HFS+ SDTargetVolume.'Name SDBootableFlag SDTargetVolumeMount.'Path >&1 2>&1 | grep -q -F "Could not unmount"; if [ "$?" == "0" ]; then echo "Could not erase " SDTargetVolume.'Name "."; exit 2; fi; if [ $JNLD -eq 0 ]; then diskutil enableJournal "SDTargetVolume.Device"; fi
Note that I didn't use hdiutil, because it's documented for use with images, not disks (even though it seemed to work for you).
Hope that's reasonably easy to follow! Let me know if it works.
03-09-2005, 02:07 PM
Finally got around to trying this hack today. It didn't work, the log file says:
diskutil <verb> with no options will provide help on that verb
I think it has to be 'diskutil unmount force' rather 'diskutil force unmount'. So I edited the transcript again and reran the backup. This time it got a little further before stopping, the log file says:
|11:03:39 AM|Info| ...ACTION: Erase Home_backup
|11:03:39 AM|Info| ......COMMAND => Erasing Home_backup
|11:03:41 AM|Info| Disk Utility Tool ?2002-2003, Apple Computer, Inc.
|11:03:41 AM|Info| Usage: diskutil [mount(Disk)|unmount(Disk)|eject] <force>
|11:03:41 AM|Info| [Mount Point|Disk Identifier|Device Node]
|11:03:41 AM|Info| Mount, unmount or eject disks or volumes.
|11:03:41 AM|Info| force is only valid on unmount or unmountDisk.
|11:03:41 AM|Info| Example: diskutil unmount /Volumes/SomeDisk
|11:03:42 AM|Info| Volume /dev/disk1s5 mounted
|11:03:46 AM|Info| Could not erase Home_backup .
|11:03:46 AM|Error| ****FAILED****: result=512 errno=1 (Operation not permitted)
So there is still a syntax issue I guess. Does it have to use the 'unmountDisk' option rather than 'unmount'?
03-09-2005, 05:12 PM
You're right -- the line does have to be "unmount force", but when I tried it on the command line it worked:
[g5:~] dnanian% diskutil unmount force /dev/disk2s2
Volume /dev/disk2s2 force unmounted
(where /dev/disk2s2 was a mounted image -- worked fine)
I then took the line, with the swap of force and unmount, and did the part up to the erase, manually substituting:
sh-2.05b$ JNLD=$(diskutil info "/Volumes/Macintosh HD 1" | grep -q -F Journaled; echo $?);diskutil unmount force "/dev/disk2s2";diskutil mount "/dev/disk2s2";
Volume /dev/disk2s2 force unmounted
Volume /dev/disk2s2 mounted
So, it looks like it works... maybe your edit changed the syntax a bit?
vBulletin® v3.8.6, Copyright ©2000-2013, Jelsoft Enterprises Ltd.