Failed to read DB file while online backup is running

Hi,

it happened already few times (seemingly randomly), that some db operation (read and also write) failed with an exception during an online backup of the same DB file was running and was close to finish its task.

The version of ObjectDB I am running is 2.6.1.b02

Any idea what is causing this and how to avoid it ?

Stacktrace 1:

pos = 2925893632
length = 2048
Caused by: com.objectdb.o._JdoUserException: Failed to read from file '/path_to_db/dbFile.odb'
NestedThrowables:
java.io.IOException: Stream Closed
at com.objectdb.o.JDE.g(JDE.java:126)
at com.objectdb.o.ERR.f(ERR.java:56)
at com.objectdb.o.JDE.f(JDE.java:52)
at com.objectdb.o.OBC.onObjectDBError(OBC.java:1503)
at com.objectdb.jpa.EMImpl.commit(EMImpl.java:302)
... 9 more
Caused by: java.io.IOException: Stream Closed
at java.io.RandomAccessFile.seek0(Native Method)
at java.io.RandomAccessFile.seek(RandomAccessFile.java:540)
at com.objectdb.o.LFL.X(LFL.java:1157)
at com.objectdb.o.LFL.U(LFL.java:1074)
at com.objectdb.o.PAG.an(PAG.java:842)
at com.objectdb.o.PGC.w(PGC.java:238)
at com.objectdb.o.SNP.F(SNP.java:421)
at com.objectdb.o.SSS.U(SSS.java:399)
at com.objectdb.o.UPT.l(UPT.java:109)
at com.objectdb.o.TSK.i(TSK.java:145)
at com.objectdb.o.TSK.f(TSK.java:95)
at com.objectdb.o.UPT.s(UPT.java:157)
at com.objectdb.o.PGT.q(PGT.java:109)
at com.objectdb.o.UPT.C(UPT.java:121)
at com.objectdb.o.UPT.l(UPT.java:110)
at com.objectdb.o.TSK.i(TSK.java:145)
at com.objectdb.o.TSK.f(TSK.java:95)
at com.objectdb.o.UPT.s(UPT.java:157)
at com.objectdb.o.PGT.q(PGT.java:109)
at com.objectdb.o.UPT.C(UPT.java:121)
at com.objectdb.o.UPT.l(UPT.java:110)
at com.objectdb.o.TSK.i(TSK.java:145)
at com.objectdb.o.TSK.f(TSK.java:95)
at com.objectdb.o.UPT.s(UPT.java:157)
at com.objectdb.o.PGT.q(PGT.java:109)
at com.objectdb.o.UPT.C(UPT.java:121)
at com.objectdb.o.URT.l(URT.java:171)
at com.objectdb.o.TSK.i(TSK.java:145)
at com.objectdb.o.TSK.f(TSK.java:95)
at com.objectdb.o.TSM.e(TSM.java:86)
at com.objectdb.o.UTT.A(UTT.java:365)
at com.objectdb.o.UTT.l(UTT.java:203)
at com.objectdb.o.TSK.i(TSK.java:145)
at com.objectdb.o.TSK.f(TSK.java:95)
at com.objectdb.o.TSM.e(TSM.java:86)
at com.objectdb.o.MST.Vh(MST.java:1374)
at com.objectdb.o.WRA.Vh(WRA.java:396)
at com.objectdb.o.WSM.Vh(WSM.java:184)
at com.objectdb.o.OBM.bQ(OBM.java:939)
at com.objectdb.o.OBM.bO(OBM.java:842)
at com.objectdb.o.OBM.bM(OBM.java:742)
at com.objectdb.jpa.EMImpl.commit(EMImpl.java:299)
... 9 more

Stacktrace 2:

