[
https://issues.apache.org/jira/browse/OAK-7027?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16787893#comment-16787893
]
Francesco Mari commented on OAK-7027:
-------------------------------------
[~dulceanu], the second patch incorporates your suggestions. It definitely
makes the code clearer. If you are alright with that, I will commit the changes.
> 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
> Attachments: OAK-7027-01.patch, OAK-7027-02.patch
>
>
> 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)
