Postfix still sending hundreds 'queue file write error'

[KlausR2020]

1. Version of Plesk and OS. Specify, if it is Virtuozzo container.
SuSE 11.0 kernel 2.6.25.20-0.5-default
Plesk 9.3.0 standalone (non-virtuozzo), actual version

2. What of the published Postfix patches have been installed.

3. Do you have enabled any spam protections.
enabled SpamAssassin

Before I applied the latest patch described before, I had this errors:

Feb 28 23:28:17 h980494 postfix/smtpd[26988]: 4DACA2D8197: client=unknown[65.55.x.x]:56788
Mar 1 00:28:17 h980494 before-remote[26987]: check handlers for addr: [email protected]
Mar 1 00:28:17 h980494 before-remote[26987]: check handlers for addr: [email protected]
Mar 1 00:28:17 h980494 before-queue[26985]: check handlers for addr: [email protected]
Mar 1 00:28:17 h980494 before-queue[26985]: check handlers for addr: [email protected]
Mar 1 00:28:17 h980494 before-queue[26985]: Processing handlers...
Mar 1 00:28:17 h980494 postfix/spawn[26984]: warning: command /usr/lib/plesk-9.0/postfix-queue killed by signal 11
Mar 1 00:28:17 h980494 kernel: postfix-queue[26985]: segfault at 7338524a ip 0804a5d2 sp bfa3e720 error 4 in postfix-queue[8048000+11000]
Mar 1 00:28:17 h980494 before-remote[26987]: Lost connection
Mar 1 00:28:17 h980494 before-remote[26987]: Some error occured
Mar 1 00:28:17 h980494 postfix/spawn[26986]: warning: command /usr/lib/plesk-9.0/postfix-queue exit status 255

The hotmail mx sends the message again within 4 minutes.
Applied the patch, the problem is solved:

Mar 1 17:36:14 h980494 postfix/smtpd[25803]: B150D2D8320: client=unknown[65.55.x.x]:22425
Mar 1 18:36:14 h980494 before-remote[25802]: check handlers for addr: [email protected]
Mar 1 18:36:14 h980494 before-remote[25802]: check handlers for addr: [email protected]
Mar 1 18:36:14 h980494 before-queue[25800]: check handlers for addr: [email protected]
Mar 1 18:36:14 h980494 before-queue[25800]: check handlers for addr: [email protected]
Mar 1 18:36:14 h980494 before-queue[25800]: Processing handlers...
Mar 1 18:36:15 h980494 before-queue[25800]: hook_dir = '/usr/local/psa/handlers/before-queue'
Mar 1 18:36:15 h980494 before-queue[25800]: recipient[3] = '[email protected]'
Mar 1 18:36:15 h980494 before-queue[25800]: handlers dir = '/usr/local/psa/handlers/before-queue/recipient/[email protected]'
Mar 1 18:36:15 h980494 before-queue[25800]: call_handlers: call executable = '/usr/local/psa/handlers/info/20-drweb-75zCjZ/executable'
Mar 1 18:36:15 h980494 drwebd.real: 127.0.0.1 [14000] /var/drweb/spool/drweb.tmp.Gmmep5 - archive MAIL
Mar 1 18:36:15 h980494 drwebd.real: 127.0.0.1 [14000] /var/drweb/spool/drweb.tmp.Gmmep5 - archive MAIL
Mar 1 18:36:15 h980494 drwebd.real: 127.0.0.1 [14000] >/var/drweb/spool/drweb.tmp.Gmmep5/1.part - Ok
Mar 1 18:36:15 h980494 drwebd.real: 127.0.0.1 [14000] >/var/drweb/spool/drweb.tmp.Gmmep5/2.part - Ok
Mar 1 18:36:15 h980494 drwebd.real: 127.0.0.1 [14000] >/var/drweb/spool/drweb.tmp.Gmmep5/DSC06823.JPG - Ok
Mar 1 18:36:15 h980494 drwebd.real: 127.0.0.1 [14000] /var/drweb/spool/drweb.tmp.Gmmep5 - Ok
Mar 1 18:36:15 h980494 qmail-queue[25807]: scan: the message(drweb.tmp.Gmmep5) sent by [email protected] to [email protected] is passed
Mar 1 18:36:15 h980494 before-queue[25800]: handlers_stderr: PASS
Mar 1 18:36:15 h980494 before-queue[25800]: call_handlers: PASS during call '/usr/local/psa/handlers/info/20-drweb-75zCjZ/executable' handler
Mar 1 18:36:15 h980494 postfix/cleanup[25806]: B150D2D8320: message-id=<[email protected]>
Mar 1 18:36:15 h980494 postfix/qmgr[3318]: B150D2D8320: from=<[email protected]>, size=128415, nrcpt=1 (queue active)

So this solves my problem, may be the same like described before.
Before I applied the patch, i had

/var/log # grep -c 'segfault at 7338524a' messages
273

273 errors from this mail...

Thanks.

 

[kanada]

Hi Igor and rest of All,

after aplying the last patch and increase:

smtpd_timeout = 3600s
smtpd_proxy_timeout = 3600s

i see new symptoms:
- queue file write error is missing (for now, 5h after change)
- new error arrived

before-queue[17511]: Processing handlers...
postfix/spawn[17510]: warning: /usr/lib/plesk-9.0/postfix-queue: process id 17511: command time limit exceeded
before-queue[17511]: Lost connection
before-queue[17511]: Some error occured

and

before-remote[17513]: check handlers for addr: remote@user
before-remote[17513]: check handlers for addr: local@user
postfix/spawn[17512]: warning: /usr/lib/plesk-9.0/postfix-queue: process id 17513: command time limit exceeded
before-remote[17513]: Lost connection
before-remote[17513]: Some error occured

Both are on that same message.

Regards,
Alex

 

[Hultenius]

I just wrote a newsletter which happened to trigger the "queue file write error" at one set of inputs. I rewrote it a bit so it could work as a "Queue File Write Error Generator". Maybe it will help the developers if they have a hard time to reproduce the error.

Files are attached. Edit the lines in error.php marked with "<----". Send a test message to make sure it's working. Then uncomment the line '$mail->Subject .= "1";' and you will get a "queue file write error".

 

[IgorG]

Well. If I correctly understood problem with 'queue file write error' was fixed with patch and timeouts increasing. But there is new error - 'command time limit exceeded'. Is it correct?

 

[schatje]

Well. If I correctly understood problem with 'queue file write error' was fixed with patch and timeouts increasing. But there is new error - 'command time limit exceeded'. Is it correct?

On my server.. the answer is YES... but this error does not produce email to postmaster mailbox

Sc

 

[IgorG]

Guys,

Regarding 'command time limit exceeded' error you can try following:

http://archives.neohapsis.com/archives/postfix/2000-05/0423.html

Postfix limits the time for delivery to command, in order to prevent a bad configuration from filling up the machine.

By default the time limit is 1000 seconds. Something must be seriously wrong if mail delivery needs that much time. The main.cf parameter name is "command_time_limit".

Or it could be that someone is using the mail system as a backdoor to execute illegitimate commands.

So, just execute follow command:

postconf -e command_time_limit=<number>

 

[kanada]

Guys,

Regarding 'command time limit exceeded' error you can try following:

http://archives.neohapsis.com/archives/postfix/2000-05/0423.html



So, just execute follow command:

postconf -e command_time_limit=<number>

IgorG,

if i think good, the new problem arrived with new postfix-queue patch.
I can try increase the "command_time_limit' value, but to this time i've increased the timeout values.
All this operations erlarge total time needed to processing one single message, dont you think?

Regards,
Alex

 

[kanada]

Hello again,

i've increase command_time_limit to 1500s, and it didn't solve the problem:

before-queue[28880]: check handlers for addr: [email protected]
before-queue[28880]: check handlers for addr: [email protected]
before-queue[28880]: Processing handlers...
postfix/spawn[28779]: warning: /usr/lib/plesk-9.0/postfix-queue: process id 28880: command time limit exceeded

In my OS (Fedora 11) once again i see hanged up processes of postfix-queue.

PS. problem with command_time_limit was discovered in year 2k, i think it was solved long time ago in postfix. As you can see problem is in postfix-queue.

 

