Uploaded image for project: 'Jackrabbit Oak'
  1. Jackrabbit Oak
  2. OAK-10422

ReadOnlyStoreBlobReferencesTest flaky

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Open
    • Major
    • Resolution: Unresolved
    • 1.22.16, 1.56.0
    • None
    • segment-tar
    • None

    Description

      Seen both in trunk and 1.22_

      -------------------------------------------------------------------------------
      Test set: org.apache.jackrabbit.oak.segment.ReadOnlyStoreBlobReferencesTest
      -------------------------------------------------------------------------------
      Tests run: 2, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 0.487 s <<< FAILURE! - in org.apache.jackrabbit.oak.segment.ReadOnlyStoreBlobReferencesTest
      collectReferencesAfterGC(org.apache.jackrabbit.oak.segment.ReadOnlyStoreBlobReferencesTest)  Time elapsed: 0.369 s  <<< FAILURE!
      java.lang.AssertionError: Read only store visible references different expected:<0> but was:<1>
              at org.apache.jackrabbit.oak.segment.ReadOnlyStoreBlobReferencesTest.assertReferences(ReadOnlyStoreBlobReferencesTest.java:140)
              at org.apache.jackrabbit.oak.segment.ReadOnlyStoreBlobReferencesTest.collectReferencesAfterGC(ReadOnlyStoreBlobReferencesTest.java:98)
      
      19:14:58.407 INFO  [main] FileStoreBuilder.java:427         Creating file store FileStoreBuilder{version=null, directory=target\junit259439335829743064\segmentstore, blobStore=DataStore backed BlobStore [org.apache.jackrabbit.oak.plugins.blob.datastore.OakFileDataStore], maxFileSize=256, segmentCacheSize=256, stringCacheSize=256, templateCacheSize=64, stringDeduplicationCacheSize=15000, templateDeduplicationCacheSize=3000, nodeDeduplicationCacheSize=1048576, memoryMapping=true, offHeapAccess=false, gcOptions=SegmentGCOptions{paused=false, estimationDisabled=false, gcSizeDeltaEstimation=0, retryCount=5, forceTimeout=60, retainedGenerations=2, gcType=FULL}}
      19:14:58.411 INFO  [main] FileStore.java:231                TarMK opened at target\junit259439335829743064\segmentstore, mmap=true, offHeapAccess=false, size=0 B (0 bytes)
      19:14:58.414 INFO  [main] SegmentNodeStore.java:133         Creating segment node store SegmentNodeStoreBuilder{blobStore=DataStore backed BlobStore [org.apache.jackrabbit.oak.plugins.blob.datastore.OakFileDataStore]}
      19:14:58.414 INFO  [main] LockBasedScheduler.java:206       Initializing SegmentNodeStore with the commitFairLock option enabled.
      19:14:58.477 INFO  [main] FileStore.java:491                TarMK closed: target\junit259439335829743064\segmentstore
      19:14:58.478 INFO  [main] FileStoreBuilder.java:467         Creating file store FileStoreBuilder{version=null, directory=target\junit259439335829743064\segmentstore, blobStore=DataStore backed BlobStore [org.apache.jackrabbit.oak.plugins.blob.datastore.OakFileDataStore], maxFileSize=256, segmentCacheSize=256, stringCacheSize=256, templateCacheSize=64, stringDeduplicationCacheSize=15000, templateDeduplicationCacheSize=3000, nodeDeduplicationCacheSize=1048576, memoryMapping=true, offHeapAccess=false, gcOptions=SegmentGCOptions{paused=false, estimationDisabled=false, gcSizeDeltaEstimation=1073741824, retryCount=5, forceTimeout=60, retainedGenerations=2, gcType=FULL}}
      19:14:58.494 INFO  [main] ReadOnlyFileStore.java:85         TarMK ReadOnly opened: target\junit259439335829743064\segmentstore (mmap=true)
      19:14:58.528 INFO  [main] ReadOnlyFileStore.java:140        TarMK closed: target\junit259439335829743064\segmentstore
      19:14:58.532 INFO  [main] FileStoreBuilder.java:427         Creating file store FileStoreBuilder{version=null, directory=target\junit5910520254964068785\segmentstore, blobStore=DataStore backed BlobStore [org.apache.jackrabbit.oak.plugins.blob.datastore.OakFileDataStore], maxFileSize=256, segmentCacheSize=256, stringCacheSize=256, templateCacheSize=64, stringDeduplicationCacheSize=15000, templateDeduplicationCacheSize=3000, nodeDeduplicationCacheSize=1048576, memoryMapping=true, offHeapAccess=false, gcOptions=SegmentGCOptions{paused=false, estimationDisabled=false, gcSizeDeltaEstimation=0, retryCount=5, forceTimeout=60, retainedGenerations=2, gcType=FULL}}
      19:14:58.536 INFO  [main] FileStore.java:231                TarMK opened at target\junit5910520254964068785\segmentstore, mmap=true, offHeapAccess=false, size=0 B (0 bytes)
      19:14:58.538 INFO  [main] SegmentNodeStore.java:133         Creating segment node store SegmentNodeStoreBuilder{blobStore=DataStore backed BlobStore [org.apache.jackrabbit.oak.plugins.blob.datastore.OakFileDataStore]}
      19:14:58.538 INFO  [main] LockBasedScheduler.java:206       Initializing SegmentNodeStore with the commitFairLock option enabled.
      19:14:58.574 INFO  [main] FileStore.java:491                TarMK closed: target\junit5910520254964068785\segmentstore
      19:14:58.581 INFO  [main] FileStoreBuilder.java:427         Creating file store FileStoreBuilder{version=null, directory=target\junit5910520254964068785\segmentstore, blobStore=DataStore backed BlobStore [org.apache.jackrabbit.oak.plugins.blob.datastore.OakFileDataStore], maxFileSize=256, segmentCacheSize=256, stringCacheSize=256, templateCacheSize=64, stringDeduplicationCacheSize=15000, templateDeduplicationCacheSize=3000, nodeDeduplicationCacheSize=1048576, memoryMapping=true, offHeapAccess=false, gcOptions=SegmentGCOptions{paused=false, estimationDisabled=false, gcSizeDeltaEstimation=1, retryCount=5, forceTimeout=60, retainedGenerations=1, gcType=FULL}}
      19:14:58.591 INFO  [main] FileStore.java:231                TarMK opened at target\junit5910520254964068785\segmentstore, mmap=true, offHeapAccess=false, size=6.1 kB (6144 bytes)
      19:14:58.592 INFO  [main] SegmentNodeStore.java:133         Creating segment node store SegmentNodeStoreBuilder{blobStore=DataStore backed BlobStore [org.apache.jackrabbit.oak.plugins.blob.datastore.OakFileDataStore]}
      19:14:58.592 INFO  [main] LockBasedScheduler.java:206       Initializing SegmentNodeStore with the commitFairLock option enabled.
      19:14:58.603 INFO  [main] LoggingGCMonitor.java:44          TarMK GC #1: started
      19:14:58.603 INFO  [main] LoggingGCMonitor.java:44          TarMK GC #1: estimation started
      19:14:58.603 INFO  [main] LoggingGCMonitor.java:44          TarMK GC #1: estimation completed in 447,1 ?s (0 ms). Estimation skipped because of missing gc journal data (expected on first run)
      19:14:58.605 INFO  [main] LoggingGCMonitor.java:44          TarMK GC #1: setting up a listener to cancel compaction if available memory on pool 'PS Old Gen' drops below 53.7 MB (53713305 bytes) / 15%.
      19:14:58.607 INFO  [main] LoggingGCMonitor.java:44          TarMK GC #1: available memory level 328.7 MB (328709344 bytes) is good, expecting at least 53.7 MB (53713305 bytes)
      19:14:58.607 INFO  [main] LoggingGCMonitor.java:44          TarMK GC #1: pre-compaction cleanup started
      19:14:58.634 INFO  [main] LoggingGCMonitor.java:44          TarMK GC #1: cleanup marking files for deletion: none
      19:14:58.635 INFO  [main] LoggingGCMonitor.java:44          TarMK GC #1: pre-compaction cleanup completed in 28,91 ms (28 ms). Post cleanup size is 11.3 kB (11264 bytes) and space reclaimed 0 B (0 bytes).
      19:14:58.635 INFO  [main] LoggingGCMonitor.java:44          TarMK GC #1: running full compaction
      19:14:58.635 INFO  [main] LoggingGCMonitor.java:44          TarMK GC #1: compaction started, gc options=SegmentGCOptions{paused=false, estimationDisabled=false, gcSizeDeltaEstimation=1, retryCount=5, forceTimeout=60, retainedGenerations=1, gcType=FULL}, current generation=GCGeneration{generation=0,fullGeneration=0,isCompacted=false}, new generation=GCGeneration{generation=1,fullGeneration=1,isCompacted=true}
      19:14:58.635 INFO  [main] LoggingGCMonitor.java:44          unable to estimate number of nodes for compaction, missing gc history.
      19:14:58.635 INFO  [main] LoggingGCMonitor.java:44          TarMK GC #1: compacting root.
      19:14:58.638 INFO  [main] LoggingGCMonitor.java:44          TarMK GC #1: compaction cycle 0 completed in 2,860 ms (2 ms). Compacted a51c8aa2-25ef-4081-a3b2-71cb4c16d4ba.00000003 to 2dd377a5-349f-4743-ad6f-36fc9bed5b74.00000007
      19:14:58.643 INFO  [main] LoggingGCMonitor.java:44          TarMK GC #1: compaction succeeded in 7,975 ms (7 ms), after 0 cycles
      19:14:58.645 INFO  [main] LoggingGCMonitor.java:44          TarMK GC #1: cleanup started using reclaimer (full generation older than 1.1, with 1 retained generations)
      19:14:58.701 INFO  [main] LoggingGCMonitor.java:44          TarMK GC #1: cleanup marking files for deletion: data00000a.tar,data00001a.tar,data00002a.tar
      19:14:58.703 INFO  [main] LoggingGCMonitor.java:44          TarMK GC #1: cleanup completed in 57,35 ms (57 ms). Post cleanup size is 5.1 kB (5120 bytes) and space reclaimed 12.3 kB (12288 bytes).
      19:14:58.735 ERROR [main] SegmentTarManager.java:143        Can't remove archive data00000a.tar
      java.nio.file.FileSystemException: target\junit5910520254964068785\segmentstore\data00000a.tar: Der Prozess kann nicht auf die Datei zugreifen, da sie von einem anderen Prozess verwendet wird.
      
      	at sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:86)
      	at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:97)
      	at sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:102)
      	at sun.nio.fs.WindowsFileSystemProvider.implDelete(WindowsFileSystemProvider.java:273)
      	at sun.nio.fs.AbstractFileSystemProvider.deleteIfExists(AbstractFileSystemProvider.java:108)
      	at java.nio.file.Files.deleteIfExists(Files.java:1165)
      	at org.apache.jackrabbit.oak.segment.file.tar.SegmentTarManager.delete(SegmentTarManager.java:141)
      	at org.apache.jackrabbit.oak.segment.file.FileReaper.reap(FileReaper.java:76)
      	at org.apache.jackrabbit.oak.segment.file.FileStore.close(FileStore.java:489)
      	at org.apache.jackrabbit.oak.segment.ReadOnlyStoreBlobReferencesTest.collectReferencesAfterGC(ReadOnlyStoreBlobReferencesTest.java:96)
      	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
      	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
      	at java.lang.reflect.Method.invoke(Method.java:498)
      	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
      	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
      	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
      	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
      	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:48)
      	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
      	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
      	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
      	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
      	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
      	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
      	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
      	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
      	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
      	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
      	at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:365)
      	at org.apache.maven.surefire.junit4.JUnit4Provider.executeWithRerun(JUnit4Provider.java:273)
      	at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:238)
      	at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:159)
      	at org.apache.maven.surefire.booter.ForkedBooter.invokeProviderInSameClassLoader(ForkedBooter.java:384)
      	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:345)
      	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:126)
      	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:418)
      19:14:58.735 WARN  [main] FileReaper.java:79                Unable to remove file data00000a.tar
      19:14:58.737 INFO  [main] FileReaper.java:84                Removed files data00001a.tar,data00002a.tar
      19:14:58.737 INFO  [main] FileStore.java:491                TarMK closed: target\junit5910520254964068785\segmentstore
      19:14:58.738 INFO  [main] FileStoreBuilder.java:467         Creating file store FileStoreBuilder{version=null, directory=target\junit5910520254964068785\segmentstore, blobStore=DataStore backed BlobStore [org.apache.jackrabbit.oak.plugins.blob.datastore.OakFileDataStore], maxFileSize=256, segmentCacheSize=256, stringCacheSize=256, templateCacheSize=64, stringDeduplicationCacheSize=15000, templateDeduplicationCacheSize=3000, nodeDeduplicationCacheSize=1048576, memoryMapping=true, offHeapAccess=false, gcOptions=SegmentGCOptions{paused=false, estimationDisabled=false, gcSizeDeltaEstimation=1073741824, retryCount=5, forceTimeout=60, retainedGenerations=2, gcType=FULL}}
      19:14:58.742 INFO  [main] ReadOnlyFileStore.java:85         TarMK ReadOnly opened: target\junit5910520254964068785\segmentstore (mmap=true)
      19:14:58.893 INFO  [main] ReadOnlyFileStore.java:140        TarMK closed: target\junit5910520254964068785\segmentstore
      

      Attachments

        Activity

          People

            Unassigned Unassigned
            reschke Julian Reschke
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

              Created:
              Updated: