8 Replies Latest reply: Apr 14, 2014 1:29 PM by Greybird-Oracle RSS

    Log file missing, log is likely invalid. Environment is invalid and must be closed.

    abc8ef96-748c-4cc0-a0ca-63a66a0da292

      It seems that a .jdb file has been to delete after a cleaning, is no longer possible to reopen the database.

      A similar bug has been fixed in version 5.0.48?

       

      JE 5.0.58  Java 1.7.0_51  x86  Windows 7 (6.1)

       

       

      Last part of je.info.0:

       

      140325 14:04:21:037 Avvertenza [C:\Data]Cleaner has 1 files not deleted because they are protected by DbBackup or replication.

          ... a lot of ...

      140326 13:23:40:017 Avvertenza [C:\Data]Cleaner has 1 files not deleted because they are protected by replication.

          ... a lot of ...

      140326 13:33:40:478 Avvertenza [C:\Data]Cleaner has 1 files not deleted because they are protected by replication.

      140326 22:07:34:556 Informazioni [C:\Data]Chose lowest utilized file for cleaning. fileChosen: 0x1 totalUtilization: 30 bestFileUtilization: 31 lnSizeCorrectionFactor: NaN isProbe: false

      140326 22:07:34:556 Grave [C:\Data]

      com.sleepycat.je.EnvironmentFailureException: (JE 5.0.58) C:\Data fetchTarget of 0x2/0x96b91b parent IN=5 IN class="com".sleepycat.je.tree.BIN lastFullVersion=0x2/0x5ee295 lastLoggedVersion=0x2/0x96bb0e parent.getDirty()=false state=2 LOG_FILE_NOT_FOUND: Log file missing, log is likely invalid. Environment is invalid and must be closed.

          at com.sleepycat.je.tree.IN.fetchTarget(IN.java:1429)

          at com.sleepycat.je.tree.BIN.fetchTarget(BIN.java:1251)

          at com.sleepycat.je.dbi.CursorImpl.fetchCurrent(CursorImpl.java:2229)

          at com.sleepycat.je.dbi.CursorImpl.getCurrentAlreadyLatched(CursorImpl.java:1434)

          at com.sleepycat.je.dbi.CursorImpl.getNext(CursorImpl.java:1561)

          at com.sleepycat.je.cleaner.UtilizationProfile.getFirstFSLN(UtilizationProfile.java:889)

          at com.sleepycat.je.cleaner.UtilizationProfile.getObsoleteDetail(UtilizationProfile.java:603)

          at com.sleepycat.je.cleaner.FileProcessor.processFile(FileProcessor.java:445)

          at com.sleepycat.je.cleaner.FileProcessor.doClean(FileProcessor.java:295)

          at com.sleepycat.je.cleaner.FileProcessor.onWakeup(FileProcessor.java:148)

          at com.sleepycat.je.utilint.DaemonThread.run(DaemonThread.java:162)

          at java.lang.Thread.run(Unknown Source)

      Caused by: java.io.FileNotFoundException: C:\Data\00000002.jdb (Impossibile trovare il file specificato)

          at java.io.RandomAccessFile.open(Native Method)

          at java.io.RandomAccessFile.<init>(Unknown Source)

          at java.io.RandomAccessFile.<init>(Unknown Source)

          at com.sleepycat.je.log.FileManager$6.<init>(FileManager.java:1282)

          at com.sleepycat.je.log.FileManager.openFileHandle(FileManager.java:1281)

          at com.sleepycat.je.log.FileManager.getFileHandle(FileManager.java:1147)

          at com.sleepycat.je.log.LogManager.getLogSource(LogManager.java:1102)

          at com.sleepycat.je.log.LogManager.getLogEntry(LogManager.java:808)

          at com.sleepycat.je.log.LogManager.getLogEntryAllowInvisibleAtRecovery(LogManager.java:772)

          at com.sleepycat.je.tree.IN.fetchTarget(IN.java:1412)

          ... 11 more

      140326 22:07:34:564 Informazioni [C:\Data]CleanerRun 3 ends on file 0x1 probe=false invokedFromDaemon=true finished=false fileDeleted=false nEntriesRead=0 nINsObsolete=0 nINsCleaned=0 nINsDead=0 nINsMigrated=0 nBINDeltasObsolete=0 nBINDeltasCleaned=0 nBINDeltasDead=0 nBINDeltasMigrated=0 nLNsObsolete=0 nLNsCleaned=0 nLNsDead=0 nLNsMigrated=0 nLNsMarked=0 nLNQueueHits=0 nLNsLocked=0 logSummary=<CleanerLogSummary endFileNumAtLastAdjustment="0x12" initialAdjustments="3" recentLNSizesAndCounts="Cor:236/2-Est:3082241/1912 "> inSummary=<INSummary totalINCount="0" totalINSize="0" totalBINDeltaCount="0" totalBINDeltaSize="0" obsoleteINCount="0" obsoleteINSize="0" obsoleteBINDeltaCount="0" obsoleteBINDeltaSize="0"/> estFileSummary=<summary totalCount="26321" totalSize="9995556" totalINCount="9942" totalINSize="1794382" totalLNCount="10092" totalLNSize="7822261" maxLNSize="21503" obsoleteINCount="9915" obsoleteLNCount="8118" obsoleteLNSize="4762854" obsoleteLNSizeCounted="8109" getObsoleteSize="6945160" getObsoleteINSize="1789508" getObsoleteLNSize="4776739" getMaxObsoleteSize="7124802" getMaxObsoleteLNSize="4956381" getAvgObsoleteLNSizeNotCounted="1542.8175"/> recalcFileSummary=<summary totalCount="0" totalSize="0" totalINCount="0" totalINSize="0" totalLNCount="0" totalLNSize="0" maxLNSize="0" obsoleteINCount="0" obsoleteLNCount="0" obsoleteLNSize="0" obsoleteLNSizeCounted="0" getObsoleteSize="0" getObsoleteINSize="0" getObsoleteLNSize="0" getMaxObsoleteSize="0" getMaxObsoleteLNSize="0" getAvgObsoleteLNSizeNotCounted="NaN"/> lnSizeCorrection=NaN newLnSizeCorrection=NaN estimatedUtilization=31 correctedUtilization=31 recalcUtilization=0

       

       

      Complete content of je.info.0:

       

      140321 11:39:26:128 Informazioni [C:\Data]Chose lowest utilized file for cleaning. totalUtilization: 46 bestFileUtilization: 101 lnSizeCorrectionFactor: NaN isProbe: false

          ... similar lines ...

      140321 16:01:41:212 Informazioni [C:\Data]Chose lowest utilized file for cleaning. totalUtilization: 37 bestFileUtilization: 101 lnSizeCorrectionFactor: NaN isProbe: true

      140321 17:17:51:955 Informazioni [C:\Data]CleanerRun 1 ends on file 0x0 probe=false invokedFromDaemon=false finished=true fileDeleted=false nEntriesRead=6113 nINsObsolete=2109 nINsCleaned=23 nINsDead=0 nINsMigrated=23 nBINDeltasObsolete=693 nBINDeltasCleaned=6 nBINDeltasDead=0 nBINDeltasMigrated=6 nLNsObsolete=2284 nLNsCleaned=588 nLNsDead=3 nLNsMigrated=585 nLNsMarked=0 nLNQueueHits=336 nLNsLocked=0 logSummary=<CleanerLogSummary endFileNumAtLastAdjustment="0x11" initialAdjustments="1" recentLNSizesAndCounts=""> inSummary=<INSummary totalINCount="2132" totalINSize="224560" totalBINDeltaCount="699" totalBINDeltaSize="59521" obsoleteINCount="2109" obsoleteINSize="213766" obsoleteBINDeltaCount="693" obsoleteBINDeltaSize="59203"/> estFileSummary=<summary totalCount="7466" totalSize="2570773" totalINCount="2831" totalINSize="284081" totalLNCount="2872" totalLNSize="2200381" maxLNSize="20823" obsoleteINCount="2802" obsoleteLNCount="2284" obsoleteLNSize="1269630" obsoleteLNSizeCounted="2284" getObsoleteSize="1637111" getObsoleteINSize="281170" getObsoleteLNSize="1269630" getMaxObsoleteSize="1637111" getMaxObsoleteLNSize="1269630" getAvgObsoleteLNSizeNotCounted="NaN"/> recalcFileSummary=<summary totalCount="7466" totalSize="2570773" totalINCount="2831" totalINSize="284081" totalLNCount="2872" totalLNSize="2200381" maxLNSize="0" obsoleteINCount="2802" obsoleteLNCount="2284" obsoleteLNSize="1269630" obsoleteLNSizeCounted="2284" getObsoleteSize="1637111" getObsoleteINSize="281170" getObsoleteLNSize="1269630" getMaxObsoleteSize="1637111" getMaxObsoleteLNSize="1269630" getAvgObsoleteLNSizeNotCounted="NaN"/> lnSizeCorrection=NaN newLnSizeCorrection=NaN estimatedUtilization=36 correctedUtilization=36 recalcUtilization=36

      140321 17:17:55:565 Informazioni [C:\Data]Chose lowest utilized file for cleaning. totalUtilization: 26 bestFileUtilization: 101 lnSizeCorrectionFactor: NaN isProbe: false

          ... similar lines ...

      140324 21:06:20:106 Informazioni [C:\Data]Chose lowest utilized file for cleaning. totalUtilization: 31 bestFileUtilization: 101 lnSizeCorrectionFactor: NaN isProbe: false

      140325 14:03:32:849 Informazioni [C:\Data]Chose lowest utilized file for cleaning. fileChosen: 0x2 totalUtilization: 31 bestFileUtilization: 30 lnSizeCorrectionFactor: NaN isProbe: false

      140325 14:03:33:318 Informazioni [C:\Data]CleanerRun 1 ends on file 0x2 probe=false invokedFromDaemon=true finished=true fileDeleted=false nEntriesRead=4799 nINsObsolete=1578 nINsCleaned=24 nINsDead=0 nINsMigrated=24 nBINDeltasObsolete=605 nBINDeltasCleaned=5 nBINDeltasDead=0 nBINDeltasMigrated=5 nLNsObsolete=1811 nLNsCleaned=464 nLNsDead=0 nLNsMigrated=464 nLNsMarked=0 nLNQueueHits=265 nLNsLocked=0 logSummary=<CleanerLogSummary endFileNumAtLastAdjustment="0x12" initialAdjustments="2" recentLNSizesAndCounts=""> inSummary=<INSummary totalINCount="1602" totalINSize="412266" totalBINDeltaCount="610" totalBINDeltaSize="62669" obsoleteINCount="1578" obsoleteINSize="396337" obsoleteBINDeltaCount="605" obsoleteBINDeltaSize="62314"/> estFileSummary=<summary totalCount="5883" totalSize="2318100" totalINCount="2212" totalINSize="474935" totalLNCount="2273" totalLNSize="1752699" maxLNSize="16507" obsoleteINCount="2183" obsoleteLNCount="1810" obsoleteLNSize="1051906" obsoleteLNSizeCounted="1810" getObsoleteSize="1611080" getObsoleteINSize="468708" getObsoleteLNSize="1051906" getMaxObsoleteSize="1611080" getMaxObsoleteLNSize="1051906" getAvgObsoleteLNSizeNotCounted="NaN"/> recalcFileSummary=<summary totalCount="5887" totalSize="2318515" totalINCount="2212" totalINSize="474935" totalLNCount="2275" totalLNSize="1752894" maxLNSize="0" obsoleteINCount="2183" obsoleteLNCount="1811" obsoleteLNSize="1052009" obsoleteLNSizeCounted="1811" getObsoleteSize="1611403" getObsoleteINSize="468708" getObsoleteLNSize="1052009" getMaxObsoleteSize="1611403" getMaxObsoleteLNSize="1052009" getAvgObsoleteLNSizeNotCounted="NaN"/> lnSizeCorrection=NaN newLnSizeCorrection=NaN estimatedUtilization=30 correctedUtilization=30 recalcUtilization=30

      140325 14:03:33:326 Informazioni [C:\Data]Chose lowest utilized file for cleaning. fileChosen: 0x0 totalUtilization: 33 bestFileUtilization: 31 lnSizeCorrectionFactor: NaN isProbe: false

      140325 14:03:34:615 Avvertenza [C:\Data]Cleaner has 1 files not deleted because they are protected by replication.

      140325 14:03:34:810 Informazioni [C:\Data]CleanerRun 2 ends on file 0x0 probe=false invokedFromDaemon=true finished=true fileDeleted=false nEntriesRead=21215 nINsObsolete=7058 nINsCleaned=17 nINsDead=5 nINsMigrated=12 nBINDeltasObsolete=2469 nBINDeltasCleaned=1 nBINDeltasDead=0 nBINDeltasMigrated=1 nLNsObsolete=8382 nLNsCleaned=1910 nLNsDead=3 nLNsMigrated=1907 nLNsMarked=0 nLNQueueHits=1163 nLNsLocked=0 logSummary=<CleanerLogSummary endFileNumAtLastAdjustment="0x12" initialAdjustments="3" recentLNSizesAndCounts="Cor:236/2-Est:3082241/1912 "> inSummary=<INSummary totalINCount="7075" totalINSize="940222" totalBINDeltaCount="2470" totalBINDeltaSize="218630" obsoleteINCount="7058" obsoleteINSize="914466" obsoleteBINDeltaCount="2469" obsoleteBINDeltaSize="218601"/> estFileSummary=<summary totalCount="25856" totalSize="9999944" totalINCount="9545" totalINSize="1158852" totalLNCount="10292" totalLNSize="8533396" maxLNSize="21440" obsoleteINCount="9527" obsoleteLNCount="8382" obsoleteLNSize="5451155" obsoleteLNSizeCounted="8380" getObsoleteSize="6918741" getObsoleteINSize="1156666" getObsoleteLNSize="5454379" getMaxObsoleteSize="6958397" getMaxObsoleteLNSize="5494035" getAvgObsoleteLNSizeNotCounted="1612.0508"/> recalcFileSummary=<summary totalCount="25856" totalSize="9999944" totalINCount="9545" totalINSize="1158852" totalLNCount="10292" totalLNSize="8533396" maxLNSize="0" obsoleteINCount="9527" obsoleteLNCount="8382" obsoleteLNSize="5451391" obsoleteLNSizeCounted="8382" getObsoleteSize="6915753" getObsoleteINSize="1156666" getObsoleteLNSize="5451391" getMaxObsoleteSize="6915753" getMaxObsoleteLNSize="5451391" getAvgObsoleteLNSizeNotCounted="NaN"/> lnSizeCorrection=NaN newLnSizeCorrection=NaN estimatedUtilization=31 correctedUtilization=31 recalcUtilization=31

      140325 14:03:34:818 Informazioni [C:\Data]No file selected for cleaning. totalUtilization: 50 bestFileUtilization: 31 lnSizeCorrectionFactor: NaN isProbe: false

      140325 14:04:21:037 Avvertenza [C:\Data]Cleaner has 1 files not deleted because they are protected by DbBackup or replication.

      140325 14:04:21:091 Avvertenza [C:\Data]Cleaner has 1 files not deleted because they are protected by replication.

          ... a lot of ...

      140325 20:13:12:904 Avvertenza [C:\Data]Cleaner has 1 files not deleted because they are protected by replication.

      140325 20:13:13:490 Informazioni [C:\Data]Chose lowest utilized file for cleaning. totalUtilization: 42 bestFileUtilization: 101 lnSizeCorrectionFactor: NaN isProbe: false

      140325 20:13:13:498 Avvertenza [C:\Data]Cleaner has 1 files not deleted because they are protected by replication.

          ... a lot of ...

      140326 13:23:38:908 Avvertenza [C:\Data]Cleaner has 1 files not deleted because they are protected by replication.

      140326 13:23:40:009 Informazioni [C:\Data]Chose lowest utilized file for cleaning. totalUtilization: 45 bestFileUtilization: 101 lnSizeCorrectionFactor: NaN isProbe: false

      140326 13:23:40:017 Avvertenza [C:\Data]Cleaner has 1 files not deleted because they are protected by replication.

          ... a lot of ...

      140326 13:33:40:478 Avvertenza [C:\Data]Cleaner has 1 files not deleted because they are protected by replication.

      140326 22:07:34:556 Informazioni [C:\Data]Chose lowest utilized file for cleaning. fileChosen: 0x1 totalUtilization: 30 bestFileUtilization: 31 lnSizeCorrectionFactor: NaN isProbe: false

      140326 22:07:34:556 Grave [C:\Data]

      com.sleepycat.je.EnvironmentFailureException: (JE 5.0.58) C:\Data fetchTarget of 0x2/0x96b91b parent IN=5 IN class="com".sleepycat.je.tree.BIN lastFullVersion=0x2/0x5ee295 lastLoggedVersion=0x2/0x96bb0e parent.getDirty()=false state=2 LOG_FILE_NOT_FOUND: Log file missing, log is likely invalid. Environment is invalid and must be closed.

          at com.sleepycat.je.tree.IN.fetchTarget(IN.java:1429)

          at com.sleepycat.je.tree.BIN.fetchTarget(BIN.java:1251)

          at com.sleepycat.je.dbi.CursorImpl.fetchCurrent(CursorImpl.java:2229)

          at com.sleepycat.je.dbi.CursorImpl.getCurrentAlreadyLatched(CursorImpl.java:1434)

          at com.sleepycat.je.dbi.CursorImpl.getNext(CursorImpl.java:1561)

          at com.sleepycat.je.cleaner.UtilizationProfile.getFirstFSLN(UtilizationProfile.java:889)

          at com.sleepycat.je.cleaner.UtilizationProfile.getObsoleteDetail(UtilizationProfile.java:603)

          at com.sleepycat.je.cleaner.FileProcessor.processFile(FileProcessor.java:445)

          at com.sleepycat.je.cleaner.FileProcessor.doClean(FileProcessor.java:295)

          at com.sleepycat.je.cleaner.FileProcessor.onWakeup(FileProcessor.java:148)

          at com.sleepycat.je.utilint.DaemonThread.run(DaemonThread.java:162)

          at java.lang.Thread.run(Unknown Source)

      Caused by: java.io.FileNotFoundException: C:\Data\00000002.jdb (Impossibile trovare il file specificato)

          at java.io.RandomAccessFile.open(Native Method)

          at java.io.RandomAccessFile.<init>(Unknown Source)

          at java.io.RandomAccessFile.<init>(Unknown Source)

          at com.sleepycat.je.log.FileManager$6.<init>(FileManager.java:1282)

          at com.sleepycat.je.log.FileManager.openFileHandle(FileManager.java:1281)

          at com.sleepycat.je.log.FileManager.getFileHandle(FileManager.java:1147)

          at com.sleepycat.je.log.LogManager.getLogSource(LogManager.java:1102)

          at com.sleepycat.je.log.LogManager.getLogEntry(LogManager.java:808)

          at com.sleepycat.je.log.LogManager.getLogEntryAllowInvisibleAtRecovery(LogManager.java:772)

          at com.sleepycat.je.tree.IN.fetchTarget(IN.java:1412)

          ... 11 more

      140326 22:07:34:564 Informazioni [C:\Data]CleanerRun 3 ends on file 0x1 probe=false invokedFromDaemon=true finished=false fileDeleted=false nEntriesRead=0 nINsObsolete=0 nINsCleaned=0 nINsDead=0 nINsMigrated=0 nBINDeltasObsolete=0 nBINDeltasCleaned=0 nBINDeltasDead=0 nBINDeltasMigrated=0 nLNsObsolete=0 nLNsCleaned=0 nLNsDead=0 nLNsMigrated=0 nLNsMarked=0 nLNQueueHits=0 nLNsLocked=0 logSummary=<CleanerLogSummary endFileNumAtLastAdjustment="0x12" initialAdjustments="3" recentLNSizesAndCounts="Cor:236/2-Est:3082241/1912 "> inSummary=<INSummary totalINCount="0" totalINSize="0" totalBINDeltaCount="0" totalBINDeltaSize="0" obsoleteINCount="0" obsoleteINSize="0" obsoleteBINDeltaCount="0" obsoleteBINDeltaSize="0"/> estFileSummary=<summary totalCount="26321" totalSize="9995556" totalINCount="9942" totalINSize="1794382" totalLNCount="10092" totalLNSize="7822261" maxLNSize="21503" obsoleteINCount="9915" obsoleteLNCount="8118" obsoleteLNSize="4762854" obsoleteLNSizeCounted="8109" getObsoleteSize="6945160" getObsoleteINSize="1789508" getObsoleteLNSize="4776739" getMaxObsoleteSize="7124802" getMaxObsoleteLNSize="4956381" getAvgObsoleteLNSizeNotCounted="1542.8175"/> recalcFileSummary=<summary totalCount="0" totalSize="0" totalINCount="0" totalINSize="0" totalLNCount="0" totalLNSize="0" maxLNSize="0" obsoleteINCount="0" obsoleteLNCount="0" obsoleteLNSize="0" obsoleteLNSizeCounted="0" getObsoleteSize="0" getObsoleteINSize="0" getObsoleteLNSize="0" getMaxObsoleteSize="0" getMaxObsoleteLNSize="0" getAvgObsoleteLNSizeNotCounted="NaN"/> lnSizeCorrection=NaN newLnSizeCorrection=NaN estimatedUtilization=31 correctedUtilization=31 recalcUtilization=0

       

       

      Database creation:

       

      EnvironmentConfig envCfg = new EnvironmentConfig();

      envCfg.setAllowCreate(true);

      envCfg.setTransactional(transactional);

      envCfg.setTxnSerializableIsolation(true);

      envCfg.setDurability(Durability.COMMIT_SYNC);

      envCfg.setSharedCache(true);

      envCfg.setCachePercent(50);

      envCfg.setLockTimeout(5, TimeUnit.SECONDS);

      envCfg.setTxnTimeout(5, TimeUnit.SECONDS);

      DatabaseConfig dbCfg = new DatabaseConfig();

      dbCfg.setAllowCreate(true);

      dbCfg.setDeferredWrite(false);

      dbCfg.setTransactional(true);

        • 1. Re: Log file missing, log is likely invalid. Environment is invalid and must be closed.
          Greybird-Oracle

          The only known bug that could cause this in JE version 5.0.58 or later is the following problem fixed in 5.0.61.  This is the description from the change log in the current released version of JE:

           

          Fixed a bug that caused data corruption (for example, resulting in an

          EnvironmentFailureException with a LOG_FILE_NOT_FOUND message) under certain

          circumstances, when many Databases are created and not all Databases are kept

          open.  In fact two bugs were fixed that contributed to the problem.  The first

          bug was a memory size calculation error and caused heavy/costly cache eviction,

          even when the cache would normally be large enough to avoid such eviction.

          This calculation error occurred during log cleaning, and only when closed

          databases had been previously evicted from the cache. The second bug caused

          Btree corruption when cache eviction was heavy and many closed databases were

          evicted.  [#21686] (JE 5.0.61)

           

          Does this description sound like it could fit in your case, i.e., do you have many Databases that are not kept open and do you see eviction occurring?

           

          The bug you referred to in JE 5.0.48 was only for deferred-write databases (DatabaseConfig.setDeferredWrite(true)), which you're not using according to the configuration you posted.

           

          --mark

          • 2. Re: Log file missing, log is likely invalid. Environment is invalid and must be closed.
            abc8ef96-748c-4cc0-a0ca-63a66a0da292

            I keep opened the databases with a map of Database objects and probably sometimes I open and close some databases with other temporary variables during particular transactions, keeping the first set of opened Databases. I fixed this behavior using only one map of opened Databases.

             

            I have many databases, I open them when is required by program and I left them opened until the program ends.

            It's better to open all Databases when the program starts or it's enough to open and keep them opened when is required?

             

            Also it's correct to do this?

            1) Start a transaction.

            2) Open an inexistent database with create option outer the transaction (null txn parameter).

            3) Put data in that created database inner the transaction.

            4) Commit.

             

            Thanks,

            Giorgio.

            • 3. Re: Log file missing, log is likely invalid. Environment is invalid and must be closed.
              Greybird-Oracle

              abc8ef96-748c-4cc0-a0ca-63a66a0da292 wrote:

               

              I keep opened the databases with a map of Database objects and probably sometimes I open and close some databases with other temporary variables during particular transactions, keeping the first set of opened Databases. I fixed this behavior using only one map of opened Databases.

               

              I have many databases, I open them when is required by program and I left them opened until the program ends.

              It's better to open all Databases when the program starts or it's enough to open and keep them opened when is required?

               

              From a CPU performance point of view, it's better to keep them open, since opening a database is fairly expensive.  The exception is when you have many (millions) of databases -- in that case, keeping them all open will use large amounts of memory, which could have a negative performance impact.

               

              Also it's correct to do this?

              1) Start a transaction.

              2) Open an inexistent database with create option outer the transaction (null txn parameter).

              3) Put data in that created database inner the transaction.

              4) Commit.

               

              Yes, that is fine.

               

              --mark

              • 4. Re: Log file missing, log is likely invalid. Environment is invalid and must be closed.
                abc8ef96-748c-4cc0-a0ca-63a66a0da292

                I upgraded to version 5.0.103 and I changed the program as described in the previous post (opening tables as required and keeping them opened until the program ends), but the error happens anyway.

                 

                 

                 

                Part of je.info.0:

                 

                2014-04-12 18:40:44.416 UTC Informazioni [C:\Data] CleanerRun 2 ends on file 0x7 probe=false invokedFromDaemon=true finished=true fileDeleted=false nEntriesRead=6596 nINsObsolete=2207 nINsCleaned=22 nINsDead=0 nINsMigrated=22 nBINDeltasObsolete=812 nBINDeltasCleaned=3 nBINDeltasDead=0 nBINDeltasMigrated=3 nLNsObsolete=2509 nLNsCleaned=617 nLNsDead=0 nLNsMigrated=617 nLNsMarked=0 nLNQueueHits=370 nLNsLocked=0 logSummary=<CleanerLogSummary endFileNumAtLastAdjustment="0x13" initialAdjustments="4" recentLNSizesAndCounts=""> inSummary=<INSummary totalINCount="2229" totalINSize="587613" totalBINDeltaCount="815" totalBINDeltaSize="85032" obsoleteINCount="2207" obsoleteINSize="570161" obsoleteBINDeltaCount="812" obsoleteBINDeltaSize="84688"/> estFileSummary=<summary totalCount="8047" totalSize="3450653" totalINCount="3042" totalINSize="669543" totalLNCount="3124" totalLNSize="2659842" maxLNSize="21530" obsoleteINCount="3016" obsoleteLNCount="2508" obsoleteLNSize="1650113" obsoleteLNSizeCounted="2508" getObsoleteSize="2435201" getObsoleteINSize="663820" getObsoleteLNSize="1650113" getMaxObsoleteSize="2435201" getMaxObsoleteLNSize="1650113" getAvgObsoleteLNSizeNotCounted="NaN"/> recalcFileSummary=<summary totalCount="8054" totalSize="3454249" totalINCount="3044" totalINSize="672645" totalLNCount="3126" totalLNSize="2660044" maxLNSize="0" obsoleteINCount="3019" obsoleteLNCount="2509" obsoleteLNSize="1650215" obsoleteLNSizeCounted="2509" getObsoleteSize="2438895" getObsoleteINSize="667120" getObsoleteLNSize="1650215" getMaxObsoleteSize="2438895" getMaxObsoleteLNSize="1650215" getAvgObsoleteLNSizeNotCounted="NaN"/> lnSizeCorrection=NaN newLnSizeCorrection=NaN estimatedUtilization=29 correctedUtilization=29 recalcUtilization=29 correctionRejected=true

                 

                2014-04-12 18:43:39.556 UTC Avvertenza [C:\Data] Cleaner deleteSafeToDeleteFiles Log file 0x7 could not be deleted. This operation will be retried at the next checkpoint. State: files = {7=status = SAFE_TO_DELETE dbIds = [0, 2, 3, 4, 5, 7, 8] lastVlsn = -1} pendingLNs = {} pendingDBs = [] anyPendingDuringCheckpoint = false lowUtilizationFiles = []

                ... 742 times (2 days) ...

                2014-04-13 17:05:27.069 UTC Avvertenza [C:\Data] Cleaner deleteSafeToDeleteFiles Log file 0x7 could not be deleted. This operation will be retried at the next checkpoint. State: files = {7=status = SAFE_TO_DELETE dbIds = [0, 2, 3, 4, 5, 7, 8] lastVlsn = -1} pendingLNs = {} pendingDBs = [] anyPendingDuringCheckpoint = false lowUtilizationFiles = []

                 

                2014-04-14 12:30:13.612 UTC Informazioni [C:\Data] Chose lowest utilized file for cleaning. fileChosen: 0x5 lnSizeCorrectionFactor: NaN totalUtilization: 49 bestFileUtilization: 30 isProbe: false

                 

                2014-04-14 12:30:13.612 UTC Grave [C:\Data]

                com.sleepycat.je.EnvironmentFailureException: Environment invalid because of previous exception: (JE 5.0.103) C:\Data fetchTarget of 0x7/0x44ef4d parent IN=86 IN class="com".sleepycat.je.tree.BIN lastFullVersion=0x6/0x8c04c4 lastLoggedVersion=0x8/0x26436a parent.getDirty()=false state=2 LOG_FILE_NOT_FOUND: Log file missing, log is likely invalid. Environment is invalid and must be closed.

                    at com.sleepycat.je.tree.IN.fetchTarget(IN.java:1442)

                    at com.sleepycat.je.tree.BIN.fetchTarget(BIN.java:1250)

                    at com.sleepycat.je.dbi.CursorImpl.fetchCurrent(CursorImpl.java:2280)

                    at com.sleepycat.je.dbi.CursorImpl.getCurrentAlreadyLatched(CursorImpl.java:1480)

                    at com.sleepycat.je.dbi.CursorImpl.getNext(CursorImpl.java:1607)

                    at com.sleepycat.je.cleaner.UtilizationProfile.getObsoleteDetail(UtilizationProfile.java:639)

                    at com.sleepycat.je.cleaner.FileProcessor.processFile(FileProcessor.java:442)

                    at com.sleepycat.je.cleaner.FileProcessor.doClean(FileProcessor.java:290)

                    at com.sleepycat.je.cleaner.FileProcessor.onWakeup(FileProcessor.java:148)

                    at com.sleepycat.je.utilint.DaemonThread.run(DaemonThread.java:148)

                    at java.lang.Thread.run(Unknown Source)

                Caused by: java.io.FileNotFoundException: C:\Data\00000007.jdb (Impossibile trovare il file specificato)

                    at java.io.RandomAccessFile.open(Native Method)

                    at java.io.RandomAccessFile.<init>(Unknown Source)

                    at java.io.RandomAccessFile.<init>(Unknown Source)

                    at com.sleepycat.je.log.FileManager$DefaultRandomAccessFile.<init>(FileManager.java:3181)

                    at com.sleepycat.je.log.FileManager$6.createFile(FileManager.java:3209)

                    at com.sleepycat.je.log.FileManager.openFileHandle(FileManager.java:1278)

                    at com.sleepycat.je.log.FileManager.getFileHandle(FileManager.java:1150)

                    at com.sleepycat.je.log.LogManager.getLogSource(LogManager.java:1224)

                    at com.sleepycat.je.log.LogManager.getLogEntry(LogManager.java:928)

                    at com.sleepycat.je.log.LogManager.getLogEntryAllowInvisibleAtRecovery(LogManager.java:892)

                    at com.sleepycat.je.tree.IN.fetchTarget(IN.java:1425)

                    ... 10 more

                 

                 

                 

                Complete content of je.info.0:

                 

                2014-04-05 09:27:34.485 UTC Informazioni [C:\Data] CleanerRun 1 ends on file 0x0 probe=false invokedFromDaemon=false finished=true fileDeleted=false nEntriesRead=13051 nINsObsolete=2936 nINsCleaned=30 nINsDead=0 nINsMigrated=30 nBINDeltasObsolete=990 nBINDeltasCleaned=7 nBINDeltasDead=0 nBINDeltasMigrated=7 nLNsObsolete=3165 nLNsCleaned=5327 nLNsDead=1 nLNsMigrated=5326 nLNsMarked=0 nLNQueueHits=3397 nLNsLocked=0 logSummary=<CleanerLogSummary endFileNumAtLastAdjustment="0x12" initialAdjustments="1" recentLNSizesAndCounts=""> inSummary=<INSummary totalINCount="2966" totalINSize="324194" totalBINDeltaCount="997" totalBINDeltaSize="84007" obsoleteINCount="2936" obsoleteINSize="309421" obsoleteBINDeltaCount="990" obsoleteBINDeltaSize="83644"/> estFileSummary=<summary totalCount="10500" totalSize="3460240" totalINCount="3963" totalINSize="408201" totalLNCount="3982" totalLNSize="2924937" maxLNSize="18883" obsoleteINCount="3926" obsoleteLNCount="3165" obsoleteLNSize="1749966" obsoleteLNSizeCounted="3165" getObsoleteSize="2281457" getObsoleteINSize="404389" getObsoleteLNSize="1749966" getMaxObsoleteSize="2281457" getMaxObsoleteLNSize="1749966" getAvgObsoleteLNSizeNotCounted="NaN"/> recalcFileSummary=<summary totalCount="15016" totalSize="9988190" totalINCount="3963" totalINSize="408201" totalLNCount="8492" totalLNSize="9452288" maxLNSize="0" obsoleteINCount="3926" obsoleteLNCount="3165" obsoleteLNSize="1749966" obsoleteLNSizeCounted="3165" getObsoleteSize="2282056" getObsoleteINSize="404389" getObsoleteLNSize="1749966" getMaxObsoleteSize="2282056" getMaxObsoleteLNSize="1749966" getAvgObsoleteLNSizeNotCounted="NaN"/> lnSizeCorrection=NaN newLnSizeCorrection=NaN estimatedUtilization=34 correctedUtilization=34 recalcUtilization=77 correctionRejected=false

                 

                2014-04-09 07:31:34.138 UTC Informazioni [C:\Data] CleanerRun 1 ends on file 0x3 probe=false invokedFromDaemon=false finished=true fileDeleted=false nEntriesRead=1055 nINsObsolete=332 nINsCleaned=19 nINsDead=0 nINsMigrated=19 nBINDeltasObsolete=137 nBINDeltasCleaned=6 nBINDeltasDead=0 nBINDeltasMigrated=6 nLNsObsolete=365 nLNsCleaned=118 nLNsDead=0 nLNsMigrated=118 nLNsMarked=0 nLNQueueHits=79 nLNsLocked=0 logSummary=<CleanerLogSummary endFileNumAtLastAdjustment="0x12" initialAdjustments="2" recentLNSizesAndCounts=""> inSummary=<INSummary totalINCount="351" totalINSize="83020" totalBINDeltaCount="143" totalBINDeltaSize="13970" obsoleteINCount="332" obsoleteINSize="72305" obsoleteBINDeltaCount="137" obsoleteBINDeltaSize="13505"/> estFileSummary=<summary totalCount="1323" totalSize="406501" totalINCount="494" totalINSize="96990" totalLNCount="483" totalLNSize="287517" maxLNSize="12838" obsoleteINCount="469" obsoleteLNCount="365" obsoleteLNSize="184883" obsoleteLNSizeCounted="365" getObsoleteSize="298958" getObsoleteINSize="92081" getObsoleteLNSize="184883" getMaxObsoleteSize="298958" getMaxObsoleteLNSize="184883" getAvgObsoleteLNSizeNotCounted="NaN"/> recalcFileSummary=<summary totalCount="1323" totalSize="406501" totalINCount="494" totalINSize="96990" totalLNCount="483" totalLNSize="287517" maxLNSize="0" obsoleteINCount="469" obsoleteLNCount="365" obsoleteLNSize="184883" obsoleteLNSizeCounted="365" getObsoleteSize="298958" getObsoleteINSize="92081" getObsoleteLNSize="184883" getMaxObsoleteSize="298958" getMaxObsoleteLNSize="184883" getAvgObsoleteLNSizeNotCounted="NaN"/> lnSizeCorrection=NaN newLnSizeCorrection=NaN estimatedUtilization=26 correctedUtilization=26 recalcUtilization=26 correctionRejected=false

                 

                2014-04-09 07:31:35.567 UTC Informazioni [C:\Data] CleanerRun 2 ends on file 0x2 probe=false invokedFromDaemon=false finished=true fileDeleted=false nEntriesRead=20998 nINsObsolete=7014 nINsCleaned=34 nINsDead=0 nINsMigrated=34 nBINDeltasObsolete=2682 nBINDeltasCleaned=2 nBINDeltasDead=0 nBINDeltasMigrated=2 nLNsObsolete=7916 nLNsCleaned=1947 nLNsDead=2 nLNsMigrated=1945 nLNsMarked=0 nLNQueueHits=1185 nLNsLocked=0 logSummary=<CleanerLogSummary endFileNumAtLastAdjustment="0x12" initialAdjustments="3" recentLNSizesAndCounts=""> inSummary=<INSummary totalINCount="7048" totalINSize="1495069" totalBINDeltaCount="2684" totalBINDeltaSize="271084" obsoleteINCount="7014" obsoleteINSize="1461815" obsoleteBINDeltaCount="2682" obsoleteBINDeltaSize="270880"/> estFileSummary=<summary totalCount="25786" totalSize="9999606" totalINCount="9732" totalINSize="1766153" totalLNCount="9863" totalLNSize="7862256" maxLNSize="27316" obsoleteINCount="9696" obsoleteLNCount="7916" obsoleteLNSize="4902079" obsoleteLNSizeCounted="7916" getObsoleteSize="7032895" getObsoleteINSize="1759619" getObsoleteLNSize="4902079" getMaxObsoleteSize="7032895" getMaxObsoleteLNSize="4902079" getAvgObsoleteLNSizeNotCounted="NaN"/> recalcFileSummary=<summary totalCount="25786" totalSize="9999606" totalINCount="9732" totalINSize="1766153" totalLNCount="9863" totalLNSize="7862256" maxLNSize="0" obsoleteINCount="9696" obsoleteLNCount="7916" obsoleteLNSize="4902079" obsoleteLNSizeCounted="7916" getObsoleteSize="7032895" getObsoleteINSize="1759619" getObsoleteLNSize="4902079" getMaxObsoleteSize="7032895" getMaxObsoleteLNSize="4902079" getAvgObsoleteLNSizeNotCounted="NaN"/> lnSizeCorrection=NaN newLnSizeCorrection=NaN estimatedUtilization=30 correctedUtilization=30 recalcUtilization=30 correctionRejected=false

                 

                2014-04-09 07:31:35.570 UTC Informazioni [C:\Data] CleanerRun 3 ends on file 0x1 probe=false invokedFromDaemon=true finished=false fileDeleted=false nEntriesRead=0 nINsObsolete=5033 nINsCleaned=27 nINsDead=9 nINsMigrated=18 nBINDeltasObsolete=1852 nBINDeltasCleaned=0 nBINDeltasDead=0 nBINDeltasMigrated=0 nLNsObsolete=6433 nLNsCleaned=2071 nLNsDead=491 nLNsMigrated=1580 nLNsMarked=0 nLNQueueHits=969 nLNsLocked=0 logSummary=<CleanerLogSummary endFileNumAtLastAdjustment="0x12" initialAdjustments="3" recentLNSizesAndCounts=""> inSummary=<INSummary totalINCount="5060" totalINSize="741727" totalBINDeltaCount="1852" totalBINDeltaSize="180079" obsoleteINCount="5033" obsoleteINSize="712452" obsoleteBINDeltaCount="1852" obsoleteBINDeltaSize="180079"/> estFileSummary=<summary totalCount="24205" totalSize="9995572" totalINCount="8598" totalINSize="1172511" totalLNCount="10238" totalLNSize="8535477" maxLNSize="25936" obsoleteINCount="8576" obsoleteLNCount="8316" obsoleteLNSize="4473708" obsoleteLNSizeCounted="7722" getObsoleteSize="6889741" getObsoleteINSize="1169510" getObsoleteLNSize="5432647" getMaxObsoleteSize="9961819" getMaxObsoleteLNSize="8504725" getAvgObsoleteLNSizeNotCounted="1614.3756"/> recalcFileSummary=<summary totalCount="19742" totalSize="8284968" totalINCount="6912" totalINSize="921806" totalLNCount="8513" totalLNSize="7132466" maxLNSize="0" obsoleteINCount="6885" obsoleteLNCount="6433" obsoleteLNSize="3643404" obsoleteLNSizeCounted="6433" getObsoleteSize="4792305" getObsoleteINSize="918205" getObsoleteLNSize="3643404" getMaxObsoleteSize="4792305" getMaxObsoleteLNSize="3643404" getAvgObsoleteLNSizeNotCounted="NaN"/> lnSizeCorrection=NaN newLnSizeCorrection=NaN estimatedUtilization=31 correctedUtilization=31 recalcUtilization=42 correctionRejected=false

                 

                2014-04-09 07:35:48.907 UTC Informazioni [C:\Data] Chose lowest utilized file for cleaning. fileChosen: 0x1 lnSizeCorrectionFactor: NaN totalUtilization: 25 bestFileUtilization: 2 isProbe: false

                 

                2014-04-09 07:35:50.401 UTC Informazioni [C:\Data] CleanerRun 1 ends on file 0x1 probe=false invokedFromDaemon=true finished=true fileDeleted=false nEntriesRead=20050 nINsObsolete=6299 nINsCleaned=10 nINsDead=9 nINsMigrated=1 nBINDeltasObsolete=2289 nBINDeltasCleaned=0 nBINDeltasDead=0 nBINDeltasMigrated=0 nLNsObsolete=9405 nLNsCleaned=833 nLNsDead=491 nLNsMigrated=342 nLNsMarked=0 nLNQueueHits=218 nLNsLocked=0 logSummary=<CleanerLogSummary endFileNumAtLastAdjustment="0x3" initialAdjustments="3" recentLNSizesAndCounts=""> inSummary=<INSummary totalINCount="6309" totalINSize="949269" totalBINDeltaCount="2289" totalBINDeltaSize="223242" obsoleteINCount="6299" obsoleteINSize="938732" obsoleteBINDeltaCount="2289" obsoleteBINDeltaSize="223242"/> estFileSummary=<summary totalCount="24205" totalSize="9995572" totalINCount="8598" totalINSize="1172511" totalLNCount="10238" totalLNSize="8535477" maxLNSize="25936" obsoleteINCount="8597" obsoleteLNCount="9896" obsoleteLNSize="7886075" obsoleteLNSizeCounted="9302" getObsoleteSize="9758153" getObsoleteINSize="1172374" getObsoleteLNSize="8298195" getMaxObsoleteSize="9989963" getMaxObsoleteLNSize="8530005" getAvgObsoleteLNSizeNotCounted="693.80554"/> recalcFileSummary=<summary totalCount="24205" totalSize="9995572" totalINCount="8598" totalINSize="1172511" totalLNCount="10238" totalLNSize="8535477" maxLNSize="0" obsoleteINCount="8588" obsoleteLNCount="9405" obsoleteLNSize="7896179" obsoleteLNSizeCounted="9405" getObsoleteSize="9354910" getObsoleteINSize="1171147" getObsoleteLNSize="7896179" getMaxObsoleteSize="9354910" getMaxObsoleteLNSize="7896179" getAvgObsoleteLNSizeNotCounted="NaN"/> lnSizeCorrection=NaN newLnSizeCorrection=NaN estimatedUtilization=2 correctedUtilization=2 recalcUtilization=6 correctionRejected=true

                 

                2014-04-10 08:06:08.826 UTC Informazioni [C:\Data] CleanerRun 2 ends on file 0x4 probe=false invokedFromDaemon=false finished=true fileDeleted=false nEntriesRead=2607 nINsObsolete=866 nINsCleaned=22 nINsDead=0 nINsMigrated=22 nBINDeltasObsolete=319 nBINDeltasCleaned=8 nBINDeltasDead=0 nBINDeltasMigrated=8 nLNsObsolete=938 nLNsCleaned=268 nLNsDead=2 nLNsMigrated=266 nLNsMarked=0 nLNQueueHits=172 nLNsLocked=0 logSummary=<CleanerLogSummary endFileNumAtLastAdjustment="0x12" initialAdjustments="4" recentLNSizesAndCounts=""> inSummary=<INSummary totalINCount="888" totalINSize="158144" totalBINDeltaCount="327" totalBINDeltaSize="33114" obsoleteINCount="866" obsoleteINSize="146081" obsoleteBINDeltaCount="319" obsoleteBINDeltaSize="32759"/> estFileSummary=<summary totalCount="3227" totalSize="1179496" totalINCount="1215" totalINSize="191258" totalLNCount="1206" totalLNSize="941074" maxLNSize="26995" obsoleteINCount="1185" obsoleteLNCount="938" obsoleteLNSize="585647" obsoleteLNSizeCounted="938" getObsoleteSize="819346" getObsoleteINSize="186535" getObsoleteLNSize="585647" getMaxObsoleteSize="819346" getMaxObsoleteLNSize="585647" getAvgObsoleteLNSizeNotCounted="NaN"/> recalcFileSummary=<summary totalCount="3227" totalSize="1179496" totalINCount="1215" totalINSize="191258" totalLNCount="1206" totalLNSize="941074" maxLNSize="0" obsoleteINCount="1185" obsoleteLNCount="938" obsoleteLNSize="585647" obsoleteLNSizeCounted="938" getObsoleteSize="819346" getObsoleteINSize="186535" getObsoleteLNSize="585647" getMaxObsoleteSize="819346" getMaxObsoleteLNSize="585647" getAvgObsoleteLNSizeNotCounted="NaN"/> lnSizeCorrection=NaN newLnSizeCorrection=NaN estimatedUtilization=31 correctedUtilization=31 recalcUtilization=31 correctionRejected=false

                 

                2014-04-10 08:06:09.422 UTC Informazioni [C:\Data] CleanerRun 3 ends on file 0x3 probe=false invokedFromDaemon=false finished=true fileDeleted=false nEntriesRead=13355 nINsObsolete=2307 nINsCleaned=55 nINsDead=25 nINsMigrated=30 nBINDeltasObsolete=809 nBINDeltasCleaned=0 nBINDeltasDead=0 nBINDeltasMigrated=0 nLNsObsolete=6512 nLNsCleaned=3224 nLNsDead=1376 nLNsMigrated=1848 nLNsMarked=0 nLNQueueHits=925 nLNsLocked=0 logSummary=<CleanerLogSummary endFileNumAtLastAdjustment="0x12" initialAdjustments="4" recentLNSizesAndCounts=""> inSummary=<INSummary totalINCount="2362" totalINSize="494278" totalBINDeltaCount="809" totalBINDeltaSize="80722" obsoleteINCount="2307" obsoleteINSize="438870" obsoleteBINDeltaCount="809" obsoleteBINDeltaSize="80722"/> estFileSummary=<summary totalCount="14868" totalSize="9999931" totalINCount="3171" totalINSize="575000" totalLNCount="9736" totalLNSize="9314427" maxLNSize="27305" obsoleteINCount="3141" obsoleteLNCount="7887" obsoleteLNSize="1483135" obsoleteLNSizeCounted="5245" getObsoleteSize="6770251" getObsoleteINSize="569560" getObsoleteLNSize="6090187" getMaxObsoleteSize="9964907" getMaxObsoleteLNSize="9284843" getAvgObsoleteLNSizeNotCounted="1743.7747"/> recalcFileSummary=<summary totalCount="14868" totalSize="9999931" totalINCount="3171" totalINSize="575000" totalLNCount="9736" totalLNSize="9314427" maxLNSize="0" obsoleteINCount="3116" obsoleteLNCount="6512" obsoleteLNSize="1609846" obsoleteLNSizeCounted="6512" getObsoleteSize="2285376" getObsoleteINSize="565026" getObsoleteLNSize="1609846" getMaxObsoleteSize="2285376" getMaxObsoleteLNSize="1609846" getAvgObsoleteLNSizeNotCounted="NaN"/> lnSizeCorrection=NaN newLnSizeCorrection=NaN estimatedUtilization=32 correctedUtilization=32 recalcUtilization=77 correctionRejected=true

                 

                2014-04-12 11:08:45.537 UTC Informazioni [C:\Data] Chose lowest utilized file for cleaning. fileChosen: 0x4 lnSizeCorrectionFactor: NaN totalUtilization: 47 bestFileUtilization: 65 isProbe: false

                 

                2014-04-12 11:08:46.837 UTC Informazioni [C:\Data] CleanerRun 1 ends on file 0x4 probe=false invokedFromDaemon=true finished=true fileDeleted=false nEntriesRead=7198 nINsObsolete=1568 nINsCleaned=34 nINsDead=16 nINsMigrated=18 nBINDeltasObsolete=561 nBINDeltasCleaned=0 nBINDeltasDead=0 nBINDeltasMigrated=0 nLNsObsolete=2504 nLNsCleaned=2212 nLNsDead=394 nLNsMigrated=1818 nLNsMarked=0 nLNQueueHits=843 nLNsLocked=0 logSummary=<CleanerLogSummary endFileNumAtLastAdjustment="0x13" initialAdjustments="4" recentLNSizesAndCounts=""> inSummary=<INSummary totalINCount="1602" totalINSize="316776" totalBINDeltaCount="561" totalBINDeltaSize="55333" obsoleteINCount="1568" obsoleteINSize="275164" obsoleteBINDeltaCount="561" obsoleteBINDeltaSize="55333"/> estFileSummary=<summary totalCount="8263" totalSize="9999861" totalINCount="2163" totalINSize="372109" totalLNCount="4716" totalLNSize="9548449" maxLNSize="27305" obsoleteINCount="2137" obsoleteLNCount="2896" obsoleteLNSize="1351391" obsoleteLNSizeCounted="2428" getObsoleteSize="3475000" getObsoleteINSize="367636" getObsoleteLNSize="3028061" getMaxObsoleteSize="9966268" getMaxObsoleteLNSize="9519329" getAvgObsoleteLNSizeNotCounted="3582.6301"/> recalcFileSummary=<summary totalCount="8263" totalSize="9999861" totalINCount="2163" totalINSize="372109" totalLNCount="4716" totalLNSize="9548449" maxLNSize="0" obsoleteINCount="2129" obsoleteLNCount="2504" obsoleteLNSize="1358720" obsoleteLNSizeCounted="2504" getObsoleteSize="1804282" getObsoleteINSize="366259" getObsoleteLNSize="1358720" getMaxObsoleteSize="1804282" getMaxObsoleteLNSize="1358720" getAvgObsoleteLNSizeNotCounted="NaN"/> lnSizeCorrection=NaN newLnSizeCorrection=NaN estimatedUtilization=65 correctedUtilization=65 recalcUtilization=82 correctionRejected=true

                 

                2014-04-12 18:40:44.071 UTC Informazioni [C:\Data] Chose lowest utilized file for cleaning. fileChosen: 0x7 lnSizeCorrectionFactor: NaN totalUtilization: 49 bestFileUtilization: 29 isProbe: false

                 

                2014-04-12 18:40:44.416 UTC Informazioni [C:\Data] CleanerRun 2 ends on file 0x7 probe=false invokedFromDaemon=true finished=true fileDeleted=false nEntriesRead=6596 nINsObsolete=2207 nINsCleaned=22 nINsDead=0 nINsMigrated=22 nBINDeltasObsolete=812 nBINDeltasCleaned=3 nBINDeltasDead=0 nBINDeltasMigrated=3 nLNsObsolete=2509 nLNsCleaned=617 nLNsDead=0 nLNsMigrated=617 nLNsMarked=0 nLNQueueHits=370 nLNsLocked=0 logSummary=<CleanerLogSummary endFileNumAtLastAdjustment="0x13" initialAdjustments="4" recentLNSizesAndCounts=""> inSummary=<INSummary totalINCount="2229" totalINSize="587613" totalBINDeltaCount="815" totalBINDeltaSize="85032" obsoleteINCount="2207" obsoleteINSize="570161" obsoleteBINDeltaCount="812" obsoleteBINDeltaSize="84688"/> estFileSummary=<summary totalCount="8047" totalSize="3450653" totalINCount="3042" totalINSize="669543" totalLNCount="3124" totalLNSize="2659842" maxLNSize="21530" obsoleteINCount="3016" obsoleteLNCount="2508" obsoleteLNSize="1650113" obsoleteLNSizeCounted="2508" getObsoleteSize="2435201" getObsoleteINSize="663820" getObsoleteLNSize="1650113" getMaxObsoleteSize="2435201" getMaxObsoleteLNSize="1650113" getAvgObsoleteLNSizeNotCounted="NaN"/> recalcFileSummary=<summary totalCount="8054" totalSize="3454249" totalINCount="3044" totalINSize="672645" totalLNCount="3126" totalLNSize="2660044" maxLNSize="0" obsoleteINCount="3019" obsoleteLNCount="2509" obsoleteLNSize="1650215" obsoleteLNSizeCounted="2509" getObsoleteSize="2438895" getObsoleteINSize="667120" getObsoleteLNSize="1650215" getMaxObsoleteSize="2438895" getMaxObsoleteLNSize="1650215" getAvgObsoleteLNSizeNotCounted="NaN"/> lnSizeCorrection=NaN newLnSizeCorrection=NaN estimatedUtilization=29 correctedUtilization=29 recalcUtilization=29 correctionRejected=true

                 

                2014-04-12 18:43:39.556 UTC Avvertenza [C:\Data] Cleaner deleteSafeToDeleteFiles Log file 0x7 could not be deleted. This operation will be retried at the next checkpoint. State: files = {7=status = SAFE_TO_DELETE dbIds = [0, 2, 3, 4, 5, 7, 8] lastVlsn = -1} pendingLNs = {} pendingDBs = [] anyPendingDuringCheckpoint = false lowUtilizationFiles = []

                ... 742 times ...

                2014-04-13 17:05:27.069 UTC Avvertenza [C:\Data] Cleaner deleteSafeToDeleteFiles Log file 0x7 could not be deleted. This operation will be retried at the next checkpoint. State: files = {7=status = SAFE_TO_DELETE dbIds = [0, 2, 3, 4, 5, 7, 8] lastVlsn = -1} pendingLNs = {} pendingDBs = [] anyPendingDuringCheckpoint = false lowUtilizationFiles = []

                 

                2014-04-14 12:30:13.612 UTC Informazioni [C:\Data] Chose lowest utilized file for cleaning. fileChosen: 0x5 lnSizeCorrectionFactor: NaN totalUtilization: 49 bestFileUtilization: 30 isProbe: false

                 

                2014-04-14 12:30:13.612 UTC Grave [C:\Data]

                com.sleepycat.je.EnvironmentFailureException: Environment invalid because of previous exception: (JE 5.0.103) C:\Data fetchTarget of 0x7/0x44ef4d parent IN=86 IN class="com".sleepycat.je.tree.BIN lastFullVersion=0x6/0x8c04c4 lastLoggedVersion=0x8/0x26436a parent.getDirty()=false state=2 LOG_FILE_NOT_FOUND: Log file missing, log is likely invalid. Environment is invalid and must be closed.

                    at com.sleepycat.je.tree.IN.fetchTarget(IN.java:1442)

                    at com.sleepycat.je.tree.BIN.fetchTarget(BIN.java:1250)

                    at com.sleepycat.je.dbi.CursorImpl.fetchCurrent(CursorImpl.java:2280)

                    at com.sleepycat.je.dbi.CursorImpl.getCurrentAlreadyLatched(CursorImpl.java:1480)

                    at com.sleepycat.je.dbi.CursorImpl.getNext(CursorImpl.java:1607)

                    at com.sleepycat.je.cleaner.UtilizationProfile.getObsoleteDetail(UtilizationProfile.java:639)

                    at com.sleepycat.je.cleaner.FileProcessor.processFile(FileProcessor.java:442)

                    at com.sleepycat.je.cleaner.FileProcessor.doClean(FileProcessor.java:290)

                    at com.sleepycat.je.cleaner.FileProcessor.onWakeup(FileProcessor.java:148)

                    at com.sleepycat.je.utilint.DaemonThread.run(DaemonThread.java:148)

                    at java.lang.Thread.run(Unknown Source)

                Caused by: java.io.FileNotFoundException: C:\Data\00000007.jdb (Impossibile trovare il file specificato)

                    at java.io.RandomAccessFile.open(Native Method)

                    at java.io.RandomAccessFile.<init>(Unknown Source)

                    at java.io.RandomAccessFile.<init>(Unknown Source)

                    at com.sleepycat.je.log.FileManager$DefaultRandomAccessFile.<init>(FileManager.java:3181)

                    at com.sleepycat.je.log.FileManager$6.createFile(FileManager.java:3209)

                    at com.sleepycat.je.log.FileManager.openFileHandle(FileManager.java:1278)

                    at com.sleepycat.je.log.FileManager.getFileHandle(FileManager.java:1150)

                    at com.sleepycat.je.log.LogManager.getLogSource(LogManager.java:1224)

                    at com.sleepycat.je.log.LogManager.getLogEntry(LogManager.java:928)

                    at com.sleepycat.je.log.LogManager.getLogEntryAllowInvisibleAtRecovery(LogManager.java:892)

                    at com.sleepycat.je.tree.IN.fetchTarget(IN.java:1425)

                    ... 10 more

                 

                2014-04-14 12:30:13.620 UTC Grave [C:\Data] checkpointId=7003

                com.sleepycat.je.EnvironmentFailureException: (JE 5.0.103) Environment must be closed, caused by: com.sleepycat.je.EnvironmentFailureException: Environment invalid because of previous exception: (JE 5.0.103) C:\Data fetchTarget of 0x7/0x44ef4d parent IN=86 IN class="com".sleepycat.je.tree.BIN lastFullVersion=0x6/0x8c04c4 lastLoggedVersion=0x8/0x26436a parent.getDirty()=false state=2 LOG_FILE_NOT_FOUND: Log file missing, log is likely invalid. Environment is invalid and must be closed.

                    at com.sleepycat.je.EnvironmentFailureException.wrapSelf(EnvironmentFailureException.java:246)

                    at com.sleepycat.je.dbi.EnvironmentImpl.checkIfInvalid(EnvironmentImpl.java:1618)

                    at com.sleepycat.je.log.LogManager.serialLog(LogManager.java:552)

                    at com.sleepycat.je.log.LogManager.logItems(LogManager.java:508)

                    at com.sleepycat.je.log.LogManager.multiLog(LogManager.java:410)

                    at com.sleepycat.je.log.LogManager.log(LogManager.java:350)

                    at com.sleepycat.je.log.LogManager.log(LogManager.java:339)

                    at com.sleepycat.je.log.LogManager.log(LogManager.java:230)

                    at com.sleepycat.je.dbi.EnvironmentImpl.logMapTreeRoot(EnvironmentImpl.java:1252)

                    at com.sleepycat.je.recovery.DirtyINMap.flushRoot(DirtyINMap.java:571)

                    at com.sleepycat.je.recovery.Checkpointer.doCheckpoint(Checkpointer.java:744)

                    at com.sleepycat.je.dbi.EnvironmentImpl.invokeCheckpoint(EnvironmentImpl.java:2072)

                    at com.sleepycat.je.Environment.sync(Environment.java:1556)

                    at it.dataon.cashregister.b.b.a(CRDatabase.java:140)

                    at it.dataon.cashregister.App.A(App.java:9512)

                    at it.dataon.cashregister.App.a(App.java:9209)

                    at it.dataon.cashregister.z.run(App.java:9204)

                    at java.awt.event.InvocationEvent.dispatch(Unknown Source)

                    at java.awt.EventQueue.dispatchEventImpl(Unknown Source)

                    at java.awt.EventQueue.access$200(Unknown Source)

                    at java.awt.EventQueue$3.run(Unknown Source)

                    at java.awt.EventQueue$3.run(Unknown Source)

                    at java.security.AccessController.doPrivileged(Native Method)

                    at java.security.ProtectionDomain$1.doIntersectionPrivilege(Unknown Source)

                    at java.awt.EventQueue.dispatchEvent(Unknown Source)

                    at java.awt.EventDispatchThread.pumpOneEventForFilters(Unknown Source)

                    at java.awt.EventDispatchThread.pumpEventsForFilter(Unknown Source)

                    at java.awt.EventDispatchThread.pumpEventsForHierarchy(Unknown Source)

                    at java.awt.EventDispatchThread.pumpEvents(Unknown Source)

                    at java.awt.EventDispatchThread.pumpEvents(Unknown Source)

                    at java.awt.EventDispatchThread.run(Unknown Source)

                Caused by: com.sleepycat.je.EnvironmentFailureException: Environment invalid because of previous exception: (JE 5.0.103) C:\Data fetchTarget of 0x7/0x44ef4d parent IN=86 IN class="com".sleepycat.je.tree.BIN lastFullVersion=0x6/0x8c04c4 lastLoggedVersion=0x8/0x26436a parent.getDirty()=false state=2 LOG_FILE_NOT_FOUND: Log file missing, log is likely invalid. Environment is invalid and must be closed.

                    at com.sleepycat.je.tree.IN.fetchTarget(IN.java:1442)

                    at com.sleepycat.je.tree.BIN.fetchTarget(BIN.java:1250)

                    at com.sleepycat.je.dbi.CursorImpl.fetchCurrent(CursorImpl.java:2280)

                    at com.sleepycat.je.dbi.CursorImpl.getCurrentAlreadyLatched(CursorImpl.java:1480)

                    at com.sleepycat.je.dbi.CursorImpl.getNext(CursorImpl.java:1607)

                    at com.sleepycat.je.cleaner.UtilizationProfile.getObsoleteDetail(UtilizationProfile.java:639)

                    at com.sleepycat.je.cleaner.FileProcessor.processFile(FileProcessor.java:442)

                    at com.sleepycat.je.cleaner.FileProcessor.doClean(FileProcessor.java:290)

                    at com.sleepycat.je.cleaner.FileProcessor.onWakeup(FileProcessor.java:148)

                    at com.sleepycat.je.utilint.DaemonThread.run(DaemonThread.java:148)

                    at java.lang.Thread.run(Unknown Source)

                Caused by: java.io.FileNotFoundException: C:\Data\00000007.jdb (Impossibile trovare il file specificato)

                    at java.io.RandomAccessFile.open(Native Method)

                    at java.io.RandomAccessFile.<init>(Unknown Source)

                    at java.io.RandomAccessFile.<init>(Unknown Source)

                    at com.sleepycat.je.log.FileManager$DefaultRandomAccessFile.<init>(FileManager.java:3181)

                    at com.sleepycat.je.log.FileManager$6.createFile(FileManager.java:3209)

                    at com.sleepycat.je.log.FileManager.openFileHandle(FileManager.java:1278)

                    at com.sleepycat.je.log.FileManager.getFileHandle(FileManager.java:1150)

                    at com.sleepycat.je.log.LogManager.getLogSource(LogManager.java:1224)

                    at com.sleepycat.je.log.LogManager.getLogEntry(LogManager.java:928)

                    at com.sleepycat.je.log.LogManager.getLogEntryAllowInvisibleAtRecovery(LogManager.java:892)

                    at com.sleepycat.je.tree.IN.fetchTarget(IN.java:1425)

                    ... 10 more

                 

                2014-04-14 12:30:13.620 UTC Informazioni [C:\Data] CleanerRun 3 ends on file 0x5 probe=false invokedFromDaemon=true finished=false fileDeleted=false nEntriesRead=0 nINsObsolete=0 nINsCleaned=0 nINsDead=0 nINsMigrated=0 nBINDeltasObsolete=0 nBINDeltasCleaned=0 nBINDeltasDead=0 nBINDeltasMigrated=0 nLNsObsolete=0 nLNsCleaned=0 nLNsDead=0 nLNsMigrated=0 nLNsMarked=0 nLNQueueHits=0 nLNsLocked=0 logSummary=<CleanerLogSummary endFileNumAtLastAdjustment="0x13" initialAdjustments="4" recentLNSizesAndCounts=""> inSummary=<INSummary totalINCount="0" totalINSize="0" totalBINDeltaCount="0" totalBINDeltaSize="0" obsoleteINCount="0" obsoleteINSize="0" obsoleteBINDeltaCount="0" obsoleteBINDeltaSize="0"/> estFileSummary=<summary totalCount="24533" totalSize="9997544" totalINCount="9274" totalINSize="1716570" totalLNCount="9485" totalLNSize="7941247" maxLNSize="21215" obsoleteINCount="9247" obsoleteLNCount="7641" obsoleteLNSize="4906917" obsoleteLNSizeCounted="7629" getObsoleteSize="6977834" getObsoleteINSize="1711572" getObsoleteLNSize="4926535" getMaxObsoleteSize="7212796" getMaxObsoleteLNSize="5161497" getAvgObsoleteLNSizeNotCounted="1634.8761"/> recalcFileSummary=<summary totalCount="0" totalSize="0" totalINCount="0" totalINSize="0" totalLNCount="0" totalLNSize="0" maxLNSize="0" obsoleteINCount="0" obsoleteLNCount="0" obsoleteLNSize="0" obsoleteLNSizeCounted="0" getObsoleteSize="0" getObsoleteINSize="0" getObsoleteLNSize="0" getMaxObsoleteSize="0" getMaxObsoleteLNSize="0" getAvgObsoleteLNSizeNotCounted="NaN"/> lnSizeCorrection=NaN newLnSizeCorrection=NaN estimatedUtilization=30 correctedUtilization=30 recalcUtilization=0 correctionRejected=false

                • 5. Re: Log file missing, log is likely invalid. Environment is invalid and must be closed.
                  Greybird-Oracle

                  It looks like the new error is for file 00000007.jdb.  Was this file deleted before you upgraded?

                   

                  In general, when this sort of problem happens, you can't just upgrade to solve it.  In addition to upgrading, you'll need to restore from a backup where the problem was not present, or recreate your data set starting with a new empty Environment directory.

                   

                  --mark

                  • 6. Re: Log file missing, log is likely invalid. Environment is invalid and must be closed.
                    Greybird-Oracle

                    Then I'm afraid it is a new problem.  Since the problem is reproducible, please do the following so that we can debug it.

                     

                    1) Start with a new empty Environment directory.

                     

                    2) Before opening the environment, set EnvironmentConfig.CLEANER_EXPUNGE to false so that .jdb files will be renamed to .del rather than deleted:

                     

                       envConfig.setConfigParam(EnvironmentConfig.CLEANER_EXPUNGE, "false");

                     

                    3) Reproduce the problem.

                     

                    Then contact me over email.  I'll ask you to send me the .jdb and .del files, as well as some other info.  My email is mark.hayes at the obvious .com.

                     

                    Thanks,

                    --mark

                    • 7. Re: Log file missing, log is likely invalid. Environment is invalid and must be closed.
                      abc8ef96-748c-4cc0-a0ca-63a66a0da292

                      I created a new empty Environment, the error happened with new data.

                       

                       

                      It's possible call Environment.sync() during a transaction just before calling Transaction.commit()?

                      This can cause the problem?

                      • 8. Re: Log file missing, log is likely invalid. Environment is invalid and must be closed.
                        Greybird-Oracle

                        Calling sync() should not cause the problem, but perhaps it is related.  Please try to reproduce the problem as described in the previous email and then contact me.

                        Thanks,

                        --mark