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 [EMAIL PROTECTED]
... 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 [EMAIL PROTECTED]
sender_local=1 ident=root
Non-recipients:
Empty Tree
---- End of tree ----
recipients_count=1
body_linecount=0 message_linecount=6
Delivery address list:
[EMAIL PROTECTED]
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: [EMAIL PROTECTED]
unique = [EMAIL PROTECTED]
dbfn_read: key=R:localhost
dbfn_read: key=R:[EMAIL PROTECTED]
no domain retry record
no address retry record
[EMAIL PROTECTED]: queued for routing
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
routing [EMAIL PROTECTED]
--------> 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 [EMAIL PROTECTED]
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 [EMAIL PROTECTED]
--------> 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 [EMAIL PROTECTED]
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 [EMAIL PROTECTED]
--------> 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 [EMAIL PROTECTED]
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 [EMAIL PROTECTED]
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 [EMAIL PROTECTED]
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: [EMAIL PROTECTED]
transport: spamcheck
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
After routing:
Local deliveries:
[EMAIL PROTECTED]
Remote deliveries:
Failed addresses:
Deferred addresses:
search_tidyup called
>>>>>>>>>>>>>>>> Local deliveries >>>>>>>>>>>>>>>>
--------> [EMAIL PROTECTED] <--------
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:[EMAIL PROTECTED]
no retry record exists
search_tidyup called
changed uid/gid: local delivery to user1 <[EMAIL PROTECTED]> 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 [EMAIL PROTECTED]
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 [EMAIL PROTECTED]
spamcheck transport returned OK for [EMAIL PROTECTED]
post-process [EMAIL PROTECTED] (0)
[EMAIL PROTECTED] delivered
LOG: MAIN
=> user1 <[EMAIL PROTECTED]> 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:
[EMAIL PROTECTED]: 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 <= [EMAIL PROTECTED] U=root P=local S=246
2006-10-30 20:31:19 1Gecqo-0004PR-Vh <= [EMAIL PROTECTED] U=Debian-exim
P=spam-scanned S=664 [EMAIL PROTECTED]
2006-10-30 20:31:19 1Gecqo-0004PR-Vh => user1 <[EMAIL PROTECTED]> 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 <[EMAIL PROTECTED]> 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/
