Unable to start Modeshape after using Backup/Restore functionality

[folch]

Hi,

I'm using Backup/Restore functionality to migrate data from our Application that is using the old Modeshape version 3.8.0 to the new Modeshape version 4.4.0.

The process is the following:

1. Our application is running without problems using Modeshape 3.8.0
   
2. Perform a backup in the old Modeshape (3.8.0) that contains some documents (binaries and metadata)
3. Perform a fresh installation of a new version of our application (which is using  Modeshape 4.4.0). Check that works and it only contains the basic structure (with some config nodes of our application).
4. Perform a restore of the backup binaries in the new installation. The restore takes a while, shows the following error and the repository does not start.

SEVERE: Error while refreshing index definitions for the "empower.repository" repository

java.lang.NullPointerException

  at org.modeshape.jcr.SystemContent.indexesKey(SystemContent.java:154)

  at org.modeshape.jcr.SystemContent.indexesNode(SystemContent.java:202)

  at org.modeshape.jcr.SystemContent.readAllIndexDefinitions(SystemContent.java:565)

  at org.modeshape.jcr.RepositoryIndexManager.readIndexDefinitions(RepositoryIndexManager.java:806)

  at org.modeshape.jcr.RepositoryIndexManager.register(RepositoryIndexManager.java:319)

  at org.modeshape.jcr.RepositoryIndexManager.<init>(RepositoryIndexManager.java:135)

  at org.modeshape.jcr.RepositoryQueryManager.<init>(RepositoryQueryManager.java:90)

  at org.modeshape.jcr.JcrRepository$RunningState.<init>(JcrRepository.java:1207)

  at org.modeshape.jcr.JcrRepository$RunningState.<init>(JcrRepository.java:982)

  at org.modeshape.jcr.JcrRepository.doStart(JcrRepository.java:388)

  at org.modeshape.jcr.JcrRepository.start(JcrRepository.java:312)

  at org.modeshape.jcr.JcrRepository.completeRestore(JcrRepository.java:543)

  at org.modeshape.jcr.BackupService.restoreRepository(BackupService.java:161)

  at org.modeshape.jcr.JcrRepositoryManager.restoreRepository(JcrRepositoryManager.java:87)

  at org.modeshape.jcr.JcrRepositoryManager.restoreRepository(JcrRepositoryManager.java:81)

  at org.apache.jsp.console.tools.repository.restore_jsp.restore(restore_jsp.java:93)

  at org.apache.jsp.console.tools.repository.restore_jsp._jspService(restore_jsp.java:173)

  at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:70)

  at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)

  at org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:432)

  at org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:390)

  at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:334)

  at javax.servlet.http.HttpServlet.service(HttpServlet.java:727)

  at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)

  at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)

  at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)

  at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)

  at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)

  at com.hp.exstream.hes.webapp.HeaderFilter.doFilter(HeaderFilter.java:157)

  at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)

  at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)

  at com.hp.exstream.hes.services.filter.CsrfHeaderFilter.doFilter(CsrfHeaderFilter.java:59)

  at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)

  at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)

  at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330)

  at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:118)

  at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:84)

  at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)

  at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:113)

  at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)

  at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:103)

  at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)

  at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:113)

  at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)

  at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:154)

  at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)

  at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:45)

  at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)

  at org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilter(BasicAuthenticationFilter.java:201)

  at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)

  at org.springframework.security.web.csrf.CsrfFilter.doFilterInternal(CsrfFilter.java:85)

  at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:106)

  at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)

  at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:50)

  at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:106)

  at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)

  at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:87)

  at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)

  at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:192)

  at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:160)

  at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:343)

  at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:260)

  at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)

  at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)

  at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)

  at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)

  at org.apache.tomee.catalina.OpenEJBValve.invoke(OpenEJBValve.java:45)

  at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)

  at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:98)

  at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:950)

  at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)

  at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:408)

  at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1040)

  at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:607)

  at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:313)

  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)

  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)

  at java.lang.Thread.run(Thread.java:745)

The system does not start anymore. When I try to restart the system is blocked at line: INFO: ISPN000128: Infinispan version: Infinispan 'Insanely Bad Elf' 7.2.3.Final and it does not start.

We are using some indexes definitions (attached you can see modeshape config) and if we try to do the same restore without adding indexes in our Modeshape config, the same error happens but it does not block the startup completely. We can work without indexes then.

Is there anything we can do to avoid this error?

Thanks in advance

Update: I tried to upgrade to Modeshape 4.5.0 and configure indexes with Lucene and I get the same error.

[hchiorean]

This is obviously a bug. I've opened [MODE-2539] Cannot 3.x restore repository backup - JBoss Issue Tracker which we'll handle for 4.6.

Did you try not using any of the advanced MapDB settings (cacheLRUEnable, mmapFileEnable, commitFileSyncDisable). In general I would not recommend ever disabling commitFileSyncDisable as you can get index corruption.

