Consulting djbware Publications

12. Logging

s/qmail follows qmail attitude to use entirely Unix file discriptors for logging. Thus, it does not possess any network capabilities to feed a remote SYSLOG server, rather additional programs are required to do so.

The purpose of logging is to provide:

From here, you can get

However,

s/qmail uses different logging schemes:

  1. qmail-send feeds the queue whether invoked by qmail-local or qmail-remote and uses the standard qmail format.
  2. The servers qmail-smtpd and qmail-pop3d use SPAMCONTROLS's logging message format.
  3. The servers qmail-qmtpd and qmail-qmqpd act 'logging-free', thus any logging is provided by means of tcpserver and sslserver only.

Quick links:

12.1 s/qmail logging strategies

If you run a MTA, it is your responsibility to care for its performance.

You also need to care about successful and unsuccessful delivieries. Both on an statistical manner but probably more importent using some kind of on-line monitoring and alarming.

s/qmail's log help you to do this task, but given a busy system you need to setup your own procedures. DJB's multilog is still the best choice. systemds journald is ok for small traffic but IMHO not targeted for application logging.

12.2 qmail-send

The qmail-send's logging uses the following tokens:

The qmail-send log also provides the delivery channel and the number of used/possible delivery instances:

A service generic multilog run script is provided. Use the respective qmail-smtpd run script for feeding the log.

2018-01-01 20:51:03.121918500 info msg 28857444: bytes 7816 from <feh@fehcom.de> qp 17808 uid 7005 2018-01-01 20:51:03.121920500 starting delivery 1356: msg 28857444 to remote x@y.de 2018-01-01 20:51:03.121922500 status: local 1/10 remote 1/100 2018-01-01 20:51:03.714440500 delivery 1356: success: 1.2.3.4_TLS_transmitted_message_accepted./Remote_host_said:_250_OK_id=1eW731-0004n7-G7/ 2018-01-01 20:51:03.714444500 status: local 1/10 remote 0/100 2018-01-01 20:51:03.714446500 end msg 28857444

Note: Given the many qmail-remote and qmail-local instances running concurrently and the monotone written log by means of multilog, mail transactions don't usually appear contiguous, but rather are splited over many lines and perhaps several qmail-send log files.

12.3 qmail-smtpd

Normally, qmail-smtpd doesn't log anything. Within s/qmail, qmail-smtpd logs some accepted and some (important) rejected SMTP session attempts.

In order to track a complete SMTP transaction (including tcpserver/sslserver + rblsmtpd) the log line includes the PID.

Caveats: Regarding ssslserver and its capabilities, not always the same PID is referenced in the logs for the same transaction.

