Data command rejected: Improper use of SMTP command pipelining?
Michael Tokarev
A legitimate mailserver (217.23.20.38 running "Sendmail Pro") tried
to send quite some spam to us, and Postfix rejected several DATA
commands with the above error message.
Yes I do have that check - reject_unauth_pipelining - in smtpd_data_restrictions,
in order to catch worms who don't speak ESMTP but tries to emit all
their crap in one go. It works, especially with some delays for generic
rDNS and the like applied at several points of SMTP conversation. But
this rule should not trigger in this case (for this very session,
smtpd_data_restrictions (as produced by a policy daemon) contained only
single instruction - reject_unauth_pipelining, which should be a no-op
here: the remote speaks ESMTP, we offered PIPELINING, and it's ok to group
MAIL FROM, several RCPT TOs and DATA commands in one packet, -- the remote
must wait for the reply to DATA command before trying to send actual message,
but it is ok to send this command in one packet together with prior RCPTs.
So I wonder why Postfix rejects their DATA command.
Complete session log is below. I changed our addresses into XXXs.
And yes, the remote was trying to send spam to us...
Thanks.
/mjt
Subject: Postfix SMTP server: errors from mail.vzk.nnov.ru[217.23.20.38]
Date: Mon, 4 Dec 2006 15:45:39 +0300 (MSK)
From: MAILER-DAEMON (Mail Delivery System)
To: postmaster (Postmaster)
Transcript of session follows.
Out: 220 hobbit.corpit.ru ESMTP Postfix (2.3.3)
In: EHLO mail.vzk.nnov.ru
Out: 250-hobbit.corpit.ru
Out: 250-PIPELINING
Out: 250-SIZE 10240000
Out: 250-ETRN
Out: 250-ENHANCEDSTATUSCODES
Out: 250-8BITMIME
Out: 250 DSN
In: MAIL FROM:<quinnd...@mapleleafmail.com>
Out: 250 2.1.0 Ok
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: RCPT TO:<xxx>
Out: 550 5.1.1 <xxx>: Recipient address rejected: User unknown
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: DATA
Out: 354 End data with <CR><LF>.<CR><LF>
Out: 250 2.0.0 Ok: queued as 13EDD35830
In: RSET
Out: 250 2.0.0 Ok
In: MAIL FROM:<r.vande...@dispro.nl>
Out: 250 2.1.0 Ok
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: RCPT TO:<xxx>
Out: 450 4.1.7 <r.vande...@dispro.nl>: Sender address rejected: unverified
address: Host or domain name not found. Name service error for
name=mail.emps.equant.com type=A: Host not found, try again
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: DATA
Out: 503 5.5.0 <DATA>: Data command rejected: Improper use of SMTP command
pipelining
In: RSET
Out: 250 2.0.0 Ok
In: MAIL FROM:<polynsky...@rg.ru>
Out: 250 2.1.0 Ok
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: RCPT TO:<xxx>
Out: 550 5.1.7 <polynsky...@rg.ru>: Sender address rejected:
undeliverable address: host mail.rg.ru[212.69.111.7] said: 550
<polynsky...@rg.ru>: Recipient address rejected: User unknown (in
reply to RCPT TO command)
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: RCPT TO:<xxx>
Out: 250 2.1.5 Ok
In: DATA
Out: 503 5.5.0 <DATA>: Data command rejected: Improper use of SMTP command
pipelining
Out: 421 4.7.0 hobbit.corpit.ru Error: too many errors
Session aborted, reason: too many errors
Wietse Venema
> I come across an.. interesting scenario here.
> A legitimate mailserver (217.23.20.38 running "Sendmail Pro") tried
> to send quite some spam to us, and Postfix rejected several DATA
> commands with the above error message.
>
> Yes I do have that check - reject_unauth_pipelining - in smtpd_data_restrictions,
> in order to catch worms who don't speak ESMTP but tries to emit all
> their crap in one go. It works, especially with some delays for generic
> rDNS and the like applied at several points of SMTP conversation. But
> this rule should not trigger in this case (for this very session,
> smtpd_data_restrictions (as produced by a policy daemon) contained only
> single instruction - reject_unauth_pipelining, which should be a no-op
> here: the remote speaks ESMTP, we offered PIPELINING, and it's ok to group
> MAIL FROM, several RCPT TOs and DATA commands in one packet, -- the remote
> must wait for the reply to DATA command before trying to send actual message,
> but it is ok to send this command in one packet together with prior RCPTs.
> So I wonder why Postfix rejects their DATA command.
>
> Complete session log is below. I changed our addresses into XXXs.
> And yes, the remote was trying to send spam to us...
This is the reject_unauth_pipelining implementation:
static int reject_unauth_pipelining(SMTPD_STATE *state,
const char *reply_name, const char *reply_class)
{
const char *myname = "reject_unauth_pipelining";
if (msg_verbose)
msg_info("%s: %s", myname, state->where);
if (state->client != 0
&& SMTPD_STAND_ALONE(state) == 0
&& (vstream_peek(state->client) > 0
|| peekfd(vstream_fileno(state->client)) > 0)
&& (strcasecmp(state->protocol, MAIL_PROTO_ESMTP) != 0
|| strcasecmp(state->where, SMTPD_CMD_DATA) == 0)) {
return (smtpd_check_reject(state, MAIL_ERROR_PROTOCOL,
503, "5.5.0",
"<%s>: %s rejected: Improper use of SMTP command pipelining",
reply_name, reply_class));
}
return (SMTPD_CHECK_DUNNO);
}
The client sent EHLO, so this was called from smtpd_data_restrictions.
I left a copy of the transcript below.
Just to be sure, what protocol is logged with the "unathorized
pipelining reject" ? SMTP or ESMTP? I don't see how state->protocol
could have been reset to SMTP after the first DATA command, but I
want to be sure.
vstream_peek(state->client) > 0
There's a non-zero, positive, amount of unread data in a
VSTREAM buffer.
peekfd(vstream_fileno(state->client)) > 0
ioctl(fd, FIONREAD, (char *) &count) completed without
error and returned a non-zero, positive, number in the "count" variable.
In both cases, a non-zero, positive, result is a definitive no-no
at DATA command time.
Here's the peekfd() implementation:
ssize_t peekfd(int fd)
{
/*
* Anticipate a series of system-dependent code fragments.
*/
#ifdef FIONREAD
int count;
return (ioctl(fd, FIONREAD, (char *) &count) < 0 ? -1 : count);
#else
#error "don't know how to look ahead"
#endif
}
Maybe ioctl FIONREAD is buggy, try it this helps:
< int count;
---
> int count = 0;
How often does this happen, or has this started recently?
Wietse
Victor Duchovni
> Yes I do have that check - reject_unauth_pipelining - in
> smtpd_data_restrictions, in order to catch worms who don't speak ESMTP but
> tries to emit all their crap in one go. It works, especially with some
> delays for generic rDNS and the like applied at several points of SMTP
> conversation. But this rule should not trigger in this case (for this
> very session, smtpd_data_restrictions (as produced by a policy daemon)
> contained only single instruction - reject_unauth_pipelining, which
> should be a no-op here: the remote speaks ESMTP, we offered PIPELINING,
> and it's ok to group MAIL FROM, several RCPT TOs and DATA commands in
> one packet, -- the remote must wait for the reply to DATA command before
> trying to send actual message, but it is ok to send this command in one
> packet together with prior RCPTs. So I wonder why Postfix rejects their
> DATA command.
Have you verified (tcpdump) that no commands were sent before the "DATA"
response from your server?
First message accepted, no expedited message content before "DATA". Then
the connection is cached for re-use, ... Is the "RSET" sent at the end
of the the first message or "just-before" the second message?
> In: MAIL FROM:<r.vande...@dispro.nl>
> Out: 250 2.1.0 Ok
> In: RCPT TO:<xxx>
> Out: 250 2.1.5 Ok
> In: RCPT TO:<xxx>
> Out: 250 2.1.5 Ok
> In: RCPT TO:<xxx>
> Out: 250 2.1.5 Ok
> In: RCPT TO:<xxx>
> Out: 450 4.1.7 <r.vande...@dispro.nl>: Sender address rejected: ...
> In: RCPT TO:<xxx>
> Out: 250 2.1.5 Ok
> In: RCPT TO:<xxx>
> Out: 250 2.1.5 Ok
> In: RCPT TO:<xxx>
> Out: 250 2.1.5 Ok
> In: RCPT TO:<xxx>
> Out: 250 2.1.5 Ok
> In: RCPT TO:<xxx>
> Out: 250 2.1.5 Ok
> In: DATA
> Out: 503 5.5.0 <DATA>: Data command rejected: Improper use of SMTP command
> pipelining
Well, at this point the only thing that can reasonbly be present in the
VSTREAM buffer or in the TCP socket receive buffer is the "RSET" that is
read below. So, assuming that the remote system did not send an expedited
"RSET" with DATA, you have a buggy ioctl(FIONREAD) implementation.
> In: RSET
> Out: 250 2.0.0 Ok
This calls for a "tcpdump"...
--
Viktor.
Disclaimer: off-list followups get on-list replies or get ignored.
Please do not ignore the "Reply-To" header.
To unsubscribe from the postfix-users list, visit
http://www.postfix.org/lists.html or click the link below:
<mailto:majo...@postfix.org?body=unsubscribe%20postfix-users>
If my response solves your problem, the best way to thank me is to not
send an "it worked, thanks" follow-up. If you must respond, please put
"It worked, thanks" in the "Subject" so I can delete these quickly.
Michael Tokarev
> Michael Tokarev:
>> I come across an.. interesting scenario here.
>> A legitimate mailserver (217.23.20.38 running "Sendmail Pro") tried
>> to send quite some spam to us, and Postfix rejected several DATA
>> commands with the above error message.
>>
>> Yes I do have that check - reject_unauth_pipelining - in smtpd_data_restrictions,
>> in order to catch worms who don't speak ESMTP but tries to emit all
>> their crap in one go. It works, especially with some delays for generic
>> rDNS and the like applied at several points of SMTP conversation. But
>> this rule should not trigger in this case (for this very session,
>> smtpd_data_restrictions (as produced by a policy daemon) contained only
>> single instruction - reject_unauth_pipelining, which should be a no-op
>> here: the remote speaks ESMTP, we offered PIPELINING, and it's ok to group
>> MAIL FROM, several RCPT TOs and DATA commands in one packet, -- the remote
>> must wait for the reply to DATA command before trying to send actual message,
>> but it is ok to send this command in one packet together with prior RCPTs.
>> So I wonder why Postfix rejects their DATA command.
Well. Something went wrong in my mind - reject_unauth_pipelining rejects a
command if there's some data to read AFTER the command. So umm.. yes, DATA
is one of such commands after which no DATA should come before a reply, and
so yes, it's perfectly valid to check for pipelining in this case and reject
it if it is indeed the case.
[]
> This is the reject_unauth_pipelining implementation:
I've looked at the code before sending my first email.
But I was confused - see above - hence looked at it from
the totally wrong side, assuming it's rejecting DATA as
coming together with PRIOR commands, not with NEXT commands.
> static int reject_unauth_pipelining(SMTPD_STATE *state,
> const char *reply_name, const char *reply_class)
[]
> }
>
> The client sent EHLO, so this was called from smtpd_data_restrictions.
> I left a copy of the transcript below.
>
> Just to be sure, what protocol is logged with the "unathorized
> pipelining reject" ? SMTP or ESMTP? I don't see how state->protocol
> could have been reset to SMTP after the first DATA command, but I
> want to be sure.
Here are the rejects for this session:
Dec 4 15:44:14 hobbit postfix/smtpd[26231]: 102863582F: reject: DATA from mail.vzk.nnov.ru[217.23.20.38]: 503 5.5.0 <DATA>: Data command rejected: Improper use of SMTP command pipelining; from=<r.vande...@dispro.nl> proto=ESMTP helo=<mail.vzk.nnov.ru>
Dec 4 15:45:29 hobbit postfix/smtpd[26231]: 51F8835830: reject: DATA from mail.vzk.nnov.ru[217.23.20.38]: 503 5.5.0 <DATA>: Data command rejected: Improper use of SMTP command pipelining; from=<polynsky...@rg.ru> proto=ESMTP helo=<mail.vzk.nnov.ru>
So yes, the protocol is ESMTP.
> vstream_peek(state->client) > 0
>
> There's a non-zero, positive, amount of unread data in a
> VSTREAM buffer.
>
> peekfd(vstream_fileno(state->client)) > 0
>
> ioctl(fd, FIONREAD, (char *) &count) completed without
> error and returned a non-zero, positive, number in the "count" variable.
>
> In both cases, a non-zero, positive, result is a definitive no-no
> at DATA command time.
Yes, I see it now.
> Here's the peekfd() implementation:
>
> ssize_t peekfd(int fd)
> {
>
> /*
> * Anticipate a series of system-dependent code fragments.
> */
> #ifdef FIONREAD
> int count;
>
> return (ioctl(fd, FIONREAD, (char *) &count) < 0 ? -1 : count);
> #else
> #error "don't know how to look ahead"
> #endif
> }
>
> Maybe ioctl FIONREAD is buggy, try it this helps:
(initialize a variable used in ioctl(FIONREAD, &var))
I don't think so. I use it alot in my programs on this and other
similar systems - had no issues so far. At least not in this case -
I mean, kernel properly initializes the variable on successeful return.
> How often does this happen, or has this started recently?
I haven't noticied it before. But now as I looked at logs,
I see quite.. some of these:
Dec 4 12:33:00 hobbit postfix/smtpd[20063]: connect from chekirda0.real.kamchatka.ru[85.28.204.43]
Dec 4 12:33:06 hobbit postfix/smtpd[20063]: 75EA73582F: client=chekirda0.real.kamchatka.ru[85.28.204.43]
Dec 4 12:33:29 hobbit postfix/smtpd[20063]: 75EA73582F: reject: RCPT from chekirda0.real.kamchatka.ru[85.28.204.43]: 450 4.1.7 <q...@egroups.com>: Sender address rejected: unverified address: Address verification in progress; from=<q...@egroups.com> to=<XXX> proto=ESMTP helo=<chekirda0.real.kamchatka.ru>
Dec 4 12:33:35 hobbit postfix/smtpd[20063]: 75EA73582F: reject: RCPT from chekirda0.real.kamchatka.ru[85.28.204.43]: 550 5.1.1 <ale...@tls.msk.ru>: Recipient address rejected: User unknown; from=<q...@egroups.com> to=<XXX> proto=ESMTP helo=<chekirda0.real.kamchatka.ru>
Dec 4 12:33:37 hobbit postfix/smtpd[20063]: 75EA73582F: reject: DATA from chekirda0.real.kamchatka.ru[85.28.204.43]: 503 5.5.0 <DATA>: Data command rejected: Improper use of SMTP command pipelining; from=<q...@egroups.com> proto=ESMTP helo=<chekirda0.real.kamchatka.ru>
Dec 4 12:33:47 hobbit postfix/smtpd[20063]: lost connection after RSET from chekirda0.real.kamchatka.ru[85.28.204.43]
Dec 4 12:33:47 hobbit postfix/smtpd[20063]: disconnect from chekirda0.real.kamchatka.ru[85.28.204.43]
Dec 4 15:43:24 hobbit postfix/smtpd[27850]: connect from europoster.lan.edunet.ru[213.184.145.226]
Dec 4 15:43:28 hobbit postfix/smtpd[27850]: 192BC3582A: client=europoster.lan.edunet.ru[213.184.145.226]
Dec 4 15:43:39 hobbit postfix/smtpd[27850]: 192BC3582A: reject: RCPT from europoster.lan.edunet.ru[213.184.145.226]: 550 5.1.7 <pozn...@poczta.onet.pl>: Sender address rejected: undeliverable address: host mx.poczta.onet.pl[213.180.130.86] said: 550 5.7.1 Policy analysis reported: Konto chwilowo niedostepne. Sprobuj pozniej / Requested mail action not taken: mailbox unavailable - Try later rcpt=<pozn...@poczta.onet.pl> (in reply to RCPT TO command); from=<pozn...@poczta.onet.pl> to=<XXX> proto=ESMTP helo=<EUROPOSTER.mshome.net>
Dec 4 15:43:45 hobbit postfix/smtpd[27850]: 192BC3582A: reject: RCPT from europoster.lan.edunet.ru[213.184.145.226]: 550 5.1.1 <ale...@tls.msk.ru>: Recipient address rejected: User unknown; from=<pozn...@poczta.onet.pl> to=<ale...@tls.msk.ru> proto=ESMTP helo=<EUROPOSTER.mshome.net>
Dec 4 15:43:46 hobbit postfix/smtpd[27850]: 192BC3582A: reject: RCPT from europoster.lan.edunet.ru[213.184.145.226]: 550 5.1.1 <aleks...@tls.msk.ru>: Recipient address rejected: User unknown; from=<pozn...@poczta.onet.pl> to=<aleks...@tls.msk.ru> proto=ESMTP helo=<EUROPOSTER.mshome.net>
Dec 4 15:43:54 hobbit postfix/smtpd[27850]: 192BC3582A: reject: DATA from europoster.lan.edunet.ru[213.184.145.226]: 503 5.5.0 <DATA>: Data command rejected: Improper use of SMTP command pipelining; from=<pozn...@poczta.onet.pl> proto=ESMTP helo=<EUROPOSTER.mshome.net>
Dec 4 15:44:04 hobbit postfix/smtpd[27850]: lost connection after DATA from europoster.lan.edunet.ru[213.184.145.226]
Dec 4 15:44:04 hobbit postfix/smtpd[27850]: disconnect from europoster.lan.edunet.ru[213.184.145.226]
Dec 4 15:43:30 hobbit postfix/smtpd[26231]: connect from mail.vzk.nnov.ru[217.23.20.38]
Dec 4 15:43:34 hobbit postfix/smtpd[26231]: 13EDD35830: client=mail.vzk.nnov.ru[217.23.20.38]
Dec 4 15:43:41 hobbit postfix/smtpd[26231]: 13EDD35830: reject: RCPT from mail.vzk.nnov.ru[217.23.20.38]: 550 5.1.1 <ser...@tls.msk.ru>: Recipient address rejected: User unknown; from=<quinnd...@mapleleafmail.com> to=<ser...@tls.msk.ru> proto=ESMTP helo=<mail.vzk.nnov.ru>
Dec 4 15:43:51 hobbit postfix/smtpd[26231]: 102863582F: client=mail.vzk.nnov.ru[217.23.20.38]
Dec 4 15:44:07 hobbit postfix/smtpd[26231]: 102863582F: reject: RCPT from mail.vzk.nnov.ru[217.23.20.38]: 450 4.1.7 <r.vande...@dispro.nl>: Sender address rejected: unverified address: Host or domain name not found. Name service error for name=mail.emps.equant.com type=A: Host not found, try again; from=<r.vande...@dispro.nl> to=<XXX> proto=ESMTP helo=<mail.vzk.nnov.ru>
Dec 4 15:44:14 hobbit postfix/smtpd[26231]: 102863582F: reject: DATA from mail.vzk.nnov.ru[217.23.20.38]: 503 5.5.0 <DATA>: Data command rejected: Improper use of SMTP command pipelining; from=<r.vande...@dispro.nl> proto=ESMTP helo=<mail.vzk.nnov.ru>
Dec 4 15:44:26 hobbit postfix/smtpd[26231]: 51F8835830: client=mail.vzk.nnov.ru[217.23.20.38]
Dec 4 15:44:52 hobbit postfix/smtpd[26231]: 51F8835830: reject: RCPT from mail.vzk.nnov.ru[217.23.20.38]: 550 5.1.7 <polynsky...@rg.ru>: Sender address rejected: undeliverable address: host mail.rg.ru[212.69.111.7] said: 550 <polynsky...@rg.ru>: Recipient address rejected: User unknown (in reply to RCPT TO command); from=<polynsky...@rg.ru> to=<XXX> proto=ESMTP helo=<mail.vzk.nnov.ru>
Dec 4 15:45:29 hobbit postfix/smtpd[26231]: 51F8835830: reject: DATA from mail.vzk.nnov.ru[217.23.20.38]: 503 5.5.0 <DATA>: Data command rejected: Improper use of SMTP command pipelining; from=<polynsky...@rg.ru> proto=ESMTP helo=<mail.vzk.nnov.ru>
Dec 4 15:45:39 hobbit postfix/smtpd[26231]: too many errors after DATA from mail.vzk.nnov.ru[217.23.20.38]
Dec 4 15:45:39 hobbit postfix/smtpd[26231]: disconnect from mail.vzk.nnov.ru[217.23.20.38]
Dec 4 22:21:29 hobbit postfix/smtpd[8048]: connect from vigoros.sp.ru[195.131.162.168]
Dec 4 22:21:32 hobbit postfix/smtpd[8048]: E1AEC35805: client=vigoros.sp.ru[195.131.162.168]
Dec 4 22:21:56 hobbit postfix/smtpd[8048]: E1AEC35805: reject: RCPT from vigoros.sp.ru[195.131.162.168]: 450 4.1.7 <pum...@mty1.uninet.net.mx>: Sender address rejected: unverified address: Address verification in progress; from=<pum...@mty1.uninet.net.mx> to=<XXX> proto=ESMTP helo=<vigoros.sp.ru>
Dec 4 22:21:59 hobbit postfix/smtpd[8048]: E1AEC35805: reject: DATA from vigoros.sp.ru[195.131.162.168]: 503 5.5.0 <DATA>: Data command rejected: Improper use of SMTP command pipelining; from=<pum...@mty1.uninet.net.mx> proto=ESMTP helo=<vigoros.sp.ru>
Dec 4 22:22:12 hobbit postfix/smtpd[8048]: 0F0B635805: client=vigoros.sp.ru[195.131.162.168]
Dec 4 22:22:46 hobbit postfix/smtpd[8048]: 0F0B635805: reject: RCPT from vigoros.sp.ru[195.131.162.168]: 550 5.1.7 <peggy....@pandora.be>: Sender address rejected: undeliverable address: host smtp-pandora.telenet-ops.be[195.130.132.39] said: 554 <peggy....@pandora.be>: Recipient address rejected: Access denied (in reply to RCPT TO command); from=<peggy....@pandora.be> to=<XXX> proto=ESMTP helo=<vigoros.sp.ru>
Dec 4 22:22:59 hobbit postfix/smtpd[8048]: 0F0B635805: reject: DATA from vigoros.sp.ru[195.131.162.168]: 503 5.5.0 <DATA>: Data command rejected: Improper use of SMTP command pipelining; from=<peggy....@pandora.be> proto=ESMTP helo=<vigoros.sp.ru>
Dec 4 22:23:10 hobbit postfix/smtpd[8048]: too many errors after DATA from vigoros.sp.ru[195.131.162.168]
Dec 4 22:23:10 hobbit postfix/smtpd[8048]: disconnect from vigoros.sp.ru[195.131.162.168]
Dec 5 00:09:36 hobbit postfix/smtpd[10334]: connect from mx.trinitygroup.ru[82.204.131.122]
Dec 5 00:09:39 hobbit postfix/smtpd[10334]: BE43F35805: client=mx.trinitygroup.ru[82.204.131.122]
Dec 5 00:09:51 hobbit postfix/smtpd[10334]: BE43F35805: reject: RCPT from mx.trinitygroup.ru[82.204.131.122]: 550 5.1.7 <por...@poczta.onet.pl>: Sender address rejected: undeliverable address: host mx.poczta.onet.pl[213.180.130.86] said: 550 5.7.1 Policy analysis reported: Konto chwilowo niedostepne. Sprobuj pozniej / Requested mail action not taken: mailbox unavailable - Try later rcpt=<por...@poczta.onet.pl> (in reply to RCPT TO command); from=<por...@poczta.onet.pl> to=<XXXX> proto=ESMTP helo=<mx.trinitygroup.ru>
Dec 5 00:09:57 hobbit postfix/smtpd[10334]: BE43F35805: reject: RCPT from mx.trinitygroup.ru[82.204.131.122]: 550 5.1.1 <ale...@tls.msk.ru>: Recipient address rejected: User unknown; from=<por...@poczta.onet.pl> to=<ale...@tls.msk.ru> proto=ESMTP helo=<mx.trinitygroup.ru>
Dec 5 00:09:59 hobbit postfix/smtpd[10334]: BE43F35805: reject: DATA from mx.trinitygroup.ru[82.204.131.122]: 503 5.5.0 <DATA>: Data command rejected: Improper use of SMTP command pipelining; from=<por...@poczta.onet.pl> proto=ESMTP helo=<mx.trinitygroup.ru>
Dec 5 00:10:09 hobbit postfix/smtpd[10334]: lost connection after RSET from mx.trinitygroup.ru[82.204.131.122]
Dec 5 00:10:09 hobbit postfix/smtpd[10334]: disconnect from mx.trinitygroup.ru[82.204.131.122]
And so on. It's all real mailservers (for some value of "real") -- I skipped
alot of zombie junk, for which, after this DATA rejection, another rejection
is logged - of message header sent as command).
Almost every time one or more recipients gets rejected due to sender address
verification probe, which is performed right away during SMTP session - maybe
it's somehow related. "Almost" - at least I can't find a case in my logs where
a SAV probe is NOT sent for the rejected RCPT's sender.
Yes - they all are trying to deliver spam. Almost all are to spamtraps (which
I didn't bother to "protect" this time, as in my original session transcript.
/mjt
Michael Tokarev
> Wietse Venema wrote:
[]
>> int count;
>>
>> return (ioctl(fd, FIONREAD, (char *) &count) < 0 ? -1 : count);
>
> (initialize a variable used in ioctl(FIONREAD, &var))
>
> I don't think so. I use it alot in my programs on this and other
> similar systems - had no issues so far. At least not in this case -
> I mean, kernel properly initializes the variable on successeful return.
> Almost every time one or more recipients gets rejected due to sender address
> verification probe, which is performed right away during SMTP session - maybe
> it's somehow related. "Almost" - at least I can't find a case in my logs where
> a SAV probe is NOT sent for the rejected RCPT's sender.
Another thing I forgot wich might be applicable here.
I'm not sure but I think I'm alone in this world who uses Postfix's unfinished
'pass' service type - exactly in a way how it was almost-implemented, i.e., to
just receive an opened file descriptor over a unix-domain socket and start SMTP
(in case of smtpd) session from the usual start.
The patch is trivial and obvious, but the whole thing hasn't been tested much.
Maybe, after all, there's really something in kernel which triggers this FIONREAD
brokeness somehow (I don't see it from the kernel code).
I'll enable some debugging, and add a logging of what's actually waiting in the
buffer -- since the amount of such events seems to be non-trivial.
/mjt
Michael Tokarev
> On Mon, Dec 04, 2006 at 04:27:49PM +0300, Michael Tokarev wrote:
>
>> Yes I do have that check - reject_unauth_pipelining - in
>> smtpd_data_restrictions, in order to catch worms who don't speak ESMTP but
>> tries to emit all their crap in one go. It works, especially with some
>> delays for generic rDNS and the like applied at several points of SMTP
>> conversation. But this rule should not trigger in this case (for this
>> very session, smtpd_data_restrictions (as produced by a policy daemon)
>> contained only single instruction - reject_unauth_pipelining, which
>> should be a no-op here: the remote speaks ESMTP, we offered PIPELINING,
>> and it's ok to group MAIL FROM, several RCPT TOs and DATA commands in
>> one packet, -- the remote must wait for the reply to DATA command before
>> trying to send actual message, but it is ok to send this command in one
>> packet together with prior RCPTs. So I wonder why Postfix rejects their
>> DATA command.
The same comment (as in my other email) to this same text applies - I was
confused about meaning of reject_unauth_pipelining.
> Have you verified (tcpdump) that no commands were sent before the "DATA"
> response from your server?
It's the hardest part. I've no control over that server and the amount of
spam they have for us. Ditto for other similar cases I mentioned in my reply
to Wietse. Sure enough, tcpdumping every smtp session is not an option... ;)
Cached? for re-use? It's stock Sendmail's feature, available for ages -
sending many messages in a single SMTP session. It even manages to try
to send spam to us with our own sender address, AND, after being rejected,
to send bounce (to that fake sender address), -- in the same session! ;)
And I don't understand your question above. RSET has been sent between
two mail transactions. It's after first message and before second -
it's in-between. For timings - well, i'm pretty sure the timestamps are
all in the same secound, but I can't know it from logs or from smtpd
postmaster notification.
>> In: MAIL FROM:<r.vande...@dispro.nl>
>> Out: 250 2.1.0 Ok
>> In: RCPT TO:<xxx>
>> Out: 250 2.1.5 Ok
>> In: RCPT TO:<xxx>
>> Out: 250 2.1.5 Ok
>> In: RCPT TO:<xxx>
>> Out: 250 2.1.5 Ok
>> In: RCPT TO:<xxx>
>> Out: 450 4.1.7 <r.vande...@dispro.nl>: Sender address rejected: ...
unverified sender
>> In: RCPT TO:<xxx>
>> Out: 250 2.1.5 Ok
>> In: RCPT TO:<xxx>
>> Out: 250 2.1.5 Ok
>> In: RCPT TO:<xxx>
>> Out: 250 2.1.5 Ok
>> In: RCPT TO:<xxx>
>> Out: 250 2.1.5 Ok
>> In: RCPT TO:<xxx>
>> Out: 250 2.1.5 Ok
>> In: DATA
>> Out: 503 5.5.0 <DATA>: Data command rejected: Improper use of SMTP command
>> pipelining
>
> Well, at this point the only thing that can reasonbly be present in the
> VSTREAM buffer or in the TCP socket receive buffer is the "RSET" that is
> read below. So, assuming that the remote system did not send an expedited
> "RSET" with DATA, you have a buggy ioctl(FIONREAD) implementation.
A wild guess. Remote timed out waiting for our reply (due to delays with
SAV above - rejected sender address), and really sent RSET. Looks strange,
but.. umm.
But well. Broken FIONREAD is a possibility too. Wonder why it never triggered
in other software.
>> In: RSET
>> Out: 250 2.0.0 Ok
>
> This calls for a "tcpdump"...
I see. I wish I able to do that.
Victor Duchovni
> >> In: RCPT TO:<xxx>
> >> Out: 250 2.1.5 Ok
> >> In: DATA
> >> Out: 503 5.5.0 <DATA>: Data command rejected: Improper use of SMTP command
> >> pipelining
> >
> > Well, at this point the only thing that can reasonbly be present in the
> > VSTREAM buffer or in the TCP socket receive buffer is the "RSET" that is
> > read below. So, assuming that the remote system did not send an expedited
> > "RSET" with DATA, you have a buggy ioctl(FIONREAD) implementation.
>
> A wild guess. Remote timed out waiting for our reply (due to delays with
> SAV above - rejected sender address), and really sent RSET. Looks strange,
Sending RSET out-of-order before the DATA response (even if delayed)
sounds broken, at that point the protocol is out of sync, why bother? And
if I recall correctly it then tries to send another message after the
RSET, how does it remember to read the DATA response if it timed the
command out?
> But well. Broken FIONREAD is a possibility too. Wonder why it never triggered
> in other software.
>
> >> In: RSET
> >> Out: 250 2.0.0 Ok
> >
> > This calls for a "tcpdump"...
>
> I see. I wish I able to do that.
Pick one of these servers that comes back to you periodically times,
but whole total bandwidth use is low enough to allow gathering packet
captures.
Wietse Venema
> Dec 4 15:43:54 hobbit postfix/smtpd[27850]: 192BC3582A: reject: DATA from europoster.lan.edunet.ru[213.184.145.226]: 503 5.5.0 <DATA>: Data command rejected: Improper use of SMTP command pipelining; from=<pozn...@poczta.onet.pl> proto=ESMTP helo=<EUROPOSTER.mshome.net>
> Dec 4 15:44:04 hobbit postfix/smtpd[27850]: lost connection after DATA from europoster.lan.edunet.ru[213.184.145.226]
Unfortunately, Postfix logs DATA as the last *valid* command. It
is still possible that DATA was followed by other garbage, but we
can't tell that from the logfile.
Fortunately, we have one that shows promise:
> Dec 4 22:22:59 hobbit postfix/smtpd[8048]: 0F0B635805: reject: DATA from vigoros.sp.ru[195.131.162.168]: 503 5.5.0 <DATA>: Data command rejected: Improper use of SMTP command pipelining; from=<peggy....@pandora.be> proto=ESMTP helo=<vigoros.sp.ru>
> Dec 4 22:23:10 hobbit postfix/smtpd[8048]: too many errors after DATA from vigoros.sp.ru[195.131.162.168]
Here, the log says that DATA was the last valid command, but this
command was followed by other garbage that triggered the hard error
limit 11 seconds later.
This is evidence that a client sent message content before Postfix
confirmed the DATA command.
What about local customizations at the socket level? Multiple
threads running around in smtpd(8) that could stomp over data?
I don't see how activity on one VSTREAM could cause a false
vstream_peek() response for another one; ditto for peekfd().
Wietse
Wietse Venema
> On Tue, Dec 05, 2006 at 01:03:50AM +0300, Michael Tokarev wrote:
>
> > >> In: RCPT TO:<xxx>
> > >> Out: 250 2.1.5 Ok
> > >> In: DATA
> > >> Out: 503 5.5.0 <DATA>: Data command rejected: Improper use of SMTP command
> > >> pipelining
> > >
> > > Well, at this point the only thing that can reasonbly be present in the
> > > VSTREAM buffer or in the TCP socket receive buffer is the "RSET" that is
> > > read below. So, assuming that the remote system did not send an expedited
> > > "RSET" with DATA, you have a buggy ioctl(FIONREAD) implementation.
> >
> > A wild guess. Remote timed out waiting for our reply (due to delays with
> > SAV above - rejected sender address), and really sent RSET. Looks strange,
>
> Sending RSET out-of-order before the DATA response (even if delayed)
> sounds broken, at that point the protocol is out of sync, why bother? And
> if I recall correctly it then tries to send another message after the
> RSET, how does it remember to read the DATA response if it timed the
> command out?
But this is by far the most plausible explanation. The sender sends
DATA, pipelined with RCPT TO commands, and then it times out while
Postfix waits up to 6 seconds per recipient for address verification.
If the client is slightly broken (like even Postfix can be under
really really unusual conditions), then it could send RSET and
commence another delivery attempt like Michael recorded in his
initial report.
Wietse