PDA

View Full Version : SuperDuper! Failure


Nick
06-10-2009, 04:37 PM
I have SD! scheduled to do a daily backup. The last one (early this morning) failed. I was able to retrieve information from the log, and it had a series of error entries:

...
...
...

| 01:17:59 AM | Info | /.Spotlight-V100
| 01:17:59 AM | Info | Preserving /.Spotlight-V100
| 01:17:59 AM | Info | Ignoring /Desktop DF
| 01:17:59 AM | Info | /Users
| 01:18:35 AM | Error | LOGGED EXCEPTION: NSAccessibilityException, reason: "AXEnabled" attribute unsupported by: <NSPanel: 0x1c9edfa0>, userInfo: {NSAccessibilityErrorCodeExceptionInfo = -25205;}
| 01:18:35 AM | Error | LOGGED EXCEPTION: NSAccessibilityException, reason: "AXChildren" attribute unsupported by: <_NSThemeCloseWidgetCell: 0x1ca034c0>, userInfo: {NSAccessibilityErrorCodeExceptionInfo = -25205;}
| 01:18:35 AM | Error | LOGGED EXCEPTION: NSAccessibilityException, reason: "AXChildren" attribute unsupported by: <_NSThemeWidgetCell: 0x1ca02140>, userInfo: {NSAccessibilityErrorCodeExceptionInfo = -25205;}
| 01:18:35 AM | Error | LOGGED EXCEPTION: NSAccessibilityException, reason: "AXChildren" attribute unsupported by: <_NSThemeWidgetCell: 0x1c9e4530>, userInfo: {NSAccessibilityErrorCodeExceptionInfo = -25205;}
| 01:18:35 AM | Error | LOGGED EXCEPTION: NSAccessibilityException, reason: "AXChildren" attribute unsupported by: <NSButtonCell: 0x1ca1ec10>, userInfo: {NSAccessibilityErrorCodeExceptionInfo = -25205;}
| 01:18:35 AM | Error | LOGGED EXCEPTION: NSAccessibilityException, reason: "AXChildren" attribute unsupported by: <NSButtonCell: 0x1c96a7c0>, userInfo: {NSAccessibilityErrorCodeExceptionInfo = -25205;}
| 01:18:35 AM | Error | LOGGED EXCEPTION: NSAccessibilityException, reason: "AXChildren" attribute unsupported by: <NSButtonCell: 0x1c962270>, userInfo: {NSAccessibilityErrorCodeExceptionInfo = -25205;}
| 01:18:35 AM | Error | LOGGED EXCEPTION: NSAccessibilityException, reason: "AXChildren" attribute unsupported by: <NSButtonCell: 0x1c928390>, userInfo: {NSAccessibilityErrorCodeExceptionInfo = -25205;}


An SD! failure has only happened to me a few times before, and it was the kind of thing that took care of itself after I rebooted and manually ran the backup. Today, rebooting didn't help. In fact, I found the iMac to be rather unresponsive while SD! was attempting to create its backup (the spinning beachball kept on appearing). After a short while, SD! seemed to stall after having run through what appeared to be approximately the same number of files (about 0.5 million), and I had to quit SD! I repeatedly attempted a manual backup (usually after rebooting), but each time the results were the same: SD! would stall, and I’d have to quit. The last time it happened (a short while ago) I checked the log, and found that SD! was stalling at about the same point in its activity; after about a half hour of no further activity, I quit SD!:

...
...
...

| 10:52:37 AM | Info | /.Spotlight-V100
| 10:52:37 AM | Info | Preserving /.Spotlight-V100
| 10:52:37 AM | Info | Ignoring /Desktop DF
| 10:52:37 AM | Info | /Users
| 11:24:36 AM | Info | User terminated processing of transcript...


I ran Disk Utility as well as TechTool Pro, and both drives (internal and external SD!) appeared to be fine.

Suggestions?

Nick
06-11-2009, 03:04 AM
The very next scheduled backup just ran...and failed. Here is the content of the log (which went on for 458 letter-size pages!):

-----------------------------------------