ActionTypeConditionExplanation
RejectAUTHmissingAUTHentication missing
Reject AUTHtypeAUTHentication of 'type' rejected
RejectAuthMethAUTHentication Method rejected
AcceptAUTHtypeAUTHentication of 'type' accepted
RejectDATAInvalid_SizeDATA exceeds sizelimit
RejectDATABad_MIME DATA includes BASE 64 MIME type listed in badmimetypes
RejectDATABad_LoaderDATA includes BASE64 loader type listed in badmimetypes
RejectDATAVirus_InfectedDATA includes virus infected message (<scanner> | 'AV scanner')
RejectDATASpam_MessageDATA includes an identified Spam message
RejectORIGBad_MailfromORIG is in badmailfrom
RejectORIGDNS_MFDomain part of ORIG has no DNS MX RR
RejectORIG Failed_AuthORIG tried SMTP Authentication; but failed
RejectORIGRequire_AuthSMTP Authentication required; but not granted
RejectORIGInvalid_SenderORIG not allowed to send
RejectORIGMissing_AuthSMTP Authentication required, but not granted
RejectORIGSPFORIG was rejected due to failed SPF permissions
AcceptORIGLocal_SenderORIG was identified as local sender address
AcceptORIGRelay_MailfromORIG was accepted als Relaymailfrom
RejectRCPTBad_RcpttoRCPT is in badrcptto
RejectRCPTToomany_RcpttoToo many RCPTs
RejectRCPTFailed_RcpttoRCPT could not acceptd as per recipients/cdb
AcceptRCPTRecipients_CdbRCPT was accepted as per recipients/cdb
AcceptRCPTRecipients_PamRCPT was accepted as per recipients/pam plug-in
AcceptRCPTRecipients_WildRCPT was accepted as per recipients/wildlisting
AcceptRCPTRcpthosts_Rcptto CPT was accepted as per rcpthosts/morercpthosts
RejectSNDRBad_HeloSNDR's HELO is in the badhelo
RejectSNDRDNS_HELOSNDR's HELO has no DNS A RR
RejectSNDRInvalid_RelaySNDR's tries relaying; but not allowd
AcceptSNDRRelay_ClientSNDR was identified as relay client
RejectTLSmissingTLS connection could not be established
AcceptSPFRecipients_CdbORIG was authorized and RCPT accepted as per recipients/cdb
AcceptSPFRecipients_PamORIG was authorized and RCPT accepted as per recipients/pam plug-in
AcceptSPFRecipients_WildORIG was authorized and RCPT was accepted as per recipients/wildlisting
AcceptSPFRcpthosts_RcpttoORIG was authorized and RCPT was accepted as per rcpthosts/morercpthosts
RejectSPFFailORIG authorization failed per SPF
DeferredSNDRGrey_ListedGreylisted sender based on IP/Hostname/Mail From/Rcpt To

The Information is typically constructed from the SMTP envelope like:

This scheme is easy extendable to other successful/deferred SMTP sessions.

Sample for a successful qmail-smtpd session:

@400000005a49ba05197af10c sslserver: pid 30556 from 1.2.3.4 @400000005a49ba0625ce69d4 sslserver: ok 30556 mail.fehcom.de:85.25.149.179:25 mail40.ml.mailersend.com:1.2.3.4::44176 @400000005a49ba341995a114 sslserver: ssl 30554 accept TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 @400000005a49ba341eefa7a4 qmail-smtpd: pid 30554 Accept::RCPT::Recipients_Pam P:ESMTPS S:1.2.3.4:mail16.maila.com H:maila.com F:bounce-c8s3-794521509891671878@ml.maila.com T:feh@fehcom.de @400000005a49ba34303796fc sslserver: ended by 30553 status 0

Sample for a rejected qmail-smtpd session:

@400000005a4a3ed73b21e2d4 sslserver: pid 19782 from 153.149.230.39 @400000005a4a3ed80f2c9714 sslserver: ok 19782 mail.fehcom.de:85.25.149.179:25 mbkd0138.ocn.ad.jp:153.149.230.39::35970 @400000005a4a3ed80f391e1c rblsmtpd: 153.149.230.39 pid 19782: greetdelay: 80 @400000005a4a3f293a5eb9e4 qmail-smtpd: pid 19782 Reject::RCPT::Failed_Rcptto P:ESMTP S:153.149.230.39:mbkd0138.ocn.ad.jp H:mbkd0138.ocn.ad.jp F:www.@silk.ocn.ne.jp T:nelson-qa@aqmail.org @400000005a4a3f2a1f740a44 sslserver: ssl 19782 accept @400000005a4a3f2a1f79461c sslserver: ended by 19781 status 0

Note 1: Again here, the entire mail transactions may not be found in one contiguous block but rather dispersed; however ordered in monotonically in time.

Note 2: Though the PID for a single transactions is preserved, given sslserver the last statement always shows the parent PID.

Note 3: Here, and in the other logging samples, sslserver is invoked for logging with the argument sslserver -V displaying the mod_ssl variables while showing the TLS Cipher Suite.

12.4 qmail-qmtpd

Starting with s/qmail 4.3 qmail-qmtpd does a minimal logging while acknowleding the received email. Together with sslserver the following log entries may be given in case of a successful transaction:

sslserver: pid 250262 from 91.20.35.221 sslserver: ok 250262 india167:0.0.0.0:6209 p5b1423dd.dip0.t-ipconnect.de:91.20.35.221::59537 sslserver: info: valid client cert received from: 91.20.35.221 for pid: 250260 sslserver: tls 250260 accept TLSv1.3:TLS_CHACHA20_POLY1305_SHA256 qmail-qmtpd: pid 250260 done.

qmail-qmtpd will do a logging in the following failure cases:

With s/qmail 4.3 some minimal logging is added:

12.5 qmail-qmqpd

Currently, qmail-qmqpd does not do any logging. Use tcpserver and its logging capabilities.

12.6 qmail-pop3d

In addition for POP3 services the qmail-smtpd scheme is used; but now logging takes place on FD 5.

qmail-pop3d does not do any logging. Use this run script to generate a logging of the Auth information provided by qmail-popup.

Sample for an accepted qmail-pop3d session:

2018-01-03 23:42:01.457744500 sslserver: status: 1/10 2018-01-03 23:42:01.458364500 sslserver: pid 26120 from 91.20.45.91 2018-01-03 23:42:01.458785500 sslserver: ok 26120 mail.fehcom.net:85.25.149.179:995 p5b142d5b.dip0.t-ipconnect.de:91.20.45.91::62745 2018-01-03 23:42:02.139181500 sslserver: ssl 26120 accept TLSv1.2:ECDHE-RSA-AES256-GCM-SHA384 2018-01-03 23:42:03.206953500 qmail-popup: pid 26120 Accept::AUTH::User P:POP3S S:91.20.45.91:p5b142d5b.dip0.t-ipconnect.de ?~ 'X@fehcom.de' 2018-01-03 23:42:03.298624500 sslserver: ended by 26119 status 256 2018-01-03 23:42:03.298627500 sslserver: status: 0/10

12.7 qmail-mrtg

qmail-mrtg is used to evaluate the log activity information provided by

showing usage and ab-usage of those services while feeding the information to MRTG. Sample for the *.cfg files can be found in the etc installation directory of s/qmail.

Once MRTG is installed, the typical invocation includes the call of MRTG with the respective cfg by means of cron:

*/4 * * * * env LANG=C mrtg /etc/qmail-mrtg.send.cfg &>/dev/null */4 * * * * env LANG=C mrtg /etc/qmail-mrtg.smtpd.cfg &>/dev/null */4 * * * * env LANG=C mrtg /etc/qmail-mrtg.pop3d.cfg &>/dev/null

Here, the crontab is used to update the taken samples by means of qmail-mrtg following the configurations in the cfg files every four minutes. The default sample time is five minutes. Overlapping entries are detected. The evaluation time can be specified by qmail-mrtg.

Additionally to MRTG, the RDD tool can be used to 'beautify' the results. Customization is entirely free and the additionally a local Network Management tool can be used to further actions.

Note: In order to provide an efficient and most effective evaluation of the log files, their size and and revolution needs to be carefully adjusted with the qmail-mrtg timings. Though qmail-mrtg tries best to reduce system load regarding reading large log-files. The smaller the log-files, the more efficient the analysis becomes.

The MRTG statistics of my server is shown here: fehcom.de

12.8 Analysis qmail-send log files

s/qmail includes the qmailanalog package in in well-suited format. qmailanalog provides statistical and performance informations regarding

using the logging format of qmail-send.

You get (according to D.J. Bernstein):

  • overall: how many messages? recipients? attempts? etc.
  • ddist: how soon were 50% of the messages delivered? 90%? 95%? 99%?
  • rxdelay: what's the best order of recipients for mailing lists?
  • recipients, rhosts: who's getting mail? bytes? messages? attempts?
  • successes, failures, deferrals: why? how often? how much delay?
  • senders, suids: messages? bytes? load? recipients? attempts? delay?

mainly evaluated by awk and some small programs.

12.9 Newanalyse

Use Newanalyse together with multilog to ensure a persistant logging of s/qmail's activity, analysis and long-haule capture.

The purpose of Newanalyse is twofold:

Calling Newanalyse on daily base you get:

However, Newanalyse allows to delete logs after a certain time span in order to comply with privacy regulations, given the logs files are not backuped.