Archive for the 'Apple System Logger' Category

Apple Bug Friday! 74

Friday, February 22nd, 2008

This bug is Typo in syslogd(8) manpage. It was filed on 2008-01-19 at 15:41 PST.

(more…)

Apple Bug Friday! 73

Friday, February 8th, 2008

This bug is ASL_QUERY_OP_REGEX should be a modifier, not an operator. It was filed on 2008-01-18 at 23:27 PST.

(more…)

ASL: Wrap-up

Monday, January 28th, 2008

Summary

ASL is available on both Tiger and Leopard.

To write to the log:

asl_log(client, /*msg*/ NULL, ASL_LEVEL_NOTICE, "printf-style format; interpolates values, such as %i", 42);

The predefined priority levels are Debug, Info, Notice, Warning, Error (ASL_LEVEL_ERR), Critical (ASL_LEVEL_CRIT), Alert, and Emergency (ASL_LEVEL_EMERG). Every predefined priority level has a symbol to go with it; for example, Notice is ASL_LEVEL_NOTICE.

To open a client connection:

aslclient client = asl_open(/*ident*/ NULL, /*facility*/ "MyClass" /*or other reasonable facility string*/, ASL_OPT_STDERR);

To close it:

asl_close(client);

Opening a client connection is optional (you can pass NULL instead), as is passing ASL_OPT_STDERR if you do it (you can pass 0 instead), but I recommend doing both, so that you can see your ASL output in your Xcode Run Log.

To read from (search) the log:

//Build a query message containing all our criteria.
aslmsg query = asl_new(ASL_TYPE_QUERY);
//Specify one or more criteria with calls to asl_set_query.
asl_set_query(query, ASL_KEY_MSG, "Hello world", ASL_QUERY_OP_EQUALS);

//Begin the search.
aslresponse response = asl_search(query);

//We don't need this anymore.
asl_free(query);

aslmsg msg;
while ((msg = aslresponse_next(response))) {
    //Do something with the message. For example, to iterate all its key-value pairs:
    const char *key;
    for (unsigned i = 0U; (key = asl_key(msg, i)); ++i) {
        const char *value = asl_get(msg, key);

        //Example: Print the key-value pair to stdout, with a tab between the key and the value.
        printf("%s\t%s\n", key, value);
    }

    //Don't call asl_free for the message. The response owns it and will free it itself.
}

aslresponse_free(response);

The messages in the response are those that match all of the criteria (i.e., the search is logical-AND, just like Google). You can set more than one criterion with the same key; you could use this, for example, to express one or more ranges of timestamps.


One final note

I’ve said before that the best way to learn an API whose documentation is insufficient is to document it. This series (which was originally one post) proved that in spades.

I thought I knew ASL before I started, but I think I roughly doubled my knowledge with all the research, testing, and Using the Source, Luke that went into this epic post. I also discovered a total of four issues with the API or its documentation that needed to be filed in RadarWeb.

So, if you know of an API whose documentation is a little thin, such as I/O Kit, or System Configuration, or Core Audio, please write about it. Not only will you inform your readers of what you know, but you will probably learn quite a bit simply in the course of writing it, and your readers will learn what you learned, as well. It will benefit everybody.

ASL: Test apps

Sunday, January 27th, 2008

In the course of writing these posts, I wrote about half a dozen test apps that I used to experiment with ASL’s behavior. A few of them are generally-useful enough that I’m going to share them with you now:

File: asllog.tgz

asllog is a command-line utility for logging messages with ASL. Its usage is very simple:

asllog key=value

It also provides a --to-file=filename switch, which you can use zero or more times to add files (using asl_add_log_file) for the message to be mirrored to.

File: aslsearch.tgz

aslsearch is a command-line utiliy for searching the ASL log or database. Its usage is similarly simple:

aslsearch expression

Each expression is comprised of a key, an operator, and a value. The operators are:

==
ASL_QUERY_OP_EQUAL
<
ASL_QUERY_OP_LESS
<=
ASL_QUERY_OP_LESS_EQUAL
>
ASL_QUERY_OP_GREATER
>=
ASL_QUERY_OP_GREATER_EQUAL
!=
ASL_QUERY_OP_NOT_EQUAL
<>
ASL_QUERY_OP_NOT_EQUAL
?
ASL_QUERY_OP_TRUE

So, for example, to search for all NSLog messages sent by Xcode:

aslsearch Sender==Xcode 'CFLog Local Time?'

File: ASLReader.tgz

Finally, ASLReader is an application that polls the log (once per second) and posts a Growl notification for every new message that it finds. This serves as an effective demonstration not only of polling the log, but also of the minimal code needed to post Growl notifications. You may find the code for this application useful to adapt to other purposes.


Next in the ASL series: Executive summary and wrap-up

ASL: Using ASL from the command line

Saturday, January 26th, 2008

Mac OS X comes with a couple of utilities you can use to work with ASL from your nearest shell prompt.

