MTA shuts down, mail within domain still works.

Discuss your pilot or production implementation with other Zimbra admins or our engineers.
User avatar
DualBoot
Elite member
Elite member
Posts: 1043
Joined: Mon Apr 18, 2016 8:18 pm
Location: Earth
ZCS/ZD Version: ZCS FLOSS - 8.7.11 Mutli servers

Re: MTA shuts down, mail within domain still works.

Postby DualBoot » Fri Jan 11, 2019 9:08 am

Hello,

I remember an old bug but with 8.6 and was fix since :
an IMAP connection from Apple Mail with Ipad or Iphone was leading to crash the server. In addition it was related to Imap Search folder
with some complex search filters.

Regards,


GrnEyedDvl
Posts: 11
Joined: Wed Dec 05, 2018 7:34 am

Re: MTA shuts down, mail within domain still works.

Postby GrnEyedDvl » Mon Jan 14, 2019 3:02 am

DualBoot wrote:Hello,

I remember an old bug but with 8.6 and was fix since :
an IMAP connection from Apple Mail with Ipad or Iphone was leading to crash the server. In addition it was related to Imap Search folder
with some complex search filters.

Regards,


Hello DualBoot,

This started on 8.6 or 8.7, but I have upgraded since then. Not sure where to go now. Any idea what version of iPhone that was?



Closing the IMAP ports obviously removed the IMAP SSL errors, but its not a real solution. People need to be able to use their phones. Its been up all weekend and I only have one error in zmmailboxd.out today. One error doesnt really bother me, and it looks like a 400 request gone wrong.

Code: Select all

2019-01-13 04:15:36.349:WARN:oejh.HttpParser:qtp66233253-13431: bad HTTP parsed: 400 No URI for HttpChannelOverHttp@44a1114b{r=0,c=false,a=IDLE,uri=null}
2019-01-13 13:20:42.683:WARN:oejh.HttpParser:qtp66233253-15800: bad HTTP parsed: 400 No Host for HttpChannelOverHttp@3f8f0786{r=0,c=false,a=IDLE,uri=null}
2019-01-13 16:18:37.537:WARN:oejs.ServletHandler:qtp66233253-16715:https:https://mail.arapahoefire.com/:
org.apache.jasper.JasperException: org.apache.jasper.JasperException: org.eclipse.jetty.io.RuntimeIOException: org.eclipse.jetty.io.EofException
   at org.apache.jasper.servlet.JspServletWrapper.handleJspException(JspServletWrapper.java:555)
   at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:461)
   at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:396)
   at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:340)
   at org.eclipse.jetty.jsp.JettyJspServlet.service(JettyJspServlet.java:107)
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
   at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:821)
   at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:583)
   at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
   at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:566)
   at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226)
   at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1158)
   at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:511)
   at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
   at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1090)
   at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
   at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:199)
   at org.eclipse.jetty.server.Dispatcher.forward(Dispatcher.java:74)
   at org.eclipse.jetty.servlet.DefaultServlet.sendWelcome(DefaultServlet.java:593)
   at org.eclipse.jetty.servlet.DefaultServlet.doGet(DefaultServlet.java:479)
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
   at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
   at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:821)
   at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1685)
   at com.zimbra.cs.servlet.RequestStringFilter.doFilter(RequestStringFilter.java:54)
   at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1668)
   at com.zimbra.webClient.filters.ForwardFilter.doFilter(ForwardFilter.java:88)
   at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1668)
   at com.zimbra.cs.servlet.SetHeaderFilter.doFilter(SetHeaderFilter.java:59)
   at com.zimbra.webClient.filters.SetHeaderFilter.doFilter(SetHeaderFilter.java:248)
   at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1668)
   at com.zimbra.cs.servlet.ContextPathBasedThreadPoolBalancerFilter.doFilter(ContextPathBasedThreadPoolBalancerFilter.java:107)
   at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1668)
   at com.zimbra.cs.servlet.ZimbraQoSFilter.doFilter(ZimbraQoSFilter.java:125)
   at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1668)
   at org.eclipse.jetty.servlets.DoSFilter.doFilterChain(DoSFilter.java:473)
   at org.eclipse.jetty.servlets.DoSFilter.doFilter(DoSFilter.java:318)
   at org.eclipse.jetty.servlets.DoSFilter.doFilter(DoSFilter.java:288)
   at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1668)
   at com.zimbra.webClient.filters.CharEncodingFilter.doFilter(CharEncodingFilter.java:37)
   at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1668)
   at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:581)
   at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143)
   at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:524)
   at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:226)
   at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1158)
   at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:511)
   at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
   at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1090)
   at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
   at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:213)
   at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:109)
   at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:119)
   at org.eclipse.jetty.rewrite.handler.RewriteHandler.handle(RewriteHandler.java:318)
   at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:437)
   at org.eclipse.jetty.server.handler.DebugHandler.handle(DebugHandler.java:84)
   at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:119)
   at org.eclipse.jetty.server.Server.handle(Server.java:517)
   at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:306)
   at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:242)
   at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:261)
   at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
   at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:192)
   at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:261)
   at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:95)
   at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:75)
   at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceAndRun(ExecuteProduceConsume.java:213)
   at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:147)
   at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:654)
   at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:572)
   at java.lang.Thread.run(Thread.java:748)
