Plesk 9.2.3: New Postfix error "Unprocessed command"

[mfichtner]

Since upgrading from Plesk 9.2.2 to 9.2.3 on Ubuntu 8.04, there seems to be a new problem with Postfix. I'm seeing more and more log entries that look like these:

Nov 3 13:47:52 cgn8 before-remote[16362]: Unprocessed command: received:
Nov 3 13:47:52 cgn8 before-remote[16362]: Unprocessed command: from:
Nov 3 13:47:52 cgn8 before-remote[16362]: Unprocessed command: subject:
Nov 3 13:47:52 cgn8 before-remote[16362]: Unprocessed command: content-type:

In this case the "Unprocessed command" log entries quote header names, in other cases the "unprocessed commands" are seemingly random words taken from the message body.

The next few log entries look like these:

Nov 3 13:47:52 cgn8 postfix/smtpd[7872]: warning: received garbage from proxy 127.0.0.1:10025: Received: [...]
Nov 3 13:47:52 cgn8 postfix/smtpd[7872]: warning: received garbage from proxy 127.0.0.1:10025: Date: [...]

And finally:

Nov 3 13:47:52 cgn8 postfix/smtpd[16363]: warning: non-SMTP command from localhost[127.0.0.1]: Received: [...]

This results in a garbled, partially received message that is delivered to the intended mailbox, and an error message returned to the sending SMTP server:

[...]
In: DATA
Out: 354 End data with <CR><LF>.<CR><LF>
Out: 451 4.3.0 Error: queue file write error

And since it's a 4xx response, this repeats over and over again, delivering endless copies of the same, garbled message to the intended recipient.

So far, I have no idea what causes this problem. It only happens with a few messages. Most e-mail is delivered just fine.

I've never seen this problem under Plesk 9.2.2.

 

[IgorG]

mfichtner,

It is known problem and as I know it is still under developer's investigation. There is KB article regarding error

Out: 354 End data with <CR><LF>.<CR><LF>
Out: 451 4.3.0 Error: queue file write error

http://kb.odin.com/en/6394

But seems problem still actual. I hope that it will be fixed in the next Plesk update.

 

[mfichtner]

thanks for your response, IgorG.

However, this does not appear to be the same known bug:

(1) I've seen the segfault described in that KB article before. The final error message reported to the sending MTA might be the same, but there were never any log entries regarding "unprocessed commands" involved. These log entries have shown up for the first time under Plesk 9.2.3.

(2) I know of at least one message triggering the "Unprocessed command" bug that doesn't contain any "strings of more than 4096 characters". The longest line in that message is 195 characters.

 

[mfichtner]

Bump.

Am I the only one seeing these "Unprocessed command" errors? Anything I can do about them, other than switching to QMail?

 

[19patje72]

hi,

We also have this problem:
Nov 19 00:14:05 srv03 before-queue[21718]: Unprocessed command:
Nov 18 16:14:05 srv03 postfix/smtpd[21595]: lost connection after DATA from unknown[127.0.0.1]
Nov 18 16:14:05 srv03 postfix/smtpd[21595]: disconnect from unknown[127.0.0.1]
Nov 18 16:14:05 srv03 postfix/smtpd[21651]: warning: lost connection with proxy 127.0.0.1:10025

This email was sent to a user with cc to other users. The Cc: all went ok, and have been received. But the To did not. Quite confusing...

 

[NicolasC]

Please fix !

Bump.

Am I the only one seeing these "Unprocessed command" errors? Anything I can do about them, other than switching to QMail?

Nope, I have also the problem...

Every new Plesk Update brings a new Bug on Postfix.... And everytime, no comment and no fix from Plesk team. I can understand if the soft was free but it's not the case !

Please, don't consider your customers as beta testers !

Release a patch ugrgently !

 

[ISSchuster]

I have the same problem...

Postfix is unusable since nearly 1 Year and nothing happens...

 

[IgorG]

Request to developers already submitted and they are working on it. I will post information from developers here as soon as I receive it.

 

[NicolasC]

Request to developers already submitted and they are working on it. I will post information from developers here as soon as I receive it.

Thanks IgorG, waiting for your reply !

 

[IgorG]

mfichtner,

I have received following information from developers:

​1. from forum:
[...]

In: DATA
Out: 354 End data with <CR><LF>.<CR><LF>
Out: 451 4.3.0 Error: queue file write error

Please check for Greylisting feature. If enabled - this answer is correct.

2. I know of at least one message triggering the "Unprocessed command" bug that doesn't contain any "strings of more than 4096 characters". The longest line in that message is 195 characters.

Already cured but not commited yet.

3. Please give me machine with such message:

Nov 3 13:47:52 cgn8 before-remote[16362]: Unprocessed command: received:
Nov 3 13:47:52 cgn8 before-remote[16362]: Unprocessed command: from:
Nov 3 13:47:52 cgn8 before-remote[16362]: Unprocessed command: subject:
Nov 3 13:47:52 cgn8 before-remote[16362]: Unprocessed command: content-type:

or provide me a source message for reproduce this problem. (ask to mfichtner)

 

[NicolasC]

Already cured but not commited yet.

Is there any patch for that, because I don't want to wait 2 month for the 9.2.4...

Not sure this can help, here is an example of error I have since 9.2.3 :

12-02 20:03:41 (+01:00) before-queue[13446]: Unprocessed command: la
12-02 20:03:41 (+01:00) before-queue[13446]: Unprocessed command: box
12-02 20:03:41 (+01:00) before-queue[13446]: Unprocessed command: http://pages.ebay.fr/aboutebay/contact.html
12-02 20:03:41 (+01:00) before-queue[13446]: Unprocessed command: --1439782353.1259780614364.javamail.system.sj-besreco041
12-02 20:03:41 (+01:00) before-queue[13446]: Unprocessed command: content-transfer-encoding:
12-02 20:03:41 (+01:00) before-queue[13446]: Unprocessed command: <html><head></head><body><div
12-02 20:03:41 (+01:00) before-queue[13446]: Unprocessed command: =3d"word-wrap:break-word"><table
12-02 20:03:41 (+01:00) before-queue[13446]: Unprocessed command: tp://pics.ebaystatic.com/aw/pics/fr/logos/ebay_95x39.gif"
12-02 20:03:41 (+01:00) before-queue[13446]: Unprocessed command: e=3d"font-weight:bold;
12-02 20:03:41 (+01:00) before-queue[13446]: Unprocessed command: ></span><span
12-02 20:03:41 (+01:00) before-queue[13446]: Unprocessed command: qu=e9
12-02 20:03:41 (+01:00) before-queue[13446]: Unprocessed command: ></td></tr></table></td></tr></table></div></div><div
12-02 20:03:41 (+01:00) before-queue[13446]: Unprocessed command: pacing=3d"0"
12-02 20:03:41 (+01:00) before-queue[13446]: Unprocessed command: "
12-02 20:03:41 (+01:00) before-queue[13446]: Unprocessed command: rgin:2px
12-02 20:03:41 (+01:00) before-queue[13446]: Unprocessed command: http://pics.ebaystatic.com/aw/pics/fr/globalassets/rtcurve.gif"
12-02 20:03:41 (+01:00) before-queue[13446]: Unprocessed command: 3"
12-02 20:03:41 (+01:00) before-queue[13446]: Unprocessed command: r><td><font
12-02 20:03:41 (+01:00) before-queue[13446]: Unprocessed command:

Thanks

 

[IgorG]

Nicolas,

I have forwarded your information to developers. Let's wait their answer.

 

[IgorG]

Developers can't reproduce this error without original message which caused it.
Is it possible to provide this original message with full headers?

 

[karesmakro]

Same problem on Plesk 9.2.3 to me since some weeks.

Dec 6 16:08:34 host postfix/smtpd[7086]: warning: received garbage from proxy 127.0.0.1:10025: address: Skolska 10
Dec 6 16:08:34 host postfix/smtpd[6945]: lost connection after DATA from localhost[127.0.0.1]
Dec 6 16:08:34 host postfix/smtpd[6945]: disconnect from localhost[127.0.0.1]

and

Out: 220 host.de ESMTP Postfix (Debian/GNU)
In: EHLO host2.net
Out: 250-host
Out: 250-PIPELINING
Out: 250-SIZE 51200000
Out: 250-VRFY
Out: 250-ETRN
Out: 250-STARTTLS
Out: 250-AUTH PLAIN CRAM-MD5 DIGEST-MD5 LOGIN
Out: 250-AUTH=PLAIN CRAM-MD5 DIGEST-MD5 LOGIN
Out: 250-ENHANCEDSTATUSCODES
Out: 250-8BITMIME
Out: 250 DSN
In: STARTTLS
Out: 220 2.0.0 Ready to start TLS
In: EHLO host2.net
Out: 250-host.de
Out: 250-PIPELINING
Out: 250-SIZE 51200000
Out: 250-VRFY
Out: 250-ETRN
Out: 250-AUTH PLAIN CRAM-MD5 DIGEST-MD5 LOGIN
Out: 250-AUTH=PLAIN CRAM-MD5 DIGEST-MD5 LOGIN
Out: 250-ENHANCEDSTATUSCODES
Out: 250-8BITMIME
Out: 250 DSN
In: MAIL FROM:<[email protected]> SIZE=4358 BODY=7BIT
Out: 250 2.1.0 Ok
In: RCPT TO:<[email protected]>
ORCPT=rfc822;[email protected]
Out: 250 2.1.5 Ok
In: DATA
Out: 354 End data with <CR><LF>.<CR><LF>
Out: 451 4.3.0 Error: queue file write error
In: QUIT
Out: 221 2.0.0 Bye

