Issue #2568: Exception makes the system unusable for several minutes

Type: Bug ReoprtVersion: 2.7.6_04Priority: HighStatus: ActiveReplies: 7
#1

this exception occurs around 2 times a week:

 

[ObjectDB 2.7.6] Unexpected exception (Error 990)
  Generated by Java HotSpot(TM) 64-Bit Server VM 1.8.0_202 (on Windows Server 2012 R2 6.3).
Please report this error on http://www.objectdb.com/database/issue/new
com.objectdb.o.InternalException: null
com.objectdb.o.InternalException
    at com.objectdb.o.ACN.ZF(ACN.java:196)
    at com.objectdb.o.ACN.ZF(ACN.java:181)
    at com.objectdb.o.RTT.s(RTT.java:295)
    at com.objectdb.o.RRT.p(RRT.java:292)
    at com.objectdb.o.RTT.g(RTT.java:136)
    at com.objectdb.o.RRT.g(RRT.java:34)
    at com.objectdb.o.RTT.m(RTT.java:181)
    at com.objectdb.o.RRT.o(RRT.java:127)
    at com.objectdb.o.RTT.g(RTT.java:134)
    at com.objectdb.o.RRT.g(RRT.java:34)
    at com.objectdb.o.RTT.m(RTT.java:181)
    at com.objectdb.o.RRT.o(RRT.java:127)
    at com.objectdb.o.RTT.g(RTT.java:134)
    at com.objectdb.o.RRT.g(RRT.java:34)
    at com.objectdb.o.TSK.b(TSK.java:146)
    at com.objectdb.o.TSK.c(TSK.java:96)
    at com.objectdb.o.TSM.a(TSM.java:88)
    at com.objectdb.o.RTT.m(RTT.java:179)
    at com.objectdb.o.RRT.o(RRT.java:127)
    at com.objectdb.o.RTT.g(RTT.java:134)
    at com.objectdb.o.RRT.g(RRT.java:34)
    at com.objectdb.o.TSK.b(TSK.java:146)
    at com.objectdb.o.TSK.c(TSK.java:96)
    at com.objectdb.o.TSM.a(TSM.java:88)
    at com.objectdb.o.RTT.m(RTT.java:179)
    at com.objectdb.o.RRT.o(RRT.java:127)
    at com.objectdb.o.RTT.g(RTT.java:134)
    at com.objectdb.o.RRT.g(RRT.java:34)
    at com.objectdb.o.TSK.b(TSK.java:146)
    at com.objectdb.o.TSK.c(TSK.java:96)
    at com.objectdb.o.MST.av(MST.java:708)
    at com.objectdb.o.MST.at(MST.java:480)
    at com.objectdb.o.MST.Zc(MST.java:446)
    at com.objectdb.o.WRA.Zc(WRA.java:268)
    at com.objectdb.o.LDR.u(LDR.java:558)
    at com.objectdb.o.LDR.Yr(LDR.java:475)
    at com.objectdb.o.OBC.Yr(OBC.java:1122)
    at com.objectdb.o.ERF.c(ERF.java:105)
    at com.objectdb.o.TVS.b(TVS.java:105)
    at com.objectdb.o.TVS.b(TVS.java:94)
    at com.objectdb.jpa.EMImpl.refresh(EMImpl.java:746)
    at com.objectdb.jpa.EMImpl.refresh(EMImpl.java:687)
    at com.objectdb.jdo.PMImpl.refresh(PMImpl.java:976)
    at com.agile.hummingbird.CoreDaemon.refresh(CoreDaemon.java:566)
    at com.agile.hummingbird.SS_ScheduledSlot.updateSlot(SS_ScheduledSlot.java:582)
    at com.agile.hummingbird.OP_Operation.executeScheduledLogic(OP_Operation.java:1150)
    at com.agile.hummingbird.OP_Operation.onNodeUpdate(OP_Operation.java:628)
    at com.agile.hummingbird.ObjectNodeLogic.callObjectTypePlugin(ObjectNodeLogic.java:1264)
    at com.agile.hummingbird.ObjectNodeLogic.updateObject(ObjectNodeLogic.java:1695)
    at com.agile.hummingbird.AC_Action.endActionWithLogic(AC_Action.java:1418)
    at com.agile.hummingbird.AC_Action.endAction(AC_Action.java:878)
    at com.agile.hummingbird.API.executeEndAction(API.java:1874)
    at com.agile.hummingbird.API.handleAction(API.java:1614)
    at com.agile.hummingbird.API.directRequest(API.java:1089)
    at com.agile.hummingbird.API.handleWebSocketRequest(API.java:890)
    at com.agile.hummingbird.WebSocketServerListener.onWebSocketText(WebSocketServerListener.java:172)
    at org.eclipse.jetty.websocket.common.events.JettyListenerEventDriver.onTextMessage(JettyListenerEventDriver.java:128)
    at org.eclipse.jetty.websocket.common.message.SimpleTextMessage.messageComplete(SimpleTextMessage.java:69)
    at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.appendMessage(AbstractEventDriver.java:65)
    at org.eclipse.jetty.websocket.common.events.JettyListenerEventDriver.onTextFrame(JettyListenerEventDriver.java:122)
    at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.incomingFrame(AbstractEventDriver.java:161)
    at org.eclipse.jetty.websocket.common.WebSocketSession.incomingFrame(WebSocketSession.java:309)
    at org.eclipse.jetty.websocket.common.extensions.AbstractExtension.nextIncomingFrame(AbstractExtension.java:163)
    at org.eclipse.jetty.websocket.common.extensions.compress.PerMessageDeflateExtension.nextIncomingFrame(PerMessageDeflateExtension.java:105)
    at org.eclipse.jetty.websocket.common.extensions.compress.CompressExtension.forwardIncoming(CompressExtension.java:136)
    at org.eclipse.jetty.websocket.common.extensions.compress.PerMessageDeflateExtension.incomingFrame(PerMessageDeflateExtension.java:85)
    at org.eclipse.jetty.websocket.common.extensions.ExtensionStack.incomingFrame(ExtensionStack.java:214)
    at org.eclipse.jetty.websocket.common.Parser.notifyFrame(Parser.java:220)
    at org.eclipse.jetty.websocket.common.Parser.parse(Parser.java:258)
    at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.readParse(AbstractWebSocketConnection.java:632)
    at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:480)
    at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
    at java.lang.Thread.run(Unknown Source)
