23 Managing Logging

This information provides overview information on the logging facilities for the Oracle Communications Messaging Server MTA, the Message Store, and services. This information also provides procedures for how to manage these logging facilities.

Topics:

• Overview of Logging

• Managing MTA Message and Connection Logs

• Managing Message Store, Admin, and Default Service Logs

• Using Message Store Log Messages

• MMP Logging

Overview of Logging

This section contains the following subsections:

• What Is Logging and How Do You Use it?

• Types of Logging Data

• Types of Messaging Server Log Files

• Tools for Managing Logging

• Tracking a Message Across the Various Log Files

What Is Logging and How Do You Use it?

Logging is the means by which a system provides you with time-stamped and labeled information about the system's services. Logging provides both a current snapshot of the system as well as a historical view.

By understanding and using Messaging Server log files, you can:

• Gather message statistics, such as message size, rate of message delivery, and how many messages are passing through the MTA

• Perform trend determination

• Correlate capacity planning

• Troubleshoot problems

For example, if your site needs to add more disk storage due to an increase in the number of users, you can use the Messaging Server log files to see what percentage your system demand has increased by and plan for the amount of new disk storage you need.

You can also use Messaging Server logs to understand what your messaging pattern looks like across one day. Understanding when your daily peak loads occur helps you conduct capacity planning.

Logging is also helpful for troubleshooting user problems. For example, if a user isn't receiving expected mail messages, you can use the Messaging Server logging facilities to trace the user's mail messages. In so doing, you might find out that the messages didn't arrive because they were automatically filtered and sent to a SPAM folder.

Types of Logging Data

In general, logging provides you with two types of information:

• Operational data

• Error conditions, also known as event logging

For the most part, Messaging Server logging provides operational data. This operational data contains information such as: the date and time a message entered the system; the sender and recipient of the message; when the message was written to disk; and at a later point in time, when the message was removed from disk and inserted into user's mailbox.

However, Messaging Server logging does also provide some event logging data. To obtain event logging data, you need to pull together multiple items from different log files. You could then use a unique constant, such as message ID, to search and correlate the life cycle of a message as it passed from point to point through the system.

Types of Messaging Server Log Files

Messaging Server logging consists of three types of log files:

1. MTA logs. These logs provide operational data previously described for the Message Transfer Agent.

2. Error logs. These are the MTA debug logs, and the MTA subcomponent logs (that is, job controller, dispatcher and so on).

3. Message Store and Service logs. These logs provide messages from the http server, mshttpd, imap, and pop services, as well as the Admin service. The format of these logs differs from that of the first two types of logs.

Table 23-1 lists the different types of log files. By default, log files are located in the MessagingServer_home/data/log directory. You can customize and view each type of log file individually.

Table 23-1 Messaging Server Log Files

Type of Log File	Log File Description	Default Name
Message Transfer Agent	Show information about message traffic through the MTA including date and time information, enqueue and dequeue information, and so on.	mail.log_current, mail.log_yesterday, mail.log
Connections	Contains remote machines (MTAs) that connect to this system to send email.	connection.log
Counters	Contains message trends in terms of messages sent and received on a per channel basis.	counters
Job Controller	Contains data on the master, job controller, sender, and dequeue channel programs.	job_controller.log
Dispatcher	Contains errors pertaining to the dispatcher. Turning on dispatcher debugging will increase the information.	dispatcher.log
Channel	Records errors pertaining to the channel. Channel options master_debug and slave_debug turn on channel debugging, which increases the verbosity of the channel log files. Level and type of information is controlled with the various *_DEBUG MTA options.	channel-name_master.log* (example: tcp_local_master.log*)channel-name_slave.log* (example: tcp_local_slave.log*)
IMAP	Contains logged events related to IMAP4 activity of this server	imap, imap.sequenceNum.timeStamp
POP	Contains logged events related to POP3 activity of this server	pop, pop.sequenceNum.timeStamp
HTTP	Contains logged events related to HTTP activity of this server	http, http.sequenceNum.timeStamp
Default	Contains logged events related to other activity of this server, such as command-line utilities and other processes	default, default.sequenceNum.timeStamp
msgtrace	Contains trace information for the Message Store. File can grow very large very quickly. Monitor accordingly.	msgtrace
watcher	Monitors process failures and unresponsive services (see Table 3-6, "Services Monitored by watcher and msprobe") and will log error messages indicating specific failures.	watcher

where:

sequenceNum - Specifies an integer that specifies the order of creation of this log file compared to others in the log-file directory. Log files with higher sequence numbers are more recent than those with lower numbers. Sequence numbers do not roll over. They increase monotonically for the life of the server (beginning at server installation).

timeStamp - Specifies a large integer that specifies the date and time of file creation. (Its value is expressed in standard UNIX time: the number of seconds since midnight January 1, 1970.)

For example, a log file named imap.63.915107696 would be the 63rd log file created in the directory of IMAP log files, created at 12:34:56 PM on December 31, 1998.

The combination of open-ended sequence numbering with a timestamp gives you more flexibility in rotating, expiring, and selecting files for analyzing. For more specific suggestions, see "Defining and Setting Service Logging Options."

Tools for Managing Logging

You can customize the policies for creating and managing Messaging Server log files by using the msconfig command.

For Message Store, the settings you specify affect which and how many events are logged. You can use those settings and other characteristics to refine searches for logged events when you are analyzing log files.

The MTA uses a separate logging facility you configure MTA logging by specifying information in configuration files.

For log analysis and report generation beyond the capabilities of Messaging Server, you need to use other tools. You can manipulate log files on your own with text editors or standard system tools.

With a scriptable text editor supporting regular-expression parsing, you can potentially search for and extract log entries based on any of the criteria discussed in this information, and possibly sort the results or even generate sums or other statistics.

In UNIX environments you might also be able to modify and use existing report-generation tools that were developed to manipulate UNIX syslog files. If you wish to use a public-domain syslog manipulation tool, remember that you might need to modify it to account for the different date/time format and for the two extra components (facility and logLevel) that appear in Messaging Server log entries but not in syslog entries.

Tracking a Message Across the Various Log Files

The following describes how a message flows through the system, and at what point information gets written to the various log files. This description is meant to aid you in your understanding of how to use Message Server's log files to troubleshoot and resolve problems. See Figure 5-2, "MTA Architecture" to follow along.

1. A remote host makes a connection to the TCP socket on your messaging host, requesting SMTP service.

2. The MTA dispatcher responds to the request, and hands off the connection to your messaging host's SMTP service. As the MTA is modular in design, it consists of a set of processes, including the job controller and the SMTP service dispatcher. The dispatcher takes the incoming TCP connection and sends it to the SMTP service. The SMTP service writes the message to disk to a channel area. The SMTP service understands the message's envelope options, such as sender and recipient. Configuration entries in the system tell what destination channel it belongs to.

3. The dispatcher writes to the dispatcher.log file that it forked a thread and made the thread available to incoming connection from a certain IP address.

4. The SMTP server writes to its tcp_smtp_server.log file, recording the dialog of what happens when the remote host connected to it and sent a message. This log file gets created when dispatcher hands off to SMTP server on the host's IP.

5. The SMTP server writes the message to a queue area on disk for a channel program such as tcp_intranet, and informs the job controller.

6. The job controller contacts the channel program.

7. The channel program delivers the message. Each channel has its own log file. However, these logs usually show the starting and stopping of the channel. To get more information, you need to enable debug level for the channel. However, as this can slow down your system and actually make problems more obscure if left on, you should only enable debug level when an actual problem is occurring.

   Note:

   For efficiency, if a channel is already running for an existing process, and a new message comes in, the system does not spawn a new channel process. The currently running process picks up the new message.

8. The message is delivered to its next hop, which could be another host, another TCP connection, and so forth. This information is written to the connection.log file when SEPARATE_CONNECTION_LOG is enabled. At the same time that the SMTP server writes the message to a queue area on disk, the channel responsible for the message writes a record in the mail.log_current file. The record shows such information as the date and time the message was enqueued, the sender, the recipient, so forth. See "MTA Message Logging Examples" for more information. The most useful file for tracing the message is the mail.log_current file.

Managing MTA Message and Connection Logs

The MTA provides facilities for logging each message as it is enqueued and dequeued. It also provides dispatcher error and debugging output.

This section consists of the following subsections:

• Understanding the MTA Log Entry Format

• Enabling MTA Logging

• Specifying Additional MTA Logging Options

• MTA Message Logging Examples

• Enabling Dispatcher Debugging

You can control logging on a per-channel basis or you can specify that message activity on all channels be logged. In the initial configuration, logging is disabled on all channels.

See "Enabling MTA Logging" for more information.

Enabling logging causes the MTA to write an entry to the MessagingServer_home/data/log/mail.log_current file each time a message passes through an MTA channel. Such log entries can be useful for gathering statistics on how many messages are passing through the MTA (or through particular channels). You can also use these log entries to investigate other issues, such as whether and when a message was sent or delivered.

The message return job, which runs every night around midnight, appends any existing mail.log_yesterday to the cumulative log file, mail.log, renames the current mail.log_current file to mail.log_yesterday, and then begins a new mail.log_current file. The message return job also performs the analogous operations for any connection.log* files.

While the MTA performs automatic rollovers to maintain the current file, you must manage the cumulative mail.log file by determining policies for tasks such as backing up the file, truncating the file, deleting the file, and so on.

When considering how to manage the log files, note that the MTA periodic return job will execute a site-supplied MessagingServer_home/data/site-programs/bin/daily_cleanup script, if one exists. Thus some sites might choose to supply their own cleanup procedure that, for instance, renames the old mail.log file once a week (or once a month), and so on.

Note:

With logging is enabled, the mail.log file steadily grows and, if left unchecked, consumes all available disk space. Monitor the size of this file and periodically delete unnecessary contents. You can also delete the entire file as another version will be created as needed.

Understanding the MTA Log Entry Format

The MTA log file is written as ASCII text. By default, each log file entry contains eight or nine fields as shown in the example below.

16-Feb-2007 14:54:13.72 tcp_local ims-ms EE 1 [e-mail] rfc822;[e-mail] marlowe@ims-ms-daemon

The log entry shows:

1. The date and time the entry was made (in the example, 16-Feb-2007 14:54:13.72).

2. The channel name for the source channel (in the example, tcp_local).

3. The channel name for the destination channel (in the example, ims-ms). For SMTP channels, when LOG_CONNECTION is enabled, a plus (+) indicates inbound to the SMTP server; a minus (-) indicates outbound via the SMTP client.

4. The type of entry (in the example, EE). Entries can consist of a single action code (see Table 23-2, "Logging Entry Action Codes") or an action code and one or more modifier codes (see Table 23-3, "Logging Entry Modifier Codes"). The format for entries is as follows

   :<action_code><zero or more optional modifiers>

   For example a logging entry code of EEC means that the email was Enqueued (action-code E) using ESMTP (modifier E) and SMTP Chunking (modifier C). Please refer to the tables below for details on the currently used action and modifier codes.

5. The size of the message (in the example, 1). This is expressed in kilobytes by default, although this default can be changed by using the BLOCK_SIZE MTA option. The SMS channel can be configured to log a page count rather than file size in this field. See Table 27-5, "SMS Channel Options" for information on LOG_PAGE_COUNT.

6. The envelope From: address (in the example, [e-mail]). Note that for messages with an empty envelope From: address, such as notification messages, this field is blank.