but I have the original postfix queue file, wich you can download at mail.tar.gz for a few days!
My guess is, that some contents in mails are interpreted as mail command on grepping the mail address, because in front of the "Skolska" in my example, there is a text like "address: " if you show the original queue file!
The mail server, which tried to sent this message is a Plesk 9.2.3 machine (postfix) too - both are debian machines.

 

[mfichtner]

IgorG,

thank you for the feedback.

Attached are two messages that have triggered the error described above. I was able to grab the complete content of these messages because they were being sent from another one of my own servers (which uses neither Plesk nor Postfix). So I had access to the mail queue of the sending machine.

Hope this helps!

 

[IgorG]

Thank you for messages. I have forwarded it to developers for further investigation. Will keep you updated.

 

[karesmakro]

One nice message again:

Dec 9 22:34:35 host before-queue[14098]: errno: Broken pipe
Dec 9 22:34:35 host before-queue[14098]: System error: Broken pipe
Dec 9 22:34:35 host before-queue[14098]: Unable to write data into outgoing socket
Dec 9 22:34:35 host before-queue[14098]: Unable to translate command answer: nic-hdl: JK1887-RIPE
Dec 9 22:34:35 host postfix/smtpd[13978]: warning: received garbage from proxy 127.0.0.1:10025: phone: +xxx xx xxxxx

 

[IgorG]

Here is workaround for fixing this problem. Please try it and update this thread with results.

 

[karesmakro]

It appears for the first, that the error has been fixed! All messages, which could not be sent the last days are sent now correctly!
Thank you for this fix.

Regards

 

[NicolasC]

Here is workaround for fixing this problem. Please try it and update this thread with results.

Nope. Patch installed at 22h22, postfix restarted and still the same :

12-11 23:17:57 (+01:00) before-remote[13372]: Unprocessed command: .map_onglet_lien_mag{
12-11 23:17:57 (+01:00) before-remote[13372]: Unprocessed command: font-size:
12-11 23:17:57 (+01:00) before-remote[13380]: Unprocessed command: atn_a11g
12-11 23:17:57 (+01:00) before-remote[13380]: Unprocessed command: font-size:
12-11 23:17:57 (+01:00) before-remote[13387]: Unprocessed command: .msochpdefault
12-11 23:17:57 (+01:00) before-remote[13383]: Unprocessed command: ext2
12-11 23:17:57 (+01:00) before-remote[13383]: Unprocessed command: }
12-11 23:22:57 (+01:00) before-remote[13849]: Unprocessed command: .batn_v13_gris
12-11 23:22:57 (+01:00) before-remote[13849]: Unprocessed command: font-size:
12-11 23:22:57 (+01:00) before-remote[13415]: Unprocessed command:
12-11 23:22:59 (+01:00) before-remote[13417]: Unprocessed command:
12-11 23:26:03 (+01:00) before-remote[14315]: Unprocessed command: .map_onglet_lien_mag{
12-11 23:26:03 (+01:00) before-remote[14315]: Unprocessed command: font-size:
12-11 23:26:05 (+01:00) before-remote[14323]: Unprocessed command: ext2
12-11 23:26:05 (+01:00) before-remote[14323]: Unprocessed command: }
12-11 23:26:05 (+01:00) before-remote[14319]: Unprocessed command: atn_a11g
12-11 23:26:05 (+01:00) before-remote[14319]: Unprocessed command: font-size:
12-11 23:26:05 (+01:00) before-remote[14326]: Unprocessed command: .msochpdefault
12-11 23:32:08 (+01:00) before-remote[15018]: Unprocessed command: ext2
12-11 23:32:08 (+01:00) before-remote[15018]: Unprocessed command: }
12-11 23:32:08 (+01:00) before-remote[15014]: Unprocessed command: .map_onglet_lien_mag{
12-11 23:32:08 (+01:00) before-remote[15014]: Unprocessed command: font-size:
12-11 23:32:08 (+01:00) before-remote[15016]: Unprocessed command: atn_a11g
12-11 23:32:08 (+01:00) before-remote[15016]: Unprocessed command: font-size:
12-11 23:32:08 (+01:00) before-remote[15019]: Unprocessed command: .msochpdefault
12-11 23:35:01 (+01:00) before-remote[15183]: Unprocessed command: tyle10
12-11 23:35:01 (+01:00) before-remote[15183]: Unprocessed command:
12-11 23:37:09 (+01:00) before-remote[15021]: Unprocessed command:
12-11 23:37:09 (+01:00) before-remote[15533]: Unprocessed command: .batn_v13_gris
12-11 23:37:09 (+01:00) before-remote[15533]: Unprocessed command: font-size:

Thanks