Logging and Debugging (Mailfromd Manual)

3.19 Logging and Debugging

Depending on its operation mode, mailfromd tries to guess whether it is appropriate to print its diagnostics and informational messages on standard error or to send them to syslog. Standard error is assumed if the program is run with one of the following command line options:

--test (see Testing Filter Scripts)
--run (see Run Mode)
--lint (see Testing Filter Scripts)
--dump-code (see Logging and Debugging Options)
--dump-grammar-trace (see Logging and Debugging Options)
--dump-lex-trace (see Logging and Debugging Options)
--dump-macros (see Logging and Debugging Options)
--dump-tree (see Logging and Debugging Options)
--xref (or --dump-xref) (see Testing Filter Scripts)

If none of these are used, mailfromd switches to syslog as soon as it finishes its startup. There are two ways to communicate with the syslogd daemon: using the syslog function from the system libc library, which is a blocking implementation in most cases, or via internal, asynchronous, syslog implementation. Whether the latter is compiled in and which implementation is used by default is determined when compiling the package, as described in Using non-blocking syslog.

The --logger command line option allows you to manually select the diagnostic channel:

--logger=stderr: Log everything to the standard error.
--logger=syslog: Log to syslog.
--logger=syslog:async: Log to syslog using the asynchronous syslog implementation.

Another way to select the diagnostic channel is by using the logger statement in the configuration file. The statement takes the same argument as its command line counterpart.

The rest of details regarding diagnostic output are controlled by the logging configuration statement.

The default syslog facility is ‘mail’; it can be changed using the --log-facility command line option or facility statement. Argument in both cases is a valid facility name, i.e. one of: ‘user’, ‘daemon’, ‘auth’, ‘authpriv’, ‘mail’, and ‘local0’ through ‘local7’. The argument can be given in upper, lower or mixed cases, and it can be prefixed with ‘log_’:

Another syslog-related parameter that can be configured is the tag, which identifies mailfromd messages. The default tag is the program name. It is changed by the --log-tag (-L command line option and the tag logging statement.

The following example configures both the syslog facility and tag:

logging {
  facility local7;
  tag "mfd";
}

As any other UNIX utility, mailfromd is very quiet unless it has something important to communicate, such as, e.g. an error condition. A set of command line options is provided for controlling the verbosity of its output.

The --trace option enables tracing Sendmail actions executed during message verifications. When this option is given, any accept, discard, continue, etc. triggered during execution of your filter program will leave their traces in the log file. Here is an example of how it looks like (syslog time stamp, tag and PID removed for readability):

k8DHxvO9030656: /etc/mailfromd.mfl:45: reject 550 5.1.1 Sender validity
not confirmed

This shows that while verifying the message with ID ‘k8DHxvO9030656’ the reject action was executed by filter script /etc/mailfromd.mfl at line 45.

The use of message ID in the log deserves a special notice. The program will always identify its log messages with the ‘Message-Id’, when it is available. Your responsibility as an administrator is to make sure it is available by configuring your MTA to export the macro ‘i’ to mailfromd. The rule of thumb is: make ‘i’ available to the very first handler mailfromd executes. It is not necessary to export it to the rest of the handlers, since mailfromd will cache it. For example, if your filter script contains ‘envfrom’ and ‘envrcpt’ handlers, export ‘i’ for ‘envfrom’. The exact instructions on how to ensure it depend on the MTA you use. For ‘Sendmail’, refer to Sendmail. For MeTA1, see MeTA1, and pmult-macros. For ‘Postfix’, see Postfix.

To push log verbosity further, use the debug configuration statement (see conf-debug) or its command line equivalent, --debug (-d, see --debug). Its argument is a debugging level, whose syntax is described in http://mailutils.org/wiki/Debug_level.

The debugging output is controlled by a set of levels, each of which can be set independently of others. Each debug level consists of a category name, which identifies the part of package for which additional debugging is desired, and a level number, which indicates how verbose should its output be.

Valid debug levels are:

error: Displays error conditions which are normally not reported, but passed to the caller layers for handling.
trace0 through trace9: Ten levels of verbosity, trace0 producing less output, trace9 producing the maximum amount of output.
prot: Displays network protocol interaction, where applicable.

The overall debugging level is specified as a list of individual levels, delimited with semicolons. Each individual level can be specified as one of:

!category: Disables all levels for the specified category.
category: Enables all levels for the specified category.
category.level: For this category, enables all levels from ‘error’ to level, inclusive.
category.=level: Enables only the given level in this category.
category.!level: Disables all levels from ‘error’ to level, inclusive, in this category.
category.!=level: Disables only the given level in this category.
category.levelA-levelB: Enables all levels in the range from levelA to levelB, inclusive.
category.!levelA-levelB: Disables all levels in the range from levelA to levelB, inclusive.

Additionally, a comma-separated list of level specifications is allowed after the dot. For example, the following specification:

acl.prot,!=trace9,!trace2

enables in category acl all levels, except trace9, trace0, trace1, and trace2.

Implementation and applicability of each level of debugging differs between various categories. Categories built-in to mailutils are described in http://mailutils.org/wiki/Debug_level. Mailfromd introduces the following additional categories:

db

trace0: Detailed debugging info about expiration and compaction.
trace5: List records being removed.

dns

trace8: Verbose information about attempted DNS queries and their results.
trace9: Enables ‘libadns’ internal debugging.

srvman

trace0: Additional information about normal conditions, such as subprocess exiting successfully or a remote party being allowed access by ACL.
trace1: Detailed transcript of server manager actions: startup, shutdown, subprocess cleanups, etc.
trace3: Additional info about fd sets.
trace4: Individual subserver status information.
trace5: Subprocess registration.

pmult

trace1: Verbosely list incoming connections, functions being executed and erroneous conditions: missing headers in SMFIR_CHGHEADER, undefined macros, etc.
trace2: List milter requests being processed.
trace7: List SMTP body content in SMFIR_REPLBODY requests.
error: Verbosely list mild errors encountered: bad recipient addresses, etc.

callout

trace0: Verification session transcript.
trace1: MX servers checks.
trace5: List emails being checked.
trace9: Additional info.

main

trace5: Info about hostnames in relayed domain list

engine

Debugging of the virtual engine.

trace5: Message modification lists.
trace6: Debug message modification operations and Sendmail macros registered.
trace7: List SMTP stages (‘xxfi_*’ calls).
trace9: Cleanup calls.

pp

Preprocessor.

trace1: Show command line of the preprocessor being run.

prog

trace8: Stack operations
trace9: Debug exception state save/restore operations.

spf

error: Mild errors.
trace0: List calls to ‘spf_eval_record’, ‘spf_test_record’, ‘spf_check_host_internal’, etc.
trace1: General debug info.
trace6: Explicitly list A records obtained when processing the ‘a’ SPF mechanism.

Categories starting with ‘bi_’ debug built-in modules:

bi_db

Database functions.

trace5: List database look-ups.
trace6: Trace operations on the greylisting database.

bi_sa

SpamAssassin and ClamAV API.

trace1: Report the findings of the ‘clamav’ function.
trace9: Trace payload in interactions with ‘spamd’.

bi_io

I/O functions.

trace1: Debug the following functions: open, spawn, write.
trace2: Report stderr redirection.
trace3: Report external commands being run.

bi_mbox

Mailbox functions.

trace1: Report opened mailboxes.

bi_other

Other built-ins.

trace1: Report results of checks for existence of usernames.

For example, the following invocation enables levels up to ‘trace2’ in category ‘engine’, all levels in category ‘savsrv’ and levels up to ‘trace0’ in category ‘srvman’:

$ mailfromd --debug='engine.trace2;savsrv;srvman.trace0'

You need to have sufficient knowledge about mailfromd internal structure to use this form of the --debug option.

To control the execution of the sender verification functions (see SMTP Callout functions), you may use --transcript (-X) command line option which enables transcripts of SMTP sessions in the logs. Here is an example of the output produced running mailfromd --transcript:

k8DHxlCa001774: RECV: 220 spf-jail1.us4.outblaze.com ESMTP Postfix
k8DHxlCa001774: SEND: HELO mail.gnu.org.ua
k8DHxlCa001774: RECV: 250 spf-jail1.us4.outblaze.com
k8DHxlCa001774: SEND: MAIL FROM: <>
k8DHxlCa001774: RECV: 250 Ok
k8DHxlCa001774: SEND: RCPT TO: <t1Kmx17Q@malaysia.net>
k8DHxlCa001774: RECV: 550 <>: No thank you rejected: Account
 Unavailable: Possible Forgery
k8DHxlCa001774: poll exited with status: not_found; sent
 "RCPT TO: <t1Kmx17Q@malaysia.net>", got "550 <>: No thank you
 rejected: Account Unavailable: Possible Forgery"
k8DHxlCa001774: SEND: QUIT