Issue with database after reboot

[Paul Jongsma]

Context:

Ubuntu 14.04 VM with Neo4J 3.2.2 

Has been running 200+ days; today the sever was rebooted for maintenance.

Ever since the Neo4J won't start; when trying to run is in console mode it takes a long time and eventually this is generated:

Starting Neo4j Server console-mode...

2017-08-25 15:47:04.985+0200 INFO  Successfully shutdown Neo4j Server

2017-08-25 15:47:04.987+0200 ERROR Failed to start Neo4j: Starting Neo4j failed: Failed to transition component 'org.neo4j.kernel.impl.pagecache.PageCacheLifecycle@283b3841' from STOPPED to SHUTTING_DOWN. Please see attached cause exception Starting Neo4j failed: Failed to transition component 'org.neo4j.kernel.impl.pagecache.PageCacheLifecycle@283b3841' from STOPPED to SHUTTING_DOWN. Please see attached cause exception

org.neo4j.server.ServerStartupException: Starting Neo4j failed: Failed to transition component 'org.neo4j.kernel.impl.pagecache.PageCacheLifecycle@283b3841' from STOPPED to SHUTTING_DOWN. Please see attached cause exception

at org.neo4j.server.exception.ServerStartupErrors.translateToServerStartupError(ServerStartupErrors.java:67)

at org.neo4j.server.AbstractNeoServer.start(AbstractNeoServer.java:235)

at org.neo4j.server.Bootstrapper.start(Bootstrapper.java:97)

at org.neo4j.server.CommunityBootstrapper.start(CommunityBootstrapper.java:48)

at org.neo4j.server.CommunityBootstrapper.main(CommunityBootstrapper.java:35)

Caused by: org.neo4j.kernel.lifecycle.LifecycleException: Failed to transition component 'org.neo4j.kernel.impl.pagecache.PageCacheLifecycle@283b3841' from STOPPED to SHUTTING_DOWN. Please see attached cause exception

at org.neo4j.kernel.lifecycle.LifeSupport$LifecycleInstance.shutdown(LifeSupport.java:515)

at org.neo4j.kernel.lifecycle.LifeSupport.shutdown(LifeSupport.java:203)

at org.neo4j.kernel.impl.factory.GraphDatabaseFacade.shutdown(GraphDatabaseFacade.java:285)

at org.neo4j.kernel.impl.factory.GraphDatabaseFacadeFactory.newFacade(GraphDatabaseFacadeFactory.java:152)

at org.neo4j.kernel.impl.factory.CommunityFacadeFactory.newFacade(CommunityFacadeFactory.java:43)

at org.neo4j.kernel.impl.factory.GraphDatabaseFacadeFactory.newFacade(GraphDatabaseFacadeFactory.java:108)

at org.neo4j.server.CommunityNeoServer$1.newGraphDatabase(CommunityNeoServer.java:66)

at org.neo4j.server.database.LifecycleManagingDatabase.start(LifecycleManagingDatabase.java:95)

at org.neo4j.kernel.lifecycle.LifeSupport$LifecycleInstance.start(LifeSupport.java:452)

at org.neo4j.kernel.lifecycle.LifeSupport.start(LifeSupport.java:111)

at org.neo4j.server.AbstractNeoServer.start(AbstractNeoServer.java:195)

... 3 more

Suppressed: java.lang.RuntimeException: Error starting org.neo4j.kernel.impl.factory.CommunityFacadeFactory, /var/lib/neo4j/data/graph.db

at org.neo4j.kernel.impl.factory.GraphDatabaseFacadeFactory.newFacade(GraphDatabaseFacadeFactory.java:143)

... 10 more

Caused by: org.neo4j.kernel.lifecycle.LifecycleException: Component 'org.neo4j.kernel.recovery.Recovery@3a37f56a' failed to initialize. Please see attached cause exception.

at org.neo4j.kernel.lifecycle.LifeSupport$LifecycleInstance.init(LifeSupport.java:434)

at org.neo4j.kernel.lifecycle.LifeSupport.init(LifeSupport.java:66)

at org.neo4j.kernel.lifecycle.LifeSupport.start(LifeSupport.java:102)

at org.neo4j.kernel.NeoStoreDataSource.start(NeoStoreDataSource.java:600)

at org.neo4j.kernel.lifecycle.LifeSupport$LifecycleInstance.start(LifeSupport.java:452)

at org.neo4j.kernel.lifecycle.LifeSupport.start(LifeSupport.java:111)

