MTA Going Down After Full Backup

[jpsinacola]

I am trying to troubleshoot a problem with my installation, specifically the MTA service going down on Saturday morning, during which I presume my full backup. It does it every Friday night / Saturday morning and I need to start services and it comes backup up without any problems. I have looked through the logs and I found that the full backup completes. I guess my first question is, does the MTA shut down during full backup? In the log, after it gives the backup detail, says ExceptionID:btpool10-54701:myserver/soap/sendmsgrequest: messageID
Code:mail.TRY_AGAIN.

I can post more of log if needed, but was wondering if anyone else had experienced that problem?

Thanks!

[phoenix]

Originally Posted by jpsinacola

I guess my first question is, does the MTA shut down during full backup?

No, the MTA doesn't shutdown after any sort of backup.

Originally Posted by jpsinacola

In the log, after it gives the backup detail, says ExceptionID:btpool10-54701:myserver/soap/sendmsgrequest: messageID
Code:mail.TRY_AGAIN.

I can post more of log if needed, but was wondering if anyone else had experienced that problem?

You need to post more details from the log files after the moment the backup finishes to to the time after the MTA shuts down (I assume you're seeing a shutdown in the log files?).

[jpsinacola]

Thanks for that info Bill, that helps a lot. So something is knocking that service offline then. I am not seeing a specific instance where it shuts down, I just see that mail.TRY_AGAIN. I am looking for more information from the MTA service itself. Here is more from the log:

2011-10-29 02:19:42,882 INFO  [FullBackupThread] [] backup - full backup took 4778054 millisec
2011-10-29 00:00:04,153 INFO  [btpool0-54574://localhost:7071/service/admin/soap/AuthRequest] [ip=127.
0.0.1;ua=zmprov/7.1.1_GA_3196;] soap - AuthRequest
2011-10-29 00:00:04,178 INFO  [btpool0-54575://mail1.mymail.com/service/soap/WaitSetRequest] [nam
e=dkcornett@mymail.com;mid=100;ip=10.99.0.60;ua=Zimbra Desktop/7.1.2_10978_Windows;] soap - WaitS
etRequest
2011-10-29 00:00:04,215 INFO  [btpool0-54574://localhost:7071/service/admin/soap/GetAllServersRequest]
 [name=zimbra;ip=127.0.0.1;ua=zmprov/7.1.1_GA_3196;] soap - GetAllServersRequest
2011-10-29 00:00:04,444 INFO  [btpool0-54574://localhost:7071/service/admin/soap/AuthRequest] [ip=127.
0.0.1;ua=zmbackup/7.1.1_GA_3196;] soap - AuthRequest
2011-10-29 00:00:04,535 INFO  [btpool0-54574://localhost:7071/service/admin/soap/BackupRequest] [name=
zimbra;ip=127.0.0.1;ua=zmbackup/7.1.1_GA_3196;] soap - BackupRequest
2011-10-29 00:00:04,538 INFO  [btpool0-54574://localhost:7071/service/admin/soap/BackupRequest] [name=
zimbra;ip=127.0.0.1;ua=zmbackup/7.1.1_GA_3196;] backup - Backup request started
2011-10-29 00:00:04,541 INFO  [btpool0-54574://localhost:7071/service/admin/soap/BackupRequest] [name=
zimbra;ip=127.0.0.1;ua=zmbackup/7.1.1_GA_3196;] backup - deleting backups on or older than Thu Sep 29
00:00:04 EDT 2011
2011-10-29 00:00:04,665 INFO  [btpool0-54574://localhost:7071/service/admin/soap/BackupRequest] [name=
zimbra;ip=127.0.0.1;ua=zmbackup/7.1.1_GA_3196;] backup - deleting backup incr-20110928.050005.088
2011-10-29 00:00:04,667 INFO  [btpool0-54574://localhost:7071/service/admin/soap/BackupRequest] [name=
zimbra;ip=127.0.0.1;ua=zmbackup/7.1.1_GA_3196;] backup - Backup request finished
2011-10-29 00:00:04,667 INFO  [BackupDeletion] [] backup - Starting deletion of 1 old backups
2011-10-29 00:00:04,667 INFO  [BackupDeletion] [] backup - Deleting old backup directory /opt/zimbra/b
ackup/sessions/TO_DELETE-incr-20110928.050005.088
2011-10-29 00:00:05,423 INFO  [Timer-Zimbra] [] session - WaitSet sweeper: 2 active WaitSets (2 accoun
ts) - 0 sets with blocked callbacks
2011-10-29 00:00:05,859 INFO  [BackupDeletion] [] backup - Finished deletion of 1 old backups
2011-10-29 00:00:05,923 INFO  [btpool0-54574://mail1.mymail.com/service/soap/NoOpRequest] [name=m
herron@mymail.com;mid=112;ip=69.246.24.154;ua=ZimbraWebClient - IE7 (Win)/7.1.1_GA_3196;] soap -
NoOpRequest
2011-10-29 00:00:06,455 INFO  [Timer-Zimbra] [] SessionCache - Removed 1 idle sessions (ADMIN). 15 act
ive sessions remain.
2011-10-29 00:00:14,766 INFO  [btpool0-54574://mail1.mymail.com/service/soap/WaitSetRequest] [nam
e=blang@mymail.com;mid=69;ip=10.3.0.15;ua=Zimbra Desktop/7.1.2_10978_Windows;] soap - WaitSetRequ
est
2011-10-29 00:00:16,622 INFO  [btpool0-54576://mail1.mymail.com/service/soap/NoOpRequest] [name=s
kimble@mymail.com;mid=65;ip=10.8.0.28;ua=ZimbraWebClient - IE8 (Win)/7.1.1_GA_3196;] soap - NoOpR
equest
2011-10-29 00:00:23,233 INFO  [btpool0-54574://mail1.mymail.com/service/soap/NoOpRequest] [name=b
scally@mymail.com;mid=70;ip=10.99.0.39;ua=ZimbraWebClient - IE7 (Win)/7.1.1_GA_3196;] soap - NoOp
Request
2011-10-29 00:00:34,971 WARN  [btpool0-54574] [] log - SSL renegotiate denied: java.nio.channels.Socke
tChannel[connected local=/10.99.0.73:443 remote=/174.255.68.118:37616]
2011-10-29 00:00:39,089 INFO  [MailboxPurge] [name=dhood@mymail.com;mid=99;] purge - Purging mess
ages.
2011-10-29 00:01:01,475 INFO  [btpool0-54574://mail1.mymail.com/service/soap/NoOpRequest] [name=g
kilby@mymail.com;mid=104;ip=75.39.8.226;ua=ZimbraWebClient - IE8 (Win)/7.1.1_GA_3196;] soap - NoO
pRequest
2011-10-29 00:01:05,423 INFO  [Timer-Zimbra] [] session - WaitSet sweeper: 2 active WaitSets (2 accoun
ts) - 1 sets with blocked callbacks
2011-10-29 00:01:09,181 INFO  [btpool0-54574://mail1.mymail.com/service/soap/WaitSetRequest] [nam
e=dkcornett@mymail.com;mid=100;ip=10.99.0.60;ua=Zimbra Desktop/7.1.2_10978_Windows;] soap - WaitS
etRequest
2011-10-29 00:01:19,754 INFO  [btpool0-54574://mail1.mymail.com/service/soap/WaitSetRequest] [nam
e=blang@mymail.com;mid=69;ip=10.3.0.15;ua=Zimbra Desktop/7.1.2_10978_Windows;] soap - WaitSetRequ
est
2011-10-29 00:01:39,156 INFO  [MailboxPurge] [name=dkcornett@mymail.com;mid=100;] purge - Purging
/4778054
...skipping
2011-10-29 02:19:42,882 INFO  [FullBackupThread] [] backup - full backup took 4778054 millisec
2011-10-29 02:19:53,157 INFO  [btpool0-54701://mail1.mymail.com/service/soap/WaitSetRequest] [nam
e=dkcornett@mymail.com;mid=100;ip=10.99.0.60;ua=Zimbra Desktop/7.1.2_10978_Windows;] soap - WaitS
etRequest
2011-10-29 02:20:03,934 INFO  [btpool0-54701://localhost:7071/service/admin/soap/AuthRequest] [ip=127.
0.0.1;ua=zmprov/7.1.1_GA_3196;] soap - AuthRequest
2011-10-29 02:20:03,992 INFO  [btpool0-54701://localhost:7071/service/admin/soap/GetAllServersRequest]
 [name=zimbra;ip=127.0.0.1;ua=zmprov/7.1.1_GA_3196;] soap - GetAllServersRequest
2011-10-29 02:20:05,438 INFO  [Timer-Zimbra] [] session - WaitSet sweeper: 2 active WaitSets (2 accoun
ts) - 1 sets with blocked callbacks
2011-10-29 02:20:06,827 INFO  [btpool0-54701://mail1.mymail.com/service/upload?fmt=raw] [name=cru
ssell@mymail.com;mid=39;ip=24.231.147.200;ua=Jakarta Commons-HttpClient/3.1;] FileUploadServlet -
 Received plain: Upload: { accountId=a9287dba-93d2-4244-89a6-ef1fff84f4ff, time=Sat Oct 29 02:20:06 ED
T 2011, size=2484, uploadId=cee5f9fe-787c-4987-b717-fa9418375e8f:76d60598-8ae0-4ad4-99b6-32fccc7dd88a,
 name=msg-1073746026, path=null }
2011-10-29 02:20:06,869 INFO  [btpool0-54701://mail1.mymail.com/service/soap/SendMsgRequest] [nam
e=crussell@mymail.com;mid=39;ip=24.231.147.200;ua=Zimbra Desktop/7.1.2_10978_Windows;] soap - Sen
dMsgRequest
2011-10-29 02:20:06,918 INFO  [MailboxPurge] [name=tcunningham@mymail.com;mid=88;] purge - Purgin
g messages.
2011-10-29 02:20:07,608 INFO  [Timer-Zimbra] [] FileUploadServlet - 2 pending file uploads
2011-10-29 02:20:11,371 INFO  [btpool0-54701://mail1.mymail.com/service/soap/SendMsgRequest] [nam
e=crussell@mymail.com;mid=39;ip=24.231.147.200;ua=Zimbra Desktop/7.1.2_10978_Windows;] SoapEngine
 - handler exception
com.zimbra.cs.mailbox.MailServiceException: try again: message send already in progress: c19870d8-75f5
-4a34-9c47-088d9077e1ea
ExceptionId:btpool0-54701://mail1.mymail.com/service/soap/SendMsgRequest:1319869211370:dcffa0a146
d4baba
Code:mail.TRY_AGAIN
 at com.zimbra.cs.mailbox.MailServiceException.TRY_AGAIN(MailServiceException.java:475)
 at com.zimbra.cs.service.mail.SendMsg.handle(SendMsg.java:142)
 at com.zimbra.soap.SoapEngine.dispatchRequest(SoapEngine.java:412)
 at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:287)
 at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:158)
 at com.zimbra.soap.SoapServlet.doWork(SoapServlet.java:294)
 at com.zimbra.soap.SoapServlet.doPost(SoapServlet.java:215)
 at javax.servlet.http.HttpServlet.service(HttpServlet.java:725)
 at com.zimbra.cs.servlet.ZimbraServlet.service(ZimbraServlet.java:208)
 at javax.servlet.http.HttpServlet.service(HttpServlet.java:814)
 at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:511)
 at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1166)
 at com.zimbra.cs.servlet.SetHeaderFilter.doFilter(SetHeaderFilter.java:79)
 at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
 at org.mortbay.servlet.UserAgentFilter.doFilter(UserAgentFilter.java:81)
 at org.mortbay.servlet.GzipFilter.doFilter(GzipFilter.java:155)
 at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1157)
 at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:388)
 at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:218)
 at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:182)
 at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765)
 at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:422)
 at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:230
)
 at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
 at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
 at org.mortbay.jetty.handler.rewrite.RewriteHandler.handle(RewriteHandler.java:230)
 at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
 at org.mortbay.jetty.handler.DebugHandler.handle(DebugHandler.java:77)
 at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
 at org.mortbay.jetty.Server.handle(Server.java:326)
 at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:543)
 at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:946)
 at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:756)
 at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:218)
 at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:405)
 at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:410)
 at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:451)
