[OAK-7027] Test failure: ExternalPrivateStoreIT.testSyncFailingDueToTooShortTimeout

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Fix Version/s: 1.12.0
• Component/s: segment-tar, tarmk-standby
• Labels: test-failure
• Assignee: Francesco Mari
• Reporter: Michael Dürig
• Created: 05/Dec/17 08:52
• Updated: 04/Oct/19 17:50
• Resolved: 08/Mar/19 14:49

Description

Seen on an internal Windows Jenkins node:

Regression

org.apache.jackrabbit.oak.segment.standby.ExternalPrivateStoreIT.testSyncFailingDueToTooShortTimeout

Error Message

Values should be different. Actual: { root = { ... } }

Stacktrace

java.lang.AssertionError: Values should be different. Actual: { root = { ... } }
	at org.apache.jackrabbit.oak.segment.standby.ExternalPrivateStoreIT.testSyncFailingDueToTooShortTimeout(ExternalPrivateStoreIT.java:87)

Standard Output

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