The older of the two is logger(1), a user interface on the older syslog(3) API. This utility is write-only; it only lets you make entries, not review previous entries. (This makes sense: Historically, syslog wrote its output to a text file that you could tail, view, or grep; you didn’t need a separate utility to read it in any way.)

The newer of the two is syslog(1). As I mentioned in the first post, the name is a bit misleading, because it’s actually built on the ASL API, not syslog(3).

Like logger, syslog lets you write (send) to the log. The usage for that is:

syslog -s -k key value

Note the -s flag, for send.

Unlike logger, you can also read from (search) the log. As with asl_set vs. asl_set_query, you can specify a comparison operator, or leave it out and default to equality testing. To search, simply leave out that -s argument.

  • syslog -k key value
  • syslog -k key operator value

In all cases, you can specify multiple key-value pairs. For searching, the criteria are joined by logical AND (just like with the ASL API underneath).

syslog also provides a -w switch that you can use to poll (“watch”) the database repeatedly. As I mentioned above, polling is the only way to do that with the current API.

Finally, syslog also provides a -c switch to configure syslogd’s filter masks:

  • syslog -c process off
  • syslog -c process new_value

The possible values for process are:

0
Master filter
syslogd” or “syslog
Data store filter
Non-zero number
Per-process filter of process with that PID
Anything else
Per-process filter of process with that name


You must be root (or use sudo) to change the master or data store filter, or (as you might have expected) the per-process filter of a process owned by root. Surprisingly, however, you can set the per-process filter of a process you don’t own, as long as it isn’t owned by root. I believe that this is either a bug or something they didn’t consider (for whatever reason), and have filed it as such.

The other argument must be one of:

“off”
Turns the filter off (of course).
A list of numbers, separated by commas (e.g., “0,1,2,4”)
Sets the filter to allow only those levels (bits), identified by number.
A string of characters from the set “pacexwnid” (e.g., “pacw”)
Sets the filter to allow only those levels, identified by name (where ‘p’, standing for “Panic”, is syslog(1)’s name for Emergency, and ‘x’ is a synonym for Error).
A hyphen, followed by one of the aforementioned letters (e.g., “–w”)*
Every level up to and including that level (i.e., ASL_FILTER_MASK_UPTO(…)); for example, “-d”, meaning “everything up to Debug” (equivalent to everything)

* Note that the first two examples (“0,1,2,4” and “pacw”) skip Error, but the third one (“-w”) includes it, since the range syntax cannot exclude any bit within the range.


Next in the ASL series: Test apps!

Apple Bug Friday! 72

Friday, January 25th, 2008

This bug is ASL provides no way to not escape messages written to a file. It was filed on 2008-01-18 at 18:44 PST.

(more…)

ASL: Undocumented keys

Friday, January 25th, 2008

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

ASL: Console

Thursday, January 24th, 2008

In Leopard, Console changed radically.

Previously, it was nothing more than a text-file reader (a pager, in UNIX terminology) designed for reading log files. It defaulted to reading console.log, although you also had the option of reading system.log or your crash logs.

Here's a screenshot of Console in Tiger. There's a source list on the left, and a plain text view on the right.

That functionality still exists in Leopard, but its default view is very different. Most obvious is the fact that it’s now a table view:

Here's a screenshot of Console in Leopard. The  source list on the left now has two “database queries”, named “All messages” and “Console messages”, in addition to the plain-text log files, and the text view on the right is replaced with a table view.

Note that if you click on one of the log files in the source list at left, it changes to a text view.

It’s easy to miss the fact that the table view is a source, too. Specifically, it’s a “log database query”.

Hmmm. Where have we heard those terms before?

Yes, dear readers, Console drinks from the ASL hose. It also provides a way for you to create new queries graphically:

The “New Log Database Query” dialog box provides the interface for you to create and edit rules that will match keys in ASL messages.

Unfortunately, this dialog box is very limited. You are limited to the stock keys, and you don’t even get all of them:

  • Message (ASL_KEY_MESSAGE)
  • Sender (ASL_KEY_SENDER)
  • Facility (ASL_KEY_FACILITY)
  • Host (ASL_KEY_HOST)
  • Time (ASL_KEY_TIME)
  • Level (ASL_KEY_LEVEL)

No PID, no UID, no GID—and no custom keys. You can’t even search for those undocumented keys that I’m going to tell you about tomorrow.

Your choice of operators is restricted, too. The options are:

  • is equal to (ASL_QUERY_OP_EQUAL)
  • contains (ASL_QUERY_OP_EQUAL | ASL_QUERY_OP_SUBSTRING)
  • starts with (ASL_QUERY_OP_EQUAL | ASL_QUERY_OP_PREFIX)
  • ends with (ASL_QUERY_OP_EQUAL | ASL_QUERY_OP_SUFFIX)
  • matches regex (ASL_QUERY_OP_EQUAL | ASL_QUERY_OP_REGEX)

