postfix-queue / Queue file write error is still happening

[MeikR]

Hi,

be carefull and test to send mails after installing hotfix http://kb.odin.com/en/8391.
For me, the queue file error is gone, but a worse one is born:

Here is the next error, after upgrading to this postfix-queue file, the external greylisting is activated even internal for regular pop users. This is very unlucky for all customers.

See this thread if you have also problems with this fix:
http://forum.parallels.com/showthread.php?t=101162

greetings

 

[IgorG]

Again, again and again... I can't forward to developers only your words that 'IT DOESN"T WORK!!! FIX IT IMMEDIATELY!!! YOU HAVE PROMISED FIX LONG TIME AGO!!!'.

Please, tell me - if you REALLY have this problem why till now nobody has used this instruction?

 

[MeikR]

Following Instructions from IgorG to get debug infos for the developer

@IgoR: I followed your Instructions and list the results here:

System:
Uptodate (upgraded 02.05.2010) Debian Lenny64bit and Plesk 9.3 (now with postfix-queue 9.2.3 with much less errors of file writing queue).

Instructions:
0. Read carefully http://kb.odin.com/en/8391
done

1. Look up time of error message.
error messages are nearly round the clock

2. Find part of DEBUG
egrep '(warning|error|fatal|panic):' /usr/local/psa/var/log/maillog | more
May 4 08:49:32 <servername> postfix/spawn[20380]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255
May 4 08:49:36 <servername> before-remote[21148]: System error: Broken pipe
May 4 08:49:36 <servername> postfix/spawn[19503]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255
May 4 08:49:36 <servername> postfix/smtpd[20217]: warning: lost connection with proxy 127.0.0.1:10025
May 4 08:49:37 <servername> postfix/smtpd[20215]: warning: 122.180.11.194: hostname NSG-Corporate-194.11.180.122.airtel.in verification failed: N
me or service not known
May 4 07:49:59 <servername> postfix/spawn[17596]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255
May 4 07:50:48 <servername> postfix/spawn[17596]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255
May 4 07:51:23 <servername> postfix/spawn[17596]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255
May 4 07:51:25 <servername> postfix/spawn[17596]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255
May 4 07:51:52 <servername> postfix/smtpd[18021]: warning: 210.89.44.239: hostname Sonali-44-239.pacenet-india.com verification failed: Name or se
rvice not known
May 4 07:51:52 <servername> postfix/spawn[17596]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255
May 4 07:51:53 <servername> postfix/smtpd[17600]: warning: 210.89.44.239: hostname Sonali-44-239.pacenet-india.com verification failed: Name or se
rvice not known
May 4 07:51:54 <servername> postfix/spawn[17596]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255
May 4 07:51:54 <servername> postfix/smtpd[18021]: warning: 210.89.44.239: hostname Sonali-44-239.pacenet-india.com verification failed: Name or se
rvice not known
May 4 07:51:55 <servername> postfix/spawn[17596]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255
May 4 07:52:02 <servername> postfix/spawn[17596]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255
May 4 07:52:26 <servername> postfix/spawn[17596]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255
May 4 07:52:39 <servername> postfix/spawn[17596]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255
May 4 07:52:59 <servername> postfix/spawn[17596]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255
May 4 07:53:02 <servername> postfix/spawn[17596]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255
May 4 07:53:04 <servername> postfix/spawn[17596]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255
May 4 07:53:31 <servername> postfix/spawn[17596]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255
May 4 07:53:57 <servername> postfix/spawn[17608]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255
May 4 07:53:57 <servername> postfix/spawn[17180]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255
May 4 07:53:58 <servername> postfix/smtpd[17600]: warning: 195.68.235.28: hostname 195-68-235-28.ferimex.net verification failed: Name or service
not known
May 4 09:02:23 <servername> before-queue[21905]: System error: Broken pipe
May 4 09:11:57 <servername> postfix/smtpd[20217]: warning: 222.252.162.19: address not listed for hostname localhost
May 4 09:12:00 <servername> postfix/spawn[21423]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255
May 4 09:12:48 <servername> postfix/spawn[21423]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255


