PDA

View Full Version : 1 of 2 Scheduled Backups Does Not Run


dmorgen
04-06-2016, 05:36 PM
Hi Dave. I have the latest SuperDuper running on Yosemite 10.10.5. For quite some time I've been running 2 scheduled SuperDuper backups, 1 of an external Thunderbolt boot drive (SSD) & 1 of an internal HD. Both are scheduled at 3AM daily. I have a wakeup scheduled for 2:54AM in Energy Saver preferences. I have seen these backups showing as having been run within the last week or so. But when I've looked for the previous 2 nights, the SSD backup has run, but not the HD backup. Both the 2 source drives & 2 destination partitions on 1 external drive seem to be mounted.

The really strange thing is I can't find any significant reference to the missing HD backups in the Superduper logs or in the Console All Messages logs. The only items containing "SuperDuper" in the latter are:

4/6/16 3:47:51.534 PM SuperDuper![34220]: LOGGED EXCEPTION: NSAccessibilityException, reason: "AXDocument" attribute unsupported by: <NSWindow: 0x7b884250>, userInfo: {
NSAccessibilityErrorCodeExceptionInfo = "-25205";
}
4/6/16 3:47:51.534 PM SuperDuper![34220]: LOGGED EXCEPTION: NSAccessibilityException, reason: "AXSubrole" attribute unsupported by: <NSWindow: 0x7b884250>, userInfo: {
NSAccessibilityErrorCodeExceptionInfo = "-25205";
}
4/6/16 3:48:16.178 PM SuperDuper![34220]: LOGGED EXCEPTION: NSAccessibilityException, reason: "AXDocument" attribute unsupported by: <NSWindow: 0x7b884250>, userInfo: {
NSAccessibilityErrorCodeExceptionInfo = "-25205";
}
4/6/16 3:48:16.178 PM SuperDuper![34220]: LOGGED EXCEPTION: NSAccessibilityException, reason: "AXSubrole" attribute unsupported by: <NSWindow: 0x7b884250>, userInfo: {
NSAccessibilityErrorCodeExceptionInfo = "-25205";
}
4/6/16 3:48:33.840 PM SuperDuper![34220]: LOGGED EXCEPTION: NSAccessibilityException, reason: "AXDocument" attribute unsupported by: <NSWindow: 0x7b884250>, userInfo: {
NSAccessibilityErrorCodeExceptionInfo = "-25205";
}
4/6/16 3:48:33.841 PM SuperDuper![34220]: LOGGED EXCEPTION: NSAccessibilityException, reason: "AXSubrole" attribute unsupported by: <NSWindow: 0x7b884250>, userInfo: {
NSAccessibilityErrorCodeExceptionInfo = "-25205";
}
4/6/16 3:50:59.717 PM WindowServer[219]: disable_update_timeout: UI updates were forcibly disabled by application "SuperDuper!" for over 1.00 seconds. Server has re-enabled them.
4/6/16 3:51:08.766 PM WindowServer[219]: common_reenable_update: UI updates were finally reenabled by application "SuperDuper!" after 10.05 seconds (server forcibly re-enabled them after 1.00 seconds)
4/6/16 3:51:58.184 PM SuperDuper![34220]: LOGGED EXCEPTION: NSAccessibilityException, reason: "AXDocument" attribute unsupported by: <NSWindow: 0x7b991790>, userInfo: {
NSAccessibilityErrorCodeExceptionInfo = "-25205";
}
4/6/16 3:51:58.184 PM SuperDuper![34220]: LOGGED EXCEPTION: NSAccessibilityException, reason: "AXSubrole" attribute unsupported by: <NSWindow: 0x7b991790>, userInfo: {
NSAccessibilityErrorCodeExceptionInfo = "-25205";
}

Are these significant? How do you suggest I proceed?

Thanks!

Dave

dnanian
04-07-2016, 12:40 AM
Hi, Dave.

