amavis Delivery status notification(DSN) failing

[Sharma, Ashish]

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=<***@mail.gmail.com>
Apr 7 11:36:15 ip-10-194-99-63 postfix/qmgr[3583]: BABCC100191: from=<***@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: <> -> <***@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 <***@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=<***@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 <***@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

------------------------------------------------------------------------------
Download Intel&#174; Parallel Studio Eval
Try the new software tools for yourself. Speed compiling, find bugs
proactively, and fine-tune applications for parallel performance.
See why Intel Parallel Studio got high marks during beta.
http://p.sf.net/sfu/intel-sw-dev
_______________________________________________
AMaViS-user mailing list
AMaViS-***@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user
AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/howto/

[Mark Martinec]

Ashish,

Post by Sharma, 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
===>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
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

------------------------------------------------------------------------------
Download Intel&#174; Parallel Studio Eval
Try the new software tools for yourself. Speed compiling, find bugs
proactively, and fine-tune applications for parallel performance.
See why Intel Parallel Studio got high marks during beta.
http://p.sf.net/sfu/intel-sw-dev
_______________________________________________
AMaViS-user mailing list
AMaViS-***@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user
AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/howto/

[Sharma, Ashish]

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:***@gmail.com
250 Ok
RCPT TO: ***@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: Mark Martinec [mailto:Mark.Martinec+***@ijs.si]
Sent: Thursday, April 08, 2010 10:03 PM
To: amavis-***@lists.sourceforge.net
Subject: Re: [AMaViS-user] amavis Delivery status notification(DSN) failing

Ashish,

Post by Sharma, 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
===>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
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

------------------------------------------------------------------------------
Download Intel&#174; Parallel Studio Eval
Try the new software tools for yourself. Speed compiling, find bugs
proactively, and fine-tune applications for parallel performance.
See why Intel Parallel Studio got high marks during beta.
http://p.sf.net/sfu/intel-sw-dev
_______________________________________________
AMaViS-user mailing list
AMaViS-***@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user
AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/howto/

------------------------------------------------------------------------------
Download Intel&#174; Parallel Studio Eval
Try the new software tools for yourself. Speed compiling, find bugs
proactively, and fine-tune applications for parallel performance.
See why Intel Parallel Studio got high marks during beta.
http://p.sf.net/sfu/intel-sw-dev
_______________________________________________
AMaViS-user mailing list
AMaViS-***@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user
AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/howto/

[Mark Martinec]

Ashish,

Post by Sharma, Ashish

Post by Sharma, Ashish
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

[...]
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 send me the full level 5 amavisd log - either set
$log_level=5; or start amavisd with a debug option
and capture its output, e.g.:

# amavisd debug 2>&1 | tee 0.log

Mark

------------------------------------------------------------------------------
Download Intel&#174; Parallel Studio Eval
Try the new software tools for yourself. Speed compiling, find bugs
proactively, and fine-tune applications for parallel performance.
See why Intel Parallel Studio got high marks during beta.
http://p.sf.net/sfu/intel-sw-dev
_______________________________________________
AMaViS-user mailing list
AMaViS-***@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user
AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/howto/

[Mark Martinec]

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:
<***@gmail.com> -> <***@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

------------------------------------------------------------------------------
Download Intel&#174; Parallel Studio Eval
Try the new software tools for yourself. Speed compiling, find bugs
proactively, and fine-tune applications for parallel performance.
See why Intel Parallel Studio got high marks during beta.
http://p.sf.net/sfu/intel-sw-dev
_______________________________________________
AMaViS-user mailing list
AMaViS-***@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user
AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/howto/

[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.

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

Thanks in advance
Ashish Sharma

-----Original Message-----
From: Mark Martinec [mailto:Mark.Martinec+***@ijs.si]
Sent: Friday, April 09, 2010 6:05 PM
To: amavis-***@lists.sourceforge.net
Subject: Re: [AMaViS-user] amavis Delivery status notification(DSN) failing

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:
<***@gmail.com> -> <***@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

------------------------------------------------------------------------------
Download Intel&#174; Parallel Studio Eval
Try the new software tools for yourself. Speed compiling, find bugs
proactively, and fine-tune applications for parallel performance.
See why Intel Parallel Studio got high marks during beta.
http://p.sf.net/sfu/intel-sw-dev
_______________________________________________
AMaViS-user mailing list
AMaViS-***@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user
AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/howto/

------------------------------------------------------------------------------
Download Intel&#174; Parallel Studio Eval
Try the new software tools for yourself. Speed compiling, find bugs
proactively, and fine-tune applications for parallel performance.
See why Intel Parallel Studio got high marks during beta.
http://p.sf.net/sfu/intel-sw-dev
_______________________________________________
AMaViS-user mailing list
AMaViS-***@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user
AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/howto/