Neo4j backup if failing

[shweta]

Hi,

This is a very critical issue for us.

We have an external centos machine which takes the an online backup for our 3.5 neo4j production.

It has recently started failing without any changes or upgrade.

It fails after this step. (Start recovering store)

2019-09-12 17:05:21.404+0000 INFO Start receiving transactions from 2678098281
2019-09-12 17:11:51.361+0000 INFO Finish receiving transactions at 2678098281
2019-09-12 17:12:32.189+0000 INFO  Start recovering store
09.14.2019 11:10:53 ERROR: Backup failed - aborting
09.14.2019 11:10:53 ERROR: Neo4j Backup Failed

Failure message is :

unexpected error: Error starting org.neo4j.com.storecopy.ExternallyManagedPageCache$GraphDatabaseFactoryWithPageCacheFactory$1, /backup/data/graph.db-backup/temp-copy
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100  194k    0     0  100  194k      0   139k  0:00:01  0:00:01 --:--:--  139k

Can you help us understand what " (Start recovering store) " step does? Also How can we go about fixing this?

We essentially run $NEO4J_ADMIN_PATH backup --from=$NEO4J_DB --backup-dir=$BACKUP_DIR --name=$BACKUP_NAME --fallback-to-full=true --check-consistency=false --pagecache=4G >> $LOG_PATH to start our backup.

Thanks

[michael.hunger]

If you have a customer contract you can raise this as a zendesk ticket.

Can you share more details from debug.log from both locations (server + backup)

[shweta]

These are logs from the server ->

 INFO [o.n.b.i.BackupImpl] BackupServer:6362-31: Full backup started...
 INFO [o.n.b.i.BackupImpl] BackupServer:6362-27: Full backup finished.

These are the logs from the backup ->

