launchd StartCalendarInterval doesn't run on time

I cannot get launchd to run a script on time on MacOS 10.8.4. So I created a test script wich did nothing other than print the current time into a text file. Actually, I created two, to see if the "system" one performed differently than the "user" one. The user script is supposed to run on the hour. The system script should run at 5 after. They do not.

The system time is correct. The scripts do not depend on anything which could cause random delays

(like sending email, or other network interactions). It appears, from the logs, that the system is up

during those times.

Here's what the output file looks like.

time from Root log below. Should be on 5.

2013-Jun-29 02:06:23

time from Jason log below. should be on the hour.

time from Root log below. Should be on 5.

2013-Jun-29 03:20:28

2013-Jun-29 03:20:28

time from Root log below. Should be on 5.

time from Jason log below. should be on the hour.

2013-Jun-29 04:19:58

2013-Jun-29 04:19:58

time from Jason log below. should be on the hour.

2013-Jun-29 05:01:03

time from Root log below. Should be on 5.

2013-Jun-29 05:19:27

time from Root log below. Should be on 5.

2013-Jun-29 06:18:57

time from Root log below. Should be on 5.

2013-Jun-29 07:18:27

time from Root log below. Should be on 5.

2013-Jun-29 08:17:57

time from Root log below. Should be on 5.

2013-Jun-29 09:17:27

The scripts are pretty much identical, except for the text printed to the file.

#! /bin/bash

# cd to the logFiles dir

cd /Users/jason/logFiles/

# log date and time to file

echo time from Jason log below. should be on the hour. >> daemonLog.txt

echo $(date +"%Y-%b-%d %H:%M:%S") >> daemonLog.txt