pos = 3003074560
length = 2048
Caused by: com.objectdb.o._JdoUserException: Failed to read from file '/path_to_db/dbFile.odb'
NestedThrowables:
java.lang.NullPointerException
at com.objectdb.o.JDE.g(JDE.java:126)
at com.objectdb.o.ERR.f(ERR.java:56)
at com.objectdb.o.JDE.f(JDE.java:52)
at com.objectdb.o.OBC.onObjectDBError(OBC.java:1503)
at com.objectdb.jdo.PMImpl.getObjectById(PMImpl.java:465)
... 9 more
Caused by: java.lang.NullPointerException
at com.objectdb.o.LFL.X(LFL.java:1157)
at com.objectdb.o.LFL.U(LFL.java:1074)
at com.objectdb.o.PAG.an(PAG.java:842)
at com.objectdb.o.PGC.w(PGC.java:238)
at com.objectdb.o.SNP.F(SNP.java:421)
at com.objectdb.o.RTT.l(RTT.java:127)
at com.objectdb.o.RRT.l(RRT.java:32)
at com.objectdb.o.RTT.D(RTT.java:179)
at com.objectdb.o.RRT.B(RRT.java:125)
at com.objectdb.o.RTT.l(RTT.java:132)
at com.objectdb.o.RRT.l(RRT.java:32)
at com.objectdb.o.RTT.D(RTT.java:179)
at com.objectdb.o.RRT.B(RRT.java:125)
at com.objectdb.o.RTT.l(RTT.java:132)
at com.objectdb.o.RRT.l(RRT.java:32)
at com.objectdb.o.TSK.i(TSK.java:145)
at com.objectdb.o.TSK.f(TSK.java:95)
at com.objectdb.o.TSM.e(TSM.java:86)
at com.objectdb.o.RTT.D(RTT.java:177)
at com.objectdb.o.RRT.B(RRT.java:125)
at com.objectdb.o.RTT.l(RTT.java:132)
at com.objectdb.o.RRT.l(RRT.java:32)
at com.objectdb.o.TSK.i(TSK.java:145)
at com.objectdb.o.TSK.f(TSK.java:95)
at com.objectdb.o.MST.aZ(MST.java:688)
at com.objectdb.o.MST.aW(MST.java:469)
at com.objectdb.o.MST.U8(MST.java:435)
at com.objectdb.o.WRA.U8(WRA.java:266)
at com.objectdb.o.LDR.F(LDR.java:536)
at com.objectdb.o.LDR.E(LDR.java:470)
at com.objectdb.o.LDR.z(LDR.java:269)
at com.objectdb.o.OBC.aP(OBC.java:1058)
at com.objectdb.o.OBC.aN(OBC.java:976)
at com.objectdb.o.OBC.aH(OBC.java:694)
at com.objectdb.jdo.PMImpl.getObjectById(PMImpl.java:449)
... 9 more

Thank you for this report. We found something that may cause this issue, and build 2.6.2_05 should fix it. If you get these errors again with build 2.6.2_05 (or above) please report again.

thx, I will be observing it with the new version.

Unfortunately the "Failed to read from file '/path_to_db/dbFile.odb'" error is happening again, although with different stacktrace (no inner exception is shown) and it is not related anymore to running of online backups. Maybe some new bug was added to the code with the previous fix.

Stacktrace 1:

pos = 4107765760
length = 2048
Failed to read from file '/path_to_db/dbFile.odb'
    com.objectdb.o.JDE.g(JDE.java:126)
    com.objectdb.o.ERR.f(ERR.java:56)
    com.objectdb.o.JDE.f(JDE.java:52)
    com.objectdb.o.OBC.onObjectDBError(OBC.java:1503)
    com.objectdb.o.RSL.get(RSL.java:176)
    java.util.AbstractList$Itr.next(AbstractList.java:358)
    com.objectdb.o.RSL$s.next(RSL.java:235)

Stacktrace 2:

pos = 3439349760
length = 2048
Failed to read from file '/path_to_db/dbFile.odb'
    com.objectdb.o.JDE.g(JDE.java:126)
    com.objectdb.o.ERR.f(ERR.java:56)
    com.objectdb.o.JDE.f(JDE.java:52)
    com.objectdb.jdo.JdoQuery.onObjectDBError(JdoQuery.java:1115)
    com.objectdb.jdo.JdoQuery.execute0(JdoQuery.java:873)
    com.objectdb.jdo.JdoQuery.execute(JdoQuery.java:748)

Build 2.6.2_05 changed only online backup code, but possibly other changes in previous recent builds could cause this. Is it a new exception? Can you check build 2.6.2 and 2.6.1 to find the last build in which this doesn't happen?

The new stack traces seem partial. Could you please check for more details in the log?