2011-10-29 02:20:28,362 INFO  [btpool0-54703://mail1.mymail.com/service/soap/WaitSetRequest] [nam
e=me@mymail.com;mid=69;ip=10.3.0.15;ua=Zimbra Desktop/7.1.2_10978_Windows;] soap - WaitSetRequ
est
2011-10-29 02:20:46,400 WARN  [btpool0-54703] [] log - SSL renegotiate denied: java.nio.channels.Socke
tChannel[connected local=/10.99.0.73:443 remote=/174.252.242.84:60408]
2011-10-29 02:20:58,149 INFO  [btpool0-54703://mail1.mymail.com/service/soap/WaitSetRequest] [nam
e=me@mymail.com;mid=100;ip=10.99.0.60;ua=Zimbra Desktop/7.1.2_10978_Windows;] soap - WaitS
etRequest
2011-10-29 02:21:05,438 INFO  [Timer-Zimbra] [] session - WaitSet sweeper: 2 active WaitSets (2 accoun
ts) - 1 sets with blocked callbacks
2011-10-29 02:21:07,050 INFO  [MailboxPurge] [name=tmayles@mymail.com;mid=89;] purge - Purging me
ssages.
2011-10-29 02:21:07,608 INFO  [Timer-Zimbra] [] FileUploadServlet - 2 pending file uploads
2011-10-29 02:21:24,888 INFO  [btpool0-54703://mail1.mymail.com/service/soap/NoOpRequest] [name=s
me@mymail.com;mid=65;ip=10.8.0.28;ua=ZimbraWebClient - IE8 (Win)/7.1.1_GA_3196;] soap - NoOpR
equest
2011-10-29 02:21:33,350 INFO  [btpool0-54703://mail1.mymail.com/service/soap/WaitSetRequest] [nam
--More--

[phoenix]

IS the service actually down at this point, what's the status of the services after the backup is done? Post the output of the following command:

zmcontrol status

Does this happen with all users? Has this problem just started? Any upgrades to the server recently? If all the services are still up and running are the accounts in maintenance mode?

[jpsinacola]

At that point, yes, the MTA service is down. All other services are running. I cannot provide the output now because all of the services are currently up. Every Saturday morning I have to VPN in to my network, I check it with zmcontrol status, I see that MTA is not running (everything else is), and I do a zmcontrol start and it starts running again and all appears normal.

This has been going on for about a couple of months, I do not have the date exactly, sorry. I have not done any software updates, neither Zimbra nor SUSE during that time frame.

I wish I had more to go on, which is why I turned to the forums hoping maybe someone had something similar, or let me know where to even start looking.

**
Upon more thought, I understand your question. Am I SURE that the backup is causing it? No, not exactly. There is nothing in the logs to show where is went down, so you could call it a "deduction" since the full backup is the only thing that is different. Other than this issue, I have ZERO problems with Zimbra and it runs wonderfully. So, I need to figure out how best to monitor it, so that I know exactly WHEN it goes down. Thoughts?
**

Thanks again for the help!

[phoenix]

Originally Posted by jpsinacola

**
Upon more thought, I understand your question. Am I SURE that the backup is causing it? No, not exactly. There is nothing in the logs to show where is went down, so you could call it a "deduction" since the full backup is the only thing that is different. Other than this issue, I have ZERO problems with Zimbra and it runs wonderfully. So, I need to figure out how best to monitor it, so that I know exactly WHEN it goes down. Thoughts?
**!

Do you have any monitoring software (such as Nagios) on your LAN or something just to check port 25 to see when exactly the MTA is stopping? Is this a VM or a bare metal server?