#2

This stack trace indicates an unexpected exception.

Are there errors in the Doctor report for this database?

The exception is thrown during refresh, can you check if it is always the same objects that refreshing them causes the exception?

ObjectDB Support
#3

from messages like these in the log:

[2020-07-24 10:56:45 #50 store] 
SectionClassifier: SectionClassifier{'bd127e47-7089-4f79-96a3-0ba6667f4d75'->merger[13111]-missing:6}

which are directly preceeding these exceptions, we can see that always the same objects (around 4) are in charge. A doctor we cannot do currently as it takes around 6-8 hours

 

 

#4

a more complete section of the log:

[2020-07-13 17:10:29 #7 store] 
RetrievalTask.reportSecondaryResult: page#55027945, reader.getPos() = 62

[2020-07-13 17:10:29 #8 store] 
SectionClassifier: SectionClassifier{'883e69ca-845d-437c-8c15-7c5eae917630'->merger[12793]-missing:2}

[2020-07-13 17:10:29 #9 *] 
[ObjectDB 2.7.6] Unexpected exception (Error 990)
  Generated by Java HotSpot(TM) 64-Bit Server VM 1.8.0_202 (on Windows Server 2012 R2 6.3).
Please report this error on http://www.objectdb.com/database/issue/new
com.objectdb.o.InternalException: null
com.objectdb.o.InternalException
    at com.objectdb.o.ACN.ZF(ACN.java:196)
    at com.objectdb.o.ACN.ZF(ACN.java:181)
    at com.objectdb.o.RTT.s(RTT.java:295)
    at com.objectdb.o.RRT.p(RRT.java:292)
    at com.objectdb.o.RTT.g(RTT.java:136)
    at com.objectdb.o.RRT.g(RRT.java:34)
    at com.objectdb.o.RTT.m(RTT.java:181)
    at com.objectdb.o.RRT.o(RRT.java:127)
    at com.objectdb.o.RTT.g(RTT.java:134)
    at com.objectdb.o.RRT.g(RRT.java:34)
    at com.objectdb.o.RTT.m(RTT.java:181)
    at com.objectdb.o.RRT.o(RRT.java:127)
    at com.objectdb.o.RTT.g(RTT.java:134)
    at com.objectdb.o.RRT.g(RRT.java:34)
    at com.objectdb.o.TSK.b(TSK.java:146)
    at com.objectdb.o.TSK.c(TSK.java:96)
    at com.objectdb.o.TSM.a(TSM.java:88)
    at com.objectdb.o.RTT.m(RTT.java:179)
    at com.objectdb.o.RRT.o(RRT.java:127)
    at com.objectdb.o.RTT.g(RTT.java:134)
    at com.objectdb.o.RRT.g(RRT.java:34)
    at com.objectdb.o.TSK.b(TSK.java:146)
    at com.objectdb.o.TSK.c(TSK.java:96)
    at com.objectdb.o.TSM.a(TSM.java:88)
    at com.objectdb.o.RTT.m(RTT.java:179)
    at com.objectdb.o.RRT.o(RRT.java:127)
    at com.objectdb.o.RTT.g(RTT.java:134)
    at com.objectdb.o.RRT.g(RRT.java:34)
    at com.objectdb.o.TSK.b(TSK.java:146)
    at com.objectdb.o.TSK.c(TSK.java:96)
    at com.objectdb.o.MST.av(MST.java:708)
    at com.objectdb.o.MST.at(MST.java:480)
    at com.objectdb.o.MST.Zc(MST.java:446)
    at com.objectdb.o.WRA.Zc(WRA.java:268)
    at com.objectdb.o.LDR.u(LDR.java:558)
    at com.objectdb.o.LDR.Yr(LDR.java:475)
    at com.objectdb.o.OBC.Yr(OBC.java:1122)
    at com.objectdb.o.ERF.c(ERF.java:105)
    at com.objectdb.o.TVS.b(TVS.java:105)
    at com.objectdb.o.TVS.b(TVS.java:94)
    at com.objectdb.jpa.EMImpl.refresh(EMImpl.java:746)
    at com.objectdb.jpa.EMImpl.refresh(EMImpl.java:687)
    at com.objectdb.jdo.PMImpl.refresh(PMImpl.java:976)
    at com.agile.hummingbird.CoreDaemon.refresh(CoreDaemon.java:566)
    at com.agile.hummingbird.SS_ScheduledSlot.linkSetSlot(SS_ScheduledSlot.java:398)
    at com.agile.hummingbird.WF_Workflow.update(WF_Workflow.java:886)
    at com.agile.hummingbird.OP_Operation.executeScheduledLogic(OP_Operation.java:1266)
    at com.agile.hummingbird.OP_Operation.onNodeUpdate(OP_Operation.java:628)
    at com.agile.hummingbird.ObjectNodeLogic.callObjectTypePlugin(ObjectNodeLogic.java:1264)
    at com.agile.hummingbird.ObjectNodeLogic.updateObject(ObjectNodeLogic.java:1695)
    at com.agile.hummingbird.AC_Action.endActionWithLogic(AC_Action.java:1418)
    at com.agile.hummingbird.AC_Action.endAction(AC_Action.java:878)
    at com.agile.hummingbird.API.executeEndAction(API.java:1874)
    at com.agile.hummingbird.API.handleAction(API.java:1614)
    at com.agile.hummingbird.API.directRequest(API.java:1089)
    at com.agile.hummingbird.API.handleWebSocketRequest(API.java:890)
    at com.agile.hummingbird.WebSocketServerListener.onWebSocketText(WebSocketServerListener.java:172)
    at org.eclipse.jetty.websocket.common.events.JettyListenerEventDriver.onTextMessage(JettyListenerEventDriver.java:128)
    at org.eclipse.jetty.websocket.common.message.SimpleTextMessage.messageComplete(SimpleTextMessage.java:69)
    at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.appendMessage(AbstractEventDriver.java:65)
    at org.eclipse.jetty.websocket.common.events.JettyListenerEventDriver.onTextFrame(JettyListenerEventDriver.java:122)
    at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.incomingFrame(AbstractEventDriver.java:161)
    at org.eclipse.jetty.websocket.common.WebSocketSession.incomingFrame(WebSocketSession.java:309)
    at org.eclipse.jetty.websocket.common.extensions.ExtensionStack.incomingFrame(ExtensionStack.java:214)
    at org.eclipse.jetty.websocket.common.Parser.notifyFrame(Parser.java:220)
    at org.eclipse.jetty.websocket.common.Parser.parse(Parser.java:258)
    at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.readParse(AbstractWebSocketConnection.java:632)
    at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:480)
    at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
    at java.lang.Thread.run(Unknown Source)

[2020-07-14 14:55:49 #10 store.file] 
LocalFile.read error: 0, 184744177664, 2048

[2020-07-14 14:55:49 #11 store.file] 
java.io.EOFException
    at java.io.RandomAccessFile.readFully(Unknown Source)
    at com.objectdb.o.LFL.Zg(LFL.java:1155)
    at com.objectdb.o.LFL.Zg(LFL.java:1127)
    at com.objectdb.o.PAG.Q(PAG.java:953)
    at com.objectdb.o.PGC.p(PGC.java:285)
    at com.objectdb.o.SNP.u(SNP.java:438)
    at com.objectdb.o.MST.ax(MST.java:514)
    at com.objectdb.o.MST.at(MST.java:475)
    at com.objectdb.o.MST.Zc(MST.java:446)
    at com.objectdb.o.WRA.Zc(WRA.java:268)
    at com.objectdb.o.LDR.u(LDR.java:558)
    at com.objectdb.o.LDR.Yr(LDR.java:475)
    at com.objectdb.o.OBC.Yr(OBC.java:1122)
    at com.objectdb.o.ERF.c(ERF.java:105)
    at com.objectdb.o.TVS.b(TVS.java:105)
    at com.objectdb.o.TVS.b(TVS.java:94)
    at com.objectdb.jpa.EMImpl.refresh(EMImpl.java:746)
    at com.objectdb.jpa.EMImpl.refresh(EMImpl.java:687)
    at com.objectdb.jdo.PMImpl.refresh(PMImpl.java:976)
    at com.agile.hummingbird.CoreDaemon.refresh(CoreDaemon.java:583)
    at com.agile.hummingbird.ObjectPropertyLogic.setValue(ObjectPropertyLogic.java:284)
    at com.agile.hummingbird.OP_Operation.executeScheduledLogic(OP_Operation.java:1178)
    at com.agile.hummingbird.OP_Operation.onNodeUpdate(OP_Operation.java:628)
    at com.agile.hummingbird.ObjectNodeLogic.callObjectTypePlugin(ObjectNodeLogic.java:1264)
    at com.agile.hummingbird.ObjectNodeLogic.updateObject(ObjectNodeLogic.java:1695)
    at com.agile.hummingbird.AC_Action.endActionWithLogic(AC_Action.java:1418)
    at com.agile.hummingbird.AC_Action.endAction(AC_Action.java:878)
    at com.agile.hummingbird.API.executeEndAction(API.java:1874)
    at com.agile.hummingbird.API.handleAction(API.java:1614)
    at com.agile.hummingbird.API.directRequest(API.java:1089)
    at com.agile.hummingbird.API.handleWebSocketRequest(API.java:890)
    at com.agile.hummingbird.WebSocketServerListener.onWebSocketText(WebSocketServerListener.java:172)
    at org.eclipse.jetty.websocket.common.events.JettyListenerEventDriver.onTextMessage(JettyListenerEventDriver.java:128)
    at org.eclipse.jetty.websocket.common.message.SimpleTextMessage.messageComplete(SimpleTextMessage.java:69)
    at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.appendMessage(AbstractEventDriver.java:65)
    at org.eclipse.jetty.websocket.common.events.JettyListenerEventDriver.onTextFrame(JettyListenerEventDriver.java:122)
    at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.incomingFrame(AbstractEventDriver.java:161)
    at org.eclipse.jetty.websocket.common.WebSocketSession.incomingFrame(WebSocketSession.java:309)
    at org.eclipse.jetty.websocket.common.extensions.ExtensionStack.incomingFrame(ExtensionStack.java:214)
    at org.eclipse.jetty.websocket.common.Parser.notifyFrame(Parser.java:220)
    at org.eclipse.jetty.websocket.common.Parser.parse(Parser.java:258)
    at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.readParse(AbstractWebSocketConnection.java:632)
    at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:480)
    at org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
    at java.lang.Thread.run(Unknown Source)

 

#5

on our extranet https://hummingbird-systems.com/de/objectdb/objectdb.htm you can login using your db name twice and download the database

#6

It is very likely, according to the stack traces and your answers, that these exceptions are thrown due to 4 corrupted objects.

However, it is unclear why this makes the system unusable for several minutes, as the exception is expected to be thrown immediately. If you see the same exception repeating many times in a short time, maybe this is caused by repeating the failed operation many times (automatically or maybe by users?), which may cause a general slowness.

ObjectDB Support
#7

the problem is that these objects are not corrupt, there seems to be a access problem for a while (when the exception is thrown) and afterwards they are useable as normal (these 4 objects are used all the time)

#8

This is strange, and indeed, if the access issue is temporary then it seems that the objects are not corrupted, although it could be helpful to verify this by running the Doctor.

The stack traces seems similar to the stack traces in this previous report. All of them are related to refreshing an object. Maybe something happens during the refresh that causes the exception? maybe it is a cache issue?

How does you application response to these exceptions? Does it try refreshing again? Can you try using a different EntityManager when such an exception happens?

Any additional information may help.

ObjectDB Support

Reply