7. The original form of the envelope To: address (in the example, [e-mail]).

8. The active (current) form of the envelope To: address (in the example, marlowe@ims-ms-daemon).

9. The delivery status (SMTP channels only).

The following three tables describe the logging entry codes.

Table 23-2 Logging Entry Action Codes

Entry	Description
B	Bad command sent to the SMTP server. The recipient address field will contain the command that was rejected while the diagnostic field will contain the response the SMTP server gave. MTA channel option, MAX_B_ENTRIES, controls how many bad commands will be logged in a given session. Default is 10.
D	Successful dequeue
E	Successful enqueue
J	Rejection of attempted enqueue (rejection by slave channel program)
K	Recipient message rejected. If the sender requests NOTIFY=NEVER DSN flag set or if the message times out or if the message is manually returned (for example: imsimta qm "delete" command always generates a "K" record for each recipient, while a qm "return" command will generate a "K" record rather than an "R" record). This indicates that there was no notification sent to the sender per the sender's own request.This can be compared with "R" records, which are the same sort of rejection/time-out, but where a new notification message (back to the original sender) is also generated regarding this failed message.
Q	Temporary failure to dequeue
R	Recipient address rejected on attempted dequeue (rejection by master channel program), or generation of a failure/bounce message
S	LMTP deposit into the message store. This action code is used on the LMTP server side.
V	Warning message that will appear whenever a transaction is abnormally aborted. There will be one "V" record per enqueued recipient address.
W	Warning message sent to notify original sender that the message has not been delivered yet, but it is still in the queue being retried.
Z	Some successful recipients, but this recipient was temporarily unsuccessful; the original message file of all recipients was dequeued, and in its place a new message file for this and other unsuccessful recipients will be immediately enqueued

Table 23-3 describes the logging entry modifier codes.

Table 23-3 Logging Entry Modifier Codes

Entry	Description
A	SASL authentication used.
B	SMTP BINARYMIME extension used (RFC 3030).
C	Chunking was used. Note that ESMTP has to be used for chunking to work, so you'll typically see field values like EEC or DEC.
E	An EHLO command was issued/accepted and therefore ESMTP was used.
L	LMTP was used.
Q	SMTP PIPELINING extension used (RFC 2920).
S	TLS/SSL used. S transaction log entries now increment the various submitted message counters associated with the channel.
U	BURL used (RFC 4468).

If LOG_CONNECTION is enabled, then an additional set of action codes will be used. See the discussion on LOG_CONNECTION in the Messaging Server Reference. These are described below.

Table 23-4 SMTP LOG_CONNECTION Action Codes + or - Entries

