We have a filtering service so all traffic comes from them through the MTA connection. On a normal business day it has started shutting down and will not receive email. Emails from domain user to domain user work fine, and sending email works fine. Sometimes doing a zmcontrol restart fixes the issue for a while, sometimes I have to reboot the entire machine.
Code: Select all
zimbra@MAIL:/$ zmcontrol -v
Release 8.8.9.GA.2055.UBUNTU14.64 UBUNTU14_64 FOSS edition, Patch 8.8.9_P8.
Code: Select all
Dec 4 10:27:03 MAIL zmmailboxdmgr[20544]: no manager process is running
Dec 4 10:33:55 MAIL zmmailboxdmgr[3061]: no manager process is running
Dec 4 11:14:03 MAIL zmmailboxdmgr[1413]: no manager process is running
Dec 4 11:14:03 MAIL zmmailboxdmgr[1455]: no manager process is running
Dec 4 11:14:04 MAIL zmmailboxdmgr[1531]: no manager process is running
Dec 4 11:14:04 MAIL zmmailboxdmgr[1548]: no manager process is running
Dec 4 11:14:04 MAIL zmmailboxdmgr[1565]: no manager process is running
Dec 4 11:14:52 MAIL zmmailboxdmgr[3315]: no manager process is running
From zmmailboxd.out, its filled with these
Code: Select all
2018-12-04 00:00:01.995:INFO:oejm.ThreadMonitor:Thread-37: Thread 'ImapSSLServer-177'[RUNNABLE,id:8217,cpu:96.81%] SPINNING
2018-12-04 00:00:01.995:WARN:oejm.ThreadMonitor:Thread-37:
org.eclipse.jetty.monitor.thread.ThreadMonitorException: Thread 'ImapSSLServer-177'[RUNNABLE,id:8217,cpu:96.81%] STACK TRACE
at java.lang.String.toUpperCase(String.java:2765)
at java.lang.String.toUpperCase(String.java:2833)
at com.zimbra.cs.imap.ImapHandler.getFolderAttrs(ImapHandler.java:2428)
at com.zimbra.cs.imap.ImapHandler.doLIST(ImapHandler.java:2233)
at com.zimbra.cs.imap.ImapHandler.executeRequest(ImapHandler.java:733)
at com.zimbra.cs.imap.NioImapHandler.processRequest(NioImapHandler.java:123)
at com.zimbra.cs.imap.NioImapHandler.messageReceived(NioImapHandler.java:63)
at com.zimbra.cs.server.NioHandlerDispatcher.messageReceived(NioHandlerDispatcher.java:95)
at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:716)
at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:434)
at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:46)
at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:796)
at org.apache.mina.filter.codec.ProtocolCodecFilter$ProtocolDecoderOutputImpl.flush(ProtocolCodecFilter.java:427)
at org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:245)
at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:434)
at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:46)
at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:796)
at com.zimbra.cs.server.NioLoggingFilter.messageReceived(NioLoggingFilter.java:68)
at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:434)
at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:46)
at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:796)
at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:75)
at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63)
at org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.runTask(OrderedThreadPoolExecutor.java:780)
at org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.runTasks(OrderedThreadPoolExecutor.java:772)
at org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.run(OrderedThreadPoolExecutor.java:714)
at java.lang.Thread.run(Thread.java:748)
Between 10:08 and 10:38 today there is zero traffic from my filtering service but all other traffic looks normal. When they try and telnet in they get a "refused" error but I cannot find one in the logs. This is strange because if I remove them from the MTA I get a normal "denied" entry in the logs like this.
Code: Select all
root@MAIL:/var/log# grep denied zimbra.log
Oct 11 06:54:14 MAIL postfix/smtpd[22770]: NOQUEUE: reject: RCPT from mail.filter.com[xxx.xxx.xxx.xxx]: 554 5.7.1 >: Relay access denied; from=> to=> proto=ESMTP helo=<mail.filter.com>
I have nothing like that in today's log. The last of the "normal" traffic ends with a "Recipient address rejected" which is expected, its an employee that no longer works here. I filtered the log by the name of the filtering service and the only strange thing I can see right before it started rejecting traffic is this part about "timeout after END-OF-MESSAGE". This is the only place in the entire log that this shows up, but I did not receive anything from the filtering service after this. In the full log you can still see traffic going between local accounts and going out to other domains, but nothing coming in. And you can see when I performed a reboot and it goes through the normal process, but nothing from my filtering service at all between 10:08 and the reboot. Then it failed again at 10:48 with the same messages in the log and forced another boot which I did at 11:14. Then it was fine the rest of the day.
Code: Select all
Dec 4 10:03:32 MAIL postfix/smtpd[7841]: NOQUEUE: reject: RCPT from mail.filter.com[xxx.xxx.xxx.xxx]: 550 5.1.1 <old.employee@domain.com>: Recipient address rejected: domain.com; from=<winter.resistant.vest@crodders.com> to=<old.employee@domain.com> proto=ESMTP helo=<mail.filter.com>
Dec 4 10:03:32 MAIL postfix/smtpd[7841]: NOQUEUE: reject: RCPT from mail.filter.com[xxx.xxx.xxx.xxx]: 550 5.1.1 <old.employee@domain.com>: Recipient address rejected: domain.com; from=<winter.resistant.vest@crodders.com> to=<old.employee@domain.com> proto=ESMTP helo=<mail.filter.com>
Dec 4 10:03:32 MAIL postfix/smtpd[7827]: 0914EC9E006A: client=mail.filter.com[xxx.xxx.xxx.xxx]
Dec 4 10:03:32 MAIL postfix/smtpd[7861]: 09437C9E006B: client=mail.filter.com[xxx.xxx.xxx.xxx]
Dec 4 10:08:31 MAIL postfix/smtpd[7821]: timeout after END-OF-MESSAGE from mail.filter.com[xxx.xxx.xxx.xxx]
Dec 4 10:08:31 MAIL postfix/smtpd[7821]: disconnect from mail.filter.com[xxx.xxx.xxx.xxx] ehlo=1 mail=2 rcpt=1/2 data=1/2 rset=2 commands=7/9
Dec 4 10:08:31 MAIL postfix/smtpd[7818]: timeout after END-OF-MESSAGE from mail.filter.com[xxx.xxx.xxx.xxx]
Dec 4 10:08:31 MAIL postfix/smtpd[7818]: disconnect from mail.filter.com[xxx.xxx.xxx.xxx] ehlo=1 mail=1 rcpt=1 data=1 commands=4
Dec 4 10:08:32 MAIL postfix/smtpd[7843]: timeout after END-OF-MESSAGE from mail.filter.com[xxx.xxx.xxx.xxx]
Dec 4 10:08:32 MAIL postfix/smtpd[7843]: disconnect from mail.filter.com[xxx.xxx.xxx.xxx] ehlo=1 mail=1 rcpt=1 data=1 commands=4
Dec 4 10:08:32 MAIL postfix/smtpd[7847]: timeout after END-OF-MESSAGE from mail.filter.com[xxx.xxx.xxx.xxx]
Dec 4 10:08:32 MAIL postfix/smtpd[7847]: disconnect from mail.filter.com[xxx.xxx.xxx.xxx] ehlo=1 mail=1 rcpt=1 data=1 commands=4
Dec 4 10:08:32 MAIL postfix/smtpd[7829]: timeout after END-OF-MESSAGE from mail.filter.com[xxx.xxx.xxx.xxx]
Dec 4 10:08:32 MAIL postfix/smtpd[7829]: disconnect from mail.filter.com[xxx.xxx.xxx.xxx] ehlo=1 mail=1 rcpt=1 data=1 commands=4
Dec 4 10:08:32 MAIL postfix/smtpd[7820]: timeout after END-OF-MESSAGE from mail.filter.com[xxx.xxx.xxx.xxx]
Dec 4 10:08:32 MAIL postfix/smtpd[7820]: disconnect from mail.filter.com[xxx.xxx.xxx.xxx] ehlo=1 mail=1 rcpt=1 data=1 commands=4
Dec 4 10:08:32 MAIL postfix/smtpd[5647]: timeout after END-OF-MESSAGE from mail.filter.com[xxx.xxx.xxx.xxx]
Dec 4 10:08:32 MAIL postfix/smtpd[5647]: disconnect from mail.filter.com[xxx.xxx.xxx.xxx] ehlo=1 mail=2 rcpt=2 data=2 rset=1 commands=8
Dec 4 10:08:32 MAIL postfix/smtpd[7832]: timeout after RSET from mail.filter.com[xxx.xxx.xxx.xxx]
Dec 4 10:08:32 MAIL postfix/smtpd[7832]: disconnect from mail.filter.com[xxx.xxx.xxx.xxx] ehlo=1 mail=2 rcpt=1/2 data=1/2 rset=2 commands=7/9
Dec 4 10:08:32 MAIL postfix/smtpd[7841]: timeout after RSET from mail.filter.com[xxx.xxx.xxx.xxx]
Dec 4 10:08:32 MAIL postfix/smtpd[7841]: disconnect from mail.filter.com[xxx.xxx.xxx.xxx] ehlo=1 mail=2 rcpt=1/2 data=1/2 rset=2 commands=7/9
Dec 4 10:08:32 MAIL postfix/smtpd[7861]: timeout after END-OF-MESSAGE from mail.filter.com[xxx.xxx.xxx.xxx]
Dec 4 10:08:32 MAIL postfix/smtpd[7819]: timeout after END-OF-MESSAGE from mail.filter.com[xxx.xxx.xxx.xxx]
Dec 4 10:08:32 MAIL postfix/smtpd[7861]: disconnect from mail.filter.com[xxx.xxx.xxx.xxx] ehlo=1 mail=1 rcpt=1 data=1 commands=4
Dec 4 10:08:32 MAIL postfix/smtpd[7819]: disconnect from mail.filter.com[xxx.xxx.xxx.xxx] ehlo=1 mail=4 rcpt=2/4 data=2/4 rset=5 commands=14/18
Dec 4 10:08:32 MAIL postfix/smtpd[7830]: timeout after END-OF-MESSAGE from mail.filter.com[xxx.xxx.xxx.xxx]
Dec 4 10:08:32 MAIL postfix/smtpd[7830]: disconnect from mail.filter.com[xxx.xxx.xxx.xxx] ehlo=1 mail=2 rcpt=2 data=2 rset=1 commands=8
Dec 4 10:08:32 MAIL postfix/smtpd[7825]: timeout after END-OF-MESSAGE from mail.filter.com[xxx.xxx.xxx.xxx]
Dec 4 10:08:32 MAIL postfix/smtpd[7825]: disconnect from mail.filter.com[xxx.xxx.xxx.xxx] ehlo=1 mail=2 rcpt=2 data=2 rset=1 commands=8
Dec 4 10:08:32 MAIL postfix/smtpd[7827]: timeout after END-OF-MESSAGE from mail.filter.com[xxx.xxx.xxx.xxx]
Dec 4 10:08:32 MAIL postfix/smtpd[7827]: disconnect from mail.filter.com[xxx.xxx.xxx.xxx] ehlo=1 mail=2 rcpt=2 data=2 rset=1 commands=8
Dec 4 10:38:31 MAIL postfix/smtpd[5885]: connect from mail.filter.com[xxx.xxx.xxx.xxx]
Dec 4 10:38:31 MAIL postfix/smtpd[7311]: connect from mail.filter.com[xxx.xxx.xxx.xxx]
Dec 4 10:38:31 MAIL postfix/smtpd[7310]: connect from mail.filter.com[xxx.xxx.xxx.xxx]
Dec 4 10:38:31 MAIL postfix/smtpd[7312]: connect from mail.filter.com[xxx.xxx.xxx.xxx]
Dec 4 10:38:31 MAIL postfix/smtpd[7313]: connect from mail.filter.com[xxx.xxx.xxx.xxx]
Dec 4 10:38:31 MAIL postfix/smtpd[5885]: NOQUEUE: filter: RCPT from mail.filter.com[xxx.xxx.xxx.xxx]: <return_0_23645497894_23622487125@texasdebrazil.fbmta.com>: Sender address triggers FILTER smtp-amavis:[127.0.0.1]:10026; from=<return_0_23645497894_23622487125@texasdebrazil.fbmta.com> to=<current.employee@domain.com> proto=ESMTP helo=<mail.filter.com>