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:<some...@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:<anotheraut...@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:<adifferenaut...@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]