| 01:15:28 AM | Info | SuperDuper!, 2.5 (84), path: /Applications/SuperDuper!/SuperDuper!.app, Mac OS 10.5.6 build 9G55 (i386)
| 01:15:28 AM | Info | Started on Thu, Jun 11, 2009 at 1:15 AM
| 01:15:28 AM | Info | Source Volume: Nick's HD, mount: /, device: /dev/disk0s2, media: Hitachi HDP725032GLA380, interconnect: Internal SATA, file system: "Journaled HFS+", OS: 10.5.6 (9G55), capacity: 297.77 GB, used: 243.77 GB, directories: 166345, files: 1367306, ejectable: NO, ACLs: Enabled
| 01:15:28 AM | Info | Target Volume: Nick's HD Clone, mount: /Volumes/Nick's HD Clone, device: /dev/disk4s5, media: LaCie d2 quadra, interconnect: External FireWire, file system: "Journaled HFS+", OS: 10.5.6 (9G55), capacity: 348.30 GB, used: 239.54 GB, directories: 163031, files: 1353813, ejectable: NO, ACLs: Enabled
| 01:15:28 AM | Info | Copy Mode : Smart Update
| 01:15:28 AM | Info | Copy Script : Backup - all files.dset
| 01:15:28 AM | Info | Transcript : BuildTranscript.plist
| 01:15:29 AM | Info | PHASE: 1. Prepare to Copy Files
| 01:15:29 AM | Info | ...ACTION: Preparing Nick's HD
| 01:15:29 AM | Info | ......COMMAND => Verifying the integrity of volinfo.database
| 01:15:29 AM | Info | volinfo.database OK
| 01:15:29 AM | Info | ......COMMAND => Enabling permissions on Nick's HD
| 01:15:29 AM | Info | Refreshing Disk Arbitration ...
| 01:15:29 AM | Info | ......COMMAND => Verifying that permissions are enabled for Nick's HD
| 01:15:29 AM | Info | Permissions on '/' are enabled.
| 01:15:29 AM | Info | ...ACTION: Preparing Nick's HD Clone
| 01:15:29 AM | Info | ......COMMAND => Enabling permissions on Nick's HD Clone
| 01:15:29 AM | Info | Refreshing Disk Arbitration ...
| 01:15:30 AM | Info | ......COMMAND => Verifying that permissions are enabled for Nick's HD Clone
| 01:15:30 AM | Info | Permissions on '/Volumes/Nick's HD Clone' are enabled.
| 01:15:30 AM | Info | ......COMMAND => Verifying that Nick's HD Clone ACL support matches Nick's HD
| 01:15:30 AM | Info | ...ACTION: Preserving Spotlight state on Nick's HD Clone
| 01:15:30 AM | Info | ......COMMAND => Disabling Spotlight search indexing on Nick's HD Clone
| 01:15:30 AM | Info | PHASE: 2. Copy Files
| 01:15:30 AM | Info | ...ACTION: Copying files from Nick's HD to Nick's HD Clone using Smart Update
| 01:15:30 AM | Info | ......COMMAND => Cloning Nick's HD to Nick's HD Clone
| 01:15:30 AM | Info | Copying copy files with delete using script: /Users/Nick/Library/Application Support/SuperDuper!/Copy Scripts/Standard Scripts/Backup - all files.dset
| 01:15:31 AM | Info | Loading 22 commands from copy script /Applications/SuperDuper!/SuperDuper!.app/Contents/Resources/Copy Scripts/Exclude system temporary files.dset
| 01:15:31 AM | Info | Loading 6 commands from copy script /Applications/SuperDuper!/SuperDuper!.app/Contents/Resources/Copy Scripts/Exclude system cache files.dset
| 01:15:31 AM | Info | Loading 1 commands from copy script /Applications/SuperDuper!/SuperDuper!.app/Contents/Resources/Copy Scripts/Exclude Norton FileSaver files.dset
| 01:15:31 AM | Info | Loading 1 commands from copy script /Applications/SuperDuper!/SuperDuper!.app/Contents/Resources/Copy Scripts/Exclude Google Desktop Index files.dset
| 01:15:31 AM | Info | Loading 1 commands from copy script /Applications/SuperDuper!/SuperDuper!.app/Contents/Resources/Copy Scripts/Exclude iTunes Temporary files.dset
| 01:15:31 AM | Info | Loading 0 commands from copy script /Users/Nick/Library/Application Support/SuperDuper!/Copy Scripts/Standard Scripts/Backup - all files.dset
| 01:15:31 AM | Info | /
| 01:15:34 AM | Info | /.vol
| 01:15:34 AM | Info | Ignoring /.vol
| 01:15:34 AM | Info | /cores
| 01:15:34 AM | Info | /Network
| 01:15:34 AM | Info | /private
| 01:15:46 AM | Info | Ignoring /private/var/run/syslog.pid
| 01:15:46 AM | Info | Ignoring /private/var/run/configd.pid
| 01:15:46 AM | Info | Ignoring /private/var/run/DirectoryService.pid
| 01:15:46 AM | Info | Ignoring /private/var/run/virusbarrierl.pid
| 01:15:46 AM | Info | Ignoring /private/var/run/mach.sym
| 01:15:46 AM | Info | Ignoring /private/var/run/diskarbitrationd.pid
| 01:15:46 AM | Info | Ignoring /private/var/run/com.apple.blued.launchd
| 01:15:46 AM | Info | Ignoring /private/var/run/mds.pid
| 01:15:46 AM | Info | Ignoring /private/var/run/automount.initialized
| 01:15:46 AM | Info | Ignoring /private/var/run/macaronid.pid
| 01:15:46 AM | Info | Ignoring /private/var/run/appfwd.pid
| 01:15:46 AM | Info | Ignoring /private/var/run/pcscd.pub
| 01:15:46 AM | Info | Ignoring /private/var/run/ntpd.pid
| 01:15:46 AM | Info | Ignoring /private/var/run/vbsb.pid
| 01:15:46 AM | Info | Ignoring /private/var/run/mds
| 01:15:46 AM | Info | Ignoring /private/var/run/cron.pid
| 01:15:46 AM | Info | Ignoring /private/var/run/vbsm.pid
| 01:15:46 AM | Info | Ignoring /private/var/run/utmpx
| 01:15:46 AM | Info | Ignoring /private/var/run/resolv.conf
| 01:15:46 AM | Info | Ignoring /private/var/run/cups
| 01:15:46 AM | Info | Ignoring /private/var/run/hdiejectd.pid
| 01:15:47 AM | Info | Ignoring /private/var/db/BootCache.playlist
| 01:15:47 AM | Info | Ignoring /private/var/db/volinfo.database
| 01:15:47 AM | Info | Ignoring /private/var/vm/swapfile0
| 01:15:47 AM | Info | Ignoring /private/var/vm/swapfile1
| 01:15:47 AM | Info | Ignoring /private/var/vm/swapfile2
| 01:15:47 AM | Info | Ignoring /private/var/vm/swapfile3
| 01:15:47 AM | Info | Ignoring /private/var/vm/swapfile4
| 01:15:47 AM | Info | Ignoring /private/var/vm/swapfile5
| 01:15:47 AM | Info | Ignoring /private/var/tmp/com.apple.speech.synthesis.globals
| 01:15:47 AM | Info | Ignoring /private/var/tmp/sh-thd-3636534418
| 01:15:47 AM | Info | Ignoring /private/var/tmp/krb5_RC56aaa
| 01:15:47 AM | Info | Ignoring /private/var/tmp/sh-thd-3655676680
| 01:15:47 AM | Info | Ignoring /private/var/tmp/krb5kdc_rcache
| 01:15:47 AM | Info | Ignoring /private/var/tmp/sh-thd-1223478919
| 01:15:47 AM | Info | Ignoring /private/var/tmp/sh-thd-1223478057
| 01:15:47 AM | Info | Ignoring /private/var/tmp/tmp.0.Q7UyzF.html
| 01:15:47 AM | Info | Ignoring /private/var/tmp/etilqs_vIjPKZG28aKOKHw
| 01:15:47 AM | Info | Ignoring /private/var/tmp/psOutput
| 01:15:47 AM | Info | Ignoring /private/var/tmp/launchd
| 01:15:47 AM | Info | Ignoring /private/var/tmp/mds
| 01:15:47 AM | Info | Ignoring /private/var/tmp/com.micromat.TechToolPro4.plist
| 01:15:47 AM | Info | Ignoring /private/tmp/virusbarrier
| 01:15:47 AM | Info | Ignoring /private/tmp/encyclopedia.shmsize
| 01:15:47 AM | Info | Ignoring /private/tmp/launchd-178.1i4N7j
| 01:15:47 AM | Info | Ignoring /private/tmp/launch-eP53fw
| 01:15:47 AM | Info | Ignoring /private/tmp/launch-RdOzin
| 01:15:47 AM | Info | Ignoring /private/tmp/launch-2ZnixA
| 01:15:47 AM | Info | Ignoring /private/tmp/amt.log
| 01:15:47 AM | Info | Ignoring /private/tmp/VBXAlertPID
| 01:15:47 AM | Info | Ignoring /private/tmp/hsperfdata_Nick
| 01:15:47 AM | Info | Ignoring /private/tmp/libswt-pi-carbon-3436.jnilib
| 01:15:47 AM | Info | Ignoring /private/tmp/libswt-carbon-3436.jnilib
| 01:15:47 AM | Info | Ignoring /private/tmp/libswt-cocoa-carbon-3436.jnilib
| 01:15:47 AM | Info | Ignoring /private/tmp/AZU11410.tmp
| 01:15:47 AM | Info | Ignoring /private/tmp/target.indexState
| 01:15:47 AM | Info | /.Spotlight-V100
| 01:15:47 AM | Info | Preserving /.Spotlight-V100
| 01:15:50 AM | Info | Ignoring /Desktop DF
| 01:15:50 AM | Info | /Users
| 01:18:32 AM | Info | Unable to create hard link from /Volumes/Nick's HD Clone/Users/Nick/Library/Safari/lock to (null)
| 01:18:32 AM | Info | Does not exist: (null)
| 01:18:32 AM | Info | Does not exist: (null)





(Repeats for over 450 pages!)




| 01:18:35 AM | Info | Does not exist: (null)
| 01:18:35 AM | Info | Does not exist: (null)
| 01:18:35 AM | Info | Does not exist: (null)
| 01:18:35 AM | Info | Does not exist: (null)
| 01:18:40 AM | Error | ****FAILED****: result=11 errno=22 (Unknown error: 0)

-----------------------------------------

I'm at a loss as to what's going on. All I know is that I no longer can use SD! to clone my drive (which makes me feel very vulnerable).


Can anyone please help?


TIA.

dnanian
06-11-2009, 06:44 AM
Yes. The problem here is that you were running Safari while we were backing up, and it created (and deleted) that 'lock' file as we were copying (and deleted it out from under us).

Repeat the backup after quitting Safari and it should work fine.

Nick
06-11-2009, 04:10 PM
Yes. The problem here is that you were running Safari while we were backing up, and it created (and deleted) that 'lock' file as we were copying (and deleted it out from under us).

Repeat the backup after quitting Safari and it should work fine.

Hi Dave. Thanks for responding (especially so early in the morning! ;) ).

Well, I’ve often had apps running (including Safari) while SD! was creating backups, and never had a problem. And looking at the log from the initial SD! failure as well as the subsequent attempt to manually run SD! (see my initial post), there is no mention of Safari. (Moreover, as I was running into a lot of spinning beachballs, I specifically made sure I had quit all apps while attempting subsequent manual backups.)

Nevertheless, I did again try a manual backup, and pretty much had the same result: It stalled after about 0.5 million files; I waited a while (about 15 more minutes), and then quit. Here is the complete log:

-----------------------------------------------------------------------
| 10:19:54 AM | Info | SuperDuper!, 2.5 (84), path: /Applications/SuperDuper!/SuperDuper!.app, Mac OS 10.5.6 build 9G55 (i386)
| 10:19:54 AM | Info | Started on Thu, Jun 11, 2009 at 10:19 AM
| 10:19:54 AM | Info | Source Volume: Nick's HD, mount: /, device: /dev/disk0s2, media: Hitachi HDP725032GLA380, interconnect: Internal SATA, file system: "Journaled HFS+", OS: 10.5.6 (9G55), capacity: 297.77 GB, used: 243.82 GB, directories: 166343, files: 1367761, ejectable: NO, ACLs: Enabled
| 10:19:54 AM | Info | Target Volume: Nick's HD Clone, mount: /Volumes/Nick's HD Clone, device: /dev/disk4s5, media: LaCie d2 quadra, interconnect: External FireWire, file system: "Journaled HFS+", OS: 10.5.6 (9G55), capacity: 348.30 GB, used: 239.60 GB, directories: 163065, files: 1354044, ejectable: NO, ACLs: Enabled
| 10:19:54 AM | Info | Copy Mode : Smart Update
| 10:19:54 AM | Info | Copy Script : Backup - all files.dset
| 10:19:54 AM | Info | Transcript : BuildTranscript.plist
| 10:19:54 AM | Info | PHASE: 1. Prepare to Copy Files
| 10:19:54 AM | Info | ...ACTION: Preparing Nick's HD
| 10:19:54 AM | Info | ......COMMAND => Verifying the integrity of volinfo.database
| 10:19:55 AM | Info | volinfo.database OK
| 10:19:55 AM | Info | ......COMMAND => Enabling permissions on Nick's HD
| 10:19:55 AM | Info | Refreshing Disk Arbitration ...
| 10:19:55 AM | Info | ......COMMAND => Verifying that permissions are enabled for Nick's HD
| 10:19:55 AM | Info | Permissions on '/' are enabled.
| 10:19:55 AM | Info | ...ACTION: Preparing Nick's HD Clone
| 10:19:55 AM | Info | ......COMMAND => Enabling permissions on Nick's HD Clone
| 10:19:55 AM | Info | Refreshing Disk Arbitration ...
| 10:19:55 AM | Info | ......COMMAND => Verifying that permissions are enabled for Nick's HD Clone
| 10:19:55 AM | Info | Permissions on '/Volumes/Nick's HD Clone' are enabled.
| 10:19:55 AM | Info | ......COMMAND => Verifying that Nick's HD Clone ACL support matches Nick's HD
| 10:19:56 AM | Info | ...ACTION: Preserving Spotlight state on Nick's HD Clone
| 10:19:56 AM | Info | ......COMMAND => Disabling Spotlight search indexing on Nick's HD Clone
| 10:19:56 AM | Info | PHASE: 2. Copy Files
| 10:19:56 AM | Info | ...ACTION: Copying files from Nick's HD to Nick's HD Clone using Smart Update
| 10:19:56 AM | Info | ......COMMAND => Cloning Nick's HD to Nick's HD Clone
| 10:19:56 AM | Info | Copying copy files with delete using script: /Users/Nick/Library/Application Support/SuperDuper!/Copy Scripts/Standard Scripts/Backup - all files.dset
| 10:19:56 AM | Info | Loading 22 commands from copy script /Applications/SuperDuper!/SuperDuper!.app/Contents/Resources/Copy Scripts/Exclude system temporary files.dset
| 10:19:56 AM | Info | Loading 6 commands from copy script /Applications/SuperDuper!/SuperDuper!.app/Contents/Resources/Copy Scripts/Exclude system cache files.dset
| 10:19:56 AM | Info | Loading 1 commands from copy script /Applications/SuperDuper!/SuperDuper!.app/Contents/Resources/Copy Scripts/Exclude Norton FileSaver files.dset
| 10:19:56 AM | Info | Loading 1 commands from copy script /Applications/SuperDuper!/SuperDuper!.app/Contents/Resources/Copy Scripts/Exclude Google Desktop Index files.dset
| 10:19:56 AM | Info | Loading 1 commands from copy script /Applications/SuperDuper!/SuperDuper!.app/Contents/Resources/Copy Scripts/Exclude iTunes Temporary files.dset
| 10:19:56 AM | Info | Loading 0 commands from copy script /Users/Nick/Library/Application Support/SuperDuper!/Copy Scripts/Standard Scripts/Backup - all files.dset
| 10:19:56 AM | Info | /
| 10:19:59 AM | Info | /.vol
| 10:19:59 AM | Info | Ignoring /.vol
| 10:19:59 AM | Info | /cores
| 10:19:59 AM | Info | /Network
| 10:19:59 AM | Info | /private
| 10:20:09 AM | Info | Ignoring /private/var/vm/swapfile0
| 10:20:09 AM | Info | Ignoring /private/var/vm/swapfile1
| 10:20:09 AM | Info | Ignoring /private/var/vm/swapfile2
| 10:20:09 AM | Info | Ignoring /private/var/vm/swapfile3
| 10:20:09 AM | Info | Ignoring /private/var/vm/swapfile4
| 10:20:09 AM | Info | Ignoring /private/var/vm/swapfile5
| 10:20:09 AM | Info | Ignoring /private/var/db/BootCache.playlist
| 10:20:09 AM | Info | Ignoring /private/var/db/volinfo.database
| 10:20:09 AM | Info | Ignoring /private/var/run/syslog.pid
| 10:20:09 AM | Info | Ignoring /private/var/run/configd.pid
| 10:20:09 AM | Info | Ignoring /private/var/run/DirectoryService.pid
| 10:20:09 AM | Info | Ignoring /private/var/run/virusbarrierl.pid
| 10:20:09 AM | Info | Ignoring /private/var/run/mach.sym
| 10:20:09 AM | Info | Ignoring /private/var/run/diskarbitrationd.pid
| 10:20:09 AM | Info | Ignoring /private/var/run/com.apple.blued.launchd
| 10:20:09 AM | Info | Ignoring /private/var/run/mds.pid
| 10:20:09 AM | Info | Ignoring /private/var/run/automount.initialized
| 10:20:09 AM | Info | Ignoring /private/var/run/macaronid.pid
| 10:20:09 AM | Info | Ignoring /private/var/run/appfwd.pid
| 10:20:09 AM | Info | Ignoring /private/var/run/pcscd.pub
| 10:20:09 AM | Info | Ignoring /private/var/run/ntpd.pid
| 10:20:09 AM | Info | Ignoring /private/var/run/vbsb.pid
| 10:20:09 AM | Info | Ignoring /private/var/run/mds
| 10:20:09 AM | Info | Ignoring /private/var/run/cron.pid
| 10:20:09 AM | Info | Ignoring /private/var/run/vbsm.pid
| 10:20:09 AM | Info | Ignoring /private/var/run/utmpx
| 10:20:09 AM | Info | Ignoring /private/var/run/cups
| 10:20:09 AM | Info | Ignoring /private/var/run/hdiejectd.pid
| 10:20:09 AM | Info | Ignoring /private/var/run/resolv.conf
| 10:20:09 AM | Info | Ignoring /private/var/tmp/com.apple.speech.synthesis.globals
| 10:20:09 AM | Info | Ignoring /private/var/tmp/sh-thd-3636534418
| 10:20:09 AM | Info | Ignoring /private/var/tmp/krb5_RC56aaa
| 10:20:09 AM | Info | Ignoring /private/var/tmp/sh-thd-3655676680
| 10:20:09 AM | Info | Ignoring /private/var/tmp/krb5kdc_rcache
| 10:20:09 AM | Info | Ignoring /private/var/tmp/sh-thd-1223478919
| 10:20:09 AM | Info | Ignoring /private/var/tmp/sh-thd-1223478057
| 10:20:09 AM | Info | Ignoring /private/var/tmp/tmp.0.Q7UyzF.html
| 10:20:09 AM | Info | Ignoring /private/var/tmp/etilqs_vIjPKZG28aKOKHw
| 10:20:09 AM | Info | Ignoring /private/var/tmp/psOutput
| 10:20:09 AM | Info | Ignoring /private/var/tmp/launchd
| 10:20:09 AM | Info | Ignoring /private/var/tmp/mds
| 10:20:09 AM | Info | Ignoring /private/var/tmp/com.micromat.TechToolPro4.plist
| 10:20:09 AM | Info | Ignoring /private/tmp/virusbarrier
| 10:20:09 AM | Info | Ignoring /private/tmp/encyclopedia.shmsize
| 10:20:09 AM | Info | Ignoring /private/tmp/launchd-178.1i4N7j
| 10:20:09 AM | Info | Ignoring /private/tmp/launch-eP53fw
| 10:20:09 AM | Info | Ignoring /private/tmp/launch-RdOzin
| 10:20:09 AM | Info | Ignoring /private/tmp/launch-2ZnixA
| 10:20:09 AM | Info | Ignoring /private/tmp/amt.log
| 10:20:09 AM | Info | Ignoring /private/tmp/VBXAlertPID
| 10:20:09 AM | Info | Ignoring /private/tmp/libswt-pi-carbon-3436.jnilib
| 10:20:09 AM | Info | Ignoring /private/tmp/libswt-carbon-3436.jnilib
| 10:20:09 AM | Info | Ignoring /private/tmp/libswt-cocoa-carbon-3436.jnilib
| 10:20:09 AM | Info | Ignoring /private/tmp/AZU11410.tmp
| 10:20:09 AM | Info | Ignoring /private/tmp/hsperfdata_Nick
| 10:20:09 AM | Info | Ignoring /private/tmp/target.indexState
| 10:20:09 AM | Info | /.Spotlight-V100
| 10:20:09 AM | Info | Preserving /.Spotlight-V100
| 10:20:12 AM | Info | Ignoring /Desktop DF
| 10:20:12 AM | Info | /Users
| 10:34:13 AM | Info | User terminated processing of transcript...
-----------------------------------------------------------------------

