SD! Failures

[Nick]

The failures began last night: About 75% of the way through, SD! would simply stall. After an hour of waiting, I'd then press the "stop" button, get the usual "SD! ain't done yet...you sure you want to stop?" message. I'd say "yes," and that would be it....except that although it stopped, it remained open, and I had to either quit from within SD! itself, or force quit.

The only thing that caught my attention as being a bit "odd" was that although the SD! window indicates the usual:

---
What's going to happen?

Pressing "Copy Now" will use "Backup - all files" to copy Nick's HD to Nick's HD Clone ..."
----

the top portion indicates:

---
Copy Nick's HD to Nick's HD Clone 1
---

whereas in the past, I'm certain it simply said:

---
Copy Nick's HD to Nick's HD Clone
---

When I checked with DU, I found that the volume indeed had what I believe is a new "mount point":

Mount Point : /Volumes/Nick's HD Clone 1

(I don't know whether this apparent mount point change is significant or meaningful, but I though it worth mentioning.)

[Nick]

BTW: After the first failure, most of the SD! logs seemed to have vanished—only a handful from last month showed up. Subsequent failures didn't seem to suffer from that apparent loss.

FWIW, here's a copy of the most-recent log:

-----------
| 09:22:02 AM | Info | SuperDuper!, 2.6.2 (87), path: /Applications/SuperDuper!.app, Mac OS 10.5.8 build 9L31a (i386)
| 09:22:02 AM | Info | Started on Fri, Dec 11, 2009 at 9:22 AM
| 09:22:02 AM | Info | Source Volume: Nick's HD, mount: /, device: /dev/disk0s2, media: Hitachi HDP725032GLA380, interconnect: Internal SATA, file system: "Journaled HFS+", OS: 10.5.8 (9L31a), capacity: 297.77 GiB, used: 244.70 GiB, directories: 103654, files: 1075231, ejectable: NO, ACLs: Enabled
| 09:22:02 AM | Info | Target Volume: Nick's HD Clone, mount: /Volumes/Nick's HD Clone 1, device: /dev/disk4s5, media: LaCie d2 quadra, interconnect: External FireWire, file system: "Journaled HFS+", OS: 10.5.8 (9L31a), capacity: 348.30 GiB, used: 241.95 GiB, directories: 103251, files: 1076029, ejectable: YES, ACLs: Enabled
| 09:22:02 AM | Info | Copy Mode : Smart Update
| 09:22:02 AM | Info | Copy Script : Backup - all files.dset
| 09:22:02 AM | Info | Transcript : BuildTranscript.plist
| 09:22:02 AM | Info | PHASE: 1. Prepare to Copy Files
| 09:22:02 AM | Info | ...ACTION: Preparing Nick's HD
| 09:22:02 AM | Info | ......COMMAND => Verifying the integrity of volinfo.database
| 09:22:02 AM | Info | volinfo.database OK
| 09:22:02 AM | Info | ......COMMAND => Enabling permissions on Nick's HD
| 09:22:03 AM | Info | Refreshing Disk Arbitration ...
| 09:22:03 AM | Info | ......COMMAND => Verifying that permissions are enabled for Nick's HD
| 09:22:03 AM | Info | Permissions on '/' are enabled.
| 09:22:03 AM | Info | ...ACTION: Preparing Nick's HD Clone
| 09:22:03 AM | Info | ......COMMAND => Enabling permissions on Nick's HD Clone
| 09:22:03 AM | Info | Refreshing Disk Arbitration ...
| 09:22:03 AM | Info | ......COMMAND => Verifying that permissions are enabled for Nick's HD Clone
| 09:22:03 AM | Info | Permissions on '/Volumes/Nick's HD Clone 1' are enabled.
| 09:22:03 AM | Info | ......COMMAND => Verifying that Nick's HD Clone ACL support matches Nick's HD
| 09:22:03 AM | Info | ...ACTION: Preserving Spotlight state on Nick's HD Clone
| 09:22:03 AM | Info | ......COMMAND => Disabling Spotlight search indexing on Nick's HD Clone
| 09:22:03 AM | Info | PHASE: 2. Copy Files
| 09:22:03 AM | Info | ...ACTION: Copying files from Nick's HD to Nick's HD Clone using Smart Update
| 09:22:03 AM | Info | ......COMMAND => Cloning Nick's HD to Nick's HD Clone
| 09:22:03 AM | Info | Copying copy files with delete using script: /Users/Nick/Library/Application Support/SuperDuper!/Copy Scripts/Standard Scripts/Backup - all files.dset
| 09:22:04 AM | Info | Loading 27 commands from copy script /Applications/SuperDuper!.app/Contents/Resources/Copy Scripts/Exclude system temporary files.dset
| 09:22:04 AM | Info | Loading 6 commands from copy script /Applications/SuperDuper!.app/Contents/Resources/Copy Scripts/Exclude system cache files.dset
| 09:22:04 AM | Info | Loading 1 commands from copy script /Applications/SuperDuper!.app/Contents/Resources/Copy Scripts/Exclude Norton FileSaver files.dset
| 09:22:04 AM | Info | Loading 2 commands from copy script /Applications/SuperDuper!.app/Contents/Resources/Copy Scripts/Exclude Google Desktop Index files.dset
| 09:22:04 AM | Info | Loading 1 commands from copy script /Applications/SuperDuper!.app/Contents/Resources/Copy Scripts/Exclude iTunes Temporary files.dset
| 09:22:04 AM | Info | Loading 0 commands from copy script /Users/Nick/Library/Application Support/SuperDuper!/Copy Scripts/Standard Scripts/Backup - all files.dset
| 09:22:07 AM | Info | /
| 09:22:07 AM | Info | /.vol
| 09:22:07 AM | Info | Ignoring /.vol
| 09:22:07 AM | Info | /cores
| 09:22:07 AM | Info | /Network
| 09:22:07 AM | Info | /Copies of Backups
| 09:23:07 AM | Info | /bin
| 09:23:07 AM | Info | /System
| 09:24:01 AM | Info | /private
| 09:24:01 AM | Info | Ignoring /private/var/folders/-H
| 09:24:01 AM | Info | Ignoring /private/var/folders/Pi
| 09:24:01 AM | Info | Ignoring /private/var/folders/zz
| 09:24:04 AM | Info | Ignoring /private/var/vm/swapfile0
| 09:24:04 AM | Info | Ignoring /private/var/db/BootCache.playlist
| 09:24:04 AM | Info | Ignoring /private/var/db/volinfo.database
| 09:24:04 AM | Info | Ignoring /private/var/run/usbmuxd
| 09:24:04 AM | Info | Ignoring /private/var/run/syslog
| 09:24:04 AM | Info | Ignoring /private/var/run/mDNSResponder
| 09:24:04 AM | Info | Ignoring /private/var/run/cupsd
| 09:24:04 AM | Info | Ignoring /private/var/run/asl_input
| 09:24:04 AM | Info | Ignoring /private/var/run/syslog.pid
| 09:24:04 AM | Info | Ignoring /private/var/run/configd.pid
| 09:24:04 AM | Info | Ignoring /private/var/run/virusbarrierl.pid
| 09:24:04 AM | Info | Ignoring /private/var/run/diskarbitrationd.pid
| 09:24:04 AM | Info | Ignoring /private/var/run/DirectoryService.pid
| 09:24:04 AM | Info | Ignoring /private/var/run/mach.sym
| 09:24:04 AM | Info | Ignoring /private/var/run/netupdated.32
| 09:24:04 AM | Info | Ignoring /private/var/run/mds.pid
| 09:24:04 AM | Info | Ignoring /private/var/run/com.apple.blued.launchd
| 09:24:04 AM | Info | Ignoring /private/var/run/automount.initialized
| 09:24:04 AM | Info | Ignoring /private/var/run/appfwd.pid
| 09:24:04 AM | Info | Ignoring /private/var/run/vbsb.pid
| 09:24:04 AM | Info | Ignoring /private/var/run/pcscd.pub
| 09:24:04 AM | Info | Ignoring /private/var/run/macaronid.pid
| 09:24:04 AM | Info | Ignoring /private/var/run/vbsm.pid
| 09:24:04 AM | Info | Ignoring /private/var/run/ntpd.pid
| 09:24:04 AM | Info | Ignoring /private/var/run/utmpx
| 09:24:04 AM | Info | Ignoring /private/var/run/mds
| 09:24:04 AM | Info | Ignoring /private/var/run/pppconfd
| 09:24:04 AM | Info | Ignoring /private/var/run/portmap.socket
| 09:24:04 AM | Info | Ignoring /private/var/run/cron.pid
| 09:24:04 AM | Info | Ignoring /private/var/run/cups
| 09:24:04 AM | Info | Ignoring /private/var/run/.DSRunningSP1
| 09:24:04 AM | Info | Ignoring /private/var/tmp/.BlankFile
| 09:24:04 AM | Info | Ignoring /private/var/tmp/tmp.0.zqWEg8
| 09:24:04 AM | Info | Ignoring /private/var/tmp/tmp.1.1PW0iI
| 09:24:04 AM | Info | Ignoring /private/var/tmp/tmp.2.wfck3Q
| 09:24:04 AM | Info | Ignoring /private/var/tmp/com.apple.speech.synthesis.globals
| 09:24:04 AM | Info | Ignoring /private/var/tmp/BonjourPrinters.plist
| 09:24:04 AM | Info | Ignoring /private/var/tmp/Nick
| 09:24:04 AM | Info | Ignoring /private/var/tmp/launchd
| 09:24:04 AM | Info | Ignoring /private/var/tmp/mds
| 09:24:04 AM | Info | Ignoring /private/tmp/virusbarrier
| 09:24:04 AM | Info | Ignoring /private/tmp/MobileDevice.log
| 09:24:04 AM | Info | Ignoring /private/tmp/encyclopedia.shmsize
| 09:24:04 AM | Info | Ignoring /private/tmp/launchd-131.yXuKBy
| 09:24:04 AM | Info | Ignoring /private/tmp/launch-UHCz9x
| 09:24:04 AM | Info | Ignoring /private/tmp/launch-U2Rzai
| 09:24:04 AM | Info | Ignoring /private/tmp/launch-KaR1Be
| 09:24:04 AM | Info | Ignoring /private/tmp/icssuis501
| 09:24:04 AM | Info | Ignoring /private/tmp/ics217
| 09:24:04 AM | Info | Ignoring /private/tmp/target395.indexState
| 09:24:04 AM | Info | Ignoring /Desktop DF
| 09:24:04 AM | Info | Ignoring /Desktop DB
| 09:24:04 AM | Info | /Users
| 10:14:56 AM | Info | User terminated processing of transcript...
-----------

(Note that I actually didn't terminate SD! until after I received a dialog telling me that it had failed.)

[dnanian]

Yeah, that generally means that your backup drive failed and it remounted at a new location. Restart your Mac and see if it goes back to just the drive name without the 1.

[Nick]

Originally Posted by dnanian

Yeah, that generally means that your backup drive failed and it remounted at a new location. Restart your Mac and see if it goes back to just the drive name without the 1.

I've had to do several hard restarts (via the power button) since then. I just checked with DU, and the mount point still has "1" appended to the volume's name.

[dnanian]

Hard restarts aren't good, Nick - you're clearly experiencing some hardware issues here. But you can use Finder's "Go To Folder" command to open

/Volumes

You can delete the folder you'll find with the name of the backup drive there, then restart your Mac.

[Nick]

Originally Posted by dnanian

Hard restarts aren't good, Nick - you're clearly experiencing some hardware issues here. But you can use Finder's "Go To Folder" command to open

/Volumes

You can delete the folder you'll find with the name of the backup drive there, then restart your Mac.

Nick's HD Clone 1 (looks like an alias) or Nick's HD Clone (which looks more like an actual folder)?

[dnanian]

Folder only. Don't delete any aliases.

[Nick]

Originally Posted by dnanian

Folder only. Don't delete any aliases.

Interesting: I disconnected the drive, and only the "Nick's HD Clone" folder showed up—the alias wasn't there. So, apparently that folder was a "ghost" (for want of a better word) that remained, and which caused the "confusion."

I deleted it, reconnected the drive, and ran SD! again. Although SD! once again got hung up at approximately that same point in the backup process, after an extremely long "stall," it continued on to successfully complete the backup.

[dnanian]

It was likely copying a large file at that point, Nick.

[Nick]

Originally Posted by dnanian

It was likely copying a large file at that point, Nick.

SD! ran for an hour and 45 minutes...much longer than usual (it usually takes only about 30 minutes to run). Nothing much had changed on my machine since the previous backup, so I can't imagine what it could've been.

The only regularly changing files I have (which just happen to be the largest ones on my machine) are two Entourage database files, which grow only incrementally over time—they're currently about 5 GB each and haven't been changing much.

[dnanian]

If they change at all, they're copied in full. And if Entourage is running while you're backing up, they could end up filling the backup drive then shrinking on a recopy.

Quit Entourage -- and any programs that might have large, active data files -- before backing up.

[Nick]

Originally Posted by dnanian

If they change at all, they're copied in full. And if Entourage is running while you're backing up, they could end up filling the backup drive then shrinking on a recopy.

Quit Entourage -- and any programs that might have large, active data files -- before backing up.

Here's how it goes: One of those files is a "backup" that gets modified 5 times a day—never around the time SD! runs. The "main" file is the "active" one. (I have things set up so that the "main" file (which changes a lot during the day) is excluded from my Time Machine backups, and only the "backup" version is included. This way, I maintain a relatively recent backup of my email files without having TM go crazy every hour. )

But I'll keep a closer eye on what's going on when SD! kicks in...and I'll make certain that I'm not actively using Entourage (sending or receiving any email) while SD! is running.

[dnanian]

That would generally mean that SD! would copy two Entourage databases, the backup and the primary. But as I said, you must quit Entourage when backing up. Do not just 'not use it'. Quit it.

[Nick]

Originally Posted by dnanian

That would generally mean that SD! would copy two Entourage databases, the backup and the primary.

Yes, I know. (I was just responding to what you said re: SD! taking a long time because of a large file, explaining that the largest file on my drive is about 5 GB, and there are two of them.) But SD! got hung up only once, and if it were on one of those files, why wouldn't it get hung up a second time on the duplicate file?

But as I said, you must quit Entourage when backing up. Do not just 'not use it'. Quit it.

OK...got it!!!

(BTW: I assume that means that even when not in use, just being "open" could mean there is Entourage activity going on in the background that could interfere with SD!'s operations.)

[dnanian]

Correct, and it wouldn't necessarily be in a stable on-disk state.