# postfix spamd slow processing

## carpman

Hello, ok have local office mail server which pulls in emai via fetchmail, email is then process by postfix, amavisnew and spamd.

I was asked to re-enable a email account, this started to pull down load of email 2500+ so killed fecthmail and comment out the account.

Problem is i now have loads of mail in postfix que and it is processing it really slow.

Server load is under 0.10 and plenty of free memory, i have up spamd processes from default 5 to 15 but still no change?

Is there any thing i can do to speed up things?

cheers

----------

## Dagger

What's the server hardware spec?

on my system I have around 7.5k spam emails per hour on one email server. It runs not only amavis new but also spf check and antivirus. CPU isn't too heavily loaded ( old PIV 1.6GHz ) but I had to put 3GB mem there.

what does logs show? Can you see constant processing or ?

----------

## carpman

 *Dagger wrote:*   

> What's the server hardware spec?
> 
> on my system I have around 7.5k spam emails per hour on one email server. It runs not only amavis new but also spf check and antivirus. CPU isn't too heavily loaded ( old PIV 1.6GHz ) but I had to put 3GB mem there.
> 
> what does logs show? Can you see constant processing or ?

 

Hello and thanks for reply The amount of spam is nowhere near your amount, the server is dual P3 933 with 1gb ram, have 3 x 15k scsi 320 drives HW Raid 5.

I also have AV checks and it normally chugs away fine processing constantly but if get high amount of email download such as with re-enabling this account then amavisnew process it for AV but then it just sort of sits in postfix que, top shows that it only spamd that is processing the mail in this que but is really slow?

When initially down loading the server load spikes high, but when processing back log in que it very low!

cheers

----------

## Dagger

can you please check your:

/etc/amavis.conf settings:

```

$max_servers

$max_requests

$child_timeout

$smtpd_timeout

```

/etc/postfix/main.cf

```

in_flow_delay

default_process_limit

```

also are you using master.cf to redirect emails to amavis or procmail?

If you're using master.cf please check maxproc settings

please take a look  here . I hope it will be helpful a bit.

----------

## carpman

Thanks for reply, as requested.

amavisd.conf

```
$max_servers  =  4

$max_requests = 20

$child_timeout=5*60

$smtpd_timeout = 120
```

/etc/postfix/main.cf  contains non of the settings you ask for.

/etc/postfix/master.cf 

```
# service type  private unpriv  chroot  wakeup  maxproc command + args

#               (yes)   (yes)   (yes)   (never) (100)
```

many thanks

----------

## carpman

opps double post

----------

## Dagger

on my config I've got:

amavis:

```

$max_servers  =  8;

$max_requests = 30;

$child_timeout=6*60;

$smtpd_timeout = 120;

```

postfix:

```

in_flow_delay = 0s

default_process_limit = 120

```

master.cf

```

smtp-amavis     unix -        -       n     -       40  smtp

  -o smtp_data_done_timeout=1200

  -o smtp_send_xforward_command=yes

```

they aren't perfectly tuned, but work quite well on my setup. Play a bit with these settings to get the best performance for your hardware.

----------

## carpman

cheers will try that.

----------

## carpman

Hello, ok tried that. It seems to have improved up initial collection of mail but once lot of mail is in postfix que it then slows down again.

It is only managing about 5 emails a minute!

Looking at top it is only spamd that is now processing this mail with load at about 0.20 . At moment the the back log of mail is just for one user so i can see that only one instance of spamd is running for that user even though i have upped spamd processes to 15?

Below is list of postifix processes from webmin just wondering if up the limit any of them can be upped to improve things?

Thinking specifically of:

```
smtp-amavis    Yes    Unix socket    Yes    Yes    No    2

127.0.0.1:10025    Yes    Internet    No    Yes    No    Default
```

```
Process name    Enabled?    Transport type    Private?    Unprivileged?    Chrooted?    Max processes

smtp    Yes    Internet    No    Yes    No    Default

submission    No    Internet    No    Yes    No    Default

smtps    Yes    Internet    No    Yes    No    Default

628    No    Internet    No    Yes    No    Default

pickup    Yes    Named pipe    No    Yes    No    1

cleanup    Yes    Unix socket    No    Yes    No    Unlimited

qmgr    Yes    Named pipe    No    Yes    No    1

qmgr    No    Named pipe    No    Yes    No    1

tlsmgr    Yes    Unix socket    Yes    Yes    No    1

rewrite    Yes    Unix socket    Yes    Yes    No    Default

bounce    Yes    Unix socket    Yes    Yes    No    Unlimited

defer    Yes    Unix socket    Yes    Yes    No    Unlimited

trace    Yes    Unix socket    Yes    Yes    No    Unlimited

verify    Yes    Unix socket    Yes    Yes    No    1

flush    Yes    Unix socket    No    Yes    No    Unlimited

proxymap    Yes    Unix socket    Yes    Yes    No    Default

smtp    Yes    Unix socket    Yes    Yes    No    40

relay    Yes    Unix socket    Yes    Yes    No    Default

showq    Yes    Unix socket    No    Yes    No    Default

error    Yes    Unix socket    Yes    Yes    No    Default

discard    Yes    Unix socket    Yes    Yes    No    Default

local    Yes    Unix socket    Yes    No    No    Default

virtual    Yes    Unix socket    Yes    No    No    Default

lmtp    Yes    Unix socket    Yes    Yes    No    Default

anvil    Yes    Unix socket    Yes    Yes    No    1

scache    Yes    Unix socket    Yes    Yes    No    1

maildrop    Yes    Unix socket    Yes    No    No    Default

old-cyrus    Yes    Unix socket    Yes    No    No    Default

cyrus    Yes    Unix socket    Yes    No    No    Default

virt-cyrus    Yes    Unix socket    Yes    No    No    Default

uucp    Yes    Unix socket    Yes    No    No    Default

ifmail    Yes    Unix socket    Yes    No    No    Default

bsmtp    Yes    Unix socket    Yes    No    No    Default

smtp-amavis    Yes    Unix socket    Yes    Yes    No    2

127.0.0.1:10025    Yes    Internet    No    Yes    No    Default

pre-cleanup    Yes    Unix socket    No    Yes    No    Unlimited

cleanup    Yes    Unix socket    No    Yes    No    Unlimited

smtp    Yes    Internet    No    Yes    No    Default

pickup    Yes    Named pipe    No    Yes    No    1
```

----------

## carpman

Hello, been trawling logs and keep find following error and wonder if that has anything to do with it?

```

Jan 16 13:03:35 mailserv postfix/local[9135]: warning: pipe_command_read: read time limit exceeded

```

----------

## Dagger

hmm... I'm running out of ideas. On my mail server I've got:

load average: 4.18, 4.36, 4.09

I will check the error message you've posted.

----------

## carpman

 *Dagger wrote:*   

> hmm... I'm running out of ideas. On my mail server I've got:
> 
> load average: 4.18, 4.36, 4.09
> 
> I will check the error message you've posted.

 

cheers, i have search for info on error but have not returned anything of use?

I could understand slow processing of que if server was under load but it is not?

Wondering if something in SA settings that are making it slow?

SA setting

```

confcat /etc/spamassassin/local.cf

 report_safe 1

 required_score 5

 use_bayes 1

 bayes_auto_learn 1

 bayes_auto_learn_threshold_nonspam 1

 bayes_auto_learn_threshold_spam 14.00

 bayes_ignore_header X-Bogosity

 bayes_ignore_header X-Spam-Flag

 bayes_ignore_header X-Spam-Status

skip_rbl_checks         0

use_razor2              1

use_dcc                 1

use_pyzor               1

ok_locales              en

```

I set following to 0 but made no difference.

```

use_razor2              1

use_dcc                 1

use_pyzor               1

```

----------

## magic919

The machine doesn't look like it is coping.  Burying it with more processes will not help it.  I'd upgrade the hardware.

----------

## carpman

 *magic919 wrote:*   

> The machine doesn't look like it is coping.  Burying it with more processes will not help it.  I'd upgrade the hardware.

 

If the load is 0.20 and there is over 500mb of free ram how can it not be coping?

4000 emails in postfix que and top shows

```

Tasks: 123 total,   1 running, 122 sleeping,   0 stopped,   0 zombie

Cpu(s):  0.5%us,  0.7%sy, 47.6%ni, 51.1%id,  0.2%wa,  0.0%hi,  0.0%si,  0.0%st

Mem:    906068k total,   871316k used,    34752k free,   105880k buffers

Swap:   979956k total,      240k used,   979716k free,   382368k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND

23877 a.m.stac  28   8 59148  55m 2532 S   68  6.3   1:41.87 spamd

23878 root      28   8 57788  54m 2508 S   29  6.1   1:08.24 spamd

24278 root      20   0  2168 1136  844 R    1  0.1   0:00.82 top

 4384 mysql     20   0  156m  27m 3676 S    0  3.1  13:59.05 mysqld

26828 root      20   0     0    0    0 S    0  0.0   0:36.46 pdflush

```

----------

## magic919

Google for the Postfix error and you'll see what I mean.  See what Wietse has to say.

----------

## carpman

from what i can gather, though could be wrong, the mail is not being initially not being processed quick enough so is being put back into postfix que and hence error message, though server load never goes higher than about 4 when downlaod large amount of mail and usually at 2.

Even if this is the case why does it take so long for re-qued mail to be processed?

If you look Dagger server specs and the amount of email he putting through then my dual P3 933 should be able to manage the amount of email it is getting?

----------

## magic919

I think if you didn't have amavis and spamassassin the machine would cope just fine.  You could take them out of the loop, stop their processes and see.  When they are stopped you can flush the mail queue and see how quickly they disappear.

I don't know if this is a just a hobby for you, so maybe I'm wrong to suggest a new machine.  But if you are looking after this for a client, what's your time cost?  What level of service do they need/expect.  How much will they spend to fix this?  I'm not asking you to answer any of this, but it's food for thought.

You are experiencing bottlenecks.  Sometimes this can be helped by running more processes but working in parallel doesn't prove faster in all cases.

It's ages since I used amavisd, but I'm sure the logs would give you an indication of how long messages take to pass through it.  How long does it take?

One of my busier servers runs mail/anti-spam/anti-virus and websites.  It can still get a message from HELO to maildir in a couple of seconds.  That's an AMD Sempron 3400+ with 1GB RAM.  My slowest server is a Celeron 2.0GHz with 128MB RAM.  That is taking 4 seconds from connect to maildir.

You've said yourself that SA brought your machine to its knees about once a month, IIRC.  Can't be a good sign.

Maybe you can move off amavis and just use SA?  I use Postfix/DSPAM/ClamAV/Dovecot for what it's worth.  With a bit of MySQL.

----------

## carpman

Hello and thanks for feedback, i appreciate you comments and will think on them.

But as i keep saying , maybe blindly, when the large amount of email is initially downloaded by fetchmail the load only get to about 4, yes i have had issues where server would get a run away process that locked server up a 100% cpu usage but since installing extra ram this has not occurred.

The problem seems not to be with amavis as it appears to have done its work and passed mail on, the re-qued (?) mail is no longer being processed by amavis only spamd. Which once again leads to me to wonder why spamd is taking so long? the reason for requeing of email maybe due to spamd being so slow?

With spamd only processing the que the server load is very very low and memory used never ever gets higher 500mb

I hear what you saying about new hardware but if i have server that apparently is not being loaded very high but has a bottle neck i would rather find the bottle neck as if i get them to buy new hard ware and still have same issue i will look stupid!

Was a pain getting thing working with amavis and sa so don't fancy changing over on live server, have to run some sort of anti spam AV as that is point of local mail server.

Here is extract of logs first is from this afternoon when i set fetchmail to download email from backup account, second is from later with only backlog que being processed.

Looking at second spamd is taking about 10 secs per email, even with rbl turned off this does not change?

It should be lot less this especially when the server is not loaded at all?

```

Jan 16 17:09:53 mailserv postfix/smtpd[13939]: initializing the server-side TLS engine

Jan 16 17:09:53 mailserv postfix/smtpd[13939]: connect from mailserv.smaartmail.domain.com[127.0.0.1]

Jan 16 17:09:53 mailserv postfix/smtpd[13939]: 476D42BC30: client=mailserv.smaartmail.domain.com[127.0.0.1]

Jan 16 17:09:53 mailserv postfix/cleanup[13942]: 476D42BC30: message-id=<002e01c7bfc7$8ff7b040$0200a8c0@KHenry>

Jan 16 17:09:53 mailserv postfix/qmgr[9126]: 476D42BC30: from=<khenry@acpa.org.uk>, size=4702, nrcpt=1 (queue active)

Jan 16 17:09:53 mailserv amavis[13236]: (13236-07) LMTP::10024 /var/amavis/tmp/amavis-20080116T162236-13236: <khenry@acpa.org.uk> -> <a.m.stacey@localhost.domain.com> SIZE=4702 Received: from smaartmail.domain.com ([127.0.0.1]) by localhost (smaartmail.domain.com [127.0.0.1]) (amavisd-new, port 10024) with LMTP for <a.m.stacey@localhost.domain.com>; Wed, 16 Jan 2008 17:09:53 +0000 (GMT)

Jan 16 17:09:53 mailserv amavis[13236]: (13236-07) Checking: bBkF-K8WJPLl <khenry@acpa.org.uk> -> <a.m.stacey@localhost.domain.com>

Jan 16 17:09:53 mailserv amavis[13236]: (13236-07) p003 1 Content-Type: multipart/alternative

Jan 16 17:09:53 mailserv amavis[13236]: (13236-07) p001 1/1 Content-Type: text/plain, size: 718 B, name: 

Jan 16 17:09:53 mailserv amavis[13236]: (13236-07) p002 1/2 Content-Type: text/html, size: 1804 B, name: 

Jan 16 17:09:53 mailserv postfix/smtpd[13939]: A0F7A2BC4A: client=mailserv.smaartmail.domain.com[127.0.0.1]

Jan 16 17:09:53 mailserv postfix/cleanup[13942]: A0F7A2BC4A: message-id=<01c7bfd0$273adba0$6c822ecf@walter>

Jan 16 17:09:53 mailserv postfix/qmgr[9126]: A0F7A2BC4A: from=<walter@pursuitfield.com>, size=28804, nrcpt=1 (queue active)

Jan 16 17:09:53 mailserv amavis[13373]: (13373-03) LMTP::10024 /var/amavis/tmp/amavis-20080116T164421-13373: <walter@pursuitfield.com> -> <a.m.stacey@localhost.domain.com> SIZE=28804 Received: from smaartmail.domain.com ([127.0.0.1]) by localhost (smaartmail.domain.com [127.0.0.1]) (amavisd-new, port 10024) with LMTP for <a.m.stacey@localhost.domain.com>; Wed, 16 Jan 2008 17:09:53 +0000 (GMT)

Jan 16 17:09:53 mailserv amavis[13373]: (13373-03) Checking: Zm5kf1L3DG0a <walter@pursuitfield.com> -> <a.m.stacey@localhost.domain.com>

Jan 16 17:09:53 mailserv amavis[13373]: (13373-03) p004 1 Content-Type: multipart/related

Jan 16 17:09:53 mailserv amavis[13373]: (13373-03) p005 1/1 Content-Type: multipart/alternative

Jan 16 17:09:53 mailserv amavis[13373]: (13373-03) p001 1/1/1 Content-Type: text/plain, size: 730 B, name: 

Jan 16 17:09:53 mailserv amavis[13373]: (13373-03) p002 1/1/2 Content-Type: text/html, size: 1217 B, name: 

Jan 16 17:09:53 mailserv amavis[13373]: (13373-03) p003 1/2 Content-Type: image/gif, size: 17950 B, name: evqrhap.gif

Jan 16 17:09:53 mailserv amavis[13236]: (13236-07) local delivery: <> -> <clean-quarantine>, mbx=/var/amavis/quarantine/clean/bBkF-K8WJPLl

Jan 16 17:09:54 mailserv postfix/smtpd[13948]: initializing the server-side TLS engine

Jan 16 17:09:54 mailserv postfix/smtpd[13948]: connect from mailserv.smaartmail.domain.com[127.0.0.1]

Jan 16 17:09:54 mailserv postfix/smtpd[13948]: 0F4002BC4B: client=mailserv.smaartmail.domain.com[127.0.0.1]

Jan 16 17:09:54 mailserv postfix/smtpd[13939]: 10CED2BC4C: client=mailserv.smaartmail.domain.com[127.0.0.1]

Jan 16 17:09:54 mailserv postfix/cleanup[13942]: 10CED2BC4C: message-id=<01c7bfd5$2a54faa0$6c822ecf@paraprofessionalrenews>

Jan 16 17:09:54 mailserv postfix/cleanup[13950]: 0F4002BC4B: message-id=<002e01c7bfc7$8ff7b040$0200a8c0@KHenry>

Jan 16 17:09:54 mailserv postfix/qmgr[9126]: 10CED2BC4C: from=<paraprofessionalrenews@laboratorios-pino.com>, size=3433, nrcpt=1 (queue active)

Jan 16 17:09:54 mailserv postfix/qmgr[9126]: 0F4002BC4B: from=<khenry@acpa.org.uk>, size=5291, nrcpt=1 (queue active)

Jan 16 17:09:54 mailserv amavis[13236]: (13236-07) FWD via SMTP: <khenry@acpa.org.uk> -> <a.m.stacey@localhost.domain.com>, 250 2.6.0 Ok, id=13236-07, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 0F4002BC4B

Jan 16 17:09:54 mailserv spamd[10757]: spamd: connection from mailserv.smaartmail.domain.com [127.0.0.1] at port 48751

Jan 16 17:09:54 mailserv spamd[10757]: spamd: setuid to a.m.stacey succeeded

Jan 16 17:09:54 mailserv amavis[13236]: (13236-07) Passed CLEAN, [212.139.87.100] <khenry@acpa.org.uk> -> <a.m.stacey@localhost.domain.com>, quarantine: clean/bBkF-K8WJPLl, Message-ID: <002e01c7bfc7$8ff7b040$0200a8c0@KHenry>, mail_id: bBkF-K8WJPLl, Hits: -, queued_as: 0F4002BC4B, 803 ms

Jan 16 17:09:54 mailserv amavis[13236]: (13236-07) TIMING [total 811 ms] - SMTP LHLO: 5 (1%)1, SMTP pre-MAIL: 1 (0%)1, SMTP pre-DATA-flush: 5 (1%)1, SMTP DATA: 77 (10%)11, body_digest: 3 (0%)11, gen_mail_id: 1 (0%)11, mime_decode: 34 (4%)15, get-file-type2: 18 (2%)18, parts_decode: 1 (0%)18, AV-scan-1: 485 (60%)78, update_cache: 5 (1%)78, decide_mail_destiny: 1 (0%)78, write-header: 12 (2%)80, save-to-local-mailbox: 1 (0%)80, fwd-connect: 42 (5%)85, fwd-mail-from: 2 (0%)85, fwd-rcpt-to: 19 (2%)87, fwd-data-cmd: 7 (1%)88, write-header: 2 (0%)89, fwd-data-contents: 2 (0%)89, fwd-data-end: 63 (8%)97, fwd-rundown: 3 (0%)97, prepare-dsn: 1 (0%)97, main_log_entry: 18 (2%)99, update_snmp: 2 (0%)100, unlink-2-files: 2 (0%)100, rundown: 1 (0%)100

Jan 16 17:09:54 mailserv postfix/qmgr[9126]: 476D42BC30: removed

Jan 16 17:09:54 mailserv postfix/lmtp[13943]: 476D42BC30: to=<a.m.stacey@localhost.domain.com>, orig_to=<a.m.stacey@localhost>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.89, delays=0.06/0.01/0.01/0.81, dsn=2.6.0, status=sent (250 2.6.0 Ok, id=13236-07, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 0F4002BC4B)

Jan 16 17:09:54 mailserv postfix/smtpd[13948]: disconnect from mailserv.smaartmail.domain.com[127.0.0.1]

Jan 16 17:09:54 mailserv amavis[7884]: (07884-28) LMTP::10024 /var/amavis/tmp/amavis-20080116T122551-07884: <paraprofessionalrenews@laboratorios-pino.com> -> <a.m.stacey@localhost.domain.com> SIZE=3433 Received: from smaartmail.domain.com ([127.0.0.1]) by localhost (smaartmail.domain.com [127.0.0.1]) (amavisd-new, port 10024) with LMTP for <a.m.stacey@localhost.domain.com>; Wed, 16 Jan 2008 17:09:54 +0000 (GMT)

Jan 16 17:09:54 mailserv spamd[10757]: spamd: processing message <002e01c7bfc7$8ff7b040$0200a8c0@KHenry> for a.m.stacey:511

Jan 16 17:09:54 mailserv amavis[7884]: (07884-28) Checking: dDksbpv0DFuf <paraprofessionalrenews@laboratorios-pino.com> -> <a.m.stacey@localhost.domain.com>

Jan 16 17:09:54 mailserv amavis[7884]: (07884-28) p003 1 Content-Type: multipart/alternative

Jan 16 17:09:54 mailserv amavis[7884]: (07884-28) p001 1/1 Content-Type: text/plain, size: 467 B, name: 

Jan 16 17:09:54 mailserv amavis[7884]: (07884-28) p002 1/2 Content-Type: text/html, size: 1133 B, name: 

Jan 16 17:09:54 mailserv postfix/smtpd[13939]: 4DD6A2BC30: client=mailserv.smaartmail.domain.com[127.0.0.1]

Jan 16 17:09:54 mailserv postfix/cleanup[13942]: 4DD6A2BC30: message-id=<951387510.36952271752575@jcpportraits.com>

Jan 16 17:09:54 mailserv postfix/qmgr[9126]: 4DD6A2BC30: from=<998sherm27@jcpportraits.com>, size=1441, nrcpt=1 (queue active)

Jan 16 17:09:54 mailserv postfix/smtpd[13939]: 8D4202BC4D: client=mailserv.smaartmail.domain.com[127.0.0.1]

Jan 16 17:09:54 mailserv postfix/cleanup[13942]: 8D4202BC4D: message-id=<01c7bff5$5b9877c0$5c3b84c3@jlb>

Jan 16 17:09:54 mailserv postfix/qmgr[9126]: 8D4202BC4D: from=<jlb@anunciocomercial.com>, size=1331, nrcpt=1 (queue active)

Jan 16 17:09:54 mailserv amavis[13373]: (13373-03) local delivery: <> -> <clean-quarantine>, mbx=/var/amavis/quarantine/clean/Zm5kf1L3DG0a

Jan 16 17:09:54 mailserv postfix/smtpd[13948]: connect from mailserv.smaartmail.domain.com[127.0.0.1]

Jan 16 17:09:54 mailserv postfix/smtpd[13948]: AB5F62BC50: client=mailserv.smaartmail.domain.com[127.0.0.1]

Jan 16 17:09:54 mailserv postfix/cleanup[13950]: AB5F62BC50: message-id=<01c7bfd0$273adba0$6c822ecf@walter>

Jan 16 17:09:54 mailserv postfix/qmgr[9126]: AB5F62BC50: from=<walter@pursuitfield.com>, size=29393, nrcpt=1 (queue active)

Jan 16 17:09:54 mailserv amavis[13373]: (13373-03) FWD via SMTP: <walter@pursuitfield.com> -> <a.m.stacey@localhost.domain.com>, 250 2.6.0 Ok, id=13373-03, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as AB5F62BC50

Jan 16 17:09:54 mailserv postfix/smtpd[13948]: disconnect from mailserv.smaartmail.domain.com[127.0.0.1]

Jan 16 17:09:54 mailserv amavis[13373]: (13373-03) Passed CLEAN, [131.161.252.120] <walter@pursuitfield.com> -> <a.m.stacey@localhost.domain.com>, quarantine: clean/Zm5kf1L3DG0a, Message-ID: <01c7bfd0$273adba0$6c822ecf@walter>, mail_id: Zm5kf1L3DG0a, Hits: -, queued_as: AB5F62BC50, 949 ms

Jan 16 17:09:54 mailserv amavis[13373]: (13373-03) TIMING [total 957 ms] - SMTP LHLO: 5 (1%)1, SMTP pre-MAIL: 1 (0%)1, SMTP pre-DATA-flush: 6 (1%)1, SMTP DATA: 83 (9%)10, body_digest: 3 (0%)10, gen_mail_id: 1 (0%)10, mime_decode: 63 (7%)17, get-file-type3: 22 (2%)19, decompose_part: 1 (0%)19, parts_decode: 1 (0%)19, AV-scan-1: 656 (69%)88, update_cache: 3 (0%)88, decide_mail_destiny: 1 (0%)88, write-header: 9 (1%)89, save-to-local-mailbox: 1 (0%)90, fwd-connect: 12 (1%)91, fwd-mail-from: 2 (0%)91, fwd-rcpt-to: 4 (0%)91, fwd-data-cmd: 1 (0%)92, write-header: 2 (0%)92, fwd-data-contents: 5 (1%)92, fwd-data-end: 47 (5%)97, fwd-rundown: 3 (0%)98, prepare-dsn: 1 (0%)98, main_log_entry: 16 (2%)99, update_snmp: 3 (0%)100, unlink-3-files: 2 (0%)100, rundown: 1 (0%)100

Jan 16 17:09:54 mailserv postfix/qmgr[9126]: A0F7A2BC4A: removed

Jan 16 17:09:54 mailserv postfix/lmtp[13946]: A0F7A2BC4A: to=<a.m.stacey@localhost.domain.com>, orig_to=<a.m.stacey@localhost>, relay=127.0.0.1[127.0.0.1]:10024, delay=1.1, delays=0.15/0.02/0.01/0.95, dsn=2.6.0, status=sent (250 2.6.0 Ok, id=13373-03, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as AB5F62BC50)

Jan 16 17:09:54 mailserv amavis[13236]: (13236-08) LMTP::10024 /var/amavis/tmp/amavis-20080116T162236-13236: <998sherm27@jcpportraits.com> -> <a.m.stacey@localhost.domain.com> SIZE=1441 BODY=7BIT Received: from smaartmail.domain.com ([127.0.0.1]) by localhost (smaartmail.domain.com [127.0.0.1]) (amavisd-new, port 10024) with LMTP for <a.m.stacey@localhost.domain.com>; Wed, 16 Jan 2008 17:09:54 +0000 (GMT)

Jan 16 17:09:54 mailserv amavis[13236]: (13236-08) Checking: CHFvoPIOth4X <998sherm27@jcpportraits.com> -> <a.m.stacey@localhost.domain.com>

Jan 16 17:09:54 mailserv amavis[13236]: (13236-08) p001 1 Content-Type: text/html, size: 271 B, name: 

Jan 16 17:09:54 mailserv postfix/smtpd[13939]: D41D32BC4A: client=mailserv.smaartmail.domain.com[127.0.0.1]

Jan 16 17:09:54 mailserv postfix/cleanup[13942]: D41D32BC4A: message-id=<991482471.49058174506195@abros.com>

Jan 16 17:09:54 mailserv postfix/qmgr[9126]: D41D32BC4A: from=<a-1crane@abros.com>, size=1428, nrcpt=1 (queue active)

Jan 16 17:09:55 mailserv amavis[7884]: (07884-28) local delivery: <> -> <clean-quarantine>, mbx=/var/amavis/quarantine/clean/dDksbpv0DFuf

Jan 16 17:09:55 mailserv postfix/smtpd[13948]: connect from mailserv.smaartmail.domain.com[127.0.0.1]

Jan 16 17:09:55 mailserv postfix/smtpd[13948]: 0A07F2BC51: client=mailserv.smaartmail.domain.com[127.0.0.1]

Jan 16 17:09:55 mailserv postfix/cleanup[13950]: 0A07F2BC51: message-id=<01c7bfd5$2a54faa0$6c822ecf@paraprofessionalrenews>

Jan 16 17:09:55 mailserv amavis[7884]: (07884-28) FWD via SMTP: <paraprofessionalrenews@laboratorios-pino.com> -> <a.m.stacey@localhost.domain.com>, 250 2.6.0 Ok, id=07884-28, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 0A07F2BC51

Jan 16 17:09:55 mailserv postfix/qmgr[9126]: 0A07F2BC51: from=<paraprofessionalrenews@laboratorios-pino.com>, size=4022, nrcpt=1 (queue active)

Jan 16 17:09:55 mailserv postfix/smtpd[13948]: disconnect from mailserv.smaartmail.domain.com[127.0.0.1]

Jan 16 17:09:55 mailserv amavis[7884]: (07884-28) Passed CLEAN, [62.13.225.47] <paraprofessionalrenews@laboratorios-pino.com> -> <a.m.stacey@localhost.domain.com>, quarantine: clean/dDksbpv0DFuf, Message-ID: <01c7bfd5$2a54faa0$6c822ecf@paraprofessionalrenews>, mail_id: dDksbpv0DFuf, Hits: -, queued_as: 0A07F2BC51, 931 ms

Jan 16 17:09:55 mailserv amavis[7884]: (07884-28) TIMING [total 941 ms] - SMTP LHLO: 5 (1%)1, SMTP pre-MAIL: 1 (0%)1, SMTP pre-DATA-flush: 6 (1%)1, SMTP DATA: 34 (4%)5, body_digest: 2 (0%)5, gen_mail_id: 1 (0%)5, mime_decode: 36 (4%)9, get-file-type2: 19 (2%)11, decompose_part: 1 (0%)11, parts_decode: 0 (0%)11, AV-scan-1: 718 (76%)88, update_cache: 3 (0%)88, decide_mail_destiny: 1 (0%)88, write-header: 9 (1%)89, save-to-local-mailbox: 0 (0%)89, fwd-connect: 13 (1%)90, fwd-mail-from: 2 (0%)91, fwd-rcpt-to: 5 (0%)91, fwd-data-cmd: 1 (0%)91, write-header: 2 (0%)91, fwd-data-contents: 2 (0%)92, fwd-data-end: 51 (5%)97, fwd-rundown: 2 (0%)97, prepare-dsn: 1 (0%)97, main_log_entry: 20 (2%)99, update_snmp: 3 (0%)100, unlink-2-files: 2 (0%)100, rundown: 1 (0%)100

Jan 16 17:09:55 mailserv postfix/lmtp[13943]: 10CED2BC4C: to=<a.m.stacey@localhost.domain.com>, orig_to=<a.m.stacey@localhost>, relay=127.0.0.1[127.0.0.1]:10024, delay=1.1, delays=0.05/0.05/0.02/0.94, dsn=2.6.0, status=sent (250 2.6.0 Ok, id=07884-28, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 0A07F2BC51)

Jan 16 17:09:55 mailserv postfix/qmgr[9126]: 10CED2BC4C: removed

Jan 16 17:09:55 mailserv amavis[7884]: (07884-28-2) LMTP::10024 /var/amavis/tmp/amavis-20080116T122551-07884: <jlb@anunciocomercial.com> -> <a.m.stacey@localhost.domain.com> SIZE=1331 BODY=7BIT Received: from smaartmail.domain.com ([127.0.0.1]) by localhost (smaartmail.domain.com [127.0.0.1]) (amavisd-new, port 10024) with LMTP for <a.m.stacey@localhost.domain.com>; Wed, 16 Jan 2008 17:09:55 +0000 (GMT)

Jan 16 17:09:55 mailserv amavis[7884]: (07884-28-2) Checking: dfT9IKQIqEy3 <jlb@anunciocomercial.com> -> <a.m.stacey@localhost.domain.com>

Jan 16 17:09:55 mailserv amavis[7884]: (07884-28-2) p001 1 Content-Type: text/plain, size: 58 B, name: 

Jan 16 17:09:55 mailserv postfix/smtpd[13939]: 440FD2BC4C: client=mailserv.smaartmail.domain.com[127.0.0.1]

Jan 16 17:09:55 mailserv postfix/cleanup[13942]: 440FD2BC4C: message-id=<000201c7bffa$d0410600$0100007f@nkvyccg>

Jan 16 17:09:55 mailserv postfix/qmgr[9126]: 440FD2BC4C: from=<littlelottie.com@watcke.com>, size=20619, nrcpt=1 (queue active)

Jan 16 17:09:55 mailserv amavis[13236]: (13236-08) local delivery: <> -> <clean-quarantine>, mbx=/var/amavis/quarantine/clean/CHFvoPIOth4X

Jan 16 17:09:55 mailserv postfix/smtpd[13948]: connect from mailserv.smaartmail.domain.com[127.0.0.1]

Jan 16 17:09:55 mailserv postfix/smtpd[13948]: 839462BC53: client=mailserv.smaartmail.domain.com[127.0.0.1]

Jan 16 17:09:55 mailserv postfix/cleanup[13950]: 839462BC53: message-id=<951387510.36952271752575@jcpportraits.com>

Jan 16 17:09:55 mailserv postfix/qmgr[9126]: 839462BC53: from=<998sherm27@jcpportraits.com>, size=2030, nrcpt=1 (queue active)

Jan 16 17:09:55 mailserv postfix/smtpd[13948]: disconnect from mailserv.smaartmail.domain.com[127.0.0.1]

Jan 16 17:09:55 mailserv amavis[13236]: (13236-08) FWD via SMTP: <998sherm27@jcpportraits.com> -> <a.m.stacey@localhost.domain.com>, 250 2.6.0 Ok, id=13236-08, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 839462BC53

Jan 16 17:09:55 mailserv amavis[13236]: (13236-08) Passed CLEAN, [58.140.13.214] <998sherm27@jcpportraits.com> -> <a.m.stacey@localhost.domain.com>, quarantine: clean/CHFvoPIOth4X, Message-ID: <951387510.36952271752575@jcpportraits.com>, mail_id: CHFvoPIOth4X, Hits: -, queued_as: 839462BC53, 823 ms

Jan 16 17:09:55 mailserv amavis[13236]: (13236-08) TIMING [total 830 ms] - SMTP LHLO: 5 (1%)1, SMTP pre-MAIL: 1 (0%)1, SMTP pre-DATA-flush: 6 (1%)1, SMTP DATA: 35 (4%)6, body_digest: 2 (0%)6, gen_mail_id: 1 (0%)6, mime_decode: 17 (2%)8, get-file-type1: 14 (2%)10, parts_decode: 0 (0%)10, AV-scan-1: 635 (76%)86, update_cache: 3 (0%)87, decide_mail_destiny: 1 (0%)87, write-header: 9 (1%)88, save-to-local-mailbox: 1 (0%)88, fwd-connect: 12 (1%)89, fwd-mail-from: 2 (0%)90, fwd-rcpt-to: 4 (1%)90, fwd-data-cmd: 1 (0%)90, write-header: 2 (0%)90, fwd-data-contents: 1 (0%)91, fwd-data-end: 54 (6%)97, fwd-rundown: 3 (0%)97, prepare-dsn: 1 (0%)98, main_log_entry: 15 (2%)99, update_snmp: 2 (0%)100, unlink-1-files: 2 (0%)100, rundown: 1 (0%)100 

```

