14.3 Log with syslog

Logging is the process of issuing one-line messages or warnings that will be either displayed to a human, archived to a file, or both. The mechanism that sendmail uses to produce these logging lines is called syslog(3). The sendmail program is concerned only with issuing its messages and warnings. Once they are issued, the syslog facility takes over and disposes of them in a manner described in the file /etc/syslog.conf. Statements in this file determine whether a logged line is written to a device (such as /dev/console), appended to a file, forwarded to another host, or displayed on a logged-in user's screen.

In the following discussion of syslog and syslog.conf, we will describe the BSD 4.4 version. Some versions of Unix, such as Ultrix, use the 4.2 version of syslog, but because syslog is public domain, we recommend you upgrade and will not cover that old version here.

14.3.1 syslog(3)

The syslog(3) facility uses two items of information to determine how to handle messages: facility and level. The facility is the category of program issuing a message. The syslog facility can handle many categories, but only one, mail, is used by sendmail. The level is the degree of severity of the warnings. The sendmail program issues messages with syslog(3) at various levels depending on how serious the message or warning is.

When sendmail first starts to run, it opens its connection to the syslog facility with the following C-language line:

openlog("sendmail", LOG_PID, LOG_MAIL);   prior to V8.10
openlog(SM_LOG_STR, LOG_PID, LOG_MAIL);   V8.10 and above

This tells syslog three things:

• Unless told otherwise with the -L command-line switch (-L), all messages should be printed using sendmail as the name of the program doing the logging. This means that regardless of what name is used to run sendmail (such as newaliases or smtpd), the name that is logged will always be either sendmail or a name you specify. To specify a different name, with V8.10 or above, just define the SM_LOG_STR compile-time macro when building sendmail:

  define(`SM_LOG_STR', `smtpd')

• The LOG_PID tells syslog that the PID (process identification number) should be included when each message is written. This is necessary because sendmail forks often, and each parent and child will have a different PID. Because queue file identifiers are constructed from PIDs, this record helps to determine which invocation of sendmail created a particular queued file. The PID also allows messages from the daemon form of sendmail to be differentiated from others.

• The facility for sendmail (and all mail-handling programs) is LOG_MAIL. We'll show why this is important when we discuss the syslog.conf file.

Just before sendmail issues a warning, it looks at the logging level defined by its LogLevel option (LogLevel). If the severity of the message or warning is greater than the logging level, nothing is output. If the severity is less than or equal to the logging level, sendmail issues that warning with a C-language call like this:

syslog(pri, msg);

Here, pri is the syslog logging priority, and msg is the text of the message or warning. Note that the LogLevel option (see LogLevel) level is different from the syslog priority. The former is used internally by sendmail to decide whether it should log a message. The latter is used by syslog to determine how it will dispose of the message.

The LogLevel option sets a threshold at and below which sendmail will issue warnings. When the LogLevel option has a zero value, essentially nothing is ever issued. When the LogLevel option has a low value, only critical warnings are issued. At higher values, less critical messages are also logged.

The syntax of the LogLevel option and the kinds of information issued for each level are explained in LogLevel. For each level, all the information produced at lower levels is also issued. That is, setting the LogLevel option to 9 causes messages for levels 1 through 8 also to be issued.

The relationship between the LogLevel option logging levels and syslog priorities is shown in Table 14-1. Note that this relationship is not strictly adhered to by sendmail.

14.3.2 Tuning syslog.conf

Although all messages are emitted by sendmail using a single facility, that of syslog, they need not all arrive at the same place. The disposition of messages is tuned by the syslog.conf file.

The file syslog.conf (usually located in the /etc directory) contains routing commands for use by syslog. That file can be complex because it is designed to handle messages from many programs other than sendmail, even messages from the kernel itself. Under SunOS the syslog.conf file is also complex because it is preprocessed by m4(1) when it is read by syslog.

The file syslog.conf is composed of lines of text that each have the form:

facility.level           target

The facility is the type of program that may be producing the message. The facility called mail is the one that sendmail uses. For the complete list, see the online manual for syslog.conf(5).

The level indicates the severity at or above which messages should be handled. These levels correspond to the LogLevel option levels shown in Table 14-1 of Section 14.3.1. The complete list of syslog.conf levels used by sendmail is shown in Table 14-2.

The target is one of the four possibilities shown in Table 14-3. The target and the preceding level must be tuned for use by sendmail.

For example, the following syslog.conf line causes messages from "mail" (the facility) that are at or above severity "info" (the level) to be appended to the file /var/log/syslog (the target):

facility               target
                        
mail.info              /var/log/syslog
       
     level

A typical (albeit much simplified) /etc/syslog.conf file might look like this:

*.err;kern.debug;user.none          /dev/console
*.err;kern.debug;user.none          /var/adm/messages
auth.notice                         @authhost
mail.info                           /var/log/syslog
*.emerg;user.none                   *

Notice that there can be multiple facility.level pairs on the left, each separated from the others by semicolons. The first two lines handle messages for all facilities at level err, all kernel messages (kern) at level debug and above, and none of the levels (none) for the facility user. The first line sends those messages to the file /dev/console, the computer's screen. The second appends its messages to the file /var/adm/messages.

The third line sends authorization messages (such as repeated login failures) to the host named authhost.

The fourth line appends all messages printed by sendmail at level info and above to the file /var/log/syslog.

The last line is an emergency broadcast facility. A message to any facility (the leftmost *) at the highest level (emerg), except for the facility user (the .none), will be written to the screen of all currently logged-in users (the target *).

Finally, note that facilities can be listed together by using a comma:

mail,daemon.info

This causes the level info to be the level for both the facilities mail and daemon. Only the facility can be listed this way. The level cannot, and (unfortunately) the target cannot.

14.3.3 syslog's Output

When the LogLevel option level is 9 or above (LogLevel), sendmail logs one line of information for each envelope sender and one line of information for each recipient delivery or deferral. As sendmail has evolved, these lines of logging information have grown more complex. Here, we discuss the lines produced by sendmail 8.12.

Each line of information logged looks something like this:

date host sendmail[pid]: qid: what=value, ...

Each line of output that syslog produces begins with five pieces of information. The date is the month, day, and time that the line of information was logged.^[3] The host is the name of the host that produced this information (note that this can differ from the name of the host on which the log files are kept).^[4] The sendmail (or whatever you specified with the -L command-line switch) is literal. Because of the LOG_PID argument that is given to openlog(3) by sendmail (Section 14.3.1), the PID of the invocation of sendmail that produced this information is included in square brackets. Finally, each line includes the qid queue identifier (Section 11.2.1) that uniquely identifies each message on a given host.

^[3] Note that the year is absent. If you need to archive log files for multiple years, you will need to modify the dates inside the files, store files in directories named after years, or use some other similar solution.

^[4] When one host sends the message to another host for handling, and when that later host also sends the message to yet another host, the final host will show the name of the middle host, not the originating host. In general it is not wise to relay messages when originating host information is of concern.

This initial information is followed by a comma-separated list of what=value equates. Which syslog equate appears in which line depends on whether the line documents the sender or the recipient and whether delivery succeeded, failed, or was deferred. In Table 14-4 we list the possibilities in alphabetical order. Then, in the sections at the end of this chapter, we describe the role that each plays.

Note that this table is not comprehensive. There are many more syslog equates used in sendmail's logging output, and those equates can document everything from authentication failure to spam rejection notices. We explain those specialty log lines and equates in their respective sections of this book. In this chapter we restrict our coverage to those equates common to everyday mail delivery.

14.3.4 Gathering Statistics from syslog

The log files that syslog creates provide a wealth of information that can be used to examine and tune the performance of sendmail. To illustrate, we will present a simple shell script for printing daily total message volume.

In the following discussion we will assume that sendmail logging is enabled (the LogLevel option, LogLevel, is nonzero) and that all syslog(8) messages for the facility mail at level LOG_INFO are being placed into the file /var/log/syslog.

14.3.4.1 message_volume.sh

Each mail message that sendmail receives for delivery (excluding those processed from the queue) causes sendmail to log a message such as this:

date host sendmail[pid]: quid: from=sender, size=bytes, ...

That is, for each sender that is logged (the from=), sendmail also logs the total received size of the message in bytes (the size=).

By summing all the size= lines in a /var/log/syslog file, we can generate the total volume of all messages received for the period represented by that file. One way to generate such a total is shown in the following Bourne shell script:

#!/bin/sh
LOG=/var/log/syslog
TOTAL=`(echo 0;
        sed -e '/size=/!d' -e 's/.*size=//' -e 's/,.*/+/' $LOG;
        echo p;
       ) | dc`
echo Total characters sent: $TOTAL

The sed(1) selects only the lines in /var/log/syslog that contain the expression size=.^[5] It then throws away all but the number immediately following each size= (the actual number of bytes of each message), and appends a + to each.

^[5] If other programs also put size= expressions into the log file, you might also want to screen for "sendmail."

The entire sequence of processes is enclosed in parentheses. An echo statement first prints a zero. Then the list of +-suffixed sizes is printed. Finally, another echo prints a character p. The resulting combined output might look like this:

0
123+
456+
7890+
p

The leading 0, the + suffixes, and the final p are commands for the dc(1) program, which adds up all the numbers (the + suffixes) and prints the total (the p). That total is saved in the variable TOTAL for later use in the final echo statement. The output of this simple script might look something like this:

Total characters sent: 8469

More sophisticated scripts are possible, but the Bourne shell's lack of arrays suggests that perl(1) would provide a more powerful scripting environment. Most of the scripts that are available publicly are written in the perl scripting language.