[SOLVED] zmrestore java.lang.NullPointerException

[jonesrn]

My attempts to use zmrestore in the gui and on the command line both end with a "system failure: java.lang.NullPointerException".

As in:

[zimbra@server0 ~]$ zmrestore -s server0.zprd.lafayette.edu -a jonesrn_test@school.edu -restoreToTime 20081215130000 -lb full-20081215.181031.854 -ca -pre restored_
using restore to time of 2008/12/15 13:00:00
Error occurred: system failure: java.lang.NullPointerException
[zimbra@server0 ~]$

What should I be looking at?

[mmorse]

Welcome to the forums,

Could you increase logging by editing:
/opt/zimbra/conf/log4.properties.in
and adding a line:
log4j.logger.zimbra.backup=DEBUG
zmmtaconfig mailboxd, then retry the restore while tail -f /opt/zimbra/log/mailbox.log

More permanently would be to add it to log4.properties.in & zmmailboxdctl restart.

Or just per user:
zmproc aal user@domain.com zimbra.backup debug
(Automatically removed on restart or with 'ral' - though we'll fix that with bug 22642.)

(5.0.10_GA_2638.RHEL5_64)

[jonesrn]

I can't find zmmtaconfig. All I have is /opt/zimbra/bin/zmmtaconfigctl. Is this the same thing?

Rob

Originally Posted by mmorse

Welcome to the forums,

Could you increase logging by editing:
/opt/zimbra/conf/log4.properties.in
and adding a line:
log4j.logger.zimbra.backup=DEBUG
zmmtaconfig mailboxd, then retry the restore while tail -f /opt/zimbra/log/mailbox.log

More permanently would be to add it to log4.properties.in & zmmailboxdctl restart.

Or just per user:
zmproc aal user@domain.com zimbra.backup debug
(Automatically removed on restart or with 'ral' - though we'll fix that with bug 22642.)

(5.0.10_GA_2638.RHEL5_64)

[jonesrn]

Is zmproc referring to zmprov?

If so, I'm guessing that I need to leave the debug line in /opt/zimbra/conf/log4j.properties.in

and then run zmprov aal user@domain.com zimbra.backup debug

Rob

[jonesrn]

[zimbra@zstore00 bin]$ ./zmprov aal jonesrn_test@zprd.lafayette.edu zimbra.backup debug
[zimbra@zstore00 bin]$ zmrestore -a jonesrn_test@zprd.lafayette.edu --label full-20081215.181031.854 -ca -pre restored
Error occurred: system failure: java.lang.NullPointerException
[zimbra@zstore00 bin]$


[zimbra@zstore00 ~]$ tail -f /opt/zimbra/log/mailbox.log
2008-12-16 16:52:52,349 INFO [IndexWritersSweeperThread] [] index - open index writers sweep: before=3, closed=0, after=3 (0ms)
2008-12-16 16:52:55,398 INFO [MailboxPurge] [name=gambere@zprd.lafayette.edu;mid=3349;] mailop - Deleting items: 4373,4374,4375,4376,4400,4401,4402,4403,4415,4416, 4420,4421,4422.
2008-12-16 16:53:22,356 INFO [IndexWritersSweeperThread] [] index - open index writers sweep: before=4, closed=1, after=3 (2ms)
2008-12-16 16:53:52,359 INFO [IndexWritersSweeperThread] [] index - open index writers sweep: before=3, closed=0, after=3 (0ms)
2008-12-16 16:53:55,534 INFO [MailboxPurge] [name=worthenk@zprd.lafayette.edu;mid=3350;] mailop - Deleting items: 4855,4859,4860,4861,4862,4863,4864,4865,4868,4871, 4872,4873,4874.
2008-12-16 16:54:22,366 INFO [IndexWritersSweeperThread] [] index - open index writers sweep: before=4, closed=0, after=4 (0ms)
2008-12-16 16:54:52,372 INFO [IndexWritersSweeperThread] [] index - open index writers sweep: before=4, closed=0, after=4 (0ms)
2008-12-16 16:55:22,377 INFO [IndexWritersSweeperThread] [] index - open index writers sweep: before=4, closed=0, after=4 (0ms)
2008-12-16 16:55:52,383 INFO [IndexWritersSweeperThread] [] index - open index writers sweep: before=4, closed=0, after=4 (0ms)
2008-12-16 16:56:22,389 INFO [IndexWritersSweeperThread] [] index - open index writers sweep: before=4, closed=0, after=4 (0ms)
2008-12-16 16:56:52,395 INFO [IndexWritersSweeperThread] [] index - open index writers sweep: before=4, closed=0, after=4 (0ms)
2008-12-16 16:57:22,402 INFO [IndexWritersSweeperThread] [] index - open index writers sweep: before=4, closed=1, after=3 (1ms)
2008-12-16 16:57:50,689 INFO [btpool0-33] [ip=127.0.0.1;] soap - AuthRequest
2008-12-16 16:57:50,805 INFO [btpool0-33] [name=zimbra;ip=127.0.0.1;] soap - GetAccountRequest
2008-12-16 16:57:50,851 INFO [btpool0-33] [name=zimbra;ip=127.0.0.1;] misc - delegated access: doc=GetAccount, authenticated account=zimbra, target account=jonesrn_test@zprd.lafayette.edu
2008-12-16 16:57:50,947 INFO [btpool0-33] [name=zimbra;ip=127.0.0.1;] soap - GetServerRequest
2008-12-16 16:57:51,027 INFO [btpool0-33] [name=zimbra;ip=139.147.11.130;] soap - AddAccountLoggerRequest
2008-12-16 16:57:51,028 INFO [btpool0-33] [name=zimbra;ip=139.147.11.130;] misc - Adding custom logger: account=jonesrn_test@zprd.lafayette.edu, category=zimbra.backup, level=debug
2008-12-16 16:57:52,407 INFO [IndexWritersSweeperThread] [] index - open index writers sweep: before=3, closed=0, after=3 (0ms)
2008-12-16 16:58:22,413 INFO [IndexWritersSweeperThread] [] index - open index writers sweep: before=3, closed=0, after=3 (0ms)
2008-12-16 16:58:52,420 INFO [IndexWritersSweeperThread] [] index - open index writers sweep: before=3, closed=0, after=3 (1ms)
2008-12-16 16:58:53,812 INFO [btpool0-33] [ip=127.0.0.1;] soap - AuthRequest
2008-12-16 16:58:53,838 INFO [btpool0-33] [name=zimbra;ip=127.0.0.1;] soap - RestoreRequest
2008-12-16 16:58:53,860 INFO [btpool0-33] [name=zimbra;ip=127.0.0.1;] io - AsyncFileCopier is starting
2008-12-16 16:58:53,863 INFO [btpool0-33] [name=zimbra;ip=127.0.0.1;] io - AsyncFileCopier is shut down
2008-12-16 16:58:53,863 WARN [btpool0-33] [name=zimbra;ip=127.0.0.1;] SoapEngine - handler exception
java.lang.NullPointerException
at com.zimbra.cs.redolog.RedoLogManager.isRolloverNee ded(RedoLogManager.java:542)
at com.zimbra.cs.redolog.RedoLogManager.rollover(Redo LogManager.java:584)
at com.zimbra.cs.redolog.RedoLogManager.forceRollover (RedoLogManager.java:621)
at com.zimbra.cs.redolog.RedoLogManager.forceRollover (RedoLogManager.java:617)
at com.zimbra.cs.backup.FileBackupTarget.restore(File BackupTarget.java:407)
at com.zimbra.cs.backup.BackupManager.restore(BackupM anager.java:716)
at com.zimbra.cs.service.backup.Restore.handle(Restor e.java:129)
at com.zimbra.soap.SoapEngine.dispatchRequest(SoapEng ine.java:411)
at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.jav a:268)
at com.zimbra.soap.SoapEngine.dispatch(SoapEngine.jav a:160)
at com.zimbra.soap.SoapServlet.doPost(SoapServlet.jav a:269)
at javax.servlet.http.HttpServlet.service(HttpServlet .java:727)
at com.zimbra.cs.servlet.ZimbraServlet.service(Zimbra Servlet.java:189)
at javax.servlet.http.HttpServlet.service(HttpServlet .java:820)
at org.mortbay.jetty.servlet.ServletHolder.handle(Ser vletHolder.java:487)
at org.mortbay.jetty.servlet.ServletHandler$CachedCha in.doFilter(ServletHandler.java:1093)
at org.mortbay.servlet.UserAgentFilter.doFilter(UserA gentFilter.java:81)
at org.mortbay.servlet.GzipFilter.doFilter(GzipFilter .java:148)
at org.mortbay.jetty.servlet.ServletHandler$CachedCha in.doFilter(ServletHandler.java:1084)
at org.mortbay.jetty.servlet.ServletHandler.handle(Se rvletHandler.java:360)
at org.mortbay.jetty.security.SecurityHandler.handle( SecurityHandler.java:216)
at org.mortbay.jetty.servlet.SessionHandler.handle(Se ssionHandler.java:181)
at org.mortbay.jetty.handler.ContextHandler.handle(Co ntextHandler.java:716)
at org.mortbay.jetty.webapp.WebAppContext.handle(WebA ppContext.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(Ha ndlerWrapper.java:139)
at org.mortbay.jetty.handler.rewrite.RewriteHandler.h andle(RewriteHandler.java:350)
at org.mortbay.jetty.handler.HandlerWrapper.handle(Ha ndlerWrapper.java:139)
at org.mortbay.jetty.Server.handle(Server.java:313)
at org.mortbay.jetty.HttpConnection.handleRequest(Htt pConnection.java:506)
at org.mortbay.jetty.HttpConnection$RequestHandler.co ntent(HttpConnection.java:844)
at org.mortbay.jetty.HttpParser.parseNext(HttpParser. java:644)
at org.mortbay.jetty.HttpParser.parseAvailable(HttpPa rser.java:211)
at org.mortbay.jetty.HttpConnection.handle(HttpConnec tion.java:381)
at org.mortbay.io.nio.SelectChannelEndPoint.run(Selec tChannelEndPoint.java:396)
at org.mortbay.thread.BoundedThreadPool$PoolThread.ru n(BoundedThreadPool.java:442)
2008-12-16 16:59:22,424 INFO [IndexWritersSweeperThread] [] index - open index writers sweep: before=3, closed=0, after=3 (0ms)
2008-12-16 16:59:52,429 INFO [IndexWritersSweeperThread] [] index - open index writers sweep: before=3, closed=0, after=3 (0ms)
2008-12-16 17:00:22,435 INFO [IndexWritersSweeperThread] [] index - open index writers sweep: before=3, closed=0, after=3 (0ms)
2008-12-16 17:00:52,440 INFO [IndexWritersSweeperThread] [] index - open index writers sweep: before=3, closed=0, after=3 (0ms)
2008-12-16 17:00:56,112 INFO [MailboxPurge] [name=gordong@zprd.lafayette.edu;mid=3357;] mailop - Deleting items: 10085,10086,10087,10088,10089.
2008-12-16 17:01:22,445 INFO [IndexWritersSweeperThread] [] index - open index writers sweep: before=4, closed=0, after=4 (0ms)
2008-12-16 17:01:52,450 INFO [IndexWritersSweeperThread] [] index - open index writers sweep: before=4, closed=0, after=4 (0ms)

[jonesrn]

Mike,

Logging revealed that the NullPointerException was found in the Redolog which had been turned off due to excessive logging during imap sync. Turning the redo log back on enabled zmrestore to run without any problems.

The logs are a powerful tool. I'm looking forward to using them the next time I get into trouble.

2008-12-16 16:58:53,863 WARN [btpool0-33] [name=zimbra;ip=127.0.0.1;] SoapEngine - handler exception
java.lang.NullPointerException
at com.zimbra.cs.redolog.RedoLogManager.isRolloverNee ded(RedoLogManager.java:542)

Thanks Rob

[msheean]

What specifically was turned back on? I'm having a NullPointerException problem causing some accounts to not be restored. Redo log is running.

[jonesrn]

Sorry msheean, I cannot recall further details on this fix. 2008 is simply too long ago.

Good Luck