No numeric search, no comparative searches (e.g., ASL_QUERY_LESS_THAN), and no negative searches (e.g., “is not equal”/ASL_QUERY_OP_NOT_EQUAL). You also don’t get to specify whether you want to be case-insensitive (ASL_QUERY_OP_CASEFOLD) or not.

But I have good news.

First, I just saved a bunch of money on my car insurance.

The other good news is that Console actually does let you search for any keys you want with any operator you want. The trick is that you have to create the query manually.

This is easy to do. You see, every Console database query is just a file. When you create a query in Console, Console creates a .aslquery file in ~/Library/Application\ Support/Console/ASLQueries. You can create these files yourself.

The format of these files is plist-based. Currently, they’re XML plists. Here’s one example:

<?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">
<array>
    <dict>
        <key>key</key>
        <string>Sender</string>
        <key>op</key>
        <integer>1</integer>
        <key>value</key>
        <string>Adium</string>
    </dict>
</array>
</plist>

If you were to assemble this query in code, it would be:

aslmsg query = asl_new(ASL_TYPE_QUERY);
asl_set(query, ASL_KEY_SENDER, "Adium", ASL_QUERY_OP_EQUAL);

Note that ASL_QUERY_OP_EQUAL is currently defined to 1 in asl.h; hence that value as the “op” value in the dictionary.

Console’s editor lets you create OR searches as well as AND searches. You may be wondering how to do this, given that the ASL API provides no way to do this (every search is AND-only). Well, here’s what the file looks like:

<?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">
<array>
    <dict>
        <key>key</key>
        <string>Sender</string>
        <key>op</key>
        <integer>1</integer>
        <key>value</key>
        <string>Fred</string>
    </dict>
    <string>or</string>
    <dict>
        <key>key</key>
        <string>Sender</string>
        <key>op</key>
        <integer>1</integer>
        <key>value</key>
        <string>Barney</string>
    </dict>
</array>
</plist>

It’s just the word “or” between two runs of property dictionaries. So, I think it’s a safe bet that Console simply runs multiple searches and unions the results together (probably using the ASL_KEY_MSG_ID property, which I’ll explain in tomorrow’s post).

So, anyway, to use keys and operators not endorsed by Console, we must create our own aslquery file. You can probably guess the rest, but I’ll go ahead and show you a couple now:

File: CFLog.aslquery.bz2

<?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">
<array>
    <dict>
        <key>key</key>
        <string>CFLog Local Time</string>
        <key>op</key>
        <integer>7</integer>
        <key>value</key>
        <string/>
    </dict>
    <string>or</string>
    <dict>
        <key>key</key>
        <string>CFLog Thread</string>
        <key>op</key>
        <integer>7</integer>
        <key>value</key>
        <string/>
    </dict>
</array>
</plist>

This query returns all NSLogs, using a couple of the undocumented keys that it leaves behind in each message. (Presumably, NSLog works by calling CFLog.) We use Console’s OR functionality, just in case one of the keys goes away.

The operator is ASL_QUERY_OP_TRUE. Note that we specify a value, even though we’re not comparing anything to it; if you omit the value key, Console seems to return every message. I’m not sure why.

Here’s another one:

File: No daemons.aslquery.bz2

<?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">
<array>
    <dict>
        <key>key</key>
        <string>Sender</string>
        <key>op</key>
        <integer>70</integer>
        <key>value</key>
        <string>d</string>
    </dict>
</array>
</plist>

Here, we see a does-not-end-with operator (ASL_QUERY_OP_NOT_EQUAL | ASL_QUERY_OP_SUFFIX). Note that the number in the integer element is decimal; the operator is, in fact, 0x46 (NOT_EQUAL being 0x6, and SUFFIX being 0x40).

Once you’ve obtained or created a .aslquery file, you’ll want to add it to Console’s source list, so you can use it. There are two ways to do this.

One is to move, link (either kind), or copy it into the ~/Library/Application\ Support/Console/ASLQueries folder, then relaunch Console. Console adds an alphabetized list of the folder’s .aslquery files to its source list on launch.

The other way is to open the File with Console.

You can’t just double-click on the .aslquery file, unfortunately. You’ll get this:

A dialog box that says ‘There is no default application specified to open the document “CFLog.aslquery”.’

You’ll need to either use that button, or simply drag the .aslquery file onto Console instead of double-clicking. Alternatively, you can use open(1) or launch.

When Console opens the file, it will add it to its source list. Note, however, that it won’t copy it to your ASLQueries folder, and that you can’t remove the query from the source list without deleting it (using either the “Move to Trash” toolbar item, or the “Move to Trash” menu item in the query’s contextual menu). And don’t even think of renaming, moving, or deleting the file out from under Console—it will get horribly confused, and probably pinwheel.

Clearly, Console is implemented around the assumption that the ASLQueries folder is simply Console’s private storage for queries created within Console.

