Backups Skipping Certain Days

[gtuhl]

I receive an automated report each morning that summarizes a lot of backup and maintenance activity from the previous night. I noticed the other day that there are certain days for which I do not have a Zimbra backup. I can see back a month, and for April 15th (Weds), April 22nd (Weds), April 29th (Weds), and May 5th (Tues) there is no backup.

Each of those days was slated to be an incremental backup. I see no failed backups in the admin console and nothing in my logs. Is there a particular place I should be looking? There are a lot of Zimbra logs so I could be looking in the wrong place.

Some other notes:

* I fired up a backup via the admin console on the 5th and that backup completed without any issues.

* Disk space is not an issue. Zimbra has 80GB of room and the backups are written to a separate disk array with Terabytes of storage available.

* The output of zmschedulebackup -q looks like this:

Current Schedule:

	f 0 1 * * 6 -a all
	i 0 1 * * 0-5 
	d 1m 0 0 * * *

* If I take a peak at the zimbra user's crontab I similarly see this:

# BACKUP BEGIN
0 1 * * 6 /opt/zimbra/bin/zmbackup -f   -a all 
0 1 * * 0-5 /opt/zimbra/bin/zmbackup -i  
0 0 * * * /opt/zimbra/bin/zmbackup -del 1m
# BACKUP END

My understanding is that this schedule should do a full backup each Saturday at 1am, and an incremental backup all other days at 1am.

Anyone have ideas as to why I would be missing incremental backups? Is this to be expected and there is simply something I don't understand about the process?

Any help is greatly appreciated.

I am running Version 5.0.11_GA_2695.UBUNTU6.NETWORK.

[bdial]

the backup system logs to /opt/zimbra/log/mailbox.log so you might watn to look there for the time/day in question and see if theres anything that would explain it.

[gtuhl]

Thanks bdial, there is indeed some useful info in /opt/zimbra/log/mailbox.log. It skipped running today as well.

Looking in /opt/zimbra/log/mailbox.log I see this at midnight when the client portion runs:

2009-05-12 00:00:05,349 INFO  [btpool0-9843] [name=zimbra;ip=127.0.0.1;] backup - Backup request st\
arted
2009-05-12 00:00:05,353 INFO  [btpool0-9843] [name=zimbra;ip=127.0.0.1;] backup - deleting backups \
on or older than Sun Apr 12 00:00:05 EDT 2009
2009-05-12 00:00:05,452 INFO  [btpool0-9843] [name=zimbra;ip=127.0.0.1;] backup - deleting backup f\
ull-20090411.050004.919

And then at 1am when the backup itself runs I see this big stack trace:

2009-05-12 01:00:04,956 INFO  [btpool0-9854] [name=zimbra;ip=127.0.0.1;] soap - BackupRequest
2009-05-12 01:00:04,960 INFO  [btpool0-9854] [name=zimbra;ip=127.0.0.1;] backup - Backup request started
2009-05-12 01:00:05,055 INFO  [btpool0-9854] [name=zimbra;ip=127.0.0.1;] backup - Found 23 accounts on server mail.weth\
ecitizens.com
2009-05-12 01:00:06,088 INFO  [ImapSSLServer-34803] [] imap - [32.130.233.120] connected
2009-05-12 01:00:06,259 INFO  [btpool0-9854] [name=zimbra;ip=127.0.0.1;] SoapEngine - handler exception
com.zimbra.common.service.ServiceException: invalid request: backup deletion is still in progress
ExceptionId:btpool0-9854:1242104406169:0ec319b508812278
Code:service.INVALID_REQUEST
        at com.zimbra.common.service.ServiceException.INVALID_REQUEST(ServiceException.java:260)
        at com.zimbra.cs.backup.BackupManager.setCurrentOp(BackupManager.java:815)
        at com.zimbra.cs.backup.BackupManager.backupIncremental(BackupManager.java:311)
        at com.zimbra.cs.service.backup.Backup.handleNetworkRequest(Backup.java:150)
        at com.zimbra.cs.service.NetworkDocumentHandler.handle(Unknown Source)
        at com.zimbra.soap.SoapEngine.dispatchRequest(SoapEngine.java:433)
        at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:288)
        at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.java:167)
        at com.zimbra.soap.SoapServlet.doPost(SoapServlet.java:269)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)
        at com.zimbra.cs.servlet.ZimbraServlet.service(ZimbraServlet.java:189)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
        at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:487)
        at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1093)
        at org.mortbay.servlet.UserAgentFilter.doFilter(UserAgentFilter.java:81)
        at org.mortbay.servlet.GzipFilter.doFilter(GzipFilter.java:148)
        at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1084)
        at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:360)
        at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
        at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
        at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:716)
        at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:406)
        at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:211)
        at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:114)
        at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:139)
        at org.mortbay.jetty.handler.rewrite.RewriteHandler.handle(RewriteHandler.java:350)
        at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:139)
        at org.mortbay.jetty.Server.handle(Server.java:313)
        at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:506)
        at org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:844)
        at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:644)
        at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:211)
        at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:381)
        at org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:396)
        at org.mortbay.thread.BoundedThreadPool$PoolThread.run(BoundedThreadPool.java:442)

So the error message seems logical. But it seems awfully strange that this happened precisely on every Wednesday in April and apparently is happening every Tuesday in May. This could perhaps just be unusual coincidence.

I am going to use zmschedulebackup to push the backup back to 3am and see if that fixes things up. Should this be treated as a bug? It seems that if this happened I should see a failed backup in the admin console so that I know something is off.

[bdial]

it's hard to say wether it should be classified as a bug or not really. while i guess overall it can be considered a failed backup, its not that the backup failed but rather it couldn't run because the delete was still going on.