Mailing List Archive: exim: users

exim processes mails twice

Index | Next | Previous | View Threaded

clemens.hardewig at crandale

Oct 31, 2006, 2:40 PM

Post #1 of 3 (388 views)
Permalink

exim processes mails twice

Hello,

I'm running an fetchmail/exim/cyrus installation under Debian Sarge with
Spamassassin.

I have a quite bizarre problem that my exim is processing my mails twice:
Executing

exim4 -d+route user1 [at] localhos
... hier nur den Versandteil ....
server:/home/user1# exec /usr/sbin/exim4 -d=0xfbb95cfd -Mc 1GecpX-0004J7-VY
Exim version 4.50 uid=102 gid=102 pid=16951 D=fbb95cfd
Berkeley DB: Sleepycat Software: Berkeley DB 4.2.52: (December 3, 2003)
Support for: iconv() IPv6 PAM Perl GnuTLS Content_Scanning Old_Demime
Lookups: lsearch wildlsearch nwildlsearch iplsearch cdb dbm dbmnz dnsdb
dsearch
ldap ldapdn ldapm mysql nis nis0 passwd pgsql
Authenticators: cram_md5 cyrus_sasl plaintext spa
Routers: accept dnslookup ipliteral iplookup manualroute queryprogram redirect
Transports: appendfile/maildir/mailstore/mbx autoreply lmtp pipe smtp
Fixed never_users: 0
changed uid/gid: forcing real = effective
uid=0 gid=102 pid=16951
auxiliary group list: <none>
configuration file is /var/lib/exim4/config.autogenerated
log selectors = 00000ffc 00020800
trusted user
admin user
skipping ACL configuration - not needed
finduser used cached passwd data for mail
set_process_info: 16951 delivering specified messages
set_process_info: 16951 delivering 1GecpX-0004J7-VY
reading spool file 1GecpX-0004J7-VY-H
user=root uid=0 gid=0 sender=root [at] domain
sender_local=1 ident=root
Non-recipients:
Empty Tree
---- End of tree ----
recipients_count=1
body_linecount=0 message_linecount=6
Delivery address list:
user1 [at] localhos
locking /var/spool/exim4/db/retry.lockfile
locked /var/spool/exim4/db/retry.lockfile
opened hints database /var/spool/exim4/db/retry: flags=0
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
Considering: user1 [at] localhos
unique = user1 [at] localhos
dbfn_read: key=R:localhost
dbfn_read: key=R:user1 [at] localhos
no domain retry record
no address retry record
user1 [at] localhos: queued for routing
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
routing user1 [at] localhos
--------> hubbed_hosts router <--------
local_part=user1 domain=localhost
checking domains
expansion of "${if exists{/etc/exim4/hubbed_hosts}
{partial-lsearch;/etc/exim4/hu
bbed_hosts}fail}" forced failure: assume not in this list
hubbed_hosts router skipped: domains mismatch
--------> smarthost router <--------
local_part=user1 domain=localhost
checking domains
localhost in "@:domain.com:localhost:domain.com"? yes (matched "localhost
")
localhost in "! +local_domains"? no (matched "! +local_domains")
smarthost router skipped: domains mismatch
--------> real_local router <--------
local_part=user1 domain=localhost
real_local router skipped: prefix mismatch
--------> system_aliases router <--------
local_part=user1 domain=localhost
checking domains
cached yes match for +local_domains
cached lookup data = NULL
localhost in "+local_domains"? yes (matched "+local_domains" - cached)
R: system_aliases for user1 [at] localhos
calling system_aliases router
rda_interpret (string): ${lookup{$local_part}lsearch{/etc/aliases}}
search_open: lsearch "/etc/aliases"
search_find: file="/etc/aliases"
key="user1" partial=-1 affix=NULL starflags=0
LRU list:
:/etc/aliases
End
internal_search_find: file="/etc/aliases"
type=lsearch key="user1"
file lookup required for user1
in /etc/aliases
lookup failed
expanded:
file is not a filter file
parse_forward_list:
system_aliases router declined for user1 [at] localhos
--------> userforward router <--------
local_part=user1 domain=localhost
checking domains
cached yes match for +local_domains
cached lookup data = NULL
localhost in "+local_domains"? yes (matched "+local_domains" - cached)
checking for local user
R: userforward for user1 [at] localhos
calling userforward router
rda_interpret (file): $home/.forward
expanded: /home/user1/.forward
stat(/home/user1/.)=0
/home/user1/.forward does not exist
userforward router declined for user1 [at] localhos
--------> procmail router <--------
local_part=user1 domain=localhost
checking domains
cached yes match for +local_domains
cached lookup data = NULL
localhost in "+local_domains"? yes (matched "+local_domains" - cached)
checking for local user
finduser used cached passwd data for user1
R: procmail for user1 [at] localhos
checking require_files
finduser used cached passwd data for user1
check subsequent files for access by user1
file check: ${if exists{/etc/procmailrc}{/etc/procmailrc}
{${home}/.procmailrc}}
expanded file: /home/user1/.procmailrc
stat() yielded -1
errno = 2
procmail router skipped: file check
--------> maildrop router <--------
local_part=user1 domain=localhost
checking domains
cached yes match for +local_domains
cached lookup data = NULL
localhost in "+local_domains"? yes (matched "+local_domains" - cached)
checking for local user
finduser used cached passwd data for user1
R: maildrop for user1 [at] localhos
checking require_files
finduser used cached passwd data for user1
check subsequent files for access by user1
file check: ${home}/.mailfilter
expanded file: /home/user1/.mailfilter
stat() yielded -1
errno = 2
maildrop router skipped: file check
--------> spamcheck_router router <--------
local_part=user1 domain=localhost
checking for local user
finduser used cached passwd data for user1
checking "condition"
calling spamcheck_router router
spamcheck_router router called for user1 [at] localhos
domain = localhost
set transport spamcheck
queued for spamcheck transport: local_part = user1
domain = localhost
errors_to=NULL
domain_data=NULL localpart_data=NULL
routed by spamcheck_router router
envelope to: user1 [at] localhos
transport: spamcheck
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
After routing:
Local deliveries:
user1 [at] localhos
Remote deliveries:
Failed addresses:
Deferred addresses:
search_tidyup called
>>>>>>>>>>>>>>>> Local deliveries >>>>>>>>>>>>>>>>
--------> user1 [at] localhos <--------
locking /var/spool/exim4/db/retry.lockfile
locked /var/spool/exim4/db/retry.lockfile
opened hints database /var/spool/exim4/db/retry: flags=0
dbfn_read: key=T:user1 [at] localhos
no retry record exists
search_tidyup called
changed uid/gid: local delivery to user1 <user1 [at] localhos> transport=spamche
ck
uid=102 gid=102 pid=16952
auxiliary group list: <none>
home=/tmp current=/tmp
set_process_info: 16952 delivering 1GecpX-0004J7-VY to user1 using spamcheck
direct command:
argv[0] = /usr/bin/spamc
direct command after expansion:
argv[0] = /usr/bin/spamc
T: spamassassin_pipe for user1 [at] localhos
spamcheck transport entered
direct command:
argv[0] = /usr/sbin/exim4
argv[1] = -oMr
argv[2] = spam-scanned
argv[3] = -bS
direct command after expansion:
argv[0] = /usr/sbin/exim4
argv[1] = -oMr
argv[2] = spam-scanned
argv[3] = -bS
set_process_info: 16954 reading output from |/usr/sbin/exim4 -oMr
spam-scanned -
bS
Writing message to pipe
writing data block fd=9 size=0 timeout=3600
writing data block fd=9 size=35 timeout=3600
writing data block fd=9 size=28 timeout=3600
writing data block fd=9 size=5 timeout=3600
process 16955 running as transport filter: write=10 read=11
process 16956 writing to transport filter
writing data block fd=10 size=246 timeout=3600
copying from the filter
waiting for filter process
waiting for writing process
writing data block fd=9 size=520 timeout=3600
end of filtering transport writing: yield=1
writing data block fd=9 size=0 timeout=3600
writing data block fd=9 size=2 timeout=3600
spamcheck transport yielded 0
search_tidyup called
journalling user1 [at] localhos
spamcheck transport returned OK for user1 [at] localhos
post-process user1 [at] localhos (0)
user1 [at] localhos delivered
LOG: MAIN
=> user1 <user1 [at] localhos> R=spamcheck_router T=spamcheck
>>>>>>>>>>>>>>>> deliveries are done >>>>>>>>>>>>>>>>
changed uid/gid: post-delivery tidying
uid=102 gid=102 pid=16951
auxiliary group list: <none>
set_process_info: 16951 tidying up after delivering 1GecpX-0004J7-VY
Processing retry items
Succeeded addresses:
user1 [at] localhos: no retry items
Failed addresses:
Deferred addresses:
end of retry processing
LOG: MAIN
Completed
end delivery of 1GecpX-0004J7-VY
search_tidyup called
search_tidyup called
>>>>>>>>>>>>>>>> Exim pid=16951 terminating with rc=0 >>>>>>>>>>>>>>>>

and now its getting interesting: in /var/log/exim4/mainlog (=LOG: MAIN) it
reads
2006-10-30 20:31:14 1GecpX-0004J7-VY <= root [at] domain U=root P=local S=246
2006-10-30 20:31:19 1Gecqo-0004PR-Vh <= root [at] domain U=Debian-exim
P=spam-scanned S=664 id=E1GecpX-0004J7-VY [at] server
2006-10-30 20:31:19 1Gecqo-0004PR-Vh => user1 <user1 [at] localhos> R=local_user
T=cyrus_delivery
2006-10-30 20:31:19 1Gecqo-0004PR-Vh Completed
2006-10-30 20:31:19 1GecpX-0004J7-VY => user1 <user1 [at] localhos> R=spamcheck_
router T=spamcheck
2006-10-30 20:31:19 1GecpX-0004J7-VY Completed

I have then 2 mail-ids: 1GecpX-0004J7-VY und 1Gecqo-0004PR-Vh. The -Vh
is not contained in the in the debug infos but both are sent to cyrus which
then recognizes a duplicate and removes one of them. Moreover, the mail is
also processed twice by spamassassin, interesting wise called one time with
user nobody (wrong) and second time with user Debian-exim (correct) and via
two different running instances of spamd.

According to my understanding the spamcheck_router may only be used if
spam-scanned protocol parameter is not set. But als on the other path it is
called although in the log file it is shown that the local_user router is
used (which is after my spamcheck_router in my config and should therefore
not be reached !?!)

Does anybody has an idea what the root cause could be for that behavior?

I'm looking forward to your reply

BR Clemens

--
## List details at http://www.exim.org/mailman/listinfo/exim-users
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://www.exim.org/eximwiki/

hs at schlittermann

Oct 31, 2006, 2:58 PM

Post #2 of 3 (333 views)
Permalink

Re: exim processes mails twice [In reply to]

Dr. Clemens Hardewig <clemens.hardewig [at] crandale> (Di 31 Okt 2006 23:40:53 CET):
> Hello,
>
> I'm running an fetchmail/exim/cyrus installation under Debian Sarge with
> Spamassassin.
>
> I have a quite bizarre problem that my exim is processing my mails twice:
> Executing

It looks like you take incoming messages, send them to spamc and spamc
in turn sends them back to Exim via a second invocation of Exim.

(It's the "classical" AMaViS model.)

So from exims POV the mail is there twice, Exim can't know that it's the
message it has already seen.)

Way out?

Use spamc as transport filter.
Or use SA-Exim.
Or use the spam capabilities in ACL.

Best regards from Dresden
Viele GrÃ¼ÃŸe aus Dresden
Heiko Schlittermann
--
SCHLITTERMANN.de ---------------------------- internet & unix support -
Heiko Schlittermann HS12-RIPE -----------------------------------------
gnupg encrypted messages are welcome - key ID: 48D0359B ---------------
gnupg fingerprint: 3061 CFBF 2D88 F034 E8D2 7E92 EE4E AC98 48D0 359B -

Attachments:

signature.asc (0.18 KB)

clemens.hardewig at crandale

Nov 1, 2006, 10:15 AM

Post #3 of 3 (345 views)
Permalink

Re: exim processes mails twice [In reply to]

Am Dienstag, 31. Oktober 2006 23:58 schrieb Heiko Schlittermann:

> It looks like you take incoming messages, send them to spamc and spamc
> in turn sends them back to Exim via a second invocation of Exim.
>
> (It's the "classical" AMaViS model.)
>
> So from exims POV the mail is there twice, Exim can't know that it's the
> message it has already seen.)
>
> Way out?
>
> Use spamc as transport filter.
This is precisely the configuration I have:
#####################################################
### transport/30_exim4-config_spamcheck
#####################################################

spamcheck:
debug_print = "T: spamassassin_pipe for $local_part@$domain"
driver = pipe
command = /usr/sbin/exim4 -oMr spam-scanned -bS
use_bsmtp = true
transport_filter = /usr/bin/spamc
home_directory = "/tmp"
current_directory = "/tmp"
user = Debian-exim
group = Debian-exim
return_fail_output = true
log_output = true
message_prefix =
message_suffix =

> Or use SA-Exim.
> Or use the spam capabilities in ACL.
>
>
> Best regards from Dresden
> Viele GrÃ¼ÃŸe aus Dresden
> Heiko Schlittermann

I'm quite fine with the transport filter method except the fact, that for what
reasons ever, each mail is spam scanned twice and therefore the autolearn
function of the bayesfilter is wrong/misleading (see exemplarily syslog):

Nov 1 18:50:30 server spamd[5016]: connection from localhost.localdomain
[127.0.0.1] at port 34287
Nov 1 18:50:31 server spamd[5016]: checking message
^^^^^^^^^ (see below)
<200611011949.10622.xxxx [at] yyyy> aka <YCPZEB.A.bJH.42NSFB [at] murph> for
nobody:65534.
Nov 1 18:50:38 server spamd[5016]: clean message (-2.6/5.0) for nobody:65534
in 7.6 seconds, 2943 bytes.
Nov 1 18:50:38 server spamd[5016]: result: . -2 - BAYES_00,NORMAL_HTTP_TO_IP
scantime=7.6,size=2943,mid=<200611011949.10622.xxxxx [at] yyyy>,rmid=<YCPZEB.A.bJ
H.42NSFB [at] murph>,bayes=5.55111512312578e-17,autolearn=ham
^^^^^^^^^^^^^^^ HERE OK
Now the second instance of spamd is called (why, from where??):
Nov 1 18:50:38 server spamd[5017]: connection from localhost.localdomain
[127.0.0.1] at port 34292
Nov 1 18:50:38 server spamd[5017]: processing message
^^^^^^^^^^^ (see
below)
<200611011949.10622.xxxxx [at] yyyy> aka <YCPZEB.A.bJH.42NSFB [at] murph> for
Nov 1 18:50:50 server spamd[5017]: clean message (-2.6/5.0) for
Debian-exim:65534 in 11.5 seconds, 2967 bytes.
Nov 1 18:50:50 server spamd[5017]: result: . -2 - BAYES_00,NORMAL_HTTP_TO_IP
scantime=11.5,size=2967,mid=<200611011949.10622.xxxx [at] yyyyy>,rmid=<YCPZEB.A.b
JH.42NSFB [at] murph>,bayes=0,autolearn=unavailable
^^^^^^^^^^^^^^^^^^^^^^ here wrong and result of the fact that
the scan results are already in the bayes db

A Mapping of the exim mail ID shows that these are the two different Mail IDs
of the two exim calls i described yesterday. Both mails are after processing
transferred to the imap server (Cyrus) which then detects the duplicate and
drops one (unf. the one with the wrong result :((()

Are the calls of spamd at all equal (NOTE: In the first call, the email is
CHECKED, in the second run, it is PROCESSED) Is there any fix in
configuration to avoid double call/processing of (portions) of spamd?

questions after questions ....

BR Clemens

--
## List details at http://www.exim.org/mailman/listinfo/exim-users
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://www.exim.org/eximwiki/

Index | Next | Previous | View Threaded

Interested in having your list archived? Contact Gossamer Threads