Lmtp

[kollross]

We currently have a 2 machine zimbra setup. One machine is a dedicated spam/filter and the second machine is mailstore/smtp/imap/pop. We noticed that every couple of days the spam filter would stop sending email to the to the mailstore. Also the outgoing smtp on the mailstore also stops sending outbound messages. I issued postqueue -f on the spam filter but that appears to have no effect. Here is the results from postqueue -p

7EB1D27863D 2643 Tue Nov 29 15:43:02 asdf@asdf.com
(delivery temporarily suspended: connect to mail.store.com[69.9.xxx.xxx]: read timeout)
I obviously changed a few of the the names.

Thus far the only way i've been able to correct the problem is by doing a
zmcontrol stop
zmcontrol start
On the mailstore server
Followed by a postqueue -f on the spam filter server.

Currently this email system is not processing a huge amount of email (a few hundred a day at most).

[marcmac]

Is there anything else in the logs around that time, on the store servere? Either in /var/log/zimbra.log or /opt/zimbra/log/zimbra.log?

Do you have backups running? We've fixed a bug that caused some delivery delays (and duped messages) when backups were running.

[kollross]

/var/log/zimbra.log

Nov 29 17:04:50 white postfix/smtp[26151]: C33D9433939F: to=<heather@bcsp.org>, relay=BCSPMX.bcsp.org[68.21.76.2], delay=1, status=sent (250 Requested ma
il action okay, completed)
Nov 29 17:04:50 white postfix/qmgr[7420]: C33D9433939F: removed
Nov 29 17:08:09 white postfix/anvil[26144]: statistics: max connection rate 1/60s for (smtp:70.225.179.38) at Nov 29 17:04:47
Nov 29 17:08:09 white postfix/anvil[26144]: statistics: max connection count 1 for (smtp:70.225.179.38) at Nov 29 17:04:47
Nov 29 17:08:09 white postfix/anvil[26144]: statistics: max cache size 1 at Nov 29 17:04:47
Nov 29 17:10:01 white postfix/sendmail[27072]: fatal: parameter inet_interfaces: no local interface found for 192.168.223.35
Nov 29 17:10:01 white zimbramon[27073]: 27073:info: 2005-11-29 17:10:01, QUEUE: 809 4
Nov 29 17:10:03 white zimbramon[27081]: 27081:info: 2005-11-29 17:10:01, STATUS: white.soltec.net: ldap: Running
Nov 29 17:10:03 white zimbramon[27081]: 27081:info: 2005-11-29 17:10:01, STATUS: white.soltec.net: logger: Running
Nov 29 17:10:03 white zimbramon[27081]: 27081:info: 2005-11-29 17:10:01, STATUS: white.soltec.net: mailbox: Running
Nov 29 17:10:03 white zimbramon[27081]: 27081:info: 2005-11-29 17:10:01, STATUS: white.soltec.net: mta: Running
Nov 29 17:10:03 white zimbramon[27081]: 27081:info: 2005-11-29 17:10:01, STATUS: white.soltec.net: snmp: Running
Nov 29 17:10:03 white zimbramon[27081]: 27081:info: 2005-11-29 17:10:01, STATUS: white.soltec.net: spell: Running
Nov 29 17:10:03 white zimbramon[27081]: 27081:info: 2005-11-29 17:10:01, DISK: white.soltec.net: dev: /dev/mapper/VolGroup00-LogVol00, mp: /, tot: 212283
, avail: 41%
Nov 29 17:10:03 white zimbramon[27081]: 27081:info: 2005-11-29 17:10:01, DISK: white.soltec.net: dev: /dev/sda1, mp: /boot, tot: 99, avail: 82
Nov 29 17:18:58 white zimbramon[30178]: 30178:info: Stopping services
Nov 29 17:18:58 white zimbramon[30178]: 30178:info: Stopping antispam
Nov 29 17:18:58 white zimbramon[30178]: 30178:info: Stopping antivirus
Nov 29 17:18:58 white zimbramon[30178]: 30178:info: Stopping ldap
Nov 29 17:18:58 white zimbramon[30178]: 30178:info: Stopping logger
Nov 29 17:19:00 white zimbramon[30178]: 30178:info: Stopping mailbox
Nov 29 17:19:03 white amavis[6209]: Net::Server: 2005/11/29-17:19:03 Server closing!

No backups are being run during these times (we are running M2)

[marcmac]

Are the clocks out of sync? The failure you posted was at 15:43, and the logs you posted are from 2 hours later.

Also - in the logs, it shows the servers being shut down - was that intentional?

[tron]

The clocks are not out of sync. Matt copied that part of the log because that is when he noticed this problem of non-delivery is occuring. I looked at the log for entries prior to 15:30:00 and did not see anything odd. I would be happy to post the whole log somewhere for you to download if you need it.

Matt shutdown and restarted the mailstore server in order to get the delivery going again. So that was intentional.

Originally Posted by marcmac