Entry	Description
C	Connection closed. A diagnostic field will follow. Written to connection.log_current (or {{mail.log_current if a single log file is being used). Used to record the reason why the connection was closed. In particular, if the connection was closed due to some session disconnect limit being reached, that fact will show up in the diagnostics field.
O	Connection opened.
T	PORT_ACCESS log entry. Further details available in the "PORT_ACCESS Mapping Table."
U	Logs SMTP authentication successes and failures. Format is the same as other O and C entries. In particular, the same application and transport information fields appear in same order. The username will be logged in the username field if it is known. Bit 7 (value 128) of the LOG_CONNECTION MTA option controls this.
X	Connection rejected.
Y	Connection attempt failed before being established.
I	ETRN command received.

With LOG_CONNECTION, LOG_FILENAME, LOG_MESSAGE_ID, LOG_NOTARY, LOG_PROCESS, and LOG_USERNAME MTA options all enabled, the format becomes as shown in the example below. (The sample log entry line has been wrapped for typographic reasons; the actual log entry would appear on one physical line.)

16-Feb-2007 15:04:01.14 2bbe.5.3 tcp_local ims-ms
EE 1 [e-mail] rfc822;[e-mail]
adam@ims-ms-daemon 20 /opt/SUNWmsgsr/data/queue/ims-ms/000/ZZf0r2i0HIaY1.01
<[e-mail]> mailsrv
example.org (example.org [192.160.253.66])

Where the additional fields, beyond those already discussed above, are:

1. The process ID (expressed in hexadecimal), followed by a period (dot) character and a count. If this had been a multithreaded channel entry (that is, a tcp_* channel entry), there would also be a thread ID present between the process ID and the count. In the example, the process ID is 2bbe.5.3.

2. The NOTARY (delivery receipt request) flags for the message, expressed as an integer (in the example, 20).

3. The file name in the MTA queue area (in the example, /opt/SUNWmsgsr/data/queue/ims-ms/000/ZZf0r2i0HIaY1.01).

4. The message ID (in the example, [e-mail]).

5. The name of the executing process (in the example, mailsrv). On UNIX, for dispatcher processes such as the SMTP server, this will usually be mailsrv (unless SASL was used, in which case it will be the authenticated user name, for example, *[e-mail]).

6. The connection information (in the example, example.org (example.org [192.160.253.66]). The connection information consists of the sending system or channel name, such as the name presented by the sending system on the HELO/EHLO line (for incoming SMTP messages), or the enqueuing channel's official host name (for other sorts of channels). In the case of TCP/IP channels, the sending system's real name, that is, the symbolic name as reported by a DNS reverse lookup and/or the IP address, can also be reported within parentheses as controlled by the ident* channel options. See the discussion on the IDENT Lookups in the Messaging Server Reference for an instance of the default identnone option, that selects display of both the name found from the DNS and IP address.

Enabling MTA Logging

To gather statistics for just a few particular MTA channels, enable the logging channel option on just those MTA channels of interest. Many sites prefer to enable logging on all MTA channels. In particular, if you are trying to track down problems, the first step in diagnosing some problems is to notice that messages are not going to the channel you expected or intended, and having logging enabled for all channels can help you investigate such problems.

To Enable MTA Logging on a Specific Channel

1. Run the msconfig edit channels command.

2. To enable logging for a particular channel, add the logging option to the channel definition. For example:

   channel-name option1 option2 logging

   In addition, you can also set a number of configuration options such as directory path for log files, log levels, and so on. See "Managing Message Store, Admin, and Default Service Logs."

   Note:

   The message return job, which runs every night around midnight, appends any existing mail.log_yesterday to the cumulative log file, mail.log, renames the current mail.log_current file to mail.log_yesterday, and then begins a new mail.log_currentfile. It also performs the analogous operations for any connection.log* files. It is possible that mail.log_yesterday contains time stamps which have already passed over rotation time.

To Enable MTA Logging on All Channels

1. Run the msconfig edit channels command.

2. Add the logging option to your defaults channel configuration file. For example:

   defaults notices 1 2 4 7 copywarnpost copysendpost postheadonly noswitchchannel \
   immnonurgent maxjobs 7 defaulthost example.org example.org logging
   
   !
   ! delivery channel to local /var/mail store
   l subdirs 20 viaaliasrequired maxjobs 7
   mailhost.example.org
   

Specifying Additional MTA Logging Options

In addition to the basic information always provided when logging is enabled, you can specify that additional, optional information fields be included by setting various LOG_* MTA options.

To Send MTA Logs to syslog

1. Enter the following command to set log_messages_syslog to 1:

   msconfig set log_messages_syslog 1 
   

To write MTA message log file entries to syslog, you need to set the log_messages_syslog option to a non-zero value. The absolute value of the non-zero value sets the syslog priority and facility mask. Negative values disable the generation of the regular mail.log* entries. Positive values mean that the syslog entries are generated in addition to the regular mail.log* entries. 0 is the default and means no syslog or event logging is performed.

Facility and priority numbers are located in the /usr/include/sys/syslog.h file.

To Control Formatting of Log Entries

1. Set the LOG_FORMAT option by running msconfig set log_format n where n corresponds to one of the settings below

   • 1 (default) the standard format.

   • 2 requests non-null formatting: empty address fields are converted to the string "<>"

   • 3 requests counted formatting: all variable length fields are preceded by N, where N is a count of the number of characters in the field.

   • 4 causes log entries to be written in an XML-compatible format. Entry log entry appears as a single XML element containing multiple attributes and no sub-elements. Three elements are currently defined, en for enqueue/dequeue entries, co for connection entries, and he for header entries.

     Enqueue/dequeue (en) elements can have the following attributes:

     ts - time stamp (always present)
     no - node name (present if LOG_NODE=1)
     pi - process id (present if LOG_PROCESS=1)
     sc - source channel (always present)
     dc - destination channel (always present)
     ac - action (always present)
     sz - size (always present)
     so - source address (always present)
     od - original destination address (always present)
     de - destination address (always present)
     rf - recipient flags (present if LOG_NOTARY=1)
     fi - filename (present if LOG_FILENAME=1)
     ei - envelope id (present if LOG_ENVELOPE_ID=1)
     mi - message id (present if LOG_MESSAGE_ID=1)
     us - username (present if LOG_USERNAME=1)
     ss - source system (present if bit 0 of LOG_CONNECTION
     is set and source system information is available)
     se - sensitivity (present if LOG_SENSITIVITY=1)
     pr - priority (present if LOG_PRIORITY=1)
     in - intermediate address (present if LOG_INTERMEDIATE=1)
     ia - initial address (present if bit 0 of LOG_INTERMEDIATE
     is set and intermediate address information is available)
     fl - filter (present if LOG_FILTER=1 and filter information
     is available)
     re - reason (present if LOG_REASON=1 and reason string is set)
     di - diagnostic (present if diagnostic info available)
     tr - transport information (present if bit 5 of LOG_CONNECTION
     is set and transport information is available)
     ap - application information (present if bit 6 of LOG_CONNECTION
     is set and application information is available)
     qt - the number of seconds the message has spent in the queue (LOG_QUEUE_TIME=1)
     

     Here is a sample en entry:

     <en ts="2004-12-08T00:40:26.70" pi="0d3730.10.43" sc="tcp_local"
     dc="l" ac="E" sz="12" so="[e-mail]"
     od="rfc822;[e-mail]"
     de="[e-mail]" rf="22"
     fi="/path/ZZ01LI4XPX0DTM00IKA8.00" ei="[e-mail]"
     mi="&lt;11a3b401c4dd01$7c1c1ee0$1906fad0@elara>" us=""
     ss="elara.whittlesong.com ([208.250.6.25])"
     in="[e-mail]" ia="[e-mail]"
     fl="spamfilter1:rvLiXh158xWdQKa9iJ0d7Q==, addheader, keep"/>
     

     Note that this entry has been wrapped for clarity; actual log file entries always appear on a single line. Connection (co) entries can have the following attributes:

     ts - time stamp (always present, also used in en entries)
     no - node name (present if LOG_NODE=1, also used in en entries)
     pi - process id (present if LOG_PROCESS=1, also used in en entries)
     sc - source channel (always present, also used in en entries)
     dr - direction (always present)
     ac - action (always present, also used in en entries)
     tr - transport information (always present, also used in en entries)
     ap - application information (always present, also used in en entries)
     mi - message id (present only if message id info available,
     also used in en entries)
     us - username (present only if username information available, also
     used in en entries)
     di - diagnostic (present only if diagnostic information available,
     also used in en entries)
     ct - the length of the connection, in seconds. (LOG_QUEUE_TIME=1,
     also used in en entries)
     

     Here is a sample co entry:

     <co ts="2004-12-08T00:38:28.41" pi="1074b3.61.281" sc="tcp_local" dr="+"
     ac="O" tr="TCP|209.55.107.55|25|209.55.107.104|33469" ap="SMTP"/>
     

     Header (he) entries have the following attributes:

     ts - time stamp (always present, also used in en entries)
     no - node name (present if LOG_NODE=1, also used in en entries)
     pi - process id (present if LOG_PROCESS=1, also used in en entries)
     va - header line value (always present)
     

     Here is a sample he entry:

     <he ts="2004-12-08T00:38:31.41" pi="1074b3.61.281" va="Subject: foo"/>
     

To Correlate Log Message Entries

• Set the LOG_MESSAGE_ID option to 1 by running msconfig set log_message_id 1.

  A value of 0 is the default and indicates that message IDs are not saved in the mail.log* files.

To Log Amount of Time Messages Have Spent in the Queue

• Set the LOG_QUEUE_TIME option to 1 by running msconfig set log_queue_time 1. This option logs the amount of time messages spent in the queue. The queue time is logged as an integer value in seconds. It appears immediately after the application information string in non-XML format logs. The attribute name in XML formatted logs for this value is qt.

To Identify Message Delivery Retries

• Set the LOG_FILENAME option to 1 by running msconfig set log_filename 1 This option makes it easier to immediately spot how many times the delivery of a particular message file has been retried. This option can also be useful in understanding when the MTA does or does not split a message to multiple recipients into separate message file copies on disk.

To Log TCP/IP Connections

• Set the LOG_CONNECTION option by running msconfig set log_connection 1 This option causes the MTA to log TCP/IP connections, as well as message traffic. The connection log entries are written to the mail.log* files by default. Optionally, the connection log entries can be written to connection.log* files. See the SEPARATE_CONNECTION_LOG option for more information.

To Write Entries to the connection.log File

• Set the SEPARATE_CONNECTION_LOG option to 1 by running msconfig set separate_connection_log 1. Use this option to specify that connection log entries instead be written to connection.log files. The default value of 0 causes the connection logging to be stored in the MTA log files.

To Correlate Log Messages by Process ID

• Set the LOG_PROCESS option by running msconfig set log_process 1. When used in conjunction with LOG_CONNECTION, this option enables correlation by process ID of which connection entries correspond to which message entries.

To Save User Names Associated with a Process That Enqueues Mail to the mail.log File

• Set the LOG_USERNAME option by running msconfig set log_username 1. This option controls whether or not the user name associated with a process that enqueues mail is saved in the mail.log file. For SMTP submissions where SASL (SMTP AUTH) is used, the user name field will be the authenticated user name (prefixed with an asterisk character).

MTA Message Logging Examples

The exact field format and list of fields logged in the MTA message files vary according to the logging options set. This section shows a few examples of interpreting typical sorts of log entries.

For a description of additional, optional fields, see "Specifying Additional MTA Logging Options."

Note:

For typographic reasons, log file entries will be shown folded onto multiple lines. Actual log file entries are one line per entry.

When reviewing a log file, keep in mind that on a typical system many messages are being handled at once. Typically, the entries relating to a particular message will be interspersed among entries relating to other messages being processed during that same time. The basic logging information is suitable for gathering a sense of the overall numbers of messages moving through the MTA.

If you wish to correlate particular entries relating to the same message to the same recipient(s), enable LOG_MESSAGE_ID. To correlate particular messages with particular files in the MTA queue area, or to see from the entries how many times a particular not-yet-successfully-dequeued message has had delivery attempted, enable LOG_FILENAME. For SMTP messages (handled via a TCP/IP channel), if you want to correlate TCP connections to and from remote systems with the messages sent, enable LOG_PROCESS and some level of LOG_CONNECTION.

MTA Logging Example: User Sends an Outgoing Message

The following example shows a basic example of the sort of log entries one might see if a local user sends a message out an outgoing TCP/IP channel, for example, to the Internet. In this example, LOG_CONNECTION is enabled. The lines marked with (1) and (2) are one entry---they would appear on one physical line in an actual log file. Similarly, the lines marked with (3) - (7) are one entry and would appear on one physical line.

Example MTA Logging: A Local User Sends An Outgoing Message

16-Feb-2007 15:41:32.36 tcp_intranet tcp_local EE 1 (1)
[e-mail] rfc822;[e-mail] [e-mail] (2)
example.org (example.org [192.160.253.66])

16-Feb-2007 15:41:34.73 tcp_local DE 1 (3)
[e-mail] rfc822;[e-mail] [e-mail] (4)
thor.example.org dns;thor.example.org

(TCP|206.184.139.12|2788|192.160.253.66|25) (5)

(thor.example.org ESMTP Sendmail ready Thu 15 Feb 2007 21:37:29 -0700 [MST]) (6)

smtp;250 2.1.5 <[e-mail]>... Receipt ok (7)

1. This line shows the date and time of an enqueue with ESMTP (EE) from the tcp_intranet channel to the tcp_local channel of a one (1) block message.

2. This is part of the same physical line of the log file as (1), presented here as a separate line for typographical convenience. It shows the envelope From: address, in this case [e-mail], and the original version and current version of the envelope To: address, in this case [e-mail].

3. This shows the date and time of a dequeue with ESMTP (DE) from the tcp_local channel of a one (1) block message that is, a successful send by the tcp_local channel to some remote SMTP server.

4. This shows the envelope From: address, the original envelope To: address, and the current form of the envelope To: address.

5. This shows that the actual system to which the connection was made is named thor.example.org in the DNS, that the local sending system has IP address 206.184.139.12 and is sending from port 2788, that the remote destination system has IP address 192.160.253.66 and the connection port on the remote destination system is port 25.

6. This shows the SMTP banner line of the remote SMTP server.

7. This shows the SMTP status code returned for this address; 250 is the basic SMTP success code and in addition, this remote SMTP server responds with extended SMTP status codes and some additional text.

MTA Logging Example: Including Optional Logging Fields

This example shows a logging entry similar to that shown in "Example MTA Logging: Sending to a List" with LOG_FILENAME=1 and LOG_MESSAGE_ID=1 showing the file name (1 and 3 below) and message ID (2 and 4 below). The message ID in particular can be used to correlate which entries relate to which message.

Example MTA Logging: Including Optional Logging Fields

16-Feb-2007 15:41:32.36 tcp_intranet tcp_local EE 1
[e-mail] rfc822;[e-mail] [e-mail]
/opt/SUNWmsgsr/data/queue/tcp_local/002/ZZf0r4i0Wdy51.01 (1)
<[e-mail]> (2)
example.org (example.org [192.160.253.66])

16-Feb-2007 15:41:34.73 tcp_local DE 1
[e-mail] rfc822;[e-mail] [e-mail]
/opt/SUNWmsgsr/data/queue/tcp_local/002/ZZf0r4i0Wdy51.01 (3)
<[e-mail]> (4)
thor.example.org dns;thor.example.org
(TCP|206.184.139.12|2788|192.160.253.66|25)
(thor.example.org ESMTP Sendmail ready at Thu, 15 Feb 2007 21:37:29 -0700 [MST])
smtp;250 2.1.5 <[e-mail]>... Recipient ok

MTA Logging Example: Sending to a List

This example illustrates sending to multiple recipients with LOG_FILENAME=1, LOG_MESSAGE_ID=1, and LOG_CONNECTION=1 enabled. Here user [e-mail] has sent to the MTA mailing list [e-mail], which expanded to [e-mail], [e-mail], and [e-mail]. Note that the original envelope To: address is [e-mail] for each recipient, though the current envelope To: address is each respective address. Note how the message ID is the same throughout, though two separate files (one for the l channel and one going out the tcp_local channel) are involved.

Example MTA Logging: Sending to a List

20-Feb-2007 14:00:16.46 tcp_local tcp_local EE 1
[e-mail] rfc822;[e-mail] [e-mail]
/opt/SUNWmsgsr/data/queue/tcp_local/004/ZZf0r2D0yuej4.01
<[e-mail]>
example.org (example.org [192.160.253.66])

20-Feb-2007 14:00:16.47 tcp_local tcp_local EE 1
[e-mail] rfc822;[e-mail] [e-mail]
/opt/SUNWmsgsr/data/queue/tcp_local/004/ZZf0r2D0yuej4.01
<[e-mail]>
example.org (example.org [192.160.253.66])

20-Feb-2007 14:00:16.48 tcp_local ims-ms EE 1
[e-mail] rfc822;[e-mail] bob@ims-ms-daemon
/opt/SUNWmsgsr/data/queue/ims-ms/008/ZZf0r2D0yuej6.01
<[e-mail]>
example.org (example.org [192.160.253.66])

20-Feb-2007 14:00:16.68 ims-ms D 1
[e-mail] rfc822;[e-mail] bob@ims-ms-daemon
/opt/SUNWmsgsr/data/queue/ims-ms/008/ZZf0r2D0yuej6.01
<[e-mail]>

20-Feb-2007 14:00:17.73 tcp_local DE 1
[e-mail] rfc822;[e-mail] [e-mail]
/opt/SUNWmsgsr/data/queue/tcp_local/004/ZZf0r2D0yuej4.01
<[e-mail]>
gw.example.org dns;gw.example.org (TCP|206.184.139.12|2788|192.160.253.66|25)
(gw.example.org -- SMTP Sendmail)
smtp;250 2.1.5 <[e-mail] >... Recipient ok

20-Feb-2007 14:00:17.75 tcp_local DE 1
[e-mail] rfc822;[e-mail] [e-mail]
/opt/SUNWmsgsr/data/queue/tcp_local/004/ZZf0r2D0yuej4.01
<[e-mail]>
gw.example.org dns;gw.example.org (TCP|206.184.139.12|2788|192.160.253.66|25)
(gw.example.org -- SMTP Sendmail)
smtp;250 2.1.5 <[e-mail]>... Recipient ok

MTA Logging Example: Sending to a Nonexistent Domain

This example illustrates an attempt to send to a nonexistent domain (here very.bogus.com); that is, sending to a domain name that is not noticed as nonexistent by the MTA's rewrite rules and that the MTA matches to an outgoing TCP/IP channel. This example assumes the MTA option settings of LOG_FILENAME=1 and LOG_MESSAGE_ID=1.

When the TCP/IP channel runs and checks for the domain name in the DNS, the DNS returns an error that no such name exists. Note the "rejection" entry (R), as seen in (5), with the DNS returning an error that this is not a legal domain name, as seen in (6).

Because the address is rejected after the message has been submitted, the MTA generates a bounce message to the original sender. The MTA enqueues the new rejection message to the original sender (1), and sends a copy to the postmaster (4) before deleting the original outbound message (the R entry shown in (5)).

Notification messages, such as bounce messages, have an empty envelope From: address--as seen, for instance, in (2) and (8)--in which the envelope From: field is shown as an empty space. The initial enqueue of a bounce message generated by the MTA shows the message ID for the new notification message followed by the message ID for the original message (3). (Such information is not always available to the MTA, but when it is available to be logged, it allows correlation of the log entries corresponding to the outbound failed message with the log entries corresponding to the resulting notification message.) Such notification messages are enqueued to the process channel, which in turn enqueues them to an appropriate destination channel (7).

Example MTA Logging: Sending to a Nonexistent Domain

20-Feb-2007 14:17:07.77 tcp_intranet tcp_local E 1
[e-mail] rfc822;[e-mail] [e-mail]
/opt/SUNWmsgsr/data/queue/tcp_local/008/ZZf0r2D0CVaL0.00
<[e-mail]>
example.org (example.org [192.160.253.66])

20-Feb-2007 14:17:08.24 tcp_local process E 1 (1)
rfc822;[e-mail] [e-mail] (2)
/opt/SUNWmsgsr/data/queue/process/ZZf0r2D0CVbR0.00
<[e-mail]>,<[e-mail]> (3)
tcp-daemon.mailhost.example.com

20-Feb-2007 14:17:08.46 tcp_local process E 1 (4)
rfc822;[e-mail] [e-mail]
/opt/SUNWmsgsr/data/queue/process/ZZf0r2D0CVbR1.00
<[e-mail]>,<[e-mail]>
tcp-daemon.mailhost.example.com

20-Feb-2007 14:17:08.46 tcp_local R 1 (5)
[e-mail] rfc822;[e-mail] [e-mail]
/opt/SUNWmsgsr/data/queue/tcp_local/008/ZZf0r2D0CVaL0.00
<[e-mail]>
Illegal host/domain name found (6)
(TCP active open: Failed gethostbyname() on very.bogus.com, resolver errno = 1)

20-Feb-2007 14:17:09.21 process ims-ms E 3 (7)
rfc822;[e-mail] adam@ims-ms-daemon (8)
/opt/SUNWmsgsr/data/queue/ims-ms/018/ZZf0r2D0CVbS1.00
<[e-mail]>
process-daemon.mailhost.example.com

20-Feb-2007 14:17:09.72 process ims-ms E 3
rfc822;[e-mail] postmaster@ims-ms-daemon
/opt/SUNWmsgsr/data/queue/ims-ms/014/ZZf0r2D0CVbS2.00
<[e-mail]>
process-daemon.mailhost.example.com

20-Feb-2007 14:17:09.73 ims-ms D 3
rfc822;[e-mail] adam@ims-ms-daemon
/opt/SUNWmsgsr/data/queue/ims-ms/018/ZZf0r2D0CVbS1.00
<[e-mail]>

20-Feb-2007 14:17:09.84 ims-ms D 3
rfc822;[e-mail] postmaster@ims-ms-daemon
/opt/SUNWmsgsr/data/queue/ims-ms/014/ZZf0r2D0CVbS2.00
<[e-mail]>

MTA Logging Example: Sending to a Nonexistent Remote User

This example illustrates an attempt to send to a bad address on a remote system. This example assumes MTA option settings of LOG_FILENAME=1 and LOG_MESSAGE_ID=1, and channel option settings of LOG_BANNER=1 and LOG_TRANSPORTINFO=1. Note the rejection entry (R), seen in (1). But in contrast to the rejection entry in "Example MTA Logging: Sending to a Nonexistent Domain," note that the rejection entry here shows that a connection to a remote system was made, and shows the SMTP error code issued by the remote SMTP server, (2) and (3). The inclusion of the information shown in (2) is due to setting the channel options LOG_BANNER=1 and LOG_TRANSPORTINFO=1.

Example MTA Logging: Sending to a Nonexistent Remote User

26-Feb-2007 13:56:35.16 tcp_intranet tcp_local EE 1
[e-mail] rfc822;[e-mail] [e-mail]
/opt/SUNWmsgsr/data/queue/tcp_local/000/ZZf0s690a3mf2.01
<[e-mail]>
example.org (example.org [192.160.253.66])

26-Feb-2007 13:56:35.19 tcp_local process E 1
rfc822;[e-mail] [e-mail]
/opt/SUNWmsgsr/data/queue/process/ZZf0s690a3ml2.00
<[e-mail]>,<[e-mail]>
tcp-daemon.mailhost.example.com

26-Feb-2007 13:56:35.20 tcp_local process E 1
rfc822;[e-mail] [e-mail]
/opt/SUNWmsgsr/data/queue/process/ZZf0s690a3ml3.00
<[e-mail]>,<[e-mail]>
tcp-daemon.mailhost.example.com

26-Feb-2007 13:56:35.20 tcp_local RE 1 (1)
[e-mail] rfc822;[e-mail] [e-mail]

/opt/SUNWmsgsr/data/queue/tcp_local/000/ZZf0s690a3mf2.01
<[e-mail]>
thor.example.org dns;thor.example.org
(TCP|206.184.139.12|2788|192.160.253.66|25) (2)
(thor.example.org -- Server ESMTP [Sun Java System Messaging
Server 6.2-8.01 [built Feb 16 2007]])
smtp;550 5.1.1 unknown or illegal alias: [e-mail] (3)

26-Feb-2007 13:56:35.62 process ims-ms E 4
rfc822;[e-mail] adam@ims-ms-daemon
/opt/SUNWmsgsr/data/queue/ims-ms/003/ZZf0s690a3mm5.00
<[e-mail]>
process-daemon.mailhost.example.com

26-Feb-2007 13:56:36.07 process ims-ms E 4
rfc822;[e-mail] postmaster@ims-ms-daemon
/opt/SUNWmsgsr/data/queue/ims-ms/016/ZZf0s690a3nm7.01
<[e-mail]>
process-daemon.mailhost.example.com

26-Feb-2007 13:56:35.83 ims-ms D 4
rfc822;[e-mail] adam@ims-ms-daemon
/opt/SUNWmsgsr/data/queue/ims-ms/003/ZZf0s690a3mm5.00
<[e-mail]>

26-Feb-2007 13:56:36.08 ims-ms D 4
rfc822;[e-mail] postmaster@ims-ms-daemon
/opt/SUNWmsgsr/data/queue/ims-ms/016/ZZf0s690a3nm7.01
<[e-mail]>

MTA Logging Example: Rejecting a Remote Side's Attempt to Submit a Message

This example illustrates the sort of log file entry resulting when the MTA rejects a remote side's attempt to submit a message. (This example assumes that no optional LOG_* options are enabled, so only the basic fields are logged in the entry. Note that enabling the LOG_CONNECTION option, in particular, would result in additional informative fields in such J entries.) In this case, the example is for an MTA that has set up SMTP relay blocking (see "Configuring SMTP Relay Blocking") with an ORIG_SEND_ACCESS mapping, including:

ORIG_SEND_ACCESS

! ...numerous entries omitted...
!
tcp_local|*|tcp_local|* $NRelaying$ not$ permitted

and where [e-mail] is not an internal address. Hence the attempt of the remote user [e-mail] to relay through the MTA system to the remote user [e-mail] is rejected.

Example MTA Logging: Rejecting a Remote Side's Attempt to Submit a Message

26-Feb-2007 14:10:06.89 tcp_local JE 0 (1)
[e-mail] rfc822; [e-mail] (2)
530 5.7.1 Relaying not allowed: [e-mail] (3)

1. This log shows the date and time the MTA rejects a remote side's attempt to submit a message. The rejection is indicated by a J record. (Cases where an MTA channel is attempting to send a message which is rejected is indicated by R records, as shown in "Example MTA Logging: Sending to a Nonexistent Domain" and "MTA Logging Example: Sending to a Nonexistent Remote User").

   Note:

   The last J record written to the log will have an indication stating that it is the last for a given session. Also, the current version of Messaging Server does not place a limit on the number of J records.

2. The attempted envelope From: and To: addresses are shown. In this case, no original envelope To: information was available so that field is empty.

3. The entry includes the SMTP error message the MTA issued to the remote (attempted sender) side.

MTA Logging Example: Multiple Delivery Attempts

This example illustrates the sort of log file entries resulting when a message cannot be delivered upon the first attempt, so the MTA attempts to send the message several times. This example assumes option settings of LOG_FILENAME=1 and LOG_MESSAGE_ID=1.

Example MTA Logging: Multiple Delivery Attempts

26-Feb-2007 14:38:16.27 tcp_intranet tcp_local EE 1 (1)
[e-mail] rfc822;[e-mail] [e-mail]
/opt/SUNWmsgsr/data/queue/tcp_local/001/ZZf0s690kN_y0.00
<[e-mail]>

26-Feb-2007 14:38:16.70 tcp_local Q 1 (2)
[e-mail] rfc822;[e-mail] [e-mail]
/opt/SUNWmsgsr/data/queue/tcp_local/001/ZZf0s690kN_y0.00 (3)
<[e-mail]>
TCP active open: Failed connect() 192.1.1.1:25 Error: no route to host (4)

...several hours worth of entries...

26-Feb-2007 16:58:11.20 tcp_local Q 1 (5)
[e-mail] rfc822;[e-mail] [e-mail]
/opt/SUNWmsgsr/data/queue/tcp_local/001/ZYf0s690kN_y0.01 (6)
<[e-mail]>
TCP active open: Failed connect() 192.1.1.1:25 Error: no route to host

...several hours worth of entries...

26-Feb-2007 19:15:12.11 tcp_local Q 1
[e-mail] rfc822;[e-mail] [e-mail]
/opt/SUNWmsgsr/data/queue/tcp_local/001/ZXf0s690kN_y0.00 (7)
<[e-mail]>
TCP active open: Failed connect() 192.1.1.1:25 Error: Connection refused (8)

...several hours worth of entries...

26-Feb-2007 22:41:12.63 tcp_local DE 1 (9)
[e-mail] rfc822;[e-mail] [e-mail]
/opt/SUNWmsgsr/data/queue/tcp_local/001/ZXf0s690kN_y0.00
<[e-mail]>
host.some.org dns;host.some.org (TCP|206.184.139.12|2788|192.1.1.1|25)
(All set, fire away)
smtp;250 2.1.5 <[e-mail] >... Recipient ok

1. The message comes in the tcp_internal channel---perhaps from a POP or IMAP client, or perhaps from another host within the organization using the MTA as an SMTP relay; the MTA enqueues it to the outgoing tcp_local channel.

2. The first delivery attempt fails, as indicated by the Q entry.

3. That this is a first delivery attempt can be seen from the ZZ* filename.

4. This delivery attempt failed when the TCP/IP package could not find a route to the remote side. As opposed to "MTA Logging Example: Sending to a Nonexistent Domain," the DNS did not object to the destination domain name, some.org; rather, the "no route to host" error indicates that there is some network problem between the sending and receiving side.

5. The next time the MTA periodic job runs it reattempts delivery, again unsuccessfully.

6. The file name is now ZY*, indicating that this is a second attempt.

7. The file name is ZX* for this third unsuccessful attempt.

8. The next time the periodic job reattempts delivery the delivery fails, though this time the TCP/IP package is not complaining that it cannot get through to the remote SMTP server, but rather the remote SMTP server is not accepting connections. (Perhaps the remote side fixed their network problem, but has not yet brought their SMTP server back up---or their SMTP server is swamped handling other messages and hence was not accepting connections at the moment the MTA tried to connect.)

9. Finally the message is dequeued.

MTA Logging Example: Incoming SMTP Message Routed Through the Conversion Channel

This example illustrates the case of a message routed through the conversion channel. The site is assumed to have a CONVERSIONS mapping table such as:

CONVERSIONS

IN-CHAN=tcp_local;OUT-CHAN=ims-ms;CONVERT Yes

This example assumes option settings of LOG_FILENAME=1 and LOG_MESSAGE_ID=1.

Example MTA Logging: Incoming SMTP Message Routed Through the Conversion Channel

26-Feb-2007 15:31:04.17 tcp_local conversion EE 1 (1)
[e-mail] rfc822;[e-mail] bert@ims-ms-daemon
/opt/SUNWmsgsr/data/queue/conversion/ZZf0s090wFwx2.01
<[e-mail]>

26-Feb-2007 15:31:04.73 conversion ims-ms E 1 (2)
[e-mail] rfc822;[e-mail] bert@ims-ms-daemon
/opt/SUNWmsgsr/data/queue/ims-ms/007/ZZf0s090wMwq1.00
<[e-mail]>

26-Feb-2007 15:31:04.73 conversion D 1 (3)
[e-mail] rfc822;[e-mail] bert@ims-ms-daemon
/opt/SUNWmsgsr/data/queue/conversion/ZZf0s090wFwx2.01
<[e-mail]>

26-Feb-2007 15:31:04.73 ims-ms D 1 (4)
[e-mail] rfc822;[e-mail] bert@ims-ms-daemon
/opt/SUNWmsgsr/data/queue/ims-ms/007/ZZf0s090wMwq1.00
<[e-mail]>

1. The message from external user [e-mail] comes in addressed to the ims-ms channel recipient [e-mail]. The CONVERSIONS mapping entry, however, causes the message to be initially enqueued to the conversion channel (rather than directly to the ims-ms channel).

2. The conversion channel runs and enqueues the message to the ims-ms channel.

3. Then the conversion channel can dequeue the message (delete the old message file).

4. And finally the ims-ms channel dequeues (delivers) the message.

MTA Logging Example: Outbound Connection Logging

This example illustrates log output for an outgoing message when connection logging is enabled, via LOG_CONNECTION=3. LOG_PROCESS=1, LOG_MESSAGE_ID=1 and LOG_FILENAME=1 are also assumed in this example. The example shows the case of user [e-mail] sending the same message (note that the message ID is the same for each message copy) to three recipients, [e-mail], [e-mail], and [e-mail]. This example assumes that the message is going out a tcp_local channel marked (as such channels usually are) with the single_sys channel option. Therefore, a separate message file on disk will be created for each set of recipients to a separate host name, as seen in (1), (2), and (3), where the [e-mail] and [e-mail] recipients are stored in the same message file, but the [e-mail] recipient is stored in a different message file.

Example MTA Logging: Outbound Connection Logging

28-Feb-2007 09:13:19.18 409f.3.1 tcp_intranet tcp_local EE 1
[e-mail] rfc822;[e-mail] [e-mail]
/opt/SUNWmsgsr/data/queue/tcp_local/000/ZZf0s4g0G2Zt0.00 (1)
<[e-mail]>
example.org (example.org [192.160.253.66])

28-Feb-2007 09:13:19.18 409f.3.1 tcp_intranet tcp_local EE 1
[e-mail] rfc822;[e-mail] [e-mail]
/opt/SUNWmsgsr/data/queue/tcp_local/000/ZZf0s4g0G2Zt0.00 (2)
<[e-mail]>
example.org (example.org [192.160.253.66])

28-Feb-2007 09:13:19.19 409f.3.2 tcp_intranet tcp_local EE 1
[e-mail] rfc822;[e-mail] [e-mail]
/opt/SUNWmsgsr/data/queue/tcp_local/004/ZZf0s4g0G2Zt1.00 (3)
<[e-mail]>
example.org (example.org [192.160.253.66])

28-Feb-2007 09:13:19.87 40a5.2.0 tcp_local - O (4)
TCP|206.184.139.12|5900|206.184.139.66|25
SMTP/hostb.example.com/mailhub.example.com (5)

28-Feb-2007 09:13:20.23 40a5.3.4 tcp_local - O (6)
TCP|206.184.139.12|5901|206.184.139.70|25
SMTP/hosta.example.com/hosta.example.com (7)

28-Feb-2007 09:13:20.50 40a5.2.5 tcp_local DE 1
[e-mail] rfc822;[e-mail] [e-mail]
/opt/SUNWmsgsr/data/queue/tcp_local/000/ZZf0s4g0G2Zt0.00
<[e-mail]>
hosta.example.com dns;hosta.example.com (8)
(TCP|206.184.139.12|5901|206.184.139.70|25)
(hosta.example.com -- Server ESMTP [Sun Java System Messaging Server
6.2-8.01 [built Feb 16 2007]])
smtp;250 2.1.5 [e-mail] and options OK.

28-Feb-2007 09:13:20.50 40a5.2.5 tcp_local DE 1
[e-mail] rfc822;[e-mail] [e-mail]
/opt/SUNWmsgsr/data/queue/tcp_local/000/ZZf0s4g0G2Zt0.00
<[e-mail]>
hosta.example.com dns;hosta.example.com
(TCP|206.184.139.12|5901|206.184.139.70|25)
(hosta.example.com -- Server ESMTP [Sun Java System Messaging Server
6.2-8.01 [built Feb 16 2007]])
smtp;250 2.1.5 [e-mail] and options OK.

28-Feb-2007 09:13:20.50 40a5.2.6 tcp_local - C (9)
TCP|206.184.139.12|5901|206.184.139.70|25
SMTP/hosta.example.com/hosta.example.com

28-Feb-2007 09:13:21.13 40a5.3.7 tcp_local DE 1
[e-mail] rfc822;[e-mail] [e-mail]
/opt/SUNWmsgsr/data/queue/tcp_local/004/ZZf0s4g0G2Zt1.00
<[e-mail]>
mailhub.example.com dns;mailhub.example.com
(TCP|206.184.139.12|5900|206.184.139.66|25)
(mailhub.example.com ESMTP Sendmail ready at Tue, 27 Feb 2007 22:19:40 GMT)
smtp;250 2.1.5 <[e-mail]>... Recipient ok

28-Feb-2007 09:13:21.33 40a5.3.8 tcp_local - C (10)
TCP|206.184.139.12|5900|206.184.139.66|25
SMTP/hostb.example.com/mailhub.example.com

1. The message is enqueued to the first recipient...

2. ....and to the second recipient...

3. ....and to the third recipient.

4. Having LOG_CONNECTION=3 set causes the MTA to write this entry. The minus, -, indicates that this entry refers to an outgoing connection. The O means that this entry corresponds to the opening of the connection. Also note that the process ID here is the same, 40a5, since the same process is used for the multithreaded TCP/IP channel for these separate connection opens, though this open is being performed by thread 2 vs. thread 3.

5. As there are two separate remote systems to which to connect, the multithreaded SMTP client in separate threads opens up a connection to each---the first in this entry, and the second shown in 7. This part of the entry shows the sending and destination IP numbers and port numbers, and shows both the initial host name, and the host name found by doing a DNS lookup. In the SMTP/initial-host/dns-host clauses, note the display of both the initial host name, and that used after performing a DNS MX record lookup on the initial host name: mailhub.example.com is apparently an MX server for hostb.example.com.

6. The multithreaded SMTP client opens up a connection to the second system in a separate thread (though the same process).

7. As there are two separate remote systems to which to connect, the multithreaded SMTP client in separate threads opens up a connection to each---the second in this entry, and the first shown above in 5. This part of the entry shows the sending and destination IP numbers and port numbers, and shows both the initial host name, and the host name found by doing a DNS lookup. In this example, the system hosta.example.com apparently receives mail directly itself.

8. Besides resulting in specific connection entries, LOG_CONNECTION=3 also causes inclusion of connection related information in the regular message entries, as seen here for instance.

9. Having LOG_CONNECTION=3 causes the MTA to write this entry. After any messages are dequeued, (the bobby and carl messages in this example), the connection is closed, as indicated by the C in this entry.

10. The connection mailhub.example.com is closed now that the delivery of the message (dave in this example) is complete.

MTA Logging Example: Inbound Connection Logging

This example illustrates log output for an incoming SMTP message when connection logging is enabled, via LOG_CONNECTION=3.

Example MTA Logging: Inbound Connection Logging

28-Feb-2007 11:50:59.10 tcp_local + O (1)
TCP|206.184.139.12|25|192.160.253.66|1244 SMTP (2)

28-Feb-2007 11:51:15.12 tcp_local ims-ms EE 1
[e-mail] rfc822;[e-mail] adam@ims-ms-daemon
THOR.EXAMPLE.ORG (THOR.EXAMPLE.ORG [192.160.253.66]) (3)

28-Feb-2007 11:51:15.32 ims-ms D 1
[e-mail] rfc822;[e-mail] adam@ims-ms-daemon

28-Feb-2007 11:51:15.66 tcp_local + C (4)
TCP|206.184.139.12|25|192.160.253.66|1244 SMTP

1. The remote system opens a connection. The O character indicates that this entry regards the opening of a connection; the + character indicates that this entry regards an incoming connection.

2. The IP numbers and ports for the connection are shown. In this entry, the receiving system (the system making the log file entry) has IP address 206.184.139.12 and the connection is being made to port 25; the sending system has IP address 192.160.253.66 and is sending from port 1244.

3. In the entry for the enqueue of the message from the incoming TCP/IP channel (tcp_local) to the ims-ms channel recipient, note that information beyond the default is included since LOG_CONNECTION=3 is enabled. Specifically, the name that the sending system claimed on its HELO or EHLO line, the sending system's name as found by a DNS reverse lookup on the connection IP number, and the sending system's IP address are all logged.

4. The inbound connection is closed. The C character indicates that this entry regards the closing of a connection; the + character indicates that this entry regards an incoming connection.

Enabling Dispatcher Debugging

Dispatcher error and debugging output (if enabled) are written to the file dispatcher.log in the MTA log directory. A default dispatcher configuration is created at installation time and can be used without any changes made. However, if you want to modify the default configuration for security or performance reasons, you can do so by running the msconfig command.

Table 23-5 Dispatcher Debugging Bits

Bit	Hexadecimal value	Decimal value	Usage
0	x 00001	1	Basic Service Dispatcher main module debugging.
1	x 00002	2	Extra Service Dispatcher main module debugging.
2	x 00004	4	Service Dispatcher configuration file logging.
3	x 00008	8	Basic Service Dispatcher miscellaneous debugging.
4	x 00010	16	Basic service debugging.
5	x 00020	32	Extra service debugging.
6	x 00040	64	Process related service debugging.
7	x 00080	128	Not used.
8	x 00100	256	Basic Service Dispatcher and process communication debugging.
9	x 00200	512	Extra Service Dispatcher and process communication debugging.
10	x 00400	1024	Packet level communication debugging.
11	x 00800	2048	Not used.
12	x 01000	4096	Basic Worker Process debugging.
13	x 02000	8192	Extra Worker Process debugging.
14	x 04000	16384	Additional Worker Process debugging, particularly connection hand-offs.
15	x 08000	32768	Not used.
16	x 10000	65536	Basic Worker Process to Service Dispatcher I/O debugging.
17	x 20000	131072	Extra Worker Process to Service Dispatcher I/O debugging.
20	x 100000	1048576	Basic statistics debugging.
21	x 200000	2097152	Extra statistics debugging.
24	x 1000000	16777216	Log PORT_ACCESS denials to the dispatcher.log file.

To Enable Dispatcher Error Debugging Output

1. Run the msconfig set dispatcher.debug -1. (See "Restricted Options.") You can also set the logical or environmental variable IMTA_DISPATCHER_DEBUG (UNIX), which defines a 32-bit debug mask in hexadecimal, to the value FFFFFFFF. The table above describes the meaning of each bit.

To Set Dispatcher options (Oracle Solaris)

The dispatcher services offered in the dispatcher configuration affect requirements for various system options. The system's heap size (datasize) must be enough to accommodate the dispatcher's thread stack usage.

1. To display the heap size (that is, default datasize), use one of the following: The csh command:

   limit
   

   The ksh command:

   ulimit -a
   

   The Solaris utility:

   sysdef
   

2. For each dispatcher service compute STACKSIZE*MAX_CONNS, and then add up the values computed for each service. The system's heap size needs to be at least twice this number.

Managing Message Store, Admin, and Default Service Logs

This section describes logging for the Message Store (POP, IMAP, and HTTP), Admin, and Default services. (See Table 23-1, "Messaging Server Log Files" for more information.)

For these services, you specify log settings and to view logs. The settings you specify affect which and how many events are logged. You can use those settings and other characteristics to refine searches for logged events when you are analyzing log files.

This section contains the following subsections:

• msconfig Logging Options

• Understanding Service Log Characteristics

  • Logging Levels

  • Categories of Logged Events

  • Service Log File Directories

• Understanding Service Log File Format

  • Store and Administration Log File Components

• Defining and Setting Service Logging Options

  • Flexible Logging Architecture

  • Planning the Options You Want

  • Understanding Logging Options

• Searching and Viewing Service Logs

  • Search Options

• Working With Service Logs

  • To Send Service Logs to syslog

  • To Disable HTTP Logging

  • To Set the Server Log Level

  • To Specify a Directory Path for Server Log Files

  • To Specify a Maximum File Size for Each Service Log

  • To Specify a Service Log Rotation Schedule

  • To Specify a Maximum Number of Service Log Files Per Directory

  • To Specify a Storage Limit

  • To Specify the Minimum Amount of Free Disk Space to Reserve

  • To Specify an Age for Logs at Which They Expire

• Implementing and Configuring Message Store Transaction Logging

  • Overview of Message Store Transaction Logging

  • Message Store Transaction Logging Log Entries

  • Configuring Message Store Transaction Logging

  • Message Store Transaction Log Examples

• Other Message Store Logging Features

• Message Store Logging Examples

  • Message Store Logging Example: Bad Password

  • Message Store Logging Example: Account Disabled

  • Message Store Logging Example: Message Appended

  • Message Store Logging Example: Message Retrieved by a Client

  • Message Store Logging Example: Message Removed from a Folder

  • Message Store Logging Example: Duplicate Login Messages

msconfig Logging Options

To control the location of log files, use the following options for specifying directory paths:

Note:

The location of MTA log files, which are in the msg-install-path/data/log directory, cannot be modified, but you can change the log subdirectory to symbolically link to another location. To separate the MTA logs from the rest of the log files, use msconfig options to specify non-default locations for non-MTA log files.

Table 23-6 msconfig Directory Paths for Log Files

Option

Description

*.logfile.logdir base.logfile.logdir dispatcher.logfile.logdir ens.logfile.logdir http.logfile.logdir imap.logfile.logdir imapproxy.logfile.logdir mta.logfile.logdir job_controller.logfile.logdir metermaid.logfile.logdir mmp.logfile.logdir msadmin.logfile.logdir messagetrace.logfile.logdir pop.logfile.logdir popproxy.logfile.logdir snmp.logfile.logdir submitproxy.logfile.logdir tcp_lmtp_server.logfile.logdir

Directory path for log files. If this is not specified, log files will be placed in the msg-install-path/data/log directory. For the MTA, this option is only used by Message Store insertion tasks Directory path to the imta log file used for Message Store insertion (ims_master, LMTP). It is not used by other parts of the MTA which always log to the default location. The default location is msg-install-path/data/log. Changing that path to a soft-link is supported. (Restart of all services required). Syntax: dirpath

Understanding Service Log Characteristics

This section describes the following log characteristics for the message store and administration services: logging levels, categories of logged events, filename conventions for logs, and log-file directories.

Logging Levels

The level, or priority, of logging defines how detailed, or verbose, the logging activity is to be. A higher priority level means less detail; it means that only events of high priority (high severity) are logged. A lower level means greater detail; it means that more events are recorded in the log file.

You can set the logging level separately for each service---POP, IMAP, HTTP, Admin, and Default by setting the service.logfile.loglevel configuration option (see "Defining and Setting Service Logging Options"). You can also use logging levels to filter searches for log events. Table 23-7 describes the available levels. These logging levels are a subset of those defined by the UNIX syslog facility.

Table 23-7 Logging Levels for Store and Administration Services

Level	Description
Critical	The minimum logging detail. An event is written to the log whenever a severe problem or critical condition occurs---such as when the server cannot access a mailbox or a library needed for it to run.
Error	An event is written to the log whenever an error condition occurs---such as when a connection attempt to a client or another server fails.
Warning	An event is written to the log whenever a warning condition occurs---such as when the server cannot understand a communication sent to it by a client.
Notice	An event is written to the log whenever a notice (a normal but significant condition) occurs---such as when a user login fails or when a session closes. This is the default log level.
Information	An event is written to the log with every significant action that takes place---such as when a user successfully logs on or off or creates or renames a mailbox.
Debug	The most verbose logging. Useful only for debugging purposes. Events are written to the log at individual steps within each process or task, to pinpoint problems.

When you select a particular logging level, events corresponding to that level and to all higher (less verbose) levels are logged. The default level of logging is Notice.

Note:

The more verbose the logging you specify, the more disk space your log files will occupy; for guidelines, see "Defining and Setting Service Logging Options."

Categories of Logged Events

Within each supported service or protocol, Messaging Server further categorizes logged events by the facility, or functional area, in which they occur. Every logged event contains the name of the facility that generated it. These categories aid in filtering events during searches. Table 23-8 lists the categories that Messaging Server recognizes for logging purposes.

Table 23-8 Categories in Which Log Events Occur

Facility	Description
General	Undifferentiated actions related to this protocol or service
LDAP	Actions related to Messaging Server accessing the LDAP directory database
Network	Actions related to network connections (socket errors fall into this category)
Account	Actions related to user accounts (user logins fall into this category)
Protocol	Protocol-level actions related to protocol-specific commands (errors returned by POP, IMAP, or HTTP functions fall into this category)
Stats	Actions related to the gathering of server statistics
Store	Low-level actions related to accessing the message store (read/write errors fall into this category)

For examples of using categories as filters in log searches, see "Searching and Viewing Service Logs."

Service Log File Directories

Every logged service is assigned a single directory, in which its log files are stored. All IMAP log files are stored together, as are all POP log files, and log files of any other service. You define the location of each directory, and you also define how many log files of what maximum size are permitted to exist in the directory.

Make sure that your storage capacity is sufficient for all your log files. Log data can be voluminous, especially at lower (more verbose) logging levels.

It is important also to define your logging level, log rotation, log expiration, and server-backup policies appropriately so that all of your log-file directories are backed up and none of them become overloaded; otherwise, you may lose information. See "Defining and Setting Service Logging Options."

Understanding Service Log File Format

All message store and administration service log files created by Messaging Server have identical content formats. Log files are multiline text files, in which each line describes one logged event. All event descriptions, for each of the supported services, have the general format:

<dateTime> <hostName> <processName>[<pid>]: <category> <logLevel>: <eventMessage> 

Table 23-9 lists the log file components. Note that this format of event descriptions is identical to that defined by the UNIX syslog facility, except that the date/time format is different and the format includes two additional components (category and logLevel).

Store and Administration Log File Components

Table 23-9 lists the log files components for POP and IMAP.

Table 23-9 POP and IMAP Log File Formats

Component	Definition
dateTime	The date and time at which the event was logged, expressed in dd/mm/yyyy hh:mm:ss format, with a time-zone field expressed as +/-hhmm from GMT. For example:02/Jan/1999:13:08:21 -0700
hostName	The name of the host machine on which the server is running: for example, showshoe. Note: If there is more than one instance of Messaging Server on the host, you can use the process ID (pid) to separate logged events of one instance from another.
processName	The name of the process that generated the event: for example, cgi_store.
pid	The process ID of the process that generated the event: for example, 18753.
category	The category that the event belongs to: for example, General (see "Example MTA Logging: Sending to a Nonexistent Remote User").
logLevel	The level of logging that the event represents: for example, Notice (see "Example MTA Logging: Sending to a Nonexistent Domain").
eventMessage	An event-specific explanatory message that may be of any length: for example, Log created (894305624).

Here are three examples of logged events:

02/May/1998:17:37:32 -0700 showshoe cgi_store[18753]: General Notice:
Log created (894155852)

04/May/1998:11:07:44 -0400 xyzmail cgi_service[343]: General Error:
function=getserverhello|port=2500|error=failed to connect

03/Dec/1998:06:54:32 +0200 ExamplePost imapd[232]: Account Notice: close [127.0.0.1]
[unauthenticated] 1998/12/3 6:54:32 0:00:00 0 115 0

IMAP and POP event entries may end with three numbers. The example above has 0 115 0. The first number is bytes sent by client, the second number is the bytes sent by the server, and third number is mailboxes selected (always 1 for POP).

When viewing a log file in the Log Viewer window, you can limit the events displayed by searching for any specific component in an event, such as a specific logging level or category, or a specific process ID. For more information, see "Searching and Viewing Service Logs."

The event message of each log entry is in a format specific to the type of event being logged, that is, each service defines what content appears in any of its event messages. Many event messages are simple and self-evident; others are more complex.

Defining and Setting Service Logging Options

You can define the message store and administration service logging configurations that best serve your administration needs. This section discusses issues that may help you decide on the best configurations and policies, and it explains how to implement them.

Flexible Logging Architecture

The naming scheme for log files (service.sequenceNum.timeStamp) helps you to design a flexible log-rotation and backup policy. The fact that events for different services are written to different files makes it easier for you to isolate problems quickly. Also, because the sequence number in a filename is ever-increasing and the timestamp is always unique, later log files do not simply overwrite earlier ones after a limited set of sequence numbers is exhausted. Instead, older log files are overwritten or deleted only when the more flexible limits of age, number of files, or total storage are reached.

Messaging Server supports automatic rotation of log files, which simplifies administration and facilitates backups. You are not required to manually retire the current log file and create a new one to hold subsequent logged events. You can back up all but the current log file in a directory at any time, without stopping the server or manually notifying the server to start a new log file.

In setting up your logging policies, you can set options (for each service) that control limits on total log storage, maximum number of log files, individual file size, maximum file age, and rate of log-file rotation.

Planning the Options You Want

Keep in mind that you must set several limits, more than one of which might cause the rotation or deletion of a log file. Whichever limit is reached first is the controlling one. For example, if your maximum log-file size is 3.5 MB, and you specify that a new log be created every day, you may actually get log files created faster than one per day if log data builds up faster than 3.5 MB every 24 hours. Then, if your maximum number of log files is 10 and your maximum age is 8 days, you may never reach the age limit on log files because the faster log rotation may mean that 10 files will have been created in less than 8 days.

The following default values, provided for Messaging Server administration logs, may be a reasonable starting point for planning:

Maximum number of log files in a directory: 10

Maximum log-file size: 2 MB

Total maximum size permitted for all log files: 20 MB

Minimum free disk space permitted: 5 MB

Log rollover time: 1 day

Maximum age before expiration: 7 days

Level of logging: Notice

You can see that this configuration assumes that server-administration log data is predicted to accumulate at about 2 MB per day, backups are weekly, and the total space allotted for storage of admin logs is at least 25 MB. (These settings may be insufficient if the logging level is more verbose.)

For POP, IMAP or HTTP logs, the same values might be a reasonable start. If all services have approximately the same log-storage requirements as the defaults shown here, you might expect to initially plan for about 150 MB of total log-storage capacity. (Note that this is meant only as a general indication of storage requirements; your actual requirements may be significantly different.)

Understanding Logging Options

You can set options that control the message store logging configuration by the command line.

The optimal settings for these options depend on the rate at which log data accumulates. It may take between 4,000 and 10,000 log entries to occupy 1 MB of storage. At the more verbose levels of logging (such as Notice), a moderately busy server may generate hundreds of megabytes of log data per week. Here is one approach you can follow:

• Set a level of logging that is consistent with your storage limits---that is, a level that you estimate will cause log-data accumulation at approximately the rate you used to estimate the storage limit.

• Define the log file size so that searching performance is not impacted. Also, coordinate it with your rotation schedule and your total storage limit. Given the rate at which log entries accumulate, you might set a maximum that is slightly larger than what you expect to accumulate by the time a rotation automatically occurs. And your maximum file size times your maximum number of files might be roughly equivalent to your total storage limit. For example, if your IMAP log rotation is daily, your expected accumulation of IMAP log data is 3 MB per day, and your total storage limit for IMAP logs is 25 MB, you might set a maximum IMAP log-file size of 3.5 MB. (In this example, you could still lose some log data if it accumulated so rapidly that all log files hit maximum size and the maximum number of log files were reached.)

• If server backups are weekly and you rotate IMAP log files daily, you might specify a maximum number of IMAP log files of about 10 (to account for faster rotation if the individual log-size limit is exceeded), and a maximum age of 7 or 8 days.

• Pick a total storage limit that is within your hardware capacity and that coordinates with the backup schedule you have planned for the server. Estimate the rate at which you anticipate that log data will accumulate, add a factor of safety, and define your total storage limit so that it is not exceeded over the period between server backups. For example, if you expect to accumulate an average of 3 MB of IMAP log-file data per day, and server backups are weekly, you might specify on the order of 25 - 30 MB as the storage limit for IMAP logs (assuming that your disk storage capacity is sufficient).

• For safety, pick a minimum amount of free disk space that you will permit on the volume that holds the log files. That way, if factors other than log-file size cause the volume to fill up, old log files will be deleted before a failure occurs from attempting to write log data to a full disk.

Searching and Viewing Service Logs

The log files provide the basic interface for viewing message store and administration log data. For a given service, log files are listed in chronological order. Once you have chosen a log file to search, you can narrow the search for individual events by specifying search options.

Search Options

These are useful search options you can specify for viewing log data:

• A time period. You can specify the beginning and end of a specific time period to retrieve events from, or you can specify a number of days (before the present) to search. You might typically specify a range to look at logged events leading up to a server crash or other occurrence whose time you know of. Alternatively, you might specify a day range to look at only today's events in the current log file.

• A level of logging. You can specify the logging level (see "Logging Levels" example, Critical to see why the server went down, or Error to locate failed protocol calls.

• A facility. You can specify the facility (see "Categories of Logged Events" that contains the problem; for example, Store if you believe a server crash involved a disk error, or Protocol if the problem lies in an IMAP protocol command error.

• A text search pattern. You can provide a text search pattern to further narrow the search. You can include any component of the event (see "Understanding Service Log File Format" search, such as event time, process name, process ID, and any part of the event message (such as remote host name, function name, error number, and so on) that you know defines the event or events you want to retrieve. Your search pattern can include the following special and wildcard characters:

* Any set of characters (example: *.com)

? Any single character (example: 199?)

[nnn] Any character in the set nnn (example: [aeiou])

[] Any character not in the set nnn (example: [Managing Logging^aeiou])

[] Any character in the range n-m (example: [A-Z])

[Managing Logging^n-m] Any character not in the range n-m (example: [Managing Logging^0-9])

\ Escape character: place before *, ?, [, or ] to use them as literals

Note:

Searches are case-sensitive.

Examples of combining logging level and facility in viewing logs might include the following:

• Specifying Account facility (and Notice level) to display failed logins, which may be useful when investigating potential security breaches

• Specifying Network facility (and all logging levels) to investigate connection problems

• Specifying all facilities (and Critical logging level) to look for basic problems in the functioning of the server

Working With Service Logs

This section describes how to work with service logs by using the msconfig command for searching and viewing logs.

To Send Service Logs to syslog

1. Run the msconfig command with the syslogfacility option:

   msconfig logfile.service.syslogfacilityvalue

   where service is admin, pop, imap, mta, base or http and value is user, mail, daemon, local0 to local7, or none.

   Once the value is set, messages are logged to the syslog facility corresponding to the set value and all the other log file service options are ignored. When the option is not set or the value is none, logging uses the Messaging Server log files.

To Disable HTTP Logging

If your system does not support HTTP message access, that is, Webmail, you can disable HTTP logging by setting the following variables. Do not set these variables if your system requires Webmail support (for example, Messenger Express).

1. Run the following msconfig commands:

   msconfig
   msconfig> set http.enable 0
   msconfig set http.enablesslport 0
   msconfig write
   

To Set the Server Log Level

1. Run the following msconfig command:

   msconfig set <service>.logfile.loglevel <loglevel>
   

   where service is admin, pop, imap, mta, base or http and loglevel is Nolog, Critical, Error, Warning, Notice, Information, or Debug.

To Specify a Directory Path for Server Log Files

1. Run the following msconfig command:

   msconfig <service>.logfile.logdir <dirpath>
   

To Specify a Maximum File Size for Each Service Log

1. Run the following msconfig command:

   msconfig set <service>.logfile.maxlogfilesize <size>
   

   where <size> specifies a number of bytes.

To Specify a Service Log Rotation Schedule

1. Run the following msconfig command:

   msconfig set <service>.logfile.rollovertime <number> 
   

   where number specifies a number of seconds.

To Specify a Maximum Number of Service Log Files Per Directory

1. Run the following msconfig command:

   msconfig <service>.logfile.maxlogsize <number> 
   

   where number specifies the maximum number of log files.

To Specify a Storage Limit

1. Run the following msconfig command:

   msconfig _service_.logfile.maxlogsize _number_
   

   where number specifies a number in bytes.

To Specify the Minimum Amount of Free Disk Space to Reserve

1. Run the following msconfig command:

   msconfig <service>.logfile.minfreediskspace <number> 
   

   where number specifies a number in bytes.

To Specify an Age for Logs at Which They Expire

msconfig -o <service>.logfile.expirytime <number>

where number specifies a number in seconds.

Implementing and Configuring Message Store Transaction Logging

This section contains the following topics:

• Overview of Message Store Transaction Logging

• Message Store Transaction Logging Log Entries

• Configuring Message Store Transaction Logging

• Message Store Transaction Log Examples

Overview of Message Store Transaction Logging

You can use Message Store transaction logging to record Messaging Server user actions and events, tracing messages similar to the way the MTA traces messages. Tracing messages in this fashion allows you to track critical events of a message's life cycle.

Message Store transaction logging uses the same XML format used in the MTA mail.log* and connection.log* files. This XML format is the default. It provides the same transaction information previously logged in the process log at the notice and information log levels as well as information in msgtrace logging. It also includes IMAP and POP context numbers in all IMAP and POP log messages. You do not set log levels for Message Store transaction logs. You instead configure settings to determine which events and attributes to log. Message Store transaction logging uses a log roll over daemon which rolls over all logs previously written using nslogger. Message Store transaction logging provides a backward-compatibility mode that behaves the way the previous store logging worked, combining process and action logging together. It provides a msgtrace mode also for backward compatibility.

Message Store Transaction Logging Log Entries

Message Store transaction logging supports the following user actions or events.

li - login action
ma - append message action
ex - expunge message action
fe - fetch or retrieve message action
qc - quota change action
qe - quota exceeded limit action
mc - create mailbox action
md - delete mailbox action
mr - rename mailbox action
ms - subscribe to mailbox action
mu - unsubscribe to mailbox action
ac - set mailbox access control list action
sl: select a mailbox                             
co: connect to a mail account 

Message Store transaction logging actions can support the following attributes.

ts - time stamp
pi - process id
si - session id
us - canonical user name, post authentication canonical user name
mi - message id
ii - folder id
tr - transport information
if - imap flags
fi - file name
sz - message size
no - node name
tg - RFC 5423 tag
ac - action flags
ct - time cost
ma - mailbox id, mailbox, URI encoded, plus uidvalidity
om - old mailbox id
ut - RFC 5423 uidset
ua - sasl authentication id, RFC 5423 "admin"
bs - body structure, RFC 5423
dq - disk quota, RFC 5423
du - disk used
qt - over quota trigger
qr - rule with over quota
ev - message envelope
mm - maximum messages
mc - message count
sq - module sequence
sn - service name, imap, pop, admincli
un - next uid
uv - uidvalidity
ui - uid
cx - context number
ur - IMAP URL
uo - SASL original user identity
at - SSL authorization type
cs - SSL cipher suite if SSL is used
cn - SSL server certificate nickname
cc - SSL client certificate subject
su - mailbox specialuse flag
ai - setacl identifier
ar - setacl rights
hl - message header size
sd - number of deleted messages
mq - message quota
mu - module sequence in milliseconds
uc - unchanged since in seconds
uu - unchanged since in milliseconds
lu - old uid
ls - old uidset
nt - anything worthy noting

Note:

Not all attributes are available to each action. The following attributes are available for all actions:

ts: time stamp,
pi: process id,
sn: service name, imap, pop, admincli

An action log entry is an XML element with the following characteristics:

• The element tag is the two character action label, which follows XML syntax to start and end: <tag ... />

• The element has many attributes defined previously, and each action has own attributes.

• The attribute starts with a two character attribute label, and its value is quoted.

• The following attributes are required for each action entry: timestamp (ts), service name (sn), and process id (pi).

A typical log entry resembles the following:

<co ts="09/Feb/2015:13:44:54.059 -0800" sn="imapd" pi="7149" ac="C" tr="[127.0.0.1:49487]" us="admin" nt="2015/2/9 13:43:52 0:01:02 158 1032 1"/>

where:

• co indicates the action label, which is connection closed.

• Three mandatory attributes, ts (time stamp), sn (service name), and pi (process id) are present.

• The action specific attributes are us (user name) and ac (action flags).

Configuring Message Store Transaction Logging

Transaction logging configuration is applied globally to IMAP, POP, and delivery Message Store components.

Enabling Message Store Transaction Logging

To trace transactions in the Message Store transaction log, you configure message tracing in addition to the logging configuration.

To enable Message Store transaction logging, run the following command:

msconfig set messagetrace.activate transactlog

To show the configuration, run the following command:

msconfig show messagetrace.activaterole.messagetrace.activate = transactlog

Enabling Message Store Transaction Log Actions and Attributes

The syntax to enable store actions and attributes is a matrix that you configure separately using actions and action attributes.

Table 23-10 shows the actions and their descriptions.

Table 23-10 Message Store Transaction Log Actions

Action	Description
all	All actions are enabled. This is the default.
+({li|lo|ma|...})	Only actions in the list are enabled. Actions are separated by a space.
-({li|lo|ma|...})	All actions are enabled except those in the list. Actions are separated by a space.

To enable all Message Store actions except for login and logout actions, run the following command.

msconfig set imap.actions '-(li lo)'

Running the msconfig show imap.actions command shows the imap.actions settings.

msconfig show imap.actionsrole.imap.actions = -(li lo)

Table 23-11 shows the attributes and their descriptions.

Table 23-11 Message Store Attributes

Attributes	Description
all	All attributes are enabled. This is the default.
+({us|mi|ii|...})	Only attributes in the list are enabled. Attributes are separated by a space.
-({us|mi|ii|...})	All attributes are enabled except those in the list. Attributes are separated by a space.

To enable only the canonical user name and session ID attributes, run the following command.

msconfig set imap.actionattributes '+(us si)'

Running the msconfig show imap.actionattributes shows the imap.actionattributes settings.

msconfig show imap.actionattributesrole.imap.actionattributes = +(us si)

Message Store Transaction Log Examples

The examples in this section use the following Messaging Store transaction logging settings:

msconfig show messagetrace
role.messagetrace.activate = transactlog
 
msconfig show imap.actions
role.imap.actions = all
 
msconfig show imap.actionattributes
role.imap.actionattributes = all

Example Message Store Transction Logs for IMAP

Example 1: Log in as Joe.

<li ts="24/Jul/2014:13:33:04.306 -0700" sn="imapd" pi="26435" us="joe" tr="[127.0.0.1:45046]" at="plaintext" cs="noSSL" si="0"/>

Example 2: Create mailbox Folder1 and Folder2.

<mc ts="24/Jul/2014:13:33:40.902 -0700" sn="imapd" pi="26435" us="joe" ma="Folder1"/><mc ts="24/Jul/2014:13:34:05.299 -0700" sn="imapd" pi="26435" us="joe" ma="Folder2"/>

Example 3: Delete mailbox Folder1.

<md ts="24/Jul/2014:13:34:12.515 -0700" sn="imapd" pi="26435" us="joe" ma="Folder1"/>

Example 4: Append message to Folder2.

<ma ts="24/Jul/2014:13:46:25.271 -0700" sn="imapd" pi="27080" us="" ma="user/joe/Folder2" sz="163" ui="1" uv="1406234045" cx="0"/>

Example 5: Expunge 2 messages in the Inbox.

<ex ts="25/Jul/2014:13:50:27.164 -0700" sn="imapd" pi="30247" ma="user/joe" mi="[e-mail]" no="[127.0.0.1:52383]"/><ex ts="25/Jul/2014:13:52:43.163 -0700" sn="imapd" pi="30247" ma="user/joe" mi="[e-mail]" no="[127.0.0.1:52383]"/>

Example 6: Log out.

<co ts="09/Feb/2015:13:44:54.059 -0800" sn="imapd" pi="7149" ac="C" tr="[127.0.0.1:49487]" us="admin" nt="2015/2/9 13:43:52 0:01:02 158 1032 1"/>

Example 7: Connect to an email account.

<co ts="05/Feb/2015:11:57:41.896 -0800" sn="imapd" pi="27433" tr="[192.0.2.1:3984]" at="ssl"/>

Example 8: Select a folder.

<sl ts="05/Feb/2015:11:57:42.005 \-0800" sn="imapd" pi="27433" tr="[192.0.2.1:3984]" ma="user/admin" us="admin"/>

Example 9: Rename a folder.

imap command: A01 RENAME Folder1 Folder2<mr ts="05/Feb/2015:12:03:52.672 \-0800" sn="imapd" pi="27433" us="admin" ma="Folder2" om="Folder1"/>

Example 10: Subscribe to a folder.

imap command: A01 SUBSCRIBE INBOX<ms ts="05/Feb/2015:12:08:21.589 \-0800" sn="imapd" pi="27433" us="admin" ma="inbox"/>

Example 11: Unsubscribe from a folder.

imap command: A01 UNSUBSCRIBE INBOX<mu ts="05/Feb/2015:12:14:39.187 \-0800" sn="imapd" pi="3613" us="admin" ma="inbox"/>

Example 12: Set acl to a mailbox.

imap command: A01 SETACL folder1 david lrstwiead<ac ts="05/Feb/2015:12:06:34.287 \-0800" sn="imapd" pi="27433" us="admin" ma="user/admin/folder1" nt="admin lrstwiepkxancd :admin lrstwiepkxancd David lrstwiead "/>

Example 13: Fetch rfc822.text.

imap command: A01 FETCH 1 RFC822.TEXT<fe ts="05/Feb/2015:14:00:54.865 \-0800" sn="imapd" pi="3613" us="admin" ma="user/admin" sz="-1:0" mi="<[e-mail]>"/>

Example 14: Change quota.

imap command: A01 SETQUOTA user/admin/Folder1 (STORAGE 512)<qc ts="05/Feb/2015:14:15:36.059 \-0800" sn="imapd" pi="3613" us="admin" ur="user/admin/Folder1" dq="512"/>

Example 15: Quota exceeds limit.

imquotacheck command: ./imquotacheck \-n \-l \-r rulefile<qe ts="05/Feb/2015:15:22:54.087 \-0800" sn="imquotacheck" pi="26490" us="admin" dq="2" du="43" mq="0" mc="0" qt="90" qr="rule3"/>

For more information on syntax and options, see "imquotacheck."

Example Message Store Transaction Logs for POP

Example 1: Log in as Joe.

<li ts="24/Jul/2014:16:59:43.187 \-0700" sn="popd" pi="27522" us="joe" tr="[127.0.0.1:29611]" at="plaintext" cs="noSSL" si="21"/>

Example 2: Fetch message.

<fe ts="24/Jul/2014:17:00:08.205 \-0700" sn="popd" pi="27522" us="joe" om="user/joe" mi="<[e-mail]>"/>

Example 3: Delete message.

<ex ts="24/Jul/2014:17:02:04.565 \-0700" sn="popd" pi="27522" ma="user/joe" mi="<[e-mail]>" no="sc11136733"/>

Example 4: Connect to an email account.

<co ts="05/Feb/2015:12:01:36.719 -0800" sn="popd" pi="27443" tr="[10.133.141.196:60395]" at=""/>

Example Message Store Transaction Logs for Message Delivery

Example 1: Send five messages to Joe.

<ma ts="24/Jul/2014:17:05:13.950 \-0700" sn="ims_master" pi="9236" us="" ma="user/joe" sz="404652" mi="<[e-mail]>" ui="5" uv="1392927327" cx="0"/><ma ts="24/Jul/2014:17:05:13.954 \-0700" sn="ims_master" pi="9236" us="" ma="user/joe" sz="404652" mi="<[e-mail]>" ui="6" uv="1392927327" cx="0"/><ma ts="24/Jul/2014:17:05:13.974 \-0700" sn="ims_master" pi="9236" us="" ma="user/joe" sz="404652" mi="<[e-mail]>" ui="7" uv="1392927327" cx="0"/><ma ts="24/Jul/2014:17:05:14.010 \-0700" sn="ims_master" pi="9240" us="" ma="user/joe" sz="404652" mi="<[e-mail]>" ui="8" uv="1392927327" cx="0"/><ma ts="24/Jul/2014:17:05:14.043 \-0700" sn="ims_master" pi="9240" us="" ma="user/joe" sz="404652" mi="<[e-mail]>" ui="9" uv="1392927327" cx="0"/>

Other Message Store Logging Features

Messaging Server provides a feature called telemetry that can capture a user's entire IMAP or POP session into a file. This feature is useful for debugging client problems. For example, if a user complains that their message access client is not working as expected, this feature can be used to trace the interaction between the access client and Messaging Server. See in "Checking User IMAP/POP/Webmail Session by Using Telemetry."

Message Store Logging Examples

The exact field format and list of fields logged in the Message Store log files vary according to the logging options set. This section shows a few examples of interpreting typical sorts of log entries.

Message Store Logging Example: Bad Password

When a user types an invalid password, "authentication" failure is logged, as opposed to a "user not found" message. The message "user not found" is the text passed to the client for security reasons, but the real reason (invalid password) is logged.

Example Message Store Logging: Invalid Password

[31/Aug/2004:16:33:14 \-0700|] vadar imapd[13027]: Account Notice: badlogin:
[192.18.126.64:40718] plaintext user1 authentication failure

Message Store Logging Example: Account Disabled

The following example shows why a user cannot log in due to a disabled account. Furthermore, the disabled account is clarified as "(inactive)" or "(hold)."

Example Message Store Logging: Account Disabled

[31/Aug/2004:16:33:14 \-0700|] vadar imapd[13027]: Account Notice: badlogin:
[192.18.126.64:40720] plaintext user3 account disabled (hold)

Message Store Logging Example: Message Appended

The following example shows an append message, which occurs when whenever a message is appended to a folder. The Message Store log records all messages entering the Message Store through the ims_master and lmtp channels. Records the "append" of user ID, folder, message size, and message ID.

Example Message Store Logging: Append

[31/Aug/2004:16:33:14 \-0700|] vadar ims_master[13822]: Store Information:append:user1:user/user1:659:<[e-mail]>

Message Store Logging Example: Message Retrieved by a Client

The Message Store log writes a "fetch" message when a client retrieves a message. The Message Store log records all client fetches of at least one body part. Records the "fetch" of user ID, folder, and message-ID.

Example Message Store Logging: Message Retrieved by a Client

[31/Aug/2004:16:33:14 \-0700|] vadar imapd[13729]: Store Information:
fetch:user1:user/user1:<[e-mail]>

Message Store Logging Example: Message Removed from a Folder

The following example shows how to remove a message from a folder.

The Message Store writes an "expunge" message when an IMAP or POP message is removed from a folder (but not removed from the system). It is logged whether it is expunged by the user or a utility. Records the "expunge" of folder and message ID.

Example Message Store Logging Example: Message Removed from a Folder

[31/Aug/2004:16:33:14 \-0700|] vadar imexpire[13923]: Store Information:
expunge:user/user1:<[e-mail]>

Message Store Logging Example: Duplicate Login Messages

If you configure message trace for one msgtrace log file, the normal "login" messages, which appear in the imap and pop log files, are duplicated in the msgtrace file. The following is a normal login message:

Example Message Store Logging: Login

[31/Aug/2004:16:33:14 \-0700|] vadar imapd[13027]: Account Information: login
[192.18.126.64:40718] user1 plaintext

Using Message Store Log Messages

Use the following links to significant Message Store logging and error message pages:

• "Overview of Logging." Provides an introduction to Messaging Server logging concepts.

• "Tools for Managing Logging." Lists available tools for managing logs.

• See the discussion on logging options in the Messaging Server Reference.

  Search for logfile. The information lists the configuration options that you set for Messaging Server by using the configutil command. You can view the documentation for the Unified Configuration equivalent of a configutil option by clicking on the configutil name link.

• "Managing Message Store, Admin, and Default Service Logs." Describes logging for the Message Store (POP, IMAP, and HTTP), Admin, and Default services.

MMP Logging

The logging format used by the MMP is unstable and subject to change at any time. It uses the nslog model and syntax used by the store, with similar configuration settings. The most interesting line in the MMP log is:

[04/Feb/2016:10:42:24 -0800] myhostname ImapProxyAService.cfg[17242]: General 
Notice: (id 3) Proxy connect for client 10.0.0.5:55159 (cleartext) canonical 
user '[e-mail]' original user 'admin' auth 'PLAIN' via MMP 
127.0.0.1:55162 to backend 127.0.0.1 (cleartext)

which can be used to correlate a connection from a client to a back end connection.

For debugging the MMP, the loglevel may be raised and the debugkeys option can be helpful.

For additional information, see the discussion on MMP in the Messaging Server Reference.