09.12.2019 00:00:56 INFO: Starting backup
2019-09-11 16:01:02.398+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store files
2019-09-11 16:03:07.836+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/neostore.nodestore.db.labels
2019-09-11 16:03:08.523+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/neostore.nodestore.db.labels
2019-09-11 16:03:08.554+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/neostore.nodestore.db
2019-09-11 16:16:38.756+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/neostore.nodestore.db
2019-09-11 16:16:38.756+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/neostore.propertystore.db.index.keys
2019-09-11 16:16:39.050+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/neostore.propertystore.db.index.keys
2019-09-11 16:16:39.051+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/neostore.propertystore.db.index
2019-09-11 16:16:39.114+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/neostore.propertystore.db.index
2019-09-11 16:16:39.114+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/neostore.propertystore.db.strings
2019-09-12 00:33:34.588+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/neostore.propertystore.db.strings
2019-09-12 00:33:34.589+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/neostore.propertystore.db.arrays
2019-09-12 07:38:14.904+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/neostore.propertystore.db.arrays
2019-09-12 07:38:14.905+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/neostore.propertystore.db
2019-09-12 14:15:45.555+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/neostore.propertystore.db
2019-09-12 14:15:45.557+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/neostore.relationshipstore.db
.....
2019-09-12 17:04:55.675+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/122/string-1.0/profiles/index-122.609987.cacheprof
2019-09-12 17:04:55.676+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/115/temporal-1.0/profiles/date.609987.cacheprof
2019-09-12 17:04:55.676+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/115/temporal-1.0/profiles/date.609987.cacheprof
2019-09-12 17:04:55.676+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/115/spatial-1.0/profiles/1-4326.609987.cacheprof
2019-09-12 17:04:55.677+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/115/spatial-1.0/profiles/1-4326.609987.cacheprof
2019-09-12 17:04:55.677+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/115/native-1.0/profiles/index-115.609987.cacheprof
2019-09-12 17:04:55.677+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/115/native-1.0/profiles/index-115.609987.cacheprof
2019-09-12 17:04:55.678+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/115/string-1.0/profiles/index-115.609987.cacheprof
2019-09-12 17:04:55.678+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/115/string-1.0/profiles/index-115.609987.cacheprof
2019-09-12 17:04:55.678+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/108/temporal-1.0/profiles/date.609987.cacheprof
2019-09-12 17:04:55.678+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/108/temporal-1.0/profiles/date.609987.cacheprof
2019-09-12 17:04:55.679+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/108/spatial-1.0/profiles/1-4326.609987.cacheprof
2019-09-12 17:04:55.680+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/108/spatial-1.0/profiles/1-4326.609987.cacheprof
2019-09-12 17:04:55.680+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/108/native-1.0/profiles/index-108.609987.cacheprof
2019-09-12 17:04:55.681+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/108/native-1.0/profiles/index-108.609987.cacheprof
2019-09-12 17:04:55.681+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/108/string-1.0/profiles/index-108.609987.cacheprof
2019-09-12 17:04:55.682+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/108/string-1.0/profiles/index-108.609987.cacheprof
2019-09-12 17:04:55.683+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/101/temporal-1.0/profiles/date.609987.cacheprof
2019-09-12 17:04:55.683+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/101/temporal-1.0/profiles/date.609987.cacheprof
2019-09-12 17:04:55.684+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/101/spatial-1.0/profiles/1-4326.609987.cacheprof
2019-09-12 17:04:55.684+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/101/spatial-1.0/profiles/1-4326.609987.cacheprof
2019-09-12 17:04:55.685+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/101/native-1.0/profiles/index-101.609987.cacheprof
2019-09-12 17:04:55.685+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/101/native-1.0/profiles/index-101.609987.cacheprof
2019-09-12 17:04:55.686+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/101/string-1.0/profiles/index-101.609987.cacheprof
2019-09-12 17:04:55.686+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/101/string-1.0/profiles/index-101.609987.cacheprof
2019-09-12 17:04:55.686+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/99/temporal-1.0/profiles/date.609992.cacheprof
2019-09-12 17:04:55.687+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/99/temporal-1.0/profiles/date.609992.cacheprof
2019-09-12 17:04:55.688+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/99/spatial-1.0/profiles/1-4326.609992.cacheprof
2019-09-12 17:04:55.689+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/99/spatial-1.0/profiles/1-4326.609992.cacheprof
2019-09-12 17:04:55.689+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/99/native-1.0/profiles/index-99.609992.cacheprof
2019-09-12 17:04:55.690+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/99/native-1.0/profiles/index-99.609992.cacheprof
2019-09-12 17:04:55.690+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/99/string-1.0/profiles/index-99.609992.cacheprof
2019-09-12 17:04:55.691+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/schema/index/lucene_native-2.0/99/string-1.0/profiles/index-99.609992.cacheprof
2019-09-12 17:04:55.691+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving store file /backup/data/graph.db-backup/temp-copy/neostore
2019-09-12 17:04:55.691+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store file /backup/data/graph.db-backup/temp-copy/neostore
2019-09-12 17:04:55.700+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving store files
2019-09-12 17:05:21.404+0000 INFO [o.n.b.i.BackupOutputMonitor] Start receiving transactions from 2678098281
2019-09-12 17:11:51.361+0000 INFO [o.n.b.i.BackupOutputMonitor] Finish receiving transactions at 2678098281
2019-09-12 17:12:32.189+0000 INFO [o.n.b.i.BackupOutputMonitor] Start recovering store
09.14.2019 11:10:53 ERROR: Backup failed - aborting
09.14.2019 11:10:53 ERROR: Neo4j Backup Failed

[shweta]

Any update on this?

This is very critical for us.

[shweta]

i see other people reporting a similar issue.

Backup Error

Any updates on this?

[michael.hunger]

Raise a new github issue

[deemeetree]

Yes, I have the same problem: impossible to do the remote backups. Same error. Has this been addressed? I raised it also in Can't backup remote database using Neo4J - #9 by deemeetree