and here extract from logs now with fetchmail turned off and just the backlog que being processed.

```

Jan 16 20:09:22 mailserv spamd[26124]: spamd: connection from mailserv.smaartmail.domain.com [127.0.0.1] at port 38510

Jan 16 20:09:22 mailserv spamd[26124]: spamd: setuid to a.m.stacey succeeded

Jan 16 20:09:22 mailserv spamd[26124]: spamd: processing message <487601c7ee8b$0045352d$fb4cf445@c-69-244-76-251.hsd1.md.comcast.net> for a.m.stacey:511

Jan 16 20:09:23 mailserv spamd[23860]: prefork: child states: IB

Jan 16 20:09:33 mailserv spamd[26124]: spamd: identified spam (21.4/5.0) for a.m.stacey:511 in 11.3 seconds, 2225 bytes.

Jan 16 20:09:33 mailserv spamd[26124]: spamd: result: Y 21 - AWL,BAYES_99,DCC_CHECK,DIGEST_MULTIPLE,DRUGS_ERECTILE,DRUG_ED_CAPS,FB_LETTERS_21B,FH_HELO_EQ_D_D_D_D,HELO_DYNAMIC_IPADDR,RAZOR2_CF_RANGE_51_100,RAZOR2_CF_RANGE_E8_51_100,RAZOR2_CHECK,RDNS_DYNAMIC,STOX_REPLY_TYPE,SUBJECT_DRUG_GAP_C,SUBJ_ALL_CAPS,TVD_FINGER_02 scantime=11.3,size=2225,user=a.m.stacey,uid=511,required_score=5.0,rhost=mailserv.smaartmail.domain.com,raddr=127.0.0.1,rport=38510,mid=<487601c7ee8b$0045352d$fb4cf445@c-69-244-76-251.hsd1.md.comcast.net>,bayes=1.000000,autolearn=unavailable

Jan 16 20:09:33 mailserv postfix/local[26527]: 8CF492BFDF: to=<a.m.stacey@localhost.domain.com>, relay=local, delay=10299, delays=0.05/10288/0/11, dsn=2.0.0, status=sent (delivered to command: /usr/bin/procmail)

Jan 16 20:09:33 mailserv postfix/qmgr[9126]: 8CF492BFDF: removed

Jan 16 20:09:33 mailserv spamd[26118]: spamd: connection from mailserv.smaartmail.domain.com [127.0.0.1] at port 38512

Jan 16 20:09:33 mailserv spamd[26118]: spamd: setuid to a.m.stacey succeeded

Jan 16 20:09:33 mailserv spamd[26118]: spamd: processing message <001a01c7eed0$a3902690$01b1d41c@VINCENT335578B> for a.m.stacey:511

Jan 16 20:09:34 mailserv spamd[23860]: prefork: child states: BI

Jan 16 20:09:44 mailserv spamd[26118]: spamd: identified spam (27.5/5.0) for a.m.stacey:511 in 10.6 seconds, 5601 bytes.

Jan 16 20:09:44 mailserv spamd[26118]: spamd: result: Y 27 - AWL,BAYES_99,DCC_CHECK,DIGEST_MULTIPLE,FB_QUALITY_REPLICA,FH_HELO_EQ_D_D_D_D,HELO_DYNAMIC_IPADDR2,HTML_FONT_SIZE_LARGE,HTML_MESSAGE,RAZOR2_CF_RANGE_51_100,RAZOR2_CF_RANGE_E4_51_100,RAZOR2_CF_RANGE_E8_51_100,RAZOR2_CHECK,RDNS_DYNAMIC,SARE_SPEC_REPLICA_OBFU,SARE_SPEC_ROLEX,SARE_SPEC_ROLEX_BUY,SARE_SPEC_ROLEX_HIQLT,UNRESOLVED_TEMPLATE scantime=10.6,size=5601,user=a.m.stacey,uid=511,required_score=5.0,rhost=mailserv.smaartmail.domain.com,raddr=127.0.0.1,rport=38512,mid=<001a01c7eed0$a3902690$01b1d41c@VINCENT335578B>,bayes=1.000000,autolearn=unavailable

Jan 16 20:09:44 mailserv postfix/local[27598]: A96C12C047: to=<a.m.stacey@localhost.domain.com>, relay=local, delay=10310, delays=0.07/10299/0/11, dsn=2.0.0, status=sent (delivered to command: /usr/bin/procmail)

Jan 16 20:09:44 mailserv postfix/qmgr[9126]: A96C12C047: removed

Jan 16 20:09:44 mailserv spamd[26124]: spamd: connection from mailserv.smaartmail.domain.com [127.0.0.1] at port 38514

Jan 16 20:09:44 mailserv spamd[26124]: spamd: setuid to a.m.stacey succeeded

Jan 16 20:09:44 mailserv spamd[26124]: spamd: processing message <56788109223451.4BD3DF5CF1@D5YZXKC> for a.m.stacey:511

Jan 16 20:09:45 mailserv spamd[23860]: prefork: child states: IB

Jan 16 20:09:48 mailserv spamd[26124]: spamd: identified spam (25.8/5.0) for a.m.stacey:511 in 4.6 seconds, 4509 bytes.

Jan 16 20:09:48 mailserv spamd[26124]: spamd: result: Y 25 - BAYES_99,DRUGS_STOCK_MIMEOLE,FB_QUALITY_REPLICA,FORGED_HOTMAIL_RCVD2,FS_REPLICA,FS_REPLICAWATCH,HTML_MESSAGE,MID_DEGREES,RAZOR2_CF_RANGE_51_100,RAZOR2_CF_RANGE_E8_51_100,RAZOR2_CHECK,RDNS_NONE,SARE_SPEC_REPLICA_OBFU,SARE_SPEC_ROLEX_HIQLT,SARE_SPEC_ROLEX_NOV5A scantime=4.6,size=4509,user=a.m.stacey,uid=511,required_score=5.0,rhost=mailserv.smaartmail.domain.com,raddr=127.0.0.1,rport=38514,mid=<56788109223451.4BD3DF5CF1@D5YZXKC>,bayes=1.000000,autolearn=unavailable

Jan 16 20:09:48 mailserv postfix/local[26527]: 4C1742C048: to=<a.m.stacey@localhost.domain.com>, relay=local, delay=10314, delays=0.05/10309/0/4.6, dsn=2.0.0, status=sent (delivered to command: /usr/bin/procmail)

Jan 16 20:09:48 mailserv postfix/qmgr[9126]: 4C1742C048: removed

Jan 16 20:09:48 mailserv spamd[26118]: spamd: connection from mailserv.smaartmail.domain.com [127.0.0.1] at port 38516

Jan 16 20:09:48 mailserv spamd[26118]: spamd: setuid to a.m.stacey succeeded

Jan 16 20:09:48 mailserv spamd[26118]: spamd: processing message <0107ffa4$0107fe78$274856dc@general> for a.m.stacey:511

Jan 16 20:09:49 mailserv spamd[23860]: prefork: child states: BI

Jan 16 20:10:00 mailserv spamd[26118]: spamd: identified spam (10.4/5.0) for a.m.stacey:511 in 11.6 seconds, 23392 bytes.

Jan 16 20:10:00 mailserv spamd[26118]: spamd: result: Y 10 - AWL,BAYES_99,EXTRA_MPART_TYPE,HTML_IMAGE_ONLY_16,HTML_MESSAGE,INVALID_DATE,PART_CID_STOCK,RDNS_NONE,STOCK_IMG_CTYPE,STOCK_IMG_HDR_FROM,STOCK_IMG_HTML,T_TVD_FW_GRAPHIC_ID1 scantime=11.6,size=23392,user=a.m.stacey,uid=511,required_score=5.0,rhost=mailserv.smaartmail.domain.com,raddr=127.0.0.1,rport=38516,mid=<0107ffa4$0107fe78$274856dc@general>,bayes=1.000000,autolearn=no

Jan 16 20:10:00 mailserv postfix/local[27598]: 726F62BFE0: to=<a.m.stacey@localhost.domain.com>, relay=local, delay=10325, delays=0.06/10313/0/12, dsn=2.0.0, status=sent (delivered to command: /usr/bin/procmail)

Jan 16 20:10:00 mailserv postfix/qmgr[9126]: 726F62BFE0: removed

Jan 16 20:10:00 mailserv spamd[26124]: spamd: connection from mailserv.smaartmail.domain.com [127.0.0.1] at port 38518

Jan 16 20:10:00 mailserv spamd[26124]: spamd: setuid to a.m.stacey succeeded

Jan 16 20:10:00 mailserv spamd[26124]: spamd: processing message <436523.95443.qm@web44910.mail.sp1.yahoo.com> for a.m.stacey:511

Jan 16 20:10:01 mailserv spamd[23860]: prefork: child states: IB

Jan 16 20:10:05 mailserv spamd[26124]: spamd: clean message (4.4/5.0) for a.m.stacey:511 in 5.1 seconds, 8778 bytes.

Jan 16 20:10:05 mailserv spamd[26124]: spamd: result: . 4 - ADVANCE_FEE_2,ADVANCE_FEE_3,ADVANCE_FEE_4,AWL,BAYES_00,HTML_MESSAGE,NA_DOLLARS,SARE_FRAUD_X3 scantime=5.1,size=8778,user=a.m.stacey,uid=511,required_score=5.0,rhost=mailserv.smaartmail.domain.com,raddr=127.0.0.1,rport=38518,mid=<436523.95443.qm@web44910.mail.sp1.yahoo.com>,bayes=0.000258,autolearn=no

Jan 16 20:10:05 mailserv postfix/local[26527]: 14A822C04A: to=<a.m.stacey@localhost.domain.com>, relay=local, delay=10330, delays=0.06/10324/0/5.1, dsn=2.0.0, status=sent (delivered to command: /usr/bin/procmail)

Jan 16 20:10:05 mailserv postfix/qmgr[9126]: 14A822C04A: removed

Jan 16 20:10:05 mailserv spamd[26118]: spamd: connection from mailserv.smaartmail.domain.com [127.0.0.1] at port 38520

Jan 16 20:10:05 mailserv spamd[26118]: spamd: setuid to a.m.stacey succeeded

Jan 16 20:10:05 mailserv spamd[26118]: spamd: processing message <00f1ffa4$00f1fe78$7b15b579@ninja> for a.m.stacey:511

Jan 16 20:10:06 mailserv spamd[23860]: prefork: child states: BI

Jan 16 20:10:17 mailserv spamd[26118]: spamd: identified spam (9.6/5.0) for a.m.stacey:511 in 11.3 seconds, 2176 bytes.

Jan 16 20:10:17 mailserv spamd[26118]: spamd: result: Y 9 - AWL,BAYES_99,DCC_CHECK,DIGEST_MULTIPLE,INVALID_DATE,MORE_SEX,RAZOR2_CF_RANGE_51_100,RAZOR2_CF_RANGE_E8_51_100,RAZOR2_CHECK,RDNS_NONE scantime=11.3,size=2176,user=a.m.stacey,uid=511,required_score=5.0,rhost=mailserv.smaartmail.domain.com,raddr=127.0.0.1,rport=38520,mid=<00f1ffa4$00f1fe78$7b15b579@ninja>,bayes=1.000000,autolearn=no

Jan 16 20:10:17 mailserv postfix/local[27598]: 2BD6C2BC6F: to=<a.m.stacey@localhost.domain.com>, relay=local, delay=10341, delays=0.06/10329/0/11, dsn=2.0.0, status=sent (delivered to command: /usr/bin/procmail)

Jan 16 20:10:17 mailserv postfix/qmgr[9126]: 2BD6C2BC6F: removed

Jan 16 20:10:17 mailserv spamd[26124]: spamd: connection from mailserv.smaartmail.domain.com [127.0.0.1] at port 38522

Jan 16 20:10:17 mailserv spamd[26124]: spamd: setuid to a.m.stacey succeeded

Jan 16 20:10:17 mailserv spamd[26124]: spamd: processing message <0107ffa4$0107fe78$7f899ddd@joe> for a.m.stacey:511

Jan 16 20:10:17 mailserv spamd[23860]: prefork: child states: IB

Jan 16 20:10:28 mailserv spamd[26124]: spamd: identified spam (14.1/5.0) for a.m.stacey:511 in 11.5 seconds, 4766 bytes.

Jan 16 20:10:28 mailserv spamd[26124]: spamd: result: Y 14 - AWL,BAYES_99,DCC_CHECK,DIGEST_MULTIPLE,FM_SCHOOLING,HTML_MESSAGE,INVALID_DATE,RAZOR2_CF_RANGE_51_100,RAZOR2_CF_RANGE_E4_51_100,RAZOR2_CHECK,RDNS_NONE,SARE_BIZOP,SARE_COLLEGE_SCAM scantime=11.5,size=4766,user=a.m.stacey,uid=511,required_score=5.0,rhost=mailserv.smaartmail.domain.com,raddr=127.0.0.1,rport=38522,mid=<0107ffa4$0107fe78$7f899ddd@joe>,bayes=0.999173,autolearn=no

Jan 16 20:10:28 mailserv postfix/local[26527]: CC8FA2C04C: to=<a.m.stacey@localhost.domain.com>, relay=local, delay=10352, delays=0.07/10340/0/12, dsn=2.0.0, status=sent (delivered to command: /usr/bin/procmail)

Jan 16 20:10:28 mailserv postfix/qmgr[9126]: CC8FA2C04C: removed

Jan 16 20:10:28 mailserv spamd[26118]: spamd: connection from mailserv.smaartmail.domain.com [127.0.0.1] at port 38524

Jan 16 20:10:28 mailserv spamd[26118]: spamd: setuid to a.m.stacey succeeded

Jan 16 20:10:28 mailserv spamd[26118]: spamd: processing message <126079728212.313999696382@kvl-rent.fi> for a.m.stacey:511

Jan 16 20:10:29 mailserv spamd[23860]: prefork: child states: BI

Jan 16 20:10:39 mailserv spamd[26118]: spamd: identified spam (10.6/5.0) for a.m.stacey:511 in 11.2 seconds, 2221 bytes.

Jan 16 20:10:39 mailserv spamd[26118]: spamd: result: Y 10 - AXB_XMID_1212,BAYES_99,FH_HELO_EQ_D_D_D_D,RAZOR2_CF_RANGE_51_100,RAZOR2_CF_RANGE_E8_51_100,RAZOR2_CHECK,SARE_SXLIFE,STOX_REPLY_TYPE scantime=11.2,size=2221,user=a.m.stacey,uid=511,required_score=5.0,rhost=mailserv.smaartmail.domain.com,raddr=127.0.0.1,rport=38524,mid=<126079728212.313999696382@kvl-rent.fi>,bayes=0.999999,autolearn=no

Jan 16 20:10:39 mailserv postfix/local[27598]: DADE92C04D: to=<a.m.stacey@localhost.domain.com>, relay=local, delay=10363, delays=0.06/10352/0/11, dsn=2.0.0, status=sent (delivered to command: /usr/bin/procmail)

Jan 16 20:10:39 mailserv postfix/qmgr[9126]: DADE92C04D: removed

Jan 16 20:10:39 mailserv spamd[26124]: spamd: connection from mailserv.smaartmail.domain.com [127.0.0.1] at port 38526

Jan 16 20:10:39 mailserv spamd[26124]: spamd: setuid to a.m.stacey succeeded

Jan 16 20:10:39 mailserv spamd[26124]: spamd: processing message <000801c7eec0$59beb370$0100000a@rufus> for a.m.stacey:511

Jan 16 20:10:40 mailserv spamd[23860]: prefork: child states: IB

Jan 16 20:10:50 mailserv spamd[26124]: spamd: identified spam (7.4/5.0) for a.m.stacey:511 in 10.4 seconds, 2551 bytes.

Jan 16 20:10:50 mailserv spamd[26124]: spamd: result: Y 7 - AWL,BAYES_95,RAZOR2_CF_RANGE_51_100,RAZOR2_CF_RANGE_E8_51_100,RAZOR2_CHECK,RDNS_NONE,SPAMMY_XMAILER scantime=10.4,size=2551,user=a.m.stacey,uid=511,required_score=5.0,rhost=mailserv.smaartmail.domain.com,raddr=127.0.0.1,rport=38526,mid=<000801c7eec0$59beb370$0100000a@rufus>,bayes=0.988692,autolearn=no

Jan 16 20:10:50 mailserv postfix/local[26527]: 92EBD2C04E: to=<a.m.stacey@localhost.domain.com>, relay=local, delay=10373, delays=0.06/10362/0/10, dsn=2.0.0, status=sent (delivered to command: /usr/bin/procmail)

Jan 16 20:10:50 mailserv postfix/qmgr[9126]: 92EBD2C04E: removed

Jan 16 20:10:50 mailserv spamd[26118]: spamd: connection from mailserv.smaartmail.domain.com [127.0.0.1] at port 38528

Jan 16 20:10:50 mailserv spamd[26118]: spamd: setuid to a.m.stacey succeeded

Jan 16 20:10:50 mailserv spamd[26118]: spamd: processing message <261032952.93662736842190@luessi.ch> for a.m.stacey:511

Jan 16 20:10:51 mailserv spamd[23860]: prefork: child states: BI

Jan 16 20:11:01 mailserv spamd[26118]: spamd: identified spam (17.5/5.0) for a.m.stacey:511 in 11.3 seconds, 16540 bytes.

Jan 16 20:11:01 mailserv spamd[26118]: spamd: result: Y 17 - BAYES_99,DYN_RDNS_AND_INLINE_IMAGE,HELO_DYNAMIC_IPADDR2,HELO_DYNAMIC_SPLIT_IP,INVALID_DATE,RCVD_NUMERIC_HELO,RDNS_DYNAMIC,SB_GIF_AND_NO_URIS scantime=11.3,size=16540,user=a.m.stacey,uid=511,required_score=5.0,rhost=mailserv.smaartmail.domain.com,raddr=127.0.0.1,rport=38528,mid=<261032952.93662736842190@luessi.ch>,bayes=1.000000,autolearn=unavailable

Jan 16 20:11:01 mailserv postfix/local[27598]: 9B6ED2C04F: to=<a.m.stacey@localhost.domain.com>, relay=local, delay=10384, delays=0.07/10373/0/11, dsn=2.0.0, status=sent (delivered to command: /usr/bin/procmail)

Jan 16 20:11:01 mailserv postfix/qmgr[9126]: 9B6ED2C04F: removed

Jan 16 20:11:01 mailserv spamd[26124]: spamd: connection from mailserv.smaartmail.domain.com [127.0.0.1] at port 59975

Jan 16 20:11:01 mailserv spamd[26124]: spamd: setuid to a.m.stacey succeeded

Jan 16 20:11:01 mailserv spamd[26124]: spamd: processing message <0107ffa4$0107fe78$dd6fe5d3@rmc> for a.m.stacey:511

```