egrep '(warning|error|fatal|panic):' /var/log/mail.error | more
May 2 06:46:18 <servername> before-queue[24432]: System error: Broken pipe
May 2 07:18:44 <servername> before-queue[25604]: System error: Broken pipe
May 2 07:56:13 <servername> before-queue[27008]: System error: Broken pipe
May 2 08:01:00 <servername> before-queue[27169]: System error: Connection reset by peer
May 2 08:11:00 <servername> before-remote[27309]: System error: Broken pipe
--cutoff some time ---
May 3 12:12:20 <servername> before-queue[29056]: System error: Broken pipe
May 3 18:31:58 <servername> before-queue[16293]: System error: Broken pipe
May 3 19:50:41 <servername> before-queue[19525]: System error: Broken pipe
May 3 19:59:13 <servername> before-queue[19917]: System error: Broken pipe
May 3 20:00:14 <servername> before-queue[20011]: System error: Broken pipe
May 3 20:01:16 <servername> before-queue[20049]: System error: Broken pipe
May 3 20:02:18 <servername> before-queue[20085]: System error: Broken pipe
May 3 20:04:20 <servername> before-remote[20163]: System error: Connection reset by peer
May 3 20:07:22 <servername> before-queue[20294]: System error: Broken pipe
May 4 08:25:23 <servername> before-remote[19767]: System error: Broken pipe
May 4 08:49:36 <servername> before-remote[21148]: System error: Broken pipe
May 4 09:02:23 <servername> before-queue[21905]: System error: Broken pipe

3. Post output of 'df -h' command.
# df -h
Dateisystem GröÃe Benut Verf Ben% Eingehängt auf
/dev/md1 458G 7,5G 427G 2% /
tmpfs 2,0G 0 2,0G 0% /lib/init/rw
udev 10M 672K 9,4M 7% /dev
tmpfs 2,0G 0 2,0G 0% /dev/shm
/dev/md0 54M 8,4M 42M 17% /boot
tmpfs 2,0G 0 2,0G 0% /opt/psa/handlers/before-local
tmpfs 2,0G 0 2,0G 0% /opt/psa/handlers/before-queue
tmpfs 2,0G 0 2,0G 0% /opt/psa/handlers/before-remote
tmpfs 2,0G 24K 2,0G 1% /opt/psa/handlers/info
tmpfs 2,0G 0 2,0G 0% /opt/psa/handlers/spool

