Postfix still sending hundreds 'queue file write error'

[ChristopheP]

Hi,

You said this problem would be fixed in 9.3 but it's not the case :/

I am receiving hundreds of messages like this:

Transcript of session follows.

Out: 220 ekadomu1.ekaserver.com ESMTP Postfix
In: EHLO pansrv1.xxxxx
Out: 250-ekadomu1.ekaserver.com
Out: 250-PIPELINING
Out: 250-SIZE 18432000
Out: 250-VRFY
Out: 250-ETRN
Out: 250-STARTTLS
Out: 250-AUTH LOGIN PLAIN CRAM-MD5 DIGEST-MD5
Out: 250-ENHANCEDSTATUSCODES
Out: 250-8BITMIME
Out: 250 DSN
In: MAIL From:<danny_power@xxxxx> SIZE=4310
Out: 250 2.1.0 Ok
In: RCPT To:<meg@xxxx>
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 as follows :

Jan 15 16:22:03 ekadomu1 postfix/smtpd[11434]: NOQUEUE: client=unknown[80.193.75.233]
Jan 15 16:22:03 ekadomu1 postfix/smtpd[11441]: 63AC95C0164: client=unknown[80.193.75.233]
Jan 15 08:22:03 ekadomu1 before-remote[11440]: check handlers for addr: danny_power@xxxxxx
Jan 15 08:22:03 ekadomu1 before-remote[11440]: check handlers for addr: meg@yyyy
Jan 15 08:22:03 ekadomu1 before-queue[11438]: check handlers for addr: danny_power@xxxxxx
Jan 15 08:22:03 ekadomu1 before-queue[11438]: check handlers for addr: meg@yyyy
Jan 15 08:22:03 ekadomu1 before-queue[11438]: Processing handlers...
Jan 15 08:22:03 ekadomu1 before-queue[11438]: hook_dir = '/usr/local/psa/handlers/before-queue'
Jan 15 08:22:03 ekadomu1 before-queue[11438]: call_handlers: call executable = '/usr/local/psa/handlers/info/10-spf-7ctHuC/executable'
Jan 15 08:22:03 ekadomu1 spf filter[11443]: Starting spf filter...
Jan 15 08:22:03 ekadomu1 spf filter[11443]: Error code: (2) Could not find a valid SPF record
Jan 15 08:22:03 ekadomu1 spf filter[11443]: Failed to query MAIL-FROM: No DNS data for 'xxxxxx'.
Jan 15 08:22:03 ekadomu1 spf filter[11443]: SPF result: none
Jan 15 08:22:03 ekadomu1 spf filter[11443]: SPF status: PASS
Jan 15 08:22:03 ekadomu1 before-queue[11438]: handlers_stderr: PASS
Jan 15 08:22:03 ekadomu1 before-queue[11438]: call_handlers: PASS during call '/usr/local/psa/handlers/info/10-spf-7ctHuC/executable' handler
Jan 15 08:22:03 ekadomu1 before-queue[11438]: recipient[3] = 'meg@yyy'
Jan 15 08:22:03 ekadomu1 before-queue[11438]: handlers dir = '/usr/local/psa/handlers/before-queue/recipient/meg@yyyyy'
Jan 15 08:22:03 ekadomu1 before-remote[11440]: Unprocessed command: received:
Jan 15 08:22:03 ekadomu1 before-remote[11440]: Unprocessed command: #011for
Jan 15 08:22:03 ekadomu1 before-remote[11440]: Unprocessed command:
Jan 15 08:22:03 ekadomu1 postfix/cleanup[11442]: 63AC95C0164: message-id=<[email protected]>
Jan 15 08:22:03 ekadomu1 before-queue[11438]: Unprocessed command: #011by
Jan 15 08:22:03 ekadomu1 before-queue[11438]: Unprocessed command:
Jan 15 08:22:03 ekadomu1 before-queue[11438]: errno: Connection reset by peer
Jan 15 08:22:03 ekadomu1 before-queue[11438]: System error: Connection reset by peer
Jan 15 08:22:03 ekadomu1 before-queue[11438]: Unable to write data into outgoing socket
Jan 15 08:22:03 ekadomu1 before-queue[11438]: Unable to translate command answer: meg@yyyy; Fri, 15 Jan 2010 16:14:59 +0000#015
Jan 15 08:22:03 ekadomu1 postfix/spawn[11437]: warning: command /usr/lib64/plesk-9.0/postfix-queue exit status 255
Jan 15 16:22:03 ekadomu1 postfix/smtpd[11434]: warning: received garbage from proxy 127.0.0.1:10025: Received-SPF: none (no valid SPF record)
Jan 15 16:22:03 ekadomu1 postfix/smtpd[11434]: warning: received garbage from proxy 127.0.0.1:10025: Received: from [10.10.10.60] by xxxxx (GMS
Jan 15 16:22:03 ekadomu1 postfix/smtpd[11434]: warning: lost connection with proxy 127.0.0.1:10025
Jan 15 16:22:03 ekadomu1 postfix/smtpd[11441]: warning: non-SMTP command from unknown[127.0.0.1]: Received: from xxxxx (unknown [80.193.75.233])
Jan 15 16:22:03 ekadomu1 postfix/smtpd[11441]: disconnect from unknown[127.0.0.1]
Jan 15 08:22:03 ekadomu1 postfix/qmgr[32182]: 63AC95C0164: from=<danny_power@xxxxx>, size=840, nrcpt=1 (queue active)
Jan 15 08:22:03 ekadomu1 postfix-local[11446]: postfix-local: from=danny_power@xxxx, to=meg@yyyy, dirname=/var/qmail/mailnames
Jan 15 08:22:03 ekadomu1 postfix-local[11446]: hook_dir = '/usr/local/psa/handlers/before-local'
Jan 15 08:22:03 ekadomu1 postfix-local[11446]: recipient[3] = 'meg@yyyyy'
Jan 15 08:22:03 ekadomu1 postfix-local[11446]: handlers dir = '/usr/local/psa/handlers/before-local/recipient/meg@yyyy'
Jan 15 08:22:03 ekadomu1 postfix-local[11446]: call_handlers: call executable = '/usr/local/psa/handlers/info/10-dd52-domainkeys-sOi2zo/executable'
Jan 15 08:22:03 ekadomu1 dk_check[11447]: DK_STAT_NOSIG: No signature available in message
Jan 15 08:22:03 ekadomu1 postfix-local[11446]: handlers_stderr: PASS
Jan 15 08:22:03 ekadomu1 postfix-local[11446]: call_handlers: PASS during call '/usr/local/psa/handlers/info/10-dd52-domainkeys-sOi2zo/executable' handler
Jan 15 08:22:03 ekadomu1 postfix/pipe[11444]: 63AC95C0164: to=<meg@xxx>, relay=plesk_virtual, delay=0.38, delays=0.36/0.01/0/0.01, dsn=2.0.0, status=sent (delivered via plesk_virtual service)
Jan 15 08:22:03 ekadomu1 postfix/qmgr[32182]: 63AC95C0164: removed

Thank you for your help

 

[ChristopheP]

Please click one of the Quick Reply icons in the posts above to activate Quick Reply.

 

[ChristopheP]

I can provide a network capture (tcpdump) of the SMTP connection, so devs can reproduce the problem. Just provide me an email to send to

 

[IgorG]

Fix for "Unprocessed command" problem was not included to 9.3.0 version. You can use patches from already published workaround.

 

[ChristopheP]

Could you please provide a link toward the patch you want me to apply ? I don't want to break anything.

In addition, it will be a pain to upgrade my 25+ servers the same way. I hope the official fix will come soon.

thank you

 

[IgorG]

All available workaround here http://forum.parallels.com/showthread.php?t=95956

Your workaround here http://forum.parallels.com/showpost.php?p=396040&postcount=43

 

[raz3k]

prove me i'm wrong

Now using plesk 9.3.0 + unprocessed command patch on centos 5.4 x86_64.

Jan 19 04:45:44 ns01 before-remote[6516]: hook_dir = '/usr/local/psa/handlers/before-remote'
Jan 19 04:45:44 ns01 before-remote[6516]: recipient[3] = '[email protected]'
Jan 19 04:45:44 ns01 before-remote[6516]: handlers dir = '/usr/local/psa/handlers/before-remote/recipient/[email protected]'
Jan 19 04:45:44 ns01 before-remote[6516]: errno: Broken pipe
Jan 19 04:45:44 ns01 before-remote[6516]: System error: Broken pipe
Jan 19 04:45:44 ns01 before-remote[6516]: Unable to write data to stream
Jan 19 04:45:44 ns01 before-remote[6516]: Some error occured
Jan 19 04:45:44 ns01 postfix/spawn[6515]: warning: command /usr/lib64/plesk-9.0/postfix-queue exit status 255

 

[IgorG]

Did you tried switch to Qmail instead Postfix?

 

[raz3k]

No, i have not, i am afraid it will break my configuration, if i still get complaints i think i will. I don't know what did the developers fixed, but this bug still exists in some way. If it is related to timeout problems, i suggest to add a new feature that allows you to manually set a desired timeout, and then everybody can work on their problem, not waiting for the developers.

Thanks.

 

[IgorG]

According to developers problem with timeout in postfix-queue is completely solved in 9.3.0 version. There are can be other internal Postfix problems which should be investigated separately. Qmail much more stable MTA than Postfix in my opinion.

 

[ISSchuster]

Same problem here... Plesk 9.3 + "postfix-queue"-Hotfix

Jan 19 18:54:46 kallisto before-remote[9900]: Unprocessed command: .
Jan 19 18:54:46 kallisto before-remote[9900]: Unprocessed command: :
Jan 19 18:54:46 kallisto before-remote[9900]: errno: Broken pipe
Jan 19 18:54:46 kallisto before-remote[9900]: System error: Broken pipe
Jan 19 18:54:46 kallisto before-remote[9900]: Unable to write data into outgoing socket
Jan 19 18:54:46 kallisto before-remote[9900]: Unable to translate command answer: :^M
Jan 19 18:54:46 kallisto postfix/spawn[9762]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255

 

[IgorG]

I have notified developers about this problem on 9.3.0. Let's wait their answer.

 

[ChristopheP]

No, i have not, i am afraid it will break my configuration, if i still get complaints i think i will.
Thanks.

I have a network capture that shows that start of SMTP connection and error message only takes 1.5seconds. I doubt there is any timeout problem this time.

 

[raz3k]

Can you please tell me how to reproduce the error (what attachment size should i use)? I have not managed, but my clients are reproducing it full time.
Thanks.

 

[ChristopheP]

Total size of the mail is 4835 for example .... that is quite low. I can provide devs the network capture of the SMTP connection, but only to them are there could be sensitive infos inside.

 

[ISSchuster]

Push... The problem still exists...

What are the programmers doing all day long? Thinking which new bug they can implement in the next version?!?

 

[JamieRW]

I too have same problem... need a fix!

Jan 30 00:17:44 server001 dk_check[10533]: DK_STAT_NOSIG: No signature available in message
Jan 30 00:56:30 server001 before-queue[11606]: Processing handlers...
Jan 30 00:56:30 server001 before-remote[11608]: Processing handlers...
Jan 30 00:56:31 server001 before-remote[11608]: errno: Broken pipe
Jan 30 00:56:31 server001 before-remote[11608]: System error: Broken pipe
Jan 30 00:56:31 server001 before-remote[11608]: Unable to write data into outgoing socket
Jan 30 00:56:31 server001 before-remote[11608]: Unable to translate command answer: ..mini {^M

j.

 

[IgorG]

I have updated workaround for 'Unprocessed command' error with new patched files. Try it.

 

[IgorG]

Hi Igor,

I tried and patch does not work.

Do you still have 'Unprocessed command' errors with this patch?

 

[kanada]

Unfortunately there's still problem with postfix (2.5.6) and "Error: queue file write error".
OS: Fedora 11
PSK: 9.3.0

Couple examples:

Out: 220 xxxxxxx ESMTP Postfix (2.5.6) (Hosting Mail Server)
In: EHLO xxxxxxxxx
Out: 250-xxxxxxxx
Out: 250-PIPELINING
Out: 250-SIZE 102400000
Out: 250-VRFY
Out: 250-ETRN
Out: 250-STARTTLS
Out: 250-AUTH CRAM-MD5 LOGIN PLAIN DIGEST-MD5
Out: 250-AUTH=CRAM-MD5 LOGIN PLAIN DIGEST-MD5
Out: 250-ENHANCEDSTATUSCODES
Out: 250-8BITMIME
Out: 250 DSN
In: STARTTLS
Out: 220 2.0.0 Ready to start TLS
In: EHLO xxxxxxx
Out: 250-xxxxxxx
Out: 250-PIPELINING
Out: 250-SIZE 102400000
Out: 250-VRFY
Out: 250-ETRN
Out: 250-AUTH CRAM-MD5 LOGIN PLAIN DIGEST-MD5
Out: 250-AUTH=CRAM-MD5 LOGIN PLAIN DIGEST-MD5
Out: 250-ENHANCEDSTATUSCODES
Out: 250-8BITMIME
Out: 250 DSN
In: MAIL FROM:<xxxx@xxxxx> SIZE=318941
Out: 250 2.1.0 Ok
In: RCPT TO:<xxxxx@xxxxx>
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

Out: 250-xxxxxxxxxxx
Out: 250-PIPELINING
Out: 250-SIZE 102400000
Out: 250-VRFY
Out: 250-ETRN
Out: 250-STARTTLS
Out: 250-AUTH CRAM-MD5 LOGIN PLAIN DIGEST-MD5
Out: 250-AUTH=CRAM-MD5 LOGIN PLAIN DIGEST-MD5
Out: 250-ENHANCEDSTATUSCODES
Out: 250-8BITMIME
Out: 250 DSN
In: AUTH LOGIN
Out: 334 ADMOQPNNH
In: ml298bznn
Out: 334 ==2saxxds
In: aMalsku
Out: 235 2.7.0 Authentication successful
In: MAIL FROM: <xxxx@xxxxxxx>
Out: 250 2.1.0 Ok
In: RCPT TO: <xxxxxxxx@xxxxxxx>
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

On both spam filter (spamassassin is on).

Regards,
Alex