You are viewing a plain text version of this content. The canonical link for it is here.
Posted to oak-issues@jackrabbit.apache.org by "Davide Giannella (JIRA)" <ji...@apache.org> on 2019/04/15 09:20:10 UTC
[jira] [Closed] (OAK-7027) Test failure:
ExternalPrivateStoreIT.testSyncFailingDueToTooShortTimeout
[ https://issues.apache.org/jira/browse/OAK-7027?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Davide Giannella closed OAK-7027.
---------------------------------
bulk close 1.12.0
> 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
> Fix For: 1.12.0
>
> 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)