(continued...)

Nick
06-11-2009, 04:11 PM
(...continued)

Now, being rather stubborn ;), I decided to try another manual run, but not quit if and when it stalled. This time it stalled as it did before (again, after about 0.5 million files). However, I decided to let it run, to see if SD! would eventually issue a failure notification. This time, after about a half hour being stalled, SD! resumed, and eventually completed a successful run. When I examined the log, it appeared to be identical to the previous log (the one above), except that after SD! resumed, there were (of course) additional entries:

-----------------------------------------------------------------------
| 01:33:37 PM | Info | SuperDuper!, 2.5 (84), path: /Applications/SuperDuper!/SuperDuper!.app, Mac OS 10.5.6 build 9G55 (i386)
| 01:33:37 PM | Info | Started on Thu, Jun 11, 2009 at 1:33 PM




(Same entries as previous log)




| 01:33:58 PM | Info | /.Spotlight-V100
| 01:33:58 PM | Info | Preserving /.Spotlight-V100
| 01:33:58 PM | Info | Ignoring /Desktop DF
| 01:33:58 PM | Info | /Users
| 02:01:39 PM | Info | Ignoring /Desktop DB
| 02:01:39 PM | Info | /Developer
| 02:03:39 PM | Info | /usr
| 02:04:09 PM | Info | /.TemporaryItems
| 02:04:09 PM | Info | Ignoring /.hotfiles.btree
| 02:04:09 PM | Info | /Copies of Backups
| 02:05:46 PM | Info | /bin
| 02:05:46 PM | Info | /System
| 02:07:01 PM | Info | /sbin
| 02:07:01 PM | Info | /Library
| 02:12:30 PM | Info | /.Trashes
| 02:12:30 PM | Info | /dev
| 02:12:30 PM | Info | /net
| 02:12:30 PM | Info | /home
| 02:12:30 PM | Info | /Applications
| 02:21:01 PM | Info | /Volumes
| 02:21:01 PM | Info | Ignoring /Volumes/.DS_Store
| 02:21:01 PM | Info | Ignoring /Volumes/TechTool Pro 4 DVD
| 02:21:01 PM | Info | Ignoring /Volumes/Mac OS X Install Disc 1
| 02:21:01 PM | Info | Ignoring /Volumes/DiskWarriorCD
| 02:21:01 PM | Info | Ignoring /Volumes/Mac OS X Install Disc 2
| 02:21:01 PM | Info | Ignoring /Volumes/.vbt5
| 02:21:01 PM | Info | Ignoring /Volumes/Nick's HD Clone
| 02:21:01 PM | Info | Ignoring /Volumes/Nick's HD
| 02:21:01 PM | Info | Ignoring /Volumes/CompUSA Western Digital
| 02:21:01 PM | Info | Ignoring /Volumes/Seagate Barracuda
| 02:21:01 PM | Info | Ignoring /Volumes/LaCie
| 02:21:01 PM | Info | Ignoring /Volumes/LaCie d2 Quadra
| 02:21:01 PM | Info | /.fseventsd
| 02:21:01 PM | Info | Preserving /.fseventsd
| 02:21:01 PM | Info | Evaluated 1527818 items occupying 242.91 GB (166348 directories, 1326844 files, 34626 symlinks)
| 02:21:01 PM | Info | Copied 27573 items totaling 12.25 GB (11904 directories, 15568 files, 101 symlinks)
| 02:21:01 PM | Info | Cloned 240.28 GB of data in 2842 seconds at an effective transfer rate of 86.58 MB/s
| 02:21:01 PM | Info | ......COMMAND => Resetting Custom Icon bit on Nick's HD Clone
| 02:21:01 PM | Info | PHASE: 3. After Successful Copy
| 02:21:01 PM | Info | ...ACTION: Making Nick's HD Clone bootable
| 02:21:01 PM | Info | ......COMMAND => Blessing OS X System Folder
| 02:21:02 PM | Info | Successfully blessed Mac OS X folder on Nick's HD Clone
| 02:21:02 PM | Info | ......COMMAND => Blessing OS 9 System Folder
| 02:21:02 PM | Info | Did not bless Mac OS 9 System Folder on Nick's HD Clone because it does not exist.
| 02:21:02 PM | Info | ...ACTION: Restoring Spotlight state on Nick's HD Clone
| 02:21:02 PM | Info | ......COMMAND => Restoring Spotlight search indexing state on Nick's HD Clone
| 02:21:02 PM | Info | Copy complete.
-----------------------------------------------------------------------

