[SOLVED] Zimbra Backup Report: FAIL

[padraig]

i seem to get a FAIL on the backup e-mail but when i check the admin UI appears to be successful, anybody else notice this. its only started since i upgraded to 4.56ne from 4.51ne on RHEL4_64


Zimbra Backup Report: FAIL

Reason:
com.zimbra.common.service.ServiceException: invalid request: backup deletion is still in progress
at com.zimbra.common.service.ServiceException.INVALID_REQUEST(ServiceException.java:182)
at com.zimbra.cs.backup.BackupManager.setCurrentOp(BackupManager.java:570)
at com.zimbra.cs.backup.BackupManager.backupIncremental(BackupManager.java:318)
at com.zimbra.cs.service.backup.Backup.handleNetworkRequest(Backup.java:116)
at com.zimbra.cs.service.NetworkDocumentHandler.handle(Unknown Source)
at com.zimbra.soap.SoapEngine.dispatchRequest(SoapEngine.java:270)
at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:168)
at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:90)
at com.zimbra.soap.SoapServlet.doPost(SoapServlet.java:223)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
at com.zimbra.cs.servlet.ZimbraServlet.service(ZimbraServlet.java:162)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:541)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:869)
at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:667)
at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:80)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
at java.lang.Thread.run(Thread.java:595)

[jholder]

Looks like it was trying to remove an old backup while starting a new one.

Is this a one time thing, or is it happening all the time?

[padraig]

its happened twice in ~1mth since upgrading to 4.56 (not before using 4.51 ~6mnths)

[padraig]

Time: Wed, 2007/09/05 01:00:35.660 IST
Reason:

com.zimbra.common.service.ServiceException: invalid request: backup deletion is still in progress
at com.zimbra.common.service.ServiceException.INVALID _REQUEST(ServiceException.java:182)
at com.zimbra.cs.backup.BackupManager.setCurrentOp(Ba ckupManager.java:570)
at com.zimbra.cs.backup.BackupManager.backupIncrement al(BackupManager.java:318)
at com.zimbra.cs.service.backup.Backup.handleNetworkR equest(Backup.java:116)
at com.zimbra.cs.service.NetworkDocumentHandler.handl e(Unknown Source)
at com.zimbra.soap.SoapEngine.dispatchRequest(SoapEng ine.java:270)
at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.jav a:168)
at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.jav a:90)
at com.zimbra.soap.SoapServlet.doPost(SoapServlet.jav a:223)
at javax.servlet.http.HttpServlet.service(HttpServlet .java:709)
at com.zimbra.cs.servlet.ZimbraServlet.service(Zimbra Servlet.java:162)
at javax.servlet.http.HttpServlet.service(HttpServlet .java:802)
at org.apache.catalina.core.ApplicationFilterChain.in ternalDoFilter(ApplicationFilterChain.java:252)
at org.apache.catalina.core.ApplicationFilterChain.do Filter(ApplicationFilterChain.java:173)
at org.apache.catalina.core.StandardWrapperValve.invo ke(StandardWrapperValve.java:213)
at org.apache.catalina.core.StandardContextValve.invo ke(StandardContextValve.java:178)
at org.apache.catalina.core.StandardHostValve.invoke( StandardHostValve.java:126)
at org.apache.catalina.valves.ErrorReportValve.invoke (ErrorReportValve.java:105)
at org.apache.catalina.core.StandardEngineValve.invok e(StandardEngineValve.java:107)
at org.apache.catalina.valves.AccessLogValve.invoke(A ccessLogValve.java:541)
at org.apache.catalina.connector.CoyoteAdapter.servic e(CoyoteAdapter.java:148)
at org.apache.coyote.http11.Http11Processor.process(H ttp11Processor.java:869)
at org.apache.coyote.http11.Http11BaseProtocol$Http11 ConnectionHandler.processConnection(Http11BaseProt ocol.java:667)
at org.apache.tomcat.util.net.PoolTcpEndpoint.process Socket(PoolTcpEndpoint.java:527)
at org.apache.tomcat.util.net.LeaderFollowerWorkerThr ead.runIt(LeaderFollowerWorkerThread.java:80)
at org.apache.tomcat.util.threads.ThreadPool$ControlR unnable.run(ThreadPool.java:684)
at java.lang.Thread.run(Thread.java:595)

[jbareMACS]

I see this error about once a week when ZCS is running its incremental backup. Here's an example:

Time: Wed, 2007/09/26 01:00:13.312 EDT
Reason:

com.zimbra.common.service.ServiceException: invalid request: backup deletion is still in progress
at com.zimbra.common.service.ServiceException.INVALID_REQUEST(ServiceException.java:182)
at com.zimbra.cs.backup.BackupManager.setCurrentOp(BackupManager.java:570)
at com.zimbra.cs.backup.BackupManager.backupIncremental(BackupManager.java:318)
at com.zimbra.cs.service.backup.Backup.handleNetworkRequest(Backup.java:116)
at com.zimbra.cs.service.NetworkDocumentHandler.handle(Unknown Source)
at com.zimbra.soap.SoapEngine.dispatchRequest(SoapEngine.java:270)
at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:168)
at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:90)
at com.zimbra.soap.SoapServlet.doPost(SoapServlet.java:223)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:709)
at com.zimbra.cs.servlet.ZimbraServlet.service(ZimbraServlet.java:162)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:802)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:541)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:869)
at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:667)
at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:80)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
at java.lang.Thread.run(Thread.java:613)

The backup is not shown in the backup history.

[padraig]

please vote for the bugzilla on this:
Bug 19575 - Zimbra Backup Report: FAIL
thanks.

[peter@mxtoolbox.com]

Can you guys shed some light on how to look in on this process. I'm getting this all the time on my large install which has slow disk performance. I would like to be able to stop the deletion process or at least check it's progress.

Running 5.0.9 with 12k users backing up to NAS so the deletion can take a long time.

[padraig]

please vote for the bugzilla on this:
Bug 19575 - Zimbra Backup Report: FAIL
thanks.

reopened bug

[inigoml]

Running 5.0.9 with 12k users backing up to NAS so the deletion can take a long time.

I agree with you.
The problem, in my installation, is due to we are dumping to a NAS via NFS. Although transfer rate is fast enought, deletion process takes ages to complete. We have only 400 mailboxes with about 500MB size each, and deleting a full backup takes hours.
I don't know how deletion process has been implemented, but I suspect that it's deleting file by file. Perhaps an "rm -Rf directory" could be faster...

[peter@mxtoolbox.com]

We too are mounting the NAS with NFS and yes, deletion does take forever. If you can use the --zip option when making your backups, it goes a lot faster since there are way less files to work on.

I just really really really (yes three really's) wish I could see the deletion thread / process so I can determine if it's really running / could kill it and prune the logs by hand. rm -rf backup/session/name is MUCH faster than the deletion script. Zimbra, can I get some love?

Peter