ASL: Undocumented keys

2008-01-25 14:16:19 UTC

In part 2, I listed the standard properties of a message. On Leopard, you can find some other keys that aren’t documented. (Obviously, this means that you shouldn’t rely on their existence or on their values having any particular nature.)

I didn’t list them in part 2 because ordinarily, you only see them when you retrieve messages from a search response. You don’t normally set any of these; in the case of one of them (ASL_KEY_TIME_NSEC), you can’t put it into the message yourself (and there’s no reason to). And I didn’t list them in part 5 because they’re undocumented. You shouldn’t rely on them in the first place; therefore, they should be sequestered.

One more thing: This information is current as of Mac OS X 10.5. To my knowledge, none of these keys exist on Tiger. And as I said above, you can’t rely on any of these continuing to exist in the future.






ASL_KEY_EXPIRE_TIME ("ASLExpireTime")

With this property set, a message won’t be deleted from the main database until no earlier than the appointed time. However, it won’t necessarily be deleted at the appointed time; it may (and probably will, in the current implementation) be deleted some time after it.

Mainly, this exists for the -utmp_ttl and -fs_ttl command-line options to the Mac OS X syslogd. According to man 8 syslogd:

-utmp_ttl
Sets the time-to-live in seconds for messages used by the utmp, wtmp, and lastlog subsystems. The default is 31,622,400 seconds (approximately 1 year). Note that if archival is enabled, these messages will be copied to an archive file after the regular time-to-live interval (24 hours, or as set using -ttl) but will persist in the active database until their own expiry time.
-fs_ttl
Sets the time-to-live in seconds for filesystem error messages generated by the kernel. The default is 31,622,400 seconds (approximately 1 year). As in the case of -utmp_tt [sic], if archival is enabled, these messages will be copied to an archive file after the regular time-to-live interval (24 hours, or as set using -ttl) but will persist in the active database until their own expiry time.

I have filed a Radar bug about the typo.

Now, if you don’t mind, I will now get more specific about how the implementation uses this property.

syslogd sets ASL_KEY_EXPIRE_TIME in any message it receives from launchd with one of three characteristics:

  • Its ASL_KEY_FACILITY property is set to “com.apple.system.utmpx”. In this case, it sets the expire time to the value of ASL_KEY_TIME plus the number of seconds specified by the utmp_ttl option. (Presumably, wtmp uses this, too. I presume this only because the names are so similar.)
  • Its ASL_KEY_FACILITY property is set to “com.apple.system.lastlog”. In this case, it sets the expire time to the value of ASL_KEY_TIME plus the number of seconds specified by the utmp_ttl option.
  • Its ASL_KEY_FACILITY property is set to FSLOG_VAL_FACILITY (“com.apple.system.fs”). In this case, it sets the expire time to the value of ASL_KEY_TIME plus the number of seconds specified by the fs_ttl option.

utmp_ttl and fs_ttl refer not only to the command-line options, but also to global variables that back them.

(Added 2008-12-22)

Karl Moskowski inquired on 2008-12-01 on Cocoa-Dev about the format of ASL_KEY_EXPIRE_TIME values. As of 10.5.6, the format is a UNIX time value (a number of seconds since 1970-01-01T00:00:00Z). The value is usually the value of ASL_KEY_TIME plus some offset (one of the TTL values in syslogd’s settings).

And he notes in a later message that syslogd ignores this property unless syslogd was started with the -a (enable archiving) flag.

syslogd periodically moves messages from the main database to an archive database. (Currently, it does this every 24 hours.) The two functions involved are asl_store_archive, which is the external function in syslog/aslcommon/asl_store.c for starting an archiving run, and archive_release, which releases (deletes) messages from a database.

  • The first time a message is encountered by asl_store_archive, it always archives the message.
  • After asl_store_archive finishes copying messages to the archive, it calls archive_release on each message it copied, to have it deleted from the main database.
  • archive_release checks the expire time of each message that has one. If that time has not yet passed, it sets a “do not archive” flag on the message, then returns; otherwise, it deletes the message from the database. This means that, at this point, a message with an expire time that has not yet passed is still in the main database, as well as the archive database.
  • The next time asl_store_archive runs, it sees the “do not archive” flag and does not copy the message. Presumably, this is either to keep a message from being in the archive twice, or from being copied to two or more archive databases (or both).
  • It does, however, call archive_release on it again. As before, it checks the expire time. If it has finally expired, it now really does delete the message from the main database; otherwise, we put it off again. (The “do not archive” flag is never cleared; once set, it remains set until the message perishes from the Earth.)

Thus, a message archived will only be archived once, and won’t be deleted from the main database until it has expired.

ASL_KEY_IGNORE (ASLIgnore)

syslogd has a configuration file named asl.conf. In this file, you set one query per line (with as many properties as you like), each with action to be executed on messages that match it.

One of the available actions is store, which tells syslogd to open the named file as a database and store the message to it, just as it would normally do in the main database. The store action has an option called exclude_asldb; if this option is specified, then syslogd will store the message to the named database, but not to the main database.

