Log_callout_delays MTA option

From Messaging Server Technical Reference Wiki
Jump to: navigation, search



Transaction logging MTA options: log_callout_delays (0-3)

The MTA can optionally use timers to measure the total time the MTA spends waiting for various external components to return a response. The log_callout_delays MTA option controls the logging of this timer information. Bit 0 (value 1), if set, causes the callout logging information to be logged immediately after delivery flags in "E" (enqueue) log records. The XML attribute name in XML format logs is "cd". Bit 1 (value 1), if set, causes callout logging information to be included in the LOG_ACTION mapping probe, again immediately after delivery flags. In both cases the information is formatted as described below.

Timings are done on a per-message basis.

The following callout timers have been implemented:

  • Time spent waiting for spam filters 1-8. (S1 - S8)
  • Time spent waiting for mapping routine callouts. (MC)
  • Time spent in the following specific mappings waiting for routine callouts:
  • Rewrite rule routine callouts. (RR)
  • Time spent creating an SMTP transaction for the MTA to process; (note that this necessarily includes MTA processing time). (STT)
  • Time spent writing the message file(s) to the MTA queue area. (QW)
  • Time used by the Indexed Search Converter (ISC) when operating as part of the LMTP server. (RD)
  • Time spent creating an LMTP transaction for the store to process; (note that this necessarily includes MTA processing time). (STT)
  • Time spent writing the message file(s) to the store. (QW)
  • Time spent performing smartsend activities (new in MS 8.1.0.11):
    • Time spent waiting on the T2 server (T2)

When logging this information, it is formatted in the order and with delimiters as follows (note that the field names are specified in the preceding list):


  S1,S2,S3,S4,S5,S6,S7,S8:MC,PA,FA,OSA,SA,OMA,MA,AW,RV,S,FW,CO,LA:RR:STT,QW,RD:T2

Each value appears an an integer time in centiseconds followed by a semicolon and an integer use count:

T;U

Any value consisting of a zero-time;zero-use-count pair will be omitted entirely. Use counts of 1 are also omitted. Finally, zero elements of the comma-separated sublists may be truncated from the right.

In the specific case of spam filter wait timers, an outright spam filter failure is indicated by presence of an "F" suffix followed by an integer code which indicates the phase where the failure occurred. The code values are:

Spamfilter phase failure codes
Code Failure Spamfilter routine Milter command
1 SYSTEM_FAILURE bmiInitSystem n/a
2 MESSAGE_FAILURE bmiInitMessage (milter connect)
3 CONNECT_FAILURE bmiProcessConnection SMFIC_CONNECT/SMFIC_HELO
4 MAILFROM_FAILURE bmiProcessFROM SMFIC_MAIL
5 AUTHADDR_FAILURE bmiProcessAUTH n/a
6 RCPTTO_FAILURE bmiAccumulateTO/bmiRejectTO SMFIC_RCPT
7 ENDRCPTTO_FAILURE bmiEndTO SMFIC_DATA
8 HEADER_FAILURE bmiAccumulateHeaders SMFIC_HEADER
9 ENDHEADER_FAILURE bmiEndHeaders SMFIC_EOH
10 BODY_FAILURE bmiAccumulateBody SMFIC_BODY
11 ENDBODY_FAILURE bmiEndBody SMFIC_BODYEOB command
12 SUBMIT_FAILURE bmiEndMessage SMFIC_BODYEOB response
13 UNKNOWN_FAILURE n/a n/a

The interpretation of delay values in the case of single recipient messages is straightforward. But things become more complex when multiple recipients are involved and multiple E records are produced:

  • Delays caused by spam filters, rewrite rule callouts, and mapping callouts other than LOG_ACTION are common to all recipients, and as such will be presented as identical values in each E record.
  • Delays writing a message to the queue are associated with a specific message file and are presented as identical values in each E record associated with that message file.
  • Delays caused by the LOG_ACTION callout are specific to a particular E record

Parsers should be aware that additional, colon-delimited elements may be added to the list as a whole, comma-separated elements may be added to sublists, and even semicolon-separated elements may be added to individual timer values.

Here are some samples of the timers field in XML format:


cd="1410,,,15:::123,25"
cd="1243,,,21:::127,33"                                                         
cd="172:1855;5,,107,248,400,500,600::4836,14"
cd=":::1222,11"

New in MS 8.1.0.11, a Python script, print_callout_delays.py, is provided that will parse and dump the contents of callout delay strings. Assuming Messaging Server is installed in the default location, it can be invoked with a command of the form:


python /opt/sun/comms/messaging64/lib/print_callout_delays.py

See also: