Invalid response code: 503 5.7.0 Error: access denied

Discussion:

(too old to reply)

George Forman

2010-11-17 17:24:12 UTC

All,

We are experiencing a problem where Postfix (Using 2.6.2) continuously returns a 503 5.7.0 Error: access denied response.

The scenario is as follows (see log snipet below for sequence details):
The client MTA attempts to send a message. On the DOT command, Postfix returns: '451 4.3.0 Error: queue file write error'
The client MTA sends a RSET command. Postfix responds with '503 5.7.0 Error: access denied'
The client MTA ignores the RSET response (based on RFC2821).
The client MTA sends MAIL FROM command. Postfix responds with '503 5.7.0 Error: access denied'
The client MTA bounces the message.
The client MTA repeats sequence (RSET, MAIL FROM and bounces the message) until Postfix hard error limit has been exceeded (ours is set to 75).
Postfix closes the connnection.

My analysis has shown the Postfix's milter interface fails when waiting for a response.
I am still actively investigating specifically the vstream event that triggers CLEANUP_STAT_WRITE to be returned.

My QUICK FIX was to modify the 503 to a 521 error code in smtpd.c (smtpd_proto function).
This prevented the problem from continuing.

I am looking for suggestions on a longer term solution.
I have made a change in smtpd_proto function:

/* XXX We use the real client for connect access control. */
if (state->access_denied && cmdp->action != quit_cmd) {
smtpd_chat_reply(state, "503 5.7.0 Error: access denied for %s",
state->namaddr); RFC 2821 Sec 3.1 */
state->error_count++;
continue;
}

New code:
/* XXX We use the real client for connect access control. */
if (state->access_denied &&
(! (cmdp->action == quit_cmd || cmdp->action == rset_cmd))) {
smtpd_chat_reply(state, "%s", state->access_denied);
state->error_count++;
continue;
}

The only side effect (I have found) is the following case where access to the host response is
changed on any commands.

New code: On connect this is returned:
554 5.7.1 <remote.mta.client[xxx.xx.xxx.xxx]>: Client host rejected: Access denied
New code: Any commands would return:

554 5.7.1 <remote.mta.client[xxx.xx.xxx.xxx]>: Client host rejected: Access denied

Old code: On connect this is returned:

554 5.7.1 <remote.mta.client[xxx.xx.xxx.xxx]>: Client host rejected: Access denied
Old code: Any commands would return:
503 5.7.0 Error: access denied for remote.mta.clent[xxx.xx.xxx.xxx]

I don't know if my solution breaks RFC2821 Sec 3.1.
Any help is greatly appreciated.

George

Log snipet:

Nov 11 14:03:24 mtain-dc12 postfix/smtpd[26639]: rec_put: type N len 0 data
Nov 11 14:03:24 mtain-dc12 postfix/smtpd[26639]: rec_put: type N len 45 data ------=_Ne
Nov 11 14:03:24 mtain-dc12 postfix/smtpd[26639]: rec_put: type N len 0 data
Nov 11 14:03:24 mtain-dc12 postfix/smtpd[26639]: rec_put: type X len 0 data
Nov 11 14:03:24 mtain-dc12 postfix/smtpd[26639]: rec_put: type E len 0 data
Nov 11 14:03:24 mtain-dc12 postfix/smtpd[26639]: vstream_fflush_some: fd 24 flush 1079
==> added debugging log messages
Nov 11 14:03:24 mtain-mb02 postfix/smtpd-log[26639]: vstream_buf_get_ready: read_fn flags indicate VSTREAM_FLAG_TIMEOUT
Nov 11 14:03:24 mtain-mb02 postfix/smtpd-log[26639]: attr_scan0: EOF Check
Nov 11 14:03:24 mtain-mb02 postfix/smtpd-log[26639]: mail_stream_finish_ipc: attr_scan failed != 2 - CLEANUP_STAT_WRITE
===> end of added debugging log messages
Nov 11 14:03:29 mtain-dc12 postfix/smtpd[26639]: > remote.mta.clent[xx.xx.xx.xx]: 451 4.3.0 Error: queue file write error
Nov 11 14:03:29 mtain-dc12 postfix/smtpd[26639]: abort all milters
Nov 11 14:03:29 mtain-dc12 postfix/smtpd[26639]: milter8_abort: abort milter inet:localhost:12345
Nov 11 14:03:29 mtain-dc12 postfix/smtpd[26639]: watchdog_pat: 0xf3a8a40
Nov 11 14:03:29 mtain-dc12 postfix/smtpd[26639]: vstream_fflush_some: fd 20 flush 41
Nov 11 14:03:29 mtain-dc12 postfix/smtpd[26639]: vstream_buf_get_ready: fd 20 got 6
Nov 11 14:03:29 mtain-dc12 postfix/smtpd[26639]: < remote.mta.clent[xx.xx.xx.xx]: RSET
Nov 11 14:03:29 mtain-dc12 postfix/smtpd[26639]: > remote.mta.clent[xx.xx.xx.xx]: 503 5.7.0 Error: access denied for remote.mta.clent[xx.xx.xx.xx]
Nov 11 14:03:29 mtain-dc12 postfix/smtpd[26639]: watchdog_pat: 0xf3a8a40
Nov 11 14:03:29 mtain-dc12 postfix/smtpd[26639]: vstream_fflush_some: fd 20 flush 88
Nov 11 14:03:57 mtain-dc12 postfix/smtpd[26639]: vstream_buf_get_ready: fd 20 got 84
Nov 11 14:03:57 mtain-dc12 postfix/smtpd[26639]: < remote.mta.clent[xx.xx.xx.xx]: MAIL FROM:<***@example.com>
Nov 11 14:03:57 mtain-dc12 postfix/smtpd[26639]: > remote.mta.clent[xx.xx.xx.xx]: 503 5.7.0 Error: access denied for remote.mta.clent[xx.xx.xx.xx]
Nov 11 14:03:57 mtain-dc12 postfix/smtpd[26639]: watchdog_pat: 0xf3a8a40
Nov 11 14:03:57 mtain-dc12 postfix/smtpd[26639]: vstream_fflush_some: fd 20 flush 88
Nov 11 14:03:57 mtain-dc12 postfix/smtpd[26639]: vstream_buf_get_ready: fd 20 got 6
Nov 11 14:03:57 mtain-dc12 postfix/smtpd[26639]: < remote.mta.clent[xx.xx.xx.xx]: RSET
Nov 11 14:03:57 mtain-dc12 postfix/smtpd[26639]: > remote.mta.clent[xx.xx.xx.xx]: 503 5.7.0 Error: access denied for remote.mta.clent[xx.xx.xx.xx]
Nov 11 14:03:57 mtain-dc12 postfix/smtpd[26639]: watchdog_pat: 0xf3a8a40
Nov 11 14:03:57 mtain-dc12 postfix/smtpd[26639]: vstream_fflush_some: fd 20 flush 88
Nov 11 14:04:09 mtain-dc12 postfix/smtpd[26639]: vstream_buf_get_ready: fd 20 got 33
Nov 11 14:04:09 mtain-dc12 postfix/smtpd[26639]: < remote.mta.client[xx.xx.xx.xx]: MAIL FROM:<***@example.com>
Nov 11 14:04:09 mtain-dc12 postfix/smtpd[26639]: > remote.mta.client[xx.xx.xx.xx]: 503 5.7.0 Error: access denied for remote.mta.client[xx.xx.xx.xx]
Nov 11 14:04:09 mtain-dc12 postfix/smtpd[26639]: watchdog_pat: 0xf3a8a40
Nov 11 14:04:09 mtain-dc12 postfix/smtpd[26639]: vstream_fflush_some: fd 20 flush 88
Nov 11 14:04:09 mtain-dc12 postfix/smtpd[26639]: vstream_buf_get_ready: fd 20 got 6
Nov 11 14:04:09 mtain-dc12 postfix/smtpd[26639]: < remote.mta.client[xx.xx.xx.xx]: RSET
Nov 11 14:04:09 mtain-dc12 postfix/smtpd[26639]: > remote.mta.client[xx.xx.xx.xx]: 503 5.7.0 Error: access denied for remote.mta.client[xx.xx.xx.xx]
Nov 11 14:04:09 mtain-dc12 postfix/smtpd[26639]: watchdog_pat: 0xf3a8a40
Nov 11 14:04:09 mtain-dc12 postfix/smtpd[26639]: vstream_fflush_some: fd 20 flush 88
Nov 11 14:04:31 mtain-dc12 postfix/smtpd[26639]: vstream_buf_get_ready: fd 20 got 36
Nov 11 14:04:31 mtain-dc12 postfix/smtpd[26639]: < remote.mta.client[xx.xx.xx.xx]: MAIL FROM:<***@example.om>
Nov 11 14:04:31 mtain-dc12 postfix/smtpd[26639]: > remote.mta.client[xx.xx.xx.xx]: 503 5.7.0 Error: access denied for remote.mta.client[xx.xx.xx.xx]

Victor Duchovni

2010-11-17 18:01:05 UTC

Permalink

Post by George Forman
The client MTA attempts to send a message. On the DOT command, Postfix returns: '451 4.3.0 Error: queue file write error'

This happens when a milter malfunctions. Check your logs, they contain
lots of relevant details.

Post by George Forman
The client MTA sends a RSET command. Postfix responds with '503 5.7.0 Error: access denied'

Postfix is intended to disconnect with a:

421 4.3.0 Mail system error

The code in question:

if (smtpd_milters != 0 && (state->err & CLEANUP_STAT_WRITE) != 0)
state->access_denied = mystrdup("421 4.3.0 Mail system error");

does not have the intended effect.

Post by George Forman
The client MTA ignores the RSET response (based on RFC2821).

It should not ignore a 5XX return code from RSET. It should disconnect.

Post by George Forman
The client MTA sends MAIL FROM command. Postfix responds with '503 5.7.0 Error: access denied'

The client is wrong to keep re-using a session after a 5XX error on RSET.

Post by George Forman
My analysis has shown the Postfix's milter interface fails when waiting
for a response.

More likely, the milter, not the interface, but this is what I
expected before getting this far in your post.

Post by George Forman
I am still actively investigating specifically the vstream event that
triggers CLEANUP_STAT_WRITE to be returned.

Most likely a milter failed. Look in the logs!

Post by George Forman
My QUICK FIX was to modify the 503 to a 521 error code in smtpd.c
(smtpd_proto function).
I am looking for suggestions on a longer term solution.
/* XXX We use the real client for connect access control. */
if (state->access_denied &&
(! (cmdp->action == quit_cmd || cmdp->action == rset_cmd))) {
smtpd_chat_reply(state, "%s", state->access_denied);
state->error_count++;
continue;
}

No, RFC 2821/5321 notwithstanding, Postfix must reject RSET, to give
clients a chance to disconnect before before real mail is rejected.
So DO NOT exempt "rset_cmd". Otherwise, the change makes sense. Postfix
gives the intended response after "." (Queue file write error) and
the next command if any (say RSET) triggers a "421" disconnect.

--
Viktor.

Victor Duchovni

2010-11-17 18:23:52 UTC

Permalink

Post by Victor Duchovni

Post by George Forman
I am looking for suggestions on a longer term solution.
/* XXX We use the real client for connect access control. */
if (state->access_denied &&
(! (cmdp->action == quit_cmd || cmdp->action == rset_cmd))) {
smtpd_chat_reply(state, "%s", state->access_denied);
state->error_count++;
continue;
}

The problem here is that smtpd_access_denied is misused from its original
intent of reporting 503 after a client fails to heed a 554 banner. Perhaps
the intended "421" disconnect on the next command should use a different
mechanism, or alternatively the code above could peek at the 2nd and 3rd
characters of the buffer and disconnect if these match "21" (a big ugly,
but avoids new complexity in the internal state).

--
Viktor.

George Forman

2010-11-17 19:26:35 UTC

Permalink

Date: Wed, 17 Nov 2010 13:01:05 -0500
Subject: Re: Invalid response code: 503 5.7.0 Error: access denied

Post by George Forman
The client MTA attempts to send a message. On the DOT command, Postfix returns: '451 4.3.0 Error: queue file write error'

This happens when a milter malfunctions. Check your logs, they contain
lots of relevant details.

Yes - The milter is failing to respond in this case.

Post by George Forman
The client MTA sends a RSET command. Postfix responds with '503 5.7.0 Error: access denied'

421 4.3.0 Mail system error
if (smtpd_milters != 0 && (state->err & CLEANUP_STAT_WRITE) != 0)
state->access_denied = mystrdup("421 4.3.0 Mail system error");
does not have the intended effect.

Post by George Forman
The client MTA ignores the RSET response (based on RFC2821).

It should not ignore a 5XX return code from RSET. It should disconnect.

I agree. The MTA client is not honoring the response code sent by Postfix.
This is the crux of our problem. We cannot get the remote MTA to fix their client
and we're forced to make changes.

Post by George Forman
The client MTA sends MAIL FROM command. Postfix responds with '503 5.7.0 Error: access denied'

The client is wrong to keep re-using a session after a 5XX error on RSET.

Post by George Forman
My analysis has shown the Postfix's milter interface fails when waiting
for a response.

More likely, the milter, not the interface, but this is what I
expected before getting this far in your post.

Post by George Forman
I am still actively investigating specifically the vstream event that
triggers CLEANUP_STAT_WRITE to be returned.

Most likely a milter failed. Look in the logs!

Yes it is the milter service that is failing in this situation. I should have made that clear
from the beginning.

Thanks for the feed back. I have tested the changes. The sequence is now:
.
451 4.3.0 Error: queue file write error
RSET
421 4.3.0 Mail system error

This change does violate RFC2821/5321 for RSET:
An SMTP server MUST NOT close the connection as the
result of receiving a RSET; that action is reserved
for QUIT (see Section 4.1.1.10).

By excluding rset_cmd as in the code snipet,
the RSET response is 250 OK.
The next command's response '421 4.3.0 Mail System Error'.

Thoughts?
George

Wietse Venema

2010-11-17 19:37:27 UTC

Permalink

Post by Victor Duchovni

I forced the 503 reply code for RFC 2821 compliance in Postfix
1.1.0, and I concluded independently that we can make an exception
for [45]21 here, since those replies are final.

Wietse

Victor Duchovni

2010-11-17 19:48:16 UTC

Permalink

Post by George Forman

Post by Victor Duchovni
No, RFC 2821/5321 notwithstanding, Postfix must reject RSET, to give
clients a chance to disconnect before before real mail is rejected.
So DO NOT exempt "rset_cmd". Otherwise, the change makes sense. Postfix
gives the intended response after "." (Queue file write error) and
the next command if any (say RSET) triggers a "421" disconnect.
--
Viktor.

.
451 4.3.0 Error: queue file write error
RSET
421 4.3.0 Mail system error
An SMTP server MUST NOT close the connection as the
result of receiving a RSET; that action is reserved
for QUIT (see Section 4.1.1.10).

No, an SMTP server may return 421 and disconnect any time it sees fit.

http://tools.ietf.org/html/rfc2821#section-3.9

Post by George Forman
By excluding rset_cmd as in the code snipet,
the RSET response is 250 OK.
The next command's response '421 4.3.0 Mail System Error'.

It is wrong to exclude RSET, since a buffered error response may then
incorrectly reject a new mail transaction. It is better to reject
RSET and give a sanely behaved client a chance to go away before it
runs into more trouble.

For now the impact is only theoretical, since "state->access_denied" is
only set with "delay_reject = no" when a client fails client restrictions,
and so any transaction would have been refused in any case, but it is
best to not set traps for future code changes.

--
Viktor.

Victor Duchovni

2010-11-17 20:03:48 UTC

Permalink

Post by Wietse Venema

Post by Victor Duchovni
The problem here is that smtpd_access_denied is misused from its original
intent of reporting 503 after a client fails to heed a 554 banner. Perhaps
the intended "421" disconnect on the next command should use a different
mechanism, or alternatively the code above could peek at the 2nd and 3rd
characters of the buffer and disconnect if these match "21" (a big ugly,
but avoids new complexity in the internal state).

I forced the 503 reply code for RFC 2821 compliance in Postfix
1.1.0, and I concluded independently that we can make an exception
for [45]21 here, since those replies are final.

Something along the lines of:

Index: src/smtpd/smtpd.c
--- src/smtpd/smtpd.c 7 Oct 2010 20:02:54 -0000 1.1.1.6
+++ src/smtpd/smtpd.c 17 Nov 2010 19:52:05 -0000
@@ -4521,8 +4521,11 @@
}
/* XXX We use the real client for connect access control. */
if (state->access_denied && cmdp->action != quit_cmd) {
- smtpd_chat_reply(state, "503 5.7.0 Error: access denied for %s",
- state->namaddr); /* RFC 2821 Sec 3.1 */
+ if (strncmp(state->acccess_denied+1, "21", 2) == 0)
+ smtpd_chat_reply(state, "%s", state->access_denied);
+ else /* RFC 2821 Sec 3.1 */
+ smtpd_chat_reply(state, "503 5.7.0 Error: access denied"
+ " for %s", state->namaddr);
state->error_count++;
continue;
}

or did I misunderstand?

On a somewhat related note, should the documentation explicitly warn that
with smtpd_delay_reject=no, clients can keep going even when rejected by
helo restrictions, if "smtpd_helo_required = no"? Of course the client
could just not send "helo/ehlo", and avoid the helo restrictions that way.
This may not be clear to those tempted to put substantive checks in
the HELO branch, without enforcing the use of "HELO".

--
Viktor.

Wietse Venema

2010-11-17 20:27:20 UTC

Permalink

Post by Victor Duchovni

Post by Wietse Venema

I forced the 503 reply code for RFC 2821 compliance in Postfix
1.1.0, and I concluded independently that we can make an exception
for [45]21 here, since those replies are final.

Index: src/smtpd/smtpd.c
--- src/smtpd/smtpd.c 7 Oct 2010 20:02:54 -0000 1.1.1.6
+++ src/smtpd/smtpd.c 17 Nov 2010 19:52:05 -0000
@@ -4521,8 +4521,11 @@
}
/* XXX We use the real client for connect access control. */
if (state->access_denied && cmdp->action != quit_cmd) {
- smtpd_chat_reply(state, "503 5.7.0 Error: access denied for %s",
- state->namaddr); /* RFC 2821 Sec 3.1 */
+ if (strncmp(state->acccess_denied+1, "21", 2) == 0)
+ smtpd_chat_reply(state, "%s", state->access_denied);
+ else /* RFC 2821 Sec 3.1 */
+ smtpd_chat_reply(state, "503 5.7.0 Error: access denied"
+ " for %s", state->namaddr);
state->error_count++;
continue;
}
or did I misunderstand?

I had a similar patch that I was going to post 30 mins ago when
someone walked into my room:

*** ./smtpd.c- Thu Sep 30 14:18:18 2010
--- ./smtpd.c Wed Nov 17 14:56:13 2010
***************
*** 4521,4526 ****
--- 4521,4531 ----
}
/* XXX We use the real client for connect access control. */
if (state->access_denied && cmdp->action != quit_cmd) {
+ /* Make exception for final response. */
+ if (strcmp(state->access_denied + 1, "21", 2) == 0) {
+ smtpd_chat_reply(state, "%s", state->access_denied);
+ continue;
+ }
smtpd_chat_reply(state, "503 5.7.0 Error: access denied for %s",
state->namaddr); /* RFC 2821 Sec 3.1 */
state->error_count++;

No point updating the error counter, in case it triggers its own
magical behavior.

Post by Victor Duchovni
On a somewhat related note, should the documentation explicitly warn that
with smtpd_delay_reject=no, clients can keep going even when rejected by
helo restrictions, if "smtpd_helo_required = no"? Of course the client
could just not send "helo/ehlo", and avoid the helo restrictions that way.
This may not be clear to those tempted to put substantive checks in
the HELO branch, without enforcing the use of "HELO".

Um, people who put restrictions on HELO commands need
smtpd_helo_required=yes, regardless of smtpd_delay_reject settings.

Wietse

Stan Hoeppner

2010-11-18 05:51:44 UTC

Permalink

Post by George Forman
All,
We are experiencing a problem where Postfix (Using 2.6.2) continuously returns a 503 5.7.0 Error: access denied response.

Looks like you're also experiencing a problem with someone else gaining
access to your Hotmail account and spamming from it. Change your
password post haste. Also contact NTT and inform them they have a bad
actor operating from the Opsource cloud, at minimum from the following IPs:

206.80.39.140
206.80.39.212

--
Stan

Victor Duchovni

2010-11-18 05:55:44 UTC

Permalink

Post by Wietse Venema
I had a similar patch that I was going to post 30 mins ago when

OK, we are on the same page then.

Post by Wietse Venema

Um, people who put restrictions on HELO commands need
smtpd_helo_required=yes, regardless of smtpd_delay_reject settings.

Yes, my point was that they may not think this through, and
perhaps we should more explicitly explain this in the docs for
smtpd_helo_restrictions, smtpd_delay_reject and in SMTP_ACCESS_README.

--
Viktor.

George Forman

2010-11-19 14:53:03 UTC

Permalink

Date: Thu, 18 Nov 2010 00:55:44 -0500
Subject: Re: Invalid response code: 503 5.7.0 Error: access denied

Post by Wietse Venema
I had a similar patch that I was going to post 30 mins ago when

OK, we are on the same page then.

Post by Wietse Venema

Um, people who put restrictions on HELO commands need
smtpd_helo_required=yes, regardless of smtpd_delay_reject settings.

Yes, my point was that they may not think this through, and
perhaps we should more explicitly explain this in the docs for
smtpd_helo_restrictions, smtpd_delay_reject and in SMTP_ACCESS_README.
--
Viktor.

I've made the change to my local code base. Will this change make it into a 2.7.x release or 2.8?

Wietse Venema

2010-11-19 15:08:19 UTC

Permalink

Post by Wietse Venema
I had a similar patch that I was going to post 30 mins ago when
OK, we are on the same page then.
I've made the change to my local code base. Will this change make
it into a 2.7.x release or 2.8?

It is in Postfix 2.8. I haven't decided if this will be back-ported.
If I back-port every fix to every supported release then I would
not get work done.

This fix is needed for a buggy client that fails to disconnect
after Postfix replies to RSET with an error status. It is unlikely
that OS distributions will pick it up even if I go through the
effort of back-porting and testing.

Wietse

Victor Duchovni

2010-11-19 17:12:43 UTC

Permalink

Post by Wietse Venema

It is in Postfix 2.8. I haven't decided if this will be back-ported.
If I back-port every fix to every supported release then I would
not get work done.
This fix is needed for a buggy client that fails to disconnect
after Postfix replies to RSET with an error status. It is unlikely
that OS distributions will pick it up even if I go through the
effort of back-porting and testing.

That said, if you were feeling very generous, we've had a 2.7.2-RC2 in
the wings for a while. The change to not send 503, when we really mean
"421" is fairly safe. I would not object to inclusion in 2.7.2, (I don't
think we need to go back to 2.4, 2.5 or 2.6).

--
Viktor.

George Forman

2010-11-19 17:21:48 UTC

Permalink

Date: Fri, 19 Nov 2010 12:12:43 -0500
Subject: Re: Invalid response code: 503 5.7.0 Error: access denied

Post by Wietse Venema

It is in Postfix 2.8. I haven't decided if this will be back-ported.
If I back-port every fix to every supported release then I would
not get work done.
This fix is needed for a buggy client that fails to disconnect
after Postfix replies to RSET with an error status. It is unlikely
that OS distributions will pick it up even if I go through the
effort of back-porting and testing.

As long as I know the fix is in 2.8 I know I don't need to carry my patch forwardindefinitely. Having it in a 2.7.x release just makes my life easier but I do understand Wietse'spoint of back-porting and I'm sure their are other higher priorities issue.
Thanks for the quick response.
George