Any idea what may have been happening—i.e., why the scheduled SD! failed to begin with, why subsequent manual attempts “stalled,” why the next scheduled backup also failed, and why it seems to be working now (though I won’t know until the next scheduled backup whether everything is “back to normal”)?

Thanks.

Nick

dnanian
06-12-2009, 02:09 PM
The one that failed with all the (null)s was definitely Safari:

| 01:18:32 AM | Info | Unable to create hard link from /Volumes/Nick's HD Clone/Users/Nick/Library/Safari/lock to (null)

That's because 'lock' was deleted out from under us.

The other issue is likely that it was copying a large file, somewhere in your Home folder...

Nick
06-12-2009, 06:18 PM
The one that failed with all the (null)s was definitely Safari:

| 01:18:32 AM | Info | Unable to create hard link from /Volumes/Nick's HD Clone/Users/Nick/Library/Safari/lock to (null)

That's because 'lock' was deleted out from under us.

The other issue is likely that it was copying a large file, somewhere in your Home folder...

Thanks, Dave.

I will let SD! continue to do its scheduled backups, and see what happens. But I never had a problem with other apps running while SD! was backing up. Was that just dumb luck, or do I need to make sure nothing else is running during SD!'s scheduled backups? (The Manual says that quitting other apps isn't "strictly necessary," but also indicates that it's "a good practice.")

