jackrabbit-oak-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Francesco Mari (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (OAK-7027) Test failure: ExternalPrivateStoreIT.testSyncFailingDueToTooShortTimeout
Date Fri, 08 Mar 2019 13:47:01 GMT

    [ 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)

Mime
View raw message