at org.neo4j.kernel.impl.transaction.state.DataSourceManager.start(DataSourceManager.java:112)

at org.neo4j.kernel.lifecycle.LifeSupport$LifecycleInstance.start(LifeSupport.java:452)

at org.neo4j.kernel.lifecycle.LifeSupport.start(LifeSupport.java:111)

at org.neo4j.kernel.impl.factory.GraphDatabaseFacadeFactory.newFacade(GraphDatabaseFacadeFactory.java:139)

... 10 more

Caused by: java.lang.NegativeArraySizeException

at org.neo4j.kernel.impl.transaction.command.PhysicalLogCommandReaderV2_2_4.readDynamicRecord(PhysicalLogCommandReaderV2_2_4.java:450)

at org.neo4j.kernel.impl.transaction.command.PhysicalLogCommandReaderV2_2_4.readDynamicRecords(PhysicalLogCommandReaderV2_2_4.java:463)

at org.neo4j.kernel.impl.transaction.command.PhysicalLogCommandReaderV2_2_4.readPropertyBlock(PhysicalLogCommandReaderV2_2_4.java:564)

at org.neo4j.kernel.impl.transaction.command.PhysicalLogCommandReaderV2_2_4.readPropertyRecord(PhysicalLogCommandReaderV2_2_4.java:511)

at org.neo4j.kernel.impl.transaction.command.PhysicalLogCommandReaderV2_2_4.visitPropertyCommand(PhysicalLogCommandReaderV2_2_4.java:230)

at org.neo4j.kernel.impl.transaction.command.Command$PropertyCommand.handle(Command.java:288)

at org.neo4j.kernel.impl.transaction.command.PhysicalLogCommandReaderV2_2_4.read(PhysicalLogCommandReaderV2_2_4.java:85)

at org.neo4j.kernel.impl.transaction.log.entry.LogEntryParsersV2_3$3.parse(LogEntryParsersV2_3.java:94)

at org.neo4j.kernel.impl.transaction.log.entry.VersionAwareLogEntryReader.readLogEntry(VersionAwareLogEntryReader.java:107)

at org.neo4j.kernel.impl.transaction.log.LogEntryCursor.next(LogEntryCursor.java:54)

at org.neo4j.kernel.recovery.LatestCheckPointFinder.find(LatestCheckPointFinder.java:77)

at org.neo4j.kernel.recovery.PositionToRecoverFrom.apply(PositionToRecoverFrom.java:53)

at org.neo4j.kernel.recovery.DefaultRecoverySPI.getPositionToRecoverFrom(DefaultRecoverySPI.java:135)

at org.neo4j.kernel.recovery.Recovery.init(Recovery.java:72)

at org.neo4j.kernel.lifecycle.LifeSupport$LifecycleInstance.init(LifeSupport.java:424)

... 19 more

Caused by: java.lang.IllegalStateException: Cannot close the PageCache while files are still mapped:

neostore (1 mapping)

neostore.counts.db.b (1 mapping)

at org.neo4j.io.pagecache.impl.muninn.MuninnPageCache.close(MuninnPageCache.java:521)

at org.neo4j.kernel.impl.pagecache.PageCacheLifecycle.shutdown(PageCacheLifecycle.java:42)

at org.neo4j.kernel.lifecycle.LifeSupport$LifecycleInstance.shutdown(LifeSupport.java:507)

... 13 more

File permissions are fine; disk was low on space earlier but not anymore.

What can I do to resolve this issue? 

Transferred it to an more up to date 2.3.7 installation but it has the same issues. 

Even worse; older backups of the same database also have this issue.

Any suggestion welcome..

Best regards

Paul

[Rik Van Bruggen]

Apparently this is usually due to incorrect file permissions:

https://neo4j.com/developer/kb/how-to-fix-cannot-close-the-pagecache-while-files-are-still-mapped/

Rik

[Paul Jongsma]

Hi Rik, 

After finding out that the database would not start that was one of the first things I checked.

But the permissions were ok, apparently the datafiles were in a state which caused the same error for a different reason.

Luckily the data is back; with the indispensable help of Michael who intensively assisted me via Slack I bootstrapped his copy-store utility and while working on that we found that removing both the tx logs, neostore.transaction.db.* and some count files in graph.db/neostore.count.db* was enough to get the database started again.

It was an intense day, especially when I found that earlier backups had issues too for quite a while it looked like we lost months of data..

But all is well, I just checked the backup made last night and that is fine; it also passes the manual consistency checks..

Thank you and Michael for all the help!

Best regards

Paul