Differences

This shows you the differences between two versions of the page.

Link to this comparison view

Next revision
Previous revision
current:logging [2015/01/13 15:54]
sj created
current:logging [2015/01/14 12:48]
sj
Line 6: Line 6:
 Normally (verbosity=1) clapf logs a single line, eg. Normally (verbosity=1) clapf logs a single line, eg.
  
-''​Sep 11 16:16:35 thorium clapf[28688]:​ 4aaa5bc2e143b68ed701d8833be296: ​sj@acts.hu got SPAM1.0002378, relay=127.0.0.1:​10026,​ delay=0.12, delays=0.01/​0.01/​0.00/​0.00/​0.00/​0.02/0.00/0.04/0.00/0.05, status=250 2.0.0 Ok: queued as 5597A17021 +''​Sep 11 16:16:35 thorium clapf[28688]:​ 4aaa5bc2e143b68ed701d8833be296: ​from=Sonia.Qian2w@gmail.comto=user@yourdomain.comresult=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| |4aaa5bc2e143b68ed701d8833be296 |clapf queue identifier|
-|sj@acts.hu |recipient ​address| +|from=Sonia.Qian2w@gmail.com  ​sender ​address| 
-|got SPAM |the recipient ​got a spam email+|to=user@yourdomain.com |recipient ​address
-|1.0000 |probabilty ​of the message| +|result=SPAM/​0.9991 |the result of the spam check, and the probability ​of the message| 
-|2378 |message size in bytes|+|size=7626 |message size in bytes
 +|attachments=0 ​ |number of attached files|
 |relay=127.0.0.1:​10026 |next hop| |relay=127.0.0.1:​10026 |next hop|
-|delay=0.12 |overall processing time in seconds| +|delay=0.25 |overall processing time in seconds| 
-|delays=0.01/0.01/​0.01/​0.00/​0.00/​0.00/​0.02/0.00/0.04/0.00/0.05 |how much time (in seconds) clapf spent in the various phases| +|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 5597A17021 |answer of the next hop|+|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 The delays=a/​b/​c/​d/​e/​f/​g/​h/​i/​j/​k field consists of the following parts
Line 30: Line 30:
 |h:​ |training| |h:​ |training|
 |i: |token update| |i: |token update|
-|j: |message ​store|+|j: |history ​store|
 |k: |smtp conversation with the next hop| |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 killall -HUP clapf to get a deep insight what clapf does under the hood.+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 ===== ===== Detailed logging =====
  
-If you set verbosity=5,​ then clapf emits lots of syslog entries:+If you set verbosity=5,​ then clapf emits lots of syslog entries ​about what it does.
  
-The usual postfix stuff: 
  
