Magic number verification failed for page

[rzorzorzo]

OrientDB Version: 3.0.21

Java Version: 1.8.0_144

OS: windows 10

Expected behavior

Actual behavior

Jun 30, 2019 1:29:32 PM com.orientechnologies.common.log.OLogManager log
INFO: Windows OS is detected, 262144 limit of open files will be set for the disk cache.
Jun 30, 2019 1:29:32 PM com.orientechnologies.common.log.OLogManager log
INFO: 17118322688 B/16325 MB/15 GB of physical memory were detected on machine
Jun 30, 2019 1:29:32 PM com.orientechnologies.common.log.OLogManager log
INFO: Detected memory limit for current process is 17118322688 B/16325 MB/15 GB
Jun 30, 2019 1:29:32 PM com.orientechnologies.common.log.OLogManager log
INFO: JVM can use maximum 3628MB of heap memory
Jun 30, 2019 1:29:32 PM com.orientechnologies.common.log.OLogManager log
INFO: Because OrientDB is running outside a container 12% of memory will be left unallocated according to the setting 'memory.leftToOS' not taking into account heap memory
Jun 30, 2019 1:29:32 PM com.orientechnologies.common.log.OLogManager log
INFO: OrientDB auto-config DISKCACHE=10,737MB (heap=3,628MB os=16,325MB)
Jun 30, 2019 1:29:32 PM com.orientechnologies.common.log.OLogManager log
INFO: System is started under an effective user : test
Jun 30, 2019 1:29:32 PM com.orientechnologies.common.log.OLogManager log
INFO: Allocation of 163202 pages.
Jun 30, 2019 1:29:33 PM com.orientechnologies.common.log.OLogManager log
INFO: WAL maximum segment size is set to 6,144 MB
Jun 30, 2019 1:29:33 PM com.orientechnologies.common.log.OLogManager log
INFO: Page size for WAL located in Z:\PortableApps\eclipse-oxygen-2\workspace\orientdbtest.\db\test is set to 4096 bytes.
Jun 30, 2019 1:29:33 PM com.orientechnologies.common.log.OLogManager log
WARNING: Storage 'test' was not closed properly. Will try to recover from write ahead log
Jun 30, 2019 1:29:33 PM com.orientechnologies.common.log.OLogManager log
INFO: Looking for last checkpoint...
Jun 30, 2019 1:29:33 PM com.orientechnologies.common.log.OLogManager log
INFO: Checkpoints are absent, the restore will start from the beginning.
Jun 30, 2019 1:29:33 PM com.orientechnologies.common.log.OLogManager log
INFO: Data restore procedure is started.
Jun 30, 2019 1:29:34 PM com.orientechnologies.common.log.OLogManager log
WARNING: Record com.orientechnologies.orient.core.storage.impl.local.paginated.wal.cas.OEmptyWALRecord{lsn=OLogSequenceNumber{segment=1, position=18}} will be skipped during data restore
Jun 30, 2019 1:29:34 PM com.orientechnologies.common.log.OLogManager log
INFO: 1 operations were processed, current LSN is OLogSequenceNumber{segment=1, position=18} last LSN is OLogSequenceNumber{segment=2, position=18}
Jun 30, 2019 1:29:34 PM com.orientechnologies.common.log.OLogManager log
WARNING: Non tx operation was used during data modification we will need index rebuild.
Jun 30, 2019 1:29:36 PM com.orientechnologies.common.log.OLogManager log
WARNING: Record com.orientechnologies.orient.core.storage.impl.local.paginated.wal.cas.OEmptyWALRecord{lsn=OLogSequenceNumber{segment=2, position=18}} will be skipped during data restore
Jun 30, 2019 1:29:39 PM com.orientechnologies.common.log.OLogManager log
INFO: Storage data recover was completed
Jun 30, 2019 1:29:39 PM com.orientechnologies.common.log.OLogManager log
INFO: Storage 'plocal:Z:\PortableApps\eclipse-oxygen-2\workspace\orientdbtest.\db/test' is opened under OrientDB distribution : 3.0.21 - Veloce (build 1d8b0c0, branch 3.0.x)
Jun 30, 2019 1:29:39 PM com.orientechnologies.common.log.OLogManager log
INFO: $ANSI{green {db=test}} Wait till indexes restore after crash was finished.
Jun 30, 2019 1:29:39 PM com.orientechnologies.common.log.OLogManager log
INFO: $ANSI{green {db=test}} Index 'ORole.name' is a durable automatic index and will be added as is without rebuilding
Jun 30, 2019 1:29:39 PM com.orientechnologies.common.log.OLogManager log
INFO: $ANSI{green {db=test}} Index 'ORole.name' was added in DB index list
Jun 30, 2019 1:29:39 PM com.orientechnologies.common.log.OLogManager log
INFO: $ANSI{green {db=test}} Index 'OUser.name' is a durable automatic index and will be added as is without rebuilding
Jun 30, 2019 1:29:39 PM com.orientechnologies.common.log.OLogManager log
INFO: $ANSI{green {db=test}} Index 'OUser.name' was added in DB index list
Jun 30, 2019 1:29:39 PM com.orientechnologies.common.log.OLogManager log
INFO: $ANSI{green {db=test}} Index 'dictionary' is a durable non-automatic index and will be added as is without rebuilding
Jun 30, 2019 1:29:39 PM com.orientechnologies.common.log.OLogManager log
INFO: $ANSI{green {db=test}} Index 'dictionary' was added in DB index list
Jun 30, 2019 1:29:39 PM com.orientechnologies.common.log.OLogManager log
INFO: $ANSI{green {db=test}} Index 'OFunction.name' is a durable automatic index and will be added as is without rebuilding
Jun 30, 2019 1:29:39 PM com.orientechnologies.common.log.OLogManager log
INFO: $ANSI{green {db=test}} Index 'OFunction.name' was added in DB index list
Jun 30, 2019 1:29:39 PM com.orientechnologies.common.log.OLogManager log
INFO: $ANSI{green {db=test}} 4 indexes were restored successfully, 0 errors
Jun 30, 2019 1:29:39 PM com.orientechnologies.common.log.OLogManager log
INFO: $ANSI{green {db=test}} Indexes restore after crash was finished.
size: 675
Jun 30, 2019 1:29:39 PM com.orientechnologies.common.log.OLogManager log
SEVERE: $ANSI{green {db=test}} Magic number verification failed for page 1425 of pupil.pcl.
Jun 30, 2019 1:29:39 PM com.orientechnologies.common.log.OLogManager log
SEVERE: $ANSI{green {db=test}} Magic number verification failed for page 1425 of pupil.pcl.
java.lang.Exception
at com.orientechnologies.orient.core.storage.cache.local.OWOWCache.dumpStackTrace(OWOWCache.java:2306)
at com.orientechnologies.orient.core.storage.cache.local.OWOWCache.verifyMagicAndChecksum(OWOWCache.java:2264)
at com.orientechnologies.orient.core.storage.cache.local.OWOWCache.loadFileContent(OWOWCache.java:2164)
at com.orientechnologies.orient.core.storage.cache.local.OWOWCache.load(OWOWCache.java:1137)
at com.orientechnologies.orient.core.storage.cache.chm.AsyncReadCache.lambda$doLoad$0(AsyncReadCache.java:150)
at java.util.concurrent.ConcurrentHashMap.compute(ConcurrentHashMap.java:1853)
at com.orientechnologies.orient.core.storage.cache.chm.AsyncReadCache.doLoad(AsyncReadCache.java:147)
at com.orientechnologies.orient.core.storage.cache.chm.AsyncReadCache.loadForRead(AsyncReadCache.java:115)
at com.orientechnologies.orient.core.storage.impl.local.paginated.atomicoperations.OAtomicOperation.loadPageForWrite(OAtomicOperation.java:111)
at com.orientechnologies.orient.core.storage.impl.local.paginated.base.ODurableComponent.loadPageForWrite(ODurableComponent.java:129)
at com.orientechnologies.orient.core.storage.cluster.v1.OPaginatedClusterV1.addEntry(OPaginatedClusterV1.java:1720)
at com.orientechnologies.orient.core.storage.cluster.v1.OPaginatedClusterV1.createRecord(OPaginatedClusterV1.java:502)
at com.orientechnologies.orient.core.storage.impl.local.OAbstractPaginatedStorage.doCreateRecord(OAbstractPaginatedStorage.java:4547)
at com.orientechnologies.orient.core.storage.impl.local.OAbstractPaginatedStorage.commitEntry(OAbstractPaginatedStorage.java:5133)
at com.orientechnologies.orient.core.storage.impl.local.OAbstractPaginatedStorage.commit(OAbstractPaginatedStorage.java:2161)
at com.orientechnologies.orient.core.storage.impl.local.OAbstractPaginatedStorage.commit(OAbstractPaginatedStorage.java:1993)
at com.orientechnologies.orient.core.db.document.ODatabaseDocumentAbstract.internalCommit(ODatabaseDocumentAbstract.java:2732)
at com.orientechnologies.orient.core.storage.impl.local.OMicroTransaction.doCommit(OMicroTransaction.java:363)
at com.orientechnologies.orient.core.storage.impl.local.OMicroTransaction.commit(OMicroTransaction.java:166)
at com.orientechnologies.orient.core.db.document.ODatabaseDocumentEmbedded.endMicroTransaction(ODatabaseDocumentEmbedded.java:799)
at com.orientechnologies.orient.core.db.document.ODatabaseDocumentEmbedded.executeSaveRecord(ODatabaseDocumentEmbedded.java:789)
at com.orientechnologies.orient.core.tx.OTransactionNoTx.saveNew(OTransactionNoTx.java:244)
at com.orientechnologies.orient.core.tx.OTransactionNoTx.saveRecord(OTransactionNoTx.java:174)
at com.orientechnologies.orient.core.db.document.ODatabaseDocumentAbstract.saveInternal(ODatabaseDocumentAbstract.java:2099)
at com.orientechnologies.orient.core.db.document.ODatabaseDocumentAbstract.save(ODatabaseDocumentAbstract.java:2064)
at com.orientechnologies.orient.core.db.document.ODatabaseDocumentAbstract.save(ODatabaseDocumentAbstract.java:85)
at com.orientechnologies.orient.core.record.impl.ODocument.save(ODocument.java:2169)
at com.orientechnologies.orient.core.record.impl.ODocument.save(ODocument.java:2160)
at com.orientechnologies.orient.core.record.impl.ODocument.save(ODocument.java:118)
at test.Test.main(Test.java:34)