The store action is implemented as the function _act_store in syslog/syslogd.tproj/asl_action.c. First, it stores the message to the database specified as its parameter. Then, if the action was specified with the exclude_asldb option, it sets the ASL_KEY_IGNORE property of the message to "Yes".

Later, the message is passed to aslmod_sendmsg to be recorded in the main ASL database. That function checks for the ASL_KEY_IGNORE property, and if it’s present, it case-insensitively compares it to "yes". (And yes, that is with a different case than it was put in with. Good thing the comparison is case-insensitive.)

If the comparison passes (i.e., the message has the ASL_KEY_IGNORE property with a "yes" value), then aslmod_sendmsg does not put the message into the queue of messages to be put into the main database.

ASL_KEY_MSG_ID (ASLMessageID)

A unique ID number assigned to this message. They increase monotonically within a given database. You’ll only see this in response to a search, because ASL sets this property in the aslmsg when creating it from the database record.

ASL_KEY_READ_UID (ReadUID)

Like ASL_KEY_IGNORE, this one comes from a rule in the asl.conf file—this time, an access action. As you can see from the description of that action in the manpage, you are guaranteed to only ever see your own user-ID in this key, because if it isn’t your UID, the access action will leave the message out of your search results.

Theoretically, you could abuse this property to create a private-messaging service, local to one Mac. In fact, you could even have channels like IRC has, and broadcasts (messages with neither a ASL_KEY_READ_UID nor a channel). Just remember that there’d be no way to disable logging the messages, since you would be using the logging system to do it. ;)

ASL_KEY_READ_GID (ReadGID)

Same deal as ASL_KEY_READ_UID, except for groups (thus, it’s a group ID rather than a user ID).

ASL_KEY_REF_PID (RefPID)

The process ID of the process that the message is about. Usually set by launchd; sometimes, on behalf of launchd agents.

ASL_KEY_REF_PROC (RefProc)

The name of the process that the message is about. Always appears alongside ASL_KEY_REF_PID, as they are both about the same process.

ASL_KEY_SESSION (Session)

This is normally set by launchd on behalf of a launchd agent. For example, on Leopard, messages from X11 have a Session of Aqua; messages from Xgrid Agent have a session of System.


Valid values for this property appear to be the launchd session types, as listed by launchctl(1). The values listed there are for Leopard; Tiger had a different set of Session values. Incidentally, the System type is documented in the launchctl manpage, but not in TN2083. I’ve filed this as a documentation bug.

Also, launchd occasionally sends messages itself, and some of those messages have an ASL_KEY_SESSION property—but with a twist.

When Finder’s Locum (the setuid-root tool that it uses to effect your superpowers when you do something that requires administrator access) exits, launchd sends a message about it. The ASL_KEY_SESSION of that message is set to a number, rather than one of the usual names. These numbers appear to increase with each message, but not monotonically; for example, one message had an ASL_KEY_SESSION of 241, and the next one had an ASL_KEY_SESSION of 245. Very strange. (I’d look up why it does this, but that’s the problem with undocumented things: No documentation.)

The property is set inside syslogd; specifically, by launchd_callback in syslog/syslogd.tproj/daemon.c. The value appears to be supplied by launchd. I know that X11 uses syslog(3) for its logging, and those messages get the ASL_KEY_SESSION property; this suggests that syslog(3) goes through launchd somehow, although this isn’t evident in the source code. I welcome further details.

ASL_KEY_TIME_NSEC (TimeNanoSec)

The billionths of a second since the start of the whole second identified by ASL_KEY_TIME. That is to say, the precise time that the message was logged is ASL_KEY_TIME + (ASL_KEY_TIME_NSEC / 1,000,000,000). This is set by syslogd when it stores the message in the database.

CFLog Local Time

Apparently set to a timestamp string by NSLog (and, presumably, CFLog). Its format is YYYY-MM-DD HH:MM:SS.sss.

CFLog Thread

My guess is that this is a thread identifier. The format is simple: it’s a short hexadecimal number. This, too, is set by NSLog (and, presumably, CFLog).


The formats of the two CFLog keys should be familiar to anybody who’s seen NSLog output in Xcode’s Run Log in Leopard. In case you haven’t, here’s what it looks like:

2007-12-10 00:12:19.645 ReadFromASLOnDemand[7346:10b] Found message: 0x178f70

The timestamp is "CFLog Local Time", and the hex number after the colon inside the square brackets is "CFLog Thread".


Next in the ASL series: ASL at the command line

2 Responses to “ASL: Undocumented keys”

  1. Jim Turner Says:

    Peter,

    Just wanted to say thanks for making this all available. I knew there had to be sub-second precision available somewhere in ASL. Too bad the key is undocumented.

  2. Martin Says:

    Nice reading indeed, thank you for making it available.

    Just as you’re saying, these methods isn’t something you can count on. I just implemented a log capture helper for an iOS-application, and while sub-second values work great in the iPhone simulator, the device locks up or acts really strange when it’s running the code.

Leave a Reply

Do not delete the second sentence.