Details
-
Bug
-
Status: Resolved
-
Major
-
Resolution: Fixed
-
None
-
None
-
None
Description
[ RUN ] CoordinatorTest.TruncateNotLearnedFill
I0318 17:39:15.814689 2065 replica.cpp:229] Opened db in 218.08ms
I0318 17:39:15.847967 2065 replica.cpp:236] Compacted db in 33.22ms
I0318 17:39:15.850085 2065 replica.cpp:252] Created db iterator in 3.93us
I0318 17:39:15.860255 2065 replica.cpp:258] Seeked to beginning of db in 807.00ns
I0318 17:39:15.873306 2065 replica.cpp:309] Iterated through 0 keys in the db in 656.00ns
I0318 17:39:15.873767 2065 replica.cpp:1039] Replica recovered with log positions 0 -> 0 and holes
I0318 17:39:16.094449 2065 replica.cpp:229] Opened db in 220.16ms
I0318 17:39:16.155133 2065 replica.cpp:236] Compacted db in 60.60ms
I0318 17:39:16.155171 2065 replica.cpp:252] Created db iterator in 4.09us
I0318 17:39:16.182206 2065 replica.cpp:258] Seeked to beginning of db in 654.00ns
I0318 17:39:16.182621 2065 replica.cpp:309] Iterated through 0 keys in the db in 846.00ns
I0318 17:39:16.183148 2065 replica.cpp:1039] Replica recovered with log positions 0 -> 0 and holes { 0 }
and unlearned { }
I0318 17:39:16.183743 2065 coordinator.cpp:60] Coordinator attempting to get elected within 2.00secs
I0318 17:39:16.184865 2212 replica.cpp:776] Replica received implicit promise request for 1
I0318 17:39:16.184958 2213 replica.cpp:776] Replica received implicit promise request for 1
I0318 17:39:16.255133 2213 replica.cpp:353] Persisting promise (6 bytes) to leveldb took 69.81ms
I0318 17:39:16.255182 2213 replica.cpp:952] Persisted promise to 1
I0318 17:39:16.255143 2212 replica.cpp:353] Persisting promise (6 bytes) to leveldb took 70.17ms
I0318 17:39:16.276269 2212 replica.cpp:952] Persisted promise to 1
I0318 17:39:16.306743 2065 coordinator.cpp:114] Coordinator elected, attempting to fill missing positions
I0318 17:39:16.307193 2065 coordinator.cpp:395] Coordinator attempting to fill position 0 in the log
I0318 17:39:16.307705 2215 replica.cpp:704] Replica received explicit promise request for 1 for position 0
I0318 17:39:16.307816 2211 replica.cpp:704] Replica received explicit promise request for 1 for position 0
I0318 17:39:16.347585 2215 replica.cpp:384] Persisting action (8 bytes) to leveldb took 39.54ms
I0318 17:39:16.347623 2215 replica.cpp:967] Persisted action at 0
I0318 17:39:16.397128 2211 replica.cpp:384] Persisting action (8 bytes) to leveldb took 88.85ms
I0318 17:39:16.397166 2211 replica.cpp:967] Persisted action at 0
I0318 17:39:16.397857 2065 coordinator.cpp:225] Coordinator attempting to write NOP action at position 0 within 1.79secs
I0318 17:39:16.398321 2210 replica.cpp:807] Replica received write request for position 0
I0318 17:39:16.398504 2210 replica.cpp:469] Reading position from leveldb took 20.90us
I0318 17:39:16.429518 2210 replica.cpp:384] Persisting action (14 bytes) to leveldb took 30.57ms
I0318 17:39:16.429558 2210 replica.cpp:967] Persisted action at 0
I0318 17:39:16.430193 2065 coordinator.cpp:316] Coordinator attempting to commit NOP action at position 0
I0318 17:39:16.430531 2213 replica.cpp:807] Replica received write request for position 0
I0318 17:39:16.455921 2213 replica.cpp:469] Reading position from leveldb took 14.00us
I0318 17:39:16.480929 2213 replica.cpp:384] Persisting action (16 bytes) to leveldb took 24.60ms
I0318 17:39:16.481076 2213 replica.cpp:967] Persisted action at 0
I0318 17:39:16.481751 2065 coordinator.cpp:384] Telling other replicas of learned action at position 0
I0318 17:39:16.505784 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 1 within 2.00secs
I0318 17:39:16.506458 2215 replica.cpp:807] Replica received write request for position 1
I0318 17:39:16.522603 2215 replica.cpp:384] Persisting action (17 bytes) to leveldb took 15.95ms
I0318 17:39:16.522704 2215 replica.cpp:967] Persisted action at 1
I0318 17:39:16.523479 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 1
I0318 17:39:16.523731 2216 replica.cpp:807] Replica received write request for position 1
I0318 17:39:16.536711 2216 replica.cpp:384] Persisting action (19 bytes) to leveldb took 12.69ms
I0318 17:39:16.536751 2216 replica.cpp:967] Persisted action at 1
I0318 17:39:16.537277 2065 coordinator.cpp:384] Telling other replicas of learned action at position 1
I0318 17:39:16.537631 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 2 within 2.00secs
I0318 17:39:16.539625 2216 replica.cpp:807] Replica received write request for position 2
I0318 17:39:16.606422 2216 replica.cpp:384] Persisting action (17 bytes) to leveldb took 25.23ms
I0318 17:39:16.606458 2216 replica.cpp:967] Persisted action at 2
I0318 17:39:16.607203 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 2
I0318 17:39:16.607470 2210 replica.cpp:807] Replica received write request for position 2
I0318 17:39:16.639116 2210 replica.cpp:384] Persisting action (19 bytes) to leveldb took 31.34ms
I0318 17:39:16.647950 2210 replica.cpp:967] Persisted action at 2
I0318 17:39:16.648910 2065 coordinator.cpp:384] Telling other replicas of learned action at position 2
I0318 17:39:16.672986 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 3 within 2.00secs
I0318 17:39:16.673742 2216 replica.cpp:807] Replica received write request for position 3
I0318 17:39:16.701328 2216 replica.cpp:384] Persisting action (17 bytes) to leveldb took 27.48ms
I0318 17:39:16.701377 2216 replica.cpp:967] Persisted action at 3
I0318 17:39:16.702013 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 3
I0318 17:39:16.702347 2215 replica.cpp:807] Replica received write request for position 3
I0318 17:39:16.753273 2215 replica.cpp:384] Persisting action (19 bytes) to leveldb took 22.03ms
I0318 17:39:16.753310 2215 replica.cpp:967] Persisted action at 3
I0318 17:39:16.753873 2065 coordinator.cpp:384] Telling other replicas of learned action at position 3
I0318 17:39:16.754207 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 4 within 2.00secs
I0318 17:39:16.754878 2211 replica.cpp:807] Replica received write request for position 4
I0318 17:39:16.806016 2211 replica.cpp:384] Persisting action (17 bytes) to leveldb took 22.35ms
I0318 17:39:16.806056 2211 replica.cpp:967] Persisted action at 4
I0318 17:39:16.806717 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 4
I0318 17:39:16.807060 2211 replica.cpp:807] Replica received write request for position 4
I0318 17:39:16.819900 2211 replica.cpp:384] Persisting action (19 bytes) to leveldb took 12.58ms
I0318 17:39:16.819939 2211 replica.cpp:967] Persisted action at 4
I0318 17:39:16.820482 2065 coordinator.cpp:384] Telling other replicas of learned action at position 4
I0318 17:39:16.820806 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 5 within 2.00secs
I0318 17:39:16.821578 2215 replica.cpp:807] Replica received write request for position 5
I0318 17:39:16.835727 2215 replica.cpp:384] Persisting action (17 bytes) to leveldb took 14.03ms
I0318 17:39:16.835806 2215 replica.cpp:967] Persisted action at 5
I0318 17:39:16.836596 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 5
I0318 17:39:16.836850 2211 replica.cpp:807] Replica received write request for position 5
I0318 17:39:16.850519 2211 replica.cpp:384] Persisting action (19 bytes) to leveldb took 13.38ms
I0318 17:39:16.850602 2211 replica.cpp:967] Persisted action at 5
I0318 17:39:16.851225 2065 coordinator.cpp:384] Telling other replicas of learned action at position 5
I0318 17:39:16.851466 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 6 within 2.00secs
I0318 17:39:16.852159 2213 replica.cpp:807] Replica received write request for position 6
I0318 17:39:16.863983 2213 replica.cpp:384] Persisting action (17 bytes) to leveldb took 11.59ms
I0318 17:39:16.864047 2213 replica.cpp:967] Persisted action at 6
I0318 17:39:16.864718 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 6
I0318 17:39:16.865108 2210 replica.cpp:807] Replica received write request for position 6
I0318 17:39:16.878198 2210 replica.cpp:384] Persisting action (19 bytes) to leveldb took 12.87ms
I0318 17:39:16.878244 2210 replica.cpp:967] Persisted action at 6
I0318 17:39:16.878852 2065 coordinator.cpp:384] Telling other replicas of learned action at position 6
I0318 17:39:16.879106 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 7 within 2.00secs
I0318 17:39:16.879812 2217 replica.cpp:807] Replica received write request for position 7
I0318 17:39:16.894014 2217 replica.cpp:384] Persisting action (17 bytes) to leveldb took 14.01ms
I0318 17:39:16.894055 2217 replica.cpp:967] Persisted action at 7
I0318 17:39:16.894824 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 7
I0318 17:39:16.895077 2216 replica.cpp:807] Replica received write request for position 7
I0318 17:39:16.938839 2216 replica.cpp:384] Persisting action (19 bytes) to leveldb took 43.51ms
I0318 17:39:16.938889 2216 replica.cpp:967] Persisted action at 7
I0318 17:39:16.939472 2065 coordinator.cpp:384] Telling other replicas of learned action at position 7
I0318 17:39:16.939764 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 8 within 2.00secs
I0318 17:39:16.964892 2213 replica.cpp:807] Replica received write request for position 8
I0318 17:39:16.991307 2213 replica.cpp:384] Persisting action (17 bytes) to leveldb took 25.96ms
I0318 17:39:16.991737 2213 replica.cpp:967] Persisted action at 8
I0318 17:39:16.992465 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 8
I0318 17:39:16.992831 2212 replica.cpp:807] Replica received write request for position 8
I0318 17:39:17.024981 2212 replica.cpp:384] Persisting action (19 bytes) to leveldb took 31.82ms
I0318 17:39:17.025022 2212 replica.cpp:967] Persisted action at 8
I0318 17:39:17.025594 2065 coordinator.cpp:384] Telling other replicas of learned action at position 8
I0318 17:39:17.025832 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 9 within 2.00secs
I0318 17:39:17.050117 2212 replica.cpp:807] Replica received write request for position 9
I0318 17:39:17.104487 2212 replica.cpp:384] Persisting action (17 bytes) to leveldb took 54.23ms
I0318 17:39:17.104554 2212 replica.cpp:967] Persisted action at 9
I0318 17:39:17.105213 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 9
I0318 17:39:17.105638 2211 replica.cpp:807] Replica received write request for position 9
I0318 17:39:17.179771 2211 replica.cpp:384] Persisting action (19 bytes) to leveldb took 65.36ms
I0318 17:39:17.179816 2211 replica.cpp:967] Persisted action at 9
I0318 17:39:17.180683 2065 coordinator.cpp:384] Telling other replicas of learned action at position 9
I0318 17:39:17.214526 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 10 within 2.00secs
I0318 17:39:17.215579 2215 replica.cpp:807] Replica received write request for position 10
I0318 17:39:17.255571 2215 replica.cpp:384] Persisting action (18 bytes) to leveldb took 14.09ms
I0318 17:39:17.255609 2215 replica.cpp:967] Persisted action at 10
I0318 17:39:17.256217 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 10
I0318 17:39:17.257014 2212 replica.cpp:807] Replica received write request for position 10
I0318 17:39:17.322252 2212 replica.cpp:384] Persisting action (20 bytes) to leveldb took 30.32ms
I0318 17:39:17.322294 2212 replica.cpp:967] Persisted action at 10
I0318 17:39:17.322865 2065 coordinator.cpp:384] Telling other replicas of learned action at position 10
I0318 17:39:17.323133 2065 coordinator.cpp:225] Coordinator attempting to write TRUNCATE action at position 11 within 2.00secs
I0318 17:39:17.323843 2214 replica.cpp:807] Replica received write request for position 11
I0318 17:39:17.338723 2214 replica.cpp:384] Persisting action (16 bytes) to leveldb took 14.69ms
I0318 17:39:17.338762 2214 replica.cpp:967] Persisted action at 11
I0318 17:39:17.339308 2065 coordinator.cpp:316] Coordinator attempting to commit TRUNCATE action at position 11
I0318 17:39:17.339732 2215 replica.cpp:807] Replica received write request for position 11
I0318 17:39:17.352978 2215 replica.cpp:384] Persisting action (18 bytes) to leveldb took 12.96ms
I0318 17:39:17.353039 2215 replica.cpp:432] Deleting ~7 keys from leveldb took 24.67us
I0318 17:39:17.353363 2215 replica.cpp:967] Persisted action at 11
I0318 17:39:17.354009 2065 coordinator.cpp:384] Telling other replicas of learned action at position 11
I0318 17:39:17.584053 2065 replica.cpp:229] Opened db in 229.69ms
I0318 17:39:17.642423 2065 replica.cpp:236] Compacted db in 58.33ms
I0318 17:39:17.642469 2065 replica.cpp:252] Created db iterator in 3.55us
I0318 17:39:17.642763 2065 replica.cpp:258] Seeked to beginning of db in 858.00ns
I0318 17:39:17.643199 2065 replica.cpp:309] Iterated through 0 keys in the db in 696.00ns
I0318 17:39:17.643694 2065 replica.cpp:1039] Replica recovered with log positions 0 -> 0 and holes
and unlearned { }
I0318 17:39:17.644258 2065 coordinator.cpp:60] Coordinator attempting to get elected within 2.00secs
I0318 17:39:17.645339 2211 replica.cpp:776] Replica received implicit promise request for 1
I0318 17:39:17.645470 2211 replica.cpp:780] Replica denying promise request for 1
I0318 17:39:17.645428 2214 replica.cpp:776] Replica received implicit promise request for 1
I0318 17:39:17.646055 2065 coordinator.cpp:60] Coordinator attempting to get elected within 2.00secs
I0318 17:39:17.724088 2214 replica.cpp:353] Persisting promise (6 bytes) to leveldb took 77.82ms
I0318 17:39:17.724148 2214 replica.cpp:952] Persisted promise to 1
I0318 17:39:17.724967 2210 replica.cpp:776] Replica received implicit promise request for 2
I0318 17:39:17.725188 2216 replica.cpp:776] Replica received implicit promise request for 2
I0318 17:39:17.764500 2216 replica.cpp:353] Persisting promise (6 bytes) to leveldb took 25.39ms
I0318 17:39:17.764585 2216 replica.cpp:952] Persisted promise to 2
I0318 17:39:17.764873 2210 replica.cpp:353] Persisting promise (6 bytes) to leveldb took 39.85ms
I0318 17:39:17.765687 2210 replica.cpp:952] Persisted promise to 2
I0318 17:39:17.766528 2065 coordinator.cpp:114] Coordinator elected, attempting to fill missing positions
I0318 17:39:17.766870 2065 coordinator.cpp:395] Coordinator attempting to fill position 0 in the log
I0318 17:39:17.767441 2214 replica.cpp:704] Replica received explicit promise request for 2 for position 0
I0318 17:39:17.767596 2214 replica.cpp:469] Reading position from leveldb took 18.08us
I0318 17:39:17.767633 2217 replica.cpp:704] Replica received explicit promise request for 2 for position 0
I0318 17:39:17.788717 2214 replica.cpp:384] Persisting action (14 bytes) to leveldb took 20.62ms
I0318 17:39:17.806522 2214 replica.cpp:967] Persisted action at 0
I0318 17:39:17.822010 2217 replica.cpp:384] Persisting action (8 bytes) to leveldb took 53.48ms
I0318 17:39:17.830750 2217 replica.cpp:967] Persisted action at 0
I0318 17:39:17.831537 2065 coordinator.cpp:225] Coordinator attempting to write NOP action at position 0 within 1.81secs
I0318 17:39:17.832728 2212 replica.cpp:807] Replica received write request for position 0
I0318 17:39:17.832890 2212 replica.cpp:469] Reading position from leveldb took 9.90us
I0318 17:39:17.847035 2212 replica.cpp:384] Persisting action (14 bytes) to leveldb took 13.71ms
I0318 17:39:17.847076 2212 replica.cpp:967] Persisted action at 0
I0318 17:39:17.847815 2065 coordinator.cpp:316] Coordinator attempting to commit NOP action at position 0
I0318 17:39:17.848116 2210 replica.cpp:807] Replica received write request for position 0
I0318 17:39:17.848399 2210 replica.cpp:469] Reading position from leveldb took 25.28us
I0318 17:39:17.872755 2210 replica.cpp:384] Persisting action (16 bytes) to leveldb took 23.90ms
I0318 17:39:17.872879 2210 replica.cpp:967] Persisted action at 0
I0318 17:39:17.873520 2065 coordinator.cpp:384] Telling other replicas of learned action at position 0
I0318 17:39:17.873733 2065 coordinator.cpp:395] Coordinator attempting to fill position 1 in the log
I0318 17:39:17.874423 2213 replica.cpp:704] Replica received explicit promise request for 2 for position 1
I0318 17:39:17.874550 2215 replica.cpp:704] Replica received explicit promise request for 2 for position 1
I0318 17:39:17.874876 2213 replica.cpp:469] Reading position from leveldb took 23.41us
I0318 17:39:17.905153 2215 replica.cpp:384] Persisting action (8 bytes) to leveldb took 30.03ms
I0318 17:39:17.905227 2215 replica.cpp:967] Persisted action at 1
I0318 17:39:17.913689 2213 replica.cpp:384] Persisting action (17 bytes) to leveldb took 37.95ms
I0318 17:39:17.914085 2213 replica.cpp:967] Persisted action at 1
I0318 17:39:17.916038 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 1 within 1.73secs
I0318 17:39:17.917341 2216 replica.cpp:807] Replica received write request for position 1
I0318 17:39:17.951892 2216 replica.cpp:469] Reading position from leveldb took 44.45us
I0318 17:39:17.980691 2216 replica.cpp:384] Persisting action (17 bytes) to leveldb took 28.18ms
I0318 17:39:17.981097 2216 replica.cpp:967] Persisted action at 1
I0318 17:39:17.982131 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 1
I0318 17:39:17.982441 2211 replica.cpp:807] Replica received write request for position 1
I0318 17:39:17.982987 2211 replica.cpp:469] Reading position from leveldb took 10.03us
I0318 17:39:18.026657 2211 replica.cpp:384] Persisting action (19 bytes) to leveldb took 42.86ms
I0318 17:39:18.026696 2211 replica.cpp:967] Persisted action at 1
I0318 17:39:18.027278 2065 coordinator.cpp:384] Telling other replicas of learned action at position 1
I0318 17:39:18.027602 2065 coordinator.cpp:395] Coordinator attempting to fill position 2 in the log
I0318 17:39:18.028259 2217 replica.cpp:704] Replica received explicit promise request for 2 for position 2
I0318 17:39:18.028323 2211 replica.cpp:704] Replica received explicit promise request for 2 for position 2
I0318 17:39:18.028558 2217 replica.cpp:469] Reading position from leveldb took 26.11us
I0318 17:39:18.093061 2211 replica.cpp:384] Persisting action (8 bytes) to leveldb took 64.11ms
I0318 17:39:18.093106 2211 replica.cpp:967] Persisted action at 2
I0318 17:39:18.093062 2217 replica.cpp:384] Persisting action (17 bytes) to leveldb took 63.54ms
I0318 17:39:18.094148 2217 replica.cpp:967] Persisted action at 2
I0318 17:39:18.095574 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 2 within 1.55secs
I0318 17:39:18.122726 2211 replica.cpp:807] Replica received write request for position 2
I0318 17:39:18.123183 2211 replica.cpp:469] Reading position from leveldb took 14.17us
I0318 17:39:18.163554 2211 replica.cpp:384] Persisting action (17 bytes) to leveldb took 20.01ms
I0318 17:39:18.163594 2211 replica.cpp:967] Persisted action at 2
I0318 17:39:18.165261 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 2
I0318 17:39:18.206522 2210 replica.cpp:807] Replica received write request for position 2
I0318 17:39:18.206655 2210 replica.cpp:469] Reading position from leveldb took 11.59us
I0318 17:39:18.238561 2210 replica.cpp:384] Persisting action (19 bytes) to leveldb took 31.42ms
I0318 17:39:18.238612 2210 replica.cpp:967] Persisted action at 2
I0318 17:39:18.239583 2065 coordinator.cpp:384] Telling other replicas of learned action at position 2
I0318 17:39:18.239930 2065 coordinator.cpp:395] Coordinator attempting to fill position 3 in the log
I0318 17:39:18.240628 2213 replica.cpp:704] Replica received explicit promise request for 2 for position 3
I0318 17:39:18.240641 2217 replica.cpp:704] Replica received explicit promise request for 2 for position 3
I0318 17:39:18.240749 2213 replica.cpp:469] Reading position from leveldb took 15.49us
I0318 17:39:18.304939 2217 replica.cpp:384] Persisting action (8 bytes) to leveldb took 63.71ms
I0318 17:39:18.304981 2217 replica.cpp:967] Persisted action at 3
I0318 17:39:18.305294 2213 replica.cpp:384] Persisting action (17 bytes) to leveldb took 63.54ms
I0318 17:39:18.306088 2213 replica.cpp:967] Persisted action at 3
I0318 17:39:18.306813 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 3 within 1.34secs
I0318 17:39:18.307317 2212 replica.cpp:807] Replica received write request for position 3
I0318 17:39:18.307517 2212 replica.cpp:469] Reading position from leveldb took 13.03us
I0318 17:39:18.330164 2212 replica.cpp:384] Persisting action (17 bytes) to leveldb took 22.16ms
I0318 17:39:18.330203 2212 replica.cpp:967] Persisted action at 3
I0318 17:39:18.331321 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 3
I0318 17:39:18.352555 2211 replica.cpp:807] Replica received write request for position 3
I0318 17:39:18.353101 2211 replica.cpp:469] Reading position from leveldb took 11.78us
I0318 17:39:18.405812 2211 replica.cpp:384] Persisting action (19 bytes) to leveldb took 25.26ms
I0318 17:39:18.405853 2211 replica.cpp:967] Persisted action at 3
I0318 17:39:18.406959 2065 coordinator.cpp:384] Telling other replicas of learned action at position 3
I0318 17:39:18.439013 2065 coordinator.cpp:395] Coordinator attempting to fill position 4 in the log
I0318 17:39:18.440008 2214 replica.cpp:704] Replica received explicit promise request for 2 for position 4
I0318 17:39:18.440127 2213 replica.cpp:704] Replica received explicit promise request for 2 for position 4
I0318 17:39:18.460943 2214 replica.cpp:469] Reading position from leveldb took 23.66us
I0318 17:39:18.488412 2213 replica.cpp:384] Persisting action (8 bytes) to leveldb took 27.07ms
I0318 17:39:18.488451 2213 replica.cpp:967] Persisted action at 4
I0318 17:39:18.488793 2214 replica.cpp:384] Persisting action (17 bytes) to leveldb took 26.92ms
I0318 17:39:18.489665 2214 replica.cpp:967] Persisted action at 4
I0318 17:39:18.490408 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 4 within 1.16secs
I0318 17:39:18.490895 2216 replica.cpp:807] Replica received write request for position 4
I0318 17:39:18.491101 2216 replica.cpp:469] Reading position from leveldb took 15.63us
I0318 17:39:18.501545 2216 replica.cpp:384] Persisting action (17 bytes) to leveldb took 9.98ms
I0318 17:39:18.501585 2216 replica.cpp:967] Persisted action at 4
I0318 17:39:18.502164 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 4
I0318 17:39:18.502578 2216 replica.cpp:807] Replica received write request for position 4
I0318 17:39:18.502843 2216 replica.cpp:469] Reading position from leveldb took 9.89us
I0318 17:39:18.530763 2216 replica.cpp:384] Persisting action (19 bytes) to leveldb took 27.44ms
I0318 17:39:18.530844 2216 replica.cpp:967] Persisted action at 4
I0318 17:39:18.531810 2065 coordinator.cpp:384] Telling other replicas of learned action at position 4
I0318 17:39:18.563977 2065 coordinator.cpp:395] Coordinator attempting to fill position 5 in the log
I0318 17:39:18.564590 2215 replica.cpp:704] Replica received explicit promise request for 2 for position 5
I0318 17:39:18.564715 2211 replica.cpp:704] Replica received explicit promise request for 2 for position 5
I0318 17:39:18.564733 2215 replica.cpp:469] Reading position from leveldb took 14.91us
I0318 17:39:18.589053 2211 replica.cpp:384] Persisting action (8 bytes) to leveldb took 23.83ms
I0318 17:39:18.589104 2211 replica.cpp:967] Persisted action at 5
I0318 17:39:18.649345 2215 replica.cpp:384] Persisting action (17 bytes) to leveldb took 72.95ms
I0318 17:39:18.658097 2215 replica.cpp:967] Persisted action at 5
I0318 17:39:18.658870 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 5 within 987.19ms
I0318 17:39:18.660074 2214 replica.cpp:807] Replica received write request for position 5
I0318 17:39:18.660208 2214 replica.cpp:469] Reading position from leveldb took 9.74us
I0318 17:39:18.688036 2214 replica.cpp:384] Persisting action (17 bytes) to leveldb took 27.35ms
I0318 17:39:18.688077 2214 replica.cpp:967] Persisted action at 5
I0318 17:39:18.720775 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 5
I0318 17:39:18.721174 2217 replica.cpp:807] Replica received write request for position 5
I0318 17:39:18.721413 2217 replica.cpp:469] Reading position from leveldb took 30.09us
I0318 17:39:18.749349 2217 replica.cpp:384] Persisting action (19 bytes) to leveldb took 27.47ms
I0318 17:39:18.749446 2217 replica.cpp:967] Persisted action at 5
I0318 17:39:18.817746 2065 coordinator.cpp:384] Telling other replicas of learned action at position 5
I0318 17:39:18.864328 2065 coordinator.cpp:395] Coordinator attempting to fill position 6 in the log
I0318 17:39:18.864795 2212 replica.cpp:704] Replica received explicit promise request for 2 for position 6
I0318 17:39:18.865005 2212 replica.cpp:469] Reading position from leveldb took 10.66us
I0318 17:39:18.865088 2210 replica.cpp:704] Replica received explicit promise request for 2 for position 6
I0318 17:39:18.974151 2212 replica.cpp:384] Persisting action (17 bytes) to leveldb took 33.01ms
I0318 17:39:19.009759 2212 replica.cpp:967] Persisted action at 6
I0318 17:39:19.011590 2210 replica.cpp:384] Persisting action (8 bytes) to leveldb took 70.04ms
I0318 17:39:19.041193 2210 replica.cpp:967] Persisted action at 6
I0318 17:39:19.041983 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 6 within 604.07ms
I0318 17:39:19.042350 2211 replica.cpp:807] Replica received write request for position 6
I0318 17:39:19.042582 2211 replica.cpp:469] Reading position from leveldb took 14.52us
I0318 17:39:19.069913 2211 replica.cpp:384] Persisting action (17 bytes) to leveldb took 26.87ms
I0318 17:39:19.069960 2211 replica.cpp:967] Persisted action at 6
I0318 17:39:19.110270 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 6
I0318 17:39:19.110947 2210 replica.cpp:807] Replica received write request for position 6
I0318 17:39:19.132870 2210 replica.cpp:469] Reading position from leveldb took 8.05us
I0318 17:39:19.176492 2210 replica.cpp:384] Persisting action (19 bytes) to leveldb took 43.19ms
I0318 17:39:19.176656 2210 replica.cpp:967] Persisted action at 6
I0318 17:39:19.177342 2065 coordinator.cpp:384] Telling other replicas of learned action at position 6
I0318 17:39:19.177526 2065 coordinator.cpp:395] Coordinator attempting to fill position 7 in the log
I0318 17:39:19.179353 2216 replica.cpp:704] Replica received explicit promise request for 2 for position 7
I0318 17:39:19.179477 2216 replica.cpp:469] Reading position from leveldb took 36.26us
I0318 17:39:19.179503 2214 replica.cpp:704] Replica received explicit promise request for 2 for position 7
I0318 17:39:19.221160 2214 replica.cpp:384] Persisting action (8 bytes) to leveldb took 40.66ms
I0318 17:39:19.249800 2214 replica.cpp:967] Persisted action at 7
I0318 17:39:19.253152 2216 replica.cpp:384] Persisting action (17 bytes) to leveldb took 73.20ms
I0318 17:39:19.293562 2216 replica.cpp:967] Persisted action at 7
I0318 17:39:19.294365 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 7 within 351.70ms
I0318 17:39:19.294901 2211 replica.cpp:807] Replica received write request for position 7
I0318 17:39:19.295464 2211 replica.cpp:469] Reading position from leveldb took 21.46us
I0318 17:39:19.348988 2211 replica.cpp:384] Persisting action (17 bytes) to leveldb took 53.08ms
I0318 17:39:19.349021 2211 replica.cpp:967] Persisted action at 7
I0318 17:39:19.369022 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 7
I0318 17:39:19.402114 2217 replica.cpp:807] Replica received write request for position 7
I0318 17:39:19.402240 2217 replica.cpp:469] Reading position from leveldb took 29.85us
I0318 17:39:19.440664 2217 replica.cpp:384] Persisting action (19 bytes) to leveldb took 37.73ms
I0318 17:39:19.441514 2217 replica.cpp:967] Persisted action at 7
I0318 17:39:19.468734 2065 coordinator.cpp:384] Telling other replicas of learned action at position 7
I0318 17:39:19.493752 2065 coordinator.cpp:395] Coordinator attempting to fill position 8 in the log
I0318 17:39:19.494539 2215 replica.cpp:704] Replica received explicit promise request for 2 for position 8
I0318 17:39:19.494627 2215 replica.cpp:469] Reading position from leveldb took 11.81us
I0318 17:39:19.494686 2212 replica.cpp:704] Replica received explicit promise request for 2 for position 8
I0318 17:39:19.523918 2212 replica.cpp:384] Persisting action (8 bytes) to leveldb took 28.28ms
I0318 17:39:19.523987 2212 replica.cpp:967] Persisted action at 8
I0318 17:39:19.548948 2215 replica.cpp:384] Persisting action (17 bytes) to leveldb took 53.88ms
I0318 17:39:19.549355 2215 replica.cpp:967] Persisted action at 8
I0318 17:39:19.566364 2065 coordinator.cpp:225] Coordinator attempting to write APPEND action at position 8 within 79.70ms
I0318 17:39:19.566807 2213 replica.cpp:807] Replica received write request for position 8
I0318 17:39:19.567327 2213 replica.cpp:469] Reading position from leveldb took 16.29us
I0318 17:39:19.623852 2213 replica.cpp:384] Persisting action (17 bytes) to leveldb took 31.76ms
I0318 17:39:19.623893 2213 replica.cpp:967] Persisted action at 8
I0318 17:39:19.642861 2065 coordinator.cpp:316] Coordinator attempting to commit APPEND action at position 8
I0318 17:39:19.648980 2213 replica.cpp:807] Replica received write request for position 8
I0318 17:39:19.649091 2213 replica.cpp:469] Reading position from leveldb took 10.27us
I0318 17:39:19.665549 2213 replica.cpp:384] Persisting action (19 bytes) to leveldb took 16.00ms
I0318 17:39:19.665599 2213 replica.cpp:967] Persisted action at 8
I0318 17:39:19.666586 2065 coordinator.cpp:384] Telling other replicas of learned action at position 8
I0318 17:39:19.692605 2065 coordinator.cpp:395] Coordinator attempting to fill position 9 in the log
I0318 17:39:19.693378 2213 replica.cpp:704] Replica received explicit promise request for 2 for position 9
I0318 17:39:19.693544 2213 replica.cpp:469] Reading position from leveldb took 13.23us
I0318 17:39:19.693467 2215 replica.cpp:704] Replica received explicit promise request for 2 for position 9
I0318 17:39:19.693686 2065 coordinator.cpp:498] Coordinator timed out attempting to fill position 9 in the log
tests/log_tests.cpp:1002: Failure
result is NONE
I0318 17:39:19.723829 2215 replica.cpp:384] Persisting action (8 bytes) to leveldb took 29.38ms
I0318 17:39:19.755179 2215 replica.cpp:967] Persisted action at 9
I0318 17:39:19.761222 2213 replica.cpp:384] Persisting action (17 bytes) to leveldb took 67.30ms
I0318 17:39:19.799235 2213 replica.cpp:967] Persisted action at 9
[ FAILED ] CoordinatorTest.TruncateNotLearnedFill (4204 ms)