I also never had SD! fail as a result of stalling and (apparently) timing out while copying a "large" file...and the largest file in my Home folder has always been my Entourage Identity, which is about 4 GB. Is there any obvious reason it should suddenly—and coincidentally—become a "choke point?"

dnanian
06-12-2009, 06:28 PM
That's the thing. It's not strictly necessary, but you can run into problems -- like this one. I don't know why any given file would "suddenly" become a choke point, but something has. If you drop me some email, I can provide you with a command that'll help you determine what file is being copied at that point in time.

Nick
06-12-2009, 06:37 PM
... If you drop me some email, I can provide you with a command that'll help you determine what file is being copied at that point in time.

PM, or forums - at - shirt-dash-pocket-dot-com?

dnanian
06-12-2009, 06:38 PM
support - at - etc.

Nick
06-12-2009, 06:48 PM
support - at - etc.

Check your Support inbox.

Nick
06-16-2009, 08:13 PM
...I can provide you with a command that'll help you determine what file is being copied at that point in time.

Thanks...It worked like a charm :). Apparently, SD! was getting hung up on my 4 GB Entourage Identity. Why it would do so all of a sudden is puzzling.

Having stalled on that file, I have been quick to quit all other open apps when SD! begins its scheduled backup. But I eventually found that if I let SD! "hang" on that Entourage file for a while (actually, for quite a while), it finally stopped timing out and continued with the backup successfully. So, that's what it seems to be doing now: Hang for a long time, but eventually proceed again to complete the backup successfully.

I wonder what caused all of this to begin with? It certainly seems like Safari somehow was the "trigger" (though it only was involved that first time); right after that, the failures seemed to be due to the hangs on the Entourage file. But now, SD! "recovers" before "giving up."

