ASL: Logging to a file

2008-01-22 12:39:15 UTC

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

13 Responses to “ASL: Logging to a file”

  1. Chris Says:

    I don’t understand where the logging actually pops out if you use the defaults. I’m presuming that the standard procedure is to pick a file name in ~/Library/Logs, call open(…., WRONLY|CREAT|APPEND..) and add that file descriptor to the log. But all this talk of “client connections” makes it sound as if the output will be squirrelled away somewhere by default. But if it is, I can’t figure out where.

  2. Peter Hosey Says:

    As I wrote in “Why ASL?”:

    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.)

    Before you ask where that database is: It’s an implementation detail, as I wrote in “Searching”:

    [The database] 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).

  3. Chris Says:

    Okaayy… but are these log messages visible outside of you writing your own code to search them? I was expecting them to turn up somewhere in Console.app since that seems to show logs from all manner of applications, but nothing appeared until I opened my own file in ~/Library/Logs and logged to that. It seems rather odd to me that there is a standard logging library that squirrels it away in an unknown place with no standard application that can access them.

    And what of log cycling? Am I supposed to take some action to stop logs growing forever?

    Implementation detail or not, I’m curious where they end up on Leopard.

  4. Peter Hosey Says:

    … are these log messages visible outside of you writing your own code to search them?

    They’re only accessible through the ASL API, which Console (in Leopard) is a GUI on top of.

    I was expecting them to turn up somewhere in Console.app since that seems to show logs from all manner of applications, …

    They should.

    … but nothing appeared until I opened my own file in ~/Library/Logs and logged to that.

    You probably searched incorrectly. If you logged it with a facility other than com.apple.console, it won’t show under “Console Messages”; you’ll need to switch to “All Messages”, or a custom query tailored to find your messages. If you did use a custom query, either you constructed it incorrectly or you’ve found a bug in ASL.

    It seems rather odd to me that there is a standard logging library that squirrels it away in an unknown place with no standard application that can access them.

    Console is that standard application.

    And what of log cycling? Am I supposed to take some action to stop logs growing forever?

    No; by default, syslogd will automatically delete messages older than 24 hours. See undocumented keys.

    Implementation detail or not, I’m curious where they end up on Leopard.

    As of 10.5.6, /var/log/asl.db. But don’t ever rely on that in shipping code.

  5. Chris Says:

    Well, I write this program:

    #import <asl.h>
    int main(int argc, char const *argv[]) {
        asl_log(NULL, NULL, ASL_LEVEL_INFO, "Supercalifragilisticexpialidocious");
    }
    

    run it, then I open Console.app, click on All Messages, and it isn’t there. If I search on Supercalifragilisticexpialidocious, it isn’t there.

    I wrote some Cocoa classes that open a file in ~/Library/Logs and connect that to the asl_log, and those come out in the file, but not in the All Messages of Console. What does come out in All Messages are calls to NSLog apparently.

    I wonder why I have log files from dozens of apps in ~/Library/Logs if this database thingy works and is a good idea. I can’t see much from other apps turning up in All Messages.

  6. Peter Hosey Says:

    That explains it, right there. See the syslogd manpage, which says:

    The default filter will retain messages in the range 0 (Emergency) to 5 (Notice) inclusive.

    Info is the second-lowest level—number 6. (Debug is the lowest, at 7.)

    I mentioned this in “Client connections”:

    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.

    What does come out in All Messages are calls to NSLog apparently.

    Those are also under Console Messages, as NSLog uses the Console facility. (Again, see “Client connections”.)

    I wonder why I have log files from dozens of apps in ~/Library/Logs if this database thingy works and is a good idea.

    Several reasons:

    1. Not everyone knows about ASL. Apple hasn’t made a very big deal about its existence; indeed, this series of posts is the most anyone’s written about it, including Apple.
    2. Even those who know about it may not have tried to actually use it directly, since NSLog works just fine. We Cocoa programmers are lazy. ☺
    3. ASL didn’t always exist. Old code uses log files because the alternative was syslog, which did the same thing—except that syslog used one log file for all processes. At least with your own log file, you didn’t have to go sifting through that one common log file to find your application’s messages. (Not a problem anymore: If you use ASL, syslog, or NSLog, you can save a database query in the Console’s sidebar to easily obtain your app’s messages.)
    4. Cross-platform programmers may not want to write code that depends on an API that only exists on one platform. For these programmers, extra functionality on one platform is a burden because that functionality, by definition of the word extra, doesn’t exist on other platforms.
  7. Chris Says:

    Thanks to your help, the mist is slowly clearing for me. One last question is what are “Console messages” for? In the old days a multi-user UNIX system had an actual console. Now that seems a bit redundant. Should we think of this as really important messages or something?

  8. Peter Hosey Says:

    The Console Messages query is the successor to the old console.log file in Mac OS X before Leopard. Before, NSLog output went to console.log; now, it goes into ASL with a facility of “com.apple.console”, which is what the Console Messages query looks for.

    Previously, writing to /dev/console (or, in an Aqua app, stdout or stderr) would also make messages appear in the appropriate place, but this doesn’t seem to work under Leopard. I should report that as a bug.

    I don’t know anything about things that other UNIX operating systems call a “console”, so I can’t speak of any similarities that Apple’s Console app, Console Messages query, or console device may have to it.

  9. Bill Says:

    Yeah, I’m just now finding that this behavior is still present in Lion. It would seem that only NSLog() can put messages into ASL console log such that you can see them using Console.app’s “All Messages”.

    I guess this keeps naive asl(3) users from shooting themselves in the foot, flooding the system log with all kinds of fluff and such.

    If you want your app to have searchable entries in ASL, it seems that you have to edit /etc/asl.conf setting up a rule to create an individual store for your app.

    Using the code below, I couldn’t get any ASL-generated log messages to appear in the console log as viewed via Console.app. Didn’t matter what severity level I chose.

    #include <asl.h>
    #import <Foundation/Foundation.h>
    
    int main (int argc, const char * argv[])
    {
        aslclient asl = asl_open(NULL, "com.apple.console", ASL_OPT_STDERR | ASL_OPT_NO_REMOTE | ASL_OPT_NO_DELAY);
        if (asl == NULL)
        {
            fprintf(stderr, "%s\n", "Can't open a connection to ASL");
            return -1;
        }
        
        asl_log(asl, NULL, ASL_LEVEL_WARNING, "Supercalifragilisticexpialidocious");
        asl_log(asl, NULL, ASL_LEVEL_NOTICE, "Supercalifragilisticexpialidocious");
        asl_log(asl, NULL, ASL_LEVEL_ALERT, "Supercalifragilisticexpialidocious");
        asl_log(asl, NULL, ASL_LEVEL_ERR, "Supercalifragilisticexpialidocious");
    
        asl_close(asl);
    }
    
  10. Jens Ayton Says:

    A possible reason for Chris’s and Bill’s troubles: if you’re a non-administrator user, you’re not authorized to see your own log messages by default. The workaround is to set ASL_KEY_READ_UID to -1.

    This, incidentally, is why DTSendSignalFlag() doesn’t work for non-administrator users.

  11. Jens Ayton Says:

    (Or your actual UID if it’s actually secret, obviously.)

  12. Peter Hosey Says:

    @Bill: Sorry I didn’t fix your comment’s mangled state before. I’ve digitally restored it as best I could, but the header names got completely munched, so I had to guess. I hope I got it right.

  13. Julian Says:

    WARNING: asl_add_log_file() is completely broken (i.e. does nothing) when compiling on 10.12+. you won’t even get a warning about this if you are compiling your app for older versions too. thanks for another bug apple.

Leave a Reply

Do not delete the second sentence.