Steps to reproduce

public static void main(String[] args)
{
try (OrientDB odb = new OrientDB("embedded:./db", OrientDBConfig.defaultConfig()))
{
odb.createIfNotExists("test", ODatabaseType.PLOCAL);
ODatabaseSession db = odb.open("test", "admin", "admin");
db.getMetadata().getSchema().getOrCreateClass("pupil");
long size = db.countClass("pupil");
System.out.println("size: "+size);
long t = System.currentTimeMillis();
db.declareIntent(new OIntentMassiveInsert());
for (int i=0; i<1000000; i++)
{
OElement doc = db.newElement("pupil");
doc.setProperty("id",size+i);
doc.setProperty("json", randomString());
doc.save();
if (i % 100 == 0)
{
System.out.println(System.currentTimeMillis()-t);
t = System.currentTimeMillis();
db.commit();
}
}
}

}

force stop the JVM while the program is running.
then restart

[rzorzorzo]

PS: adding: java option -Dstorage.useWAL=false does not help.

[rzorzorzo]

PS: conf.getConfigurations().setValue(OGlobalConfiguration.USE_WAL, false);
neither

[andrii0lomakin]

Hi, I see that check points are absent in WAL did you run load with WAL disabled ? If so please enable WAL and run again. WAL is used to restore database after crash it should not be disabled.

