3 Replies Latest reply: Mar 14, 2012 9:47 PM by Charles Lamb RSS

    je.rep.InsufficientLogException

    915071
      Hello,
      I faced an exception belowed, how do I resolve it?

      [rg1-rn1] JE: rg1-rn1(1):KVROOT/mystore/sn1/rg1-rn1/env:DETACHED rg1-rn1(1) exited unexpectedly with exception com.sleepycat.je.rep.InsufficientLogException: (JE 5.0.36) rg1-rn1(1):KVROOT/mystore/sn1/rg1-rn1/env INSUFFICIENT_LOG: Log files at this node are obsolete. Environment is invalid and must be closed.com.sleepycat.je.rep.InsufficientLogException: (JE 5.0.36) rg1-rn1(1):KVROOT/mystore/sn1/rg1-rn1/env INSUFFICIENT_LOG: Log files at this node are obsolete. Environment is invalid and must be closed
        • 1. Re: je.rep.InsufficientLogException
          Charles Lamb
          foreversunyao wrote:
          Hello,
          I faced an exception belowed, how do I resolve it?

          [rg1-rn1] JE: rg1-rn1(1):KVROOT/mystore/sn1/rg1-rn1/env:DETACHED rg1-rn1(1) exited unexpectedly with exception com.sleepycat.je.rep.InsufficientLogException: (JE 5.0.36) rg1-rn1(1):KVROOT/mystore/sn1/rg1-rn1/env INSUFFICIENT_LOG: Log files at this node are obsolete. Environment is invalid and must be closed.com.sleepycat.je.rep.InsufficientLogException: (JE 5.0.36) rg1-rn1(1):KVROOT/mystore/sn1/rg1-rn1/env INSUFFICIENT_LOG: Log files at this node are obsolete. Environment is invalid and must be closed
          This may be due to a couple of possible situations. The general exception is indicative that a Rep Node (RN1 in RG1) did not recover or more likely that the operation occurred in the middle of rg1-rn1's recovery. If you do a ping and the output for RG1 shows any node (particularly rg1-rn1) in a DETACHED state, then that node was not able to recover and we need to dig more deeply into that (look in the rg1-rn1 logs). You might be able to work around this situation by stopping and restarting that particular node.

          If ping shows Master, Replica, Replica (normal), then it is likely that you were hit by a bug that we have fixed, but not yet released (21081). In that case, we will assume that this was a transient exception which occurred during recovery of rg1-rn1. If it is not transient, then please send us the output of the ping command as well as information from the rg1-rn1 logs.

          Thanks.

          Charles Lamb
          • 2. Re: je.rep.InsufficientLogException
            915071
            Hello,
            Low details, and "信息" is for information,"警告" is for warning and "严重" is for Critical, or may be you can use google translate for this word(Chinese).
            Thanks.

            03-14-12 18:51:51:801 CST 信息 [rg1-rn1] Starting service process: rg1-rn1, Java command line arguments: [-XX:+UseConcMarkSweepGC, -XX:+UseParNewGC, -XX:+DisableExplicitGC, -XX:NewRatio=18, -XX:SurvivorRatio=4, -XX:MaxTenuringThreshold=10, -XX:CMSInitiatingOccupancyFraction=75, -XX:+UseLargePages, -Xms150m, -Xmx200m]
            03-14-12 18:51:51:905 CST 信息 [rg1-rn1] RepNodeStateUpdateThread started
            03-14-12 18:51:51:971 CST 信息 [rg1-rn1] Partition db cache mode: EVICT_LN
            03-14-12 18:51:52:108 CST 信息 [rg1-rn1] JVM Runtime maxMemory (bytes): 207880192
            03-14-12 18:51:52:110 CST 信息 [rg1-rn1] Non-default JE properties for environment: {je.rep.vlsn.logCacheSize=128, je.rep.envUnknownStateTimeout=10 s, je.tree.maxDelta=10, je.log.faultReadSize=4096, je.rep.vlsn.distance=1000000, je.env.runEvictor=true, je.cleaner.minUtilization=40, je.rep.replicaAckTimeout=5 s, je.cleaner.threads=2, je.evictor.lruOnly=false, je.rep.replayMaxOpenDbHandles=100, je.log.writeQueueSize=2097152, je.evictor.criticalPercentage=105, je.log.iteratorReadSize=1048576, je.log.numBuffers=16, je.nodeMaxEntries=128, je.evictor.nodesPerScan=200, je.rep.preHeartbeatTimeoutMs=5000000000, je.checkpointer.bytesInterval=200000000, je.cleaner.lazyMigration=false, je.txn.durability=write_no_sync,write_no_sync,simple_majority, je.cleaner.readSize=1048576, je.rep.txnRollbackLimit=10, je.log.fileCacheSize=2000, je.log.fileMax=1073741824}
            03-14-12 18:51:52:166 CST 信息 [rg1-rn1] Starting RepNodeService
            03-14-12 18:51:52:293 CST 信息 [rg1-rn1] Starting MonitorAgent
            03-14-12 18:51:52:323 CST 信息 [rg1-rn1] RepNodeAdmin registered
            03-14-12 18:51:52:697 CST 信息 [rg1-rn1] JE recovery: FIND_END_OF_LOG
            03-14-12 18:52:08:491 CST 信息 [rg1-rn1] JE recovery: FIND_LAST_CKPT
            03-14-12 18:52:08:506 CST 信息 [rg1-rn1] JE recovery: READ_DBMAP_INFO
            03-14-12 18:52:08:542 CST 信息 [rg1-rn1] JE recovery: UNDO_DBMAP_RECORDS
            03-14-12 18:52:08:572 CST 信息 [rg1-rn1] JE recovery: REDO_DBMAP_RECORDS
            03-14-12 18:52:08:647 CST 信息 [rg1-rn1] JE recovery: READ_DATA_INFO
            03-14-12 18:52:08:671 CST 信息 [rg1-rn1] JE recovery: UNDO_DATA_RECORDS
            03-14-12 18:52:08:709 CST 信息 [rg1-rn1] JE recovery: REDO_DATA_RECORDS
            03-14-12 18:52:08:799 CST 信息 [rg1-rn1] JE recovery: POPULATE_UTILIZATION_PROFILE
            03-14-12 18:52:08:823 CST 信息 [rg1-rn1] JE recovery: REMOVE_TEMP_DBS
            03-14-12 18:52:08:904 CST 信息 [rg1-rn1] JE recovery: RECOVERY_FINISHED
            03-14-12 18:52:09:21 CST 信息 [rg1-rn1] JE: Started ServiceDispatcher. HostPort=ip83:6011
            03-14-12 18:52:09:349 CST 信息 [rg1-rn1] JE: Current group size: 3
            03-14-12 18:52:09:350 CST 信息 [rg1-rn1] JE: Existing node rg1-rn1 querying for a current master.
            03-14-12 18:52:09:416 CST 信息 [rg1-rn1] JE: Master changed to rg1-rn3
            03-14-12 18:52:09:438 CST 信息 [rg1-rn1] JE recovery: BECOME_CONSISTENT
            03-14-12 18:52:09:450 CST 信息 [rg1-rn1] JE: Node rg1-rn1 started
            03-14-12 18:52:09:451 CST 信息 [rg1-rn1] JE: Replica loop started with master: rg1-rn3(3)
            03-14-12 18:52:09:790 CST 信息 [rg1-rn1] JE: Replica-feeder handshake start
            03-14-12 18:52:10:155 CST 信息 [rg1-rn1] JE: Replica-feeder rg1-rn3 handshake completed.
            03-14-12 18:52:10:184 CST 信息 [rg1-rn1] JE: Replica-feeder rg1-rn3 syncup started. Replica range: first=1 last=98,294,368 sync=98,294,367 txnEnd=98,294,367
            03-14-12 18:52:10:185 CST 信息 [rg1-rn1] JE syncup: FIND_MATCHPOINT 0/-1
            03-14-12 18:52:10:187 CST 信息 [rg1-rn1] JE: Requested 98,294,367 from rg1-rn3(3) but that node did not have that vlsn.
            03-14-12 18:52:10:192 CST 信息 [rg1-rn1] JE: Replica-feeder rg1-rn3 syncup ended. Elapsed time: 22ms
            03-14-12 18:52:10:192 CST 信息 [rg1-rn1] JE syncup: END 0/-1
            03-14-12 18:52:10:195 CST 警告 [rg1-rn1] JE: Exiting inner Replica loop with exception com.sleepycat.je.rep.InsufficientLogException: (JE 5.0.36) rg1-rn1(1):KVROOT/mystore/sn1/rg1-rn1/env INSUFFICIENT_LOG: Log files at this node are obsolete. Environment is invalid and must be closed.
            com.sleepycat.je.rep.InsufficientLogException: (JE 5.0.36) rg1-rn1(1):KVROOT/mystore/sn1/rg1-rn1/env INSUFFICIENT_LOG: Log files at this node are obsolete. Environment is invalid and must be closed.
                 at com.sleepycat.je.rep.stream.ReplicaFeederSyncup.setupLogRefresh(ReplicaFeederSyncup.java:475)
                 at com.sleepycat.je.rep.stream.ReplicaFeederSyncup.getFeederRecord(ReplicaFeederSyncup.java:549)
                 at com.sleepycat.je.rep.stream.ReplicaFeederSyncup.findMatchpoint(ReplicaFeederSyncup.java:368)
                 at com.sleepycat.je.rep.stream.ReplicaFeederSyncup.execute(ReplicaFeederSyncup.java:140)
                 at com.sleepycat.je.rep.impl.node.Replica.initReplicaLoop(Replica.java:585)
                 at com.sleepycat.je.rep.impl.node.Replica.runReplicaLoopInternal(Replica.java:373)
                 at com.sleepycat.je.rep.impl.node.Replica.runReplicaLoop(Replica.java:309)
                 at com.sleepycat.je.rep.impl.node.RepNode.run(RepNode.java:1318)

            03-14-12 18:52:10:197 CST 信息 [rg1-rn1] JE: Replica stats - Lag waits: 0 Lag wait time: 0ms. VLSN waits: 0 Lag wait time: 0ms.
            03-14-12 18:52:10:198 CST 警告 [rg1-rn1] JE: Environment needs to be restarted: Environment invalid because of previous exception: (JE 5.0.36) rg1-rn1(1):KVROOT/mystore/sn1/rg1-rn1/env INSUFFICIENT_LOG: Log files at this node are obsolete. Environment is invalid and must be closed.
            03-14-12 18:52:10:199 CST 严重 [rg1-rn1] JE:
            com.sleepycat.je.rep.InsufficientLogException: (JE 5.0.36) Environment must be closed, caused by: com.sleepycat.je.rep.InsufficientLogException: Environment invalid because of previous exception: (JE 5.0.36) rg1-rn1(1):KVROOT/mystore/sn1/rg1-rn1/env INSUFFICIENT_LOG: Log files at this node are obsolete. Environment is invalid and must be closed. fetchTarget of 0x5/0x2af8b150 parent IN=57002 IN class=com.sleepycat.je.tree.BIN lastFullVersion=0x5/0x2edd674e lastLoggedVersion=0x5/0x2ef8a709 parent.getDirty()=false state=0
                 at com.sleepycat.je.rep.InsufficientLogException.wrapSelf(InsufficientLogException.java:111)
                 at com.sleepycat.je.dbi.EnvironmentImpl.checkIfInvalid(EnvironmentImpl.java:1497)
                 at com.sleepycat.je.log.LogManager.getLogEntry(LogManager.java:798)
                 at com.sleepycat.je.log.LogManager.getLogEntryAllowInvisibleAtRecovery(LogManager.java:772)
                 at com.sleepycat.je.tree.IN.fetchTarget(IN.java:1400)
                 at com.sleepycat.je.tree.BIN.fetchTarget(BIN.java:1266)
                 at com.sleepycat.je.dbi.CursorImpl.fetchCurrent(CursorImpl.java:2224)
                 at com.sleepycat.je.dbi.CursorImpl.getCurrentAlreadyLatched(CursorImpl.java:1429)
                 at com.sleepycat.je.dbi.CursorImpl.getNext(CursorImpl.java:1556)
                 at com.sleepycat.je.cleaner.UtilizationProfile.getObsoleteDetail(UtilizationProfile.java:632)
                 at com.sleepycat.je.cleaner.FileProcessor.processFile(FileProcessor.java:410)
                 at com.sleepycat.je.cleaner.FileProcessor.doClean(FileProcessor.java:290)
                 at com.sleepycat.je.cleaner.FileProcessor.onWakeup(FileProcessor.java:149)
                 at com.sleepycat.je.utilint.DaemonThread.run(DaemonThread.java:162)
                 at java.lang.Thread.run(Thread.java:662)
            Caused by: com.sleepycat.je.rep.InsufficientLogException: Environment invalid because of previous exception: (JE 5.0.36) rg1-rn1(1):KVROOT/mystore/sn1/rg1-rn1/env INSUFFICIENT_LOG: Log files at this node are obsolete. Environment is invalid and must be closed.
                 at com.sleepycat.je.rep.stream.ReplicaFeederSyncup.setupLogRefresh(ReplicaFeederSyncup.java:475)
                 at com.sleepycat.je.rep.stream.ReplicaFeederSyncup.getFeederRecord(ReplicaFeederSyncup.java:549)
                 at com.sleepycat.je.rep.stream.ReplicaFeederSyncup.findMatchpoint(ReplicaFeederSyncup.java:368)
                 at com.sleepycat.je.rep.stream.ReplicaFeederSyncup.execute(ReplicaFeederSyncup.java:140)
                 at com.sleepycat.je.rep.impl.node.Replica.initReplicaLoop(Replica.java:585)
                 at com.sleepycat.je.rep.impl.node.Replica.runReplicaLoopInternal(Replica.java:373)
                 at com.sleepycat.je.rep.impl.node.Replica.runReplicaLoop(Replica.java:309)
                 at com.sleepycat.je.rep.impl.node.RepNode.run(RepNode.java:1318)

            03-14-12 18:52:10:199 CST 信息 [rg1-rn1] JE: RepNode main thread shutting down.
            03-14-12 18:52:10:207 CST 信息 [rg1-rn1] JE: RepNode shutdown exception:
            Environment invalid because of previous exception: (JE 5.0.36) rg1-rn1(1):KVROOT/mystore/sn1/rg1-rn1/env INSUFFICIENT_LOG: Log files at this node are obsolete. Environment is invalid and must be closed.rg1-rn1(1)[REPLICA]
            No feeders.
            GlobalCBVLSN=-1
            Group info [rg1] 56c3cdd4-155f-431e-b284-74c2c014b9bb
            Representation version: 2
            Change version: 3
            Max rep node ID: 3
            Node:rg1-rn3 ip81:6010 (is member) changeVersion:3 LocalCBVLSN:98,030,126 at:星期二 三月 13 13:49:43 CST 2012
            Node:rg1-rn1 ip83:6011 (is member) changeVersion:1 LocalCBVLSN:98,030,125 at:星期二 三月 13 13:34:25 CST 2012
            Node:rg1-rn2 ip82:6010 (is member) changeVersion:2 LocalCBVLSN:98,030,126 at:星期二 三月 13 13:49:48 CST 2012
            vlsnRange=first=1 last=98,294,368 sync=98,294,367 txnEnd=98,294,367
            lastReplayedTxn=null lastReplayedVLSN=98,294,368 numActiveReplayTxns=21

            03-14-12 18:52:10:208 CST 信息 [rg1-rn1] JE: Shutting down node rg1-rn1(1)
            03-14-12 18:52:10:208 CST 信息 [rg1-rn1] JE: Elections shutdown initiated
            03-14-12 18:52:10:219 CST 信息 [rg1-rn1] JE: Elections shutdown completed
            03-14-12 18:52:10:220 CST 信息 [rg1-rn1] JE: RepNode main thread: REPLICA rg1-rn1(1) exited.
            03-14-12 18:52:10:222 CST 信息 [rg1-rn1] JE: ServiceDispatcher shutdown starting. HostPort=ip83:6011 Registered services: []
            03-14-12 18:52:10:225 CST 信息 [rg1-rn1] JE: ServiceDispatcher shutdown completed. HostPort=ip83:6011
            03-14-12 18:52:10:227 CST 信息 [rg1-rn1] JE: rg1-rn1(1) shutdown completed.
            03-14-12 18:52:10:230 CST 严重 [rg1-rn1] JE: rg1-rn1(1):KVROOT/mystore/sn1/rg1-rn1/env:DETACHED rg1-rn1(1) exited unexpectedly with exception com.sleepycat.je.rep.InsufficientLogException: Environment invalid because of previous exception: (JE 5.0.36) rg1-rn1(1):KVROOT/mystore/sn1/rg1-rn1/env INSUFFICIENT_LOG: Log files at this node are obsolete. Environment is invalid and must be closed.com.sleepycat.je.rep.InsufficientLogException: Environment invalid because of previous exception: (JE 5.0.36) rg1-rn1(1):KVROOT/mystore/sn1/rg1-rn1/env INSUFFICIENT_LOG: Log files at this node are obsolete. Environment is invalid and must be closed.
                 at com.sleepycat.je.rep.stream.ReplicaFeederSyncup.setupLogRefresh(ReplicaFeederSyncup.java:475)
                 at com.sleepycat.je.rep.stream.ReplicaFeederSyncup.getFeederRecord(ReplicaFeederSyncup.java:549)
                 at com.sleepycat.je.rep.stream.ReplicaFeederSyncup.findMatchpoint(ReplicaFeederSyncup.java:368)
                 at com.sleepycat.je.rep.stream.ReplicaFeederSyncup.execute(ReplicaFeederSyncup.java:140)
                 at com.sleepycat.je.rep.impl.node.Replica.initReplicaLoop(Replica.java:585)
                 at com.sleepycat.je.rep.impl.node.Replica.runReplicaLoopInternal(Replica.java:373)
                 at com.sleepycat.je.rep.impl.node.Replica.runReplicaLoop(Replica.java:309)
                 at com.sleepycat.je.rep.impl.node.RepNode.run(RepNode.java:1318)

            03-14-12 18:52:11:860 CST 信息 [rg1-rn1] JE: Network restore candidate server: Node:rg1-rn2 ip82:6010 (is member) changeVersion:2 LocalCBVLSN:101,807,744 at:星期三 三月 14 18:48:22 CST 2012
            • 3. Re: je.rep.InsufficientLogException
              Charles Lamb
              Thanks. Could please also tell us what led to this exception (extended downtime of a rep node, or anything else that is "interesting")? Could you send us the output of ping?

              Charles Lamb