Benjamin Mahler created MESOS-531:
-------------------------------------
Summary: 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
