Google Groups no longer supports new Usenet posts or subscriptions. Historical content remains viewable.
Dismiss

amavis Delivery status notification(DSN) failing

74 views
Skip to first unread message

Sharma, Ashish

unread,
Apr 8, 2010, 10:05:34 AM4/8/10
to
Hi,

I have a postfix mail server over which I have deployed a custom content filter written in java.

Now I introduced amavisd (containing clamav and spamassassin) as content filter such that the mail is passing in following manner:

===>mail from outside ===> Postfix ====> amavisd ===> custom content filter

I referred the link(http://wiki.centos.org/HowTos/Amavisd) to setup amavisd(containing clamav and spamassassin)


Here my setup is running ok when amavisd is bypassed and mail is directly being sent to custom content filter but I receive following error logs as soon as I start passing my mails via amavisd:

Apr 7 11:36:14 ip-10-194-99-63 postfix/smtpd[3585]: connect from mail-pw0-f48.google.com[209.85.160.48]
Apr 7 11:36:14 ip-10-194-99-63 postfix/smtpd[3585]: BABCC100191: client=mail-pw0-f48.google.com[209.85.160.48]
Apr 7 11:36:14 ip-10-194-99-63 postfix/cleanup[3593]: BABCC100191: message-id=<x2h6c32076e1004070836p2...@mail.gmail.com>
Apr 7 11:36:15 ip-10-194-99-63 postfix/qmgr[3583]: BABCC100191: from=<ashiish...@gmail.com>, size=1966, nrcpt=1 (queue active)
Apr 7 11:36:45 ip-10-194-99-63 postfix/smtpd[3585]: disconnect from mail-pw0-f48.google.com[209.85.160.48]
Apr 7 11:36:54 ip-10-194-99-63 amavis[3264]: (03264-02) (!)rw_loop: leaving rw loop, no progress, last event (select) 34.987 s ago
Apr 7 11:36:54 ip-10-194-99-63 amavis[3264]: (03264-02) (!)SEND via SMTP: <> -> <ashiish...@gmail.com>, 451 4.5.0 From MTA([10.194.99.63]:10030) during fwd-connect (Negative greeting: at (eval 57) line 596, <GEN18> line 162.): id=03264-02
Apr 7 11:36:54 ip-10-194-99-63 amavis[3264]: (03264-02) (!!)TROUBLE in check_mail: delivery-notification FAILED: temporarily unable to send DSN to <ashiish...@gmail.com>: 451 4.5.0 From MTA([10.194.99.63]:10030) during fwd-connect (Negative greeting: at (eval 57) line 596, <GEN18> line 162.): id=03264-02 at /usr/sbin/amavisd line 11359, <GEN18> line 162.
Apr 7 11:36:54 ip-10-194-99-63 amavis[3264]: (03264-02) (!)PRESERVING EVIDENCE in /var/amavis/tmp/amavis-20100407T113615-03264
Apr 7 11:36:54 ip-10-194-99-63 postfix/lmtp[3594]: BABCC100191: to=<ida6786...@dev1.cpgtest.ostinet.net>, relay=127.0.0.1[127.0.0.1]:10024, delay=40, delays=0.54/0.01/0/40, dsn=4.5.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.5.0 Error in processing, id=03264-02, delivery-notification FAILED: temporarily unable to send DSN to <ashiish...@gmail.com>: 451 4.5.0 From MTA([10.194.99.63]:10030) during fwd-connect (Negative greeting: at (eval 57) line 596, <GEN18> line 162.): id=03264-02 at /usr/sbin/amavisd line 11359, <GEN18> line 162. (in reply to end of DATA command))

I have no idea where the problem is actually residing.

Please help

Thanks in advance
Ashish Sharma

Wietse Venema

unread,
Apr 8, 2010, 12:06:35 PM4/8/10
to
Sharma, Ashish:

> Apr 7 11:36:54 ip-10-194-99-63 postfix/lmtp[3594]: BABCC100191: to=<ida6786...@dev1.cpgtest.ostinet.net>, relay=127.0.0.1[127.0.0.1]:10024, delay=40, delays=0.54/0.01/0/40, dsn=4.5.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.5.0 Error in processing, id=03264-02, delivery-notification FAILED: temporarily unable to send DSN to <ashiish...@gmail.com>: 451 4.5.0 From MTA([10.194.99.63]:10030) during fwd-connect (Negative greeting: at (eval 57) line 596, <GEN18> line 162.): id=03264-02 at /usr/sbin/amavisd line 11359, <GEN18> line 162. (in reply to end of DATA command))

The Postfix SMTP server after the filter is giving problems.

What is the result of:

$ telnet 10.194.99.63 10030

Wietse

Mark Martinec

unread,
Apr 8, 2010, 12:34:13 PM4/8/10
to
Ashish,

> I have a postfix mail server over which I have deployed a custom content
> filter written in java.
>
> Now I introduced amavisd (containing clamav and spamassassin) as content
> filter such that the mail is passing in following manner:
>
> ===>mail from outside ===> Postfix ====> amavisd ===> custom content filter
>
> I referred the link(http://wiki.centos.org/HowTos/Amavisd) to setup
> amavisd(containing clamav and spamassassin)
>
> Here my setup is running ok when amavisd is bypassed and mail is directly
> being sent to custom content filter but I receive following error logs as
> soon as I start passing my mails via amavisd:
>

> Apr 7 11:36:54 ip-10-194-99-63

> amavis[3264]: (03264-02) (!)rw_loop: leaving rw loop, no progress,
> last event (select) 34.987 s ago

Apparently your custom content filter is not responding with a SMTP greeting
when amavisd tries to send a delivery notification to it.

At log level 5 you can see what traffic is being passed on to the
back-end server/scanner specified by $notify_method .
Or do a packet capture on a loopback interface if using inet socket.
Make sure your backend filter can handle multiple transactions
within a single SMTP session.

Btw, do you really want to send bounces too to the java filter?
These could be sent directly to Postfix ($notify_method), while
filtered messages could go to your filter ($forward_method).

Mark

Sharma, Ashish

unread,
Apr 9, 2010, 2:41:24 AM4/9/10
to
Wietse,

Following is the requested result:

$telnet 10.194.99.63 10030
Trying 10.194.99.63...
Connected to ip-10-194-99-63.ec2.internal (10.194.99.63).
Escape character is '^]'.
220 Hello
Mail From:ashiish...@gmail.com
503 5.5.1 Error: need EHLO command
EHLO
250 Custom Java SMTP Server
MAIL FROM:ashiish...@gmail.com
250 Ok
RCPT TO:cp_...@dev1.cpgtest.ostinet.net
250 OK
DATA:
354 send data now
Ashish sharma is testing this
.
250 message received
Connection closed by foreign host.


Thanks
Ashish Sharma

Sharma, Ashish

unread,
Apr 9, 2010, 4:33:07 AM4/9/10
to
Mark,

Following is the telnet log with my custom content filter:

$ telnet 10.194.99.63 10030


Trying 10.194.99.63...
Connected to ip-10-194-99-63.ec2.internal (10.194.99.63).
Escape character is '^]'.
220 Hello

HELO


250 Custom Java SMTP Server

MAIL FROM:ashiiis...@gmail.com


250 Ok
RCPT TO: cp_...@dev1.cpgtest.ostinet.net
250 OK
DATA
354 send data now

Testing from local


.
250 message received
Connection closed by foreign host.

My custom content filter is able to support multiple transactions in a simple SMTP session.

Also I changed the $notify_method and redirected it to the postfix, but I don't think it would have any impact on this whole setup.

Still facing the same problem.

Please help.

My amavisd information is:
Product name: amavisd-new
Version: 2.6.4

Thanks in advance
Ashish Sharma

-----Original Message-----
From: owner-pos...@postfix.org [mailto:owner-pos...@postfix.org] On Behalf Of Mark Martinec
Sent: Thursday, April 08, 2010 10:04 PM
To: postfi...@postfix.org
Subject: Re: amavis Delivery status notification(DSN) failing

Ashish,

> I have a postfix mail server over which I have deployed a custom content
> filter written in java.
>
> Now I introduced amavisd (containing clamav and spamassassin) as content
> filter such that the mail is passing in following manner:
>
> ===>mail from outside ===> Postfix ====> amavisd ===> custom content filter
>
> I referred the link(http://wiki.centos.org/HowTos/Amavisd) to setup
> amavisd(containing clamav and spamassassin)
>
> Here my setup is running ok when amavisd is bypassed and mail is directly
> being sent to custom content filter but I receive following error logs as
> soon as I start passing my mails via amavisd:
>

> Apr 7 11:36:54 ip-10-194-99-63

Wietse Venema

unread,
Apr 9, 2010, 6:53:00 AM4/9/10
to
Sharma, Ashish:

> Wietse,
>
> Following is the requested result:
>
> $telnet 10.194.99.63 10030

> Trying 10.194.99.63...
> Connected to ip-10-194-99-63.ec2.internal (10.194.99.63).
> Escape character is '^]'.
> 220 Hello
> Mail From:ashiish...@gmail.com
> 503 5.5.1 Error: need EHLO command
> EHLO
> 250 Custom Java SMTP Server
> MAIL FROM:ashiish...@gmail.com

> 250 Ok
> RCPT TO:cp_...@dev1.cpgtest.ostinet.net
> 250 OK
> DATA:
> 354 send data now
> Ashish sharma is testing this
> .
> 250 message received
> Connection closed by foreign host.

Now you should connect to the same program with 10 connections at
the same time, using the Postfix smtp-source tool.

./smtp-source -c -l 10000 -m 1000 -s 10 -f ashiish...@gmail.com -t cp_...@dev1.cpgtest.ostinet.net 10.194.99.63:100

The Postfix smtp-source tool is distributed with Postfix source
code, and is sometimes installed by Linux distributions.

Wietse

Mark Martinec

unread,
Apr 9, 2010, 8:36:38 AM4/9/10
to
Ashish,

> Attached is the full level 5 log for your reference.

Thank you!

Apr 9 07:17:31 ip-10-194-99-63 amavis[18885]: (18885-05)
(about to connect to [127.0.0.1]:10030) FWD via SMTP:
<ashiish...@gmail.com> -> <ida6786...@dev1.cpgtest.ostinet.net>
Apr 9 07:17:31 ip-10-194-99-63 amavis[18885]: (18885-05)
smtp session: setting up a new session
Apr 9 07:17:31 ip-10-194-99-63 amavis[18885]: (18885-05)
establish_or_refresh, state: down
Apr 9 07:17:31 ip-10-194-99-63 amavis[18885]: (18885-05)
smtp creating socket by IO::Socket::INET to [127.0.0.1]:10030
Apr 9 07:17:31 ip-10-194-99-63 amavis[18885]: (18885-05)
rw_loop: needline=1, flush=0, wr=0, timeout=35
Apr 9 07:17:31 ip-10-194-99-63 amavis[18885]: (18885-05)
rw_loop: receiving
Apr 9 07:17:31 ip-10-194-99-63 amavis[18885]: (18885-05)
rw_loop read 10 chars< 220 Hello\n
Apr 9 07:17:31 ip-10-194-99-63 amavis[18885]: (18885-05)
rw_loop: needline=1, flush=0, wr=0, timeout=35
Apr 9 07:17:56 ip-10-194-99-63 postfix/smtpd[19431]:
disconnect from mail-pw0-f48.google.com[209.85.160.48]
Apr 9 07:18:06 ip-10-194-99-63 amavis[18885]: (18885-05)
(!)rw_loop: leaving rw loop, no progress, last event (select) 34.994 s ago


Your java filter sent a greeting: "220 Hello\n"
instead of: "220 Hello\r\n". Amavisd waited 30 seconds but
end of line (CR LF) never arrived, so the session was aborted.

RFC 5321 (and RFC 2821 and RFC 821) requires that SMTP commands
and replies are terminated by a CRLF, not by a single LF character.

Mark

Sharma, Ashish

unread,
Apr 9, 2010, 8:39:33 AM4/9/10
to
Wietse,

Executed the command you sent, getting the following error message:

fatal: lost connection while sending message

thanks in advance
Ashish Sharma


-----Original Message-----
From: owner-pos...@postfix.org [mailto:owner-pos...@postfix.org] On Behalf Of Wietse Venema
Sent: Friday, April 09, 2010 4:23 PM
To: Postfix users
Subject: Re: amavis Delivery status notification(DSN) failing

Wietse Venema

unread,
Apr 9, 2010, 8:47:48 AM4/9/10
to
Sharma, Ashish:

> Wietse,
>
> Executed the command you sent, getting the following error message:
>
> fatal: lost connection while sending message

Then, your custom SMTP code needs to be replaced. To speed up
development, may I suggest that you consider using already-deployed
SMTP code instead of re-inventing your own.

Wietse

Sharma, Ashish

unread,
Apr 9, 2010, 9:14:34 AM4/9/10
to
Wietse,

Thanks for your suggestion.

Since I am new in this can you suggest some java based deployments that I can use. I too looked for what you have suggested but maybe I didn't looked hard enough.

Thanks in advance

Sharma, Ashish

unread,
Apr 9, 2010, 9:45:50 AM4/9/10
to
Mark,

Accepted your point, but I am actually doing what you have suggested already.

Maybe the proof lies in the fact that my custom content filter is working fine when amavisd is not used and postfix is directly communicating with my component. I am not receiving such problem in that case.

Is it because postfix is little lax in enforcing smtp for content filter?

Thanks in advance
Ashish Sharma

-----Original Message-----
From: owner-pos...@postfix.org [mailto:owner-pos...@postfix.org] On Behalf Of Mark Martinec
Sent: Friday, April 09, 2010 6:07 PM
To: postfi...@postfix.org
Subject: Re: amavis Delivery status notification(DSN) failing

Mark Martinec

unread,
Apr 9, 2010, 9:56:54 AM4/9/10
to
Ashish,

>> Your java filter sent a greeting: "220 Hello\n"
>> instead of: "220 Hello\r\n". Amavisd waited 30 seconds but
>> end of line (CR LF) never arrived, so the session was aborted.
>> RFC 5321 (and RFC 2821 and RFC 821) requires that SMTP commands
>> and replies are terminated by a CRLF, not by a single LF character.
>

> Accepted your point, but I am actually doing what you have suggested
> already.
>
> Maybe the proof lies in the fact that my custom content filter is working
> fine when amavisd is not used and postfix is directly communicating with
> my component. I am not receiving such problem in that case.

> Is it because postfix is little lax in enforcing smtp for content filter?

Yes, it is. (in general, not specific to content filter interfacing)

Mark

Wietse Venema

unread,
Apr 9, 2010, 9:59:18 AM4/9/10
to
Sharma, Ashish:
> Mark,

>
> Accepted your point, but I am actually doing what you have suggested already.
>
> Maybe the proof lies in the fact that my custom content filter is
> working fine when amavisd is not used and postfix is directly
> communicating with my component. I am not receiving such problem
> in that case.

Postfix accepts non-compliant SMTP responses from your home-grown
SMTP code. That does not mean that your program is correct.

You need to fix your code, or better, use code that already works
instead of re-inventing SMTP badly.

Wietse

Sharma, Ashish

unread,
Apr 12, 2010, 10:17:26 AM4/12/10
to
Andreas,

Thanks for the suggestion,

On comparison I found this http://code.google.com/p/subethasmtp/ to be more appropriate(lightweight and easy to use for a simple postfix content filter) than the heavyweight Apache James.

Ashish Sharma

-----Original Message-----
From: owner-pos...@postfix.org [mailto:owner-pos...@postfix.org] On Behalf Of lst_...@kwsoft.de
Sent: Friday, April 09, 2010 7:37 PM
To: postfi...@postfix.org
Subject: RE: amavis Delivery status notification(DSN) failing

Zitat von "Sharma, Ashish" <ashish....@hp.com>:

> Wietse,
>
> Thanks for your suggestion.
>
> Since I am new in this can you suggest some java based deployments
> that I can use. I too looked for what you have suggested but maybe I
> didn't looked hard enough.
>

> Thanks in advance
> Ashish Sharma


http://james.apache.org/

Regards

Andreas

0 new messages