[folch]

Hi Horia,

yes, we tried to not using advanced MapDB settings. I get the same error.

Even upgrading to Modeshape 4.5.0 and using Lucene, the error still happens.

Do you see any other workaround? Do you know when you are going to release 4.6.0? We cannot wait so long and we need to find an alternative solution. I'm thinking on using backup/restore from JCR. Do you see anything else we can try?

[hchiorean]

We've just released 4.5.0.Final, so 4.6 will be released sometime in January/February.

I don't know what's causing the issue, as we already have a test which validates restoring a 3.8.1 backup with binaries and it works fine: modeshape/RepositoryBackupAndRestoreTest.java at modeshape-4.4.0.Final · ModeShape/modeshape · GitHub

Whatever the issue is, it's not happening on every data restore. After I fix it, if there is a workaround I will update the JIRA issue. If there isn't, then the only option to get the codebase prior to 4.6.0.Final is to build from GitHub a master snapshot and use that.

[hchiorean]

When you perform the backup/restore, is the ISPN cache name (the one that's configured in JSON as the "storage"/"cacheName" attribute) the same for both the backup and the restore repository ?

If not, this is what may be causing the bug, so try to make sure you're using the same Infinispan cache name in both cases.

[folch]

You are totally right Horia.

I don't know why, but storage/cacheName has been changed. If I don't change cacheName  the issue disapears.

Many thanks

[hchiorean]

Glad the workaround is valid. This is still a bug however, since keeping the repo/cache name is not a requirement.

[folch]

In some environments I still see a NullpointerException like this when I restore an old repository:

[15/12/15 17:41:36:932 CET] 00000094 RepositoryLoc W org.modeshape.common.logging.slf4j.SLF4JLoggerImpl warn The lock with the key "48f1104317f1e7mode:lock-48f11047505d6480004cb6-92d9-4842-8121-0adc5fdadcc3" cannot be found in the system area, although it is being referenced by the locks container. This should not happen and indicates a corruption of the system data.

[15/12/15 17:41:36:933 CET] 00000094 RepositoryLoc E org.modeshape.common.logging.slf4j.SLF4JLoggerImpl error Error while refreshing locks for the "empower.repository" repository

                                 java.lang.NullPointerException

  at org.modeshape.jcr.cache.document.SessionNode.removeChildFromNode(SessionNode.java:1253)

  at org.modeshape.jcr.cache.document.SessionNode.removeChild(SessionNode.java:1220)

  at org.modeshape.jcr.RepositoryLockManager.refreshFromSystem(RepositoryLockManager.java:133)

  at org.modeshape.jcr.JcrRepository$RunningState.<init>(JcrRepository.java:1156)

  at org.modeshape.jcr.JcrRepository$RunningState.<init>(JcrRepository.java:982)

  at org.modeshape.jcr.JcrRepository.doStart(JcrRepository.java:388)

  at org.modeshape.jcr.JcrRepository.start(JcrRepository.java:312)

  at org.modeshape.jcr.JcrRepository.completeRestore(JcrRepository.java:543)

  at org.modeshape.jcr.BackupService.restoreRepository(BackupService.java:161)

  at org.modeshape.jcr.JcrRepositoryManager.restoreRepository(JcrRepositoryManager.java:87)

  at org.modeshape.jcr.JcrRepositoryManager.restoreRepository(JcrRepositoryManager.java:81)

  at com.ibm._jsp._restore.restore(_restore.java:118)

  at com.ibm._jsp._restore._jspService(_restore.java:211)

  at com.ibm.ws.jsp.runtime.HttpJspBase.service(HttpJspBase.java:99)

  at javax.servlet.http.HttpServlet.service(HttpServlet.java:668)

  at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1232)

  at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:781)

  at com.ibm.ws.webcontainer.servlet.ServletWrapper.handleRequest(ServletWrapper.java:480)

  at com.ibm.ws.webcontainer.servlet.ServletWrapperImpl.handleRequest(ServletWrapperImpl.java:178)

  at com.ibm.wsspi.webcontainer.servlet.GenericServletWrapper.handleRequest(GenericServletWrapper.java:122)

  at com.ibm.ws.jsp.webcontainerext.AbstractJSPExtensionServletWrapper.handleRequest(AbstractJSPExtensionServletWrapper.java:220)

  at com.ibm.ws.webcontainer.filter.WebAppFilterChain.invokeTarget(WebAppFilterChain.java:136)

  at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:97)

  at com.hp.exstream.hes.webapp.HeaderFilter.doFilter(HeaderFilter.java:139)

  at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:195)

  at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:91)

  at com.hp.exstream.hes.services.filter.CsrfHeaderFilter.doFilter(CsrfHeaderFilter.java:59)

  at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:195)

  at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:91)

  at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:330)

  at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:118)

  at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:84)

  at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)

  at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:113)

  at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)

  at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:103)

  at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)

  at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:113)

  at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)

  at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:154)

  at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)

  at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:45)

  at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)

  at org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilter(BasicAuthenticationFilter.java:201)

  at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)

  at org.springframework.security.web.csrf.CsrfFilter.doFilterInternal(CsrfFilter.java:85)

  at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:106)

  at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)

  at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:50)

  at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:106)

  at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)

  at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:87)

  at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:342)

  at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:192)

  at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:160)

  at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:343)

  at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:260)

  at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:195)

  at com.ibm.ws.webcontainer.filter.WebAppFilterChain.doFilter(WebAppFilterChain.java:91)

  at com.ibm.ws.webcontainer.filter.WebAppFilterManager.doFilter(WebAppFilterManager.java:967)

  at com.ibm.ws.webcontainer.filter.WebAppFilterManager.invokeFilters(WebAppFilterManager.java:1107)

  at com.ibm.ws.webcontainer.webapp.WebApp.handleRequest(WebApp.java:3926)

  at com.ibm.ws.webcontainer.webapp.WebGroup.handleRequest(WebGroup.java:304)

  at com.ibm.ws.webcontainer.WebContainer.handleRequest(WebContainer.java:1007)

  at com.ibm.ws.webcontainer.WSWebContainer.handleRequest(WSWebContainer.java:1817)

  at com.ibm.ws.webcontainer.channel.WCChannelLink.ready(WCChannelLink.java:200)

  at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleDiscrimination(HttpInboundLink.java:463)

  at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.handleNewRequest(HttpInboundLink.java:530)

  at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.processRequest(HttpInboundLink.java:316)

  at com.ibm.ws.http.channel.inbound.impl.HttpInboundLink.ready(HttpInboundLink.java:287)

  at com.ibm.ws.tcp.channel.impl.NewConnectionInitialReadCallback.sendToDiscriminators(NewConnectionInitialReadCallback.java:214)

  at com.ibm.ws.tcp.channel.impl.NewConnectionInitialReadCallback.complete(NewConnectionInitialReadCallback.java:113)

  at com.ibm.ws.tcp.channel.impl.AioReadCompletionListener.futureCompleted(AioReadCompletionListener.java:175)

  at com.ibm.io.async.AbstractAsyncFuture.invokeCallback(AbstractAsyncFuture.java:217)

  at com.ibm.io.async.AsyncChannelFuture.fireCompletionActions(AsyncChannelFuture.java:161)

  at com.ibm.io.async.AsyncFuture.completed(AsyncFuture.java:138)

  at com.ibm.io.async.ResultHandler.complete(ResultHandler.java:204)

  at com.ibm.io.async.ResultHandler.runEventProcessingLoop(ResultHandler.java:775)

  at com.ibm.io.async.ResultHandler$2.run(ResultHandler.java:905)

  at com.ibm.ws.util.ThreadPool$Worker.run(ThreadPool.java:1881)

