7.4 syslog

7.4 syslog

The syslog facility isn't a program used to evaluate system performance, but rather a set of library calls and a daemon, syslogd, that records information that the system and its programs think is worth logging. All email server applications mentioned in this book, but especially sendmail, use syslog to log data about their behavior, and it would be unwise for an email administrator to ignore this fact. The syslog package was originally developed as a part of the sendmail distribution to help maintain the information it would log. It was later adopted by the rest of Berkeley UNIX around the BSD 4.1 timeframe, and from there spread to other UNIX versions. Now it has become so ubiquitous that the fact that its origin is tied to sendmail has been largely forgotten.

7.4.1 syslog and sendmail

During an SMTP message reception, sendmail logs the sender information at the end of the message transaction, whether the message is actually sent or not. If the message is accepted, then the log entry occurs after the end of the DATA phase. If the message is rejected, then the log entry is made immediately after the rejection. During a successful SMTP message reception, sendmail logs the recipient information at the end of the session, although the precise timing can vary depending on sendmail's delivery mode. At the conclusion of each failed delivery attempt, that attempt is also logged. At least two log entries for each successful delivery and one log entry for each unsuccessful attempt, plus various other entries for start-up, encountering errors, STARTTLS information, and so on, will be made. The two types of log entries mentioned initially make up the bulk of the log messages generated, however, and are the two that occur as a result of a successful delivery. All of these log messages can result in a lot of data, and this information can provide significant insight into what is happening on the server.

Here is an example sendmail log entry for a successful message delivery:

 Mar 12 14:39:49 discovery sendmail[44639]: g2CMdnkq044639:   from=<[e-mail]>, size=1047, class=0, nrcpts=1,   msgid=<[e-mail]>,   proto=ESMTP, daemon=MTA, relay=mail.acm.org [199.222.69.4]  Mar 12 14:39:49 discovery sendmail[44641]: g2CMdnkq044639:   to=<[e-mail]>, delay=00:00:00, xdelay=00:00:00,   mailer=local, pri=30052, dsn=2.0.0, stat=Sent 

The first question asked might be, "How do we count the total number of messages that flow through the system?" This question isn't as simple to answer as it might seem. The answer depends on whether one wants to count the number of SMTP connections, the number of unique messages as sent by a sender, or the number of messages (often sent to multiple recipients) that end up in someone's mailbox somewhere. Each of these metrics is a valid choice, but in my judgment the bulk of the work is done for each successful message recipient, so I generally choose to count the number of syslog entries with both the to= pattern and stat=Sent in them. I call that measure the number of messages that the system has successfully processed, mindful that it is merely one statistic that is much more nebulous than it appears at first glance.

If we consider the format of these log entries to contain a set of fields delimited by whitespace, the first three fields contain information about the date and time when the log entry was made. This information can be parsed to track the busiest time of day for the server. In the from entry, the eighth field contains the size of the message in bytes, which we can use to find out the average message size handled by the system. On the same entry, the tenth field lists the number of recipients per message, another interesting statistic to track. In the to entry, the information in the delay and xdelay fields are of particular interest. The delay field measures the total amount of elapsed time between the receipt of the message and this particular delivery attempt. The xdelay field, which stands for transaction delay, measures the amount of time consumed on this particular delivery attempt, which should reveal something about the current connectivity to a particular site.

A great deal more information available in the logs can be extracted for various purposes, but at this point the next step will be left to the imagination of the reader. Section 2.1.1 of the Sendmail Installation and Operation Guide provides additional information on the sendmail log entries.

A similar set of information can be extracted from the logs left by any of the POP or IMAP daemons discussed in this book. Combined with other statistical information gathered with the tools described here, one can plot number of processes versus load average, connection rates versus disk activity, and so on to obtain a thorough understanding of any email server's performance. These checks can be easily automated, and at least the most basic ones should be part of an email administrator's baselining effort.

7.4.2 syslog and Performance

If a server handles a large volume of email, the resources consumed by syslog in writing out the many log entries can be significant. On very large servers, mounting /var/log or its equivalent on its own disk might be appropriate. Beyond this point, an additional syslog issue directly affects performance that should be mentioned. On Linux systems, by default the syslog daemon will fsync() its log files after each entry is written to them. On a busy email server, this operation can cause a measurable slowdown. In most organizations, email server logs aren't so critical. This behavior can be switched off by preceding the appropriate entry in the /etc/syslog.conf file with "-":

 mail.* -/var/adm/mail 

If logging continues to pose a performance problem for a host, it may be appropriate to log the information to a dedicated remote logging host. If this step is taken, replacing the mail. entries in /etc/syslog.conf with one like the following may be appropriate:

 mail.* @loghost.example.com 

The loghost.example.com machine may end up aggregating log information for a large number of hosts. Because the host name is included in each log entry, it should be straightforward to split the entries out again on the log host if desired. On the log host, a RAID system with a high-performance filesystem may be mounted on /var/log to handle this load.

One downside to remote logging is that syslog sends its messages to the log host using UDP. Thus, if a log message becomes lost en route, it will not be retransmitted. This behavior makes this method less useful if saving each log message is critical. One way to work around it is to replace the default syslog daemon with syslog-ng [SYS] or one of several packages with similar feature sets that support logging over TCP.