4. Any additional related errors from /var/log/messages
# egrep '(warning|error|fatal|panic):' /var/log/messages | more
May 2 14:50:05 <servername> kernel: [ 53.219102] warning: `ntpd' uses 32-bit capabilities (legacy support in use)


So the "postfix-queue exit status 255" seems to be normal greylisting procedures, but I cannot get detailed information about the broken pipes.
If I should post other infos, plz let me know.

regards

 

[karesmakro]

O.k., here is your reply:

0. done
1. 04.05.2010 at 8:55 a clock
2. my debug log you can find on http://www.it-connect-unix.de/downloads/postfix_error.txt
3. df -h

Dateisystem          Größe Benut  Verf Ben% Eingehängt auf
/dev/md1               56G   12G   41G  22% /
tmpfs                 2,0G     0  2,0G   0% /lib/init/rw
udev                   10M   72K   10M   1% /dev
tmpfs                 2,0G  4,0K  2,0G   1% /dev/shm
/dev/md0              183M   69M  104M  40% /boot
/dev/md3              855G   83G  729G  11% /var
tmpfs                 2,0G     0  2,0G   0% /opt/psa/handlers/before-local
tmpfs                 2,0G     0  2,0G   0% /opt/psa/handlers/before-queue
tmpfs                 2,0G     0  2,0G   0% /opt/psa/handlers/before-remote
tmpfs                 2,0G  1,3M  2,0G   1% /opt/psa/handlers/info
tmpfs                 2,0G     0  2,0G   0% /opt/psa/handlers/spool

4. no additional infos

one hint: the mail, which failed to send is a systeminformation report of a server, I administrate! And you can see in the data stream, parts of this systeminformation, which shouldn't be displayed in this logentry.
At this moment, I have to kill the postfix-queue processes, because they never stop.

Used postfix-queue file is from Plesk 9.3.0! I can't use the new postfix-queue file from 9.5.1, because I got thousands of postfix-queue processes and server stops to accept mails ...
Next thing is, that no user can send mails from horde, which is not acceptable for my customer, because there are some companies, which uses webmail to handle their business mail.
No chance, to revert to the newer version!

Some more informations needed?

 

[IgorG]

Guys, thank you very much. I have discussed and forwarded your details and logs to developers. It will be checked and investigated soon. I will update this thread with any useful information as soon as I receive it from developers.

 

[IgorG]

@IgoR: I followed your Instructions and list the results here:
......
regards

Could you please provide me output of the following commands?

1. postconf |grep timeout
2. egrep -C 10 '(warning|error|fatal|panic):' /usr/local/psa/var/log/maillog | more

 

[karesmakro]

Some other information:
do the developer know about the problem related to multiple sender addresses? Which could also lead to a not correctly parsed mails! What's about mails, which are filtered more the once, before the mail is accepted by a plesk mailserver? This was for example happened, when my related systeminformation in my previous post was sent? I speak about all the mail header contents, which I can see in my debug log file (the filter parts). The mail, which was sent and leaded to the queue file write error was an email in unix textformat.
Why your posftix-queue file parses the data end stream?

 

[karesmakro]

@Igor the ouputs:

postconf |grep timeout
connection_cache_protocol_timeout = 5s
daemon_timeout = 18000s
ipc_timeout = 7200s
lmtp_connect_timeout = 0s
lmtp_data_done_timeout = 600s
lmtp_data_init_timeout = 120s
lmtp_data_xfer_timeout = 180s
lmtp_lhlo_timeout = 300s
lmtp_mail_timeout = 300s
lmtp_quit_timeout = 300s
lmtp_rcpt_timeout = 300s
lmtp_rset_timeout = 20s
lmtp_starttls_timeout = 300s
lmtp_tls_session_cache_timeout = 3600s
lmtp_xforward_timeout = 300s
milter_command_timeout = 30s
milter_connect_timeout = 30s
milter_content_timeout = 300s
qmqpd_timeout = 300s
smtp_connect_timeout = 30s
smtp_data_done_timeout = 600s
smtp_data_init_timeout = 120s
smtp_data_xfer_timeout = 180s
smtp_helo_timeout = 300s
smtp_mail_timeout = 300s
smtp_quit_timeout = 300s
smtp_rcpt_timeout = 300s
smtp_rset_timeout = 20s
smtp_starttls_timeout = 300s
smtp_tls_session_cache_timeout = 3600s
smtp_xforward_timeout = 300s
smtpd_policy_service_timeout = 100s
smtpd_proxy_timeout = 3600s
smtpd_starttls_timeout = 300s
smtpd_timeout = 3600s
smtpd_tls_session_cache_timeout = 3600s
trigger_timeout = 10s

to your second question, I have only a maillog file with 0 bytes, because my logs goes all to mail.info, mail.err and mail.warn
but here are some parts of it

May  2 21:37:46 deb-gk1 before-remote[22847]: Lost connection
May  2 21:37:46 deb-gk1 before-remote[22847]: Some error occured
May  2 21:39:53 deb-gk1 before-remote[18919]: errno: Broken pipe
May  2 21:39:53 deb-gk1 before-remote[18919]: System error: Broken pipe
May  2 21:39:53 deb-gk1 before-remote[18919]: Unable to write data into incoming socket
May  2 21:39:53 deb-gk1 before-remote[18919]: Unable to translate command answer:     font-size:   10px;
May  3 07:27:10 deb-gk1 before-remote[17704]: errno: Broken pipe
May  3 07:27:10 deb-gk1 before-remote[17704]: System error: Broken pipe
May  3 07:27:10 deb-gk1 before-remote[17704]: Unable to write data into incoming socket
May  3 07:27:10 deb-gk1 before-remote[17704]: Unable to translate command answer:     font-size:   10px;
May  3 15:31:56 deb-gk1 before-remote[10622]: Lost connection
May  3 15:31:56 deb-gk1 before-remote[10622]: Some error occured
May  3 15:34:09 deb-gk1 before-remote[7634]: errno: Broken pipe
May  3 15:34:09 deb-gk1 before-remote[7634]: System error: Broken pipe
May  3 15:34:09 deb-gk1 before-remote[7634]: Unable to write data into incoming socket
May  3 15:34:09 deb-gk1 before-remote[7634]: Unable to translate command answer: <a href=3D"http://info.bonprix.de/re?l=3Dew4
pd6If6057pI5&req=3Dversion%3D90=

 

[ISSchuster]

Update:

"postfix-queue" from 9.5.1 is working without problems (24 hours now) - but only without greylisting (and spf)

I have no hanging or long running postfix-queue-process at the moment. Even messages which have been rejected before ("queue file wirte error") could be delivered successfully after updating to 9.5.1 AND deactivating greylisting...

 

[IgorG]

@Igor the ouputs:

Could you please update thread with:

# md5sum /usr/lib/plesk-9.0/postfix-queue (or /usr/lib64/plesk-9.0/postfix-queue)
# cat /etc/*release
# uname -a

Also we need the same part of maillog but for before-queue.
Thank you.

 

[karesmakro]

1. md5sum
1b77a431a89846fd3caffb847092840b

2. cat /etc/*release
cat /etc/debian_version
4.0
is it, what you wanted to see?

3. uname -a
2.6.27.46 #1 SMP Sat Apr 3 18:01:51 CEST 2010 x86_64 GNU/Linux
is self compiled, because of unusual used hardware (ethernet card)

4. tail -n 500 /var/log/mail.warn | grep before-queue

May  5 07:24:37 deb-gk1 before-queue[29317]: Processing handlers...
May  5 07:29:38 deb-gk1 before-queue[29317]: Timeout reading data from stream
May  5 07:29:38 deb-gk1 before-queue[29317]: Unable to read data exit status code from stream
May  5 07:29:38 deb-gk1 before-queue[29317]: Some error occured
May  5 07:30:27 deb-gk1 before-queue[29538]: Processing handlers...
May  5 07:30:27 deb-gk1 before-queue[29538]: call_handlers: stop call handlers from dir '/opt/psa/handlers/before-queue/global'
May  5 07:32:44 deb-gk1 before-queue[29566]: Processing handlers...
May  5 07:37:04 deb-gk1 before-queue[29768]: Processing handlers...
May  5 07:37:04 deb-gk1 before-queue[29768]: call_handlers: stop call handlers from dir '/opt/psa/handlers/before-queue/global'
May  5 07:37:45 deb-gk1 before-queue[29566]: Timeout reading data from stream
May  5 07:37:45 deb-gk1 before-queue[29566]: Unable to read data exit status code from stream
May  5 07:37:45 deb-gk1 before-queue[29566]: Some error occured
May  5 07:40:11 deb-gk1 before-queue[29893]: Processing handlers...
May  5 07:40:11 deb-gk1 before-queue[29893]: call_handlers: stop call handlers from dir '/opt/psa/handlers/before-queue/global'

 

[MeikR]

Hi,

after 3 days of watching the behavior of the postfix-queue file 9.2.3 I have still queue file errors. Every few minutes I get a mail with these error, because the sending server try again and again... So this is not a solution for me.

New errors:
Since I followed the instructions in http://kb.odin.com/en/8391 in setting the timeout settings:

/etc/postfix/main.cf
--->8---
smtpd_timeout=3600s
smtpd_proxy_timeout=3600s
---8<---

Now, I got some timeouts even for very little mails

In: MAIL From:<[email protected]> SIZE=12855
Out: 250 2.1.0 Ok
In: RCPT To:<[email protected]> NOTIFY=SUCCESS,FAILURE,DELAY
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
Out: 421 4.4.2 servername.de Error: timeout exceeded

@IgorG: The result of your egrep -C 10 '(warning|error|fatal|panic):' /usr/local/psa/var/log/maillog is very big and has sensitive data. How can I provide it to you?

Here is the timeout info, you wanted to know:

# postconf |grep timeout
connection_cache_protocol_timeout = 5s
daemon_timeout = 18000s
ipc_timeout = 3600s
lmtp_connect_timeout = 0s
lmtp_data_done_timeout = 600s
lmtp_data_init_timeout = 120s
lmtp_data_xfer_timeout = 180s
lmtp_lhlo_timeout = 300s
lmtp_mail_timeout = 300s
lmtp_quit_timeout = 300s
lmtp_rcpt_timeout = 300s
lmtp_rset_timeout = 20s
lmtp_starttls_timeout = 300s
lmtp_tls_session_cache_timeout = 3600s
lmtp_xforward_timeout = 300s
milter_command_timeout = 30s
milter_connect_timeout = 30s
milter_content_timeout = 300s
qmqpd_timeout = 300s
smtp_connect_timeout = 30s
smtp_data_done_timeout = 600s
smtp_data_init_timeout = 120s
smtp_data_xfer_timeout = 180s
smtp_helo_timeout = 300s
smtp_mail_timeout = 300s
smtp_quit_timeout = 300s
smtp_rcpt_timeout = 300s
smtp_rset_timeout = 20s
smtp_starttls_timeout = 300s
smtp_tls_session_cache_timeout = 3600s
smtp_xforward_timeout = 300s
smtpd_policy_service_timeout = 100s
smtpd_proxy_timeout = 100s
smtpd_starttls_timeout = 300s
smtpd_timeout = 300s
smtpd_tls_session_cache_timeout = 3600s
trigger_timeout = 10s

# uname -a
Linux servername 2.6.26-2-amd64 #1 SMP Thu Feb 11 00:59:32 UTC 2010 x86_64 GNU/Linux

tail -n 2000 /var/log/mail.warn | grep before-queue | more (only some entrys)

May 6 12:45:35 h1673007 before-queue[12262]: call_handlers: stop call handlers from dir '/opt/psa/handlers/before-queue/global'
May 6 12:45:35 h1673007 before-queue[12267]: Processing handlers...
May 6 12:45:41 h1673007 before-queue[12276]: Processing handlers...
May 6 12:45:47 h1673007 before-queue[12285]: Processing handlers...
May 6 12:45:48 h1673007 before-queue[12285]: Lost connection
May 6 12:45:48 h1673007 before-queue[12285]: Some error occured
May 6 12:45:49 h1673007 before-queue[12287]: Processing handlers...
May 6 13:44:54 h1673007 before-queue[15593]: call_handlers: stop call handlers from dir '/opt/psa/handlers/before-queue/global'
May 6 13:45:07 h1673007 before-queue[15608]: Processing handlers...
May 6 13:45:08 h1673007 before-queue[15608]: call_handlers: stop call handlers from dir '/opt/psa/handlers/before-queue/global'
May 6 13:45:26 h1673007 before-queue[15621]: Processing handlers...
May 6 13:45:27 h1673007 before-queue[15621]: call_handlers: stop call handlers from dir '/opt/psa/handlers/before-queue/global'

Greetings...

 

[IgorG]

Thank you for detailed information. I have forwarded it to developers too.

 

[GravuTrad]

Followed, cause i got this problem too and it still unsolved....

 

[MeikR]

Any news to this problem???

@IgorG:
we are waiting: 3 weeks of nothing happens...
You want to update this thread. The developers cannot need soooo much time for this...

 

[ChristopheP]

Almost 1 year this problem hit my servers and it's still not fixed.

Mind fixing it ? or hand over the source code of postfix-queue, I will fix it myself

 

[karesmakro]

I don't believe, it'll be ever fixed by plesk ... I read in another forum, as somebody hired a gold level support from plesk and no solution. This was a year ago.
I integrated my own solution using policyd v2, and this is the last server, I built with plesk ...

 

[ChristopheP]

You are right, Plesk has the potential to rule everything but lately they seem to grab the money and drink cocktails.

Give us postfix-queue source code. There is no trade-secret inside this crappy piece of software, except if you want to hide some dirty programming.

 

[fearz]

appeciating your support please

so i was using 9.2.1 and honestly with no problems whatsoever sending emails .. including attachments, our mailserver sends and receives around 1000 emails per day,

i had some of these errors but no one complained i also was using the mail extensively but no problems appeared until on may 31st there was an email bieng sent by a client from hotmail to our mail server and it repeatedly outputed the famous queue file write error , it was the only email that was causing that problem, and no matter what i do hotmail servers would keep on sending & sending that email..i simply coukdnt stop it

i tried several things to try and remove it, but i couldn't stop it, so i did the upgrade to plesk 9.5.2 - the error was gone and emails were working fine, sending emails with attachments from 4 to 20 megabytes with no problems, but i kept monitoring logs i concluded the following:

if i was sending an email including an attachment, and i canceled the sending, the error comes back (same error)

Jun 6 22:10:41 server1 before-queue[28387]: Lost connection.
Jun 6 22:10:41 server1 before-queue[28387]: Some error occured
Jun 6 22:10:41 server1 postfix/spawn[20202]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255
Jun 6 22:10:41 server1 before-remote[28389]: Lost connection.
Jun 6 22:10:41 server1 before-remote[28389]: Some error occured
Jun 6 22:10:41 server1 postfix/spawn[20205]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255

so then i relaxed that this output would be caused by cancelled emails that were sent

until i got this:

Jun 6 11:27:24 server1 before-remote[30624]: System error: Broken pipe
Jun 6 11:27:24 server1 before-remote[30624]: Unable write data into stream
Jun 6 11:27:24 server1 before-remote[30624]: Some error occured
Jun 6 11:27:24 server1 postfix/spawn[30623]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255
Jun 6 11:27:24 server1 before-queue[30622]: System error: Connection reset by peer
Jun 6 11:27:24 server1 before-queue[30622]: Unable write data into stream
Jun 6 11:27:24 server1 before-queue[30622]: Some error occured
Jun 6 11:27:24 server1 postfix/spawn[30621]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255

I dont know what might have happened to output this, i tried to reproduce the error but failed.

Can anybody support by telling me what might have caused that?

i double checked sending emails with various attachment sizes and there are no problems doing so,

im using Centos 5 i386

 

[fearz]

i've joined the club!

now i cant even have it stable!

either decrease timeout and have postfix-queue processes timeout early but then i receive broken pipe errors

or i increase the timeout and have many postfix-queue processes running...

any solutions for that?