Postmaster wrote:
On 01/04/2010 20:03, Eric Shubert wrote:
Can you find the smtp log messages that correspond to the first
receipt of a duplicated message?
Will you post a bit of your spamd log? That might give some sort of
indication.
Given that this is a virtual host, it's a bit hard to make a
knowledgeable recommendation for improving performance. Is your host
paging at all? I'm not familiar at all with Linode VPS. Can you fill
us in on that environment? (what type of virtualization, etc)
Ok, another duplicated message today, from the header:
Received: by simscan 1.4.0 ppid: 32077, pid: 32078, t: 64.1936s
scanners: attach: 1.4.0 clamav: 0.95.3/m:52/d:10688 spam: 3.2.5
64.19 seconds to scan - sounds very long to me.
Yeah, that one's long. Can you find out how big this message was?
From SMTP log:
The first receipt of a message
2010-04-02 15:46:24.801712500 tcpserver: pid 32076 from 195.222.187.12
2010-04-02 15:46:24.801837500 tcpserver: ok 32076
xxxxxxxxxx.uk:109.74.205.xx:25 :195.222.187.12::33377
2010-04-02 15:46:24.882010500 spamdyke[32076]:
DEBUG(filter_rdns_missing()@filter.c:848): checking for missing rDNS; rdns:
mail07.odnoklassniki.ru
2010-04-02 15:46:24.882109500 spamdyke[32076]:
DEBUG(filter_rdns_whitelist_file()@filter.c:956): searching rDNS whitelist
file(s); rdns: mail07.odnoklassniki.ru
2010-04-02 15:46:24.882253500 spamdyke[32076]:
DEBUG(filter_rdns_blacklist_file()@filter.c:1059): searching rDNS blacklist
file(s); rdns: mail07.odnoklassniki.ru
2010-04-02 15:46:24.882391500 spamdyke[32076]:
DEBUG(filter_ip_whitelist()@filter.c:1127): searching IP whitelist file(s); ip:
195.222.187.12
2010-04-02 15:46:24.882573500 spamdyke[32076]:
DEBUG(filter_ip_blacklist()@filter.c:1177): searching IP blacklist file(s); ip:
195.222.187.12
2010-04-02 15:46:24.882702500 spamdyke[32076]:
DEBUG(filter_ip_in_rdns_whitelist()@filter.c:1272): checking for IP in rDNS
+keyword(s) in whitelist file; ip: 195.222.187.12 rdns: mail07.odnoklassniki.ru
2010-04-02 15:46:24.882796500 spamdyke[32076]:
DEBUG(filter_ip_in_rdns_blacklist()@filter.c:1226): checking for IP in rDNS
+keyword(s) in blacklist file; ip: 195.222.187.12 rdns: mail07.odnoklassniki.ru
2010-04-02 15:46:24.882852500 spamdyke[32076]:
DEBUG(filter_rdns_resolve()@filter.c:1318): checking rDNS resolution; rdns:
mail07.odnoklassniki.ru
2010-04-02 15:46:24.951669500 spamdyke[32076]:
DEBUG(filter_dns_rbl()@filter.c:1527): checking DNS RBL(s); ip: 195.222.187.12
2010-04-02 15:46:24.965085500 spamdyke[32076]:
DEBUG(filter_earlytalker()@filter.c:1695): checking for earlytalker; delay: 5
2010-04-02 15:46:30.216776500 spamdyke[32076]:
DEBUG(filter_sender_whitelist()@filter.c:1747): searching sender whitelist(s);
sender: bezotv...@odnoklassniki.ru
2010-04-02 15:46:30.217293500 spamdyke[32076]:
DEBUG(filter_sender_blacklist()@filter.c:1881): searching sender blacklist(s);
sender: bezotv...@odnoklassniki.ru
2010-04-02 15:46:30.227601500 spamdyke[32076]:
DEBUG(filter_sender_no_mx()@filter.c:2080): checking for sender domain MX
record; domain: odnoklassniki.ru
2010-04-02 15:46:30.288520500 CHKUSER accepted sender: from <bezotv...@odnoklassniki.ru::>
remote <mail07.odnoklassniki.ru:unknown:195.222.187.12> rcpt <> : sender accepted
2010-04-02 15:46:30.342820500 spamdyke[32076]:
DEBUG(filter_recipient_whitelist()@filter.c:2113): searching recipient
whitelist(s); recipient: alexan...@xxxxxxxxxx.uk
2010-04-02 15:46:30.342937500 spamdyke[32076]:
DEBUG(filter_recipient_relay()@filter.c:2183): checking relaying; relay-level:
0 recipient: alexan...@xxxxxxxxxx.uk ip: 195.222.187.12 rdns:
mail07.odnoklassniki.ru local_recipient: true relaying_allowed: false
2010-04-02 15:46:30.343023500 spamdyke[32076]:
DEBUG(filter_recipient_local()@filter.c:2154): checking for unqualified
recipient; recipient: alexan...@xxxxxxxxxx.uk
2010-04-02 15:46:30.343107500 spamdyke[32076]:
DEBUG(filter_recipient_max()@filter.c:2244): checking maximum recipients;
maximum: 50 current: 0
2010-04-02 15:46:30.343190500 spamdyke[32076]:
DEBUG(filter_recipient_blacklist()@filter.c:2278): searching recipient
blacklist(s); recipient: alexan...@xxxxxxxxxx.uk
2010-04-02 15:46:30.357374500 spamdyke[32076]:
DEBUG(filter_recipient_graylist()@filter.c:2342): checking graylist; recipient:
alexan...@xxxxxxxxxx.uk sender: bezotv...@odnoklassniki.ru
2010-04-02 15:46:30.404446500 CHKUSER accepted rcpt: from <bezotv...@odnoklassniki.ru::>
remote <mail07.odnoklassniki.ru:unknown:195.222.187.12> rcpt
<alexan...@xxxxxxxxxx.uk> : found existing recipient
2010-04-02 15:46:30.404449500 policy_check: remote bezotv...@odnoklassniki.ru
-> local alexan...@xxxxxxxxxx.uk (UNAUTHENTICATED SENDER)
2010-04-02 15:46:30.404451500 policy_check: policy allows transmission
2010-04-02 15:46:30.404452500 spamdyke[32076]: ALLOWED from:
bezotv...@odnoklassniki.ru to: alexan...@xxxxxxxxxx.uk origin_ip:
195.222.187.12 origin_rdns: mail07.odnoklassniki.ru auth: (unknown)
2010-04-02 15:47:21.317362500 tcpserver: ok 32112 xxxxxxxxxx.uk:127.0.0.1:25
:127.0.0.1::52381
2010-04-02 15:47:21.333530500 spamdyke[32112]:
DEBUG(filter_rdns_missing()@filter.c:848): checking for missing rDNS; rdns:
localhost
2010-04-02 15:47:21.333626500 spamdyke[32112]:
DEBUG(filter_rdns_whitelist_file()@filter.c:956): searching rDNS whitelist
file(s); rdns: localhost
2010-04-02 15:47:21.342533500 spamdyke[32112]:
DEBUG(filter_rdns_blacklist_file()@filter.c:1059): searching rDNS blacklist
file(s); rdns: localhost
2010-04-02 15:47:21.342588500 spamdyke[32112]:
DEBUG(filter_ip_whitelist()@filter.c:1127): searching IP whitelist file(s); ip:
127.0.0.1
2010-04-02 15:47:21.350848500 spamdyke[32112]: FILTER_WHITELIST_IP ip:
127.0.0.1 file: /etc/spamdyke/whitelist_ip(1)
2010-04-02 15:47:21.442125500 tcpserver: end 32112 status 0
2010-04-02 15:47:21.442158500 tcpserver: status: 1/100
This is where is times out!
2010-04-02 15:47:31.086705500 spamdyke[32076]: TIMEOUT from:
bezotv...@odnoklassniki.ru to: alexan...@xxxxxxxxxx.uk origin_ip:
195.222.187.12 origin_rdns: mail07.odnoklassniki.ru auth: (unknown) reason:
TIMEOUT
2010-04-02 15:47:33.592357500 tcpserver: status: 2/100
2010-04-02 15:47:34.589170500 simscan:[32077]:CLEAN
(3.20/12.00):64.1667s:=?KOI8-R?Q?Odnoklassniki.ru__?=:195.222.187.12:bezotv...@odnoklassniki.ru:alexan...@xxxxxxxxxx.uk
2010-04-02 15:47:38.606549500 tcpserver: end 32076 status 0
2010-04-02 15:47:38.606594500 tcpserver: status: 1/100
Looks like spamdyke is timing it out, after 60 seconds.
The second message:
2010-04-02 15:47:38.606659500 tcpserver: pid 32122 from 208.79.240.2
2010-04-02 15:47:38.700322500 tcpserver: ok 32122
xxxxxxxxxx.uk:109.74.205.xx:25 :208.79.240.2::47802
2010-04-02 15:47:39.310517500 spamdyke[32122]:
DEBUG(filter_rdns_missing()@filter.c:848): checking for missing rDNS; rdns:
mail.rollernet.us
2010-04-02 15:47:39.310623500 spamdyke[32122]:
DEBUG(filter_rdns_whitelist_file()@filter.c:956): searching rDNS whitelist
file(s); rdns: mail.rollernet.us
2010-04-02 15:47:39.310758500 spamdyke[32122]:
DEBUG(filter_rdns_blacklist_file()@filter.c:1059): searching rDNS blacklist
file(s); rdns: mail.rollernet.us
2010-04-02 15:47:39.310861500 spamdyke[32122]:
DEBUG(filter_ip_whitelist()@filter.c:1127): searching IP whitelist file(s); ip:
208.79.240.2
2010-04-02 15:47:39.317852500 spamdyke[32122]:
DEBUG(filter_ip_blacklist()@filter.c:1177): searching IP blacklist file(s); ip:
208.79.240.2
2010-04-02 15:47:39.317964500 spamdyke[32122]:
DEBUG(filter_ip_in_rdns_whitelist()@filter.c:1272): checking for IP in rDNS
+keyword(s) in whitelist file; ip: 208.79.240.2 rdns: mail.rollernet.us
2010-04-02 15:47:39.318131500 spamdyke[32122]:
DEBUG(filter_ip_in_rdns_blacklist()@filter.c:1226): checking for IP in rDNS
+keyword(s) in blacklist file; ip: 208.79.240.2 rdns: mail.rollernet.us
2010-04-02 15:47:39.318199500 spamdyke[32122]:
DEBUG(filter_rdns_resolve()@filter.c:1318): checking rDNS resolution; rdns:
mail.rollernet.us
2010-04-02 15:47:39.510203500 spamdyke[32122]:
DEBUG(filter_dns_rbl()@filter.c:1527): checking DNS RBL(s); ip: 208.79.240.2
2010-04-02 15:47:39.629926500 spamdyke[32122]:
DEBUG(filter_earlytalker()@filter.c:1695): checking for earlytalker; delay: 5
2010-04-02 15:47:45.999601500 spamdyke[32122]:
DEBUG(filter_sender_whitelist()@filter.c:1747): searching sender whitelist(s);
sender: bezotv...@odnoklassniki.ru
2010-04-02 15:47:46.010459500 spamdyke[32122]:
DEBUG(filter_sender_blacklist()@filter.c:1881): searching sender blacklist(s);
sender: bezotv...@odnoklassniki.ru
2010-04-02 15:47:46.013598500 spamdyke[32122]:
DEBUG(filter_sender_no_mx()@filter.c:2080): checking for sender domain MX
record; domain: odnoklassniki.ru
2010-04-02 15:47:46.015396500 CHKUSER accepted sender: from <bezotv...@odnoklassniki.ru::>
remote <mail.rollernet.us:unknown:208.79.240.2> rcpt <> : sender accepted
2010-04-02 15:47:46.016148500 spamdyke[32122]:
DEBUG(filter_recipient_whitelist()@filter.c:2113): searching recipient
whitelist(s); recipient: alexan...@xxxxxxxxxx.uk
2010-04-02 15:47:46.016244500 spamdyke[32122]:
DEBUG(filter_recipient_relay()@filter.c:2183): checking relaying; relay-level:
0 recipient: alexan...@xxxxxxxxxx.uk ip: 208.79.240.2 rdns: mail.rollernet.us
local_recipient: true relaying_allowed: false
2010-04-02 15:47:46.016305500 spamdyke[32122]:
DEBUG(filter_recipient_local()@filter.c:2154): checking for unqualified
recipient; recipient: alexan...@xxxxxxxxxx.uk
2010-04-02 15:47:46.016376500 spamdyke[32122]:
DEBUG(filter_recipient_max()@filter.c:2244): checking maximum recipients;
maximum: 50 current: 0
2010-04-02 15:47:46.016480500 spamdyke[32122]:
DEBUG(filter_recipient_blacklist()@filter.c:2278): searching recipient
blacklist(s); recipient: alexan...@xxxxxxxxxx.uk
2010-04-02 15:47:46.027100500 spamdyke[32122]:
DEBUG(filter_recipient_graylist()@filter.c:2342): checking graylist; recipient:
alexan...@xxxxxxxxxx.uk sender: bezotv...@odnoklassniki.ru
2010-04-02 15:47:46.063764500 CHKUSER accepted rcpt: from <bezotv...@odnoklassniki.ru::>
remote <mail.rollernet.us:unknown:208.79.240.2> rcpt <alexan...@xxxxxxxxxx.uk> :
found existing recipient
2010-04-02 15:47:46.064413500 policy_check: remote bezotv...@odnoklassniki.ru
-> local alexan...@xxxxxxxxxx.uk (UNAUTHENTICATED SENDER)
2010-04-02 15:47:46.064439500 policy_check: policy allows transmission
2010-04-02 15:47:46.064546500 spamdyke[32122]: ALLOWED from:
bezotv...@odnoklassniki.ru to: alexan...@xxxxxxxxxx.uk origin_ip: 208.79.240.2
origin_rdns: mail.rollernet.us auth: (unknown)
2010-04-02 15:48:01.981804500 simscan:[32131]:CLEAN
(3.20/12.00):15.9017s:=?KOI8-R?Q?Odnoklassniki.ru__?=:208.79.240.2:bezotv...@odnoklassniki.ru:alexan...@xxxxxxxxxx.uk
2010-04-02 15:48:02.234594500 tcpserver: end 32122 status 0
2010-04-02 15:48:02.234596500 tcpserver: status: 0/100
From SMAPD:
2010-04-02 15:46:35.328109500 [10874] info: spamd: connection from
localhost.localdomain [127.0.0.1] at port 39560
2010-04-02 15:46:40.774410500 [10874] info: spamd: processing message
<301585728.15102501270219584629.javamail.bezotv...@mail12.odnoklassniki.ru> for
clamav:89
2010-04-02 15:47:34.071976500 [10874] info: spamd: clean message (3.2/5.0) for
clamav:89 in 60.6 seconds, 1916 bytes.
2010-04-02 15:47:34.292647500 [10874] info: spamd: result: . 3 -
AWL,MIME_BASE64_TEXT,RDNS_NONE,SARE_SUB_ENC_KOI8R
scantime=60.6,size=1916,user=clamav,uid=89,required_score=5.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=39560,mid=<301585728.15102501270219584629.javamail.bezotv...@mail12.odnoklassniki.ru>,autolearn=no,shortcircuit=no
2010-04-02 15:47:39.190952500 [10854] info: prefork: child states: II
2010-04-02 15:47:52.561175500 [10874] info: spamd: connection from
localhost.localdomain [127.0.0.1] at port 39569
2010-04-02 15:47:52.980243500 [10874] info: spamd: processing message
<301585728.15102501270219584629.javamail.bezotv...@mail12.odnoklassniki.ru> for
clamav:89
2010-04-02 15:48:01.938757500 [10874] info: spamd: clean message (3.2/5.0) for
clamav:89 in 9.4 seconds, 2538 bytes.
2010-04-02 15:48:01.966518500 [10874] info: spamd: result: . 3 -
AWL,MIME_BASE64_TEXT,RDNS_NONE,SARE_SUB_ENC_KOI8R,SPF_HELO_PASS
scantime=9.4,size=2538,user=clamav,uid=89,required_score=5.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=39569,mid=<301585728.15102501270219584629.javamail.bezotv...@mail12.odnoklassniki.ru>,autolearn=no,shortcircuit=no
2010-04-02 15:48:02.041354500 [10854] info: prefork: child states: II
It took ClamAV 60.6 seconds to scan!!!!
What is your idle-timeout setting in spamdyke.conf? I'm guessing it's
60. If you bump it up a bit, you'll probably not get duplicates any
more. That doesn't help your slow scan times though.
Now a bit more information about my host:
[r...@xxxxxxxxxx]# uname -a
Linux xxxxxxxxxxx.uk 2.6.32-x86_64-linode11 #1 SMP Sat Dec 5 16:55:26
UTC 2009 x86_64 x86_64 x86_64 GNU/Linux
total used free shared buffers cached
Mem: 343 330 12 0 3 32
-/+ buffers/cache: 295 48
Swap: 255 255 0
[r...@xxxxxxxxxxxxxx]# vmstat 1 2
procs -----------memory---------- ---swap-- -----io---- --system--
-----cpu------
r b swpd free buff cache si so bi bo in cs us sy
id wa st
0 0 262136 9736 2592 43048 7 3 57 9 19 14 0 0
97 2 0
0 0 262136 9740 2592 43024 0 0 0 0 89 170 0 0
100 0 0
Looks to me like you could use more ram.
Then in my /var/log/messages I can see the following:
Mar 31 11:23:02 xxxxxxxxxx kernel: swapper: page allocation failure.
order:0, mode:0x20
Apr 2 15:46:18 xxxxxxxxxx nagios: SERVICE ALERT: xxxxxxxxxxxx.uk;Swap
Usage;CRITICAL;SOFT;1;SWAP CRITICAL - 0% free (0 MB out of 255 MB)
which tell me I was out of memory/SWAP.
Yep. You really need more ram. More swap would keep you from running
out, but it won't help performance.
Linode is Xen-based, VPS provider (www.linode.com), I have 360Mb of RAM
(Guaranteed Resources) and 4 processor Xen instances.
I have Nagios, Munin-node, crushFTP server with WebDAV + full
Qmailtoaster (ClamAV and SpamAssassin) running on the server. I have
already optimised httpd memory usage, but ClamAV...
[r...@xxxxxxxxxxx log]# ps aux | grep clamav
USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND
clamav 2711 0.0 0.2 21580 784 ? Ss Mar30 0:00
/usr/bin/freshclam -d -p /var/run/clamav/freshclam.pid
root 4090 0.0 0.2 61192 792 ttyp1 S+ 16:22 0:00 grep clamav
clamav 16378 0.0 19.1 169016 67232 ? Sl 00:25 0:06
/usr/sbin/clamd
[r...@xxxxxxxxx log]# ps aux | grep spamd
root 4094 0.0 0.2 61192 780 ttyp1 R+ 16:22 0:00 grep spamd
qmaill 10843 0.0 0.0 3676 320 ? S 04:02 0:00
/usr/bin/multilog t s1000000 n100 /var/log/qmail/spamd
root 10854 0.0 1.0 170840 3652 ? S 04:02 0:07
/usr/bin/perl -T -w /usr/bin/spamd -x -u vpopmail -s stderr
vpopmail 10874 0.0 16.2 175444 57120 ? S 04:02 0:04 spamd child
vpopmail 10875 0.0 0.4 170840 1588 ? S 04:02 0:00 spamd child
root 16356 0.0 0.0 3664 332 ? S 00:25 0:00
supervise spamd
vpopmail 16375 0.0 0.1 5924 536 ? S 00:25 0:00
/usr/bin/tcpserver -v -R -H -l xxxxxxxxxxx.uk -x
/etc/tcprules.d/tcp.smtp.cdb -c 100 -u 89 -g 89 0 smtp
/usr/local/bin/spamdyke --config-file /etc/spamdyke/spamdyke.conf
/var/qmail/bin/qmail-smtpd /home/vpopmail/bin/vchkpw /bin/true
ClamAV takes around -19.1% of the memory and SpamAssassin "only takes 16.2%
I'll probably try to increase the Swap size and reboot my VPS and see if
it helps.
If not then I have to disable crushFTP (this is a Java FTP/WebDAV; 128Mb
of memory reserved for Java).
I'd do the later. Get rid of anything running that you don't absolutely
need.
Note, ram usage will fluctuate as mail is processed, so the clam and
spam figures will vary depending on what's being processed at the
moment. Some swapping is ok so long as you're not concerned about
response times.
Increase your idle-timeout setting in spamdyke, and perhaps reduce your
concurrencyincoming setting so you don't get slammed, and you might be
able to get by.
--
-Eric 'shubes'
---------------------------------------------------------------------------------
Qmailtoaster is sponsored by Vickers Consulting Group
(www.vickersconsulting.com)
Vickers Consulting Group offers Qmailtoaster support and installations.
If you need professional help with your setup, contact them today!
---------------------------------------------------------------------------------
Please visit qmailtoaster.com for the latest news, updates, and packages.
To unsubscribe, e-mail: qmailtoaster-list-unsubscr...@qmailtoaster.com
For additional commands, e-mail: qmailtoaster-list-h...@qmailtoaster.com