GrnEyedDvl
Posts: 11
Joined: Wed Dec 05, 2018 7:34 am

Re: MTA shuts down, mail within domain still works.

Postby GrnEyedDvl » Tue Jan 15, 2019 1:54 am

Well disabling IMAP had no impact other than shortening my log files and making people mad. This is really frustrating as now I have practically 0 info to go on. I did have a few 400 errors (maybe 10) as posted above, and literally nothing else that reports as "error" or "denied" or "rejected" or any other keyword I can think of to grep logs with. The only real clue I have is that there is a TIMEOUT message related to the filtering service we use, and right after that message no more emails come in.

Filtering the log files by searching for the filtering service machine name gives me this:

Code: Select all

Jan 14 09:41:01 MAIL postfix/smtpd[9186]: NOQUEUE: filter: RCPT from ida.axint.net[50.21.186.48]: <name@domain.com>: Sender address triggers FILTER smtp-amavis:[127.0.0.1]:10026; from=<name@domain.com> to=<name@domain.com> proto=ESMTP helo=<ida.axint.net>
Jan 14 09:41:01 MAIL postfix/smtpd[9186]: 31D7FC9E0067: client=ida.axint.net[50.21.186.48]

Internal traffic here is fine, but nothing from the filtering service

Jan 14 09:46:01 MAIL postfix/smtpd[9134]: timeout after END-OF-MESSAGE from ida.axint.net[50.21.186.48]
Jan 14 09:46:01 MAIL postfix/smtpd[9134]: disconnect from ida.axint.net[50.21.186.48] ehlo=1 mail=1 rcpt=1 data=1 commands=4
Jan 14 09:46:01 MAIL postfix/smtpd[9174]: timeout after RSET from ida.axint.net[50.21.186.48]
Jan 14 09:46:01 MAIL postfix/smtpd[9174]: disconnect from ida.axint.net[50.21.186.48] ehlo=1 mail=1 rcpt=0/1 data=0/1 rset=1 commands=3/5
Jan 14 09:46:01 MAIL postfix/smtpd[9184]: timeout after RSET from ida.axint.net[50.21.186.48]
Jan 14 09:46:01 MAIL postfix/smtpd[9184]: disconnect from ida.axint.net[50.21.186.48] ehlo=1 mail=1 rcpt=0/1 data=0/1 rset=1 commands=3/5
Jan 14 09:46:01 MAIL postfix/smtpd[9132]: timeout after END-OF-MESSAGE from ida.axint.net[50.21.186.48]
Jan 14 09:46:01 MAIL postfix/smtpd[9132]: disconnect from ida.axint.net[50.21.186.48] ehlo=1 mail=1 rcpt=1 data=1 commands=4
Jan 14 09:46:01 MAIL postfix/smtpd[9131]: timeout after END-OF-MESSAGE from ida.axint.net[50.21.186.48]
Jan 14 09:46:01 MAIL postfix/smtpd[9131]: disconnect from ida.axint.net[50.21.186.48] ehlo=1 mail=2 rcpt=1/2 data=1/2 rset=2 commands=7/9
Jan 14 09:46:01 MAIL postfix/smtpd[9150]: timeout after END-OF-MESSAGE from ida.axint.net[50.21.186.48]
Jan 14 09:46:01 MAIL postfix/smtpd[9150]: disconnect from ida.axint.net[50.21.186.48] ehlo=1 mail=1 rcpt=1 data=1 commands=4
Jan 14 09:46:01 MAIL postfix/smtpd[9143]: timeout after END-OF-MESSAGE from ida.axint.net[50.21.186.48]
Jan 14 09:46:01 MAIL postfix/smtpd[9149]: timeout after END-OF-MESSAGE from ida.axint.net[50.21.186.48]
Jan 14 09:46:01 MAIL postfix/smtpd[9143]: disconnect from ida.axint.net[50.21.186.48] ehlo=1 mail=1 rcpt=1 data=1 commands=4
Jan 14 09:46:01 MAIL postfix/smtpd[9149]: disconnect from ida.axint.net[50.21.186.48] ehlo=1 mail=1 rcpt=1 data=1 commands=4
Jan 14 09:46:01 MAIL postfix/smtpd[9168]: timeout after END-OF-MESSAGE from ida.axint.net[50.21.186.48]
Jan 14 09:46:01 MAIL postfix/smtpd[9168]: disconnect from ida.axint.net[50.21.186.48] ehlo=1 mail=1 rcpt=1 data=1 commands=4
Jan 14 09:46:01 MAIL postfix/smtpd[9153]: timeout after END-OF-MESSAGE from ida.axint.net[50.21.186.48]
Jan 14 09:46:01 MAIL postfix/smtpd[9133]: timeout after END-OF-MESSAGE from ida.axint.net[50.21.186.48]
Jan 14 09:46:01 MAIL postfix/smtpd[9148]: timeout after END-OF-MESSAGE from ida.axint.net[50.21.186.48]
Jan 14 09:46:01 MAIL postfix/smtpd[9153]: disconnect from ida.axint.net[50.21.186.48] ehlo=1 mail=1 rcpt=1 data=1 commands=4
Jan 14 09:46:01 MAIL postfix/smtpd[9133]: disconnect from ida.axint.net[50.21.186.48] ehlo=1 mail=3 rcpt=1/3 data=1/3 rset=4 commands=10/14
Jan 14 09:46:01 MAIL postfix/smtpd[9148]: disconnect from ida.axint.net[50.21.186.48] ehlo=1 mail=2 rcpt=1/2 data=1/2 rset=2 commands=7/9
Jan 14 09:46:01 MAIL postfix/smtpd[6742]: timeout after END-OF-MESSAGE from ida.axint.net[50.21.186.48]
Jan 14 09:46:01 MAIL postfix/smtpd[6742]: disconnect from ida.axint.net[50.21.186.48] ehlo=1 mail=2 rcpt=2 data=2 rset=1 commands=8
Jan 14 09:46:01 MAIL postfix/smtpd[9186]: timeout after END-OF-MESSAGE from ida.axint.net[50.21.186.48]
Jan 14 09:46:01 MAIL postfix/smtpd[9186]: disconnect from ida.axint.net[50.21.186.48] ehlo=1 mail=1 rcpt=1 data=1 commands=4
Jan 14 09:46:01 MAIL postfix/smtpd[9183]: timeout after END-OF-MESSAGE from ida.axint.net[50.21.186.48]
Jan 14 09:46:01 MAIL postfix/smtpd[9183]: disconnect from ida.axint.net[50.21.186.48] ehlo=1 mail=1 rcpt=1 data=1 commands=4