[rzorzorzo]

Hi, WAL is on:

public static void main(String[] args)
{
OrientDBConfig conf = OrientDBConfig.defaultConfig();
conf.getConfigurations().setValue(OGlobalConfiguration.USE_WAL, true);
try (OrientDB odb = new OrientDB("embedded:./db", conf))
{
odb.createIfNotExists("test", ODatabaseType.PLOCAL);
ODatabaseSession db = odb.open("test", "admin", "admin");
if (!db.getMetadata().getSchema().existsClass("pupil"))
{
OClass c = db.getMetadata().getSchema().createClass("pupil");
c.createProperty("id", OType.LONG);
c.createIndex("idx_pupil_id", OClass.INDEX_TYPE.UNIQUE, "id");
}
long size = db.countClass("pupil");
System.out.println("size: "+size);
long t = System.currentTimeMillis();
db.declareIntent(new OIntentMassiveInsert());
for (int i=0; i<1000000; i++)
{
OElement doc = db.newElement("pupil");
doc.setProperty("id",size+i);
doc.setProperty("json", randomString());
doc.save();
if (i % 100 == 0)
{
System.out.println(System.currentTimeMillis()-t);
t = System.currentTimeMillis();
db.commit();
}
}
}

}

INFO: $ANSI{green {db=test}} 5 indexes were restored successfully, 0 errors
Jun 30, 2019 7:56:55 PM com.orientechnologies.common.log.OLogManager log
INFO: $ANSI{green {db=test}} Indexes restore after crash was finished.
size: 208
Jun 30, 2019 7:56:56 PM com.orientechnologies.common.log.OLogManager log
SEVERE: $ANSI{green {db=test}} Magic number verification failed for page 453 of pupil.pcl.
Jun 30, 2019 7:56:56 PM com.orientechnologies.common.log.OLogManager log
SEVERE: $ANSI{green {db=test}} Magic number verification failed for page 453 of pupil.pcl.
java.lang.Exception
at com.orientechnologies.orient.core.storage.cache.local.OWOWCache.dumpStackTrace(OWOWCache.java:2306)
at com.orientechnologies.orient.core.storage.cache.local.OWOWCache.verifyMagicAndChecksum(OWOWCache.java:2264)
at com.orientechnologies.orient.core.storage.cache.local.OWOWCache.loadFileContent(OWOWCache.java:2164)
at com.orientechnologies.orient.core.storage.cache.local.OWOWCache.load(OWOWCache.java:1137)
at com.orientechnologies.orient.core.storage.cache.chm.AsyncReadCache.lambda$doLoad$0(AsyncReadCache.java:150)

[andrii0lomakin]

I see I will try to reproduce that, if that will not be possible on my side, I will ask for the broken database.

[andrii0lomakin]

Reproduced and fixed, tried several times and all is OK on my side. I will push in an hour. Will you able to build code from the branch or I need to provide you new build?

[andrii0lomakin]

Hi, @rzorzorzo do I need to provide you a special distribution to test this issue?

[rzorzorzo]

hello,
i will try to build it. i hope i will have time for this on the weekend.

[rzorzorzo]

tested with maven build 3.1.0-M3. all OK.

[andrii0lomakin]

Cool thank you. We release 3.0.22 in a couple of days.