Details
-
Bug
-
Status: Open
-
Major
-
Resolution: Unresolved
-
1.22.16, 1.56.0
-
None
-
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