The system.log seems to indicate that the system was up at those times. That is, unless it decided to take random naps around the top of the hour. 🙂 (I'd be surprised if this ClamAV thing was the problem, btw.) But that 08:59:57 message is curious. However Date&Time is set automatically from time.apple.com, and I have checked it against my NTP server at work.

Jun 29 05:35:10 <hostname>.apple.SecurityServer[20]: Succeeded authorizing right 'system.privilege.admin' by client '/Library/PrivilegedHelperTools/com.apple.serverd' [70] for authorization created by '/Applications/Server.app/Contents/ServerRoot/usr/libexec/ServerEventAgent' [108] (100000,0)

Jun 29 05:40:33 <hostname> freshclam[113]: Your ClamAV installation is OUTDATED!

Jun 29 05:40:33 <hostname> freshclam[113]: Local version: 0.97.6 Recommended version: 0.97.8

Jun 29 07:34:25 <hostname> com.apple.SecurityServer[20]: Succeeded authorizing right 'system.privilege.admin' by client '/Applications/Server.app/Contents/ServerRoot/usr/libexec/ServerEventAgent' [108] for authorization created by '/Applications/Server.app/Contents/ServerRoot/usr/libexec/ServerEventAgent' [108] (2,0)

Jun 29 07:34:25 <hostname> com.apple.SecurityServer[20]: Succeeded authorizing right 'system.privilege.admin' by client '/Library/PrivilegedHelperTools/com.apple.serverd' [70] for authorization created by '/Applications/Server.app/Contents/ServerRoot/usr/libexec/ServerEventAgent' [108] (100000,0)

Jun 29 07:35:10 <hostname> com.apple.SecurityServer[20]: Succeeded authorizing right 'system.privilege.admin' by client '/Applications/Server.app/Contents/ServerRoot/usr/libexec/ServerEventAgent' [108] for authorization created by '/Applications/Server.app/Contents/ServerRoot/usr/libexec/ServerEventAgent' [108] (2,0)

Jun 29 07:35:10 <hostname> com.apple.SecurityServer[20]: Succeeded authorizing right 'system.privilege.admin' by client '/Library/PrivilegedHelperTools/com.apple.serverd' [70] for authorization created by '/Applications/Server.app/Contents/ServerRoot/usr/libexec/ServerEventAgent' [108] (100000,0)

Jun 29 07:40:39 <hostname> freshclam[113]: Your ClamAV installation is OUTDATED!

Jun 29 07:40:39 <hostname> freshclam[113]: Local version: 0.97.6 Recommended version: 0.97.8

Jun 29 08:59:57 <hostname> com.apple.time[234]: Interval maximum value is 946100000 seconds (specified value: 9223372036854775807).

Jun 29 09:00:29 --- last message repeated 232 times ---

Jun 29 09:35:10 <hostname> com.apple.SecurityServer[20]: Succeeded authorizing right 'system.privilege.admin' by client '/Applications/Server.app/Contents/ServerRoot/usr/libexec/ServerEventAgent' [108] for authorization created by '/Applications/Server.app/Contents/ServerRoot/usr/libexec/ServerEventAgent' [108] (2,0)

Jun 29 09:35:10 <hostname> com.apple.SecurityServer[20]: Succeeded authorizing right 'system.privilege.admin' by client '/Library/PrivilegedHelperTools/com.apple.serverd' [70] for authorization created by '/Applications/Server.app/Contents/ServerRoot/usr/libexec/ServerEventAgent' [108] (100000,0)

The /var/log/com.apple.launchd.peruser.501 log file seems to show nothing troublesome. (I must admit that I don't know what all this means.)

It doesn't have times to correlate, so I've included the last 20 lines at 2013-Jun-29 12:07.

833735 com.apple.launchd.peruser.501 200 com.apple.launchd.peruser.501 200 MIG callout: 416

833738 com.apple.launchd.peruser.501 200 com.apple.distnoted.xpc.agent 203 Getting key: 5

833741 com.apple.launchd.peruser.501 200 com.apple.launchd.peruser.501 200 MIG demux succeeded.

833745 com.apple.launchd.peruser.501 200 com.apple.launchd.peruser.501 200 MIG request.

834023 com.apple.launchd.peruser.501 200 com.apple.launchd.peruser.501 200 MIG callout: 416

834028 com.apple.launchd.peruser.501 200 com.apple.distnoted.xpc.agent 203 Getting key: 5

834031 com.apple.launchd.peruser.501 200 com.apple.launchd.peruser.501 200 MIG demux succeeded.

834035 com.apple.launchd.peruser.501 200 com.apple.launchd.peruser.501 200 MIG request.

834084 com.apple.launchd.peruser.501 200 com.apple.launchd.peruser.501 200 MIG callout: 416

834088 com.apple.launchd.peruser.501 200 com.apple.distnoted.xpc.agent 203 Getting key: 5

834091 com.apple.launchd.peruser.501 200 com.apple.launchd.peruser.501 200 MIG demux succeeded.

834094 com.apple.launchd.peruser.501 200 com.apple.launchd.peruser.501 200 MIG request.

834693 com.apple.launchd.peruser.501 200 com.apple.launchd.peruser.501 200 MIG callout: 69

834699 com.apple.launchd.peruser.501 200 com.apple.launchd.peruser.501 200 Background: Receive right returned to us: com.apple.distributed_notifications@Uv3

834707 com.apple.launchd.peruser.501 200 com.apple.distnoted.xpc.agent 203 Tried to dispatch an already active job: PID is still valid.

834710 com.apple.launchd.peruser.501 200 com.apple.launchd.peruser.501 200 Background: No submanagers left.

834713 com.apple.launchd.peruser.501 200 com.apple.distnoted.xpc.agent 203 Job is active: PID is still valid

834716 com.apple.launchd.peruser.501 200 com.apple.distnoted.xpc.agent 203 Job was sent SIGTERM.

834718 com.apple.launchd.peruser.501 200 com.apple.launchd.peruser.501 200 MIG demux succeeded.

834720 com.apple.launchd.peruser.501 200 com.apple.launchd.peruser.501 200 MIG request.

And, finally, here are the plist files. The one called "testDaemonRoot" is the one I put in the system directory with these commands.

605 sudo cp com.jason.testDaemonRoot.plist /Library/LaunchDaemons//

606 launchctl load -w /Library/LaunchDaemons/com.jason.testDaemonRoot.plist

The one called "testDaemonJason" I entered with this command.

597 launchctl load com.jason.testDaemonJason.plist

mini:crons jason$ cat com.jason.testDaemonRoot.plist

<?xml version="1.0" encoding="UTF-8"?>

<!DOCTYPE plist PUBLIC "-/Apple/DTD PLIST 1.0/EN" "http:/www.apple.com/DTDs/PropertyList-1.0.dtd">

<plist version="1.0">

<dict>

<key>Label</key>

<string>com.jason.testDaemonRoot</string>

<key>ProgramArguments</key>

<array>

<string>/Users/jason/bin/daemonTestRoot.sh</string>

</array>

<key>StartCalendarInterval</key>

<array>

<dict>

<key>Minute</key>

<integer>5</integer>

</dict>

</array>

</dict>

</plist>

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

mini:crons jason$ cat com.jason.testDaemonJason.plist

<?xml version="1.0" encoding="UTF-8"?>

<!DOCTYPE plist PUBLIC "-/Apple/DTD PLIST 1.0/EN" "http:/www.apple.com/DTDs/PropertyList-1.0.dtd">

<plist version="1.0">

<dict>

<key>Label</key>

<string>com.jason.testDaemonJason</string>

<key>ProgramArguments</key>

<array>

<string>/Users/jason/bin/daemonTestJason.sh</string>

</array>

<key>StartCalendarInterval</key>

<array>

<dict>

<key>Hour</key>

<integer>21</integer>

<key>Minute</key>

<integer>0</integer>

</dict>

<dict>

<key>Hour</key>

<integer>22</integer>

<key>Minute</key>

<integer>0</integer>

</dict>

<dict>

<key>Hour</key>

<integer>23</integer>

<key>Minute</key>

<integer>0</integer>

</dict>

<dict>

<key>Hour</key>

<integer>0</integer>

<key>Minute</key>

<integer>0</integer>

</dict>

<dict>

<key>Hour</key>

<integer>1</integer>

<key>Minute</key>

<integer>0</integer>

</dict>

<dict>

<key>Hour</key>

<integer>2</integer>

<key>Minute</key>

<integer>0</integer>

</dict>

<dict>

<key>Hour</key>

<integer>3</integer>

<key>Minute</key>

<integer>0</integer>

</dict>

<dict>

<key>Hour</key>

<integer>04</integer>

<key>Minute</key>

<integer>0</integer>

</dict>

<dict>

<key>Hour</key>

<integer>05</integer>

<key>Minute</key>

<integer>0</integer>

</dict>

</array>

</dict>

</plist>

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

I hope I've given someone enough information to tell me what's going wrong here. Thanks very much for reading this!