AnsweredAssumed Answered

First document failure: Failed loading value for 6; Caused by: Database lock acquisition failure: lockFile (db.lck)

Question asked by SatyaKomatineni3761 on Aug 23, 2016
Latest reply on Aug 23, 2016 by Srinivas Chandrakanth Vangari

Error

********

First document failure: Failed loading value for 6; Caused by: Database lock acquisition failure: lockFile (db.lck)

 

Impact

*********

A process with a flow control of 8/2 (processes/threads) fails once in 4 or 5 runs with this error

 

Run conditions

***************

  1. Molecule
  2. 8 CPUs per node, 32G of physical RAM per node
  3. 4G of RAM per node
  4. 4 nodes
  5. No other processes are running
  6. It is a heavy process that has lot of call outs and complex processing and could take 20 minutes for 3K of documents even with an 8/2 process/thread split

 

Here is a summary of the problem

****************************

 

  1. A process comes in with around 1200 documents into an EDI trading partner
  2. About 80 of them take the acknowledgments branch right off the bat and the rest goes to the main processing branch
  3. The main branch is attempted first (1120 docs)
  4. The 80 acknowledgment branch is executed the LAST
  5. The process is realizing that somehow the 1120 docs are in error. However it finishes the 80 ack branch and ftps that file out through a trading partner
  6. Then reports a single error of 1120 saying the Database lock acquisition failure (See the process log below)

 

What is happening is this

****************************

  1. The main branch has an 8/2 breakdown of processes/threads. This breakdown occurs at least twice in the overall process
  2. The second 8/2 breakdown is “launching” 8 processes
  3. When it fails, ONE of the 8 processes is failing to “execute”
  4. The failed execution id of this process matches the “execution id” that is reported in the dblock acquisition error.
  5. So the “Return” path from that sub process to the main branch reports an error
  6. This triggers the “ack” branch as that is the next branch and completes it
  7. Then reports the error
  8. As the error reporting comes after the ack branch it appears the trading partner is causing it
  9. But the real culprit is failing to execute/start ONE of the 8 processes
  10. We have confirmed this with multiple process logs when this happens

 

 

Bottom Line

****************************

  1. This error happens while executing or spawning one of the 8 flow control processes

 

Key questions

****************************

  1. What happens in Boomi between “launching” a process and “executing” a process as these 2 lines follow each other one after the other
  2. What is a First document failure?
  3. What is the behavior of “ack” branch in a trading partner as to when does it execute compared to the main branch, and is it guaranteed to execute etc.

 

Memory/CPU conditions

*********************

  1. We have went back and looked at both and they seem ok at the physical level (as we cannot monitor the memory on a proc by proc basis). However we don’t suspect memory at the proc level as the process itself is not spawned and failed in the process

 

Suggestions to Boomi to report this error out

************************************

  1. Indicate explicitly that the process cannot be spawned or whatever the immediate cause and not leave it to the generic exception which yield no result as why a lock is being acquired
  2. Indicate what part of the executing the process failed?
  3. This would have saved us lot of research

 

Last few lines of process log

***********************************

2016-08-20T03:08:32Z           INFO   Data Process    [1] Scripting: groovy    Executing with 38 documents in

2016-08-20T03:08:32Z           INFO   Data Process    [1] Scripting: groovy    Completed with 38 documents out

2016-08-20T03:08:32Z           INFO   Data Process                Data Process Execution (SCRIPTING) produced 38 documents.

2016-08-20T03:08:32Z           INFO   Data Process                Shape executed successfully in 61 ms.

2016-08-20T03:08:32Z           INFO   Trading Partner            x12 Trading Partner Connector            Executing Trading Partner Shape with 38 document(s).

2016-08-20T03:08:33Z           INFO   Trading Partner            x12 Trading Partner Connector            Data Process Execution (SCRIPTING) produced 38 documents.

2016-08-20T03:08:33Z           INFO   Trading Partner            x12 Trading Partner Connector            Permanently added 'securefile.bcbsfl.com' (RSA) to the list of known hosts.

2016-08-20T03:08:54Z           INFO   Trading Partner            x12 Trading Partner Connector            Shape executed successfully in 22053 ms.

2016-08-20T03:08:54Z           WARNING      cleanup...                     PSP_Process encountered 1234 document error(s)

2016-08-20T03:08:54Z           SEVERE          cleanup...                     First document failure: Failed loading value for 6; Caused by: Database lock acquisition failure: lockFile: org.hsqldb.persist.LockFile@87a07492[file =/opt/boomi/Boomi_AtomSphere/Molecule/Molecule_Prod_EMB_Molecule/execution/history/2016.08.19/execution-61a16042-5e04-495f-af34-9d75cecb8fb4-2016.08.19/eods/db.lck, exists=false, locked=false, valid=false, ] method: openRAF reason: java.io.FileNotFoundException: /opt/boomi/Boomi_AtomSphere/Molecule/Molecule_Prod_EMB_Molecule/execution/history/2016.08.19/execution-61a16042-5e04-495f-af34-9d75cecb8fb4-2016.08.19/eods/db.lck (Stale file handle)

2016-08-20T03:08:55Z           INFO   cleanup...                     Errors occurred in process.

 

Exception

*****************

com.boomi.store.DataStoreException: Failed loading value for 6

at com.boomi.store.db.BigMap.get(BigMap.java: 248)

at com.boomi.process.origdoc.ProcessDocumentCache.access$200(ProcessDocumentCache.java: 36)

at com.boomi.process.origdoc.ProcessDocumentCache$1.hasNext(ProcessDocumentCache.java: 248)

at com.boomi.process.ProcessExecution.isEmpty(ProcessExecution.java: 1397)

at com.boomi.process.ProcessExecution.handleChildResultData(ProcessExecution.java: 999)

at com.boomi.process.ProcessExecution.handleChildResult(ProcessExecution.java: 939)

at com.boomi.process.shape.FlowControlShape.executeInitial(FlowControlShape.java: 220)

at com.boomi.process.shape.BaseFiberShape.execute(BaseFiberShape.java: 76)

at com.boomi.process.graph.ProcessShape.executeShape(ProcessShape.java: 550)

at com.boomi.process.graph.ProcessGraph.executeShape(ProcessGraph.java: 488)

at com.boomi.process.graph.ProcessGraph.executeNextShapes(ProcessGraph.java: 572)

at com.boomi.process.graph.ProcessGraph.executeShape(ProcessGraph.java: 509)

at com.boomi.process.graph.ProcessGraph.executeNextShapes(ProcessGraph.java: 572)

at com.boomi.process.graph.ProcessGraph.executeShape(ProcessGraph.java: 509)

at com.boomi.process.graph.ProcessGraph.executeNextShapes(ProcessGraph.java: 572)

at com.boomi.process.graph.ProcessGraph.executeShape(ProcessGraph.java: 509)

at com.boomi.process.graph.ProcessGraph.executeNextShapes(ProcessGraph.java: 572)

at com.boomi.process.graph.ProcessGraph.executeShape(ProcessGraph.java: 509)

at com.boomi.process.graph.ProcessGraph.executeNextShapes(ProcessGraph.java: 572)

at com.boomi.process.graph.ProcessGraph.executeShape(ProcessGraph.java: 509)

at com.boomi.process.graph.ProcessGraph.executeNextShapes(ProcessGraph.java: 572)

at com.boomi.process.graph.ProcessGraph.execute(ProcessGraph.java: 307)

at com.boomi.process.ProcessExecution.call(ProcessExecution.java: 783)

at com.boomi.execution.ExecutionTask.call(ExecutionTask.java: 920)

at com.boomi.execution.ExecutionTask.call(ExecutionTask.java: 63)

at com.boomi.util.concurrent.CancellableFutureTask.run(CancellableFutureTask.java: 172)

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

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

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

Caused by: java.sql.SQLException: Database lock acquisition failure: lockFile: org.hsqldb.persist.LockFile@87a07492[file =/opt/boomi/Boomi_AtomSphere/Molecule/Molecule_Prod_EMB_Molecule/execution/history/2016.08.19/execution-61a16042-5e04-495f-af34-9d75cecb8fb4-2016.08.19/eods/db.lck, exists=false,

locked=false, valid=false, ] method: openRAF reason: java.io.FileNotFoundException: /opt/boomi/Boomi_AtomSphere/Molecule/Molecule_Prod_EMB_Molecule/execution/history/2016.08.19/execution-61a16042-5e04-495f-af34-9d75cecb8fb4-2016.08.19/eods/db.lck (Stale file handle)

at org.hsqldb.jdbc.JDBCUtil.sqlException(null: null)

at org.hsqldb.jdbc.JDBCUtil.sqlException(null: null)

at org.hsqldb.jdbc.JDBCConnection.<init>(null: null)

at org.hsqldb.jdbc.JDBCDriver.getConnection(null: null)

at org.hsqldb.jdbc.JDBCDriver.connect(null: null)

at java.sql.DriverManager.getConnection(DriverManager.java: 664)

at java.sql.DriverManager.getConnection(DriverManager.java: 247)

at com.boomi.container.embeddeddb.HsqlEmbeddedDatabase.openConnection(HsqlEmbeddedDatabase.java: 185)

at com.boomi.container.embeddeddb.HsqlEmbeddedDatabase.open(HsqlEmbeddedDatabase.java: 97)

at com.boomi.container.embeddeddb.EmbeddedDatabaseService.open(EmbeddedDatabaseService.java: 50)

at com.boomi.store.db.BigMap.getDb(BigMap.java: 556)

at com.boomi.process.origdoc.ProcessDocumentCache.load(ProcessDocumentCache.java: 180)

at com.boomi.process.origdoc.ProcessDocumentCache.load(ProcessDocumentCache.java: 36)

at com.boomi.store.db.BigMap.get(BigMap.java: 241)

Caused by: org.hsqldb.HsqlException: Database lock acquisition failure: lockFile: org.hsqldb.persist.LockFile@87a07492[file =/opt/boomi/Boomi_AtomSphere/Molecule/Molecule_Prod_EMB_Molecule/execution/history/2016.08.19/execution-61a16042-5e04-495f-af34-9d75cecb8fb4-2016.08.19/eods/db.lck, exists=false, locked=false, valid=false, ] method: openRAF reason: java.io.FileNotFoundException: /opt/boomi/Boomi_AtomSphere/Molecule/Molecule_Prod_EMB_Molecule/execution/history/2016.08.19/execution-61a16042-5e04-495f-af34-9d75cecb8fb4-2016.08.19/eods/db.lck (Stale file handle)

at org.hsqldb.error.Error.error(null: null)

at org.hsqldb.error.Error.error(null: null)

at org.hsqldb.persist.LockFile.newLockFileLock(null: null)

at org.hsqldb.persist.Logger.acquireLock(null: null)

at org.hsqldb.persist.Logger.open(null: null)

at org.hsqldb.Database.reopen(null: null)

at org.hsqldb.Database.open(null: null)

at org.hsqldb.DatabaseManager.getDatabase(null: null)

at org.hsqldb.DatabaseManager.newSession(null: null)

Outcomes