Volume Number: 23 (2007)
Issue Number: 01
Column Tag: Mac in the Shell
by Edward Marczak
Log files are the heartbeat of your system. You can track what's going on in good times and bad - the latter hopefully pointing you to a way to make things right again. When I say 'heartbeat', however, I should be clear that it's really many hearts. All of the child processes jabbering away, speaking their part. This article aims to teach you how to read logs, show examples, explain the various log contents, and give some logging tips and tricks.
Now, logs may not be a shell topic per se, they're often associated with work in the shell, and perhaps for good reason. On an OS X box, you have the excellent Console.app (/Applications/Utilities/Console.app). It gives you quick access to most important log files, provides quick searching capabilities, and will automatically decompress gzip-rolled logs. Plus, you don't need to open a shell just to access your logs, if that sort of thing bugs you. Additionally, on an OS X Server, the Server Admin application accesses various logs depending on context. While Server Admin is useful for a quick peek, it uses an HTTP call to pull down the log files at appropriate intervals. Due to this, it's not a good way to watch a file fill up quickly. This brings us back to the shell.
Longtime readers of this column already know where I'm heading with this: we're going to run Terminal.app and be looking at logs through a command-line interface. So, open it up now (/Applications/Utilities/Terminal.app).
How do entries in log files appear? This may seem to be a simple question, but it isn't. A log is simply a text file. This text file runs in chronological order, with new entries appended to the end. Any application is certainly capable of performing this on its own, and sometimes, that is the case. More commonly, though, log entries will be logged to the syslog daemon, which in turn is responsible for writing the entries to the proper log or logs. Interestingly, but perhaps not surprisingly, Apple has their own logging facility intended to replace syslogd. In fact, the little secret here is that syslogd is the Apple System Log in disguise.
The Apple System Log, or 'asl' is a syslog-compatible replacement for standard syslog (which deviously is named 'syslogd'). Fortunately for everyone involved, you can still treat it just like syslog, which I will tend to do here.
Programs use an API to write log entries to the syslogd server. As the suffix may clue you in to, syslogd runs as a daemon in the background. As of 10.4, it's initially run, and subsequently controlled from launchd. Of course, applications are free to just drop a text file somewhere and write to it.
Let's take a look at a typical log entry. We'll start out easy:
Nov 6 06:54:40 Jack-Kerouak lookupd[1775]: lookupd
(version 369.5) starting - Mon Nov 6 06:54:40 2006
This is, of course, one long line, but you should get used to it. Often, log lines will wrap - on paper and in your terminal. Each line is read left to right, as you'd expect. Let's pick this entry apart:
Nov 6 06:54:40 - The date and time that this entry was logged. Do note that this is a 24-hour clock ("military time"). Also, read on for a note about GMT entries.
Jack-Kerouac - The hostname of the system that logged this entry. Jack-Kerouac is the name of my PowerBook as I'm often 'On the Road'.
lookupd[1775] - The name and process id or pid that sent the message to the log.
lookupd (version 369.5) starting - Mon Nov 6 06:54:40 2006 - The message itself. This is a simple, "hey, I'm starting up" message.
That was easy, right? The time is an obvious one: you need this to figure out the sequence of events, or, correlate log events with some other happening - be it electronic or real-world (like a power outage, etc.). Why do we need the hostname? If we're looking at the entry in a log on a particular system, it came from that system, right? End of story, no? Fortunately, no. syslogd can be set up to accept log entries from other machines and devices. This can be incredibly useful, but only if you know the host that's creating the message!
The next entry is the process name and process id that sent this message. While the process can set any name it likes, the syslog daemon is responsible for logging the pid that sent the message. Having the pid is interesting: some processes are long-lived, and you can easily correlate a log entry with a pid. Some processes are very ephemeral, and will have wisped away before you can hunt them down based on their pid. Also, if you're looking at an aged log, don't rely on the pid! Process IDs come and go, and may be recycled. Don't look at yesterday's log and try to line up events with pids - even from the same process. These entries may be hints, but until you have good evidence, they should be considered suspect.
Finally, we have the message, or, what the program is trying to tell you! Of course, this depends on the situation. In my example, lookupd is just letting us know that it is starting up. It's simply informational.
Where does one find logs to watch? On a typical Unix system, you'll find all of your logs under one neat hierarchy: /var/log. As is typical for Apple, however, you'll find all of your Unixy logs in /var/log as you may expect, Apple-fied logs under /Library/Logs, and user space logs in each user's ~/Library/Logs directory. Wow. That's a lot of logs.
My example entry above came from /var/log/system.log. system.log is as close to the heartbeat of the system as possible with one log. Consider it the log. Of course, that viewpoint depends on what you're trying to troubleshoot. That said, I do like leaving system.log up in my face as much as possible. It's a great way to pick out issues before they cause havoc.
For apps that log through syslog, how does syslog know in which logs to write each message? For that, you need to consult /etc/syslog.conf. This plain-text configuration file for syslog follows some very standard conventions. Lines beginning with a hash ("#") are ignored, and don't contribute to the configuration. The "*" is a wild-card, and can match multiple facilities. Repeating designations and specifying different log files.
One of my first articles for MacTech detailed syslogd, its conventions, how to get it to accept remote messages and how to get it to write messages to various log files. It's now on-line at http://www.mactech.com/articles/
mactech/Vol.20/20.12/UnixTipsForOSX/index.html. One of the few things in that article that needs updating for 10.4 is how to get syslogd to allow remote messages to be logged. We had an article earlier this year that details this procedure, so I won't go into the detail that he did. For the sake of completeness, though, I'll give you the walkthrough. Remember: you do not need to do this to follow this article. You would typically only do this on a server that is up 24x7 and will centralize logs for an entire LAN or enterprise. With that out of the way:
1. Edit/System/Library/LaunchDaemons/
com.apple.syslogd.plist
2. Add "-u" to the ProgramArguments key, making it look like this:
<key>ProgramArguments</key>
<array>
<string>/usr/sbin/syslogd</string>
<string>-u</string>
</array 3. Save the file
4.Reload syslogd:
# launchctl unload
/System/Library/LaunchDaemons/com.apple.syslogd.plist
# launchctl load
/System/Library/LaunchDaemons/com.apple.syslogd.plist
5. While that gets it going immediately, something wreaks havoc with it during the nightly cron routines. To counteract this, simply unload and load syslog each night in a script. Create /etc/daily.local and add the following lines:
launchctl unload /System/Library/LaunchDaemons/com.apple.syslogd.plist sleep 2 launchctl load
/System/Library/LaunchDaemons/com.apple.syslogd.plist
6. Save this file.
7. Mark /etc/daily.local executable:
sudo chmod 744 /etc/daily.local
8. Now you're done!
Again, this is just the how. For the 'why', please reference Aaron's article.
So, how does one watch a log? As alluded to earlier, there are several ways. There's the very excellent Console.app. Of course, earlier, I listed reasons why I prefer the shell for such a task, so that's what I'll be covering. There are three distinct programs that let you follow what's going on with a log file.
First, there's the ubiquitous tail. tail displays the last lines of a file - 10 by default. More importantly, you can use the '-f' switch to have tail follow the output of a log file in "real-time". I put that in quotes simply because there's always a delay between when an app performs an action and posts a log entry, to the time when it actually shows up. That said, tail is about the best you can do. A listing in print will just not do this justice: you need to see it in action yourself. So, please, open an admin shell, and run:
tail -f /var/log/system.log
You'll initially see the last 10 lines of system log, and then, as new entries are posted, the display will add them to the listing.
Unfortunately, the OS X version of tail is missing a critical feature: following multiple files at once (you can, however, simply tail the last line of multiple files). Every other version of tail I've ever worked with could do this: Solaris, GNU/Linux and yes, even FreeBSD 6. Fortunately, if you're a fink or Mac Ports user (neé Darwin Ports), you can install the excellent multitail. multitail makes up for the lack of features in the current tail. multitail has some other nice features, too. I do find the syntax a little cumbersome, though. After you've run 'fink install multitail' or 'port install multitail', go check it out with:
multitail -I /var/log/system.log -I /var/log/mail.log
Very, very handy.
Another program that's great for viewing log files is less. Now, most people think of less as a better more, or vi-without-the-editing. Did you know that less can also follow a file? One thing that I love about using less to follow a file is highlighting. Let's say you're troubleshooting an e-mail issue for one user. On a busy server, the mail log fills up and scrolls away pretty quickly. Here's what you do: Run less /var/log/mail.log. This just brings mail.log into the buffer of less. Search on the user's login id. For example, you'd type /stevej (that's forward slash, then "stevej"). less will then jump to the first occurrence of "stevej" and highlight it. Something like this line:
Nov 6 05:16:45 xtc postfix/smtpd[4817]: 59D955B7E49:
client=topgun.apple.com[12.34.56.234], sasl_method=CRAM-MD5,
sasl_username=stevej
Now, type F (that's a capital F). less will tell you that it is "Waiting for data... (interrupt to abort)" and start following the file, displaying new lines as they're added to it. Interrupt is control-c. As new lines are added, any occurrences of "stevej' will also be highlighted. This can be of tremendous use in spotting a line you're looking for. If you do see something useful scroll by, just hit command-c, and then use the arrow keys or control-b (back one page), and control-f (forward one page) to navigate. When you're ready to follow again, just press shift-F.
The last way that I'm going to describe is an Apple-specific method. As I mentioned, syslogd in OS X is actually an Apple creation more properly called asl, the Apple System Log. In all other syslogd implementations you find, a message comes into syslogd, gets processed and ultimately written to the right file - end of story. asl does this, too, but then takes the extra step of writing all entries to a backing store. In this case, /var/log/asl.log, but this may change in future releases. This new syslogd-is-really-asl setup appeared in 10.4, so, don't go trying this on your Panther box.
That explanation is leading me to this: the syslog program. Note the lack of a trailing 'd', and the fact that you'll only find this on OS X machines. OK, try it: type syslog and press return. You'll get a screen full of log entries that looks like you just typed cat /var/log/system.log. So, what's the point? The syslog program can follow the entries, similar to less. The "-w" switch will wait for new data, and display it as it arrives. It'd be nice if, like tail, we saw a few previous entries as well, but syslog stoically sits there, cursor on the line below. OK, I can do this with less, what else?
Remember that backing store? Entries are actually written in there in a raw, key/value pair listing. To see that format, we override the default 'standard' format using the '-F' (capital F) switch. Try typing syslog -F raw. Looks a little different this time, doesn't it? You can also use the '-F' switch to define a custom format for your purposes - no awk required! Try this:
syslog -F '$Time $(Sender)[$(PID)]: $Message'
This basically just drops the hostname from the standard format. Useful, if the log you're viewing could only be from one host, and you want to focus on the other details.
While not quite as good as multitail, by default, syslog reports on anything, arriving via the syslog mechanism. This is very useful in conjuction with the -w switch. Of course, unlike multitail, you cannot choose to watch arbitrary files.
Overall, Apple's asl implementation gets more interesting the deeper you dive into it. It can filter the outout according to your criteria:
syslog -k Sender postfix
...to see only messages generated by postfix. It also has a full POSIX API, allowing apps to log to and search the asl data store.
All of that said, I rarely, if ever, use syslog to watch logs. Give me the flexibility and portability of tail, grep and less - that's pretty much all you need. Add to it the simple unfamiliarity, newness and slight clumsiness of syslog, well... perhaps we'll see more in 10.5.
What about all of those other logs I pointed out earlier. Take a look in /Library/Logs. You should see something similar to the following:
drwxrwxr-x 3 root admin 102 Apr 28 2005 AppleFileService drwxrwxr-x 13 root admin 442 Jul 17 10:02 Console drwxrwxr-x 9 root admin 306 Nov 5 08:07 CrashReporter drwxrwxr-x 14 root admin 476 Nov 8 17:19 DirectoryService drwxr-xr-x 3 root admin 102 Sep 7 15:48 NetUpdate drwxrwxr-x 6 root admin 204 Oct 19 2005 Qmaster -rw-rw-rw- 1 root admin 6653 Nov 2 15:04 Software Update.log -rw-r-r- 1 root admin 6910 Oct 19 10:21 panic.log
(If you also have a memberd_dump.log, it's because you, or someone on your machine, ran memberd -l at some point). All of these entries should look relatively familiar. The thing to note is that many are directories, each containing multiple, though related, log files. These files are ideal candidates to view via tail or less.
When you start going through these logs, you'll find that some logs are more useful than others. Sometimes, but not always, you can make a seemingly not-useful log very useful! How?
Some programs let you set the level of logging verbosity. Here's where people unfamiliar with Unix are going to say, "see! That's why I hate Unix!" The fact of the matter is, a) it's up to the application, how much or how little it will log, and if it will let you alter that amount, and b) each app handles this in its own way. There is no single mechanism that allows you to alter the logging level for any given app.
If you're using OS X Server, Server Admin will let you alter the log level of most services. Key here being most. If you're using plain 'ol OS X, you have to do it yourself. Doing it by hand can be better in either case as many programs have logging options that Server Admin won't let you set anyway.
Samba is a great example of many of the topics that we've discussed so far: it can log via syslog, its own mechanism or both. Additionally, you can configure the detail of the logs from minimal to very detailed. You can get more information right on your own disk at file:///usr/share/swat/using_samba/ch06.html, but here's the gist: In samba's /etc/smb.conf file, the following entries configure logging:
log level: sets the detail of the log. Ranges from
1(minimal) to 10 (extreme!).
log file: Where to store the logs file on disk.
max log size: Max size in Kb before samba rolls the log.
debug timestamp: Show time stamps in the logs? Values
of "yes" or "no".
syslog: Send log entries to syslog? Value is a number that
represents the syslog level - values of or below the
number you specify are sent to syslog. Anything higher is
only sent to the samba logs.
syslog only: says what it does, does what it says. Set to
"yes", you won't see any entries in the samba logs.
By default with OS X, samba does not log through syslog. This is the primary reason I stick with tail, grep, and less as my log analysis tools of choice. Samba also does something pretty cool with its config file: while most programs require a reload to pick up alterations, changes in /etc/smb.conf file are picked up every 60 seconds - no reload required! (This can be dangerous too - always work on a copy of smb.conf, check it with testparm, keep the good one on hand just in case, and then move the copy into place.)
My other favorite non-system.log log is the debug log generated by DirectoryServices (although DirectoryServices does log via asl). I mentioned this in the August 2006 Mac in the Shell column, but it bears repeating. Find Directory Service's logs at /Library/Logs/DirectoryService. To increase the verbosity, send the DirectoryService process a USR1 signal: killall -USR1 DirectoryService. Now have a gander at your /Library/Logs/DirectoryService/DirectoryService.server.log file (or, use syslog -k Sender DirectoryService - perhaps even with the -w flag).
Understanding how to read and monitor log files can make troubleshooting easier. More importantly, it is a harbinger of issues, before your users complain. For something that's just baked into me at this point, I tend to take logs for granted (just a little). Even I didn't realize that this topic was so deep and that I'd write this much. Hopefully, the importance of logs, and ways you can make your life easier with them is much more clear now. There are even a few things I just couldn't touch on this month regarding logs, as they really deserve more attention. So, next month (to my surprise), I'll be discussing my favorite log monitoring utilities. You can't stare a monitor watching logs 24x7, right? But, a computer can.
Media of the month: Neal Stephenson's Cryptonomicon. An 'oldie' (1999) but goodie. Now that it comes in paperback, it's even that much easier to read! Despite the Neal Stephenson book-ending-curse, Cryptonomicon is a great read, incredibly prescient; you'll recognize many of the elements, and ultimately learn something (especially if you continue on to the Bruce Schneier penned appendix!).
January! Happy New Year, and Happy MacWorld! If you're attending the show, please stop by the MacTech booth! If you picked this issue up while at the booth, stop back often and please say hello to the MacTech staff and authors that will be doing the same.
Ed Marczak owns and operates Radiotope, a technology consultancy that brings enterprise solutions to small and medium-sized businesses. Outside of this piece of the puzzle, he is Executive Editor of MacTech Magazine, a husband and father, and CTO of WheresSpot, among other things. Find the missing tech piece at http://www.radiotope.com
