[ https://issues.apache.org/jira/browse/OAK-7027?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Francesco Mari reassigned OAK-7027: ----------------------------------- Assignee: Francesco Mari > Test failure: ExternalPrivateStoreIT.testSyncFailingDueToTooShortTimeout > ------------------------------------------------------------------------ > > Key: OAK-7027 > URL: https://issues.apache.org/jira/browse/OAK-7027 > Project: Jackrabbit Oak > Issue Type: Bug > Components: segment-tar, tarmk-standby > Reporter: Michael Dürig > Assignee: Francesco Mari > Priority: Major > Labels: test-failure > > Seen on an internal Windows Jenkins node: > h3. Regression > org.apache.jackrabbit.oak.segment.standby.ExternalPrivateStoreIT.testSyncFailingDueToTooShortTimeout > h3. Error Message > {noformat} > Values should be different. Actual: { root = { ... } } > {noformat} > h3. Stacktrace > {noformat} > java.lang.AssertionError: Values should be different. Actual: { root = { ... > } } > at > org.apache.jackrabbit.oak.segment.standby.ExternalPrivateStoreIT.testSyncFailingDueToTooShortTimeout(ExternalPrivateStoreIT.java:87) > {noformat} > h3. Standard Output > {noformat} > 22:41:13.646 INFO [main] FileStoreBuilder.java:340 Creating file > store FileStoreBuilder{version=1.8-SNAPSHOT, > directory=target\junit2834122541179880349\junit3041268421527563090, > blobStore=DataStore backed BlobStore > [org.apache.jackrabbit.core.data.FileDataStore], maxFileSize=1, > segmentCacheSize=0, stringCacheSize=0, templateCacheSize=0, > stringDeduplicationCacheSize=15000, templateDeduplicationCacheSize=3000, > nodeDeduplicationCacheSize=1, memoryMapping=false, > gcOptions=SegmentGCOptions{paused=false, estimationDisabled=false, > gcSizeDeltaEstimation=1073741824, retryCount=5, forceTimeout=60, > retainedGenerations=2, gcType=FULL}} > 22:41:13.646 INFO [main] FileStore.java:241 TarMK opened at > target\junit2834122541179880349\junit3041268421527563090, mmap=false, size=0 > B (0 bytes) > 22:41:13.646 DEBUG [main] FileStore.java:247 TAR files: > TarFiles{readers=[],writer=target\junit2834122541179880349\junit3041268421527563090\data00000a.tar} > 22:41:13.646 DEBUG [main] TarWriter.java:185 Writing segment > 4cea1684-ef05-44f5-a869-3ef2df6e0c9a to > target\junit2834122541179880349\junit3041268421527563090\data00000a.tar > 22:41:13.646 INFO [main] FileStoreBuilder.java:340 Creating file > store FileStoreBuilder{version=1.8-SNAPSHOT, > directory=target\junit2834122541179880349\junit4470899745425503556, > blobStore=DataStore backed BlobStore > [org.apache.jackrabbit.core.data.FileDataStore], maxFileSize=1, > segmentCacheSize=0, stringCacheSize=0, templateCacheSize=0, > stringDeduplicationCacheSize=15000, templateDeduplicationCacheSize=3000, > nodeDeduplicationCacheSize=1, memoryMapping=false, > gcOptions=SegmentGCOptions{paused=false, estimationDisabled=false, > gcSizeDeltaEstimation=1073741824, retryCount=5, forceTimeout=60, > retainedGenerations=2, gcType=FULL}} > 22:41:13.646 INFO [main] FileStore.java:241 TarMK opened at > target\junit2834122541179880349\junit4470899745425503556, mmap=false, size=0 > B (0 bytes) > 22:41:13.646 DEBUG [main] FileStore.java:247 TAR files: > TarFiles{readers=[],writer=target\junit2834122541179880349\junit4470899745425503556\data00000a.tar} > 22:41:13.646 DEBUG [main] TarWriter.java:185 Writing segment > 8d19c7dc-8b48-4e10-a58d-31c15c93f2fe to > target\junit2834122541179880349\junit4470899745425503556\data00000a.tar > 22:41:13.646 INFO [main] DataStoreTestBase.java:127 Test begin: > testSyncFailingDueToTooShortTimeout > 22:41:13.646 INFO [main] SegmentNodeStore.java:120 Creating segment > node store SegmentNodeStoreBuilder{blobStore=DataStore backed BlobStore > [org.apache.jackrabbit.core.data.FileDataStore]} > 22:41:13.646 INFO [main] LockBasedScheduler.java:155 Initializing > SegmentNodeStore with the commitFairLock option enabled. > 22:41:13.708 DEBUG [main] StandbyServer.java:248 Binding was > successful > 22:41:13.708 DEBUG [main] TarWriter.java:185 Writing segment > 4a5183bd-bcdf-41ab-a557-6f19143bbc91 to > target\junit2834122541179880349\junit3041268421527563090\data00000a.tar > 22:41:13.739 DEBUG [main] TarRevisions.java:240 TarMK journal > update null -> 4a5183bd-bcdf-41ab-a557-6f19143bbc91.0000000c > 22:41:13.755 DEBUG [standby-1] GetHeadRequestEncoder.java:33 Sending request > from client 9aa63ed8-347b-4f00-ae7c-f984e0623e90 for current head > 22:41:13.755 DEBUG [primary-1] ClientFilterHandler.java:53 Client > /127.0.0.1:65480 is allowed > 22:41:13.755 DEBUG [primary-1] RequestDecoder.java:42 Parsed 'get head' > message > 22:41:13.755 DEBUG [primary-1] CommunicationObserver.java:120 Message 'get > head' received from client 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > 22:41:13.755 DEBUG [primary-1] GetHeadRequestHandler.java:43 Reading head for > client 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > 22:41:13.755 DEBUG [primary-1] GetHeadResponseEncoder.java:36 Sending head > 4a5183bd-bcdf-41ab-a557-6f19143bbc91.0000000c to client > 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > 22:41:13.755 DEBUG [standby-1] ResponseDecoder.java:82 Decoding 'get > head' response > 22:41:13.755 DEBUG [standby-run-23] StandbyClientSyncExecution.java:103 Found > missing segment 4a5183bd-bcdf-41ab-a557-6f19143bbc91 > 22:41:13.755 DEBUG [standby-run-23] StandbyClientSyncExecution.java:124 > Inspecting segment 4a5183bd-bcdf-41ab-a557-6f19143bbc91 > 22:41:13.755 DEBUG [standby-1] GetReferencesRequestEncoder.java:33 Sending > request from client 9aa63ed8-347b-4f00-ae7c-f984e0623e90 for references of > segment 4a5183bd-bcdf-41ab-a557-6f19143bbc91 > 22:41:13.755 DEBUG [primary-1] RequestDecoder.java:48 Parsed 'get > references' message > 22:41:13.771 DEBUG [primary-1] GetReferencesRequestHandler.java:39 Reading > references of segment 4a5183bd-bcdf-41ab-a557-6f19143bbc91 for client > 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > 22:41:13.771 DEBUG [primary-1] GetReferencesResponseEncoder.java:34 Sending > references of segment 4a5183bd-bcdf-41ab-a557-6f19143bbc91 to client > 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > 22:41:13.771 DEBUG [standby-1] ResponseDecoder.java:94 Decoding 'get > references' response > 22:41:13.771 DEBUG [standby-run-23] StandbyClientSyncExecution.java:184 Found > reference from 4a5183bd-bcdf-41ab-a557-6f19143bbc91 to > 4cea1684-ef05-44f5-a869-3ef2df6e0c9a > 22:41:13.771 DEBUG [standby-run-23] StandbyClientSyncExecution.java:124 > Inspecting segment 4cea1684-ef05-44f5-a869-3ef2df6e0c9a > 22:41:13.771 DEBUG [standby-1] GetReferencesRequestEncoder.java:33 Sending > request from client 9aa63ed8-347b-4f00-ae7c-f984e0623e90 for references of > segment 4cea1684-ef05-44f5-a869-3ef2df6e0c9a > 22:41:13.771 DEBUG [primary-1] RequestDecoder.java:48 Parsed 'get > references' message > 22:41:13.771 DEBUG [primary-1] GetReferencesRequestHandler.java:39 Reading > references of segment 4cea1684-ef05-44f5-a869-3ef2df6e0c9a for client > 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > 22:41:13.771 DEBUG [primary-1] GetReferencesResponseEncoder.java:34 Sending > references of segment 4cea1684-ef05-44f5-a869-3ef2df6e0c9a to client > 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > 22:41:13.771 DEBUG [standby-1] ResponseDecoder.java:94 Decoding 'get > references' response > 22:41:13.771 INFO [standby-run-23] StandbyClientSyncExecution.java:196 > Copying data segment 4cea1684-ef05-44f5-a869-3ef2df6e0c9a from primary > 22:41:13.771 DEBUG [standby-1] GetSegmentRequestEncoder.java:33 Sending > request from client 9aa63ed8-347b-4f00-ae7c-f984e0623e90 for segment > 4cea1684-ef05-44f5-a869-3ef2df6e0c9a > 22:41:13.771 DEBUG [primary-1] RequestDecoder.java:45 Parsed 'get > segment' message > 22:41:13.771 DEBUG [primary-1] CommunicationObserver.java:120 Message 'get > segment' received from client 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > 22:41:13.771 DEBUG [primary-1] GetSegmentRequestHandler.java:39 Reading > segment 4cea1684-ef05-44f5-a869-3ef2df6e0c9a for client > 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > 22:41:13.771 DEBUG [primary-1] CommunicationObserver.java:125 Segment with > size 192 sent to client 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > 22:41:13.771 DEBUG [primary-1] GetSegmentResponseEncoder.java:43 Sending > segment 4cea1684-ef05-44f5-a869-3ef2df6e0c9a to client > 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > 22:41:13.771 DEBUG [standby-1] ResponseDecoder.java:86 Decoding 'get > segment' response > 22:41:13.771 DEBUG [standby-run-23] TarWriter.java:185 Writing segment > 4cea1684-ef05-44f5-a869-3ef2df6e0c9a to > target\junit2834122541179880349\junit4470899745425503556\data00000a.tar > 22:41:13.771 INFO [standby-run-23] StandbyClientSyncExecution.java:196 > Copying data segment 4a5183bd-bcdf-41ab-a557-6f19143bbc91 from primary > 22:41:13.771 DEBUG [standby-1] GetSegmentRequestEncoder.java:33 Sending > request from client 9aa63ed8-347b-4f00-ae7c-f984e0623e90 for segment > 4a5183bd-bcdf-41ab-a557-6f19143bbc91 > 22:41:13.771 DEBUG [primary-1] RequestDecoder.java:45 Parsed 'get > segment' message > 22:41:13.771 DEBUG [primary-1] CommunicationObserver.java:120 Message 'get > segment' received from client 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > 22:41:13.771 DEBUG [primary-1] GetSegmentRequestHandler.java:39 Reading > segment 4a5183bd-bcdf-41ab-a557-6f19143bbc91 for client > 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > 22:41:13.771 DEBUG [primary-1] CommunicationObserver.java:125 Segment with > size 448 sent to client 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > 22:41:13.771 DEBUG [primary-1] GetSegmentResponseEncoder.java:43 Sending > segment 4a5183bd-bcdf-41ab-a557-6f19143bbc91 to client > 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > 22:41:13.771 DEBUG [standby-1] ResponseDecoder.java:86 Decoding 'get > segment' response > 22:41:13.771 DEBUG [standby-run-23] TarWriter.java:185 Writing segment > 4a5183bd-bcdf-41ab-a557-6f19143bbc91 to > target\junit2834122541179880349\junit4470899745425503556\data00000a.tar > 22:41:13.771 DEBUG [standby-1] GetBlobRequestEncoder.java:33 Sending request > from client 9aa63ed8-347b-4f00-ae7c-f984e0623e90 for blob > c3ac16ad0c8bc3a3ff30cef8e296af92d53058c13a8930406d3f08e271b4b57b#5242880 > 22:41:13.771 DEBUG [primary-1] RequestDecoder.java:39 Parsed 'get blob' > request > 22:41:13.771 DEBUG [primary-1] CommunicationObserver.java:120 Message 'get > blob id' received from client 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > 22:41:13.771 DEBUG [primary-1] GetBlobRequestHandler.java:41 Reading blob > c3ac16ad0c8bc3a3ff30cef8e296af92d53058c13a8930406d3f08e271b4b57b#5242880 for > client 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > 22:41:13.771 DEBUG [primary-1] CommunicationObserver.java:130 Binary with > size 5242880 sent to client 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > 22:41:13.771 DEBUG [primary-1] GetBlobResponseEncoder.java:41 Sending blob > c3ac16ad0c8bc3a3ff30cef8e296af92d53058c13a8930406d3f08e271b4b57b#5242880 to > client 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > 22:41:13.786 DEBUG [primary-1] ChunkedBlobStream.java:128 Sending chunk 1/5 > of size 1048576 from blob > c3ac16ad0c8bc3a3ff30cef8e296af92d53058c13a8930406d3f08e271b4b57b#5242880 to > client 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > 22:41:13.802 DEBUG [primary-1] ChunkedBlobStream.java:128 Sending chunk 2/5 > of size 1048576 from blob > c3ac16ad0c8bc3a3ff30cef8e296af92d53058c13a8930406d3f08e271b4b57b#5242880 to > client 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > 22:41:13.802 DEBUG [standby-1] ResponseDecoder.java:90 Decoding 'get > blob' response > 22:41:13.802 DEBUG [standby-1] ResponseDecoder.java:150 Received chunk > 1/5 of size 1048576 from blob > c3ac16ad0c8bc3a3ff30cef8e296af92d53058c13a8930406d3f08e271b4b57b#5242880 > 22:41:13.802 DEBUG [standby-1] ResponseDecoder.java:159 All checks OK. > Appending chunk to disk to > C:\Windows\TEMP\c3ac16ad0c8bc3a3ff30cef8e296af92d53058c13a8930406d3f08e271b4b57b#5242880.tmp > > 22:41:13.802 DEBUG [primary-1] ChunkedBlobStream.java:128 Sending chunk 3/5 > of size 1048576 from blob > c3ac16ad0c8bc3a3ff30cef8e296af92d53058c13a8930406d3f08e271b4b57b#5242880 to > client 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > 22:41:13.802 DEBUG [standby-1] ResponseDecoder.java:90 Decoding 'get > blob' response > 22:41:13.818 DEBUG [standby-1] ResponseDecoder.java:150 Received chunk > 2/5 of size 1048576 from blob > c3ac16ad0c8bc3a3ff30cef8e296af92d53058c13a8930406d3f08e271b4b57b#5242880 > 22:41:13.818 DEBUG [standby-1] ResponseDecoder.java:159 All checks OK. > Appending chunk to disk to > C:\Windows\TEMP\c3ac16ad0c8bc3a3ff30cef8e296af92d53058c13a8930406d3f08e271b4b57b#5242880.tmp > > 22:41:13.818 DEBUG [primary-1] ChunkedBlobStream.java:128 Sending chunk 4/5 > of size 1048576 from blob > c3ac16ad0c8bc3a3ff30cef8e296af92d53058c13a8930406d3f08e271b4b57b#5242880 to > client 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > 22:41:13.818 DEBUG [standby-1] ResponseDecoder.java:90 Decoding 'get > blob' response > 22:41:13.818 DEBUG [standby-1] ResponseDecoder.java:150 Received chunk > 3/5 of size 1048576 from blob > c3ac16ad0c8bc3a3ff30cef8e296af92d53058c13a8930406d3f08e271b4b57b#5242880 > 22:41:13.818 DEBUG [standby-1] ResponseDecoder.java:159 All checks OK. > Appending chunk to disk to > C:\Windows\TEMP\c3ac16ad0c8bc3a3ff30cef8e296af92d53058c13a8930406d3f08e271b4b57b#5242880.tmp > > 22:41:13.818 DEBUG [primary-1] ChunkedBlobStream.java:128 Sending chunk 5/5 > of size 1048576 from blob > c3ac16ad0c8bc3a3ff30cef8e296af92d53058c13a8930406d3f08e271b4b57b#5242880 to > client 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > 22:41:13.833 DEBUG [standby-1] ResponseDecoder.java:90 Decoding 'get > blob' response > 22:41:13.833 DEBUG [standby-1] ResponseDecoder.java:150 Received chunk > 4/5 of size 1048576 from blob > c3ac16ad0c8bc3a3ff30cef8e296af92d53058c13a8930406d3f08e271b4b57b#5242880 > 22:41:13.833 DEBUG [standby-1] ResponseDecoder.java:159 All checks OK. > Appending chunk to disk to > C:\Windows\TEMP\c3ac16ad0c8bc3a3ff30cef8e296af92d53058c13a8930406d3f08e271b4b57b#5242880.tmp > > 22:41:13.833 DEBUG [standby-1] ResponseDecoder.java:90 Decoding 'get > blob' response > 22:41:13.833 DEBUG [standby-1] ResponseDecoder.java:150 Received chunk > 5/5 of size 1048576 from blob > c3ac16ad0c8bc3a3ff30cef8e296af92d53058c13a8930406d3f08e271b4b57b#5242880 > 22:41:13.833 DEBUG [standby-1] ResponseDecoder.java:159 All checks OK. > Appending chunk to disk to > C:\Windows\TEMP\c3ac16ad0c8bc3a3ff30cef8e296af92d53058c13a8930406d3f08e271b4b57b#5242880.tmp > > 22:41:13.833 DEBUG [standby-1] ResponseDecoder.java:167 Received entire > blob c3ac16ad0c8bc3a3ff30cef8e296af92d53058c13a8930406d3f08e271b4b57b#5242880 > 22:41:13.880 DEBUG [standby-run-23] ResponseDecoder.java:66 Processing input > stream finished! Deleting file > C:\Windows\TEMP\c3ac16ad0c8bc3a3ff30cef8e296af92d53058c13a8930406d3f08e271b4b57b#5242880.tmp > 22:41:13.896 DEBUG [standby-run-23] TarRevisions.java:240 TarMK journal > update null -> 4a5183bd-bcdf-41ab-a557-6f19143bbc91.0000000c > 22:41:13.911 WARN [standby-1] ExceptionHandler.java:37 Exception caught > on client 9aa63ed8-347b-4f00-ae7c-f984e0623e90 > io.netty.handler.timeout.ReadTimeoutException: null > 22:41:13.911 INFO [standby-run-23] StandbyClientSyncExecution.java:82 > updated head state successfully: true in 156ms. > 22:41:13.911 DEBUG [standby-run-23] StandbyClient.java:157 Channel closed > 22:41:16.137 DEBUG [main] StandbyClientSync.java:277 Group shut down > 22:41:16.137 DEBUG [main] StandbyServer.java:219 Channel > disconnected > 22:41:16.137 DEBUG [main] StandbyServer.java:219 Channel > disconnected > 22:41:16.137 DEBUG [main] StandbyServer.java:230 Boss group shut > down > 22:41:16.137 DEBUG [main] StandbyServer.java:236 Worker group shut > down > 22:41:16.137 INFO [main] DataStoreTestBase.java:132 Test end: > testSyncFailingDueToTooShortTimeout > 22:41:16.137 DEBUG [main] Scheduler.java:134 The scheduler > FileStore background tasks was successfully shut down > 22:41:16.137 DEBUG [main] TarRevisions.java:236 Head state did > not change, skipping flush > 22:41:16.184 INFO [main] FileStore.java:480 TarMK closed: > target\junit2834122541179880349\junit4470899745425503556 > 22:41:16.184 DEBUG [main] Scheduler.java:134 The scheduler > FileStore background tasks was successfully shut down > 22:41:16.184 DEBUG [main] TarRevisions.java:236 Head state did > not change, skipping flush > 22:41:16.199 INFO [main] FileStore.java:480 TarMK closed: > target\junit2834122541179880349\junit3041268421527563090 > {noformat} -- This message was sent by Atlassian JIRA (v7.6.3#76005)