Note: If you try to use Console’s editor to edit one of your hand-rolled queries that uses unapproved keys or operators, Console will only show you all criteria up to and excluding the first criterion it doesn’t recognize. That criterion, and all criteria after it, won’t show up.

The UTI for .aslquery files is com.apple.aslquery. Unfortunately, Apple didn’t actually import this type into Console by putting a UTImportedTypeDeclarations property in Console’s Info.plist, so Launch Services rejects Console’s claim to be able to open the file (and it does have one). That’s why you have to jump through hoops to open a .aslquery file with Console. Furthermore, Apple didn’t even export it from any bundle. This is more evidence that Apple considers .aslquery files private to Console.


Next in the ASL series: Undocumented keys

ASL: Searching

Wednesday, January 23rd, 2008

Putting messages into the log is one thing. But what if you want to look up messages that are already in it?

Well, the first thing you need to do is create a message.

No! Wait! Come back! I didn’t put that in the wrong section!

This is what that type argument to asl_new is for. The other valid value is ASL_TYPE_QUERY, which is the type of message you need to construct to hold your search parameters.

You specify those parameters by setting them as properties of the query message. You don’t ordinarily use asl_set for this; instead, you use asl_set_query:

int asl_set_query(aslmsg msg, const char *key, const char *value, uint32_t op);

The difference is that fourth argument, op. The operators defined as of Mac OS X 10.4 and 10.5 are:

  • ASL_QUERY_OP_EQUAL
  • ASL_QUERY_OP_LESS
  • ASL_QUERY_OP_LESS_EQUAL
  • ASL_QUERY_OP_GREATER
  • ASL_QUERY_OP_GREATER_EQUAL
  • ASL_QUERY_OP_NOT_EQUAL
  • ASL_QUERY_OP_TRUE

That last one doesn’t compare values at all; you can just pass NULL. It tests whether the given key is present in a message, regardless of its value (hence the name: as far as values are concerned, their comparison is always true).

If you use any of the other operators, you can bitwise-OR one or more of these values into it to modify its behavior:

  • ASL_QUERY_OP_CASEFOLD: Case-insensitive matching.
  • ASL_QUERY_OP_PREFIX: Tests whether the given value is at the start of the value in the log.
  • ASL_QUERY_OP_SUFFIX: Tests whether the given value is at the end of the value in the log.
  • ASL_QUERY_OP_SUBSTRING: Tests whether the given value is anywhere within the value in the log.
  • ASL_QUERY_OP_NUMERIC: Compares values as numbers, rather than as strings. This is the solution to the old “100 < 90” problem.
  • ASL_QUERY_OP_REGEX: Does what it says on the box.

Incidentally, you can use asl_set with a query message; it’s equivalent to calling asl_set_query with the ASL_QUERY_OP_EQUAL operator.

A single query message can hold multiple query parameters. The ASL server joins them all with the logical AND; there is no way to do logical OR, other than to run multiple queries and union the results yourself.

You can set more than one parameter with the same key. This should work with any key, though it’s probably not that useful for keys with string values, such as the message key. It’s more useful for numeric keys, and most useful for ranges of timestamps: You can specify that a message’s time must be ≥ start and < (or ≤) end.

Once you’ve assembled a query message, it’s time to perform the search.

aslresponse asl_search(aslclient asl, aslmsg msg);

As usual, you can pass NULL for the client connection. You can’t pass NULL for the query message; it will give you NULL back. (“You want to search for nothing?! Well, you found it!”) However, you can use an empty query message (one with no properties set) to search for everything: the search will return all messages from the database, even those that don’t have an ASL_KEY_MSG property.

An aslresponse is a really basic iterator object (like NSEnumerator). ASL provides exactly two functions for working with one:

aslmsg aslresponse_next(aslresponse r);
void aslresponse_free(aslresponse a);

Just like with any other iterator, each call to aslresponse_next returns another message from the response, until the response is exhausted; when you call it with an already-exhausted response, it returns NULL.

There is no way to count the contents of an aslresponse, other than to count them yourself (i.e., iterate the entire response and increment a counter on each pass through your loop).

The aslresponse owns the aslmsgs that it returns, so don’t call asl_free on them yourself; the response will do that for you when you free it with aslresponse_free.

Searches are not live. Once you hit the end of a response, you will never get another message from it, even if more messages come in that would match the query. This has the unfortunate side effect that you must poll if you wish to monitor the log using only public interfaces; you could use kevent or select to watch the ASL database file, but that file is not guaranteed to always be in the same place, and it didn’t even exist in Tiger (it was a plain-text log file instead).

When you obtain a message from aslresponse_next, you’ll want to retrieve some properties from it. You do this using asl_get:

const char *asl_get(aslmsg msg, const char *key);

If you want to test whether a message possesses a certain property, just call that function anyway. Just like -[NSDictionary objectForKey:], it returns NULL if the key isn’t present in that message.

To walk all the keys of a message, use asl_key:

const char *asl_key(aslmsg msg, uint32_t n);

