Parallels Forums
> Plesk Products Discussion > Parallels Plesk Panel for Linux/Unix > Parallels Plesk Panel 9.2 for Linux/UNIX > Parallels Plesk Panel 9.2 for Linux/UNIX Troubleshooting Issues  
Plesk 9.2.3: New Postfix error "Unprocessed command"  
  

Plesk 9.2.3: New Postfix error "Unprocessed command"

Nov 3, 2009, 02:04 PM
#1  

mfichtner
Junior Member


Join: Dec 2004
Posts: 15
Plesk 9.2.3: New Postfix error "Unprocessed command"
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:

Quote:
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:

Quote:
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:

Quote:
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:

Quote:
[...]
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.
Nov 4, 2009, 03:36 AM
#2  
IgorG's Avatar

IgorG
Parallels Team


Join: Oct 2009
Posts: 1,652
mfichtner,

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

Quote:
Out: 354 End data with <CR><LF>.<CR><LF>
Out: 451 4.3.0 Error: queue file write error
http://kb.parallels.com/en/6394

But seems problem still actual. I hope that it will be fixed in the next Plesk update.
Nov 4, 2009, 06:34 AM
#3  

mfichtner
Junior Member


Join: Dec 2004
Posts: 15
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.
Nov 11, 2009, 10:13 PM
#4  

mfichtner
Junior Member


Join: Dec 2004
Posts: 15
Bump.

Am I the only one seeing these "Unprocessed command" errors? Anything I can do about them, other than switching to QMail?
Nov 19, 2009, 01:58 AM
#5  

19patje72
Junior Member


Join: Apr 2007
Posts: 25
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...
Nov 30, 2009, 07:09 AM
#6  

NicolasC
Junior Member


Join: Jun 2009
Posts: 16
Please fix !
Quote:
Originally Posted by mfichtner View Post
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 !
Nov 30, 2009, 05:48 PM
#7  

ISSchuster
Junior Member


Join: Dec 2008
Posts: 7
I have the same problem...

Postfix is unusable since nearly 1 Year and nothing happens...
Dec 1, 2009, 12:47 AM
#8  
IgorG's Avatar

IgorG
Parallels Team


Join: Oct 2009
Posts: 1,652
Request to developers already submitted and they are working on it. I will post information from developers here as soon as I receive it.
Dec 1, 2009, 02:01 AM
#9  

NicolasC
Junior Member


Join: Jun 2009
Posts: 16
Quote:
Originally Posted by IgorG View Post
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 !
Dec 3, 2009, 01:36 AM
#10  
IgorG's Avatar

IgorG
Parallels Team


Join: Oct 2009
Posts: 1,652
mfichtner,

I have received following information from developers:

​1. from forum:
[...]
Quote:
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:

Quote:
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)
Dec 3, 2009, 06:02 AM
#11  

NicolasC
Junior Member


Join: Jun 2009
Posts: 16
Quote:
Originally Posted by IgorG View Post
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 :

Quote:
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
Dec 4, 2009, 12:19 AM
#12  
IgorG's Avatar

IgorG
Parallels Team


Join: Oct 2009
Posts: 1,652
Nicolas,

I have forwarded your information to developers. Let's wait their answer.
Dec 4, 2009, 03:51 AM
#13  
IgorG's Avatar

IgorG
Parallels Team


Join: Oct 2009
Posts: 1,652
Developers can't reproduce this error without original message which caused it.
Is it possible to provide this original message with full headers?
Dec 6, 2009, 10:42 AM
#14  

karesmakro


Join: Nov 2009
Posts: 3
Same problem on Plesk 9.2.3 to me since some weeks.
Quote:
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
Quote:
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:<root@host2.net> SIZE=4358 BODY=7BIT
Out: 250 2.1.0 Ok
In: RCPT TO:<mail@mymail.de>
ORCPT=rfc822;mail@mymail.de
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.
Dec 7, 2009, 09:10 PM
#15  

mfichtner
Junior Member


Join: Dec 2004
Posts: 15
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!
Attached Files
File Type: gz B0027178012-000083.MSG.gz (9.2 KB, 5 views)
File Type: gz B0027215972-000068.MSG.gz (11.2 KB, 3 views)
Dec 8, 2009, 03:50 AM
#16  
IgorG's Avatar

IgorG
Parallels Team


Join: Oct 2009
Posts: 1,652
Thank you for messages. I have forwarded it to developers for further investigation. Will keep you updated.
Dec 9, 2009, 04:39 PM
#17  

karesmakro


Join: Nov 2009
Posts: 3
One nice message again:
Quote:
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
Dec 10, 2009, 01:48 AM
#18  
IgorG's Avatar

IgorG
Parallels Team


Join: Oct 2009
Posts: 1,652
Here is workaround for fixing this problem. Please try it and update this thread with results.
Dec 10, 2009, 02:36 AM
#19  

karesmakro


Join: Nov 2009
Posts: 3
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
Dec 11, 2009, 05:46 PM
#20  

NicolasC
Junior Member


Join: Jun 2009
Posts: 16
Quote:
Originally Posted by IgorG View Post
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 :

Quote:
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


12>

Thread tools Display modes
Linear Mode