[IgorG]

Guys,

According to information from development team patch will be updated later today. I will post it here as soon as I receive it.
We will fix this problem together soon

 

[kanada]

Guys,

According to information from development team patch will be updated later today. I will post it here as soon as I receive it.
We will fix this problem together soon

Thank's IgorG,

im very glad that someone pickup the problem and do extensive work to fix it, finnally

Regards,
Alex

 

[MichielK]

Guys,

According to information from development team patch will be updated later today. I will post it here as soon as I receive it.
We will fix this problem together soon

Hi Igor,

thanks for the support and the effort to tackle this problem!

Could you please ask the development team why they wrote their own implementation of a proxy filtering system for postfix when they also could have used the default postfix milter system with packages like the spamass-milter software?

 

[ArtZ]

Plesk 9.3.0 with Ubuntu 8.04 64-bit

Igor,

This is huge for us, happening on all of our machines.

1: Plesk 9.3.0 on Ubuntu 8.04 64-bit. Dedicated server (not a Virtuozzo container).
2: No patches.
3: No spam protection. Greylisting is off. We use Google Postini for filtering before messages reach Postfix.
4: Messages seem to come in waves at random times of day. I have not been able to identify any cause.
5: None.

-- Art Z.

 

[kanada]

Hi,

unfortunately i have bad news for you, "Error: queue file write error
" is comming back. I think this may be connected with

command time limit exceeded

I got

queue file write error

on messages with

command time limit exceeded

In logs i found errors:

postfix/spawn[5093]: warning: /usr/lib/plesk-9.0/postfix-queue: process id 5191: command time limit exceeded

and

postfix/smtpd[8026]: warning: NOQUEUE: queue file size limit exceeded

Regards,
Alex

 

[AndreeW]

1. Version of Plesk and OS. Specify, if it is Virtuozzo container.
openSUSE 11.0 (i586)
Parallels Plesk Panel 9.3.0

3. Do you have enabled any spam protections.
greylisting, no Spam-Assasin

4. Conditions for occurrence of this error that you have noticed.
Clients with an inhouse-mailserver, e-mails with attachments > 2MB

 

[Brujo]

has some of you now also the expirience wit hundreds of old hangin postfix-queue processes like

30 1429 0.0 0.0 11528 784 ? Ss Mar02 0:00 /usr/lib64/plesk-9.0/postfix-queue 127.0.0.1 10027 before-queue
30 1430 0.0 0.0 11520 744 ? Ss Mar02 0:00 /usr/lib64/plesk-9.0/postfix-queue 127.0.0.1 10026 before-remote
30 2368 0.0 0.0 11524 784 ? Ss Mar02 0:00 /usr/lib64/plesk-9.0/postfix-queue 127.0.0.1 10027 before-queue
30 2369 0.0 0.0 11524 752 ? Ss Mar02 0:00 /usr/lib64/plesk-9.0/postfix-queue 127.0.0.1 10026 before-remote

Brujo

 

[Martijn Beulens]

451 4.3.0 Error: queue file write error

dist-deb-Ubuntu-8.04-i386
Updated via control-panel -> home -> update

Still get mails like
Out: 220 artemis.***.nl ESMTP Postfix (Ubuntu)
In: EHLO red3.iqmedia.nl
Out: 250-artemis.***.nl
Out: 250-PIPELINING
Out: 250-SIZE 102400000
Out: 250-VRFY
Out: 250-ETRN
Out: 250-STARTTLS
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 red3.iqmedia.nl
Out: 250-artemis.***.nl
Out: 250-PIPELINING
Out: 250-SIZE 102400000
Out: 250-VRFY
Out: 250-ETRN
Out: 250-AUTH PLAIN CRAM-MD5 DIGEST-MD5 LOGIN
Out: 250-ENHANCEDSTATUSCODES
Out: 250-8BITMIME
Out: 250 DSN
In: MAIL FROM:<anonymous@***.nl>
Out: 250 2.1.0 Ok
In: RCPT TO:<info@***.nl>
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

 

[gckorn]

queue file write error