(BTW: I really don't use Terminal except on rare occasions (like this time), as I'm not comfortable with it (the one time I really attempted to do something "significant" (by "blindly" following someone's poor instructions), I wiped out my desktop!). I did notice that each time I opened Terminal to use the command you provided, as soon as Terminal opened (before I entered any command/password), it informed me "You have mail." The handful of times I've opened Terminal in the past, I never ran into that. And my email habits/behavior haven't changed, so I wonder why I'm receiving that message. But I guess that's not an SD! question, is it? :o)

dnanian
06-16-2009, 11:17 PM
It's likely mail that a system tool has sent you.

As far as "all this" goes, hard to say. You should generally quit Entourage, though, before copying its data.

Nick
06-17-2009, 12:42 AM
It's likely mail that a system tool has sent you.
Where would it be located (certainly not in Mail.app or Entourage)?

... You should generally quit Entourage, though, before copying its data.
I use an automator workflow that quits Entourage and copies its data to a "backup" folder in my docs folder. That's the file that SD! gets hung-up on.

chris_johnsen
06-17-2009, 01:53 AM
Where would it be located (certainly not in Mail.app or Entourage)?

Note: I will be describing what I see on my Tiger machine. If you have Leopard some details might be different.

System-based email is in the file /var/mail/username (where username is your user's "short user name"). Mail is really geared towards Internet email, so it does not offer a direct way to check this mailbox. You can, however, import this system email into Mail. Choose File > Import Mailboxes…; select Other (the key phrase here is "mbox file"); click Continue; press ⌘⇧G (Command-Shift-G); type /var; click Go; select mail; click Choose; make sure your short user name is checked in the Items to import list; click Continue; read the displayed info about where to find the imported messages; click Done.

Entourage should also be able to do the job. The key words you want to look for are import and mbox. Then just point it to your /var/mail/username file.

Nick
06-17-2009, 03:48 AM
Note: I will be describing what I see on my Tiger machine. If you have Leopard some details might be different.

System-based email is in the file /var/mail/username (where username is your user's "short user name"). Mail is really geared towards Internet email, so it does not offer a direct way to check this mailbox. You can, however, import this system email into Mail. Choose File > Import Mailboxes…; select Other (the key phrase here is "mbox file"); click Continue; press ⌘⇧G (Command-Shift-G); type /var; click Go; select mail; click Choose; make sure your short user name is checked in the Items to import list; click Continue; read the displayed info about where to find the imported messages; click Done.

Entourage should also be able to do the job. The key words you want to look for are import and mbox. Then just point it to your /var/mail/username file.

Thanks for the instructions, Chris.

I found daily messages going back over two months (and apparently still ongoing):

-----------------------------------------------------------------------------------------------------------------------

From: Nick @ nicks-imac.local (Cron Daemon)
Subject: Cron <Nick@nicks-imac> open file:///Users/Nick/Library/Application%20Support/
SuperDuper%21/Scheduled%20Copies/Smart%20Update%20Nick%27s%20HD%20Clone%20from
%20Nick%27s%20HD%201.sdsp/Copy%20Job.app
Date: April 11, 2009 1:15:01 AM EDT
To: Nick @ nicks-imac.local
__________________________________________________ _____________________________________________

The file /Users/Nick/Library/Application Support/SuperDuper!/Scheduled Copies/Smart Update Nick's HD Clone from
Nick's HD 1.sdsp/Copy Job.app does not exist.









-----------------------------------------------------------------------------------------------------------------------


They are all identical, one for each daily backup, coincident with the initiation of each backup, since April 11.


Any idea what they mean (and what is causing them)?

chris_johnsen
06-17-2009, 05:31 AM
I do not do (automatically) scheduled backups, so I am not sure.

If your scheduled backups are working despite these emails showing that it is not able to start the "Copy Job" app, then I would guess that these emails are from "left over" scheduler entries that were deleted but somehow left in the crontab. The error in the email seems to indicate that the backup driver app for that scheduled backup it no longer there. I would guess that the whole .sdsp bundle was deleted from the ~/Library/Application Support/SuperDuper!/Scheduled Copies directory.

The app's path seems to indicate that the erroneous entry was for a scheduled backup from "Nick's HD 1" (note the trailing 1) to "Nick's HD Clone". The trailing "1" seems to indicate that you might have had two volumes named "Nick's HD" active at the time this entry was created. SuperDuper! actually identifies each volume its special, unique identifier, not its user visible name. So it is not a problem to have multiple volumes with the same name, but it is probably not very common unless you have just restored a failed internal drive or something.

I will have to defer to Dave as to whether SuperDuper!'s scheduler function can cleanup this bogus looking crontab entry or if it needs to be done by hand to stop your daily of system emails.

dnanian
06-17-2009, 08:58 AM
I don't know why an 'extra' crontab entry might be there, but I'd delete your existing schedules, then open Terminal and type:

crontab -r

(followed by return)

Then, start SD! and recreate your schedule(s). That should remove any extra crontab entries and stop the email.

Nick
06-17-2009, 11:54 AM
I do not do (automatically) scheduled backups, so I am not sure.

If your scheduled backups are working despite these emails showing that it is not able to start the "Copy Job" app, then I would guess that these emails are from "left over" scheduler entries that were deleted but somehow left in the crontab. The error in the email seems to indicate that the backup driver app for that scheduled backup it no longer there. I would guess that the whole .sdsp bundle was deleted from the ~/Library/Application Support/SuperDuper!/Scheduled Copies directory.

The app's path seems to indicate that the erroneous entry was for a scheduled backup from "Nick's HD 1" (note the trailing 1) to "Nick's HD Clone". The trailing "1" seems to indicate that you might have had two volumes named "Nick's HD" active at the time this entry was created. SuperDuper! actually identifies each volume its special, unique identifier, not its user visible name. So it is not a problem to have multiple volumes with the same name, but it is probably not very common unless you have just restored a failed internal drive or something.

I will have to defer to Dave as to whether SuperDuper!'s scheduler function can cleanup this bogus looking crontab entry or if it needs to be done by hand to stop your daily of system emails.

There's only one volume named "Nick's HD" (it resides on my internal drive). SD! backs it up to a volume (named (appropriately enough) "Nick's HD Clone") on an external drive.

Nick
06-17-2009, 11:57 AM
I don't know why an 'extra' crontab entry might be there, but I'd delete your existing schedules, then open Terminal and type:

crontab -r

(followed by return)

Then, start SD! and recreate your schedule(s). That should remove any extra crontab entries and stop the email.

I'll give it a try. (If nothing else, perhaps I'll overcome my FOT ("Fear of Terminal") :rolleyes: ).

Nick
06-21-2009, 05:30 AM
I don't know why an 'extra' crontab entry might be there, but I'd delete your existing schedules, then open Terminal and type:

crontab -r

(followed by return)

Then, start SD! and recreate your schedule(s). That should remove any extra crontab entries and stop the email.

I followed your instructions, but it didn't help: The very next time I opened Terminal, I was still greeted with "You have mail."

Thinking that I might have made an error, I then re-entered "crontab -r" and hit return. Terminal responded with "crontab: no crontab for Nick". So, it seems that I did do it right...if "right" means getting rid of "crontab" (whatever that file may be).

dnanian
06-21-2009, 09:56 AM
You're going to get "You Have Mail" until you delete all the mail that's there. The point was to prevent any more mail from being generated.

Nick
06-21-2009, 10:54 AM
You're going to get "You Have Mail" until you delete all the mail that's there. The point was to prevent any more mail from being generated.

I'm not sure whether that's the dumbest question I've ever asked; if not, it certainly is among the Top Ten. :o In my own (feeble) defense, all I can do is point to (and blame it on) a severe lack of sleep at the time I posted.

Sorry...and thanks!

dnanian
06-21-2009, 10:55 AM
It wasn't stupid at all, Nick. :)

Nick
06-21-2009, 11:09 AM
It wasn't stupid at all, Nick. :)

You're way too kind, Dave.


(BTW: Any suggestions for reference material re: Terminal that won't make my eyes glaze over?)

dnanian
06-21-2009, 11:47 AM
Pretty much everything you're going to read about the various shells and commands is going to be dry. But one of the O'Reilly online books might help -- it's not so much Terminal as it is "Unix"...

sjk
06-21-2009, 03:26 PM
From Hivelogic - My First PeepCode Screencast: Meet the Command Line (http://hivelogic.com/articles/view/meet-the-command-line):

Meet the Command Line is a 70 minute screencast geared for people who have never used the UNIX command line, or are learning it for the first time.

If you can afford $9.

dnanian
06-21-2009, 05:08 PM
Hey, good catch - I'm sure Dan did a good job with that.