You should set the wake event for ONE minute before the scheduled copy time. Otherwise, your Mac will likely go to sleep before the backup runs (it doesn't wait the full time for your normal sleep).

The Accessibility exceptions are fine and not related to the copy. They usually have to do with voice recognition/dictation/control programs.

dmorgen
04-08-2016, 02:53 PM
Hi Dave,

That didn't solve the problem. AFAIK, that or anything else related to Superduper hasn't changed in quite some time. But it's possible something installed an update I don't know about or remember.

What next?

Thanks.

Dave

dnanian
04-08-2016, 05:03 PM
So, if you edit the schedule and tell it to run a few minutes from "now", does that work?

dmorgen
04-09-2016, 11:40 AM
Hi Dave. That worked!

It just occurred to me ... when the problem happened, it was the 2nd backup that worked. But it didn't start until 314AM, though scheduled for 3AM. Presumably, the 1st backup caused a delay between 3AM & 314AM, though there were no signs of it running.

Any idea why the problem occurred?

Now, should I just change the 2 schedules back to 3AM & see if it works.

Thanks.

Dave

dnanian
04-09-2016, 01:10 PM
That certainly seems weird. I don't know why it would cause a delay if it wasn't running.

dmorgen
04-13-2016, 04:14 PM
Talk about weird ... the previous 2 days, NEITHER drive backup has been performed! It's now set for 559PM. I haven't changed anything since it was working! I saved the console logs for the 2 days. They show the system (or network?) going to sleep before the backup time then awakening after with a "Previous sleep cause: 5".

Here's an excerpt from the log. I can send the whole thing if you'd like.

Any idea what's going on?

Thanks.

Dave

dmorgen
04-13-2016, 04:15 PM
The log excerpt:

4/12/16 5:18:17.463 PM WindowServer[216]: CGError post_notification(const CGSNotificationType, void *const, const size_t, const bool, const CGSRealTimeDelta, const int, const CGSConnectionID *const, const pid_t): Timed out 1.000 second wait for reply from "Fantastical" for synchronous notification type 102 (kCGSDisplayWillSleep) (CID 0x16c13, PID 429)
4/12/16 5:22:10.517 PM WindowServer[216]: handle_will_sleep_auth_and_shield_windows: Deferring.
4/12/16 5:43:10.726 PM GoogleSoftwareUpdateAgent[25913]: 2016-04-12 17:43:10.723 GoogleSoftwareUpdateAgent[25913/0xa064d1d4] [lvl=2] -[KSAgentApp setupLoggerOutput] Agent settings: <KSAgentSettings:0x20e650 bundleID=com.google.Keystone.Agent lastCheck=2016-04-12 19:42:24 +0000 checkInterval=18000.000000 uiDisplayInterval=604800.000000 sleepInterval=1800.000000 jitterInterval=900 maxRunInterval=0.000000 isConsoleUser=1 ticketStorePath=/Users/dmorgen/Library/Google/GoogleSoftwareUpdate/TicketStore/Keystone.ticketstore runMode=3 daemonUpdateEngineBrokerServiceName=com.google.Key stone.Daemon.UpdateEngine daemonAdministrationServiceName=com.google.Keyston e.Daemon.Administration logEverything=0 logBufferSize=2048 alwaysPromptForUpdates=0 productIDToUpdate=(null) lastUIDisplayed=(null) alwaysShowStatusItem=0 updateCheckTag=(null) printResults=NO userInitiated=NO>
4/12/16 5:48:05.263 PM WindowServer[216]: handle_will_sleep_auth_and_shield_windows: Deferring.
4/12/16 5:49:33.991 PM coreaudiod[266]: 2016-04-12 05:49:33.991135 PM [AirPlay] Power: SystemWillSleep
4/12/16 6:32:09.000 PM kernel[0]: Previous sleep cause: 5
4/12/16 6:32:10.313 PM WindowServer[216]: handle_will_sleep_auth_and_shield_windows: Ordering out authw 0x0(0), shield 0x7fc8bdfa5a20(2001) (lock state: 1)
4/12/16 6:32:10.314 PM WindowServer[216]: handle_will_sleep_auth_and_shield_windows: errs 0x0, 0x0
4/12/16 6:32:16.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: sleep for 1 seconds and then try again
4/12/16 6:58:22.377 PM coreaudiod[266]: 2016-04-12 06:58:22.376637 PM [AirPlay] Power: SystemWillSleep
4/12/16 8:58:37.000 PM kernel[0]: RTC: Maintenance 2016/4/13 00:58:37, sleep 2016/4/12 22:58:42
4/12/16 8:58:37.000 PM kernel[0]: Previous sleep cause: 5
4/12/16 8:58:42.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: sleep for 1 seconds and then try again
4/12/16 8:59:48.000 PM kernel[0]: RTC: Maintenance 2016/4/13 02:59:38, sleep 2016/4/13 00:59:48
4/12/16 10:59:38.000 PM kernel[0]: Previous sleep cause: 5
4/12/16 10:59:41.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: sleep for 1 seconds and then try again
4/12/16 10:59:42.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: sleep for 1 seconds and then try again
4/12/16 10:59:43.000 PM kernel[0]: AFP_VFS afpfs_DoReconnect: sleep for 1 seconds and then try again

dnanian
04-13-2016, 04:26 PM
Those are attempts to connect to the network volume that are failing. (The "sleep for 1 second" bit is because the "reconnect" process waits a second (using the "sleep" call) before trying again.)

But if it runs normally but not after sleep, it sounds to me like your system is having problems after waking...

dmorgen
04-13-2016, 06:32 PM
The network volume is a Synology NAS which does take awhile to complete a connection. But it's not involved in this backup (which uses directly connected external drives & an internal drive). I've got to run now, but I'll look into it when I'll hopefully have some time tonight or tomorrow.

Thanks.

Dave

dmorgen
04-25-2016, 04:24 PM
Hi Dave. I've got the problem solved. First I discovered a fairly consistent pattern ... the backup worked while I was using the system, but not when I was not using it for awhile. I was able to confirm from the logs the failures seemed to be due to problems connecting to the Synology NAS, which is usually connected when I'm using the system, but periodically gets disconnected (I never had the chance to isolate the causes of the disconnect, but it was probably after the system goes to sleep). Generally, unless I was doing something manual involving the NAS, I'd discover the disconnect when iTunes tried to access it's data stored there. But I have no idea why backup tried connecting to the NAS, since it was involved with the backup. Also, why the problem started happening after using the same setup for quite awhile without this problem.

So, I tried implementing something I've been wanting to do for quite some time. I purchased & installed Mountain. I configured it to prevent the NAS from disconnecting from the Mac, when the Mac went to sleep. The SuperDuper backup has now been performing successfully at 3AM each day for about a week now.

Thanks for your help!

Dave

dnanian
04-25-2016, 05:17 PM
Good to hear!