As you can see, it takes the index of the key name to retrieve. Similarly to asl_get, if you pass an index that’s out of bounds, it returns NULL.

Note: On Tiger, if the sender of a message didn’t set its ASL_KEY_MSG property before sending it, the message you get back in the search response will have an ASL_KEY_MSG key with a NULL value (you’ll know this because asl_key will find and return the key, but asl_get will return NULL). I think that this is actually a bug in the search code that parses the ASL log file, not a bug in asl_send; on Leopard, the bug is gone, which, I suspect, is because Leopard now uses a database instead of a log file for searches.

The nature of asl_key suggests that the implementation does not hash keys, but simply keeps parallel arrays. This makes sense, because ASL messages have fewer than a dozen keys, and O(n) can take less real time than O(1) for small n.


Next in the ASL series: Console

ASL: Logging to a file

Tuesday, January 22nd, 2008

As I mentioned in the previous post, every ASL client connection (including the default connection) has a set of file descriptors to which ASL will mirror any message you send through it. The set is initially empty, unless you use ASL_OPT_STDERR when creating the connection, in which case ASL will add STDERR_FILENO to it for you.

You can add files to the set with asl_add_log_file, and you can remove them from it with asl_remove_log_file:

int asl_add_log_file(aslclient asl, int fd);
int asl_remove_log_file(aslclient asl, int fd);

As usual, pass NULL to these functions to work with the default connection.

The format of the output changed in Leopard. In Tiger, it’s the “raw” format:

      220 [Time 1197742037] [Host] [Sender ReadFromASLOnDemand] [PID 848] [UID 501] [GID 501] [Level 4] [Message Content object's class (AppDelegate) isn't the class that the object controller is expecting (NSMutableDictionary)]

That number at the start, which is space-padded to ten characters, is the length of the message, including both the space after the length and the newline at the end.

In Leopard, it’s the “std” format:

Fri Dec  7 20:31:55 Foldable-Mac.local ReadFromASLOnDemand[4188] <Warning>: Content object's class (AppDelegate) isn't the class that the object controller is expecting (NSMutableDictionary)

As you can see, the “std” format is simply the NSLog format with the addition of the name of the log level.

Speaking of log levels, every file receives all messages sent to the connection, regardless of the connection’s filter mask.

In either format, ASL encodes your message using strvis. strvis is a function for escaping various characters; ASL uses it to escape newlines, tabs, and any non-ASCII characters. That’s right: Any non-ASCII characters that you send to ASL will show up in stderr as escape sequences (but they will be logged correctly). You can see why this escaping is annoying; worse, there’s no way to turn it off. I’ve filed this in RadarWeb, to request a way to turn this “feature” off.

I recommend you always add stderr to the default connection, preferably as early as possible (in main). This way, every time you do something like this, it will show up in the Xcode run log:

asl_log(/*client*/ NULL, ASL_LEVEL_DEBUG, "Number of active frobnitzers: %u\n", [activeFrobnitzers count]);

Another way would be to open your own client connection with the ASL_OPT_STDERR option (as described above), and use that for all your logging.

Finally, in case you’re wondering, removing a log file from a connection does not close the file. The documentation and header make a rather big point of this.


Next in the ASL series: Searching the log database

ASL: Client connections

Monday, January 21st, 2008

As you saw, both asl_log and asl_send can take an aslclient object or not. The aslclient type represents a connection to the ASL server; when you pass NULL, it uses a default connection.

A client connection has two useful properties:

  • A filter mask, which tells the connection which priority levels it should ignore
  • A set of file descriptors, to which ASL will mirror any messages send through the connection

When you send a message (whether with asl_log or with asl_send directly), the ASL library checks the message’s priority against the filter mask; if the bit for that priority level is not set, then the library does not forward the message on to syslogd (in other words, the message will not truly be sent). However, the library will write the message to every file in the set of FDs, regardless of the filter mask; the filter mask only governs sending messages to syslogd.

You create a client connection of your own with asl_open, and close the connection with asl_close:

aslclient asl_open(const char *ident, const char *facility, uint32_t opts);
void asl_close(aslclient asl);

The ident argument to asl_open, which defaults to your process name, becomes the default sender name (ASL_KEY_SENDER) on every message sent through the connection. Similarly, the facility argument, which defaults to “user”, becomes the default facility name (ASL_KEY_FACILITY) of every message sent through the connection. You can set these on a per-message basis using asl_set.

The last argument is a set of option flags. As of Tiger and Leopard, three flags are available:

ASL_OPT_STDERR
Immediately add STDERR_FILENO to the connection’s set of file descriptors to mirror to.
ASL_OPT_NO_DELAY
BugThe documentation tersely defines this as “connect to the server immediately”. I’ve filed a documentation bug to ask for clarification, but thanks to the source, I can provide a much better explanation. By default, the ASL library will connect to syslogd lazily—specifically, in asl_send. This option tells the ASL library to connect to syslogd immediately, in asl_open, rather than wait until asl_send. Unfortunately, the source did not tell me why you would care.
ASL_OPT_NO_REMOTE
Tells the library to ignore the two server-side filter masks, leaving only the client connection’s own (client-side) filter mask. The manpages for asl(3) and syslogd goes into more detail. I don’t think most of you will need this, especially since both server-side filter masks are off by default anyway.

