This article applies to:

• Trustwave MailMarshal (SEG)

Question:

Information:

This article provides a short overview of how to read MailMarshal SMTP Log files.

Each MailMarshal service creates a text log file. A new file is created at least daily. If the log reaches 10MB, a new file is started. The logs are deleted after five days by default (14 days in some later versions of SEG). The logs are located in the logging subfolder of the installation (for instance, c:\Program Files\Marshal\MailMarshal\logging). The files are named with the name of the service, date, and sequence letter (for instance, MMControllerJun13b.log).

You can change the location using the Server Tool. You can change the retention policy with a Registry/Advanced setting (see article Q10447).

Note: If you set up a rule to archive or quarantine messages, in recent versions the logging information is saved with the file and available in the Console. This is an easy way to retain logging information for longer than the default period.

The logs are useful for troubleshooting purposes. Processing information and problems encountered are recorded in the log files.

What is logged?

• The MMArrayManager log (present in version 6.0 and above) includes information about the database connection and database writing, directory connector updates, SpamCensor updates, configuration changes, and configuration reloads.
• The MMController log for version 6.0 and above is present on email processing servers and includes information about the array manager connection and configuration retrieval. Version 6.2 and above also includes information about DNS lookup and caching. Prior to version 6.0, the array manager is not present and the controller log also includes directory connector updates, SpamCensor updates, and other system information.
• The MMSender log contains information about outbound connections and messages MailMarshal has sent. It will contain server handshaking and validation information. 
• The MMReceiver log contains information about inbound connections and messages MailMarshal has received. It will contain DoS and DHA blocking details, server handshaking and validation information. This log alsos contain information on Receiver rules that have triggered.
• The MMEngine log contains a record of Standard rule processing for each message. This includes for each message a list of the rules that were checked, what rules if any triggered, and what actions MailMarshal performed.
• The MMSpamProfiler log provides information about the SpamProfiler spam detection service (if enabled). This includes SpamProfiler signature updates, and message detection scores. This log is present in versions above 7.5.7; in 6.7 through 7.2.3; and in other versions depending on hotfix installation.
• Other tools and services, such as the quarantine upgrade tool, also create log files.

How does email flow?

To troubleshoot email processing, you should understand how MailMarshal processes email.

1. When an email message is sent through MailMarshal (inbound or outbound), the Receiver service handshakes and validates the sending server. If the message is accepted, the Receiver assigns a unique message number starting with b00 (b0000X.XX), and applies any Receiver rules.

2. The Receiver then creates a MML file containing the message, in the Incoming folder.

3. The Engine picks up each MML file in turn, unpacks the email and its contents by layers, then applies the Standard rules. After actioning the rules, if a message is not blocked the Engine places the file in the ProcessedOk folder.

4. The Sender service picks up the MML file and makes the required connections to send it to each recipient domain.

Note: The message number (starting with b00 for ordinary messages) is unique. This number identifies an individual message throughout the MailMarshal system. Therefore when looking through the logs (or in the Console) you can track particular messages through each of the services by searching via the message number.

For instance, in the Sender or Receiver logs, you can track by time sent or received, and email addresses of sender and recipient.

In the log files you will also notice the 4 digit number (for example 0116) before the time stamp of each line of log. This is the thread ID. This number is also useful to track when reading the raw logs. Normally MailMarshal services, especially the Sender and Receiver, are working on multiple threads at the same time. To trace a particular message you need to follow the thread ID which may skip lines in the logs. If you are interested in engine action, it is much easier to archive files and view the log excerpts, because these excerpts contain only the information about the specific message.

Examples

MMReceiver log for an incoming email (in this case, from Windows Mail on the local system)