Version of Plesk - 9.3
Version of OS - Linux 2.6.18
SPF Spam Protection = ON (reject when mail resolves to fail "DENY")
No other spam protection

Example of today's (3/3/2010) error messages:

Transcript of session follows.
Out: 220 server.xxxxx.com ESMTP Postfix
In: EHLO owner
Out: 250-server.xxxxx.com
Out: 250-PIPELINING
Out: 250-SIZE 10240000
Out: 250-VRFY
Out: 250-ETRN
Out: 250-AUTH CRAM-MD5 DIGEST-MD5 LOGIN PLAIN
Out: 250-ENHANCEDSTATUSCODES
Out: 250-8BITMIME
Out: 250 DSN
In: AUTH LOGIN
Out: 334 VXNlcm5hbWU6
In: amxsZkBqYXktbGl2ZXJtb3JlLWxmLm9yZw==
Out: 334 UGFzc3dvcmQ6
In: Qm9ubmll
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

Guys,

This problem Postfix "queue file write error" is really became priority for us and I would like to receive the following information from you:

1. Version of Plesk and OS. Specify, if it is Virtuozzo container.
2. What of the published Postfix patches have been installed.
3. Do you have enabled any spam protections.
4. Conditions for occurrence of this error that you have noticed.
5. Your any additional information which you considers necessary to inform about this problem.

Please answer strictly on these points, shortly and with necessary details.
On the basis of this collected information I will prepare the analytical report for developers.
Thank you for cooperation.

 

[ChristopheP]

Well. If I correctly understood problem with 'queue file write error' was fixed with patch and timeouts increasing. But there is new error - 'command time limit exceeded'. Is it correct?

Of course since your patch doesn't really address the problem but causes another layer to timeout. Increasing timeouts will only lead to the multiplication of postfix-queue process and then server crash.

The processin of an email should take from to 1 to 15 seconds in most cases, if it takes more time , increasing timeouts to 15 minutes won't solve anything as there is a more serious problem happening.

 

[IgorG]

Problem still under developer's investigation. Be patient, please.

 

[misterdee]

Guys,

This problem Postfix "queue file write error" is really became priority for us and I would like to receive the following information from you:

1. Version of Plesk and OS. Specify, if it is Virtuozzo container.
2. What of the published Postfix patches have been installed.
3. Do you have enabled any spam protections.
4. Conditions for occurrence of this error that you have noticed.
5. Your any additional information which you considers necessary to inform about this problem.

Please answer strictly on these points, shortly and with necessary details.
On the basis of this collected information I will prepare the analytical report for developers.
Thank you for cooperation.

Hi Igor,

Glad to see things are progressing with this. Here is my information:

1.
# uname -r : 2.6.18-164.11.1.el5xen (running as a Xen instance)
# cat /etc/redhat-release : Red Hat Enterprise Linux Server release 5.4 (Tikanga) (x86_64)
Plesk is version 9.3.0, license is 100 domain. No Plesk Add-on packs and no updates applied through the control panel.

2.
None of the published postfix patches have been installed, as they did not seem to work for other users.

3.
The only spam protection is spamassassin as set up by the Plesk installer. No additional spam filtering software like SpamAssassin is being used. Greylisting, Domain Keys and SPF have all been switched on and off, but this seems to make no difference.

4. It's difficult to describe when this error occurs. It used to occur with only large attachments, but it seems that mail of any size can trigger it. This suggests to me that it's a character or character-combination that is causing this. I have attached a few transcripts which I hope help a little.

5.

A few notes and observations:

I have changed smtpd_proxy_timeout = 600s (10 minutes). This seems to have taken effect, judging from the log file (attached).

Observation: generally this problem occurs on some domains and not on others. For example, it never seems to occur on our own domains, but only on some (not all) customer domains.

Observation: There are emails stuck in the queue which don't seem to relate to these problematic emails. HOWEVER, their existence DOES seem to have some influence. They also do not relate to the queued emails listed in the Plesk control panel. For example:

# df -h
(output reduced)
tmpfs 1.0G 137M 888M 14% /usr/local/psa/handlers/spool

