Ok I finally got some relavent log messages. It looks like something
crazy is happening in forward.c when it looks up an external forward
address, somehow the sender's address gets a little garbled and gets
some random text added to the end of the string (malloc kind of error?).
Anyways, here's the relevant portion of the log...
--------------------- SNIP -----------------------------------
Aug 20 09:35:48 mx postfix/qmgr[1792]: A885C11E566:
from=<[EMAIL PROTECTED]>, size=3448, nrcpt=2 (queue active)
Aug 20 09:35:48 mx amavis[14939]: (14939-13) ESMTP::10024
/var/run/amavis/tmp/amavis-20040820T085615-14939: <[EMAIL PROTECTED]> ->
<[EMAIL PROTECTED]>,<[EMAIL PROTECTED]> Received: SIZE=3448 from
mx.imtco.com ([127.0.0.1]) by localhost (mx [127.0.0.1]) (amavisd-new,
port 10024) with ESMTP id 14939-13; Fri, 20 Aug 2004 09:35:48 -0400 (EDT)
Aug 20 09:35:48 mx amavis[14939]: (14939-13) Checking:
<[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]>,<[EMAIL PROTECTED]>
Aug 20 09:35:50 mx amavis[14939]: (14939-13) spam_scan: hits=-4.9
tests=BAYES_00
Aug 20 09:35:50 mx amavis[14939]: (14939-13) FWD via SMTP:
[127.0.0.1]:10025 <[EMAIL PROTECTED]> ->
<[EMAIL PROTECTED]>,<[EMAIL PROTECTED]>
Aug 20 09:35:50 mx amavis[14939]: (14939-13) Passed, <[EMAIL PROTECTED]>
-> <[EMAIL PROTECTED]>,<[EMAIL PROTECTED]>, Message-ID:
<[EMAIL PROTECTED]>, Hits: -4.9
Aug 20 09:35:50 mx postfix/qmgr[1792]: A90E211E569:
from=<[EMAIL PROTECTED]>, size=3804, nrcpt=2 (queue active)
Aug 20 09:35:50 mx amavis[14939]: (14939-13) TIMING [total 2118 ms] -
SMTP EHLO: 1 (0%), SMTP pre-MAIL: 0 (0%), SMTP pre-DATA-flush: 3 (0%),
SMTP DATA: 38 (2%), body hash: 0 (0%), lookup_sql: 3 (0%), lookup_sql: 2
(0%), mime_decode: 16 (1%), get-file-type: 16 (1%), get-file-type: 10
(0%), decompose_part: 3 (0%), decompose_part: 0 (0%), parts: 0 (0%),
AV-scan-1: 6 (0%), lookup_sql: 2 (0%), lookup_sql: 2 (0%), SA msg read:
2 (0%), SA parse: 1 (0%), SA check: 1875 (89%), fwd-connect: 9 (0%),
fwd-mail-from: 1 (0%), fwd-rcpt-to: 3 (0%), write-header: 2 (0%),
fwd-data: 0 (0%), fwd-data-end: 114 (5%), fwd-rundown: 1 (0%),
unlink-2-files: 5 (0%), rundown: 0 (0%)
Aug 20 09:35:50 mx dbmail/lmtpd[1585]: misc.c, find_bounded: Found
[EMAIL PROTECTED] of length [16] between '<' and '>' so next skip [22]
Aug 20 09:35:50 mx dbmail/lmtpd[1585]: misc.c, find_bounded: Found
[EMAIL PROTECTED] of length [16] between '<' and '>' so next skip [20]
Aug 20 09:35:50 mx dbmail/lmtpd[1585]: misc.c, find_bounded: Found
[EMAIL PROTECTED] of length [17] between '<' and '>' so next skip [21]
Aug 20 09:35:50 mx dbmail/lmtpd[1585]: sort.c, sort_and_deliver: message
id=189542, size=3705 is inserted
Aug 20 09:35:50 mx dbmail/lmtpd[1585]: forward.c,forward: delivering to
[1] external addresses
Aug 20 09:35:50 mx dbmail/lmtpd[1585]: forward.c,forward: opening pipe
to command /usr/sbin/sendmail -f [EMAIL PROTECTED]
[EMAIL PROTECTED]
Aug 20 09:35:50 mx dbmail/lmtpd[1585]: forward.c,forward: sending
message id number [189541] to forward pipe
Aug 20 09:35:50 mx dbmail/lmtpd[1585]: ChildSighandler(): got signal [17]
Aug 20 09:35:50 mx postfix/qmgr[1792]: E5A1511E566:
from=<[EMAIL PROTECTED]>, size=3915, nrcpt=1 (queue active)
Aug 20 09:35:51 mx amavis[14872]: (14872-12) ESMTP::10024
/var/run/amavis/tmp/amavis-20040820T085305-14872:
<[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]> Received:
SIZE=3915 from mx.imtco.com ([127.0.0.1]) by localhost (mx [127.0.0.1])
(amavisd-new, port 10024) with ESMTP id 14872-12 for
<[EMAIL PROTECTED]>; Fri, 20 Aug 2004 09:35:51 -0400 (EDT)
Aug 20 09:35:51 mx amavis[14872]: (14872-12) Checking:
<[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]>
Aug 20 09:35:51 mx amavis[14872]: (14872-12) spam_scan: hits=-4.9
tests=BAYES_00
Aug 20 09:35:51 mx amavis[14872]: (14872-12) FWD via SMTP:
[127.0.0.1]:10025 <[EMAIL PROTECTED]> ->
<[EMAIL PROTECTED]>
Aug 20 09:35:51 mx postfix/qmgr[1792]: 53CE411E569:
from=<[EMAIL PROTECTED]>, size=4295, nrcpt=1 (queue active)
Aug 20 09:35:51 mx amavis[14872]: (14872-12) Passed,
<[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]>, Message-ID:
<[EMAIL PROTECTED]>, Hits: -4.9
Aug 20 09:35:51 mx amavis[14872]: (14872-12) TIMING [total 466 ms] -
SMTP EHLO: 1 (0%), SMTP pre-MAIL: 0 (0%), SMTP pre-DATA-flush: 102
(22%), SMTP DATA: 39 (8%), body hash: 0 (0%), lookup_sql: 2 (1%),
mime_decode: 16 (4%), get-file-type: 13 (3%), get-file-type: 10 (2%),
decompose_part: 3 (1%), decompose_part: 0 (0%), parts: 0 (0%),
AV-scan-1: 3 (1%), lookup_sql: 2 (0%), SA msg read: 2 (0%), SA parse: 1
(0%), SA check: 178 (38%), fwd-connect: 8 (2%), fwd-mail-from: 1 (0%),
fwd-rcpt-to: 1 (0%), write-header: 3 (1%), fwd-data: 0 (0%),
fwd-data-end: 72 (15%), fwd-rundown: 2 (0%), unlink-2-files: 3 (1%),
rundown: 0 (0%)
Aug 20 09:35:51 mx postfix/qmgr[1792]: 92D9B11E566: from=<>, size=6025,
nrcpt=1 (queue active)
Aug 20 09:35:51 mx postfix/qmgr[1792]: 92D9B11E566:
to=<[EMAIL PROTECTED]>, relay=none, delay=0, status=bounced (bad
address syntax: "[EMAIL PROTECTED]")
------------------------- SNIP --------------------------------------
As you can see, some time after dbmail-lmtp does a lookup and before
it actually does the pipe to sendmail, some extra garbage chars get
added to the end of the sender address. Sometimes this manifests itself
by sendmail interpreting the extra charaters as a second email address
local to it's self, but most of the time it bounces the email due to
it being malformed...
This is a pretty critical bug I'd say. Any help fixing this asap would
be very much appreciated...
Also I didn't notice this until after switching to RC8...previously
I was using an older cvs version...not exactly sure what date in cvs
I was using though...
Thanks,
Doug Stanley
Ilja Booij wrote:
Hi,
Douglas Stanley wrote:
I just upgraded to RC8 the other day from an older cvs version. First of
all, when was the table name prefix added? That threw me off for a bit.
Anyways, now I'm noticing some strange things happening..well atleast
one strange thing. My setup is as follows:
postfix -> amavisd-new+spamassassin+clamav -> postfix -> dbmail
That is our "new" email server, we also have an old email server that
is being phased out. The new one is out front accepting all incoming
mail, and I have forwards setup in dbmail to redirect mail to the old
server for those people still on the old server.
What I notice is that every once in a while, when a mail for someone
on the old server comes in, that it's first pass through the system
works fine, but sometime after dbmail-lmtp is called and it re-sends
the forward through the system, some thing happens that causes it to
be sent to multiple addresses...
For example, a mail comes in for [EMAIL PROTECTED] and goes through the
content filter and then gets handed off to dbmail, dbmail looks it up
and sees it is a forward to [EMAIL PROTECTED] and then goes
to forward it on to that address...lets also say that the new mailserver
is mx.example.com...
So as the new forwarded mail from dbmail goes through the system all of
a sudden the mail is not just to [EMAIL PROTECTED] it's now
addressed to [EMAIL PROTECTED] and random weird things like
[EMAIL PROTECTED] or [EMAIL PROTECTED]
My guess is that there are extra characters getting added sometime after
dbmail sends out the forward message that postfix is translating into
local recipients and therefore adds the @mx.example.com domain to them.
Any ideas on what would cause this to happen?
No idea yet,
would you care adding some log output from dbmail and postfix indicating
the problem?
Thanks,
Doug
p.s. any timeline on the official release of 2.0? Also, are there going
to be anymore database schema changes?
No more database schema changes before 2.0. If rc8 proves to be stable,
it will be released as 2.0.0. Maybe we'll have to add some small
patches, but nothing major.
Ilja
begin:vcard
fn:Douglas Stanley
n:Stanley;Douglas
org:Integrated Marketing Technologies;IT
adr:;;2945 Carquest Dr.;Brunswick;Ohio;44212;USA
email;internet:[EMAIL PROTECTED]
title:Systems Administrator
tel;work:330-220-6715
x-mozilla-html:FALSE
url:http://www.imtco.com
version:2.1
end:vcard
