Flaky execution of scheduled backups? No Sat. AM in "Daily"?

[DrDan in MA]

I've been having difficulties making SD! do backups regularly. I'm running SD 77 on a PBG4 and a Mini, each MacOSX 10.4.5 (all updated) and each with its own external, mounted, formatted FW HD with a previous Full Backup already present on that partition. I've got both systems set to wake up at 0320 each day, and a smart backup set to happen at 0330. Sometimes it works, but most mornings when I wake up, the backup has not happened! :( Howcumdat?

What more info can I/should I have supplied to make this question answerable?

OBTW, it appeared one Friday evening, when I scheduled a backup for DAILY at 0330, that the next scheduled backup was SUN at 0330. However, as I'd hoped, when I awoke on Saturday AM, the 0330 backup had happened. So this may be simply some feedback problem...

[dnanian]

Because you should set the wake time for one minute before the backup time.

There's a known issue with the "Next Copy" column but it's purely a display thing -- the backup will occur on the right day. We have the display problem fixed internally, and the fix will be included in the next update.

[DaleMeyn]

Just and addendum: I've noticed that when Energy Saver wakes my iMac up for the scheduled update, the iMac will go back to sleep before the update happens if the wakeup was too early, even if the programmed interval before going to sleep is set for 20 minutes. For example, if I set the computer to wake up 1 minute before SD! is scheduled to back up, it will happen, then the computer will stay awake until 20 minutes after the backup is finished. If I set the computer to wake up, and nothing is done, it goes back to sleep in a minute or so.

[dnanian]

That's exactly right. I don't know why Energy Saver does this, but it does... so, if you set for one minute before the scheduled time, we start running before it has an chance to forget that you wanted it to be awake. :)

[DrDan in MA]

Hmm... ah do bleev (IIRC) that I was experiencing the problem when the wakeup-call was at 0329, so I backed off 9 more minutes, hence 0320. However, I'll reset the wakeup to 0329 and see what happens, to report back in a day or three.

As ever, tnx for the feedback, dnanian; and also to you, DaleMeyn.

Glad the known issue is display only; as I said, the SAT 0330 backup (which was one of those that "took") did happen despite that buglet, so I guess that agrees w/the data. :)

[DrDan in MA]

Mixed results, to report, thus far. Both my Macs are OSX 10.4.5 and running the latest SD! (2.1v77), but there's only one that performs its backup consistently -- the Mini. As for my AL-PbG4, it's got a backup set for 0330 and a wakeup set for 0329 (like the Mini), but it hasn't done its thing for a couple of days. Yesterday's, well, perhaps because I hadn't mounted the external disk (an 80 GB partition of a LaCie 160GB) prior to going to bed. So last night, I was sure to have done that, but as of this AM, no log could be found.Incidentally, this would be an appropriate time to note that it appears, to these not-on-the-code-side eyes, to be inordinately difficult to monitor what SD! has done recently. It seems to me that every different scheduled event has its own "subdirectory" in an INVISIBLE subdirectory, and if there's a given repetitive event, all successful execution logs of that event are kept together but majorly hard to get to. I haven't yet found a way of viewing all recent logs together, which would (imho) help me in figuring out what's been done and what's been missed. If my understanding of what I'm groping for is intelligible, what would be cool is if SD! had an easily-accessible, consistently-named, single, non-invisible subdir, within which all recent copy logs could be displayed. I suppose that each separate scheduled copy event could have its own subdir within this dir, and then I could just display the dir in time-ordered format to see which was the most recently executed event. Then I could dive into that subdir to see what just happened, while at the same time being able to retain easy access to, understanding of, and thus to get a larger context of, all other recent copy events. Does this sound like a reasonable enhancement?While I was watching this CPU and later writing this, SD! successfully did a backup at 0800 after the CPU woke itself from sleep at 0759. I'd scheduled the event at 0740 and had then manually put the machine into SLEEP mode, and left it alone till at 0759 it awoke with the LaCie drives still mounted...The (smart) backup I'd just scheduled for 0800 was in fact, happily, successful, taking about 14':20" but, even though I'm virtually certain that I had asked that this event should SLEEP the AL-PbG4 at its conclusion, that didn't happen (maybe because I was "using" the CPU at that point, though I made sure not to touch TextEdit as the SD! run was finishing its copy and stopping). I couldn't verify that the SLEEP was supposed to happen, though, when I re-opened the event for inspection and editing. Strange, possibly irrelevant.

Anyhoo, perhaps SD! has difficulty in REALLY awakening the LaCie drive when it's been asleep for hours? But there's no record of what might have happened at 0330 today... Hence my interest in a single spot for looking at logs... Further idle thoughts: If SD! event X were written and saved at 1600 on a given day, so that it is "in place and ready" for later execution at, say, 2330 that same day, and something prevents that from happening, is there a mechanism for saying "HEY -- event X was supposed to happen but didn't, and here's (what we know about) why..."...?

[dnanian]

We rely on the system's wake and scheduling features to do their things. If those don't work reliably, it's hard for us to work reliably, and harder still to "work around" the problem, since we didn't "write" that part.

As far as logs go, there's no plan for an integrated log "folder", no. But we're always looking for ways to improve things, and I have various ideas in this area.

But, anyway. If the drive wasn't mounted, your backup would fail. Why the second one failed is something I can't explain, but if SD! wasn't "waiting to run" when you woke, it means it probably didn't wake at all, or went to sleep very, very quickly after waking.

If you're comfortable doing so, you can try to change your crontab to run the event at 3:30:30 by changing the "0" at the start of the line to a "30". Then, set your wake event to 3:30, and see if that works...

[DrDan in MA]

Hi Dave, thanks again for your prompt and helpful responses.

"We rely on the system's wake and scheduling features to do their things. If those don't work reliably, it's hard for us to work reliably, and harder still to "work around" the problem, since we didn't "write" that part."
I hear you on that.
As far as logs go, there's no plan for an integrated log "folder", no. But we're always looking for ways to improve things, and I have various ideas in this area.
Well thanks for letting me vent :) I've often found that developers have already thought of better ways to address issues than just plain end-users; glad you're already processing ideas for improvements in this area...
But, anyway. If the drive wasn't mounted, your backup would fail. Why the second one failed is something I can't explain, but if SD! wasn't "waiting to run" when you woke, it means it probably didn't wake at all, or went to sleep very, very quickly after waking.
Waitamminnit, I do remember times when I've awoken the system in the morning, and there was SD! all bright-eyed and bushytailed, already beginning its work. I didn't understand why that might have been... so what you're telling me is that those times represent occasions when OSX didn't even ever wake from sleep. If this repeats, I guess I'll bug the folx at AppleCare.
If you're comfortable doing so, you can try to change your crontab to run the event at 3:30:30 by changing the "0" at the start of the line to a "30". Then, set your wake event to 3:30, and see if that works...
OK, I don't mind doing this if it'll help, but your description doesn't help me enough, please add some specificity... I find that can't change the final 0 of 3:30 into 0:30 within the usual SD! edit screen, so I'm assuming (???) that if I get into the TERMINAL app and look for "CronTabs" I can edit one. If it's not too much hassle, could you pls point me to doc of just how I do this? ... and how changing the time that the SD! run will start from an integer to a fraction of a minute will help things out, if in fact it's the OS's problem for not having woken up at all? In other words, I don't understand where this is going or how I can help do this suggested test. :)

[dnanian]

I don't think the AppleCare guys are going to be of much help, Dan.

If you had a situation where, when you woke your computer SD! was there waiting, it did indeed start to do its thing, but the system decided it would be best to put it to sleep again. Which is frustrating. Tweaking the crontab will likely help.

Snag a copy of CronniX to edit the crontab, actually. It should let you change the "seconds" to 30 seconds past the minute, rather than the minute itself...

[DrDan in MA]

OK, I just snagged & installed CronnIX and used it to mod the crontab that I'd previously set for 0330 to start the SD! run. Now, if I did it all OK, SD! will launch at 03:30:30. I also changed my sys wakeup event to 0330 as you suggested. Now I see the method to your fix -- tighten up the interval between sys wakeup and SD! startup.

Hopefully when I awake Sat. morning, I'll find a backup completed & waiting. I know that Sat. AM is not "showing up" in the display of SD!'s intentions (it still sez that the next backup will be SUN 0330) but we both know that it'll try on SAT morning. I wondered whether having "changed the crontab behind SD!'s back" would cause SD to complain or display what was afoot, but no problems displayed themselves when I looked at SD!'s scheduled backup screen...Film at 0700ish... :)

[dnanian]

Sounds good. Let's see what happens!

[DrDan in MA]

Well this is strange data. Last night, the Mini's scheduled backup didn't happen, witness that when I awoke it from its sleep around 0700, there SD! was, all rarin' to go. I cancelled that run, but soon just started it again by hand. (Incidentally, imho it would be useful, if it isn't done yet, for there to be logs created from SD! copies that are initiated by hand... (??? Is this there already and I've just missed it???)

Now comes the the really strange data. :confused: I was up late last night to watch what happened at 0330 (I'd scheduled a sys wakeup for 0330 and used CronniX to change the crontab for an SD! run from 03:30:00 to 03:30:30. I'd been working on other stuff but put the AL-PbG4 to sleep manually at 03:27.

Promptly at 03:30:00 the system awoke from its brief slumber, with the external LaCie drive mounted. I use iPulse to monitor the sys and time, and watched 03:30:30 come and go with no launch of SD!.
As far as SD! is concerned it "believes" it has a scheduled copy set for 0330, witness its text in the SCHEDULE window, under What's going to happen? -- Daily at 3:30AM, "Backup-all files will be used to copy Al-PbG4 to LaCie80Gb. Smart update will...

However,

CronniX reports that the CronTab of DrDan is
Minute [] 30:30
Hour [] 3
Day of month [x] *
Month [x] *
Day of week (All)

and that the cmd to be executed is
open file:///Users/DrDan/Library/Application\%20Support/SuperDuper\%21/Scheduled\%20Copies/Smart\%20Update\%20LaCie80Gb\%20from\%20AL-PbG4.sdsp/Copy\%20Job.app
with the "Prepend "/usr/bin/open" box not checked.So I watched the seconds tick by... and to my surprise, promptly at 03:31:00 SD! was launched, and the successful run of SD! began at 03:31:15 and went until 3:49:29.

Perhaps the crontab at 3:30:30 kept the PbG4 from resuming its sleep, but SD! wasn't capable of starting except on a minute boundary, hence its start was rounded up?

One tiny piece of external evidence for that hypothesis is that despite the internal display of this event as being scheduled to start at 0330, the log of this run has the filename 2006-03-25 03/31/15 -0500 (when it actually started) and was last modified at 03:59 (when it ended). The title bar of this log reads
Smart Update LaCie80Gb from AL-PbG4.sdsp - Sat, Mar 25, 2006 at 3:31AM

Is anything here of any value? :)

[dnanian]

Well, that's strange. You have to recognize that we don't do the launch -- cron does. If it didn't launch us at 30:30, it must be because cron is only running at minute boundaries, unfortunately. Rats.

One more thing to suggest. Snag a copy of NMS Sleep Assist from Version Tracker. Set up a "sleep hold" for SuperDuper... maybe that'll prevent things from sleeping on us... worth a try.

[DrDan in MA]

OK I've got NMS Sleep Assist 2.3Beta3 installed, but (and I hate to ask) :o I need some more hints as to what to set. Are you suggesting, say, that I forget CronniX (since there seems to be no granularity less than a minute for crontabs), set a normal energy-saver sys wakeup at 03:29, and then that I somehow (guidance needed here?) tell NMS Sleep Assistant to hold off sleeping for awhile (say a min or three) and schedule an SD! run for 03:30? I see where I can put custom holds on a per-app basis. Assuming SD! is in the right place (/Applications) what do I put where? :confused:

And am I the only one with flaky SD run startitude? If so I guess my M.O. as "Worst-Case-Dan" is still alive. :D

[dnanian]

No, leave things exactly as-is. But, set up a "Sleep Hold" in NMS Sleep Assist for "SuperDuper!:0", "SDCopy.root" and "Copy Job:0".

[DrDan in MA]

OK, Sys wakeup set for 03:30, CroniX modified my CronTab (originally set by SD! as 03:30) ahead 30 seconds to 3:30:30 as before.

I went to the NMS "SETUP SLEEP HOLDS" screen and as I think you wanted, entered the following info into the 8 boxes at the bottom of the screen. [n] is box numbering convention, rows first.

[1] [sdcopy.root] [SuperDuper:0] [4]

[1] [2] [Copy Job:0] [4]

I put sdcopy.root in box 2 of row 1 because the field had previously been filled with an example ending in .root -- shows ya that I have no real understanding of what's up here.

All three boxes -- 2 and 3 of row 1, and 3 of row 2, now have system-supplied checkboxes to their left. I made no other changes to the SETUP SLEEP HOLDS screen.

I've now QUIT out of NMS Sleep Assist and await events tonight.

I'm not quite clear on why this exercise was actually necessary; :confused: after all, last nite the backup was in fact done, though SD was launched at 03:31 rather than 03:30:30 as the modified CronTab said. More data by tomorrow in any case. :)

[dnanian]

We'll see if this prevents sleep from happening too quickly in those cases where you had problems, Dan.

[DrDan in MA]

This morning's data: Mini backup took place successfully; SysWakeup 0329, SD! session scheduled 0330, no CronniX or NMS Sleep Assist installed or active, log of session says that it was scheduled for 03:30, log of session records that activity actually began at 03:30:30.

Al-PbG4 backup successful; SysWakeup 0329, SD! session scheduled 0330, CronniX moved that crontab to 03:30:30, NMS Sleep Assist settings as described by you and executed by me, title of log of session says that it was scheduled for 3:31, log of session records that activity actually began 03:31:15 (I wasn't there to see what happened when, but it's a safe assumption that SD! was summoned at 03:31. The processor on Al-PbG4 is slightly faster than the Mini's... Does that explain the 15 seconds less in startup time? Think not).

Anyhow, that's today's batch. More later. Still wondering whether anyone else is reporting flaky SD runs when invoked from sleep...?

[dnanian]

Well, that's good so far, Dan. Let's see how it works moving forward.

We have occasional reports of people with issues like this, but it's not terribly common, no.

[DrDan in MA]

I was up at 0325 this AM after both CPUs had been asleep for about 4 hours. I touched neither of 'em.

Mini: awoke normally from sleep at 0329 and ran SD! at 0330 without incident.

Al-PbG4: it never awoke from sleep, and so it never got a chance to run SD! or the other sleep-extenders etc. I woke it up and ran SD! myself later; when I awoke from my own sleep at 0700, I saw the successful 3-green-band window.I would've liked to know where the log (if any) for that hand-started session is -- though I remember the trick on disclosing the hidden "Logs" subdir, nothing of interest was there... it seems to me that if that run had aborted, there would be a log that would exist somehow... is it anywhere?I wonder whether there's a fix for "Sleeping Beauty syndrome" (when a Mac's scheduled to awake but doesn't)... and where I would find such a fix... :confused:

[dnanian]

You could perhaps try resetting the power manager, Dan. That's different for nearly every Mac, so check the Apple site.

The hand-started session log would be available by making the main window active and doing Cmd-L (or showing the log window).

[DrDan in MA]

Tnx for the pointer to the location of the last successful logfile. I look forward to the results of your thinking on how to somehow consolidate the world of LogFiles. :)

I just got off the phone with AppleCare -- they had me uncheck the OSX 10.4.5 Energy Saver option "Put the hard disk(s) to sleep when possible" -- these boxes had been checked on both of my computers.

Of course, the Mini had been doing its scheduled backup regularly, and the Pb hadn't; and now both of them are set "NOT to put their hard disk(s) to sleep." So I'm not entirely certain this is the fix for the PB.

The AppleCare rep put it well -- "so what you want is to be able to wake your Mac PowerBook up not from just sleep, but from deep sleep." Apparently the latter is when the disks are asleep as well. And the proposed fix is not to allow the disks to sleep -- which is fine by me, since all this is in "Settings for Power Adapter" anyhow.

More data on SD! performance by tomorrow. I promise to let enough time elapse before 0329 or 0330 to let any "deep sleep" set in; but I think that "deep sleep" is a thing of the past.

[dnanian]

Um, I really don't think he had an idea, actually, Dan...

[mikeap]

Hey Dave,
What about a built inn emailer, as used for sending the log file to support, that can email me at my address when a scheduled backup does not execture for whatever reason. My NAS device emails me every time the power goes out, a drive goes bad, a firmware is needed, etc. How about that kind of reporting when a backup fails?
Mike

[dnanian]

Take a look on the Forums, Mike, and I think you'll find some good examples of exactly that! :)

[drlotto]

Tnx for the pointer to the location of the last successful logfile. I look forward to the results of your thinking on how to somehow consolidate the world of LogFiles. :)

I just got off the phone with AppleCare -- they had me uncheck the OSX 10.4.5 Energy Saver option "Put the hard disk(s) to sleep when possible" -- these boxes had been checked on both of my computers.

Of course, the Mini had been doing its scheduled backup regularly, and the Pb hadn't; and now both of them are set "NOT to put their hard disk(s) to sleep." So I'm not entirely certain this is the fix for the PB.

The AppleCare rep put it well -- "so what you want is to be able to wake your Mac PowerBook up not from just sleep, but from deep sleep." Apparently the latter is when the disks are asleep as well. And the proposed fix is not to allow the disks to sleep -- which is fine by me, since all this is in "Settings for Power Adapter" anyhow.

More data on SD! performance by tomorrow. I promise to let enough time elapse before 0329 or 0330 to let any "deep sleep" set in; but I think that "deep sleep" is a thing of the past.
DrDan,
Wish I had seen this thread sooner, hopefully you're still out there. I've had the same problem as you (with less determination to figure it out). I've got a Mini set to wake at 1:14 A with SD to "Erase and Back-up" to a FW ExtHD starting at 1:15 A. When I wake at ~8:30 A (I'm a bum) and manually wake my Mini at ~8:32 A, I see SD open and counting down to start backing up. I'm pretty sure SD doesn't have a 8 h 15 min countdown. I've rest the Power Managing Unit a couple of time to no avail.
The most I can add to this thread (despite empathy) is that I downloaded and installed DssW Sleepmonitor to track this behaviour. I highly recommend it. I've only had one back up session that has recorded and it shows the system waking at the appropriate time and shows the mini prepares to sleep 3 min 18 sec later. Interestingly, after 30 sec it logs that it cannot sleep. This "prepared-cannot wake" cycle repeated every 3-5 min until the computer finally went to sleep 7 h 39 m 1 s later. Unfortunately, I thought because of the "prepared-cannot wake" cycling that the back-up worked and did not pay attention to what happened when I manually woke it. After going back to the back-up files I realized they weren't updated. I have the mini set to back up 2x a week Sun and Wed so tomorrow I'll pay more attention and will try to report if anyone is interested. My current hypothesis: Since I have the hardrives set to sleep when possible, I think my internal HD starts but my external HD doesn't. SD may be waiting for the External to start. If that is the problem, I'm not sure how to fix it as I do not want the drives spinning all the time.

DrLotto

[dnanian]

Drive sleep should be entirely independent of "sleep" -- when we run, a "sleeping" drive should still appear to be connected, and we'd then use it, which would wake it up...

[drlotto]

OK I paid closer attention this time when I looked at the Mini this AM. The Mini was on this AM, although its monitor was asleep I could tell from the non-flashing light. The ExtHD was still asleep. I clicked the Mouse (BTW it is a BT Mouse and KeyBd if that matters) and the monitor turned on, then SD started and began a 10 sec countdown, and the ExtHD started spinning as SD was opening. I didn't have time to look at the sleepmonitor log but it looks like the Mini woke and couldn't return to sleep while SD and the ExtHD did not start. I'll post the sleep monitor log later tonight.

DrLotto

[drlotto]

Here's the log:

Today, 1:14:00 AM Preparing to wake
Today, 1:14:07 AM System powering on after 2 hours 25 minutes 10 seconds
Today, 1:18:55 AM Preparing to sleep after 16 minutes 33 seconds idle time
Today, 1:19:25 AM System will not sleep
Today, 1:21:57 AM Preparing to sleep after 19 minutes 22 seconds idle time
Today, 1:22:27 AM System will not sleep
...... "Prep to/System will not" sleep cycle repeats every 2-5 mins ........
Today, 6:28:28 AM Preparing to sleep after 5 hours 4 minutes 40 seconds idle time
Today, 6:28:58 AM System will not sleep
Today, 6:30:59 AM Preparing to sleep after 5 hours 7 minutes 1 second idle time
Today, 6:31:29 AM System will not sleep
...... I clicked on the mouse here ......
...... SD dialog opens and starts 10 s countdown as the Ext HD starts......
...... I canceled the backup and went to work ......
Today, 6:46:36 AM Preparing to sleep after 13 minutes 5 seconds idle time
Today, 6:46:36 AM System sleeping after 5 hours 32 minutes 29 seconds

Essentially the same thing occurred on Sun. Any comments?

DrLotto

[dnanian]

It just sounds like it's not "really" awake, DrLotto. Otherwise, we'd be running...

[drlotto]

There were 4 indicators that the Mini was awake:
1. the activity light
2. the sleep monitor stating its awake and cannot sleep
3. the internal HD spinning before I clicked the mouse
4. me looking at the desktop as the monitor started and then SD started

I guess I'm on my own to figure this out. I'll to try hooking up a non-BT mouse+keyboard to see if there is a relation there (googled this suggestion from another site). If I find a solution I'll pass it on.

I usually just go on and forget about asking for support but I think it may help to express my disappointment this time. I'm not disappointed with SD but with the last support and the email support responses from ShirtPocket. Both modes of support led to the same quick "solution" that the issue had to be the Mac because SD works so well. Good luck and thanks for playing.

I agree that the root cause of this issue could boil down to hardware or my specific configuration, but that doesn't mean that SP support could attempt to investigate. Maybe a future version could incorporate a fix or work-around for flawed hardware.

Obviously, I'm in the underwhelming minority to actually have a problem with SD, but I'm at least the 2nd person with this specific issue (I'm not sure if DrDan ever solved the problem). I write this only because this is where SP could distinguish itself from the self-serve support offered by other corps.

DrLotto

[dnanian]

I understand, and I do the best I can to help. I've done what we documented myself, on many different machines, without this kind of problem. I've attempted to duplicate your issue, and I've been unable to. (Two of the systems I tested had BT mice/keyboards, two had wired, one had non-Apple [MS].)

If I can't reproduce the issue, and it's not happening to a lot of people, it's really difficult for me to provide support above and beyond what I've done. It's not that I don't want to help: it's just that we're simply scheduling a program to run with a system facility: cron. If cron then fails to run us -- or the system doesn't allow us to run after wake in your configuration -- there's nothing we can "tweak" to convince it to do so other than the time between wake and run.

Apart from clean installing to another drive/partition and trying it in a pristine configuration -- something I'm sure you'd not want to do -- the only thing I can suggest is creating a new, fresh account, logging out of your regular one and into that, and scheduling as that user (you'll have to re-enter your registration info). Perhaps something you're running is interfering.

[DrDan in MA]

Hi -- I haven't been around in awhile, sorry for having missed out on DrLotto's traffic and problem. Perhaps this fix will work for you too, DrLotto...?

Reason I haven't been around is that SD has been working regularly as daily clockwork on both an Al-PBg4 and PowerPC Mini. I am not using either CronIX or NMS Sleep Assist on either.

All I've done is to modify Energy Saver to UNcheck the option that says "Put the HD to sleep when possible." Thus, the HD's are never turned off (I always run my systems on external power when I'm at home, so no worries about power, only extra wear-'n'-tear on HD's, but whatthehell) and so whenever a wakeup event happens (both systems wake at 3:29AM daily), the HD's are ready to run and when SD!'s schedule 0330 run is involked, it can start up and do its thing. Whenever I check into SD!'s status I invariably find that its last run was completed at about 0340 each day. Been like that for weex.

I've been saying to myself for awhile that I really should come back here and thank you for all your support and close this issue (at least from my own perspective).

I wonder: would it be prudent to, every so often, do another run -- say at 00:00 as I go to bed -- that would do a total erase and re-write of the backup area, so that at 03:30, it would again resume the daily smart backups? I would have to hand-start the complete backup because I wouldn't be able to schedule more than one daily wakeup...

Any ideas on what interval would be good for a complete re-write? Monthly? Or is this not needed, d'you think?

Looking fwd ti the next rev that'll fix the minor day-of-update-display bug (Saturday AM not shown, discussed elsewhere) and whatever other nifty NEW features now in your pipeline.

Great product still!!! Thanks. :)