-<​code>​ 
-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] 
-</​code>​ 
- 
-Ok, clapf starts with a fork(): 
- 
-<​code>​ 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ fork() 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ sent: 220 av-engine.localhost LMTP^M ​ 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ got: LHLO mail.aaaa.fu 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ sent: 250-av-engine.localhost^M 250-PIPELINING^M ​ 
-250-SIZE^M 250-8BITMIME^M 250 XFORWARD NAME ADDR PROTO HELO^M 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ got: XFORWARD NAME=1.2.3.4-dsl.aaa.fu ADDR=192.168.11.22 
-</​code>​ 
- 
-If you have zombie protection enabled and postfix sends the XFORWARD data: 
- 
-<​code>​ 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ zombie check: - [15] NAME=1.2.3.4-dsl.aaa.fu ​ 
-ADDR=192.168.11.22 in 45 us 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ client address: 192.168.11.22 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ got: XFORWARD PROTO=ESMTP HELO=1.2.3.4-dsl.aaa.fu 
-</​code>​ 
- 
-Go on with the SMTP conversation:​ 
- 
-<​code>​ 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ got: MAIL FROM:<​sj@1.2.3.4-dsl.aaa.fu>​ SIZE=917 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ got: RCPT TO:<​sj@acts.hu>​ 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ got: DATA 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ sent: 250 Ok^M 250 Ok^M 250 Ok^M 250 Ok^M 354 Send  
-mail data; end it with <​CRLF>​.<​CRLF>​^M ​ 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ period: *QUIT^M * 
-</​code>​ 
- 
-Got the period (.) command, so clapf can process the email 
- 
-<​code>​ 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ got: (.) 
-</​code>​ 
- 
-Let's pass it the the antivirus scanner, it seems that it's clear 
- 
-<​code>​ 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ trying to pass to CLAMD 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ CLAMD CMD: SCAN /​var/​spool/​clapf 
-/​tmp/​4bcff551fafb8fa422be146cf03dae^M ​ 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ CLAMD DEBUG: 56 /​var/​spool/​clapf 
-/​tmp/​4bcff551fafb8fa422be146cf03dae:​ OK 
-</​code>​ 
- 
-Let's deal with the first recipient: 
- 
-<​code>​ 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ round 0 in injection 
-</​code>​ 
- 
-If you have memcached support, it tries to query the user data and the policy settings: 
- 
-<​code>​ 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ memcached user query=_c:​sj@acts.hu, ​ 
-data=1000:​sj:​acts.hu:​1 (17) 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ memcached parsed user data: uid: 1000, name: sj,  
-domain: acts.hu, policy group: 1 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ memcached policy query=_c:1, data=0:​1:​1: ​ 
-:​1:​65535:::​0.9200:​1.0100:​1:​5:​1:​1:​1:​1:​1:​0:​1:​0:​0 (53) 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ memcached parsed policy data: spam limit: 0.9200, ​ 
-oblivion: 1.0100, subject prefix: * *, rbl: **, training mode: 1, meta: 1 
-</​code>​ 
- 
-If you have whitelist enabled: 
- 
-<​code>​ 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ sql: SELECT whitelist FROM t_white_list WHERE uid=0 OR 
- ​uid=1000 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ whitelist: @partners.zzz.com$^M no-reply@xxxx.com$ 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ matching @partners.zzz.com$ on sj@1.2.3.4-dsl.aaa.fu 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ matching no-reply@xxxx.com$ on sj@1.2.3.4-dsl.aaa.fu 
-</​code>​ 
- 
-Let's do the Bayesian spam check: 
- 
-<​code>​ 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ running Bayesian test 
-</​code>​ 
- 
-then update the timestamp of the tokens (unless update_tokens=0) 
- 
-<​code>​ 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ updated 24/34 tokens 
-</​code>​ 
- 
-Save the email to the user's queue directory (if you have compiled clapf with --with-store=...) 
- 
-<​code>​ 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ saving to queue: /​var/​lib/​clapf/​queue/​acts.hu 
-/​s/​sj/​h.4bcff551fafb8fa422be146cf03dae 
-</​code>​ 
- 
-Ok, we are ready to pass the email back to postfix (to 127.0.0.1:​10026/​tcp):​ 
- 
-<​code>​ 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ trying to inject back 
-Apr 22 09:05:53 myhost postfix/​smtpd[2583]:​ connect from localhost[127.0.0.1] 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ got in injecting: 220 mail.aaaa.fu ESMTP Don't spam 
- or die^M  
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ sent in injecting: EHLO av-engine.localhost^M ​ 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ got in injecting: 250-mail.aaaa.fu^M 250-PIPELINING^M ​ 
-250-SIZE 15000000^M 250-ETRN^M 250-XFORWARD NAME ADDR PROTO HELO SOURCE^M 250-ENHANCEDSTATUSCODES^M 250-8BITMIME^M 250 DSN^M  
-Apr 22 09:05:53 myhost postfix/​smtpd[2583]:​ A468D14022: client=1.2.3.4-dsl.aaa.fu[192.168.11.22] 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ sent in injecting: XFORWARD NAME=1.2.3.4-dsl.aaa.fu ​ 
-ADDR=192.168.11.22^M XFORWARD PROTO=ESMTP HELO=1.2.3.4-dsl.aaa.fu^M MAIL FROM:<​sj@1.2.3.4-dsl.aaa.fu>​ SIZE=917^M RCPT 
- ​TO:<​sj@acts.hu>​^M DATA^M ​ 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ got in injecting: 250 2.0.0 Ok^M 250 2.0.0 Ok^M 250  
-2.1.0 Ok^M 250 2.1.5 Ok^M 354 End data with <​CR><​LF>​.<​CR><​LF>​^M ​ 
-Apr 22 09:05:53 myhost postfix/​cleanup[2577]:​ A468D14022: message-id=<​20100422070553.5E458207A63@1.2.3.4-dsl.aaa.fu>​ 
-Apr 22 09:05:53 myhost postfix/​qmgr[2942]:​ A468D14022: from=<​sj@1.2.3.4-dsl.aaa.fu>,​ size=1122, nrcpt=1 (queue active) 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ got in injecting: 250 2.0.0 Ok: queued as A468D14022^M ​ 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ sent in injecting: QUIT 
-</​code>​ 
- 
-We are done with injecting, let's pass a response to the "​."​ command back to the first postfix instance: 
- 
-<​code>​ 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ sent: 250 Ok 4bcff551fafb8fa422be146cf03dae <​sj@acts.hu>​^M ​ 
-</​code>​ 
- 
-Syslog some clapf statistics: 
- 
-<​code>​ 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ sj@acts.hu got HAM, 0.0653, 920,  relay=127.0.0.1:​10026,​ 
-delay=0.07, delays=0.00/​0.00/​0.00/​0.00/​0.00/​0.00/​0.00/​0.00/​0.01/​0.00/​0.05,​ status=250 2.0.0 Ok: queued as A468D14022 
-</​code>​ 
- 
-Finish the L/SMTP conversation with the first postfix instance: 
- 
-<​code>​ 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ got: QUIT 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ sent: 221 av-engine.localhost Goodbye^M ​ 
-</​code>​ 
- 
-Log the fact that clapf has removed the file from its own ../tmp directory: 
- 
-<​code>​ 
-Apr 22 09:05:53 myhost clapf[2579]:​ 4bcff551fafb8fa422be146cf03dae:​ removed 
-</​code>​ 
- 
-The first postfix instance also has some info to syslog: 
- 
-<​code>​ 
-Apr 22 09:05:53 myhost postfix/​lmtp[2578]:​ 9C02D17022: to=<​sj@acts.hu>,​ relay=127.0.0.1[127.0.0.1]:​10025,​ delay=0.08, ​ 
-delays=0.01/​0/​0.01/​0.07,​ dsn=2.0.0, status=sent (250 Ok 4bcff551fafb8fa422be146cf03dae <​sj@acts.hu>​) 
-</​code>​ 
- 
-The fork()'​ed clapf process has finished, time to say goodbye: 
- 
-<​code>​ 
-Apr 22 09:05:53 myhost clapf[2579]:​ child has finished 
-Apr 22 09:05:53 myhost clapf[2579]:​ processed 1 messages 
-</​code>​ 
- 
-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=<​sj@mail.aaaa.fu>,​ orig_to=<​sj@acts.hu>,​ 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 
-</​code>​