There are two reasons to create your own client connection:

  • The more common reason is that you have a multithreaded program wherein multiple threads will log to ASL. The manpage warns you not to share connections among threads; instead, you must create one connection for every thread that will log to ASL.
  • The less common reason is that you want to configure your connection:
    • You can set your own identity and/or default facility string. There are few reasons to change the identity; your process name should be good enough. The facility, however, should be useful: You could put your class names into it (as I suggested above), or, since Console shows all messages with a facility of "com.apple.console", you could create a connection with that as its facility, and all your logging (well, all your logging through that connection) would show up in Console. (You can always set the facility for each message, or in a template message; I explained both techniques in the previous post.)
    • You can disable the remote-control filter masks by including the ASL_OPT_NO_REMOTE option, as I mentioned above.
    • You can have multiple client connections with different filter masks or different sets of output files.

Once you’ve created a client connection, you can set its filter mask with asl_set_filter:

int asl_set_filter(aslclient asl, int f);

The filter mask is simply a bitmask, where the priority constants are indices into its bits. asl.h provides two macros with which you can easily create new filter mask values:

  • ASL_FILTER_MASK takes one of the priority constants and returns a filter mask with only that priority level enabled.
  • ASL_FILTER_MASK_UPTO takes one of the priority constants and returns a filter mask “for all priorities up to and including” that priority level, as the header puts it.

Note that priority levels are sorted the wrong way around, so “up to Emergency” is the same as “Emergency only”, since Emergency is numerically the lowest priority.

Additionally, there are predefined filter-mask values for each of the predefined priority levels:

  • ASL_FILTER_MASK_EMERG
  • ASL_FILTER_MASK_ALERT
  • ASL_FILTER_MASK_CRIT
  • ASL_FILTER_MASK_ERR
  • ASL_FILTER_MASK_WARNING
  • ASL_FILTER_MASK_NOTICE
  • ASL_FILTER_MASK_INFO
  • ASL_FILTER_MASK_DEBUG

Hopefully, there will never be a priority level named “UPTO”.

The default filter mask of every connection, according to asl.h, is ASL_FILTER_MASK_UPTO(ASL_LEVEL_NOTICE); i.e., everything but ASL_LEVEL_INFO and ASL_LEVEL_DEBUG.

The asl_set_filter function returns the previously-set filter mask, so if you want to modify the existing filter mask, you’ll have to do something like this:

int mask = asl_set_filter(client, 0);
mask = /*modify mask in some way*/;
asl_set_filter(client, mask);

If Apple’s own admonition not to share a client connection between threads wasn’t enough for you, that should convince you.

There’s no function to get the filter mask, so in order to do that, you must do the same jig, only without the step in the middle:

//Get the mask
int mask = asl_set_filter(client, 0);
asl_set_filter(client, mask);

//Do whatever you wanted to do with mask

There are actually four filter masks:

  • The library-side filter, which is the one you configure with asl_set_filter
  • The master filter for all processes
  • The data store filter
  • The per-process remote-controllable filter

The latter two are also configurable, using the syslog(1) utility. I’ll tell you more about that in one of the later posts.

In any case, you probably won’t need to worry about filter masks, as I said above. The library-side filter mask includes all the priority levels that you care about most of the time; the server-side filter masks are disabled by default; and logging to a file (including stderr) includes all messages, regardless of any filter masks.


Next in the ASL series: Logging to a file

ASL: Logging

Sunday, January 20th, 2008

ASL provides two ways to write to the log.

The first, and most recognizable, way is the asl_log pair of functions:

int asl_log(aslclient asl, aslmsg msg, int level, const char *format, ...);
int asl_vlog(aslclient asl, aslmsg msg, int level, const char *format, va_list ap);

The last two arguments (format, and .../ap) are the same as the arguments to printf/vprintf or syslog/vsyslog. They’re also similar to NSLog/NSLogv, except that ASL does not support %@ in its format strings.

The first two arguments to asl_log are optional. If you pass NULL as the client, it uses a default connection with default settings. If you pass NULL for the message, all of the message’s properties other than the level and content will have their default values. Normally, you will pass NULL for the first two arguments.

The argument in the middle, level, specifies the importance of the message. It works exactly the same way as syslog(3)’s priority argument; in fact, they use the same values, and those values have the same names.

If you don’t feel like changing over all your NSLog calls to use asl_log because you’ll have to change your format strings to use %s and -UTF8String instead of %@, don’t worry. Here’s a one-line macro you can stash in a header file to give you an asl_log-like NSLog:

#define asl_NSLog(client, msg, level, format, ...) asl_log(client, msg, level, "%s", [[NSString stringWithFormat:format, ##__VA_ARGS__] UTF8String])

This macro gives you all the flexibility of asl_log and all the format specifiers of NSLog.

The other way to write to the log is to construct a message object yourself and send the whole thing.

ASL defines a type called aslmsg, which is little more than a key-value mapping. All keys and values are UTF-8 C strings. ASL provides and uses several stock keys for the normal properties of a message:

ASL_KEY_LEVEL
The priority level of the message, expressed as the decimal representation of an integer (ASL_LEVEL_*). When setting this property, you can use the level-name strings (ASL_STRING_*) here; they are names, not numbers, but they will be translated to the correct values for you.

ASL_KEY_MSG
The content of the message.
ASL_KEY_TIME
The time the message was sent. This is read-only; you can’t back-date a message.
ASL_KEY_SENDER
The name of the process that sent this message. You can set a different value for the sender, either in your call to asl_open or by asl_set. Conversely, don’t assume that all sender names (even those that match the name of a process) are accurate, since the real sender may have lied.
ASL_KEY_FACILITY
The name of the facility that sent this message. The wording of the manpage suggests that this property is intended for identifying subsystems in your program; in the context of a Cocoa app, this could mean different classes. On the other hand, if you want your messages to show up in Console, you must use the facility string "com.apple.console" (NSLog seems to do this, and it’s obliquely documented in the manpage for the syslog(1) utility; I’ll talk more about syslog(1) in one of the later posts). By the way, you can’t use any facility name starting with “com.apple.system” unless you’re running as root; otherwise, syslogd will correct it to the default value, “user”.
ASL_KEY_PID
The process ID that sent the message. Read-only.
ASL_KEY_UID
The user ID of the user who owns the process that sent the message. Read-only.
ASL_KEY_GID
The group ID of the primary group of the user who owns the process that sent the message. Read-only.
ASL_KEY_HOST
The hostname of the machine this message was sent from. Read-only since Leopard (writable in 10.4.10—that’s probably a bug, and I have no idea whether they’ve fixed it in 10.4.11).

You can actually use any keys you want; you’re not limited to the Apple-provided keys. However, you would be wise to use reverse-DNS notation in your custom keys, just in case Apple adds one or more standard keys in a future version of Mac OS X; you wouldn’t want to horribly confuse syslogd.

You create a message with the asl_new function:

aslmsg asl_new(uint32_t type);

For a message you plan to write, the correct type is ASL_TYPE_MSG. (That’s not the only type; there’s one other. I’ll tell you about it a few posts from now.)

Of course, an empty message isn’t much good to anybody. The next step is to set its properties using asl_set:

int asl_set(aslmsg msg, const char *key, const char *value);

You don’t need to set all the properties; all of the properties except ASL_KEY_MSG have reasonable default values.

Once you have a filled-out message, you need to write it to the log. There are two ways to do this.

The first way is to use asl_log or asl_vlog. When you pass your message to one of these functions, it’s used as a template; ASL creates a new message based on the one you provide, sets its ASL_KEY_MSG property to the string it constructs from your format and arguments, then puts that message into the log.

The other way is to directly call asl_send:

int asl_send(aslclient asl, aslmsg msg);

As with asl_log, that first argument is optional.

You probably won’t find a reason to use asl_send. On the one hand, you could create an entire aslmsg from scratch, including ASL_KEY_MSG and any custom properties that you want to attach to the message, and call asl_send with it—every time. On the other hand, you could fill out a basic aslmsg once during initialization, putting all your custom properties in it, and keep it around, and use it later as a template in one or more one-line calls to asl_log.

Note that asl_send mutates the message you pass in. When you omit one of the stock keys, asl_send adds it to your message, with a default value. The default values are:

Key Default value
ASL_KEY_TIME The current time (set unconditionally)
ASL_KEY_HOST On Tiger: NULL (set unconditionally)
On Leopard: The “.local” hostname, derived from Sharing prefs (set unconditionally)
ASL_KEY_SENDER The name of your process (only on Leopard; already set by asl_new on Tiger)
ASL_KEY_PID Your process ID (set unconditionally)
ASL_KEY_UID The user (set unconditionally)
ASL_KEY_GID The primary group of the user (set unconditionally)
ASL_KEY_LEVEL NULL
ASL_KEY_MESSAGE NULL
ASL_KEY_FACILITY “user”

I determined this simply by iterating on the key-value pairs of a message after I sent it. (I’ll talk more about inspecting messages in the forthcoming post on searching.)

In case you’re wondering whether you can safely mutate a message object that you’ve already passed to asl_send, without inadvertently modifying the message in the database: Currently, yes, but this fact isn’t documented, so there’s no guarantee that it will always be this way. (A future version could, for example, poke syslogd whenever you call asl_set.)
The documentation seems to assume that you will throw your message away immediately after sending it; asl_log, on the other hand, explicitly uses your message “as a template”.

The documentation says that asl_send is for when you have completely filled out a message already, but this actually is not necessary (at least, not at this time). Most properties will be added for you; the only one you need to add is ASL_KEY_LEVEL, and only because if you don’t set it yourself, ASL acts as if it were set to ASL_LEVEL_DEBUG, which is excluded by the default filter mask (more on those in tomorrow’s post), which will result in your message not being sent on to syslogd.

Also, on Tiger, asl_send does not add the ASL_KEY_HOST key for you; this means that the message will not have an ASL_KEY_HOST property at all when it is entered into the log. Only asl_log and asl_vlog add the property. This was fixed in Leopard; the ASL_KEY_HOST property is always added (by asl_send) whenever you don’t set it yourself.

When you’re done with the message, free it with asl_free:

void asl_free(aslmsg msg);

Next in the ASL series: Client connections

Why ASL?

Sunday, January 20th, 2008

It occurred to me just a few minutes ago that I should have discussed this first. So, I’m retroactively designating this post as the first in the ASL series. (I’m also forging the timestamp—I actually posted this at about 16:44 PST).


Most of us probably use NSLog when we want to log some information:

void NSLog(NSString *format, ...);

Those of us unlucky enough to not have access to Cocoa (e.g., working on a UNIX utility) probably use printf/fprintf instead:

int printf(const char *restrict format, ...);
int fprintf(FILE *restrict file, const char *restrict format, ...);

Both of these are fine, but they lack a couple of things.

First off, they lack any indication of a message’s importance. All messages are just lines in a file (especially with the *printf functions), and they’re all on equal footing.

That problem is solved by syslog(3):

void syslog(int priority, const char *format, ...);

syslog lets you specify any of eight different levels of priority for a message:

  • Emergency
  • Alert
  • Critical
  • Error
  • Warning
  • Notice
  • Info
  • Debug

And that’s great. syslog and the lesser functions NSLog and printf/fprintf have served all of us well for years.

But, for Mac OS X 10.4, Apple said “we can do better”.

And so they created the Apple System Logger.

ASL redefines a “message” to be more than just text. Now, it’s a bundle of key-value pairs—what Cocoa and CF call a dictionary. All the usual properties of a message (including the timestamp, the priority, the process that sent it, and the message itself) are now simply pairs in the dictionary. This is the other thing that NSLog and printf/fprintf lack.

This has two practical benefits:

  1. You can make up your own properties. You’re not limited to just the stock properties anymore; you can invent any properties you want.
  2. You can search the log more easily, now that messages are no longer just text. (This was improved in Leopard, which uses a real database for the log storage; Tiger used a text-based log file.)

And all this is very easy to use—barely more complex than using NSLog. Here’s a taste:

asl_log(NULL, NULL, ASL_LEVEL_NOTICE, "Hello %s!", "world");

I’ll tell more about the task of writing to the log (as well as list all nine of the standard properties) in the next post.

UPDATE 2009-04-24: Corrected use of syslog’s LOG_NOTICE to ASL’s ASL_LEVEL_NOTICE.

Next week: Apple System Logger

Saturday, January 19th, 2008

In Mac OS X 10.4, Apple introduced a new logging system called Apple System Logger. ASL is comprised of three parts:

  • A logging API with all the capabilities of syslog(3) and more. You may think of it as the Quartz or QuickDraw GX to syslog’s QuickDraw.
  • syslogd. Apple’s implementation is modular; on Mac OS X, it includes (among many other modules, well-documented in Mac OS X Internals) an input for communication with ASL clients (i.e., your app) and an output that reads and writes the ASL database. (Minor note: Tiger uses a log file instead of a database.)
  • A front-end command-line tool, confusingly named syslog(1), even though it uses the ASL API rather than syslog(3).

The implementations of all three parts are open-source. The logging API is part of Libc, and syslogd and the command-line utility are the two halves of the syslog project. (In case you’re wondering: Those exist in Tiger’s Libc and Tiger’s syslog as well.)

The API is declared with plenty of comments in /usr/include/asl.h, and documented* in a manpage, though neither of those is exactly an exhaustive treatment of the API.

So, over the next Beatles’ week, I’m going to run a series of posts about ASL. I plan to give you:

  • A tutorial on using the ASL API
  • Bits of code and suggestions that go beyond the documentation
  • Three of my test apps, which are general enough that someone should be able to use them for purposes other than simply pounding on the API

Stay tuned!

(Also, this is post #601 in WordPress’ DB. Woo!)

Posts in this series


* While I was in Cupertino, I told Blake that it’s undocumented, but after I got home, I found the manpage. It exists in both Tiger and Leopard. Oops. Sorry, Blake.

Report-an-Apple-Bug Friday! 71

Friday, January 18th, 2008

This bug is Description of ASL_OPT_NO_DELAY is unclear. It was filed on 2008-01-18 at 17:34 PST.

(more…)