[exim] 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@localhost
... 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@???
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@localhost
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@localhost
unique = user1@localhost
dbfn_read: key=R:localhost
dbfn_read: key=R:user1@localhost
no domain retry record
no address retry record
user1@localhost: queued for routing
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
routing user1@localhost
--------> 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@localhost
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@localhost
--------> 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@localhost
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@localhost
--------> 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@localhost
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@localhost
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@localhost
  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@localhost
  transport: spamcheck
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>
After routing:
  Local deliveries:
    user1@localhost
  Remote deliveries:
  Failed addresses:
  Deferred addresses:
search_tidyup called
>>>>>>>>>>>>>>>> Local deliveries >>>>>>>>>>>>>>>>
--------> user1@localhost <--------
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@localhost
no retry record exists
search_tidyup called
changed uid/gid: local delivery to user1 <user1@localhost> 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@localhost
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@localhost
spamcheck transport returned OK for user1@localhost
post-process user1@localhost (0)
user1@localhost delivered
LOG: MAIN
  => user1 <user1@localhost> 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@localhost: 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@??? U=root P=local S=246
2006-10-30 20:31:19 1Gecqo-0004PR-Vh <= root@??? U=Debian-exim
P=spam-scanned S=664 id=E1GecpX-0004J7-VY@???
2006-10-30 20:31:19 1Gecqo-0004PR-Vh => user1 <user1@localhost> 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@localhost> 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