You are right I just found the full stack traces in the odb log file rather than the normal application log:

Stacktrace 1:

[2015-06-11 13:12:41 #4 *]
java.lang.NullPointerException
at com.objectdb.o.LFL.X(LFL.java:1157)
at com.objectdb.o.LFL.U(LFL.java:1074)
at com.objectdb.o.PAG.au(PAG.java:906)
at com.objectdb.o.PGC.A(PGC.java:265)
at com.objectdb.o.SNP.G(SNP.java:436)
at com.objectdb.o.MST.aX(MST.java:510)
at com.objectdb.o.MST.aW(MST.java:471)
at com.objectdb.o.MST.U8(MST.java:442)
at com.objectdb.o.WRA.U8(WRA.java:266)
at com.objectdb.o.LDR.F(LDR.java:536)
at com.objectdb.o.LDR.E(LDR.java:470)
at com.objectdb.o.OBC.UO(OBC.java:1080)
at com.objectdb.o.RSL.r(RSL.java:321)
at com.objectdb.o.RSL.get(RSL.java:169)
at java.util.AbstractList$Itr.next(AbstractList.java:358)
at com.objectdb.o.RSL$s.next(RSL.java:235)

Stacktrace 2:

[2015-06-11 13:14:21 #5 *]
java.lang.NullPointerException
at com.objectdb.o.LFL.X(LFL.java:1157)
at com.objectdb.o.LFL.U(LFL.java:1074)
at com.objectdb.o.PAG.au(PAG.java:906)
at com.objectdb.o.PGC.A(PGC.java:265)
at com.objectdb.o.SNP.G(SNP.java:436)
at com.objectdb.o.OBI.v(OBI.java:444)
at com.objectdb.o.OBI.<init>(OBI.java:199)
at com.objectdb.o.SBI.<init>(SBI.java:50)
at com.objectdb.o.MST.a1(MST.java:823)
at com.objectdb.o.BQI.Uu(BQI.java:128)
at com.objectdb.o.PLN.U9(PLN.java:488)
at com.objectdb.o.TAI.A(TAI.java:201)
at com.objectdb.o.TAI.Uu(TAI.java:134)
at com.objectdb.o.TQI.Uu(TQI.java:54)
at com.objectdb.o.PRG.ag(PRG.java:685)
at com.objectdb.o.PRG.af(PRG.java:553)
at com.objectdb.o.QRM.Vb(QRM.java:286)
at com.objectdb.o.MST.Vb(MST.java:988)
at com.objectdb.o.WRA.Vb(WRA.java:311)
at com.objectdb.o.WSM.Vb(WSM.java:115)
at com.objectdb.o.QRR.g(QRR.java:247)
at com.objectdb.o.QRR.f(QRR.java:153)
at com.objectdb.jdo.JdoQuery.execute0(JdoQuery.java:844)
at com.objectdb.jdo.JdoQuery.execute(JdoQuery.java:748)

These stack traces indicate accessing ObjectDB database after its file was closed.

More details will be needed in order to explore this issue, including range of affected ObjectDB versions.

I finally got back to investigating this issue, so here are my results:

- up to the version 2.6.2_04 the mistake is happening only when the DB read/write happens during the online backup (as described in the first post)

- from version 2.6.2_05 and above the mistake is happening not only during the online backup is running, but even after the online backup is finished and some next DB readings are coming

One important point to note is that the same operations, which end up with mistake after the online DB backup was running (at least once), are executing without mistake from starting of the application up to the first online backup. So I assume the online backup is making some change which then causes the issue.

I paste again the latest stacktrace I got with version 2.6.2_05

java.lang.NullPointerException
at com.objectdb.o.LFL.X(LFL.java:1157)
at com.objectdb.o.LFL.U(LFL.java:1074)
at com.objectdb.o.PAG.au(PAG.java:906)
at com.objectdb.o.PGC.A(PGC.java:265)
at com.objectdb.o.SNP.G(SNP.java:436)
at com.objectdb.o.OBI.<init>(OBI.java:169)
at com.objectdb.o.SBI.<init>(SBI.java:50)
at com.objectdb.o.MST.a1(MST.java:823)
at com.objectdb.o.BQI.Uu(BQI.java:128)
at com.objectdb.o.PRG.ag(PRG.java:685)
at com.objectdb.o.PRG.af(PRG.java:553)
at com.objectdb.o.QRM.Vb(QRM.java:286)
at com.objectdb.o.MST.Vb(MST.java:988)
at com.objectdb.o.WRA.Vb(WRA.java:311)
at com.objectdb.o.WSM.Vb(WSM.java:115)
at com.objectdb.o.QRR.g(QRR.java:247)
at com.objectdb.o.QRR.f(QRR.java:153)
at com.objectdb.jdo.JdoQuery.execute0(JdoQuery.java:844)
at com.objectdb.jdo.JdoQuery.execute(JdoQuery.java:748)

I also paste my code for the online backuping which I launch automatically every few hours. I have a suspicion that something can be wrong in my code, because I am using in the whole application the JDO access (with PersistenceManagerFactory), but for the online backup I use JPA (hence I found in the manual the only example of launching the online backup through JPA). Therefore I have there also an instance of EntitiManagerFactory which I never close. I close only the EntityManager instance on every launch of the online backup.

Here is the class for the online backup task:

public class BackupDatabaseTask extends UpdateTask {

private static final long INTERVAL_TO_KEEP_BACKUPS = 2*60*60*1000l;

public void performTask(Date date) {
  long wholestart = D.profile("Starting BackupDatabaseTask", null);
   
  backupJDODatabase(ChatServerImpl.getInstance().getChatDB());
  backupJDODatabase(QuantServerImpl.getInstance().getCompanyDB());
  backupStoreImages(QuantServerImpl.getInstance().getCompanyDB());
 
  // delete all the backups in the backup dir which are older than 2 hours
  File backupDirToTrim = QuantServerImpl.getInstance().getCompanyDB().getBackupDirectory();
  if(backupDirToTrim.exists() && backupDirToTrim.isDirectory() && backupDirToTrim.canWrite()) {
   for (File subdir : backupDirToTrim.listFiles()) {
    if(subdir.isDirectory() && (date.getTime() - subdir.lastModified() > INTERVAL_TO_KEEP_BACKUPS)) {
     Files.deleteDirectoryRecursively(subdir);
    }
   }
  } else {
   D.error("DB Backup directory could not be written: " + backupDirToTrim.getAbsolutePath() + " with name: " + backupDirToTrim.getName());
  }
 
  D.profile("Finished BackupDatabaseTask", wholestart);
}

private void backupStoreImages(JDODatabase database) {
  File companyDirectory = database.getBackupDirectory();
  File latestBackupDir = getNewestSubdir(companyDirectory);
  ImageServerImpl.getInstance().copyAllImages(latestBackupDir);
}

private File getNewestSubdir(File companyDirectory) {
  File newestSubDir = null;
  for (File subdir : companyDirectory.listFiles()) {
   if(subdir.isDirectory()) {
    if(newestSubDir == null || newestSubDir.lastModified() < subdir.lastModified()) {
     newestSubDir = subdir;
    }
   }
  }
  return newestSubDir;
}

public void backupJDODatabase(JDODatabase database) {
  EntityManager em = database.createEntityManager();
  TypedQuery<Thread> backupQuery = em.createQuery("objectdb backup", Thread.class);
  backupQuery.setParameter("target", database.getBackupDirectory());
  Thread backupThread = backupQuery.getSingleResult();
  // Wait until the backup is completed.
  try {
   backupThread.join();
  } catch (InterruptedException e) {
   e.printStackTrace();
  }
  em.close();
}
}

and here is the interesting part of JDODatabase:

private EntityManagerFactory emf;
private EntityManagerFactory getEntityManagerFactory() {
  if(emf == null) {
   synchronized (this) {
    if(emf == null) {
     emf = Persistence.createEntityManagerFactory(getAbsoluteDBPath());  
    }
   }
  }
  return emf;
}

public EntityManager createEntityManager() {
  return getEntityManagerFactory().createEntityManager();
}

Apparently an attempt to fix the issue in build 2.6.2_05 made it worst.

Please try version 2.6.3 that should fix it.

There is nothing wrong in using JDO and JPA together, so your code is fine.

Version 2.6.3 seems to fix both mistakes.
Thanks!