Are the clocks out of sync? The failure you posted was at 15:43, and the logs you posted are from 2 hours later.

Also - in the logs, it shows the servers being shut down - was that intentional?

[marcmac]

I don't need the whole log - but his original post mentioned that incoming and outgoing mail were both not functioning - and the first line of the logs posted show a successful outbound delivery...

So - if there's nothing in our logs for the time - check /var/log/messages and see if the system was complaining about anything?

[tron]

I don't see the system complaining about anything in /var/log/messages either. Here is an excerpt from 15:20. Now, one thing peculiar I did notice is that, according to /var/log/messages, amavisd is running even though I have disabled SPAM/Virus filtering on mailstore server through the admin GUI. Is that the correct behavior?

Nov 29 15:20:01 white zimbramon[4597]: 4597:info: 2005-11-29 15:20:01, QUEUE: 0
0
Nov 29 15:20:01 white crond(pam_unix)[4596]: session closed for user zimbra
Nov 29 15:20:01 white crond(pam_unix)[4591]: session closed for user root
Nov 29 15:20:02 white crond(pam_unix)[4593]: session closed for user root
Nov 29 15:20:03 white zimbramon[4603]: 4603:info: 2005-11-29 15:20:01, STATUS: w
hite.soltec.net: ldap: Running
Nov 29 15:20:03 white zimbramon[4603]: 4603:info: 2005-11-29 15:20:01, STATUS: w
hite.soltec.net: logger: Running
Nov 29 15:20:03 white zimbramon[4603]: 4603:info: 2005-11-29 15:20:01, STATUS: w
hite.soltec.net: mailbox: Running
Nov 29 15:20:03 white zimbramon[4603]: 4603:info: 2005-11-29 15:20:01, STATUS: w
hite.soltec.net: mta: Running
Nov 29 15:20:03 white zimbramon[4603]: 4603:info: 2005-11-29 15:20:01, STATUS: w
hite.soltec.net: snmp: Running
Nov 29 15:20:03 white zimbramon[4603]: 4603:info: 2005-11-29 15:20:01, STATUS: w
hite.soltec.net: spell: Running
Nov 29 15:20:03 white zimbramon[4603]: 4603:info: 2005-11-29 15:20:01, DISK: whi
te.soltec.net: dev: /dev/mapper/VolGroup00-LogVol00, mp: /, tot: 212297, avail:
41%

Originally Posted by marcmac

I don't need the whole log - but his original post mentioned that incoming and outgoing mail were both not functioning - and the first line of the logs posted show a successful outbound delivery...

So - if there's nothing in our logs for the time - check /var/log/messages and see if the system was complaining about anything?

[kollross]

Here are the logs from the exact time as as the time out email. The previous snipit of log was right before i zmcontrol stop on the mailstore server. So basically there are timeouts between the spam server and the mailstore server for a few hours. If you would like to vew the entire log (82 Meg) i've uploaded it too http://www.soltec.net/zimbra.tar.gz


Nov 29 15:43:02 black postfix/cleanup[16479]: D9824278634: message-id=<15425121@cwmzajykpmonZ-lajjs>
Nov 29 15:43:02 black postfix/qmgr[2755]: D9824278634: from=<Clinton.vwwr@endogenter.com>, size=2239, nrcpt=1 (queue active)
Nov 29 15:43:02 black amavis[13721]: (13721-04) ESMTP::10024 /opt/zimbra/amavisd/tmp/amavis-20051129T153040-13721: <Clinton.vwwr@
endogenter.com> -> <penny@gardencourts.com> Received: SIZE=2239 BODY=8BITMIME from black.soltec.net ([127.0.0.1]) by localhost (b
lack.soltec.net [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id 13721-04 for <penny@gardencourts.com>; Tue, 29 Nov 2005 15:4
3:02 -0500 (EST)
Nov 29 15:43:02 black amavis[13721]: (13721-04) body hash: a1a89965eab718fb60057dbacc9caa6a
Nov 29 15:43:02 black amavis[13721]: (13721-04) Checking: ySA6RJrxvnXU [72.11.147.31] <Clinton.vwwr@endogenter.com> -> <penny@gar
dencourts.com>
Nov 29 15:43:02 black amavis[13721]: (13721-04) p003 1 Content-Type: multipart/alternative
Nov 29 15:43:02 black amavis[13721]: (13721-04) p001 1/1 Content-Type: text/plain, size: 1 B, name:
Nov 29 15:43:02 black amavis[13721]: (13721-04) p002 1/2 Content-Type: text/html, size: 1344 B, name:
Nov 29 15:43:02 black amavis[13721]: (13721-04) Checking for banned types and filenames
Nov 29 15:43:02 black amavis[13721]: (13721-04) collect banned table[0]: penny@gardencourts.com, tables: DEFAULT=>Amavis::Lookup:
:RE=ARRAY(0x8914944)
Nov 29 15:43:02 black amavis[13721]: (13721-04) p.path penny@gardencourts.com: "P=p003,L=1,M=multipart/alternative | P=p001,L=1/1
,M=text/plain,T=dat"
Nov 29 15:43:02 black amavis[13721]: (13721-04) p.path penny@gardencourts.com: "P=p003,L=1,M=multipart/alternative | P=p002,L=1/2
,M=text/html,T=html"
Nov 29 15:43:02 black amavis[13721]: (13721-04) lookup_ldap_attr(amavisspamkilllevel) (WARN: no such attribute in LDAP entry), "p
enny@gardencourts.com" result=undef
Nov 29 15:43:02 black postfix/smtpd[16517]: connect from localhost.localdomain[127.0.0.1]
Nov 29 15:43:02 black amavis[13721]: (13721-04) AUTH not needed, user='', MTA offers 'LOGIN PLAIN'
Nov 29 15:43:02 black postfix/smtpd[16517]: 7EB1D27863D: client=localhost.localdomain[127.0.0.1]
Nov 29 15:43:02 black amavis[13721]: (13721-04) response to RCPT TO for <penny@gardencourts.com>: "250 Ok"
Nov 29 15:43:02 black postfix/cleanup[16479]: 7EB1D27863D: message-id=<15425121@cwmzajykpmonZ-lajjs>
Nov 29 15:43:02 black postfix/qmgr[2755]: 7EB1D27863D: from=<Clinton.vwwr@endogenter.com>, size=2643, nrcpt=1 (queue active)
Nov 29 15:43:02 black postfix/smtpd[16517]: disconnect from localhost.localdomain[127.0.0.1]
Nov 29 15:43:02 black amavis[13721]: (13721-04) FWD via SMTP: <Clinton.vwwr@endogenter.com> -> <penny@gardencourts.com>, 250 2.6.
0 Ok, id=13721-04, from MTA([127.0.0.1]:10025): 250 Ok: queued as 7EB1D27863D
Nov 29 15:43:02 black postfix/qmgr[2755]: 7EB1D27863D: to=<penny@gardencourts.com>, relay=none, delay=0, status=deferred (deliver
y temporarily suspended: conversation with white.soltec.net[69.9.180.194] timed out while sending end of data -- message may be s
ent more than once)
Nov 29 15:43:02 black amavis[13721]: (13721-04) lookup_ldap_attr(amavisspamtag2level) (WARN: no such attribute in LDAP entry), "p
enny@gardencourts.com" result=undef
Nov 29 15:43:02 black amavis[13721]: (13721-04) Passed CLEAN, [72.11.147.31] [72.11.147.31] <Clinton.vwwr@endogenter.com> -> <pen
ny@gardencourts.com>, Message-ID: <15425121@cwmzajykpmonZ-lajjs>, mail_id: ySA6RJrxvnXU, Hits: -, 356 ms
Nov 29 15:43:02 black amavis[13721]: (13721-04) TIMING [total 384 ms] - SMTP EHLO: 2 (0%)0, SMTP pre-MAIL: 1 (0%)1, lookup_ldap:
13 (3%)4, SMTP pre-DATA-flush: 1 (0%)4, SMTP DATA: 27 (7%)11, body_hash: 1 (0%)11, gen_mail_id: 0 (0%)11, mime_decode: 9 (2%)14,
get-file-type2: 7 (2%)16, parts_decode: 0 (0%)16, update_cache: 3 (1%)16, deal_with_mail_size: 0 (0%)16, fwd-connect: 3 (1%)17, f
wd-mail-from: 3 (1%)18, fwd-rcpt-to: 45 (12%)30, write-header: 1 (0%)30, fwd-data: 0 (0%)30, fwd-data-end: 91 (24%)54, fwd-rundow
n: 85 (22%)76, main_log_entry: 91 (24%)100, update_snmp: 1 (0%)100, unlink-2-files: 1 (0%)100, rundown: 0 (0%)100
Nov 29 15:43:02 black postfix/smtp[16515]: D9824278634: to=<penny@gardencourts.com>, relay=127.0.0.1[127.0.0.1], delay=1, status=
sent (250 2.6.0 Ok, id=13721-04, from MTA([127.0.0.1]:10025): 250 Ok: queued as 7EB1D27863D)


Here actually is the entry from the original time out email that i posted

[marcmac]

That is the correct behaviour - postfix tends to remember where things in the queue are supposed to be sent - so if you were running amavis, and stopped it, even if you took it out of the content_filter line, you could (potentially) trap msgs in your queue forever.

[marcmac]

These logs are from the MTA, right?

Is there anything interesting about the network, or are the boxes on the same LAN?


Is this an accurate description of what you're seeing:

Periodically, mail from the mta->mailstore will stop delivering, with the "delivery temporarily suspended" message. At the same time, mail from the mailstore->world will start to timeout?

If that is the case, then I don't think it's just the mailstore, since that wouldn't explain why the MTA instance on the mailstore is timing out. Is it pointing to a relay_host, or is it delivering mail directly to the world? I'm curious to see if the problem could be DNS related.