This is an old revision of the document!


Logging

Based on the verbosity level clapf syslog()s about its operation.

Normally (verbosity=1) clapf logs a single line, eg.

Sep 11 16:16:35 thorium clapf[28688]: 4aaa5bc2e143b68ed701d8833be296: from=Sonia.Qian2w@gmail.com, to=user@yourdomain.com, result=SPAM/0.9991, size=7626, attachments=0, relay=127.0.0.1:10026, delay=0.25, delays=0.00/0.07/0.01/0.00/0.00/0.00/0.10/0.00/0.00/0.00/0.07, status=250 2.0.0 Ok: queued as A90BC1D04C

4aaa5bc2e143b68ed701d8833be296 clapf queue identifier
from=Sonia.Qian2w@gmail.com sender address
to=user@yourdomain.com recipient address
result=SPAM/0.9991 the result of the spam check, and the probability of the message
size=7626 message size in bytes
attachments=0 number of attached files
relay=127.0.0.1:10026 next hop
delay=0.25 overall processing time in seconds
delays=0.00/0.07/0.01/0.00/0.00/0.00/0.10/0.00/0.00/0.00/0.07 how much time (in seconds) clapf spent in the various phases
status=250 2.0.0 Ok: queued as A90BC1D04C answer of the next hop

The delays=a/b/c/d/e/f/g/h/i/j/k field consists of the following parts

a: lmtp/smtp conversation needed to get the message from the MTA
b: message parsing
c: antivirus scanning
d: query user data
e: query policy settings
f: minefield query
g: statistical check
h: training
i: token update
j: history store
k: smtp conversation with the next hop

verbosity=1 is the recommended setting for normal operation. If you want to debug something set verbosity=5, then /etc/init.d/rc.clapf reload to get a deep insight what clapf does under the hood.

Detailed logging

If you set verbosity=5, then clapf emits lots of syslog entries:

The usual postfix stuff:

Apr 22 09:05:53 myhost postfix/smtpd[2574]: connect from 1.2.3.4-dsl.aaa.fu[192.168.11.22]
Apr 22 09:05:53 myhost postfix/smtpd[2574]: 9C02D17022: client=1.2.3.4-dsl.aaa.fu[192.168.11.22]
Apr 22 09:05:53 myhost postfix/cleanup[2577]: 9C02D17022: message-id=<20100422070553.5E458207A63@1.2.3.4-dsl.aaa.fu>
Apr 22 09:05:53 myhost postfix/qmgr[2942]: 9C02D17022: from=<sj@1.2.3.4-dsl.aaa.fu>, size=917, nrcpt=1 (queue active)
Apr 22 09:05:53 myhost postfix/smtpd[2574]: disconnect from 1.2.3.4-dsl.aaa.fu[192.168.11.22]

Ok, clapf starts with a fork():

Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: sent: 220 av-engine.localhost ESMTP^M 
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: got: LHLO thorium.datanet.hu
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: sent: 250-av-engine.localhost^M 250-PIPELINING^M 250-SIZE^M 250-8BITMIME^M 250 XFORWARD NAME ADDR PROTO HELO^M 
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: got: XFORWARD ADDR=113.162.63.107
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: smtp client xforward address: *113.162.63.107*
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: got: XFORWARD PROTO=ESMTP HELO=[113.162.63.107]
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: got: MAIL FROM:<cc9de2d2@sdhw.com> SIZE=1350 BODY=8BITMIME
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: got: RCPT TO:<user@yourdomain.com>
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: we trapped user@yourdomain.com on the blackhole
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: got: DATA
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: sent: 250 Ok^M 250 Ok^M 250 Ok^M 250 Ok^M 354 Send mail data; end it with <CRLF>.<CRLF>^M 
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: period found
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: got: (.)
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: parsed message
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: CLAMD CMD: SCAN /var/clapf/tmp/4000000054b5ad8b17aa096c00d1ccd722a9^M 
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: CLAMD DEBUG: 56 /var/clapf/tmp/4000000054b5ad8b17aa096c00d1ccd722a9: OK 
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: done virus scanning
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: round 0 in injection
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: query user data for user@yourdomain.com
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: query user data for @yourdomain.com
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: 113.162.63.107 is trapped on minefield
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: zombie check: - [19] 
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: running statistical test
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: updated 69/156 tokens
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: trying to inject back
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: got in injecting: 220 thorium.datanet.hu ESMTP spam is not welcome / spamet kuldeni tilos!^M 
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: sent in injecting: EHLO av-engine.localhost^M 
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: got in injecting: 250-thorium.datanet.hu^M 250-PIPELINING^M 250-SIZE 15000000^M 250-ETRN^M 250-STARTTLS^M 250-XFORWARD NAME ADDR PROTO HELO SOURCE PORT IDENT^M 250-ENHANCEDSTATUSCODES^M 250-8BITMIME^M 250 DSN^M 
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: sent in injecting: MAIL FROM:<cc9de2d2@sdhw.com> SIZE=1350 BODY=8BITMIME^M RCPT TO: <user@yourdomain.com>^M DATA^M 
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: got in injecting: 250 2.1.0 Ok^M 250 2.1.5 Ok^M 354 End data with <CR><LF>.<CR><LF>^M 
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: got in injecting: 250 2.0.0 Ok: queued as 706AA48050^M 
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: sent in injecting: QUIT
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: sent: 250 Ok 4000000054b5ad8b17aa096c00d1ccd722a9 <user@yourdomain.com>^M 
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: from=cc9de2d2@sdhw.com, to=user@yourdomain.com, result=SPAM/1.0000, size=1348, attachments=0, relay=127.0.0.1:10026, delay=0.10, delays=0.00/0.00/0.00/0.00/0.00/0.00/0.02/0.00/0.02/0.00/0.05, status=250 2.0.0 Ok: queued as 706AA48050
Jan 14 00:42:57 thorium postfix/lmtp[18949]: 5EC404804F: to=<user@yourdomain.com>, relay=127.0.0.1[127.0.0.1]:10025, delay=0.12, delays=0.01/0.01/0/0.1, dsn=2.0.0, status=sent (250 Ok 4000000054b5ad8b17aa096c00d1ccd722a9 <user@yourdomain.com>)
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: saving to queue: /var/clapf/queue/00/22/a9/4000000054b5ad8b17aa096c00d1ccd722a9
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: got: QUIT
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: removed
Jan 14 00:42:57 thorium clapf[13867]: 4000000054b5ad8b17aa096c00d1ccd722a9: sent: 221 av-engine.localhost Goodbye^M 




The second postfix instance syslog()'s, too:

<code>
Apr 22 09:05:53 myhost postfix/qmgr[2942]: 9C02D17022: removed
Apr 22 09:05:53 myhost postfix/smtpd[2583]: disconnect from localhost[127.0.0.1]
Apr 22 09:05:53 myhost postfix/local[2584]: A468D14022: to=<user@yourdomain.com>, relay=local, 
delay=0.08, delays=0.04/0.01/0/0.03, dsn=2.0.0, status=sent (delivered to command: /usr/local/bin/maildrop)
Apr 22 09:05:53 myhost postfix/qmgr[2942]: A468D14022: removed