Mail not delivering suddenly.. (log included)

[Geoff Winans]

Okay, so here's the annoying issue; both qmail and postfix are displaying this behavior.

I have one email address @geeklan.com

qMail has the following in the log files:

Aug 27 11:15:06 GeekLAN relaylock: /var/qmail/bin/relaylock: mail from 209.85.212.179:53157 (mail-vw0-f179.google.com)
Aug 27 11:15:06 GeekLAN qmail-queue-handlers[4625]: Handlers Filter before-queue for qmail started ...
Aug 27 11:15:06 GeekLAN qmail-queue-handlers[4625]: from=*****@gmail.com
Aug 27 11:15:06 GeekLAN qmail-queue-handlers[4625]: to=*****@geeklan.com
Aug 27 11:15:06 GeekLAN qmail-queue-handlers[4625]: hook_dir = '/usr/local/psa/handlers/before-queue'
Aug 27 11:15:06 GeekLAN qmail-queue-handlers[4625]: recipient[3] = '*****@geeklan.com'
Aug 27 11:15:06 GeekLAN qmail-queue-handlers[4625]: handlers dir = '/usr/local/psa/handlers/before-queue/recipient/*****@geeklan.com'
Aug 27 11:15:06 GeekLAN qmail-queue-handlers[4625]: starter: submitter[4626] exited normally
Aug 27 11:15:06 GeekLAN qmail: 1251396906.607598 new msg 4718644
Aug 27 11:15:06 GeekLAN qmail: 1251396906.607648 info msg 4718644: bytes 1708 from <*****@gmail.com> qp 4626 uid 2020
Aug 27 11:15:06 GeekLAN qmail: 1251396906.613327 starting delivery 9: msg 4718644 to local *****@geeklan.com
Aug 27 11:15:06 GeekLAN qmail: 1251396906.613370 status: local 1/10 remote 0/20
Aug 27 11:15:06 GeekLAN qmail-local-handlers[4627]: Handlers Filter before-local for qmail started ...
Aug 27 11:15:06 GeekLAN qmail-local-handlers[4627]: cannot create temporary file - (13) Permission denied
Aug 27 11:15:06 GeekLAN qmail-local-handlers[4627]: cannot read message from stdin
Aug 27 11:15:06 GeekLAN qmail: 1251396906.616487 delivery 9: failure:
Aug 27 11:15:06 GeekLAN qmail: 1251396906.616528 status: local 0/10 remote 0/20
Aug 27 11:15:06 GeekLAN qmail-queue-handlers[4629]: Handlers Filter before-queue for qmail started ...
Aug 27 11:15:06 GeekLAN qmail-queue-handlers[4629]: from=
Aug 27 11:15:06 GeekLAN qmail-queue-handlers[4629]: to=*****@gmail.com
Aug 27 11:15:06 GeekLAN qmail-queue-handlers[4629]: hook_dir = '/usr/local/psa/handlers/before-queue'
Aug 27 11:15:06 GeekLAN qmail-queue-handlers[4629]: recipient[3] = '*****@gmail.com'
Aug 27 11:15:06 GeekLAN qmail-queue-handlers[4629]: handlers dir = '/usr/local/psa/handlers/before-queue/recipient/*****@gmail.com'
Aug 27 11:15:06 GeekLAN qmail-queue-handlers[4629]: starter: submitter[4630] exited normally
Aug 27 11:15:06 GeekLAN qmail: 1251396906.625173 bounce msg 4718644 qp 4629
Aug 27 11:15:06 GeekLAN qmail: 1251396906.625262 end msg 4718644
Aug 27 11:15:06 GeekLAN qmail: 1251396906.625768 new msg 4719109
Aug 27 11:15:06 GeekLAN qmail: 1251396906.625854 info msg 4719109: bytes 2190 from <> qp 4630 uid 2522
Aug 27 11:15:06 GeekLAN qmail: 1251396906.629426 starting delivery 10: msg 4719109 to remote *****@gmail.com
Aug 27 11:15:06 GeekLAN qmail: 1251396906.629465 status: local 0/10 remote 1/20
Aug 27 11:15:06 GeekLAN qmail-remote-handlers[4631]: Handlers Filter before-remote for qmail started ...
Aug 27 11:15:06 GeekLAN qmail-remote-handlers[4631]: from=
Aug 27 11:15:06 GeekLAN qmail-remote-handlers[4631]: to=*****@gmail.com
Aug 27 11:15:06 GeekLAN qmail-remote-handlers[4631]: hook_dir = '/usr/local/psa/handlers/before-remote'
Aug 27 11:15:06 GeekLAN qmail-remote-handlers[4631]: recipient[3] = '*****@gmail.com'
Aug 27 11:15:06 GeekLAN qmail-remote-handlers[4631]: handlers dir = '/usr/local/psa/handlers/before-remote/recipient/*****@gmail.com'
Aug 27 11:15:09 GeekLAN qmail: 1251396909.467656 delivery 10: success: 209.85.217.45_accepted_message./Remote_host_said:_250_2.0.0_OK_1251396908_25si1202529gxk.23/
Aug 27 11:15:09 GeekLAN qmail: 1251396909.467723 status: local 0/10 remote 0/20
Aug 27 11:15:09 GeekLAN qmail: 1251396909.467752 end msg 4719109


I'm guessing it has something to do with these lines:

Aug 27 11:15:06 GeekLAN qmail-local-handlers[4627]: Handlers Filter before-local for qmail started ...
Aug 27 11:15:06 GeekLAN qmail-local-handlers[4627]: cannot create temporary file - (13) Permission denied
Aug 27 11:15:06 GeekLAN qmail-local-handlers[4627]: cannot read message from stdin
Aug 27 11:15:06 GeekLAN qmail: 1251396906.616487 delivery 9: failure:


FACTS:
- No server configuration has been changed that deals with mail in any way
- I am an experienced UNIX Admin (~10 years behind me) and this issue has completely and utterly stumped me. I'd strace the pid, but it's impossible to catch it fast enough. That would tell me everything I need to know.
- This issue has, quite literally, popped up on it's own with 0 interaction. Mail was working two days ago and then stopped.
- I am not using any of the AV Applications.

I'll be damned if I can figure out what path it can't write to due to permissions. I'm at a loss and losing a lot of valuable clientele. My host has told me to do a fresh install of the OS/CP on my server, which is so far beyond unacceptable I had to tear the representative a new one.

I need help, please.

 

[Geoff Winans]

Addendun;

This has become even more annoying.

It's only doing it for one domain (geeklan.com). If I delete and then recreate the domain in PLESK it fixes it temporarily, and then it goes back to the same problem. How the hell do bugs like this creep in to applications? This has got to be the weirdest one I've ever seen.

Deleting the mail account itself and recreating it does nothing.

Fixed after removal/recreation of the entire domain and then it does it again? Ugh.

 

[Matt356]

Possible corrupted queue?

Hi

I'm not as experienced as you, so don't know if this will help, but after the last upgrade I had to basically delete and rebuild the whole qmail queue system (including those already scanned for viruses, etc.), not just the queue folder itself. That was the only way to get rid of error messages regarding inability to deliver.

It seems the upgrade changed enough in the way qmail works (or spamassassin, I really don't know) that the messages which had passed the scanning were no longer in the format that the next part of the delivery system expected and so could not be parsed for delivery.

Matt

 

[Geoff Winans]

Anyone?

I still have no solution to this and it's getting REALLY irritating removing and re-adding the domain - considering it's the primary domain on the server with about a dozen accounts.

 

[Geoff Winans]

Anyone?

Parallels? How about some support for the product you produce and the bug since 9.2.2 with mail for my domain not delivering even after recreating it?

 

[shall]

I fixed this with the following series of commands. Ignore issues during "remove" (you may not have them all installed).

yum remove qmail-scanner
yum remove qmhandle
yum remove psa-spamassassin
yum remove drweb-base
yum update
service psa stopall
service psa start

Next go into Plesk and reinstall spamassassin and drweb, if you so desire.

THEN go into each domain and reactivate spamassassin and drweb, since it's been removed and disabled for every account (including settings).

 

[DeaneM]

That fixed receiving messages, but I still can't send out

After performing the yum steps, and rebooting my server (your service psa commands don't work for me), I can now receive emails at my server, but sending out still results in the permission errors:



Jun 1 15:17:55 mydomain /var/qmail/bin/relaylock[26163]: /var/qmail/bin/relaylock: mail from 1.2.3.4:53533 (my.dsl.address.net)
Jun 1 15:17:56 mydomain cmd5checkpw: SMTP connect from my.dsl.address.net [1.2.3.4]
Jun 1 15:17:56 mydomain cmd5checkpw: SMTP user [email protected]: logged in from my.dsl.address.net [1.2.3.4]
Jun 1 15:17:56 mydomain qmail-queue-handlers[26166]: Handlers Filter before-queue for qmail started ...
Jun 1 15:17:56 mydomain qmail-queue-handlers[26166]: [email protected]
Jun 1 15:17:56 mydomain qmail-queue-handlers[26166]: [email protected]
Jun 1 15:17:56 mydomain qmail-queue-handlers[26166]: handlers_stderr: SKIP
Jun 1 15:17:56 mydomain qmail-queue-handlers[26166]: SKIP during call 'check-quota' handler
Jun 1 15:17:56 mydomain qmail-queue-handlers[26166]: starter: submitter[26168] exited normally
Jun 1 15:17:56 mydomain qmail: 1338589076.594074 new msg 112152730
Jun 1 15:17:56 mydomain qmail: 1338589076.594108 info msg 112152730: bytes 662 from <[email protected]> qp 26168 uid 2020
Jun 1 15:17:56 mydomain qmail: 1338589076.596951 starting delivery 3: msg 112152730 to remote [email protected]
Jun 1 15:17:56 mydomain qmail: 1338589076.596978 status: local 0/10 remote 1/20
Jun 1 15:17:56 mydomain qmail-remote-handlers[26169]: Handlers Filter before-remote for qmail started ...
Jun 1 15:17:56 mydomain qmail-remote-handlers[26169]: cannot create temporary file - (13) Permission denied
Jun 1 15:17:56 mydomain qmail-remote-handlers[26169]: cannot read message from stdin
Jun 1 15:17:56 mydomain qmail: 1338589076.599152 delivery 3: failure: handlers_permanentfail/
Jun 1 15:17:56 mydomain qmail: 1338589076.599378 status: local 0/10 remote 0/20
Jun 1 15:17:56 mydomain qmail-queue-handlers[26170]: Handlers Filter before-queue for qmail started ...
Jun 1 15:17:56 mydomain qmail-queue-handlers[26170]: cannot create temporary file - (13) Permission denied
Jun 1 15:17:56 mydomain qmail-queue-handlers[26170]: cannot read message from stdin
Jun 1 15:17:56 mydomain qmail: 1338589076.601871 warning: trouble injecting bounce message, will try later

 

[shall]

Have you run an fsck on the server? It's possible that the file system or drive is damaged and the OS is preventing write's to protect the data.

Another thing to check would be to run a mail check. This is the command you need for that:
/usr/local/psa/admin/sbin/mchk --with-spam

That will repair the filters and account-related settings, but might not actually fix the problem either. Depending on how much mail you have stored this can take anywhere from a few minutes to many hours - during which time mail will NOT work.