Everything in between is internal mail traffic and outgoing mail.

Jan 14 10:06:00 MAIL postfix/postscreen[5599]: CONNECT from [50.21.186.48]:57520 to [50.204.193.195]:25
Jan 14 10:06:00 MAIL postfix/postscreen[5599]: WHITELISTED [50.21.186.48]:57520
Jan 14 10:06:00 MAIL postfix/postscreen[5599]: CONNECT from [50.21.186.48]:57526 to [50.204.193.195]:25
Jan 14 10:06:00 MAIL postfix/postscreen[5599]: WHITELISTED [50.21.186.48]:57526
Jan 14 10:06:00 MAIL postfix/postscreen[5599]: CONNECT from [50.21.186.48]:57528 to [50.204.193.195]:25
Jan 14 10:06:00 MAIL postfix/postscreen[5599]: WHITELISTED [50.21.186.48]:57528
Jan 14 10:06:00 MAIL postfix/smtpd[5600]: connect from ida.axint.net[50.21.186.48]
Jan 14 10:06:00 MAIL postfix/smtpd[5862]: connect from ida.axint.net[50.21.186.48]
Jan 14 10:06:00 MAIL postfix/postscreen[5599]: CONNECT from [50.21.186.48]:57530 to [50.204.193.195]:25
Jan 14 10:06:00 MAIL postfix/postscreen[5599]: WHITELISTED [50.21.186.48]:57530
Jan 14 10:06:00 MAIL postfix/postscreen[5599]: CONNECT from [50.21.186.48]:57532 to [50.204.193.195]:25
Jan 14 10:06:00 MAIL postfix/postscreen[5599]: WHITELISTED [50.21.186.48]:57532
Jan 14 10:06:00 MAIL postfix/smtpd[5863]: connect from ida.axint.net[50.21.186.48]
Jan 14 10:06:00 MAIL postfix/smtpd[5864]: connect from ida.axint.net[50.21.186.48]
Jan 14 10:06:00 MAIL postfix/smtpd[5865]: connect from ida.axint.net[50.21.186.48]
Jan 14 10:06:00 MAIL postfix/smtpd[5862]: NOQUEUE: filter: RCPT from ida.axint.net[50.21.186.48]: <name@domain.com>: Sender address triggers FILTER smtp-amavis:[127.0.0.1]:10026; from=<name@domain.com> to=<name@domain.com> proto=ESMTP helo=<ida.axint.net>


Everything coming in from outside the domain during this time stacks up on the filtering service. A quick google search on the phrase "postfix/smtpd[9143]: timeout after END-OF-MESSAGE from" gets me lots of hits about $smtp_connection_cache_on_demand and setting it to 0. Like this one:
http://postfix.1071664.n5.nabble.com/ti ... 24768.html

That setting is not in /opt/zimbra/postfix/conf/main.cf

Instead there is one named lmtp_connection_cache_time_limit = 4s

I found some minimal info about that on the Performance Tuning Guide though I hardly consider this a "large" deployment.
https://wiki.zimbra.com/wiki/Performanc ... eployments

I havent changed anything I can remember in the last 4 years from default settings.


UPDATE:
I did find that setting in amavisd. Since we are filtering with another service anyways I disabled amavis. Will see what happens.

Return to “Administrators”

Who is online

Users browsing this forum: Google [Bot] and 17 guests