Launchd: StartCalendarInterval not working reliably in Yosemite

[Stefan Haller]

I have this LaunchAgent in ~/Library/LaunchAgents/ that fires once every
night at 1am to trigger a backup. (I also configured my Energy Saver
schedule to wake up the machine at 1 so that the job can run.) This has
worked perfectly and super reliably for many months now.

After upgrading to Yosemite this no longer works. On most days, the job
doesn't run at all; on some days I have seen it trigger at random times,
e.g. 16:12 (the machine was awake the whole day).

The relevant section of the launchd plist is

<key>StartCalendarInterval</key>
<dict>
<key>Hour</key>
<integer>1</integer>
<key>Minute</key>
<integer>0</integer>
</dict>

For testing I have created a new plist which is an almost exact
duplicate, with just a different Label, and calling a different Program;
this triggered correctly at 1am.

Does anybody have experience with this? Any ideas how to trouble-shoot
this?


--
Stefan Haller
Berlin, Germany
http://www.haller-berlin.de/

[Chris Ridd]

The launchd sources aren't public in Yosemite (by accident or design?),
so it will be hard to troubleshoot:

$ what /sbin/launchd
/sbin/launchd
PROGRAM:launchd PROJECT:libxpc-559.1.22
VERSION:Darwin System Bootstrapper 2.0.0: Tue Sep 9 16:30:56 PDT
2014; root:libxpc_executables-559.1.22~6/launchd/RELEASE_X86_64

Does it remember when a job last ran in some database, to avoid
re-running it too soon? You could try running it under dtruss to see
what files it is looking at through the day, though that'll give a lot
of data to look through...

--
Chris

[David Empson]

There is a "Debug" key with a boolean parameter which the man page
claims be added to the plist to enable debug logging while dealing with
this job. It might provide some clues. See 'man launchd.plist' for
details.

Yosemite appears to have a significant rewrite of launchd, including
deprecating many old features that could be manipulated via launchctl.
This might be a bug in the new version. If you are sure you have the
syntax right (I can't see anything wrong with the StartCalendarInterval
bit), a bug report to Apple may be in order.

--
David Empson
dem...@actrix.gen.nz

[Bruce Horrocks]

On 05/11/2014 08:05, Stefan Haller wrote:
> I have this LaunchAgent in ~/Library/LaunchAgents/ that fires once every
> night at 1am to trigger a backup. (I also configured my Energy Saver
> schedule to wake up the machine at 1 so that the job can run.) This has
> worked perfectly and super reliably for many months now.
>
> After upgrading to Yosemite this no longer works. On most days, the job
> doesn't run at all; on some days I have seen it trigger at random times,
> e.g. 16:12 (the machine was awake the whole day).

Has the previous run finished? If the program is still running then
launchd won't start another, but will wait for it to finish first. This
might explain a new backup starting at 16:12.

>
> The relevant section of the launchd plist is
>
> <key>StartCalendarInterval</key>
> <dict>
> <key>Hour</key>
> <integer>1</integer>
> <key>Minute</key>
> <integer>0</integer>
> </dict>
>
> For testing I have created a new plist which is an almost exact
> duplicate, with just a different Label, and calling a different Program;
> this triggered correctly at 1am.

You could delete the old one and re-create it, just in case. I assume
you have done this already?

Does the original have the right permissions? (But if they are wrong I
would have thought that it would never run.)

> Does anybody have experience with this? Any ideas how to trouble-shoot
> this?

Change the entry to launch a shell script that writes out the date and
time to a log file; then calls the backup program; then logs the date
and time again so you get exact times for when each invocation starts
and finishes.

Create a second entry that just calls (a copy of) the shell script that
logs but doesn't invoke the backup. This way you can see if launchd is
launching something at the right time, just not your program.

--
Bruce Horrocks
Surrey
England
(bruce at scorecrow dot com)

[Stefan Haller]

Bruce Horrocks <07....@scorecrow.com> wrote:

> On 05/11/2014 08:05, Stefan Haller wrote:
> > I have this LaunchAgent in ~/Library/LaunchAgents/ that fires once every
> > night at 1am to trigger a backup. (I also configured my Energy Saver
> > schedule to wake up the machine at 1 so that the job can run.) This has
> > worked perfectly and super reliably for many months now.
> >
> > After upgrading to Yosemite this no longer works. On most days, the job
> > doesn't run at all; on some days I have seen it trigger at random times,
> > e.g. 16:12 (the machine was awake the whole day).
>
> Has the previous run finished? If the program is still running then
> launchd won't start another, but will wait for it to finish first. This
> might explain a new backup starting at 16:12.

Yes, a run usually doesn't take more than an hour.

> Change the entry to launch a shell script that writes out the date and
> time to a log file; then calls the backup program; then logs the date
> and time again so you get exact times for when each invocation starts
> and finishes.

This is the current setup already, that's how I know when the job starts
(and ends).

Yesterday I have changed the Label of the existing job, it didn't make a
difference either (the job launched at 3:32 in the morning, with the
machine being awake all night).

> Create a second entry that just calls (a copy of) the shell script that
> logs but doesn't invoke the backup. This way you can see if launchd is
> launching something at the right time, just not your program.

I'll try this next, thanks.

[Stefan Haller]

David Empson <dem...@actrix.gen.nz> wrote:

> There is a "Debug" key with a boolean parameter which the man page
> claims be added to the plist to enable debug logging while dealing with
> this job. It might provide some clues.

Good suggestion, I hadn't noticed this; unfortunately, it doesn't seem
to make a difference. I suspect this only affects any kind of logging
that's done by the launched program, but not by launchd itself.

[Stefan Haller]

Stefan Haller <stk.u...@haller-berlin.de> wrote:

> Bruce Horrocks <07....@scorecrow.com> wrote:
>
> > Create a second entry that just calls (a copy of) the shell script that
> > logs but doesn't invoke the backup. This way you can see if launchd is
> > launching something at the right time, just not your program.
>
> I'll try this next, thanks.

I did that; both jobs fired at 1:41:25 this night. I'll continue to
watch this some more, but I more and more tend to believe it's simply a
bug.

[Stefan Haller]

Stefan Haller <stk.u...@haller-berlin.de> wrote:

> I have this LaunchAgent in ~/Library/LaunchAgents/ that fires once every
> night at 1am to trigger a backup. (I also configured my Energy Saver
> schedule to wake up the machine at 1 so that the job can run.) This has
> worked perfectly and super reliably for many months now.
>
> After upgrading to Yosemite this no longer works. On most days, the job
> doesn't run at all; on some days I have seen it trigger at random times,
> e.g. 16:12 (the machine was awake the whole day).

In case anybody is interested, I reported this as a bug two weeks ago,
and it was closed as a duplicate.

The upgrade to 10.10.1 doesn't seem to make any difference, it still
fires at completely arbitrary times.

I guess for now I'll try converting it to a cron job and see if that
works better. Anybody have experience with that? I know that cron has
been deprecated in Mac OS X for ages, but it should still work, no?

[niko....@gmail.com]

This seems to be fixed in OS X 10.10.3.

[Stefan Haller]

<niko....@gmail.com> wrote:

> This seems to be fixed in OS X 10.10.3.

Thanks. I'm not sure I'll even try this though, because meanwhile I have
converted my launchd job to a cron job, and for this particular use case
I actually *like* the fact that it doesn't fire when the machine is
asleep. With launchd, the task would start the next time the machine
wakes up, which is not what I want in this case. So I think I'll just
keep the cron job.