Shirt Pocket Discussions

Shirt Pocket Discussions (https://www.shirt-pocket.com/forums/index.php)
-   General (https://www.shirt-pocket.com/forums/forumdisplay.php?f=6)
-   -   SuperDuper! Failure (https://www.shirt-pocket.com/forums/showthread.php?t=5324)

Nick 06-10-2009 03:37 PM

SuperDuper! Failure
 
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 02: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 05: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 03:10 PM

Quote:

Originally Posted by dnanian (Post 25128)
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 03: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 01: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 05:18 PM

Quote:

Originally Posted by dnanian (Post 25147)
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 05: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 05:37 PM

Quote:

Originally Posted by dnanian (Post 25152)
... 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 05:38 PM

support - at - etc.

Nick 06-12-2009 05:48 PM

Quote:

Originally Posted by dnanian (Post 25154)
support - at - etc.

Check your Support inbox.

Nick 06-16-2009 07:13 PM

Quote:

Originally Posted by dnanian (Post 25152)
...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 10: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-16-2009 11:42 PM

Quote:

Originally Posted by dnanian (Post 25200)
It's likely mail that a system tool has sent you.

Where would it be located (certainly not in Mail.app or Entourage)?

Quote:

... 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 12:53 AM

Quote:

Originally Posted by Nick (Post 25206)
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.


All times are GMT -4. The time now is 04:05 AM.

Powered by vBulletin® Version 3.8.9
Copyright ©2000 - 2024, vBulletin Solutions, Inc.