4020 14:17:16.960 Accepted 127.0.0.1:1300 on interface 127.0.0.1:25 (1 of 50 active), Total active 1. Assigning thread 3724
3724 14:17:16.960 DOS - IP whitelisted. <127.0.0.1> will not be evaluated.
3724 14:17:16.960 TX: <220 vm-example45 ESMTP MailMarshal (v6.9.5.2936) Ready>
3724 14:17:16.960 RX: <HELO vmexample45>
3724 14:17:16.960 TX: <250 vm-example45 Hello vmexample45 (127.0.0.1)>
3724 14:17:16.960 RX: <MAIL FROM: <admin@example.com>>
3724 14:17:16.960 TX: <250 sender ok <admin@example.com>>
3724 14:17:16.960 RX: <RCPT TO: <auser@example.com>>
3724 14:17:16.960 Checking user criteria for Rule Connection Policies:Deny Junk Mailers in Global Blacklist
3724 14:17:16.960 Created temp mail file <C:\Program Files (x86)\Marshal\MailMarshal\Queues\Incoming\~B4dae422c0000.000000000001.0001.mml>
3724 14:17:16.960 TX: <250 recipient ok <auser@example.com>>
3724 14:17:16.960 RX: <DATA>
3724 14:17:16.960 TX: <354 send the mail data, end with .>
3724 14:17:16.976 MessageId <<CF2AFCFD69974446B9FAEBE29579CCF9@vmexample45>> accepted for normal processing.
3724 14:17:16.976 Received Mail Message C:\Program Files (x86)\Marshal\MailMarshal\Queues\Incoming\B4dae422c0000.000000000001.0001.mml from 127.0.0.1, 1188 bytes.
3724 14:17:16.976 TX: <250 B4dae422c0000 Message accepted for delivery>
3724 14:17:16.976 RX: <QUIT>
3724 14:17:16.976 TX: <221 vm-example45 closing connection>
3724 14:17:16.976 Thread exiting for 127.0.0.1 after 16 millisecs


From the logs above you can see the Receiver thread starting, standard SMTP responses that indicate that the message has been received, and the saving of the message as a local text file.

MMEngine log:

3924 14:17:16.976 Incoming Msg Event
3908 14:17:16.976 Thread 1 running for B4dae422c0000.000000000001.0001.mml - Message ID:<CF2AFCFD69974446B9FAEBE29579CCF9@vmexample45>
3908 14:17:16.976 20 Apr 2011 - B4dae422c0000.000000000001.0001.mml
3908 14:17:16.976 Message From <admin@example.com>, Return-path <admin@example.com>, Recipients (1) -  <auser@example.com>
3908 14:17:16.976 Thread 1 Starting to unpack <B4dae422c0000.000000000001.0001.mml>
3908 14:17:16.992 MimeTags::Process tag Content-Type =  multipart/alternative; boundary="----=_NextPart_000_000F_01CBFF65.A707FF10"
3908 14:17:16.992  MimeTags::Process tag Content-Type =  text/plain; charset="iso-8859-1"
3908 14:17:16.992  MimeTags::Process tag Content-Transfer-Encoding =  quoted-printable
3908 14:17:16.992  Encoding <quoted-printable>
3908 14:17:16.992  Quoted-Printable encoded section consumed 12 bytes - file C:\Program Files (x86)\Marshal\MailMarshal\Unpacking\T1\U2\Quoted-Printable.txt
3908 14:17:16.992  MimeTags::Process tag Content-Type =  text/html; charset="iso-8859-1"
3908 14:17:16.992  MimeTags::Process tag Content-Transfer-Encoding =  quoted-printable
3908 14:17:16.992  Encoding <quoted-printable>
3908 14:17:16.992  Quoted-Printable encoded section consumed 345 bytes - file C:\Program Files (x86)\Marshal\MailMarshal\Unpacking\T1\U2\Quoted-Printable_1.txt
3908 14:17:16.992  UnpackComposite: End boundary found - unwinding
3908 14:17:16.992 Type=MAIL,  size=1343,  Name=B4dae422c0000.000000000001.0001.mml
3908 14:17:16.992   Type=MHDR,  size=600,  Name=MsgHeader.txt
3908 14:17:16.992   Type=MBODY,  size=12,  Name=Quoted-Printable.txt
3908 14:17:16.992   Type=MBODY,  size=326,  Name=Quoted-Printable_1.txt
3908 14:17:16.992 1 user(s) match ruleset - Content:Virus & Threats (Inbound)
3908 14:17:16.992   1 user(s) match rule - Content:Virus & Threats (Inbound):Block Known Threats
3908 14:17:16.992     Name=U1\B4dae422c0000.000000000001.0001.mml (MAIL,1343) False
3908 14:17:16.992   1 user(s) match rule - Content:Virus & Threats (Inbound):Block Known Virus Attachments
3908 14:17:16.992     Name=U1\B4dae422c0000.000000000001.0001.mml (MAIL,1343) False
3908 14:17:16.992       Name=U2\MsgHeader.txt (MHDR,600) False
3908 14:17:16.992       Name=U2\Quoted-Printable.txt (MBODY,12) False
3908 14:17:16.992       Name=U2\Quoted-Printable_1.txt (MBODY,326) False
3908 14:17:16.992   1 user(s) match rule - Content:Virus & Threats (Inbound):Block Virus - Zero Day Protection Framework
3908 14:17:16.992     Name=U1\B4dae422c0000.000000000001.0001.mml (MAIL,1343) False
3908 14:17:17.007 0 user(s) match ruleset - Content:Virus & Threats (Outbound)
3908 14:17:17.007 1 user(s) match ruleset - Content:Attachment Management (Inbound)
3908 14:17:17.007   1 user(s) match rule - Content:Attachment Management (Inbound):Block Suspect Attachments
3908 14:17:17.007     Name=U1\B4dae422c0000.000000000001.0001.mml (MAIL,1343) False
3908 14:17:17.007       Name=U2\MsgHeader.txt (MHDR,600) False
3908 14:17:17.007       Name=U2\Quoted-Printable.txt (MBODY,12) False
3908 14:17:17.007       Name=U2\Quoted-Printable_1.txt (MBODY,326) False
3908 14:17:17.007   1 user(s) match rule - Content:Attachment Management (Inbound):Block Password Protected Attachments
3908 14:17:17.007     Name=U1\B4dae422c0000.000000000001.0001.mml (MAIL,1343) False
3908 14:17:17.007       Name=U2\MsgHeader.txt (MHDR,600) False
3908 14:17:17.007       Name=U2\Quoted-Printable.txt (MBODY,12) False
3908 14:17:17.007       Name=U2\Quoted-Printable_1.txt (MBODY,326) False
3908 14:17:17.007   1 user(s) match rule - Content:Attachment Management (Inbound):Block Unknown Attachments
3908 14:17:17.007     Name=U1\B4dae422c0000.000000000001.0001.mml (MAIL,1343) False
3908 14:17:17.007       Name=U2\MsgHeader.txt (MHDR,600) False
3908 14:17:17.007       Name=U2\Quoted-Printable.txt (MBODY,12) False
3908 14:17:17.007       Name=U2\Quoted-Printable_1.txt (MBODY,326) False
3908 14:17:17.007   1 user(s) match rule - Content:Attachment Management (Inbound):Block EXECUTABLE Files
3908 14:17:17.007     Name=U1\B4dae422c0000.000000000001.0001.mml (MAIL,1343) False
3908 14:17:17.007       Name=U2\MsgHeader.txt (MHDR,600) False
3908 14:17:17.007       Name=U2\Quoted-Printable.txt (MBODY,12) False
3908 14:17:17.007       Name=U2\Quoted-Printable_1.txt (MBODY,326) False
3908 14:17:17.007 0 user(s) match ruleset - Content:Attachment Management (Outbound)
3908 14:17:17.007 1 user(s) match ruleset - Content:Policy Management (Inbound)
3908 14:17:17.007   1 user(s) match rule - Content:Policy Management (Inbound):Block Pornographic Language
3908 14:17:17.007     Name=U1\B4dae422c0000.000000000001.0001.mml (MAIL,1343) False
3908 14:17:17.007       Name=U2\MsgHeader.txt (MHDR,600) False
3908 14:17:17.007       Name=U2\Quoted-Printable.txt (MBODY,12) False
3908 14:17:17.007       Name=U2\Quoted-Printable_1.txt (MBODY,326) False
3908 14:17:17.007 0 user(s) match ruleset - Content:Policy Management (Outbound)
3908 14:17:17.007 1 user(s) match ruleset - Content:Automated Responses
3908 14:17:17.007   1 user(s) match rule - Content:Automated Responses:Allow Senders in Recipient Allow List
3908 14:17:17.007  0 user(s) match user list
3908 14:17:17.007 1 user(s) match ruleset - Content:Message Archiving
3908 14:17:17.007   1 user(s) match rule - Content:Message Archiving:Archive All Inbound Messages
3908 14:17:17.007 Name=U1\B4dae422c0000.000000000001.0001.mml Message level criterion TRUE
3908 14:17:17.007     Requesting Action <Content:Message Archiving:Archive All Inbound Messages:CopyMessage> be run
3908 14:17:17.007   0 user(s) match rule - Content:Message Archiving:Archive All Outbound Messages
3908 14:17:17.007 Msg <B4dae422c0000> Completed
3908 14:17:17.007 Thread exiting for <B4dae422c0000.000000000001.0001.mml> after 31 millisecs
3924 14:17:17.007 (1) Thread(s) has exited - 0 still active


When the MailMarshal Engine processes an email, it first declares the contents of the email including the type, size and name (as you can see in the entries above at time 14:17:16.992). This information is essential to any further actions such as unpacking. (For instance, the file could be corrupt. You can confirm what MailMarshal has found by looking here).

The Engine unpacks the email into its parts and attachments, then unpacks each part for as many layers as are required. Each of these layers is normally identified by U1 (level 1) U2 (level2) and so on.

• In U1 you would expect the entire message (mml file), in U2 you would expect to see the email parts (msg header, body). U3 would have the next level of attachment contents (being the items attached in the email).

The Engine log records which rules have been applied to a message. For each rule, the log shows the number of users this rule applies to. In the example above 1 user(s) match rule - Content:Message Archiving:Archive All Inbound Messages

Each item in the message contents is scanned using the criteria defined in the rules that match. If the rule triggers for that item, it is actioned as "True" and if not "False". Depending on the actions if any, the message is passed through the remaining rules.

MMSender log for a message successfully sent to a local domain server:

0336 14:17:17.007 Adding message <B4dae422c0000.000000000001.0001.mml> - Message ID: <CF2AFCFD69974446B9FAEBE29579CCF9@vmexample45> age 20/04/11 14:17:16 to auser@example.com
0336 14:17:17.007 Starting thread 3160 for new message B4dae422c0000.000000000001.0001.mml 1343 bytes, Threads(New:1, Deferred:0, Static:1, DNS:0)
3160 14:17:17.007 Attempting delivery of B4dae422c0000.000000000001.0001.mml via route Local Domain - static route
3160 14:17:17.007 Delivering via Forward to IP IP(10.74.24.5):97
3160 14:17:17.007 RX: <220 example.com ESMTP Mail Service, Version: 42 -- ready at 04/20/11 14:17:17>
3160 14:17:17.007 TX: <EHLO vm-example45>
3160 14:17:17.023 RX: <250-example.com [10.74.24.5], this server offers 4 extensions>
3160 14:17:17.023 RX: <250-AUTH LOGIN>
3160 14:17:17.023 RX: <250-SIZE 5120000>
3160 14:17:17.023 RX: <250-HELP>
3160 14:17:17.023 RX: <250 AUTH=LOGIN>
3160 14:17:17.023 TX: <MAIL FROM:<admin@example.com> SIZE=1343>
3160 14:17:17.023 RX: <250 Requested mail action okay, completed>
3160 14:17:17.023 TX: <RCPT TO:<auser@example.com>>
3160 14:17:17.023 RX: <250 Requested mail action okay, completed>
3160 14:17:17.023 TX: <DATA>
3160 14:17:17.023 RX: <354 Start mail input; end with <CRLF>.<CRLF>>
3160 14:17:17.023 RX: <250 Requested mail action okay, completed>
3160 14:17:17.023 TX: <QUIT>
3160 14:17:17.023 RX: <221 Service closing transmission channel>
3160 14:17:17.023 Thread exiting for B4dae422c0000.000000000001.0001.mml after 16 millisecs
0336 14:17:17.023 (1) Thread(s) has exited - 0 still active

Notes:

See additional information in the following articles:

• Q10175 - General tips on reading MailMarshal service logs
• Q10192 - How do email messages flow through MailMarshal SMTP?

This article was previously published as:

NETIQKB29391

Marshal KB403