In this case, this is not causing a repository failure, the restore ends without problems and it's totally functional. However this NullpointerExceptions appears every time we start the repository.

Can we do something to avoid it? Or can we do something to fix this Lock not found?

[hchiorean]

As the WARN message states, somehow the data that's being restored has corrupted locks. By that I mean the system data where locks are being stored still reports existing locks even though those locks are not present any more.  This should've been handled as part of [MODE-2450] Phantom locks should be removed from the system area on repository startup - JBoss Issue Tracker, but that fix seems to not work entirely, as per your particular case.

There is no way to work around this, but I can look at a better fix for MODE-2450 for 4.6.0.Final.

In general, any system area corruption is considered "a catastrophic error" out of which a repository cannot recover. Ideally we should find the cause of these corruptions on a case-by-case basis, but this may not apply in the case of a backup/restore. If you're restoring a backup of a corrupt repository (due to whatever old bug) then there's not much we can do.

[folch]

Hi Horia,

I agree with you, if the backup is corrupted there's not much to do. However, in this particular case, if we can avoid that we show a warning for missing Locks everytime we start the respository would be fantastic?

thanks

[hchiorean]

The WARN should only have been shown once, after the first restart post backup restore. However, because of the NPE the phantom lock references aren't cleaned up properly causing the message to be displayed each time the repository restarts.

One thing you can actually try is manually editing the backup file to solve the phantom lock:

1. the repository data is backed up in bunch of .gz files, but inside those files should be clear-text JSON data. So first you'd have to extract the .gz files somewhere

2. in the extracted files, search for the problematic keys (which are reported in the WARN message). For example: 48f1104317f1e7mode:lock-48f11047505d6480004cb6-92d9-4842-8121-0adc5fdadcc3. You should be able to locate a JSON object which has a CHILDREN attribute which contains an array of {key,name} pairs of objects. Simply edit the file and remove the {key,name} pair from the array. If the array becomes empty, leave it as such: []

3. repackage the edited file in the original .gz

That way you should be able to manually fix the phantom locks and avoid the error.