Understanding Logs

---

The logs generated by qmail and its support programs are extremely valuable for troubleshooting a wide range of problems, including local or remote delivery failures and delays, apparent delivery to the wrong mailbox, and the absence of long-running daemons.

To use the logs, you'll need to know where they are, what format they're in, and how to interpret their contents. The installation determines the location and format of the logs. If splogger is used for logging, /etc/syslog.conf tells you which file(s) contain the logs. If multilog is used, the log run scripts (/service/*/log/run or /var/qmail/supervise/*/log/run) probably specify the location of the logs.

multilog

multilog, which is part of the daemontools package, logs messages to a series of files in a specified directory.

The log directory is specified on the multilog command line, so you can find it by examining your /service/servicename /log/run script or your qmail startup script.

The number of files in the log directory and the maximum size of each file are determined by multilog options. The log filenames are the TAI64 (Temps Atomique International) timestamps (http://cr.yp.to/proto/utctai.html) of the time at which the file was started. The tai64nlocal command, also from daemontools, converts TAI64 timestamps into local, human-readable timestamps.

A typical multilog log entry looks like:

 @4000000038c3eeb104a6ecf4 delivery 153: success: did_1+0+0/ 

@4000000038c3eeb104a6ecf4 is the optional, but recommended, TAI64 time-stamp. The log message itself is delivery 153: success: did_1+0+0.

splogger

splogger uses the Syslog logging system to send messages to the Syslog daemon. Syslog is configured in /etc/syslog.conf. Messages sent to Syslog have a facility and priority. Entries in /etc/syslog.conf filter on the facility and priority to direct the messages to the desired log file, remote log host, or the console. splogger logs to the mail facility by default, so greping the syslog.conf file for mail should show the disposition of qmail's log messages. For example:

 # grep mail /etc/syslog.conf # Log anything (except mail) of level info or higher. *.info;mail.none;authpriv.none;cron.none                 /var/log/messages # Log all the mail messages in one place. mail.*                                                   /var/log/maillog # Save mail and news errors of level err and higher in a # 

The fourth line of the output shows that messages to the mail facility at all priorities are logged to /var/log/maillog.

Typical locations include

• /var/log/syslog

• /var/log/maillog

• /var/adm/SYSLOG

A typical Syslog log entry looks like this:

 Jun  3 11:35:23 sparge qmail: 928424123.963558 delivery 153: success: did_1+0+0/ 

and means the following:

• Jun 3 11:35:23 is the Syslog timestamp.

• sparge is the name of the system that sent the message.

• qmail: is the tag splogger places on all qmail log entries.

• 928424123.963558 is a TAI timestamp.

• delivery 153: success: did_1+0+0/ is the log message itself.

qmail-send Log Messages

Once you've located the logs, you'll have to interpret them. The qmail-send logs are the most informative, showing the details of every delivery attempted.

Successful Delivery

Here's a typical log sequence for a message sent to a remote system from the local system:

 1 new msg 93881 2 info msg 93881: bytes 348 from <[e-mail]> qp 18458 uid 500 3 starting delivery 3975: msg 93881 to remote [e-mail] 4 status: local 0/10 remote 1/20 5 delivery 3975: success:   10.128.133.180_accepted_message./Remote_host_said:_250_ok_989757358_qp_15460/ 6 status: local 0/10 remote 0/20 7 end msg 93881 

Line 1 indicates that qmail-send has received a new message, and its queue ID is 93881. The queue ID is the inode number of the /var/qmail/queue/mess/NN/ file—the queue file that contains the message. The queue ID is guaranteed to be unique as long as the message remains in the queue.

Note 

Inodes are structures that Unix uses to store information about a file such as the owner, group, access permissions (mode), and modification and access times, as well as the contents of the file itself. Each inode has an identification number unique to the file system. qmail uses this uniqueness property to ensure that its queue IDs are unique.

Line 2 says that the message is from [e-mail] and is 348 bytes long. Note that this is the envelope sender address, not the address listed in the From header field, which might be different.

Line 3 says that qmail-remote is starting to deliver the message to [e-mail], and it's assigning the ID 3975 to the delivery.

Line 4 says that zero local deliveries and one remote delivery are pending. It also shows that concurrencylocal is 10 and concurrencyremote is 20.

Line 5 says that delivery 3975 is complete and successful, and it returns the remote server's response, which often contains information that the remote site's mail administrator would find helpful in tracking the delivery. In this case, the 989757358 is a timestamp and the qp_15460 is the remote system's delivery ID.

Line 6 says that no local deliveries and no remote deliveries are pending; in other words, the delivery is complete.

Line 7 says that the message has been delivered completely and removed from the queue. At this point, the queue ID, 93881, is reusable for another delivery.

Unsuccessful Local Delivery

If a delivery fails—either temporarily or permanently—qmail-send will log the reason for the failure.

For example, if the mail administrator tests delivery to a nonexistent local user, qmail-send will log something like this:

 1 new msg 312428 2 info msg 312428: bytes 225 from <[e-mail]> qp 1382 uid 0 3 starting delivery 1: msg 312428 to local [e-mail] 4 status: local 1/10 remote 0/20 5 delivery 1: failure: Sorry,_no_mailbox_here_by_that_name._(#5.1.1)/ 6 status: local 0/10 remote 0/20 7 bounce msg 312428 qp 1385 8 end msg 312428 

Now line 5 says failure instead of success, and the message contains the reason that the delivery failed: nosuchuser is not a valid local recipient (user or alias).

Line 7 shows that a bounce message is being generated. Line 8 would be followed by a series of entries logging the delivery of the bounce message.

If the failure is temporary, the logs will look like this:

 1 new msg 312429 2 info msg 312429: bytes 224 from <[e-mail]> qp 1477 uid 0 3 starting delivery 13: msg 312429 to local [e-mail] 4 status: local 1/10 remote 0/20 5 delivery 13: deferral: please_try_again_later/ 6 status: local 0/10 remote 0/20 

Line 5 says deferral, which indicates a temporary error, and logs the output from qmail-local (please_try_again_later), which was the output of a program delivery that exited with the code 111:

 |echo "please try again later" && exit 111 

Because the delivery is still pending, no end msg 312429 entry is logged.

The delivery will be retried periodically until queuelifetime expires, at which point it will be tried once more before being considered a permanent failure.

Unsuccessful Remote Delivery

Remote delivery failures look like local delivery failures:

 1 new msg 93887 2 info msg 93887: bytes 946 from <[e-mail]> qp 5548 uid 49495 3 starting delivery 1866: msg 93887 to remote [e-mail] 4 status: local 0/10 remote 1/20 5 delivery 1866: failure:   Sorry,_I_couldn't_find_any_host_named_dolphin.example.com._(#5.1.2)/ 6 status: local 0/10 remote 0/20 7 bounce msg 93887 qp 5550 8 end msg 93887 

Again, line 5 indicates failure and shows the reason: The remote host is invalid. And again line 7 shows that a bounce message is being generated.

tcpserver Log Messages

While qmail-send keeps a detailed record of its activity, qmail-smtpd does just the opposite: It does no logging whatsoever. If you're serving SMTP using tcpserver, as recommended in Chapter 2, "Installing qmail," you'll at least have a record of connections and connection attempts.

Successful Connection

A successful connection to the SMTP port looks like this:

 1 tcpserver: status: 1/20 2 tcpserver: pid 1418 from 192.168.1.4 3 tcpserver: ok 1418 example.com:192.168.1.8:25 example.net:192.168.1.4::4471 4 tcpserver: end 1418 status 0 5 tcpserver: status: 0/20 

Line 1 shows that one of the maximum of twenty connections is active.

Line 2 shows that tcpserver has spawned process ID 1418 to handle the connection.

Line 3 shows that the connection was accepted by example.com, port 25 (SMTP), from example.net, port 4471.

Line 4 shows that the connection was terminated and qmail-smtpd exited with status 0 (zero), indicating success.

Line 5 shows that there are no active connections.

Unsuccessful Connection

An unsuccessful connection to the SMTP port looks like this:

 1 tcpserver: status: 1/20 2 tcpserver: pid 1554 from 127.0.0.1 3 tcpserver: deny 1554 localhost:127.0.0.1:25 localhost:127.0.0.1::32778 4 tcpserver: end 1554 status 25600 5 tcpserver: status: 0/20 

Lines 1 and 2 are similar to those from a successful connection.

Line 3 shows that the connection was denied (deny) by localhost, port 25, from localhost, port 32778.

Line 4 shows that the connection was terminated with an error (nonzero) status of 25600.

Interpreting the exit status beyond success/failure is tricky. In this case, we know the connection failed because access was denied (deny in line 3). If the connection is allowed (ok in line 3), but the status is nonzero, qmail-smtpd exited with an error code. The most common cause of this is the remote server sending a message with "bare linefeeds."

To really see why qmail-smtpd is failing, you'll need to record the SMTP dialogue with recordio (see the next section).

Using recordio to Log SMTP Sessions

If tcpserver's connection logging is insufficient for troubleshooting problems with incoming SMTP sessions, you can use the recordio utility from the ucspitcp package to record both sides of every session.

If you're running qmail-smtpd under tcpserver, as described in Chapter 2, "Installing qmail," simply insert recordio on the tcpserver command line right before the invocation of qmail-smtpd. For example, change this:

 exec /usr/local/bin/softlimit -m 2000000 \      /usr/local/bin/tcpserver -v -p -x /etc/tcp.smtp.cdb -c "$MAXSMTPD" \           -u "$QMAILDUID" -g "$NOFILESGID" 0 smtp /var/qmail/bin/qmail-smtpd 2>&1 

to this:

 exec /usr/local/bin/softlimit -m 2000000 \      /usr/local/bin/tcpserver -v -p -x /etc/tcp.smtp.cdb -c "$MAXSMTPD" \           -u "$QMAILDUID" -g "$NOFILESGID" 0 smtp /usr/local/bin/recordio \                /var/qmail/bin/qmail-smtpd 2>&1 

Next, tell supervise to restart the qmail-smtpd service:

 # svc -t /service/qmail-smtpd # 

The log of a short SMTP session looks like this:

 1 tcpserver: status: 1/20 2 tcpserver: pid 1619 from 192.168.1.4 3 tcpserver: ok 1619 example.com:192.168.1.8:25 example.net:192.168.1.4::4552 4 1619 > 220 dolphin.example.com ESMTP 5 1619 < helo dude 6 1619 > 250 dolphin.example.com 7 1619 < mail from:<[e-mail]> 8 1619 > 250 ok 9 1619 < rcpt to:<[e-mail]> 10 1619 > 250 ok 11 1619 < quit 12 tcpserver: end 1619 status 0 13 tcpserver: status: 0/20 14 1619 > 221 dolphin.example.com 15 1619 > [EOF] 

The recordio entries are intermingled with the tcpserver entries and are prefixed by the process ID of recordio, 1619. Lines sent by the local qmail-smtpd are prefixed with greater-than signs (>), and lines received from the remote host are prefixed with less-than signs (<). Lines 1 through 3 log the acceptance of the connection. Line 4 is qmail-smtpd sending the SMTP greeting message. Lines 4 through 11 contain both sides of the SMTP dialogue, which is ended before a message was injected—perhaps the remote user was testing relaying or acceptability of the recipient address. In lines 12 and 13, tcpserver logs the termination of the connection. Lines 14 and 15 show qmail-smtpd's response to the SMTP QUIT command.

Caution 

While recordio is in use, the tcpserver logs grow dramatically faster than they do when only connections are being logged. If you're using multilog, this will cause your logs to rotate faster than normal. If you're using splogger, this can result in huge log files—perhaps filling up the file system that holds the logs. It's best to enable recordio only during brief test periods. Also, if you're logging using splogger, the increased logging burden imposed by recordio can cause syslogd to consume lots of processor cycles. (See Chapter 2, "Installing qmail," for information about Syslog and multilog).

Extended Message Logging

The combination of message headers (see the next section, "Using Message Headers") and logs is usually sufficient for troubleshooting purposes. If further logging is required, it can be accomplished using QUEUE_EXTRA.

QUEUE_EXTRA is a compile-time configuration variable that specifies an additional recipient that will be added to every delivery. The dot-qmail file that handles the extra recipient address can log everything—up to and including the entire message.

To use QUEUE_EXTRA, edit extra.h in the qmail source directory. Specify the additional recipient in the format "Trecipient\0",and the length of the QUEUE_EXTRA string in QUEUE_EXTRALEN (the \0 counts as one character). For example:

 #define QUEUE_EXTRA "Tlog\0" #define QUEUE_EXTRALEN 5 

Shut down qmail if it's running. If you installed the qmailctl script from Chapter 2, "Installing qmail," that can be done by executing the following command:

 # qmailctl stop Stopping qmail. . .   qmail-smtpd   qmail-send # 

If you don't have the qmailctl script, you should use your startup/shutdown script or send qmail-send a TERM signal.

Then rebuild qmail using this:

 # make setup check . . .lots of output 

Next, populate /var/qmail/alias/.qmail-log with instructions to implement the logging you desire. For example, to log only Message-ID fields, you could use something like this:

 | awk '/^$/ { exit } /^[mM][eE][sS][sS][aA][gG][eE]-/ { print }' 

Finally, restart qmail:

 # qmailctl start Starting qmail # 

With the previous Message-ID logging enabled, a typical delivery will look like this:

 1 new msg 311925 2 info msg 311925: bytes 211 from <[e-mail]> qp 8024 uid 0 3 starting delivery 1: msg 311925 to local [e-mail] 4 status: local 1/10 remote 0/20 5 starting delivery 2: msg 311925 to remote [e-mail] 6 status: local 1/10 remote 1/20 7 delivery 1: success: Message-   ID:_<[e-mail]>/did_0+0+1/ 8 status: local 0/10 remote 1/20 9 delivery 2: success:   192.168.1.4_accepted_message./Remote_host_said:_250_ok_991581345_qp_8830/ 10 status: local 0/10 remote 0/20 11 end msg 311925 

Line 3 shows the injection of the extra copy of the message. Line 7 shows the output of the delivery to "log," which contains the Message-ID. Line 9 logs the actual remote delivery status.

You could, of course, keep a copy of every message that passes through the system simply by specifying a mailbox delivery in /var/qmail/alias/.qmail-log, for example:

 ./Maillog/ 

The .qmail-log file must not contain any delivery instructions that will inject more messages—such as forwarding to another address—because those messages will also be logged. This will create a loop.

Caution 

Logging the contents of messages may be illegal in some areas. The legality of such logging might depend upon whether users have been notified in advance. Consult a loca attorney if you're not sure. Regardless of the legality of logging message content, mail administrators should respect the privacy of their users by logging only what they need and keeping the logs accessible only to those who need access.

---