# cd /usr/local/psa/handlers/spool
# ls -l | wc -l
71
(there are 71 items spooled)
[root@myserver spool]# ls -lh | sort -rn
total 137M
-rw------- 1 mhandlers-user popuser 8.0K Mar 3 21:21 proxy.WJTZGI
-rw------- 1 mhandlers-user popuser 8.0K Mar 3 20:11 proxy.4UHBEl
-rw------- 1 mhandlers-user popuser 8.0K Mar 3 19:46 proxy.tYzo4A
-rw------- 1 mhandlers-user popuser 8.0K Mar 3 19:21 proxy.EsnWnS
-rw------- 1 mhandlers-user popuser 8.0K Mar 3 18:56 proxy.SugCYe
-rw------- 1 mhandlers-user popuser 8.0K Mar 3 18:31 proxy.fvFvvu
-rw------- 1 mhandlers-user popuser 8.0K Mar 3 18:05 proxy.mDe3At
-rw------- 1 mhandlers-user popuser 8.0K Mar 3 17:20 proxy.EofyGC
-rw------- 1 mhandlers-user popuser 8.0K Mar 3 11:10 proxy.fCiWOE
-rw------- 1 mhandlers-user popuser 8.0K Mar 3 03:24 proxy.5Ohf34
-rw------- 1 mhandlers-user popuser 8.0K Mar 2 22:10 proxy.wbVWkt
-rw------- 1 mhandlers-user popuser 8.0K Mar 2 18:42 proxy.e3bQjd
-rw------- 1 mhandlers-user popuser 8.0K Mar 2 16:22 proxy.7FVy0y
-rw------- 1 mhandlers-user popuser 8.0K Mar 2 14:47 proxy.iEeo4I
-rw------- 1 mhandlers-user popuser 8.0K Mar 2 13:42 proxy.uqHfR1
-rw------- 1 mhandlers-user popuser 8.0K Mar 2 13:22 proxy.JAUb8f
-rw------- 1 mhandlers-user popuser 8.0K Mar 2 13:02 proxy.UPtCYd
-rw------- 1 mhandlers-user popuser 8.0K Mar 2 12:42 proxy.fpzIog
-rw------- 1 mhandlers-user popuser 8.0K Mar 2 12:22 proxy.5MbrCi
-rw------- 1 mhandlers-user popuser 8.0K Mar 2 12:02 proxy.5Trqfl
-rw------- 1 mhandlers-user popuser 8.0K Mar 2 11:41 proxy.XeuUl5
-rw------- 1 mhandlers-user popuser 8.0K Feb 23 04:53 proxy.CZF7Uk
-rw------- 1 mhandlers-user popuser 8.0K Feb 23 04:42 proxy.T8FJye
-rw------- 1 mhandlers-user popuser 8.0K Feb 22 22:36 proxy.T4nrqH
-rw------- 1 mhandlers-user popuser 8.0K Feb 22 16:31 proxy.YTZL6x
-rw------- 1 mhandlers-user popuser 8.0K Feb 22 10:26 proxy.O6NmqQ
-rw------- 1 mhandlers-user popuser 8.0K Feb 22 04:21 proxy.PeKCFU
-rw------- 1 mhandlers-user popuser 8.0K Feb 21 20:40 proxy.8QhHy5
-rw------- 1 mhandlers-user popuser 8.0K Feb 21 15:31 proxy.IVOLsu
-rw------- 1 mhandlers-user popuser 8.0K Feb 21 12:03 proxy.HldlTI
-rw------- 1 mhandlers-user popuser 8.0K Feb 21 09:43 proxy.kbw6GP
-rw------- 1 mhandlers-user popuser 8.0K Feb 21 08:08 proxy.9XdKDz
-rw------- 1 mhandlers-user popuser 8.0K Feb 21 06:58 proxy.P8emCd
-rw------- 1 mhandlers-user popuser 8.0K Feb 21 06:33 proxy.upJ8Tk
-rw------- 1 mhandlers-user popuser 8.0K Feb 21 06:08 proxy.cknUBz
-rw------- 1 mhandlers-user popuser 8.0K Feb 21 05:43 proxy.TnjyiV
-rw------- 1 mhandlers-user popuser 8.0K Feb 21 05:18 proxy.t6I7r5
-rw------- 1 mhandlers-user popuser 8.0K Feb 21 04:52 proxy.owXEcg
-rw------- 1 mhandlers-user popuser 31K Feb 22 09:36 proxy.cwaGP5
-rw------- 1 mhandlers-user popuser 2 Feb 16 09:19 proxy.n8czFW
-rw------- 1 mhandlers-user popuser 2 Feb 16 05:03 proxy.N782lP
-rw------- 1 mhandlers-user popuser 28M Mar 3 13:40 proxy.dIMj78
-rw------- 1 mhandlers-user popuser 28M Mar 3 13:09 proxy.wHE8xj
-rw------- 1 mhandlers-user popuser 28M Mar 3 12:37 proxy.grd0oL
-rw------- 1 mhandlers-user popuser 28M Mar 3 11:59 proxy.fgFSSF
-rw------- 1 mhandlers-user popuser 28K Feb 23 09:07 proxy.KtNet4
-rw------- 1 mhandlers-user popuser 23K Mar 2 10:23 proxy.EXyG3i
-rw------- 1 mhandlers-user popuser 23K Mar 1 12:55 proxy.cAnpLk
-rw------- 1 mhandlers-user popuser 20K Feb 28 14:52 proxy.fCM60X
-rw------- 1 mhandlers-user popuser 20K Feb 28 14:32 proxy.VzFFhY
-rw------- 1 mhandlers-user popuser 20K Feb 28 08:27 proxy.aq7LnE
-rw------- 1 mhandlers-user popuser 20K Feb 28 02:22 proxy.98J5n7
-rw------- 1 mhandlers-user popuser 20K Feb 27 20:16 proxy.L3AbrN
-rw------- 1 mhandlers-user popuser 20K Feb 27 14:11 proxy.0CKUcr
-rw------- 1 mhandlers-user popuser 20K Feb 27 06:30 proxy.Cp471S
-rw------- 1 mhandlers-user popuser 20K Feb 27 01:21 proxy.Nk4tXS
-rw------- 1 mhandlers-user popuser 20K Feb 26 21:53 proxy.RYbcUQ
-rw------- 1 mhandlers-user popuser 20K Feb 26 19:33 proxy.l8dPaY
-rw------- 1 mhandlers-user popuser 20K Feb 26 17:58 proxy.jwNqZ0
-rw------- 1 mhandlers-user popuser 20K Feb 26 16:53 proxy.2Vu1HM
-rw------- 1 mhandlers-user popuser 20K Feb 26 16:33 proxy.a76XR4
-rw------- 1 mhandlers-user popuser 20K Feb 26 16:13 proxy.KeiGb3
-rw------- 1 mhandlers-user popuser 20K Feb 26 15:53 proxy.WNMTxa
-rw------- 1 mhandlers-user popuser 20K Feb 26 15:33 proxy.Z39hmd
-rw------- 1 mhandlers-user popuser 20K Feb 26 15:12 proxy.GhyxkM
-rw------- 1 mhandlers-user popuser 20K Feb 26 14:52 proxy.7Zrx11
-rw------- 1 mhandlers-user popuser 1 Feb 19 23:27 proxy.sCb4yV
-rw------- 1 mhandlers-user popuser 1 Feb 16 05:03 proxy.1jsy8s
-rw------- 1 mhandlers-user popuser 13M Feb 26 09:13 proxy.1gaaCD
-rw------- 1 mhandlers-user popuser 13M Feb 15 15:03 proxy.fL16cY

There seems to be a build up of repeated messages, which are not forwarded to the mailboxes (or rejected). They just sit in this spool, gobbling up memory. However, in the Plesk control panel, there are only 4 entries:

Mar 2, 2010 11:48 PM 1 day(s) 09:44:21 20,85 KB
Mar 3, 2010 02:55 PM 18:43:31 688,30 KB
Mar 1, 2010 02:20 PM 2 day(s) 19:10:12 30,14 KB
Mar 1, 2010 09:35 AM 2 day(s) 23:56:44 497,76 KB



The only other information I can supply is from the log file (attached).