[
https://issues.apache.org/jira/browse/MESOS-531?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13708613#comment-13708613
]
Benjamin Mahler commented on MESOS-531:
---------------------------------------
Hey Ben, looks like 10 seconds is still not enough for the jenkins build? It
doesn't look like any of the other operations took anywhere near 10 seconds,
oddly enough.
https://builds.apache.org/job/Mesos-Trunk-Ubuntu-Build-Out-Of-Src-Disable-Java-Disable-Python-Disable-Webui/1374/consoleFull
[ RUN ] CoordinatorTest.MultipleAppendsNotLearnedFill
I0714 16:27:24.335188 9984 replica.cpp:230] Opened db in 98.239755ms
I0714 16:27:24.355736 9984 replica.cpp:237] Compacted db in 20.511213ms
I0714 16:27:24.355768 9984 replica.cpp:253] Created db iterator in 2.646us
I0714 16:27:24.367625 9984 replica.cpp:259] Seeked to beginning of db in 845ns
I0714 16:27:24.375591 9984 replica.cpp:310] Iterated through 0 keys in the db
in 295ns
I0714 16:27:24.383606 9984 replica.cpp:1040] Replica recovered with log
positions 0 -> 0 and holes { 0 } and unlearned { }
I0714 16:27:24.488376 9984 replica.cpp:230] Opened db in 96.824126ms
I0714 16:27:24.497361 9984 replica.cpp:237] Compacted db in 8.952727ms
I0714 16:27:24.507064 9984 replica.cpp:253] Created db iterator in 1.826us
I0714 16:27:24.515029 9984 replica.cpp:259] Seeked to beginning of db in 346ns
I0714 16:27:24.522994 9984 replica.cpp:310] Iterated through 0 keys in the db
in 171ns
I0714 16:27:24.531013 9984 replica.cpp:1040] Replica recovered with log
positions 0 -> 0 and holes { 0 } and unlearned { }
I0714 16:27:24.538972 9984 coordinator.cpp:61] Coordinator attempting to get
elected within 9.999999232secs
I0714 16:27:24.547353 10010 replica.cpp:777] Replica received implicit promise
request for 1
I0714 16:27:24.547379 10013 replica.cpp:777] Replica received implicit promise
request for 1
I0714 16:27:24.595247 10010 replica.cpp:354] Persisting promise (6 bytes) to
leveldb took 40.367334ms
I0714 16:27:24.595247 10013 replica.cpp:354] Persisting promise (6 bytes) to
leveldb took 32.398505ms
I0714 16:27:24.595281 10010 replica.cpp:953] Persisted promise to 1
I0714 16:27:24.606374 10013 replica.cpp:953] Persisted promise to 1
I0714 16:27:24.622907 9984 coordinator.cpp:115] Coordinator elected,
attempting to fill missing positions
I0714 16:27:24.630764 9984 coordinator.cpp:396] Coordinator attempting to fill
position 0 in the log
I0714 16:27:24.638815 10007 replica.cpp:705] Replica received explicit promise
request for 1 for position 0
I0714 16:27:24.638870 10012 replica.cpp:705] Replica received explicit promise
request for 1 for position 0
I0714 16:27:24.659981 10007 replica.cpp:385] Persisting action (8 bytes) to
leveldb took 13.432753ms
I0714 16:27:24.661692 10012 replica.cpp:385] Persisting action (8 bytes) to
leveldb took 7.206798ms
I0714 16:27:24.686354 10012 replica.cpp:968] Persisted action at 0
I0714 16:27:24.678169 10007 replica.cpp:968] Persisted action at 0
I0714 16:27:24.702540 9984 coordinator.cpp:226] Coordinator attempting to
write NOP action at position 0 within 9.836436992secs
I0714 16:27:24.710485 10010 replica.cpp:808] Replica received write request for
position 0
I0714 16:27:24.718251 10010 replica.cpp:470] Reading position from leveldb took
10.351us
I0714 16:27:24.741430 10010 replica.cpp:385] Persisting action (14 bytes) to
leveldb took 15.232603ms
I0714 16:27:24.741462 10010 replica.cpp:968] Persisted action at 0
I0714 16:27:24.758296 9984 coordinator.cpp:317] Coordinator attempting to
commit NOP action at position 0
I0714 16:27:24.766219 10009 replica.cpp:808] Replica received write request for
position 0
I0714 16:27:24.774008 10009 replica.cpp:470] Reading position from leveldb took
6.742us
I0714 16:27:24.795513 10009 replica.cpp:385] Persisting action (16 bytes) to
leveldb took 13.537529ms
I0714 16:27:24.795543 10009 replica.cpp:968] Persisted action at 0
I0714 16:27:24.813791 9984 coordinator.cpp:385] Telling other replicas of
learned action at position 0
I0714 16:27:24.821974 9984 coordinator.cpp:226] Coordinator attempting to
write APPEND action at position 1 within 9.999990784secs
I0714 16:27:24.830011 10006 replica.cpp:808] Replica received write request for
position 1
I0714 16:27:24.858784 10006 replica.cpp:385] Persisting action (17 bytes) to
leveldb took 21.023139ms
I0714 16:27:24.858819 10006 replica.cpp:968] Persisted action at 1
I0714 16:27:24.865808 9984 coordinator.cpp:317] Coordinator attempting to
commit APPEND action at position 1
I0714 16:27:24.873775 10013 replica.cpp:808] Replica received write request for
position 1
I0714 16:27:24.899158 10013 replica.cpp:385] Persisting action (19 bytes) to
leveldb took 17.570758ms
I0714 16:27:24.899194 10013 replica.cpp:968] Persisted action at 1
I0714 16:27:24.909525 9984 coordinator.cpp:385] Telling other replicas of
learned action at position 1
I0714 16:27:24.917474 9984 coordinator.cpp:226] Coordinator attempting to
write APPEND action at position 2 within 9.999994112secs
I0714 16:27:24.925595 10009 replica.cpp:808] Replica received write request for
position 2
I0714 16:27:24.954395 10009 replica.cpp:385] Persisting action (17 bytes) to
leveldb took 21.019052ms
I0714 16:27:24.954428 10009 replica.cpp:968] Persisted action at 2
I0714 16:27:24.961422 9984 coordinator.cpp:317] Coordinator attempting to
commit APPEND action at position 2
I0714 16:27:24.969372 10009 replica.cpp:808] Replica received write request for
position 2
I0714 16:27:24.994832 10009 replica.cpp:385] Persisting action (19 bytes) to
leveldb took 17.647826ms
I0714 16:27:24.994865 10009 replica.cpp:968] Persisted action at 2
I0714 16:27:25.005239 9984 coordinator.cpp:385] Telling other replicas of
learned action at position 2
I0714 16:27:25.013078 9984 coordinator.cpp:226] Coordinator attempting to
write APPEND action at position 3 within 9.999995136secs
I0714 16:27:25.021235 10011 replica.cpp:808] Replica received write request for
position 3
I0714 16:27:25.065531 10011 replica.cpp:385] Persisting action (17 bytes) to
leveldb took 36.540374ms
I0714 16:27:25.065568 10011 replica.cpp:968] Persisted action at 3
I0714 16:27:25.073034 9984 coordinator.cpp:317] Coordinator attempting to
commit APPEND action at position 3
I0714 16:27:25.081012 10007 replica.cpp:808] Replica received write request for
position 3
I0714 16:27:25.121362 10007 replica.cpp:385] Persisting action (19 bytes) to
leveldb took 32.571637ms
I0714 16:27:25.121397 10007 replica.cpp:968] Persisted action at 3
I0714 16:27:25.128756 9984 coordinator.cpp:385] Telling other replicas of
learned action at position 3
I0714 16:27:25.144563 9984 coordinator.cpp:226] Coordinator attempting to
write APPEND action at position 4 within 9.999995904secs
I0714 16:27:25.160624 10010 replica.cpp:808] Replica received write request for
position 4
I0714 16:27:25.199887 10010 replica.cpp:385] Persisting action (17 bytes) to
leveldb took 23.510681ms
I0714 16:27:25.199919 10010 replica.cpp:968] Persisted action at 4
I0714 16:27:25.224350 9984 coordinator.cpp:317] Coordinator attempting to
commit APPEND action at position 4
I0714 16:27:25.240442 10011 replica.cpp:808] Replica received write request for
position 4
I0714 16:27:25.261942 10011 replica.cpp:385] Persisting action (19 bytes) to
leveldb took 5.814639ms
I0714 16:27:25.276039 10011 replica.cpp:968] Persisted action at 4
I0714 16:27:25.292104 9984 coordinator.cpp:385] Telling other replicas of
learned action at position 4
I0714 16:27:25.308045 9984 coordinator.cpp:226] Coordinator attempting to
write APPEND action at position 5 within 9.999996672secs
I0714 16:27:25.324215 10006 replica.cpp:808] Replica received write request for
position 5
I0714 16:27:25.363330 10006 replica.cpp:385] Persisting action (17 bytes) to
leveldb took 23.467845ms
I0714 16:27:25.363366 10006 replica.cpp:968] Persisted action at 5
I0714 16:27:25.379966 9984 coordinator.cpp:317] Coordinator attempting to
commit APPEND action at position 5
I0714 16:27:25.395915 10007 replica.cpp:808] Replica received write request for
position 5
I0714 16:27:25.417419 10007 replica.cpp:385] Persisting action (19 bytes) to
leveldb took 5.780145ms
I0714 16:27:25.431553 10007 replica.cpp:968] Persisted action at 5
I0714 16:27:25.447656 9984 coordinator.cpp:385] Telling other replicas of
learned action at position 5
I0714 16:27:25.463527 9984 coordinator.cpp:226] Coordinator attempting to
write APPEND action at position 6 within 9.999994112secs
I0714 16:27:25.479701 10012 replica.cpp:808] Replica received write request for
position 6
I0714 16:27:25.518810 10012 replica.cpp:385] Persisting action (17 bytes) to
leveldb took 23.432964ms
I0714 16:27:25.518849 10012 replica.cpp:968] Persisted action at 6
I0714 16:27:25.535362 9984 coordinator.cpp:317] Coordinator attempting to
commit APPEND action at position 6
I0714 16:27:25.551455 10010 replica.cpp:808] Replica received write request for
position 6
I0714 16:27:25.572895 10010 replica.cpp:385] Persisting action (19 bytes) to
leveldb took 5.742274ms
I0714 16:27:25.587066 10010 replica.cpp:968] Persisted action at 6
I0714 16:27:25.603173 9984 coordinator.cpp:385] Telling other replicas of
learned action at position 6
I0714 16:27:25.619014 9984 coordinator.cpp:226] Coordinator attempting to
write APPEND action at position 7 within 9.99999488secs
I0714 16:27:25.635179 10009 replica.cpp:808] Replica received write request for
position 7
I0714 16:27:25.674281 10009 replica.cpp:385] Persisting action (17 bytes) to
leveldb took 23.386822ms
I0714 16:27:25.674316 10009 replica.cpp:968] Persisted action at 7
I0714 16:27:25.690950 9984 coordinator.cpp:317] Coordinator attempting to
commit APPEND action at position 7
I0714 16:27:25.706888 10011 replica.cpp:808] Replica received write request for
position 7
I0714 16:27:25.728368 10011 replica.cpp:385] Persisting action (19 bytes) to
leveldb took 5.71963ms
I0714 16:27:25.742578 10011 replica.cpp:968] Persisted action at 7
I0714 16:27:25.758646 9984 coordinator.cpp:385] Telling other replicas of
learned action at position 7
I0714 16:27:25.774529 9984 coordinator.cpp:226] Coordinator attempting to
write APPEND action at position 8 within 9.999995136secs
I0714 16:27:25.790643 10006 replica.cpp:808] Replica received write request for
position 8
I0714 16:27:25.829757 10006 replica.cpp:385] Persisting action (17 bytes) to
leveldb took 23.355514ms
I0714 16:27:25.829792 10006 replica.cpp:968] Persisted action at 8
I0714 16:27:25.846434 9984 coordinator.cpp:317] Coordinator attempting to
commit APPEND action at position 8
I0714 16:27:25.862406 10006 replica.cpp:808] Replica received write request for
position 8
I0714 16:27:25.887995 10006 replica.cpp:385] Persisting action (19 bytes) to
leveldb took 5.830345ms
I0714 16:27:25.949959 10006 replica.cpp:968] Persisted action at 8
I0714 16:27:25.958017 9984 coordinator.cpp:385] Telling other replicas of
learned action at position 8
I0714 16:27:25.966014 9984 coordinator.cpp:226] Coordinator attempting to
write APPEND action at position 9 within 9.99999616secs
I0714 16:27:25.974138 10006 replica.cpp:808] Replica received write request for
position 9
I0714 16:27:26.013138 10006 replica.cpp:385] Persisting action (17 bytes) to
leveldb took 31.270566ms
I0714 16:27:26.013175 10006 replica.cpp:968] Persisted action at 9
I0714 16:27:26.021524 9984 coordinator.cpp:317] Coordinator attempting to
commit APPEND action at position 9
I0714 16:27:26.029885 10011 replica.cpp:808] Replica received write request for
position 9
I0714 16:27:26.078461 10011 replica.cpp:385] Persisting action (19 bytes) to
leveldb took 40.770334ms
I0714 16:27:26.078500 10011 replica.cpp:968] Persisted action at 9
I0714 16:27:26.089726 9984 coordinator.cpp:385] Telling other replicas of
learned action at position 9
I0714 16:27:26.097589 9984 coordinator.cpp:226] Coordinator attempting to
write APPEND action at position 10 within 9.99999616secs
I0714 16:27:26.105727 10007 replica.cpp:808] Replica received write request for
position 10
I0714 16:27:26.169548 10007 replica.cpp:385] Persisting action (18 bytes) to
leveldb took 56.097112ms
I0714 16:27:26.169586 10007 replica.cpp:968] Persisted action at 10
I0714 16:27:26.177428 9984 coordinator.cpp:317] Coordinator attempting to
commit APPEND action at position 10
I0714 16:27:26.185390 10011 replica.cpp:808] Replica received write request for
position 10
I0714 16:27:26.206764 10011 replica.cpp:385] Persisting action (20 bytes) to
leveldb took 13.565279ms
I0714 16:27:26.206795 10011 replica.cpp:968] Persisted action at 10
I0714 16:27:26.224802 9984 coordinator.cpp:385] Telling other replicas of
learned action at position 10
I0714 16:27:26.311933 9984 replica.cpp:230] Opened db in 78.748725ms
I0714 16:27:26.327993 9984 replica.cpp:237] Compacted db in 16.023748ms
I0714 16:27:26.328026 9984 replica.cpp:253] Created db iterator in 2.336us
I0714 16:27:26.340726 9984 replica.cpp:259] Seeked to beginning of db in 628ns
I0714 16:27:26.348702 9984 replica.cpp:310] Iterated through 0 keys in the db
in 559ns
I0714 16:27:26.356731 9984 replica.cpp:1040] Replica recovered with log
positions 0 -> 0 and holes { 0 } and unlearned { }
I0714 16:27:26.364753 9984 coordinator.cpp:61] Coordinator attempting to get
elected within 9.999998976secs
I0714 16:27:26.373018 10009 replica.cpp:777] Replica received implicit promise
request for 1
I0714 16:27:26.380614 10009 replica.cpp:781] Replica denying promise request
for 1
I0714 16:27:26.373078 10006 replica.cpp:777] Replica received implicit promise
request for 1
I0714 16:27:26.388710 9984 coordinator.cpp:61] Coordinator attempting to get
elected within 9.999999232secs
I0714 16:27:26.442368 10006 replica.cpp:354] Persisting promise (6 bytes) to
leveldb took 45.811518ms
I0714 16:27:26.442406 10006 replica.cpp:953] Persisted promise to 1
I0714 16:27:26.448874 10011 replica.cpp:777] Replica received implicit promise
request for 2
I0714 16:27:26.448935 10012 replica.cpp:777] Replica received implicit promise
request for 2
I0714 16:27:26.468737 10012 replica.cpp:354] Persisting promise (6 bytes) to
leveldb took 4.380537ms
I0714 16:27:26.487759 10012 replica.cpp:953] Persisted promise to 2
I0714 16:27:26.471591 10011 replica.cpp:354] Persisting promise (6 bytes) to
leveldb took 15.224057ms
I0714 16:27:26.504217 10011 replica.cpp:953] Persisted promise to 2
I0714 16:27:26.512413 9984 coordinator.cpp:115] Coordinator elected,
attempting to fill missing positions
I0714 16:27:26.525559 9984 coordinator.cpp:396] Coordinator attempting to fill
position 0 in the log
I0714 16:27:26.528326 10011 replica.cpp:705] Replica received explicit promise
request for 2 for position 0
I0714 16:27:26.528393 10013 replica.cpp:705] Replica received explicit promise
request for 2 for position 0
I0714 16:27:26.536161 10011 replica.cpp:470] Reading position from leveldb took
11.196us
I0714 16:27:26.556309 10013 replica.cpp:385] Persisting action (8 bytes) to
leveldb took 12.184991ms
I0714 16:27:26.575484 10013 replica.cpp:968] Persisted action at 0
I0714 16:27:26.559298 10011 replica.cpp:385] Persisting action (14 bytes) to
leveldb took 7.200853ms
I0714 16:27:26.591967 10011 replica.cpp:968] Persisted action at 0
I0714 16:27:26.600278 9984 coordinator.cpp:226] Coordinator attempting to
write NOP action at position 0 within 9.788432128secs
I0714 16:27:26.608155 10013 replica.cpp:808] Replica received write request for
position 0
I0714 16:27:26.615906 10013 replica.cpp:470] Reading position from leveldb took
9.22us
I0714 16:27:26.639039 10013 replica.cpp:385] Persisting action (14 bytes) to
leveldb took 15.175661ms
I0714 16:27:26.639072 10013 replica.cpp:968] Persisted action at 0
I0714 16:27:26.655462 9984 coordinator.cpp:317] Coordinator attempting to
commit NOP action at position 0
I0714 16:27:26.663933 10012 replica.cpp:808] Replica received write request for
position 0
I0714 16:27:26.671728 10012 replica.cpp:470] Reading position from leveldb took
9.779us
I0714 16:27:26.683689 10012 replica.cpp:385] Persisting action (16 bytes) to
leveldb took 4.006607ms
I0714 16:27:26.687647 10012 replica.cpp:968] Persisted action at 0
I0714 16:27:26.695742 9984 coordinator.cpp:385] Telling other replicas of
learned action at position 0
I0714 16:27:26.703698 9984 coordinator.cpp:396] Coordinator attempting to fill
position 1 in the log
I0714 16:27:26.711916 10008 replica.cpp:705] Replica received explicit promise
request for 2 for position 1
I0714 16:27:26.711936 10007 replica.cpp:705] Replica received explicit promise
request for 2 for position 1
I0714 16:27:26.727572 10007 replica.cpp:470] Reading position from leveldb took
11.975us
I0714 16:27:26.723500 10008 replica.cpp:385] Persisting action (8 bytes) to
leveldb took 3.924472ms
I0714 16:27:26.754871 10008 replica.cpp:968] Persisted action at 1
I0714 16:27:26.762619 10007 replica.cpp:385] Persisting action (17 bytes) to
leveldb took 27.104882ms
I0714 16:27:26.779373 10007 replica.cpp:968] Persisted action at 1
I0714 16:27:26.787468 9984 coordinator.cpp:226] Coordinator attempting to
write APPEND action at position 1 within 9.60124032secs
I0714 16:27:26.795611 10011 replica.cpp:808] Replica received write request for
position 1
I0714 16:27:26.803319 10011 replica.cpp:470] Reading position from leveldb took
10.348us
I0714 16:27:26.838358 10011 replica.cpp:385] Persisting action (17 bytes) to
leveldb took 27.084475ms
I0714 16:27:26.838392 10011 replica.cpp:968] Persisted action at 1
I0714 16:27:26.846732 9984 coordinator.cpp:317] Coordinator attempting to
commit APPEND action at position 1
I0714 16:27:26.855398 10013 replica.cpp:808] Replica received write request for
position 1
I0714 16:27:26.863164 10013 replica.cpp:470] Reading position from leveldb took
7.717us
I0714 16:27:26.874758 10013 replica.cpp:385] Persisting action (19 bytes) to
leveldb took 3.671327ms
I0714 16:27:26.879050 10013 replica.cpp:968] Persisted action at 1
I0714 16:27:26.887199 9984 coordinator.cpp:385] Telling other replicas of
learned action at position 1
I0714 16:27:26.895110 9984 coordinator.cpp:396] Coordinator attempting to fill
position 2 in the log
I0714 16:27:26.903223 10010 replica.cpp:705] Replica received explicit promise
request for 2 for position 2
I0714 16:27:26.903295 10013 replica.cpp:705] Replica received explicit promise
request for 2 for position 2
I0714 16:27:26.910975 10010 replica.cpp:470] Reading position from leveldb took
8.171us
I0714 16:27:27.195600 10013 replica.cpp:385] Persisting action (8 bytes) to
leveldb took 172.997017ms
I0714 16:27:27.206722 10013 replica.cpp:968] Persisted action at 2
I0714 16:27:27.215579 10010 replica.cpp:385] Persisting action (17 bytes) to
leveldb took 53.414636ms
I0714 16:27:27.433336 10010 replica.cpp:968] Persisted action at 2
I0714 16:27:27.545346 9984 coordinator.cpp:226] Coordinator attempting to
write APPEND action at position 2 within 8.84337408secs
I0714 16:27:27.656095 10010 replica.cpp:808] Replica received write request for
position 2
I0714 16:27:27.760342 10010 replica.cpp:470] Reading position from leveldb took
11.431us
I0714 16:27:27.886832 10010 replica.cpp:385] Persisting action (17 bytes) to
leveldb took 14.853565ms
I0714 16:27:27.991597 10010 replica.cpp:968] Persisted action at 2
I0714 16:27:28.102567 9984 coordinator.cpp:317] Coordinator attempting to
commit APPEND action at position 2
I0714 16:27:28.210137 10007 replica.cpp:808] Replica received write request for
position 2
I0714 16:27:28.322583 10007 replica.cpp:470] Reading position from leveldb took
10.147us
I0714 16:27:28.594615 10007 replica.cpp:385] Persisting action (19 bytes) to
leveldb took 160.397651ms
I0714 16:27:28.594651 10007 replica.cpp:968] Persisted action at 2
I0714 16:27:28.700542 9984 coordinator.cpp:385] Telling other replicas of
learned action at position 2
I0714 16:27:28.813117 9984 coordinator.cpp:396] Coordinator attempting to fill
position 3 in the log
I0714 16:27:29.027573 10013 replica.cpp:705] Replica received explicit promise
request for 2 for position 3
I0714 16:27:29.027609 10006 replica.cpp:705] Replica received explicit promise
request for 2 for position 3
I0714 16:27:29.251719 10013 replica.cpp:470] Reading position from leveldb took
12.546us
I0714 16:27:29.527860 10006 replica.cpp:385] Persisting action (8 bytes) to
leveldb took 164.558847ms
I0714 16:27:29.527899 10006 replica.cpp:968] Persisted action at 3
I0714 16:27:29.563917 10013 replica.cpp:385] Persisting action (17 bytes) to
leveldb took 53.101647ms
I0714 16:27:29.785984 10013 replica.cpp:968] Persisted action at 3
I0714 16:27:29.893908 9984 coordinator.cpp:226] Coordinator attempting to
write APPEND action at position 3 within 6.494823424secs
I0714 16:27:30.012223 10006 replica.cpp:808] Replica received write request for
position 3
I0714 16:27:30.131587 10006 replica.cpp:470] Reading position from leveldb took
49.865us
I0714 16:27:30.392055 10006 replica.cpp:385] Persisting action (17 bytes) to
leveldb took 143.523551ms
I0714 16:27:30.392091 10006 replica.cpp:968] Persisted action at 3
I0714 16:27:30.400254 9984 coordinator.cpp:317] Coordinator attempting to
commit APPEND action at position 3
I0714 16:27:30.514436 10013 replica.cpp:808] Replica received write request for
position 3
I0714 16:27:30.625924 10013 replica.cpp:470] Reading position from leveldb took
49.151us
I0714 16:27:30.901687 10013 replica.cpp:385] Persisting action (19 bytes) to
leveldb took 168.174898ms
I0714 16:27:30.901720 10013 replica.cpp:968] Persisted action at 3
I0714 16:27:31.018265 9984 coordinator.cpp:385] Telling other replicas of
learned action at position 3
I0714 16:27:31.128280 9984 coordinator.cpp:396] Coordinator attempting to fill
position 4 in the log
I0714 16:27:31.240067 10007 replica.cpp:705] Replica received explicit promise
request for 2 for position 4
I0714 16:27:31.240111 10006 replica.cpp:705] Replica received explicit promise
request for 2 for position 4
I0714 16:27:31.353126 10007 replica.cpp:470] Reading position from leveldb took
14.447us
I0714 16:27:31.820147 10006 replica.cpp:385] Persisting action (8 bytes) to
leveldb took 357.080046ms
I0714 16:27:31.820291 10006 replica.cpp:968] Persisted action at 4
I0714 16:27:31.924595 10007 replica.cpp:385] Persisting action (17 bytes) to
leveldb took 138.547949ms
I0714 16:27:32.154578 10007 replica.cpp:968] Persisted action at 4
I0714 16:27:32.240763 9984 coordinator.cpp:226] Coordinator attempting to
write APPEND action at position 4 within 4.147970304secs
I0714 16:27:32.320402 10009 replica.cpp:808] Replica received write request for
position 4
I0714 16:27:32.407912 10009 replica.cpp:470] Reading position from leveldb took
51.208us
I0714 16:27:32.597887 10009 replica.cpp:385] Persisting action (17 bytes) to
leveldb took 104.395289ms
I0714 16:27:32.597919 10009 replica.cpp:968] Persisted action at 4
I0714 16:27:32.702991 9984 coordinator.cpp:317] Coordinator attempting to
commit APPEND action at position 4
I0714 16:27:32.810886 10008 replica.cpp:808] Replica received write request for
position 4
I0714 16:27:32.934155 10008 replica.cpp:470] Reading position from leveldb took
13.419us
I0714 16:27:33.192646 10008 replica.cpp:385] Persisting action (19 bytes) to
leveldb took 136.883828ms
I0714 16:27:33.192682 10008 replica.cpp:968] Persisted action at 4
I0714 16:27:33.209456 9984 coordinator.cpp:385] Telling other replicas of
learned action at position 4
I0714 16:27:33.319069 9984 coordinator.cpp:396] Coordinator attempting to fill
position 5 in the log
I0714 16:27:33.426913 10006 replica.cpp:705] Replica received explicit promise
request for 2 for position 5
I0714 16:27:33.427026 10009 replica.cpp:705] Replica received explicit promise
request for 2 for position 5
I0714 16:27:33.534322 10006 replica.cpp:470] Reading position from leveldb took
58.952us
I0714 16:27:33.659219 10009 replica.cpp:385] Persisting action (8 bytes) to
leveldb took 11.492942ms
I0714 16:27:33.882906 10009 replica.cpp:968] Persisted action at 5
I0714 16:27:33.918465 10006 replica.cpp:385] Persisting action (17 bytes) to
leveldb took 156.915421ms
I0714 16:27:34.026422 10006 replica.cpp:968] Persisted action at 5
I0714 16:27:34.142242 9984 coordinator.cpp:226] Coordinator attempting to
write APPEND action at position 5 within 2.246486272secs
I0714 16:27:34.254112 10006 replica.cpp:808] Replica received write request for
position 5
I0714 16:27:34.365353 10006 replica.cpp:470] Reading position from leveldb took
55.301us
I0714 16:27:34.616361 10006 replica.cpp:385] Persisting action (17 bytes) to
leveldb took 139.439406ms
I0714 16:27:34.616401 10006 replica.cpp:968] Persisted action at 5
I0714 16:27:34.712389 9984 coordinator.cpp:317] Coordinator attempting to
commit APPEND action at position 5
I0714 16:27:34.818411 10009 replica.cpp:808] Replica received write request for
position 5
I0714 16:27:34.921931 10009 replica.cpp:470] Reading position from leveldb took
17.905us
I0714 16:27:35.266427 10009 replica.cpp:385] Persisting action (19 bytes) to
leveldb took 224.892154ms
I0714 16:27:35.266479 10009 replica.cpp:968] Persisted action at 5
I0714 16:27:35.278337 9984 coordinator.cpp:385] Telling other replicas of
learned action at position 5
I0714 16:27:35.388500 9984 coordinator.cpp:396] Coordinator attempting to fill
position 6 in the log
I0714 16:27:35.493741 10006 replica.cpp:705] Replica received explicit promise
request for 2 for position 6
I0714 16:27:35.493794 10010 replica.cpp:705] Replica received explicit promise
request for 2 for position 6
I0714 16:27:35.601150 10006 replica.cpp:470] Reading position from leveldb took
15.619us
I0714 16:27:35.715723 10010 replica.cpp:385] Persisting action (8 bytes) to
leveldb took 10.92735ms
I0714 16:27:35.939981 10010 replica.cpp:968] Persisted action at 6
I0714 16:27:35.974887 10006 replica.cpp:385] Persisting action (17 bytes) to
leveldb took 162.455266ms
I0714 16:27:36.083508 10006 replica.cpp:968] Persisted action at 6
I0714 16:27:36.199393 9984 coordinator.cpp:226] Coordinator attempting to
write APPEND action at position 6 within 189.321216ms
I0714 16:27:36.315032 10008 replica.cpp:808] Replica received write request for
position 6
I0714 16:27:36.389111 9984 coordinator.cpp:307] Coordinator timed out while
attempting to write APPEND action at position 6
../../src/tests/log_tests.cpp:846: Failure
result is NONE
I0714 16:27:36.430405 10008 replica.cpp:470] Reading position from leveldb took
55.019us
I0714 16:27:36.790755 10008 replica.cpp:385] Persisting action (17 bytes) to
leveldb took 138.267479ms
I0714 16:27:36.790792 10008 replica.cpp:968] Persisted action at 6
[ FAILED ] CoordinatorTest.MultipleAppendsNotLearnedFill (12657 ms)
> CoordinatorTest.MultipleAppendsNotLearnedFill is flaky on Jenkins.
> ------------------------------------------------------------------
>
> Key: MESOS-531
> URL: https://issues.apache.org/jira/browse/MESOS-531
> Project: Mesos
> Issue Type: Bug
> Reporter: Benjamin Mahler
> Assignee: Benjamin Hindman
>
> Possibly related to: https://issues.apache.org/jira/browse/MESOS-301
> [ RUN ] CoordinatorTest.MultipleAppendsNotLearnedFill
> I0626 20:41:20.289326 21774 replica.cpp:230] Opened db in 237.445813ms
> I0626 20:41:20.308446 21774 replica.cpp:237] Compacted db in 19.002175ms
> I0626 20:41:20.315197 21774 replica.cpp:253] Created db iterator in 7.332us
> I0626 20:41:20.334137 21774 replica.cpp:259] Seeked to beginning of db in
> 1.932us
> I0626 20:41:20.334539 21774 replica.cpp:310] Iterated through 0 keys in the
> db in 615ns
> I0626 20:41:20.335080 21774 replica.cpp:1040] Replica recovered with log
> positions 0 -> 0 and holes { 0 } and unlearned { }
> I0626 20:41:20.523996 21774 replica.cpp:230] Opened db in 188.349334ms
> I0626 20:41:20.555011 21774 replica.cpp:237] Compacted db in 30.939383ms
> I0626 20:41:20.555060 21774 replica.cpp:253] Created db iterator in 10.073us
> I0626 20:41:20.579107 21774 replica.cpp:259] Seeked to beginning of db in
> 7.307us
> I0626 20:41:20.599915 21774 replica.cpp:310] Iterated through 0 keys in the
> db in 732ns
> I0626 20:41:20.607065 21774 replica.cpp:1040] Replica recovered with log
> positions 0 -> 0 and holes { 0 } and unlearned { }
> I0626 20:41:20.607624 21774 coordinator.cpp:61] Coordinator attempting to get
> elected within 4.999999232secs
> I0626 20:41:20.608510 21912 replica.cpp:777] Replica received implicit
> promise request for 1
> I0626 20:41:20.608522 21917 replica.cpp:777] Replica received implicit
> promise request for 1
> I0626 20:41:20.710583 21912 replica.cpp:354] Persisting promise (6 bytes) to
> leveldb took 101.963472ms
> I0626 20:41:20.735069 21912 replica.cpp:953] Persisted promise to 1
> I0626 20:41:20.727517 21917 replica.cpp:354] Persisting promise (6 bytes) to
> leveldb took 117.919493ms
> I0626 20:41:20.739506 21917 replica.cpp:953] Persisted promise to 1
> I0626 20:41:20.740284 21774 coordinator.cpp:115] Coordinator elected,
> attempting to fill missing positions
> I0626 20:41:20.740641 21774 coordinator.cpp:396] Coordinator attempting to
> fill position 0 in the log
> I0626 20:41:20.741108 21914 replica.cpp:705] Replica received explicit
> promise request for 1 for position 0
> I0626 20:41:20.741199 21916 replica.cpp:705] Replica received explicit
> promise request for 1 for position 0
> I0626 20:41:20.768059 21914 replica.cpp:385] Persisting action (8 bytes) to
> leveldb took 26.626278ms
> I0626 20:41:20.795083 21914 replica.cpp:968] Persisted action at 0
> I0626 20:41:20.789412 21916 replica.cpp:385] Persisting action (8 bytes) to
> leveldb took 47.504565ms
> I0626 20:41:20.807698 21916 replica.cpp:968] Persisted action at 0
> I0626 20:41:20.823902 21774 coordinator.cpp:226] Coordinator attempting to
> write NOP action at position 0 within 4.78372608secs
> I0626 20:41:20.824486 21916 replica.cpp:808] Replica received write request
> for position 0
> I0626 20:41:20.825059 21916 replica.cpp:470] Reading position from leveldb
> took 15.527us
> I0626 20:41:20.862961 21916 replica.cpp:385] Persisting action (14 bytes) to
> leveldb took 37.290911ms
> I0626 20:41:20.862998 21916 replica.cpp:968] Persisted action at 0
> I0626 20:41:20.871186 21774 coordinator.cpp:317] Coordinator attempting to
> commit NOP action at position 0
> I0626 20:41:20.879195 21919 replica.cpp:808] Replica received write request
> for position 0
> I0626 20:41:20.889878 21919 replica.cpp:470] Reading position from leveldb
> took 8.181us
> I0626 20:41:20.919744 21919 replica.cpp:385] Persisting action (16 bytes) to
> leveldb took 24.685238ms
> I0626 20:41:20.919786 21919 replica.cpp:968] Persisted action at 0
> I0626 20:41:20.920251 21774 coordinator.cpp:385] Telling other replicas of
> learned action at position 0
> I0626 20:41:20.920711 21774 coordinator.cpp:226] Coordinator attempting to
> write APPEND action at position 1 within 4.999993088secs
> I0626 20:41:20.927342 21918 replica.cpp:808] Replica received write request
> for position 1
> I0626 20:41:20.994742 21918 replica.cpp:385] Persisting action (17 bytes) to
> leveldb took 53.357611ms
> I0626 20:41:20.994783 21918 replica.cpp:968] Persisted action at 1
> I0626 20:41:21.003219 21774 coordinator.cpp:317] Coordinator attempting to
> commit APPEND action at position 1
> I0626 20:41:21.013100 21915 replica.cpp:808] Replica received write request
> for position 1
> I0626 20:41:21.078357 21915 replica.cpp:385] Persisting action (19 bytes) to
> leveldb took 64.882431ms
> I0626 20:41:21.078403 21915 replica.cpp:968] Persisted action at 1
> I0626 20:41:21.087177 21774 coordinator.cpp:385] Telling other replicas of
> learned action at position 1
> I0626 20:41:21.091090 21774 coordinator.cpp:226] Coordinator attempting to
> write APPEND action at position 2 within 4.99999488secs
> I0626 20:41:21.099269 21915 replica.cpp:808] Replica received write request
> for position 2
> I0626 20:41:21.219250 21915 replica.cpp:385] Persisting action (17 bytes) to
> leveldb took 91.141975ms
> I0626 20:41:21.219358 21915 replica.cpp:968] Persisted action at 2
> I0626 20:41:21.227320 21774 coordinator.cpp:317] Coordinator attempting to
> commit APPEND action at position 2
> I0626 20:41:21.239523 21916 replica.cpp:808] Replica received write request
> for position 2
> I0626 20:41:21.287796 21916 replica.cpp:385] Persisting action (19 bytes) to
> leveldb took 48.019459ms
> I0626 20:41:21.295094 21916 replica.cpp:968] Persisted action at 2
> I0626 20:41:21.303203 21774 coordinator.cpp:385] Telling other replicas of
> learned action at position 2
> I0626 20:41:21.318981 21774 coordinator.cpp:226] Coordinator attempting to
> write APPEND action at position 3 within 4.999994112secs
> I0626 20:41:21.319692 21919 replica.cpp:808] Replica received write request
> for position 3
> I0626 20:41:21.352903 21919 replica.cpp:385] Persisting action (17 bytes) to
> leveldb took 32.915002ms
> I0626 20:41:21.352957 21919 replica.cpp:968] Persisted action at 3
> I0626 20:41:21.359335 21774 coordinator.cpp:317] Coordinator attempting to
> commit APPEND action at position 3
> I0626 20:41:21.359695 21915 replica.cpp:808] Replica received write request
> for position 3
> I0626 20:41:21.419529 21915 replica.cpp:385] Persisting action (19 bytes) to
> leveldb took 52.467613ms
> I0626 20:41:21.427070 21915 replica.cpp:968] Persisted action at 3
> I0626 20:41:21.427574 21774 coordinator.cpp:385] Telling other replicas of
> learned action at position 3
> I0626 20:41:21.428028 21774 coordinator.cpp:226] Coordinator attempting to
> write APPEND action at position 4 within 4.999994112secs
> I0626 20:41:21.428659 21915 replica.cpp:808] Replica received write request
> for position 4
> I0626 20:41:21.455736 21915 replica.cpp:385] Persisting action (17 bytes) to
> leveldb took 26.806304ms
> I0626 20:41:21.455778 21915 replica.cpp:968] Persisted action at 4
> I0626 20:41:21.479257 21774 coordinator.cpp:317] Coordinator attempting to
> commit APPEND action at position 4
> I0626 20:41:21.503290 21913 replica.cpp:808] Replica received write request
> for position 4
> I0626 20:41:21.537670 21913 replica.cpp:385] Persisting action (19 bytes) to
> leveldb took 34.117047ms
> I0626 20:41:21.537742 21913 replica.cpp:968] Persisted action at 4
> I0626 20:41:21.538226 21774 coordinator.cpp:385] Telling other replicas of
> learned action at position 4
> I0626 20:41:21.538622 21774 coordinator.cpp:226] Coordinator attempting to
> write APPEND action at position 5 within 4.999994112secs
> I0626 20:41:21.539290 21913 replica.cpp:808] Replica received write request
> for position 5
> I0626 20:41:21.564021 21913 replica.cpp:385] Persisting action (17 bytes) to
> leveldb took 24.500044ms
> I0626 20:41:21.564059 21913 replica.cpp:968] Persisted action at 5
> I0626 20:41:21.571207 21774 coordinator.cpp:317] Coordinator attempting to
> commit APPEND action at position 5
> I0626 20:41:21.591270 21916 replica.cpp:808] Replica received write request
> for position 5
> I0626 20:41:21.629318 21916 replica.cpp:385] Persisting action (19 bytes) to
> leveldb took 34.212925ms
> I0626 20:41:21.629400 21916 replica.cpp:968] Persisted action at 5
> I0626 20:41:21.629915 21774 coordinator.cpp:385] Telling other replicas of
> learned action at position 5
> I0626 20:41:21.630229 21774 coordinator.cpp:226] Coordinator attempting to
> write APPEND action at position 6 within 4.999995136secs
> I0626 20:41:21.630880 21918 replica.cpp:808] Replica received write request
> for position 6
> I0626 20:41:21.677770 21918 replica.cpp:385] Persisting action (17 bytes) to
> leveldb took 46.614006ms
> I0626 20:41:21.677819 21918 replica.cpp:968] Persisted action at 6
> I0626 20:41:21.683238 21774 coordinator.cpp:317] Coordinator attempting to
> commit APPEND action at position 6
> I0626 20:41:21.699316 21919 replica.cpp:808] Replica received write request
> for position 6
> I0626 20:41:21.729264 21919 replica.cpp:385] Persisting action (19 bytes) to
> leveldb took 22.204145ms
> I0626 20:41:21.729676 21919 replica.cpp:968] Persisted action at 6
> I0626 20:41:21.735285 21774 coordinator.cpp:385] Telling other replicas of
> learned action at position 6
> I0626 20:41:21.735566 21774 coordinator.cpp:226] Coordinator attempting to
> write APPEND action at position 7 within 4.9999936secs
> I0626 20:41:21.736253 21915 replica.cpp:808] Replica received write request
> for position 7
> I0626 20:41:21.763922 21915 replica.cpp:385] Persisting action (17 bytes) to
> leveldb took 27.472401ms
> I0626 20:41:21.763962 21915 replica.cpp:968] Persisted action at 7
> I0626 20:41:21.783509 21774 coordinator.cpp:317] Coordinator attempting to
> commit APPEND action at position 7
> I0626 20:41:21.805896 21915 replica.cpp:808] Replica received write request
> for position 7
> I0626 20:41:21.861004 21915 replica.cpp:385] Persisting action (19 bytes) to
> leveldb took 21.942984ms
> I0626 20:41:21.861044 21915 replica.cpp:968] Persisted action at 7
> I0626 20:41:21.867172 21774 coordinator.cpp:385] Telling other replicas of
> learned action at position 7
> I0626 20:41:21.871148 21774 coordinator.cpp:226] Coordinator attempting to
> write APPEND action at position 8 within 4.99999616secs
> I0626 20:41:21.875263 21919 replica.cpp:808] Replica received write request
> for position 8
> I0626 20:41:21.930502 21919 replica.cpp:385] Persisting action (17 bytes) to
> leveldb took 41.428199ms
> I0626 20:41:21.939056 21919 replica.cpp:968] Persisted action at 8
> I0626 20:41:21.939671 21774 coordinator.cpp:317] Coordinator attempting to
> commit APPEND action at position 8
> I0626 20:41:21.940099 21913 replica.cpp:808] Replica received write request
> for position 8
> I0626 20:41:21.975831 21913 replica.cpp:385] Persisting action (19 bytes) to
> leveldb took 35.384641ms
> I0626 20:41:21.975870 21913 replica.cpp:968] Persisted action at 8
> I0626 20:41:21.976367 21774 coordinator.cpp:385] Telling other replicas of
> learned action at position 8
> I0626 20:41:21.976743 21774 coordinator.cpp:226] Coordinator attempting to
> write APPEND action at position 9 within 4.999994112secs
> I0626 20:41:22.003428 21916 replica.cpp:808] Replica received write request
> for position 9
> I0626 20:41:22.097714 21916 replica.cpp:385] Persisting action (17 bytes) to
> leveldb took 90.627852ms
> I0626 20:41:22.103101 21916 replica.cpp:968] Persisted action at 9
> I0626 20:41:22.119375 21774 coordinator.cpp:317] Coordinator attempting to
> commit APPEND action at position 9
> I0626 20:41:22.123510 21915 replica.cpp:808] Replica received write request
> for position 9
> I0626 20:41:22.517976 21915 replica.cpp:385] Persisting action (19 bytes) to
> leveldb took 366.866721ms
> I0626 20:41:22.634582 21915 replica.cpp:968] Persisted action at 9
> I0626 20:41:22.663561 21774 coordinator.cpp:385] Telling other replicas of
> learned action at position 9
> I0626 20:41:22.663754 21774 coordinator.cpp:226] Coordinator attempting to
> write APPEND action at position 10 within 4.999992832secs
> I0626 20:41:22.664383 21915 replica.cpp:808] Replica received write request
> for position 10
> I0626 20:41:22.749339 21915 replica.cpp:385] Persisting action (18 bytes) to
> leveldb took 84.660755ms
> I0626 20:41:22.749498 21915 replica.cpp:968] Persisted action at 10
> I0626 20:41:22.755388 21774 coordinator.cpp:317] Coordinator attempting to
> commit APPEND action at position 10
> I0626 20:41:22.775377 21918 replica.cpp:808] Replica received write request
> for position 10
> I0626 20:41:22.803761 21918 replica.cpp:385] Persisting action (20 bytes) to
> leveldb took 20.68537ms
> I0626 20:41:22.804170 21918 replica.cpp:968] Persisted action at 10
> I0626 20:41:22.844249 21774 coordinator.cpp:385] Telling other replicas of
> learned action at position 10
> I0626 20:41:23.054677 21774 replica.cpp:230] Opened db in 183.449273ms
> I0626 20:41:23.111276 21774 replica.cpp:237] Compacted db in 56.510958ms
> I0626 20:41:23.111356 21774 replica.cpp:253] Created db iterator in 5.844us
> I0626 20:41:23.111747 21774 replica.cpp:259] Seeked to beginning of db in
> 1.167us
> I0626 20:41:23.119043 21774 replica.cpp:310] Iterated through 0 keys in the
> db in 459ns
> I0626 20:41:23.139217 21774 replica.cpp:1040] Replica recovered with log
> positions 0 -> 0 and holes { 0 } and unlearned { }
> I0626 20:41:23.140028 21774 coordinator.cpp:61] Coordinator attempting to get
> elected within 4.99998592secs
> I0626 20:41:23.141047 21915 replica.cpp:777] Replica received implicit
> promise request for 1
> I0626 20:41:23.141069 21914 replica.cpp:777] Replica received implicit
> promise request for 1
> I0626 20:41:23.141240 21915 replica.cpp:781] Replica denying promise request
> for 1
> I0626 20:41:23.142765 21774 coordinator.cpp:61] Coordinator attempting to get
> elected within 4.99999872secs
> I0626 20:41:23.236892 21914 replica.cpp:354] Persisting promise (6 bytes) to
> leveldb took 94.860911ms
> I0626 20:41:23.237288 21914 replica.cpp:953] Persisted promise to 1
> I0626 20:41:23.243592 21913 replica.cpp:777] Replica received implicit
> promise request for 2
> I0626 20:41:23.243639 21916 replica.cpp:777] Replica received implicit
> promise request for 2
> I0626 20:41:23.311789 21913 replica.cpp:354] Persisting promise (6 bytes) to
> leveldb took 44.663944ms
> I0626 20:41:23.323551 21913 replica.cpp:953] Persisted promise to 2
> I0626 20:41:23.392300 21916 replica.cpp:354] Persisting promise (6 bytes) to
> leveldb took 69.141155ms
> I0626 20:41:23.395490 21916 replica.cpp:953] Persisted promise to 2
> I0626 20:41:23.396211 21774 coordinator.cpp:115] Coordinator elected,
> attempting to fill missing positions
> I0626 20:41:23.396749 21774 coordinator.cpp:396] Coordinator attempting to
> fill position 0 in the log
> I0626 20:41:23.397155 21916 replica.cpp:705] Replica received explicit
> promise request for 2 for position 0
> I0626 20:41:23.397258 21915 replica.cpp:705] Replica received explicit
> promise request for 2 for position 0
> I0626 20:41:23.397424 21916 replica.cpp:470] Reading position from leveldb
> took 16.991us
> I0626 20:41:23.436779 21915 replica.cpp:385] Persisting action (8 bytes) to
> leveldb took 38.895284ms
> I0626 20:41:23.445092 21916 replica.cpp:385] Persisting action (14 bytes) to
> leveldb took 46.738579ms
> I0626 20:41:23.476065 21916 replica.cpp:968] Persisted action at 0
> I0626 20:41:23.475684 21915 replica.cpp:968] Persisted action at 0
> I0626 20:41:23.483412 21774 coordinator.cpp:226] Coordinator attempting to
> write NOP action at position 0 within 4.659352576secs
> I0626 20:41:23.508016 21914 replica.cpp:808] Replica received write request
> for position 0
> I0626 20:41:23.535081 21914 replica.cpp:470] Reading position from leveldb
> took 19.925us
> I0626 20:41:23.598891 21914 replica.cpp:385] Persisting action (14 bytes) to
> leveldb took 31.794238ms
> I0626 20:41:23.619079 21914 replica.cpp:968] Persisted action at 0
> I0626 20:41:23.619822 21774 coordinator.cpp:317] Coordinator attempting to
> commit NOP action at position 0
> I0626 20:41:23.620852 21917 replica.cpp:808] Replica received write request
> for position 0
> I0626 20:41:23.621188 21917 replica.cpp:470] Reading position from leveldb
> took 12.396us
> I0626 20:41:23.651787 21917 replica.cpp:385] Persisting action (16 bytes) to
> leveldb took 30.098942ms
> I0626 20:41:23.651824 21917 replica.cpp:968] Persisted action at 0
> I0626 20:41:23.659102 21774 coordinator.cpp:385] Telling other replicas of
> learned action at position 0
> I0626 20:41:23.669332 21774 coordinator.cpp:396] Coordinator attempting to
> fill position 1 in the log
> I0626 20:41:23.675351 21919 replica.cpp:705] Replica received explicit
> promise request for 2 for position 1
> I0626 20:41:23.675426 21912 replica.cpp:705] Replica received explicit
> promise request for 2 for position 1
> I0626 20:41:23.683060 21919 replica.cpp:470] Reading position from leveldb
> took 12.668us
> I0626 20:41:23.748842 21912 replica.cpp:385] Persisting action (8 bytes) to
> leveldb took 42.732767ms
> I0626 20:41:23.771150 21912 replica.cpp:968] Persisted action at 1
> I0626 20:41:23.770740 21919 replica.cpp:385] Persisting action (17 bytes) to
> leveldb took 64.103326ms
> I0626 20:41:23.772492 21919 replica.cpp:968] Persisted action at 1
> I0626 20:41:23.773185 21774 coordinator.cpp:226] Coordinator attempting to
> write APPEND action at position 1 within 4.369583616secs
> I0626 20:41:23.773668 21913 replica.cpp:808] Replica received write request
> for position 1
> I0626 20:41:23.773900 21913 replica.cpp:470] Reading position from leveldb
> took 31.376us
> I0626 20:41:23.798800 21913 replica.cpp:385] Persisting action (17 bytes) to
> leveldb took 24.487176ms
> I0626 20:41:23.798853 21913 replica.cpp:968] Persisted action at 1
> I0626 20:41:23.799362 21774 coordinator.cpp:317] Coordinator attempting to
> commit APPEND action at position 1
> I0626 20:41:23.799837 21915 replica.cpp:808] Replica received write request
> for position 1
> I0626 20:41:23.800123 21915 replica.cpp:470] Reading position from leveldb
> took 7.923us
> I0626 20:41:23.853301 21915 replica.cpp:385] Persisting action (19 bytes) to
> leveldb took 52.650456ms
> I0626 20:41:23.853366 21915 replica.cpp:968] Persisted action at 1
> I0626 20:41:23.859273 21774 coordinator.cpp:385] Telling other replicas of
> learned action at position 1
> I0626 20:41:23.867152 21774 coordinator.cpp:396] Coordinator attempting to
> fill position 2 in the log
> I0626 20:41:23.883357 21913 replica.cpp:705] Replica received explicit
> promise request for 2 for position 2
> I0626 20:41:23.883427 21915 replica.cpp:705] Replica received explicit
> promise request for 2 for position 2
> I0626 20:41:23.905468 21913 replica.cpp:470] Reading position from leveldb
> took 26.87us
> I0626 20:41:24.010098 21915 replica.cpp:385] Persisting action (8 bytes) to
> leveldb took 67.007264ms
> I0626 20:41:24.026720 21915 replica.cpp:968] Persisted action at 2
> I0626 20:41:24.039180 21913 replica.cpp:385] Persisting action (17 bytes) to
> leveldb took 93.785236ms
> I0626 20:41:24.039219 21913 replica.cpp:968] Persisted action at 2
> I0626 20:41:24.059291 21774 coordinator.cpp:226] Coordinator attempting to
> write APPEND action at position 2 within 4.083469824secs
> I0626 20:41:24.152204 21916 replica.cpp:808] Replica received write request
> for position 2
> I0626 20:41:24.207103 21916 replica.cpp:470] Reading position from leveldb
> took 20.477us
> I0626 20:41:24.297492 21916 replica.cpp:385] Persisting action (17 bytes) to
> leveldb took 70.184444ms
> I0626 20:41:24.297580 21916 replica.cpp:968] Persisted action at 2
> I0626 20:41:24.314306 21774 coordinator.cpp:317] Coordinator attempting to
> commit APPEND action at position 2
> I0626 20:41:24.351313 21914 replica.cpp:808] Replica received write request
> for position 2
> I0626 20:41:24.371170 21914 replica.cpp:470] Reading position from leveldb
> took 26.576us
> I0626 20:41:24.443598 21914 replica.cpp:385] Persisting action (19 bytes) to
> leveldb took 72.01364ms
> I0626 20:41:24.443743 21914 replica.cpp:968] Persisted action at 2
> I0626 20:41:24.444273 21774 coordinator.cpp:385] Telling other replicas of
> learned action at position 2
> I0626 20:41:24.444576 21774 coordinator.cpp:396] Coordinator attempting to
> fill position 3 in the log
> I0626 20:41:24.445240 21913 replica.cpp:705] Replica received explicit
> promise request for 2 for position 3
> I0626 20:41:24.445255 21916 replica.cpp:705] Replica received explicit
> promise request for 2 for position 3
> I0626 20:41:24.445966 21916 replica.cpp:470] Reading position from leveldb
> took 16.94us
> I0626 20:41:24.477943 21913 replica.cpp:385] Persisting action (8 bytes) to
> leveldb took 32.457971ms
> I0626 20:41:24.511087 21913 replica.cpp:968] Persisted action at 3
> I0626 20:41:24.504189 21916 replica.cpp:385] Persisting action (17 bytes) to
> leveldb took 25.827586ms
> I0626 20:41:24.531059 21916 replica.cpp:968] Persisted action at 3
> I0626 20:41:24.531718 21774 coordinator.cpp:226] Coordinator attempting to
> write APPEND action at position 3 within 3.6110528secs
> I0626 20:41:24.532310 21918 replica.cpp:808] Replica received write request
> for position 3
> I0626 20:41:24.532635 21918 replica.cpp:470] Reading position from leveldb
> took 10.518us
> I0626 20:41:24.581715 21918 replica.cpp:385] Persisting action (17 bytes) to
> leveldb took 48.61473ms
> I0626 20:41:24.581756 21918 replica.cpp:968] Persisted action at 3
> I0626 20:41:24.584699 21774 coordinator.cpp:317] Coordinator attempting to
> commit APPEND action at position 3
> I0626 20:41:24.591269 21916 replica.cpp:808] Replica received write request
> for position 3
> I0626 20:41:24.601011 21916 replica.cpp:470] Reading position from leveldb
> took 7.182us
> I0626 20:41:24.636215 21916 replica.cpp:385] Persisting action (19 bytes) to
> leveldb took 34.690083ms
> I0626 20:41:24.636250 21916 replica.cpp:968] Persisted action at 3
> I0626 20:41:24.642242 21774 coordinator.cpp:385] Telling other replicas of
> learned action at position 3
> I0626 20:41:24.647207 21774 coordinator.cpp:396] Coordinator attempting to
> fill position 4 in the log
> I0626 20:41:24.655419 21914 replica.cpp:705] Replica received explicit
> promise request for 2 for position 4
> I0626 20:41:24.655449 21912 replica.cpp:705] Replica received explicit
> promise request for 2 for position 4
> I0626 20:41:24.663072 21914 replica.cpp:470] Reading position from leveldb
> took 13.025us
> I0626 20:41:24.752864 21912 replica.cpp:385] Persisting action (8 bytes) to
> leveldb took 63.273747ms
> I0626 20:41:24.752964 21912 replica.cpp:968] Persisted action at 4
> I0626 20:41:24.771162 21914 replica.cpp:385] Persisting action (17 bytes) to
> leveldb took 76.064668ms
> I0626 20:41:24.812331 21914 replica.cpp:968] Persisted action at 4
> I0626 20:41:24.839303 21774 coordinator.cpp:226] Coordinator attempting to
> write APPEND action at position 4 within 3.303465728secs
> I0626 20:41:24.893604 21919 replica.cpp:808] Replica received write request
> for position 4
> I0626 20:41:24.893775 21919 replica.cpp:470] Reading position from leveldb
> took 32.084us
> I0626 20:41:24.927736 21919 replica.cpp:385] Persisting action (17 bytes) to
> leveldb took 33.511705ms
> I0626 20:41:24.927777 21919 replica.cpp:968] Persisted action at 4
> I0626 20:41:24.975308 21774 coordinator.cpp:317] Coordinator attempting to
> commit APPEND action at position 4
> I0626 20:41:24.983397 21915 replica.cpp:808] Replica received write request
> for position 4
> I0626 20:41:24.991194 21915 replica.cpp:470] Reading position from leveldb
> took 33.638us
> I0626 20:41:25.030565 21915 replica.cpp:385] Persisting action (19 bytes) to
> leveldb took 31.506767ms
> I0626 20:41:25.039055 21915 replica.cpp:968] Persisted action at 4
> I0626 20:41:25.039706 21774 coordinator.cpp:385] Telling other replicas of
> learned action at position 4
> I0626 20:41:25.040030 21774 coordinator.cpp:396] Coordinator attempting to
> fill position 5 in the log
> I0626 20:41:25.040755 21914 replica.cpp:705] Replica received explicit
> promise request for 2 for position 5
> I0626 20:41:25.040809 21918 replica.cpp:705] Replica received explicit
> promise request for 2 for position 5
> I0626 20:41:25.040969 21914 replica.cpp:470] Reading position from leveldb
> took 17.849us
> I0626 20:41:25.731782 21914 replica.cpp:385] Persisting action (17 bytes) to
> leveldb took 689.848034ms
> I0626 20:41:25.731890 21914 replica.cpp:968] Persisted action at 5
> I0626 20:41:25.731782 21918 replica.cpp:385] Persisting action (8 bytes) to
> leveldb took 690.345411ms
> I0626 20:41:25.935171 21918 replica.cpp:968] Persisted action at 5
> I0626 20:41:25.959568 21774 coordinator.cpp:226] Coordinator attempting to
> write APPEND action at position 5 within 2.183219712secs
> I0626 20:41:25.987756 21914 replica.cpp:808] Replica received write request
> for position 5
> I0626 20:41:26.023177 21914 replica.cpp:470] Reading position from leveldb
> took 25.73us
> I0626 20:41:26.807257 21914 replica.cpp:385] Persisting action (17 bytes) to
> leveldb took 783.485219ms
> I0626 20:41:26.807368 21914 replica.cpp:968] Persisted action at 5
> I0626 20:41:26.831714 21774 coordinator.cpp:317] Coordinator attempting to
> commit APPEND action at position 5
> I0626 20:41:26.943361 21912 replica.cpp:808] Replica received write request
> for position 5
> I0626 20:41:27.013192 21912 replica.cpp:470] Reading position from leveldb
> took 26.435us
> I0626 20:41:27.136229 21912 replica.cpp:385] Persisting action (19 bytes) to
> leveldb took 113.172463ms
> I0626 20:41:27.136286 21912 replica.cpp:968] Persisted action at 5
> I0626 20:41:27.137073 21774 coordinator.cpp:385] Telling other replicas of
> learned action at position 5
> I0626 20:41:27.168833 21774 coordinator.cpp:396] Coordinator attempting to
> fill position 6 in the log
> I0626 20:41:27.195685 21917 replica.cpp:705] Replica received explicit
> promise request for 2 for position 6
> I0626 20:41:27.195741 21919 replica.cpp:705] Replica received explicit
> promise request for 2 for position 6
> I0626 20:41:27.238976 21917 replica.cpp:470] Reading position from leveldb
> took 40.612us
> I0626 20:41:27.312754 21919 replica.cpp:385] Persisting action (8 bytes) to
> leveldb took 73.706819ms
> I0626 20:41:27.443476 21917 replica.cpp:385] Persisting action (17 bytes) to
> leveldb took 110.879543ms
> I0626 20:41:27.455013 21917 replica.cpp:968] Persisted action at 6
> I0626 20:41:27.453696 21919 replica.cpp:968] Persisted action at 6
> I0626 20:41:27.456243 21774 coordinator.cpp:226] Coordinator attempting to
> write APPEND action at position 6 within 686.525696ms
> I0626 20:41:27.456938 21916 replica.cpp:808] Replica received write request
> for position 6
> I0626 20:41:27.457139 21916 replica.cpp:470] Reading position from leveldb
> took 23.735us
> I0626 20:41:27.496920 21916 replica.cpp:385] Persisting action (17 bytes) to
> leveldb took 39.292541ms
> I0626 20:41:27.496959 21916 replica.cpp:968] Persisted action at 6
> I0626 20:41:27.531868 21774 coordinator.cpp:317] Coordinator attempting to
> commit APPEND action at position 6
> I0626 20:41:27.651242 21913 replica.cpp:808] Replica received write request
> for position 6
> I0626 20:41:27.660727 21913 replica.cpp:470] Reading position from leveldb
> took 31.153us
> I0626 20:41:27.718060 21913 replica.cpp:385] Persisting action (19 bytes) to
> leveldb took 51.000821ms
> I0626 20:41:27.723131 21913 replica.cpp:968] Persisted action at 6
> I0626 20:41:27.743257 21774 coordinator.cpp:385] Telling other replicas of
> learned action at position 6
> I0626 20:41:27.764978 21774 coordinator.cpp:396] Coordinator attempting to
> fill position 7 in the log
> I0626 20:41:27.771358 21915 replica.cpp:705] Replica received explicit
> promise request for 2 for position 7
> I0626 20:41:27.771390 21912 replica.cpp:705] Replica received explicit
> promise request for 2 for position 7
> I0626 20:41:27.779307 21915 replica.cpp:470] Reading position from leveldb
> took 29.999us
> I0626 20:41:27.834671 21912 replica.cpp:385] Persisting action (8 bytes) to
> leveldb took 51.314695ms
> I0626 20:41:27.891047 21912 replica.cpp:968] Persisted action at 7
> I0626 20:41:27.871721 21915 replica.cpp:385] Persisting action (17 bytes) to
> leveldb took 28.643979ms
> I0626 20:41:27.899489 21915 replica.cpp:968] Persisted action at 7
> I0626 20:41:27.900194 21774 coordinator.cpp:226] Coordinator attempting to
> write APPEND action at position 7 within 242.566656ms
> I0626 20:41:27.900635 21913 replica.cpp:808] Replica received write request
> for position 7
> I0626 20:41:27.900951 21913 replica.cpp:470] Reading position from leveldb
> took 9.194us
> I0626 20:41:27.933037 21913 replica.cpp:385] Persisting action (17 bytes) to
> leveldb took 31.555207ms
> I0626 20:41:27.933074 21913 replica.cpp:968] Persisted action at 7
> I0626 20:41:27.959275 21774 coordinator.cpp:317] Coordinator attempting to
> commit APPEND action at position 7
> I0626 20:41:27.983212 21916 replica.cpp:808] Replica received write request
> for position 7
> I0626 20:41:27.983522 21916 replica.cpp:470] Reading position from leveldb
> took 8.346us
> I0626 20:41:28.017935 21916 replica.cpp:385] Persisting action (19 bytes) to
> leveldb took 33.885755ms
> I0626 20:41:28.018018 21916 replica.cpp:968] Persisted action at 7
> I0626 20:41:28.023262 21774 coordinator.cpp:385] Telling other replicas of
> learned action at position 7
> I0626 20:41:28.031113 21774 coordinator.cpp:396] Coordinator attempting to
> fill position 8 in the log
> I0626 20:41:28.040364 21913 replica.cpp:705] Replica received explicit
> promise request for 2 for position 8
> I0626 20:41:28.040405 21918 replica.cpp:705] Replica received explicit
> promise request for 2 for position 8
> I0626 20:41:28.071641 21913 replica.cpp:470] Reading position from leveldb
> took 39.919us
> I0626 20:41:28.143702 21774 coordinator.cpp:499] Coordinator timed out
> attempting to fill position 8 in the log
> tests/log_tests.cpp:846: Failure
> result is NONE
> I0626 20:41:28.170296 21918 replica.cpp:385] Persisting action (8 bytes) to
> leveldb took 95.220196ms
> I0626 20:41:28.170302 21913 replica.cpp:385] Persisting action (17 bytes) to
> leveldb took 94.763157ms
> I0626 20:41:28.170440 21918 replica.cpp:968] Persisted action at 8
> I0626 20:41:28.170812 21913 replica.cpp:968] Persisted action at 8
> [ FAILED ] CoordinatorTest.MultipleAppendsNotLearnedFill (8121 ms)
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
