Postfix still sending hundreds 'queue file write error'

[ISSchuster]

Same here... Problem still exists... I think you should look for new developers / programmers - they are obviously incompetent...

I receive the following error message every few hours - before and after the new patch...

There is only one difference - after installing the patch no "Unprocessed command" are logged in maillog.

It seems that the developers only changed the logging-procedure - so that "Unprocessed command" Errors will not be written to the maillog any longer...


Transcript of session follows.

Out: 220 ganymed.xxxxx.eu ESMTP Postfix (Debian/GNU)
In: EHLO inc.ru
Out: 250-ganymed.xxxxxxx.eu
Out: 250-PIPELINING
Out: 250-SIZE 134217728
Out: 250-VRFY
Out: 250-ETRN
Out: 250-STARTTLS
Out: 250-AUTH CRAM-MD5 LOGIN PLAIN DIGEST-MD5
Out: 250-ENHANCEDSTATUSCODES
Out: 250-8BITMIME
Out: 250 DSN
In: MAIL FROM:<> SIZE=3926
Out: 250 2.1.0 Ok
In: RCPT TO:<[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

 

[IgorG]

I have informed developers.

 

[kanada]

IgorG after install patched postfix-queue in my opinion problem with "Unprocessed command" is gone away.
I've patched it yesterday and after that..
1. postfix work better, before in ps/top i saw a lot (150-200) of hanged up processes postfix-queue, now i see working 30-40. Mail traffic is on that same level like before.
2. i recive less error messages with "Error: queue file write error", bofore ~500 by day, now ~150 by day.
3. good point of ISSchuster, maillog is cleared from the "Unprocessed command".

However I'll test it with next couple of days and post there results.

Regards,
Alex

 

[IgorG]

Yes I do, no change same errors.

"Unprocessed command"?

 

[IgorG]

Yes e.g.


DM.

Where is 'Unprocessed command' error here?
Patch for fixing 'Unprocessed command' error.

 

[Brujo]

just to confirm, tons of queue file write errors on my Centos Servers with postfix, since I updated one to 9.3.0 he has definitifely more errors as the other one which is still 9.2.3. To be honest it makes no fun to run postfix and it is just a nightmare. Many ideas seems to be good but the implementation from developer is just poor, cant believe that after this long time it is still such unstable and lot off issues.

I have several other mailserver running postfix without plesk and this once are such stable and work like a charm.


just my 2 cent
Brujo

 

[Brujo]

@Igorg

one question - I think we can agree that Plesk try to get postfix running now longer than 1 Year and the development team is not able to get it done, why is Plesk such bored and still keep the postfix implementation closed source? I am pretty sure if the postfix implementation would be open it can/ or will be fixed imeadetely!!

just my next 2 cents
Brujo

 

[IgorG]

I understand your discontent, but I am not responsible for the answer on such questions. I can notice only that Plesk is not open source product and you should understand it too.

 

[igraf]

Hi
i have the same error ...

Transcript of session follows.

Out: 220 xxx.xxx.com ESMTP Postfix
In: EHLO spam-be-03.be08.sunrise.ch
Out: 250-xxx.xxx.com
Out: 250-PIPELINING
Out: 250-SIZE 20480000
Out: 250-VRFY
Out: 250-ETRN
Out: 250-STARTTLS
Out: 250-AUTH DIGEST-MD5 CRAM-MD5 LOGIN PLAIN
Out: 250-ENHANCEDSTATUSCODES
Out: 250-8BITMIME
Out: 250 DSN
In: STARTTLS
Out: 220 2.0.0 Ready to start TLS
In: EHLO spam-be-03.be08.sunrise.ch
Out: 250-xxx.xxx.com
Out: 250-PIPELINING
Out: 250-SIZE 20480000
Out: 250-VRFY
Out: 250-ETRN
Out: 250-AUTH DIGEST-MD5 CRAM-MD5 LOGIN PLAIN
Out: 250-ENHANCEDSTATUSCODES
Out: 250-8BITMIME
Out: 250 DSN
In: MAIL From:<> SIZE=7836
Out: 250 2.1.0 Ok
In: RCPT To:<[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

maillog

Feb 5 04:27:15 xxx before-remote[23168]: Unprocessed command: 8/4256255055_63e32ee602_o.jpg">
Feb 5 04:27:15 xxx before-remote[23168]: Unprocessed command: <tbody><tr><td
Feb 5 04:27:15 xxx before-remote[23168]: errno: Broken pipe
Feb 5 04:27:15 xxx before-remote[23168]: System error: Broken pipe
Feb 5 04:27:15 xxx before-remote[23168]: Unable to write data into incoming socket
Feb 5 04:27:15 xxx before-remote[23168]: Unable to translate command answer: <TBODY><TR><TD style="TEXT-ALIGN: center"><P style="TEXT-ALIGN: center; MARGIN-BOTTOM: 0px"><FONT size=2
Feb 5 04:27:15 xxx postfix/spawn[23148]: warning: command /usr/lib64/plesk-9.0/postfix-queue exit status 255
Feb 5 03:27:15 xxx postfix/smtpd[23150]: disconnect from unknown[127.0.0.1]

the problem is solved correctly, or they're waiting for response from the programmer

 

[Brujo]

Igorg please dont missunderstand, I reale apreciate that one is present in the forum to try to help, and just to be clear I was not talking about open source for Plesk in generaly. I was talking about the part with the postfix implementation and in detail around the plesk postfix-queue which obiously has the most problems. And to be honest after that long time it never works stable for production server and this makes me sad becaus postfix itself is just a great MTA and the knowledge that nothing can be done byself in terms of closed source implementation.

Brujo

 

[kanada]

Unfortunately i have bad news for Plesk developers. Couple days after postfix restart in my OS i see hundered hanged up processes of postfix-queue.

30 26223 0.0 0.0 3468 804 ? Ss Feb03 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10027 before-queue
30 26224 0.0 0.0 3464 744 ? Ss Feb03 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10026 before-remote
30 26245 0.0 0.0 3472 948 ? Ss 08:33 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10027 before-queue
30 26246 0.0 0.0 3468 668 ? Ss 08:33 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10026 before-remote
30 26356 0.0 0.0 3472 736 ? Ss Feb05 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10027 before-queue
30 26357 0.0 0.0 3472 680 ? Ss Feb05 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10026 before-remote
30 26614 0.0 0.0 3468 800 ? Ss Feb04 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10027 before-queue
30 26615 0.0 0.0 3464 736 ? Ss Feb04 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10026 before-remote
30 26702 0.0 0.0 3468 732 ? Ss Feb05 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10027 before-queue
30 26703 0.0 0.0 3468 676 ? Ss Feb05 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10026 before-remote
30 26872 0.0 0.0 3464 792 ? Ss Feb04 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10027 before-queue
30 26873 0.0 0.0 3468 740 ? Ss Feb04 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10026 before-remote
30 26891 0.0 0.0 3464 812 ? Ss Feb03 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10027 before-queue
30 26892 0.0 0.0 3464 736 ? Ss Feb03 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10026 before-remote
30 27159 0.0 0.0 3468 732 ? Ss Feb05 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10027 before-queue
30 27160 0.0 0.0 3472 676 ? Ss Feb05 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10026 before-remote
30 28897 0.0 0.0 3464 796 ? Ss Feb04 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10027 before-queue
30 28898 0.0 0.0 3468 744 ? Ss Feb04 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10026 before-remote
30 28943 0.0 0.0 3468 808 ? Ss Feb03 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10027 before-queue
30 28944 0.0 0.0 3464 744 ? Ss Feb03 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10026 before-remote
30 28971 0.0 0.0 3464 792 ? Ss Feb02 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10027 before-queue
30 28973 0.0 0.0 3464 748 ? Ss Feb02 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10026 before-remote
30 29680 0.0 0.0 3468 940 ? Ss Feb05 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10027 before-queue
30 29681 0.0 0.0 3472 680 ? Ss Feb05 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10026 before-remote
30 30713 0.0 0.0 3468 816 ? Ss Feb03 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10027 before-queue
30 30714 0.0 0.0 3464 736 ? Ss Feb03 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10026 before-remote
30 32142 0.0 0.0 3472 740 ? Ss Feb05 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10027 before-queue
30 32143 0.0 0.0 3472 680 ? Ss Feb05 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10026 before-remote
30 32310 0.0 0.0 3464 796 ? Ss Feb04 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10027 before-queue
30 32311 0.0 0.0 3464 736 ? Ss Feb04 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10026 before-remote
30 32598 0.0 0.0 3468 736 ? Ss Feb05 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10027 before-queue
30 32600 0.0 0.0 3472 680 ? Ss Feb05 0:00 /usr/lib/plesk-9.0/postfix-queue 127.0.0.1 10026 before-remote

ps aux |grep postfix-queue |wc -l
153

I think this is problem with "Error: queue file write error".

This situation crush my postfix in 5-6 days after postfix restart. These time i cannot connect to the 127.0.0.1:10027 or 127.0.0.1:10026. Postfix collect messages in his queue couse he can't send it durning problems with postfix-queue.

Only way to repair is stoping postfix process and killed all hanged up postfix-queue.
OS: Fedora 11
Plesk: 9.3.0

Regadrs,
Alex

 

[Brujo]

Hi Alex, just to confirm, same behaviour on my Server running under Centos5. It seems each queue write error left over a hanging postfix-queue process...

Brujo

 

[Roman Hochuli]

Igor

I appreciate your effort in this forum. Thank you.

Still in this case the main problem here is not the 'Unprocessed command' or at lease not in my variation of this problem. I do not even see the 'Unprocessed command's after applying your workaroud.

The problem is the 'queue file write error' which seems to be originated also somewhere around postfix-queue but is simply not the same. I have tested this now with multiple versions of postfix (up to 2.6.5).

Have a look at this log (taken with -v setting on most postfix processes). I cut off all but the last few lines of the SMTP "DATA" part.

Feb 9 16:47:43 shared-1 postfix/smtpd[12523]: vstream_buf_get_ready: fd 9 got 4096
Feb 9 16:47:43 shared-1 postfix/smtpd[12523]: vstream_fflush_some: fd 22 flush 4096
Feb 9 16:47:43 shared-1 postfix/smtpd[12523]: vstream_buf_get_ready: fd 9 got 3591
Feb 9 16:47:43 shared-1 postfix/smtpd[12523]: > 127.0.0.1:10025: .
Feb 9 16:47:43 shared-1 postfix/smtpd[12523]: vstream_fflush_some: fd 22 flush 3801
Feb 9 17:47:43 shared-1 before-queue[15193]: hook_dir = '/usr/local/psa/handlers/before-queue'
Feb 9 17:47:43 shared-1 before-queue[15193]: call_handlers: call executable = '/usr/local/psa/handlers/info/10-spf-suJQ6C/executable'
Feb 9 17:47:43 shared-1 spf filter[15351]: Starting spf filter...
Feb 9 17:47:43 shared-1 before-queue[15193]: handlers_stderr: SKIP
Feb 9 17:47:43 shared-1 before-queue[15193]: call_handlers: SKIP during call '/usr/local/psa/handlers/info/10-spf-suJQ6C/executable' handler
Feb 9 17:47:43 shared-1 before-queue[15193]: recipient[3] = '[email protected]'
Feb 9 17:47:43 shared-1 before-queue[15193]: handlers dir = '/usr/local/psa/handlers/before-queue/recipient/[email protected]'
Feb 9 17:47:43 shared-1 before-remote[15195]: errno: Broken pipe
Feb 9 17:47:43 shared-1 before-remote[15195]: System error: Broken pipe
Feb 9 17:47:43 shared-1 before-remote[15195]: Unable to write data to stream
Feb 9 17:47:43 shared-1 before-remote[15195]: Some error occured
Feb 9 17:47:43 shared-1 postfix/spawn[12556]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255
Feb 9 17:47:43 shared-1 postfix/spawn[12556]: master_notify: status 1
Feb 9 17:47:43 shared-1 postfix/spawn[12556]: connection closed
Feb 9 17:47:43 shared-1 before-queue[15193]: errno: Connection reset by peer
Feb 9 17:47:43 shared-1 before-queue[15193]: System error: Connection reset by peer
Feb 9 17:47:43 shared-1 before-queue[15193]: Unable to write data to stream
Feb 9 17:47:43 shared-1 before-queue[15193]: Some error occured
Feb 9 17:47:43 shared-1 postfix/spawn[12554]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255
Feb 9 17:47:43 shared-1 postfix/spawn[12554]: master_notify: status 1
Feb 9 16:47:43 shared-1 postfix/smtpd[12523]: smtp_get: EOF
Feb 9 17:47:43 shared-1 postfix/spawn[12554]: connection closed

No 'Unprocessed command's but still we end up with our dreaded queue file write error.

Please have another, closer look at this.

If you like I will also be able to provide more logs / open an actual support-case on this if it helps.

Best regards
Roman

 

[IgorG]

Roman,

We have following KB article regarding this error - http://kb.odin.com/en/6074

 

[Roman Hochuli]

Hello Igor

From the KB:
The recompiled utility with timeout value 300 seconds is included to Parallels Plesk Panel since version 9.2.

I run 9.3.0. So there should this fix be included, right?

Regards
Roman

 

[Roman Hochuli]

Actually, I am running the postfix-queue-binary from here: http://forum.parallels.com/showpost.php?p=396040&postcount=43 (Dated Jan, 29).

 

[IgorG]

Hello Igor

From the KB:
The recompiled utility with timeout value 300 seconds is included to Parallels Plesk Panel since version 9.2.

I run 9.3.0. So there should this fix be included, right?

Regards
Roman

Right, this timeout was removed in 9.3.0

 

[IgorG]

Actually, I am running the postfix-queue-binary from here: http://forum.parallels.com/showpost.php?p=396040&postcount=43 (Dated Jan, 29).

I have informed developers that this patch had fixed 'Unprocessed command' problem but other problems remains the same there. They are working on it.

 

[schatje]

After 2 days does not got this error, now this happen again on my server

Transcript of session follows.

 Out: 220 server.zeninxxyy.com ESMTP Postfix
 In:  EHLO Balivillage4
 Out: 250-server.zeninxxyy.com
 Out: 250-PIPELINING
 Out: 250-SIZE 10240000
 Out: 250-VRFY
 Out: 250-ETRN
 Out: 250-STARTTLS
 Out: 250-AUTH DIGEST-MD5 CRAM-MD5 PLAIN LOGIN
 Out: 250-ENHANCEDSTATUSCODES
 Out: 250-8BITMIME
 Out: 250 DSN
 In:  STARTTLS
 Out: 220 2.0.0 Ready to start TLS
 In:  EHLO Balivillage4
 Out: 250-server.zeninxxyy.com
 Out: 250-PIPELINING
 Out: 250-SIZE 10240000
 Out: 250-VRFY
 Out: 250-ETRN
 Out: 250-AUTH DIGEST-MD5 CRAM-MD5 PLAIN LOGIN
 Out: 250-ENHANCEDSTATUSCODES
 Out: 250-8BITMIME
 Out: 250 DSN
 In:  AUTH LOGIN
 Out: 334 VXNlcmadcWU6
 In:  aW5mb0BiYWXyZmlsbGFnZS5jb20=
 Out: 334 UGFzD34vcmQ6
 In:  YmF2AbCyMzQ=
 Out: 235 2.0.0 Authentication successful
 In:  MAIL FROM: <[email protected]>
 Out: 250 2.1.0 Ok
 In:  RCPT TO: <[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

Session aborted, reason: lost connection

HOW TO FIX THIS error??

I am use Plesk 9.3
The support guys from my Datacenter was fix it with http://kb.odin.com/en/6074
before they fix.. i got a thousand error in one day, but now i just got 3 or 5 email

Sc

 

[Flamenetworks]

Hello,

just to inform you that i'm getting, on a new server installed 5 days ago, the following errors on Plesk 9.3.0 Debian 4.0 93091230.06:

Feb 25 12:55:34 web2 postfix/smtpd[6261]: connect from bay0-omc3-s8.bay0.hotmail.com[65.54.190.146]
Feb 25 12:55:35 web2 postfix/smtpd[6267]: connect from localhost[127.0.0.1]
Feb 25 12:55:35 web2 postfix/smtpd[6261]: NOQUEUE: client=bay0-omc3-s8.bay0.hotmail.com[65.54.190.146]
Feb 25 12:55:35 web2 postfix/smtpd[6267]: 4E54876807E: client=bay0-omc3-s8.bay0.hotmail.com[65.54.190.146]
Feb 25 12:55:35 web2 before-remote[6266]: check handlers for addr: xxx@xxx
Feb 25 12:55:35 web2 before-queue[6264]: check handlers for addr: xxx@xxx
Feb 25 12:55:35 web2 before-remote[6266]: check handlers for addr: yyy@yyy
Feb 25 12:55:35 web2 before-queue[6264]: check handlers for addr: yyy@yyy
Feb 25 12:55:35 web2 before-queue[6264]: Processing handlers...
Feb 25 12:55:35 web2 before-queue[6264]: hook_dir = '/opt/psa/handlers/before-queue'
Feb 25 12:55:35 web2 before-queue[6264]: call_handlers: call executable = '/opt/psa/handlers/info/05-grey-JhoYSE/executable'
Feb 25 12:55:35 web2 greylisting filter[6269]: Starting greylisting filter...
Feb 25 12:55:35 web2 greylisting filter[6269]: Timeout finished
Feb 25 12:55:35 web2 before-queue[6264]: handlers_stderr: SKIP
Feb 25 12:55:35 web2 before-queue[6264]: call_handlers: SKIP during call '/opt/psa/handlers/info/05-grey-JhoYSE/executable' handler
Feb 25 12:55:35 web2 before-queue[6264]: recipient[3] = 'yyy@yyy'
Feb 25 12:55:35 web2 before-queue[6264]: handlers dir = '/opt/psa/handlers/before-queue/recipient/yyy@yyy'
Feb 25 12:55:35 web2 postfix/cleanup[6268]: 4E54876807E: message-id=<[email protected]>
Feb 25 12:55:54 web2 postfix/smtpd[5615]: timeout after DATA from localhost[127.0.0.1]
Feb 25 12:55:54 web2 before-remote[5988]: Unprocessed command: .externalclass
Feb 25 12:55:54 web2 postfix/smtpd[5615]: disconnect from localhost[127.0.0.1]
Feb 25 12:55:54 web2 before-remote[5988]: Unprocessed command: </style>
Feb 25 12:55:54 web2 before-remote[5988]: errno: Connection reset by peer
Feb 25 12:55:54 web2 before-remote[5988]: System error: Connection reset by peer
Feb 25 12:55:54 web2 before-remote[5988]: Unable to write data into outgoing socket
Feb 25 12:55:54 web2 before-remote[5988]: Unable to translate command answer: </style>^M
Feb 25 12:55:54 web2 postfix/spawn[5613]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255
Feb 25 12:57:16 web2 postfix/smtpd[6261]: disconnect from bay0-omc3-s8.bay0.hotmail.com[65.54.190.146]

And then i get the following e-mail message on postmaster mailbox:

Transcript of session follows.

Out: 220 myserver.com ESMTP Postfix (Debian/GNU)
In: EHLO bay0-omc3-s8.bay0.hotmail.com
Out: 250-myserver.com
Out: 250-PIPELINING
Out: 250-SIZE 1073741824
Out: 250-VRFY
Out: 250-ETRN
Out: 250-STARTTLS
Out: 250-AUTH LOGIN DIGEST-MD5 PLAIN CRAM-MD5
Out: 250-ENHANCEDSTATUSCODES
Out: 250-8BITMIME
Out: 250 DSN
In: MAIL FROM:<[email protected]> SIZE=10693
Out: 250 2.1.0 Ok
In: RCPT TO:<[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

Best regards,

F.