Macos – System logs in Mac OSX 10.6

loggingmacmacososx-snow-leopard

Something is filling up my system log files, to the point that console.app will only show the last half hour of each file. It looks like something is trying to escape its sandbox, but I'm not exactly sure what… I'm getting MANY repeated messages that look like:

Feb  3 00:29:57 Brians-mini sandboxd[16]: syslogd(15) deny file-read-data /private/var/log/asl/StoreData
Feb  3 00:29:57 Brians-mini sandboxd[16]: syslogd(15) deny mach-task-name
Feb  3 00:29:57 Brians-mini sandboxd[16]: syslogd(15) deny file-read-data /private/var/log/asl/StoreData
Feb  3 00:29:57 Brians-mini sandboxd[16]: syslogd(15) deny mach-task-name
Feb  3 00:29:59: --- last message repeated 1 time ---
Feb  3 00:29:57 Brians-mini sandboxd[16]: *** process 16 exceeded 500 log message per second limit  -  remaining messages this second discarded ***
Feb  3 00:29:57 Brians-mini sandboxd[16]: syslogd(15) deny mach-task-name
Feb  3 00:30:00: --- last message repeated 499 times ---
Feb  3 00:29:58 Brians-mini sandboxd[16]: *** process 16 exceeded 500 log message per second limit  -  remaining messages this second discarded ***
Feb  3 00:29:58 Brians-mini sandboxd[16]: syslogd(15) deny mach-task-name

Edit to add:

Activity monitor says that sandboxd is taking up 60% cpu, and syslogd is taking up 120%. Now, I assume that that's PER processor (I'm on a core 2 duo) But that's still an AWFUL lot of cpu for those two processes…

EDIT: var/log/asl as per request:

drwxr-xr-x  25 root     wheel       850 Jan  6 06:41 ./
drwxr-xr-x  47 root     wheel      1598 Feb  4 15:16 ../
-rw-r-----   1 root     admin     11414 Jan  4 11:49 2010.01.04.U0.G80.asl
-rw-------   1 root     wheel       874 Jan  4 09:41 2010.01.04.U0.asl
-rw-------   1 acordex  wheel     43862 Jan  4 17:53 2010.01.04.U501.asl
-rw-r--r--   1 root     wheel     44614 Jan  4 23:42 2010.01.04.asl
-rw-r-----   1 root     admin  10241494 Jan  5 16:53 2010.01.05.U0.G80.asl
-rw-------   1 acordex  wheel    669585 Jan  5 18:11 2010.01.05.U501.asl
-rw-r--r--   1 root     wheel    772889 Jan  5 23:42 2010.01.05.asl
-rw-r-----   1 root     admin      9731 Jan  6 18:54 2010.01.06.U0.G80.asl
-rw-------   1 acordex  wheel    404532 Jan  6 18:50 2010.01.06.U501.asl
-rw-r--r--   1 root     wheel    838013 Jan  6 18:53 2010.01.06.asl
-rw-r-----   1 root     admin     52896 Sep 24 18:20 BB.2010.09.30.U0.G80.asl
-rw-r--r--   1 root     wheel     50908 Sep 29 10:30 BB.2010.09.30.asl
-rw-r-----   1 root     admin     58875 Oct 30 11:18 BB.2010.10.31.U0.G80.asl
-rw-r--r--   1 root     wheel     46188 Oct 30 17:41 BB.2010.10.31.asl
-rw-r-----   1 root     admin     10322 Nov  5 18:21 BB.2010.11.29.U0.G80.asl
-rw-r--r--   1 root     wheel      2159 Nov  4 17:21 BB.2010.11.29.asl
-rw-r-----   1 root     admin      6586 Nov  9 14:06 BB.2010.11.30.U0.G80.asl
-rw-r--r--   1 root     wheel     23147 Nov 25 16:36 BB.2010.11.30.asl
-rw-r-----   1 root     admin     21686 Dec 16 19:06 BB.2010.12.31.U0.G80.asl
-rw-r--r--   1 root     wheel     36951 Dec 23 18:32 BB.2010.12.31.asl
-rw-r--r--   1 root     wheel      2584 Jan  6 16:49 BB.2011.01.31.asl
-rw-r--r--   1 root     wheel        12 Jan  6 18:54 StoreData
-rw-r--r--   1 root     wheel         8 Jan  6 16:59 SweepStore

Best Answer

Looks to me like it's syslogd itself causing the problem -- it's been sandboxed away from its data files, so when it tries to access them it generates a sandbox error, which gets handed to syslogd, which triggers it to try to get at its files again... and this repeats as fast as syslogd and sandboxd can go.

Check the contents of /System/Library/LaunchDaemons/com.apple.syslogd.plist (the launchd item that controls how syslogd is launched). It should have a section like this:

    <key>ProgramArguments</key>
    <array>
<!--
    Un-comment the following lines to run syslogd with a sandbox profile.
    Sandbox profiles restrict processes from performing unauthorized
    operations; so it may be necessary to update the profile
    (/usr/share/sandbox/syslogd.sb) if any changes are made to the syslog
    configuration (/etc/syslog.conf).
-->
<!--
        <string>/usr/bin/sandbox-exec</string>
        <string>-f</string>
        <string>/usr/share/sandbox/syslogd.sb</string>
-->
        <string>/usr/sbin/syslogd</string>
    </array>

Note that in the above example (taken from my Mac), the sandbox wrapper around syslogd is commented out. Is the same true on your Mac? If not, re-add the comment markers, and restart syslogd (you can do this with launchctl, but I'd just reboot the machine).

Another note: I took a look in the sandbox profile, /usr/share/sandbox/syslogd.sb, and it looks (to my inexpert eyes) like it does deny mach-task-name and access to /private/var/log/asl/StoreData -- apparently, Apple hasn't debugged (/updated) the profile to match what syslogd actually needs...

Related Question