----------

## Dagger

that is quite unusual in my opinion. On my server it takes around 1-2 sec to check a single email having few of amavis processes running at the same time.

```

Jan 17 12:00:52 [amavis] (27795-10) TIMING [total 363 ms] - SMTP EHLO: 2 (1%)1, SMTP pre-MAIL: 1 (0%)1, SMTP pre-DATA-flush: 2 (1%)1, SMTP DATA: 44 (12%)13, body_digest: 1 (0%)14, gen_mail_id: 0 (0%)14, mime_decode: 24 (7%)21, get-file-type2: 19 (5%)26, decompose_part: 1 (0%)26, decompose_part: 5 (1%)27, get-file-type1: 14 (4%)31, decompose_part: 42 (12%)43, parts_decode: 0 (0%)43, AV-scan-1: 27 (7%)50, read_snmp_variables: 1 (0%)50, best_try_originator: 6 (2%)52, update_cache: 1 (0%)52, decide_mail_destiny: 2 (0%)53, write-header: 5 (1%)54, save-to-local-mailbox: 0 (0%)54, fwd-connect: 43 (12%)66, fwd-mail-from: 3 (1%)67, fwd-rcpt-to: 10 (3%)70, fwd-data-cmd: 1 (0%)70, write-header: 1 (0%)70, fwd-data-contents: 9 (3%)73, fwd-data-end: 76 (21%)94, fwd-rundown: 2 (1%)95, prepare-dsn: 1 (0%)95, main_log_entry: 13 (4%)99, update_snmp: 2 (1%)99, unlink-2-files: 1 (0%)100, rundown: 1 (0%)100

Jan 17 12:00:55 [amavis] (26570-18) TIMING [total 340 ms] - SMTP EHLO: 4 (1%)1, SMTP pre-MAIL: 2 (0%)2, SMTP pre-DATA-flush: 4 (1%)3, SMTP DATA: 43 (13%)15, body_digest: 1 (0%)16, gen_mail_id: 0 (0%)16, mime_decode: 18 (5%)21, get-file-type2: 21 (6%)28, decompose_part: 47 (14%)41, parts_decode: 0 (0%)41, AV-scan-1: 27 (8%)49, read_snmp_variables: 1 (0%)50, best_try_originator: 6 (2%)51, update_cache: 1 (0%)52, decide_mail_destiny: 3 (1%)53, write-header: 7 (2%)55, save-to-local-mailbox: 0 (0%)55, fwd-connect: 30 (9%)64, fwd-mail-from: 5 (1%)65, fwd-rcpt-to: 6 (2%)67, fwd-data-cmd: 1 (0%)67, write-header: 1 (0%)68, fwd-data-contents: 11 (3%)71, fwd-data-end: 75 (22%)93, fwd-rundown: 3 (1%)94, prepare-dsn: 3 (1%)95, main_log_entry: 14 (4%)99, update_snmp: 2 (1%)99, unlink-2-files: 2 (0%)100, rundown: 1 (0%)100

Jan 17 12:00:59 [amavis] (19471-13) TIMING [total 1884 ms] - SMTP EHLO: 3 (0%)0, SMTP pre-MAIL: 1 (0%)0, SMTP pre-DATA-flush: 5 (0%)0, SMTP DATA: 34 (2%)2, body_digest: 1 (0%)2, gen_mail_id: 0 (0%)2, mime_decode: 9 (0%)3, get-file-type1: 14 (1%)4, decompose_part: 1 (0%)4, parts_decode: 0 (0%)4, AV-scan-1: 9 (0%)4, spam-wb-list: 6 (0%)4, SA msg read: 1 (0%)4, SA parse: 3 (0%)5, SA check: 1761 (93%)98, SA finish: 4 (0%)98, update_cache: 1 (0%)98, decide_mail_destiny: 2 (0%)99, write-header: 13 (1%)99, save-to-local-mailbox: 1 (0%)99, prepare-dsn: 2 (0%)99, main_log_entry: 9 (0%)100, update_snmp: 2 (0%)100, unlink-1-files: 1 (0%)100, rundown: 0 (0%)100

```

SPF takes much longer and is much more memory hungry than amavis.

----------

## carpman

Thanks for reply.

Yes that is what i thought, but why is the question i am stumped on?

----------

## Dagger

The other idea....

What DNS are you using on it? When I was using my main DNS server (BIND) it was much slower. I installed DNSMASQ as a local dns caching service and it improved speed quite a lot.

----------

## carpman

 *Dagger wrote:*   

> The other idea....
> 
> What DNS are you using on it? When I was using my main DNS server (BIND) it was much slower. I installed DNSMASQ as a local dns caching service and it improved speed quite a lot.

 

Hello, you know i have been thinking about  dnscache, the server is behind a firewall, smoothwall corp, which also serves as local nameserver/dns as well as connection to net.

There is nothing on server, no bind, but was thinking of installing djbdns and using the dnscache app from that.

How easy/hard was it to setup DNSMASQ?

cheers

----------

