----------------------------------------------------------- This is an automatically generated e-mail. To reply, visit: https://reviews.apache.org/r/75016/#review226627 -----------------------------------------------------------
Bad patch! Reviews applied: [75026, 75006, 75016] Failed command: ['bash', '-c', "set -o pipefail; export OS='ubuntu:20.04' BUILDTOOL='autotools' COMPILER='gcc' CONFIGURATION='--verbose --disable-libtool-wrappers --disable-parallel-test-execution' ENVIRONMENT='GLOG_v=1 MESOS_VERBOSE=1'; ./support/jenkins/buildbot.sh 2>&1 | tee build_75016"] Error: ...<truncated>... 608 leveldb.cpp:460] Deleting ~5 keys from leveldb took 58.296446ms I0702 23:09:08.160527 185622 leveldb.cpp:460] Deleting ~5 keys from leveldb took 58.344862ms I0702 23:09:08.453644 185608 leveldb.cpp:527] Compacting range 0-4 took 293.062117ms I0702 23:09:08.453647 185622 leveldb.cpp:527] Compacting range 0-4 took 293.023561ms I0702 23:09:08.453737 185608 replica.cpp:712] Persisted action TRUNCATE at position 11 I0702 23:09:08.453779 185622 replica.cpp:712] Persisted action TRUNCATE at position 11 I0702 23:09:08.596930 185607 leveldb.cpp:217] Opened db in 142.122166ms I0702 23:09:08.720153 185607 leveldb.cpp:224] Compacted db in 123.177527ms I0702 23:09:08.720275 185607 leveldb.cpp:239] Created db iterator in 58219ns I0702 23:09:08.720345 185607 leveldb.cpp:245] Seeked to beginning of db in 43706ns I0702 23:09:08.720427 185607 leveldb.cpp:320] Iterated through 1 keys in the db in 60342ns I0702 23:09:08.720506 185607 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0702 23:09:08.721552 185614 catchup.cpp:342] Starting missing positions recovery I0702 23:09:08.722127 185619 catchup.cpp:368] Replica is in VOTING status I0702 23:09:08.724004 185609 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(923)@172.17.0.2:39115 I0702 23:09:08.724252 185627 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(924)@172.17.0.2:39115 I0702 23:09:08.725714 185631 recover.cpp:197] Received a recover response from a replica in VOTING status I0702 23:09:08.726336 185631 recover.cpp:197] Received a recover response from a replica in VOTING status I0702 23:09:08.728060 185619 catchup.cpp:423] Starting catch-up from position 0 to 10 I0702 23:09:08.730479 185624 replica.cpp:391] Replica received explicit promise request from __req_res__(926)@172.17.0.2:39115 for position 0 with proposal 0 I0702 23:09:08.730707 185618 replica.cpp:391] Replica received explicit promise request from __req_res__(927)@172.17.0.2:39115 for position 0 with proposal 0 I0702 23:09:08.730892 185630 replica.cpp:391] Replica received explicit promise request from __req_res__(928)@172.17.0.2:39115 for position 0 with proposal 0 I0702 23:09:08.731860 185619 replica.cpp:695] Replica received learned notice for position 0 from log-network(42)@172.17.0.2:39115 I0702 23:09:08.731927 185621 replica.cpp:695] Replica received learned notice for position 0 from log-network(42)@172.17.0.2:39115 I0702 23:09:08.731973 185611 replica.cpp:695] Replica received learned notice for position 0 from log-network(42)@172.17.0.2:39115 I0702 23:09:08.764217 185619 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 32.309763ms I0702 23:09:08.764312 185619 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:08.780947 185621 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 48.976663ms I0702 23:09:08.780962 185611 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 48.952353ms I0702 23:09:08.781044 185621 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:08.781087 185611 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:08.783393 185630 replica.cpp:391] Replica received explicit promise request from __req_res__(929)@172.17.0.2:39115 for position 1 with proposal 0 I0702 23:09:08.783475 185614 replica.cpp:391] Replica received explicit promise request from __req_res__(930)@172.17.0.2:39115 for position 1 with proposal 0 I0702 23:09:08.783777 185622 replica.cpp:391] Replica received explicit promise request from __req_res__(931)@172.17.0.2:39115 for position 1 with proposal 0 I0702 23:09:08.784629 185629 replica.cpp:695] Replica received learned notice for position 1 from log-network(42)@172.17.0.2:39115 I0702 23:09:08.784701 185616 replica.cpp:695] Replica received learned notice for position 1 from log-network(42)@172.17.0.2:39115 I0702 23:09:08.784781 185615 replica.cpp:695] Replica received learned notice for position 1 from log-network(42)@172.17.0.2:39115 I0702 23:09:08.805960 185615 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 21.129343ms I0702 23:09:08.806005 185616 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 21.241774ms I0702 23:09:08.806008 185629 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 21.330119ms I0702 23:09:08.839468 185615 leveldb.cpp:460] Deleting ~1 keys from leveldb took 33.457894ms I0702 23:09:08.839499 185616 leveldb.cpp:460] Deleting ~1 keys from leveldb took 33.434288ms I0702 23:09:08.839504 185629 leveldb.cpp:460] Deleting ~1 keys from leveldb took 33.395602ms I0702 23:09:09.061496 185615 leveldb.cpp:527] Compacting range 0-0 took 221.971287ms I0702 23:09:09.061599 185615 replica.cpp:712] Persisted action NOP at position 1 I0702 23:09:09.064569 185621 replica.cpp:391] Replica received explicit promise request from __req_res__(934)@172.17.0.2:39115 for position 2 with proposal 0 I0702 23:09:09.211786 185616 leveldb.cpp:527] Compacting range 0-0 took 372.224436ms I0702 23:09:09.211791 185629 leveldb.cpp:527] Compacting range 0-0 took 372.184211ms I0702 23:09:09.211877 185616 replica.cpp:712] Persisted action NOP at position 1 I0702 23:09:09.211956 185629 replica.cpp:712] Persisted action NOP at position 1 I0702 23:09:09.212091 185616 replica.cpp:391] Replica received explicit promise request from __req_res__(933)@172.17.0.2:39115 for position 2 with proposal 0 I0702 23:09:09.212158 185629 replica.cpp:391] Replica received explicit promise request from __req_res__(932)@172.17.0.2:39115 for position 2 with proposal 0 I0702 23:09:09.337218 185623 replica.cpp:391] Replica received explicit promise request from __req_res__(935)@172.17.0.2:39115 for position 2 with proposal 1 I0702 23:09:09.337474 185618 replica.cpp:391] Replica received explicit promise request from __req_res__(936)@172.17.0.2:39115 for position 2 with proposal 1 I0702 23:09:09.337652 185608 replica.cpp:391] Replica received explicit promise request from __req_res__(937)@172.17.0.2:39115 for position 2 with proposal 1 I0702 23:09:09.338508 185628 replica.cpp:695] Replica received learned notice for position 2 from log-network(42)@172.17.0.2:39115 I0702 23:09:09.338572 185617 replica.cpp:695] Replica received learned notice for position 2 from log-network(42)@172.17.0.2:39115 I0702 23:09:09.383685 185608 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 45.959862ms I0702 23:09:09.383769 185608 replica.cpp:712] Persisted action NOP at position 2 I0702 23:09:09.384034 185608 replica.cpp:695] Replica received learned notice for position 2 from log-network(42)@172.17.0.2:39115 I0702 23:09:09.403688 185617 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 65.067103ms I0702 23:09:09.403688 185628 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 65.134314ms I0702 23:09:09.433143 185608 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 49.073821ms I0702 23:09:09.612012 185628 leveldb.cpp:460] Deleting ~1 keys from leveldb took 208.21753ms I0702 23:09:09.612013 185617 leveldb.cpp:460] Deleting ~1 keys from leveldb took 208.264679ms I0702 23:09:09.640509 185608 leveldb.cpp:460] Deleting ~1 keys from leveldb took 207.308113ms I0702 23:09:10.003401 185628 leveldb.cpp:527] Compacting range 1-1 took 391.328329ms I0702 23:09:10.003401 185617 leveldb.cpp:527] Compacting range 1-1 took 391.29452ms I0702 23:09:10.003496 185628 replica.cpp:712] Persisted action NOP at position 2 I0702 23:09:10.003540 185617 replica.cpp:712] Persisted action NOP at position 2 I0702 23:09:10.078488 185608 leveldb.cpp:527] Compacting range 1-1 took 437.914215ms I0702 23:09:10.078575 185608 replica.cpp:712] Persisted action NOP at position 2 I0702 23:09:10.081004 185616 replica.cpp:391] Replica received explicit promise request from __req_res__(938)@172.17.0.2:39115 for position 3 with proposal 1 I0702 23:09:10.081243 185611 replica.cpp:391] Replica received explicit promise request from __req_res__(939)@172.17.0.2:39115 for position 3 with proposal 1 I0702 23:09:10.081359 185614 replica.cpp:391] Replica received explicit promise request from __req_res__(940)@172.17.0.2:39115 for position 3 with proposal 1 I0702 23:09:10.082233 185617 replica.cpp:695] Replica received learned notice for position 3 from log-network(42)@172.17.0.2:39115 I0702 23:09:10.082283 185627 replica.cpp:695] Replica received learned notice for position 3 from log-network(42)@172.17.0.2:39115 I0702 23:09:10.128003 185614 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 46.583252ms I0702 23:09:10.128090 185614 replica.cpp:712] Persisted action NOP at position 3 I0702 23:09:10.128310 185614 replica.cpp:695] Replica received learned notice for position 3 from log-network(42)@172.17.0.2:39115 I0702 23:09:10.157577 185627 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 75.251579ms I0702 23:09:10.157584 185617 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 75.313192ms I0702 23:09:10.204200 185614 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 75.8535ms I0702 23:09:10.220973 185627 leveldb.cpp:460] Deleting ~1 keys from leveldb took 63.336707ms I0702 23:09:10.220996 185617 leveldb.cpp:460] Deleting ~1 keys from leveldb took 63.313327ms I0702 23:09:10.248984 185614 leveldb.cpp:460] Deleting ~1 keys from leveldb took 44.725115ms I0702 23:09:10.611692 185617 leveldb.cpp:527] Compacting range 2-2 took 390.606409ms I0702 23:09:10.611694 185627 leveldb.cpp:527] Compacting range 2-2 took 390.650149ms I0702 23:09:10.611796 185617 replica.cpp:712] Persisted action NOP at position 3 I0702 23:09:10.611852 185627 replica.cpp:712] Persisted action NOP at position 3 I0702 23:09:10.686731 185614 leveldb.cpp:527] Compacting range 2-2 took 437.689233ms I0702 23:09:10.686820 185614 replica.cpp:712] Persisted action NOP at position 3 I0702 23:09:10.689354 185618 replica.cpp:391] Replica received explicit promise request from __req_res__(941)@172.17.0.2:39115 for position 4 with proposal 1 I0702 23:09:10.689507 185626 replica.cpp:391] Replica received explicit promise request from __req_res__(942)@172.17.0.2:39115 for position 4 with proposal 1 I0702 23:09:10.689867 185630 replica.cpp:391] Replica received explicit promise request from __req_res__(943)@172.17.0.2:39115 for position 4 with proposal 1 I0702 23:09:10.690557 185615 replica.cpp:695] Replica received learned notice for position 4 from log-network(42)@172.17.0.2:39115 I0702 23:09:10.690600 185614 replica.cpp:695] Replica received learned notice for position 4 from log-network(42)@172.17.0.2:39115 I0702 23:09:10.752357 185630 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 62.404031ms I0702 23:09:10.752444 185630 replica.cpp:712] Persisted action NOP at position 4 I0702 23:09:10.752663 185630 replica.cpp:695] Replica received learned notice for position 4 from log-network(42)@172.17.0.2:39115 I0702 23:09:10.785925 185614 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 95.281897ms I0702 23:09:10.785931 185615 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 95.32688ms I0702 23:09:10.824716 185630 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 72.018768ms I0702 23:09:10.858148 185614 leveldb.cpp:460] Deleting ~1 keys from leveldb took 72.160095ms I0702 23:09:10.858152 185615 leveldb.cpp:460] Deleting ~1 keys from leveldb took 72.119982ms I0702 23:09:10.899933 185630 leveldb.cpp:460] Deleting ~1 keys from leveldb took 75.158109ms I0702 23:09:11.278157 185615 leveldb.cpp:527] Compacting range 3-3 took 419.90579ms I0702 23:09:11.278157 185614 leveldb.cpp:527] Compacting range 3-3 took 419.95165ms I0702 23:09:11.278251 185615 replica.cpp:712] Persisted action NOP at position 4 I0702 23:09:11.278295 185614 replica.cpp:712] Persisted action NOP at position 4 I0702 23:09:11.353307 185630 leveldb.cpp:527] Compacting range 3-3 took 453.315402ms I0702 23:09:11.353394 185630 replica.cpp:712] Persisted action NOP at position 4 I0702 23:09:11.355695 185620 replica.cpp:391] Replica received explicit promise request from __req_res__(944)@172.17.0.2:39115 for position 5 with proposal 1 I0702 23:09:11.355898 185616 replica.cpp:391] Replica received explicit promise request from __req_res__(945)@172.17.0.2:39115 for position 5 with proposal 1 I0702 23:09:11.355926 185620 leveldb.cpp:510] Reading position from leveldb took 156180ns I0702 23:09:11.356084 185616 leveldb.cpp:510] Reading position from leveldb took 114528ns I0702 23:09:11.356209 185622 replica.cpp:391] Replica received explicit promise request from __req_res__(946)@172.17.0.2:39115 for position 5 with proposal 1 I0702 23:09:11.394420 185622 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 38.137026ms I0702 23:09:11.394506 185622 replica.cpp:712] Persisted action NOP at position 5 I0702 23:09:11.537851 185609 replica.cpp:391] Replica received explicit promise request from __req_res__(947)@172.17.0.2:39115 for position 5 with proposal 2 I0702 23:09:11.538049 185609 leveldb.cpp:510] Reading position from leveldb took 142894ns I0702 23:09:11.538061 185619 replica.cpp:391] Replica received explicit promise request from __req_res__(948)@172.17.0.2:39115 for position 5 with proposal 2 I0702 23:09:11.538206 185612 replica.cpp:391] Replica received explicit promise request from __req_res__(949)@172.17.0.2:39115 for position 5 with proposal 2 I0702 23:09:11.538270 185619 leveldb.cpp:510] Reading position from leveldb took 126097ns I0702 23:09:11.538339 185612 leveldb.cpp:510] Reading position from leveldb took 73818ns I0702 23:09:11.594672 185609 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 56.532702ms I0702 23:09:11.594676 185612 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 56.284088ms I0702 23:09:11.594765 185609 replica.cpp:712] Persisted action APPEND at position 5 I0702 23:09:11.594806 185612 replica.cpp:712] Persisted action NOP at position 5 I0702 23:09:11.595878 185613 replica.cpp:695] Replica received learned notice for position 5 from log-network(42)@172.17.0.2:39115 I0702 23:09:11.595992 185624 replica.cpp:695] Replica received learned notice for position 5 from log-network(42)@172.17.0.2:39115 I0702 23:09:11.639083 185619 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 100.747732ms I0702 23:09:11.639173 185619 replica.cpp:712] Persisted action APPEND at position 5 I0702 23:09:11.639441 185619 replica.cpp:695] Replica received learned notice for position 5 from log-network(42)@172.17.0.2:39115 I0702 23:09:11.665755 185624 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 69.703842ms I0702 23:09:11.665755 185613 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 69.831902ms I0702 23:09:11.665851 185624 replica.cpp:712] Persisted action APPEND at position 5 I0702 23:09:11.665894 185613 replica.cpp:712] Persisted action APPEND at position 5 I0702 23:09:11.668256 185609 replica.cpp:391] Replica received explicit promise request from __req_res__(950)@172.17.0.2:39115 for position 6 with proposal 2 I0702 23:09:11.668444 185609 leveldb.cpp:510] Reading position from leveldb took 137944ns I0702 23:09:11.668599 185626 replica.cpp:391] Replica received explicit promise request from __req_res__(952)@172.17.0.2:39115 for position 6 with proposal 2 I0702 23:09:11.714077 185619 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 74.601218ms I0702 23:09:11.714165 185619 replica.cpp:712] Persisted action APPEND at position 5 I0702 23:09:11.714310 185619 replica.cpp:391] Replica received explicit promise request from __req_res__(951)@172.17.0.2:39115 for position 6 with proposal 2 I0702 23:09:11.714464 185619 leveldb.cpp:510] Reading position from leveldb took 112134ns I0702 23:09:11.775539 185626 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 106.892841ms I0702 23:09:11.775539 185609 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 107.005282ms I0702 23:09:11.775652 185626 replica.cpp:712] Persisted action NOP at position 6 I0702 23:09:11.775694 185609 replica.cpp:712] Persisted action APPEND at position 6 I0702 23:09:11.777125 185608 replica.cpp:695] Replica received learned notice for position 6 from log-network(42)@172.17.0.2:39115 I0702 23:09:11.777195 185631 replica.cpp:695] Replica received learned notice for position 6 from log-network(42)@172.17.0.2:39115 I0702 23:09:11.830715 185619 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 116.186509ms I0702 23:09:11.830804 185619 replica.cpp:712] Persisted action APPEND at position 6 I0702 23:09:11.831041 185619 replica.cpp:695] Replica received learned notice for position 6 from log-network(42)@172.17.0.2:39115 I0702 23:09:11.857340 185608 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 80.16001ms I0702 23:09:11.857369 185631 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 80.130678ms I0702 23:09:11.857441 185608 replica.cpp:712] Persisted action APPEND at position 6 I0702 23:09:11.857484 185631 replica.cpp:712] Persisted action APPEND at position 6 I0702 23:09:11.859871 185613 replica.cpp:391] Replica received explicit promise request from __req_res__(953)@172.17.0.2:39115 for position 7 with proposal 2 I0702 23:09:11.860047 185613 leveldb.cpp:510] Reading position from leveldb took 116848ns I0702 23:09:11.860165 185620 replica.cpp:391] Replica received explicit promise request from __req_res__(955)@172.17.0.2:39115 for position 7 with proposal 2 I0702 23:09:11.897387 185619 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 66.311145ms I0702 23:09:11.897475 185619 replica.cpp:712] Persisted action APPEND at position 6 I0702 23:09:11.897620 185619 replica.cpp:391] Replica received explicit promise request from __req_res__(954)@172.17.0.2:39115 for position 7 with proposal 2 I0702 23:09:11.897775 185619 leveldb.cpp:510] Reading position from leveldb took 112730ns I0702 23:09:11.924032 185620 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 63.807142ms I0702 23:09:11.924033 185613 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 63.921813ms I0702 23:09:11.924136 185620 replica.cpp:712] Persisted action NOP at position 7 I0702 23:09:11.924178 185613 replica.cpp:712] Persisted action APPEND at position 7 I0702 23:09:11.925271 185615 replica.cpp:695] Replica received learned notice for position 7 from log-network(42)@172.17.0.2:39115 I0702 23:09:11.925328 185610 replica.cpp:695] Replica received learned notice for position 7 from log-network(42)@172.17.0.2:39115 I0702 23:09:11.964026 185619 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 66.180099ms I0702 23:09:11.964088 185619 replica.cpp:712] Persisted action APPEND at position 7 I0702 23:09:11.964257 185619 replica.cpp:695] Replica received learned notice for position 7 from log-network(42)@172.17.0.2:39115 I0702 23:09:12.015702 185615 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 90.388384ms I0702 23:09:12.015705 185610 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 90.333235ms I0702 23:09:12.015794 185615 replica.cpp:712] Persisted action APPEND at position 7 I0702 23:09:12.015853 185610 replica.cpp:712] Persisted action APPEND at position 7 I0702 23:09:12.018312 185617 replica.cpp:391] Replica received explicit promise request from __req_res__(956)@172.17.0.2:39115 for position 8 with proposal 2 I0702 23:09:12.018488 185617 leveldb.cpp:510] Reading position from leveldb took 118264ns I0702 23:09:12.018771 185614 replica.cpp:391] Replica received explicit promise request from __req_res__(958)@172.17.0.2:39115 for position 8 with proposal 2 I0702 23:09:12.055732 185619 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 91.454949ms I0702 23:09:12.055822 185619 replica.cpp:712] Persisted action APPEND at position 7 I0702 23:09:12.055968 185619 replica.cpp:391] Replica received explicit promise request from __req_res__(957)@172.17.0.2:39115 for position 8 with proposal 2 I0702 23:09:12.056123 185619 leveldb.cpp:510] Reading position from leveldb took 113521ns I0702 23:09:12.090703 185617 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 72.149245ms I0702 23:09:12.090715 185614 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 71.888887ms I0702 23:09:12.090799 185617 replica.cpp:712] Persisted action APPEND at position 8 I0702 23:09:12.090843 185614 replica.cpp:712] Persisted action NOP at position 8 I0702 23:09:12.092114 185621 replica.cpp:695] Replica received learned notice for position 8 from log-network(42)@172.17.0.2:39115 I0702 23:09:12.092157 185611 replica.cpp:695] Replica received learned notice for position 8 from log-network(42)@172.17.0.2:39115 I0702 23:09:12.130731 185619 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 74.541302ms I0702 23:09:12.130820 185619 replica.cpp:712] Persisted action APPEND at position 8 I0702 23:09:12.131057 185619 replica.cpp:695] Replica received learned notice for position 8 from log-network(42)@172.17.0.2:39115 I0702 23:09:12.165695 185611 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 73.494584ms I0702 23:09:12.165699 185621 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 73.52743ms I0702 23:09:12.165787 185611 replica.cpp:712] Persisted action APPEND at position 8 I0702 23:09:12.165833 185621 replica.cpp:712] Persisted action APPEND at position 8 I0702 23:09:12.168188 185614 replica.cpp:391] Replica received explicit promise request from __req_res__(959)@172.17.0.2:39115 for position 9 with proposal 2 I0702 23:09:12.168413 185614 leveldb.cpp:510] Reading position from leveldb took 155860ns I0702 23:09:12.168603 185616 replica.cpp:391] Replica received explicit promise request from __req_res__(961)@172.17.0.2:39115 for position 9 with proposal 2 I0702 23:09:12.214025 185619 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 82.932369ms I0702 23:09:12.214113 185619 replica.cpp:712] Persisted action APPEND at position 8 I0702 23:09:12.214260 185619 replica.cpp:391] Replica received explicit promise request from __req_res__(960)@172.17.0.2:39115 for position 9 with proposal 2 I0702 23:09:12.214417 185619 leveldb.cpp:510] Reading position from leveldb took 114761ns I0702 23:09:12.249011 185616 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 80.349182ms I0702 23:09:12.249013 185614 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 80.505876ms I0702 23:09:12.249114 185616 replica.cpp:712] Persisted action NOP at position 9 I0702 23:09:12.249156 185614 replica.cpp:712] Persisted action APPEND at position 9 I0702 23:09:12.250245 185629 replica.cpp:695] Replica received learned notice for position 9 from log-network(42)@172.17.0.2:39115 I0702 23:09:12.250330 185625 replica.cpp:695] Replica received learned notice for position 9 from log-network(42)@172.17.0.2:39115 I0702 23:09:12.289017 185619 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 74.535003ms I0702 23:09:12.289105 185619 replica.cpp:712] Persisted action APPEND at position 9 I0702 23:09:12.289342 185619 replica.cpp:695] Replica received learned notice for position 9 from log-network(42)@172.17.0.2:39115 I0702 23:09:12.323980 185629 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 73.677931ms I0702 23:09:12.324002 185625 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 73.619879ms I0702 23:09:12.324084 185629 replica.cpp:712] Persisted action APPEND at position 9 I0702 23:09:12.324151 185625 replica.cpp:712] Persisted action APPEND at position 9 I0702 23:09:12.326515 185609 replica.cpp:391] Replica received explicit promise request from __req_res__(962)@172.17.0.2:39115 for position 10 with proposal 2 I0702 23:09:12.326691 185609 leveldb.cpp:510] Reading position from leveldb took 117504ns I0702 23:09:12.326864 185622 replica.cpp:391] Replica received explicit promise request from __req_res__(964)@172.17.0.2:39115 for position 10 with proposal 2 I0702 23:09:12.374337 185619 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 84.961104ms I0702 23:09:12.374425 185619 replica.cpp:712] Persisted action APPEND at position 9 I0702 23:09:12.374570 185619 replica.cpp:391] Replica received explicit promise request from __req_res__(963)@172.17.0.2:39115 for position 10 with proposal 2 I0702 23:09:12.374727 185619 leveldb.cpp:510] Reading position from leveldb took 113360ns I0702 23:09:12.407302 185609 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 80.544358ms I0702 23:09:12.407344 185622 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 80.425145ms I0702 23:09:12.407388 185609 replica.cpp:712] Persisted action APPEND at position 10 I0702 23:09:12.407424 185622 replica.cpp:712] Persisted action NOP at position 10 I0702 23:09:12.408522 185626 replica.cpp:695] Replica received learned notice for position 10 from log-network(42)@172.17.0.2:39115 I0702 23:09:12.408649 185627 replica.cpp:695] Replica received learned notice for position 10 from log-network(42)@172.17.0.2:39115 I0702 23:09:12.457743 185619 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 82.951495ms I0702 23:09:12.457832 185619 replica.cpp:712] Persisted action APPEND at position 10 I0702 23:09:12.458070 185619 replica.cpp:695] Replica received learned notice for position 10 from log-network(42)@172.17.0.2:39115 I0702 23:09:12.490643 185626 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 82.073495ms I0702 23:09:12.490666 185627 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 81.954134ms I0702 23:09:12.490736 185626 replica.cpp:712] Persisted action APPEND at position 10 I0702 23:09:12.490777 185627 replica.cpp:712] Persisted action APPEND at position 10 I0702 23:09:12.491489 185627 catchup.cpp:357] Recover process terminated I0702 23:09:12.493561 185616 leveldb.cpp:510] Reading position from leveldb took 96808ns I0702 23:09:12.493736 185616 leveldb.cpp:510] Reading position from leveldb took 75582ns I0702 23:09:12.493880 185616 leveldb.cpp:510] Reading position from leveldb took 70892ns I0702 23:09:12.494021 185616 leveldb.cpp:510] Reading position from leveldb took 69828ns I0702 23:09:12.494163 185616 leveldb.cpp:510] Reading position from leveldb took 69838ns I0702 23:09:12.494302 185616 leveldb.cpp:510] Reading position from leveldb took 69105ns I0702 23:09:12.506543 185619 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 48.438681ms I0702 23:09:12.506631 185619 replica.cpp:712] Persisted action APPEND at position 10 [ OK ] RecoverTest.CatchupVotingWithGap (6982 ms) [ RUN ] RecoverTest.CatchupVotingOnePosition I0702 23:09:12.641501 185607 leveldb.cpp:217] Opened db in 130.161904ms I0702 23:09:12.674883 185607 leveldb.cpp:224] Compacted db in 33.335107ms I0702 23:09:12.674999 185607 leveldb.cpp:239] Created db iterator in 51699ns I0702 23:09:12.675038 185607 leveldb.cpp:245] Seeked to beginning of db in 12730ns I0702 23:09:12.675065 185607 leveldb.cpp:320] Iterated through 0 keys in the db in 10333ns I0702 23:09:12.675132 185607 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0702 23:09:12.708163 185614 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 32.41765ms I0702 23:09:12.708248 185614 replica.cpp:322] Persisted replica status to VOTING I0702 23:09:12.826162 185607 leveldb.cpp:217] Opened db in 117.016218ms I0702 23:09:12.858220 185607 leveldb.cpp:224] Compacted db in 32.011649ms I0702 23:09:12.858325 185607 leveldb.cpp:239] Created db iterator in 40709ns I0702 23:09:12.858364 185607 leveldb.cpp:245] Seeked to beginning of db in 12049ns I0702 23:09:12.858397 185607 leveldb.cpp:320] Iterated through 0 keys in the db in 9706ns I0702 23:09:12.858455 185607 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0702 23:09:12.884574 185630 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 25.578359ms I0702 23:09:12.884658 185630 replica.cpp:322] Persisted replica status to VOTING I0702 23:09:13.002585 185607 leveldb.cpp:217] Opened db in 117.030817ms I0702 23:09:13.033295 185607 leveldb.cpp:224] Compacted db in 30.663165ms I0702 23:09:13.033401 185607 leveldb.cpp:239] Created db iterator in 40502ns I0702 23:09:13.033439 185607 leveldb.cpp:245] Seeked to beginning of db in 11963ns I0702 23:09:13.033468 185607 leveldb.cpp:320] Iterated through 0 keys in the db in 9903ns I0702 23:09:13.033526 185607 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0702 23:09:13.069316 185625 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 35.320584ms I0702 23:09:13.069409 185625 replica.cpp:322] Persisted replica status to VOTING I0702 23:09:13.187526 185607 leveldb.cpp:217] Opened db in 117.244342ms I0702 23:09:13.283337 185607 leveldb.cpp:224] Compacted db in 95.761745ms I0702 23:09:13.283421 185607 leveldb.cpp:239] Created db iterator in 35504ns I0702 23:09:13.283471 185607 leveldb.cpp:245] Seeked to beginning of db in 30736ns I0702 23:09:13.283530 185607 leveldb.cpp:320] Iterated through 1 keys in the db in 44043ns I0702 23:09:13.283581 185607 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0702 23:09:13.397290 185607 leveldb.cpp:217] Opened db in 113.486133ms I0702 23:09:13.502799 185607 leveldb.cpp:224] Compacted db in 105.462029ms I0702 23:09:13.502909 185607 leveldb.cpp:239] Created db iterator in 47435ns I0702 23:09:13.502976 185607 leveldb.cpp:245] Seeked to beginning of db in 41672ns I0702 23:09:13.503051 185607 leveldb.cpp:320] Iterated through 1 keys in the db in 53942ns I0702 23:09:13.503122 185607 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0702 23:09:13.615859 185607 leveldb.cpp:217] Opened db in 112.393592ms I0702 23:09:13.702816 185607 leveldb.cpp:224] Compacted db in 86.911217ms I0702 23:09:13.702927 185607 leveldb.cpp:239] Created db iterator in 47309ns I0702 23:09:13.702996 185607 leveldb.cpp:245] Seeked to beginning of db in 41649ns I0702 23:09:13.703069 185607 leveldb.cpp:320] Iterated through 1 keys in the db in 53869ns I0702 23:09:13.703141 185607 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0702 23:09:13.703909 185629 catchup.cpp:342] Starting missing positions recovery I0702 23:09:13.704447 185629 catchup.cpp:368] Replica is in VOTING status I0702 23:09:13.706265 185614 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(965)@172.17.0.2:39115 I0702 23:09:13.706432 185623 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(966)@172.17.0.2:39115 I0702 23:09:13.706653 185623 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(967)@172.17.0.2:39115 I0702 23:09:13.707823 185609 recover.cpp:197] Received a recover response from a replica in VOTING status I0702 23:09:13.708436 185609 recover.cpp:197] Received a recover response from a replica in VOTING status I0702 23:09:13.709682 185628 catchup.cpp:357] Recover process terminated [ OK ] RecoverTest.CatchupVotingOnePosition (1204 ms) [----------] 9 tests from RecoverTest (35059 ms total) [----------] 4 tests from LogTest [ RUN ] LogTest.WriteRead I0702 23:09:13.834080 185607 leveldb.cpp:217] Opened db in 118.805591ms I0702 23:09:13.869304 185607 leveldb.cpp:224] Compacted db in 35.171348ms I0702 23:09:13.869427 185607 leveldb.cpp:239] Created db iterator in 60066ns I0702 23:09:13.869495 185607 leveldb.cpp:245] Seeked to beginning of db in 26363ns I0702 23:09:13.869549 185607 leveldb.cpp:320] Iterated through 0 keys in the db in 22253ns I0702 23:09:13.869657 185607 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0702 23:09:13.917421 185617 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 47.158732ms I0702 23:09:13.917513 185617 replica.cpp:322] Persisted replica status to VOTING I0702 23:09:14.052031 185607 leveldb.cpp:217] Opened db in 133.656762ms I0702 23:09:14.086043 185607 leveldb.cpp:224] Compacted db in 33.966283ms I0702 23:09:14.086153 185607 leveldb.cpp:239] Created db iterator in 41139ns I0702 23:09:14.086191 185607 leveldb.cpp:245] Seeked to beginning of db in 11953ns I0702 23:09:14.086220 185607 leveldb.cpp:320] Iterated through 0 keys in the db in 9749ns I0702 23:09:14.086277 185607 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0702 23:09:14.118779 185614 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 32.044205ms I0702 23:09:14.118863 185614 replica.cpp:322] Persisted replica status to VOTING I0702 23:09:14.261924 185607 leveldb.cpp:217] Opened db in 142.238597ms I0702 23:09:14.369541 185607 leveldb.cpp:224] Compacted db in 107.573106ms I0702 23:09:14.369655 185607 leveldb.cpp:239] Created db iterator in 49189ns I0702 23:09:14.369727 185607 leveldb.cpp:245] Seeked to beginning of db in 43716ns I0702 23:09:14.369807 185607 leveldb.cpp:320] Iterated through 1 keys in the db in 59209ns I0702 23:09:14.369879 185607 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0702 23:09:14.480015 185607 leveldb.cpp:217] Opened db in 109.775771ms I0702 23:09:14.586262 185607 leveldb.cpp:224] Compacted db in 106.20114ms I0702 23:09:14.586374 185607 leveldb.cpp:239] Created db iterator in 47516ns I0702 23:09:14.586444 185607 leveldb.cpp:245] Seeked to beginning of db in 42822ns I0702 23:09:14.586520 185607 leveldb.cpp:320] Iterated through 1 keys in the db in 54565ns I0702 23:09:14.586591 185607 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0702 23:09:14.587688 185629 recover.cpp:437] Starting replica recovery I0702 23:09:14.588234 185629 recover.cpp:468] Replica is in VOTING status I0702 23:09:14.588553 185629 recover.cpp:447] Recover process terminated I0702 23:09:14.589219 185610 log.cpp:554] Attempting to start the writer I0702 23:09:14.591471 185620 replica.cpp:497] Replica received implicit promise request from __req_res__(968)@172.17.0.2:39115 with proposal 1 I0702 23:09:14.591687 185618 replica.cpp:497] Replica received implicit promise request from __req_res__(969)@172.17.0.2:39115 with proposal 1 I0702 23:09:14.639083 185620 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 47.547661ms I0702 23:09:14.639176 185620 replica.cpp:344] Persisted promised to 1 I0702 23:09:14.655754 185618 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 64.001389ms I0702 23:09:14.655836 185618 replica.cpp:344] Persisted promised to 1 I0702 23:09:14.656908 185629 coordinator.cpp:238] Coordinator attempting to fill missing positions I0702 23:09:14.658989 185619 replica.cpp:391] Replica received explicit promise request from __req_res__(970)@172.17.0.2:39115 for position 0 with proposal 2 I0702 23:09:14.659111 185615 replica.cpp:391] Replica received explicit promise request from __req_res__(971)@172.17.0.2:39115 for position 0 with proposal 2 I0702 23:09:14.697582 185619 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 38.523817ms I0702 23:09:14.697584 185615 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 38.381023ms I0702 23:09:14.697671 185619 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:14.697716 185615 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:14.699331 185610 replica.cpp:541] Replica received write request for position 0 from __req_res__(972)@172.17.0.2:39115 I0702 23:09:14.699471 185614 replica.cpp:541] Replica received write request for position 0 from __req_res__(973)@172.17.0.2:39115 I0702 23:09:14.699496 185610 leveldb.cpp:510] Reading position from leveldb took 93988ns I0702 23:09:14.699606 185614 leveldb.cpp:510] Reading position from leveldb took 73699ns I0702 23:09:14.739321 185610 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 39.723232ms I0702 23:09:14.739351 185614 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 39.687963ms I0702 23:09:14.739409 185610 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:14.739441 185614 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:14.740226 185625 replica.cpp:695] Replica received learned notice for position 0 from log-network(44)@172.17.0.2:39115 I0702 23:09:14.740271 185618 replica.cpp:695] Replica received learned notice for position 0 from log-network(44)@172.17.0.2:39115 I0702 23:09:14.781133 185618 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 40.801901ms I0702 23:09:14.781159 185625 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 40.885482ms I0702 23:09:14.781231 185618 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:14.781291 185625 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:14.782119 185612 log.cpp:570] Writer started with ending position 0 I0702 23:09:14.783006 185610 log.cpp:578] Attempting to append 11 bytes to the log I0702 23:09:14.783237 185630 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 I0702 23:09:14.784336 185619 replica.cpp:541] Replica received write request for position 1 from __req_res__(974)@172.17.0.2:39115 I0702 23:09:14.784471 185620 replica.cpp:541] Replica received write request for position 1 from __req_res__(975)@172.17.0.2:39115 I0702 23:09:14.969414 185620 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 184.878735ms I0702 23:09:14.969419 185619 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 185.023838ms I0702 23:09:14.969507 185620 replica.cpp:712] Persisted action APPEND at position 1 I0702 23:09:14.969555 185619 replica.cpp:712] Persisted action APPEND at position 1 I0702 23:09:14.970532 185616 replica.cpp:695] Replica received learned notice for position 1 from log-network(44)@172.17.0.2:39115 I0702 23:09:14.970588 185608 replica.cpp:695] Replica received learned notice for position 1 from log-network(44)@172.17.0.2:39115 I0702 23:09:15.014665 185608 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 44.031747ms I0702 23:09:15.014695 185616 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 44.115412ms I0702 23:09:15.014765 185608 replica.cpp:712] Persisted action APPEND at position 1 I0702 23:09:15.014804 185616 replica.cpp:712] Persisted action APPEND at position 1 I0702 23:09:15.017117 185618 leveldb.cpp:510] Reading position from leveldb took 101042ns [ OK ] LogTest.WriteRead (1308 ms) [ RUN ] LogTest.Position I0702 23:09:15.141155 185607 leveldb.cpp:217] Opened db in 117.730098ms I0702 23:09:15.169368 185607 leveldb.cpp:224] Compacted db in 28.165903ms I0702 23:09:15.169479 185607 leveldb.cpp:239] Created db iterator in 47525ns I0702 23:09:15.169519 185607 leveldb.cpp:245] Seeked to beginning of db in 12810ns I0702 23:09:15.169545 185607 leveldb.cpp:320] Iterated through 0 keys in the db in 10057ns I0702 23:09:15.169608 185607 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0702 23:09:15.191165 185621 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 21.074774ms I0702 23:09:15.191295 185621 replica.cpp:322] Persisted replica status to VOTING I0702 23:09:15.309170 185607 leveldb.cpp:217] Opened db in 117.059862ms I0702 23:09:15.344409 185607 leveldb.cpp:224] Compacted db in 35.19089ms I0702 23:09:15.344516 185607 leveldb.cpp:239] Created db iterator in 41266ns I0702 23:09:15.344554 185607 leveldb.cpp:245] Seeked to beginning of db in 11957ns I0702 23:09:15.344580 185607 leveldb.cpp:320] Iterated through 0 keys in the db in 9766ns I0702 23:09:15.344663 185607 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0702 23:09:15.392570 185616 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 47.446362ms I0702 23:09:15.392652 185616 replica.cpp:322] Persisted replica status to VOTING I0702 23:09:15.519009 185607 leveldb.cpp:217] Opened db in 125.466953ms I0702 23:09:15.627943 185607 leveldb.cpp:224] Compacted db in 108.887707ms I0702 23:09:15.628053 185607 leveldb.cpp:239] Created db iterator in 47205ns I0702 23:09:15.628124 185607 leveldb.cpp:245] Seeked to beginning of db in 43196ns I0702 23:09:15.628201 185607 leveldb.cpp:320] Iterated through 1 keys in the db in 55792ns I0702 23:09:15.628273 185607 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0702 23:09:15.762111 185607 leveldb.cpp:217] Opened db in 133.4219ms I0702 23:09:15.877980 185607 leveldb.cpp:224] Compacted db in 115.824393ms I0702 23:09:15.878091 185607 leveldb.cpp:239] Created db iterator in 46729ns I0702 23:09:15.878159 185607 leveldb.cpp:245] Seeked to beginning of db in 41786ns I0702 23:09:15.878234 185607 leveldb.cpp:320] Iterated through 1 keys in the db in 54522ns I0702 23:09:15.878306 185607 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0702 23:09:15.879281 185623 recover.cpp:437] Starting replica recovery I0702 23:09:15.879706 185624 recover.cpp:468] Replica is in VOTING status I0702 23:09:15.880082 185624 recover.cpp:447] Recover process terminated I0702 23:09:15.880721 185624 log.cpp:554] Attempting to start the writer I0702 23:09:15.882906 185618 replica.cpp:497] Replica received implicit promise request from __req_res__(976)@172.17.0.2:39115 with proposal 1 I0702 23:09:15.883057 185615 replica.cpp:497] Replica received implicit promise request from __req_res__(977)@172.17.0.2:39115 with proposal 1 I0702 23:09:15.937690 185618 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 54.731205ms I0702 23:09:15.937772 185618 replica.cpp:344] Persisted promised to 1 I0702 23:09:15.954440 185615 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 71.326606ms I0702 23:09:15.954524 185615 replica.cpp:344] Persisted promised to 1 I0702 23:09:15.955476 185623 coordinator.cpp:238] Coordinator attempting to fill missing positions I0702 23:09:15.957603 185619 replica.cpp:391] Replica received explicit promise request from __req_res__(978)@172.17.0.2:39115 for position 0 with proposal 2 I0702 23:09:15.957708 185627 replica.cpp:391] Replica received explicit promise request from __req_res__(979)@172.17.0.2:39115 for position 0 with proposal 2 I0702 23:09:16.004551 185619 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 46.860106ms I0702 23:09:16.004554 185627 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 46.784264ms I0702 23:09:16.004643 185619 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:16.004688 185627 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:16.006217 185623 replica.cpp:541] Replica received write request for position 0 from __req_res__(980)@172.17.0.2:39115 I0702 23:09:16.006351 185623 leveldb.cpp:510] Reading position from leveldb took 76101ns I0702 23:09:16.006345 185626 replica.cpp:541] Replica received write request for position 0 from __req_res__(981)@172.17.0.2:39115 I0702 23:09:16.006515 185626 leveldb.cpp:510] Reading position from leveldb took 76768ns I0702 23:09:16.054678 185626 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 48.104086ms I0702 23:09:16.054703 185623 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 48.283925ms I0702 23:09:16.054769 185626 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:16.054811 185623 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:16.055682 185617 replica.cpp:695] Replica received learned notice for position 0 from log-network(45)@172.17.0.2:39115 I0702 23:09:16.055702 185627 replica.cpp:695] Replica received learned notice for position 0 from log-network(45)@172.17.0.2:39115 I0702 23:09:16.104801 185617 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 49.064694ms I0702 23:09:16.104806 185627 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 49.026311ms I0702 23:09:16.104894 185617 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:16.104939 185627 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:16.105825 185615 log.cpp:570] Writer started with ending position 0 I0702 23:09:16.106668 185616 log.cpp:578] Attempting to append 11 bytes to the log I0702 23:09:16.106879 185620 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 I0702 23:09:16.108038 185625 replica.cpp:541] Replica received write request for position 1 from __req_res__(982)@172.17.0.2:39115 I0702 23:09:16.108167 185631 replica.cpp:541] Replica received write request for position 1 from __req_res__(983)@172.17.0.2:39115 I0702 23:09:16.154897 185625 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 46.793104ms I0702 23:09:16.154914 185631 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 46.675873ms I0702 23:09:16.154990 185625 replica.cpp:712] Persisted action APPEND at position 1 I0702 23:09:16.155031 185631 replica.cpp:712] Persisted action APPEND at position 1 I0702 23:09:16.155884 185610 replica.cpp:695] Replica received learned notice for position 1 from log-network(45)@172.17.0.2:39115 I0702 23:09:16.155906 185614 replica.cpp:695] Replica received learned notice for position 1 from log-network(45)@172.17.0.2:39115 I0702 23:09:16.205037 185610 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 49.112066ms I0702 23:09:16.205040 185614 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 49.084444ms I0702 23:09:16.205132 185610 replica.cpp:712] Persisted action APPEND at position 1 I0702 23:09:16.205175 185614 replica.cpp:712] Persisted action APPEND at position 1 [ OK ] LogTest.Position (1188 ms) [ RUN ] LogTest.Metrics I0702 23:09:16.331821 185607 leveldb.cpp:217] Opened db in 120.815038ms I0702 23:09:16.361049 185607 leveldb.cpp:224] Compacted db in 29.183397ms I0702 23:09:16.361176 185607 leveldb.cpp:239] Created db iterator in 53092ns I0702 23:09:16.361227 185607 leveldb.cpp:245] Seeked to beginning of db in 17346ns I0702 23:09:16.361266 185607 leveldb.cpp:320] Iterated through 0 keys in the db in 15667ns I0702 23:09:16.361351 185607 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0702 23:09:16.390103 185616 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 28.196862ms I0702 23:09:16.390185 185616 replica.cpp:322] Persisted replica status to VOTING I0702 23:09:16.508200 185607 leveldb.cpp:217] Opened db in 117.093881ms I0702 23:09:16.611354 185607 leveldb.cpp:224] Compacted db in 103.108094ms I0702 23:09:16.611467 185607 leveldb.cpp:239] Created db iterator in 48899ns I0702 23:09:16.611538 185607 leveldb.cpp:245] Seeked to beginning of db in 43739ns I0702 23:09:16.611616 185607 leveldb.cpp:320] Iterated through 1 keys in the db in 57649ns I0702 23:09:16.611687 185607 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0702 23:09:16.612587 185625 recover.cpp:437] Starting replica recovery I0702 23:09:16.613103 185625 recover.cpp:468] Replica is in VOTING status I0702 23:09:16.613411 185625 recover.cpp:447] Recover process terminated I0702 23:09:16.614017 185625 log.cpp:554] Attempting to start the writer I0702 23:09:16.616101 185620 replica.cpp:497] Replica received implicit promise request from __req_res__(984)@172.17.0.2:39115 with proposal 1 I0702 23:09:16.666815 185620 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 50.65946ms I0702 23:09:16.666899 185620 replica.cpp:344] Persisted promised to 1 I0702 23:09:16.667944 185613 coordinator.cpp:238] Coordinator attempting to fill missing positions I0702 23:09:16.670017 185626 replica.cpp:391] Replica received explicit promise request from __req_res__(985)@172.17.0.2:39115 for position 0 with proposal 2 I0702 23:09:16.708566 185626 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 38.481685ms I0702 23:09:16.708652 185626 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:16.710155 185617 replica.cpp:541] Replica received write request for position 0 from __req_res__(986)@172.17.0.2:39115 I0702 23:09:16.710304 185617 leveldb.cpp:510] Reading position from leveldb took 78498ns I0702 23:09:16.750363 185617 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 39.997717ms I0702 23:09:16.750449 185617 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:16.751315 185625 replica.cpp:695] Replica received learned notice for position 0 from log-network(46)@172.17.0.2:39115 I0702 23:09:16.792114 185625 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 40.739755ms I0702 23:09:16.792200 185625 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:16.793041 185623 log.cpp:570] Writer started with ending position 0 I0702 23:09:16.798516 185622 process.cpp:3671] Handling HTTP event for process 'metrics' with path: '/metrics/snapshot' [ OK ] LogTest.Metrics (600 ms) [ RUN ] LogTest.ReaderCatchup I0702 23:09:16.977115 185607 leveldb.cpp:217] Opened db in 166.286247ms I0702 23:09:17.011054 185607 leveldb.cpp:224] Compacted db in 33.880019ms I0702 23:09:17.011224 185607 leveldb.cpp:239] Created db iterator in 93694ns I0702 23:09:17.011287 185607 leveldb.cpp:245] Seeked to beginning of db in 21927ns I0702 23:09:17.011332 185607 leveldb.cpp:320] Iterated through 0 keys in the db in 16516ns I0702 23:09:17.011427 185607 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0702 23:09:17.035493 185619 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 23.343504ms I0702 23:09:17.035578 185619 replica.cpp:322] Persisted replica status to VOTING I0702 23:09:17.178484 185607 leveldb.cpp:217] Opened db in 142.027712ms I0702 23:09:17.211133 185607 leveldb.cpp:224] Compacted db in 32.60182ms I0702 23:09:17.211267 185607 leveldb.cpp:239] Created db iterator in 45169ns I0702 23:09:17.211308 185607 leveldb.cpp:245] Seeked to beginning of db in 12006ns I0702 23:09:17.211333 185607 leveldb.cpp:320] Iterated through 0 keys in the db in 9597ns I0702 23:09:17.211393 185607 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0702 23:09:17.236851 185616 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 24.9637ms I0702 23:09:17.236933 185616 replica.cpp:322] Persisted replica status to VOTING I0702 23:09:17.371567 185607 leveldb.cpp:217] Opened db in 133.749951ms I0702 23:09:17.402873 185607 leveldb.cpp:224] Compacted db in 31.249422ms I0702 23:09:17.403002 185607 leveldb.cpp:239] Created db iterator in 43271ns I0702 23:09:17.403028 185607 leveldb.cpp:245] Seeked to beginning of db in 8606ns I0702 23:09:17.403041 185607 leveldb.cpp:320] Iterated through 0 keys in the db in 6389ns I0702 23:09:17.403098 185607 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0702 23:09:17.438289 185628 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 34.655595ms I0702 23:09:17.438393 185628 replica.cpp:322] Persisted replica status to VOTING I0702 23:09:17.556710 185607 leveldb.cpp:217] Opened db in 117.43892ms I0702 23:09:17.661387 185607 leveldb.cpp:224] Compacted db in 104.63256ms I0702 23:09:17.661511 185607 leveldb.cpp:239] Created db iterator in 59955ns I0702 23:09:17.661582 185607 leveldb.cpp:245] Seeked to beginning of db in 44596ns I0702 23:09:17.661675 185607 leveldb.cpp:320] Iterated through 1 keys in the db in 72092ns I0702 23:09:17.661763 185607 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0702 23:09:17.774859 185607 leveldb.cpp:217] Opened db in 112.717031ms I0702 23:09:17.878103 185607 leveldb.cpp:224] Compacted db in 103.199655ms I0702 23:09:17.878214 185607 leveldb.cpp:239] Created db iterator in 46786ns I0702 23:09:17.878281 185607 leveldb.cpp:245] Seeked to beginning of db in 41815ns I0702 23:09:17.878356 185607 leveldb.cpp:320] Iterated through 1 keys in the db in 53392ns I0702 23:09:17.878427 185607 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0702 23:09:17.881474 185627 replica.cpp:497] Replica received implicit promise request from __req_res__(987)@172.17.0.2:39115 with proposal 1 I0702 23:09:17.881613 185628 replica.cpp:497] Replica received implicit promise request from __req_res__(988)@172.17.0.2:39115 with proposal 1 I0702 23:09:17.925273 185628 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 43.61272ms I0702 23:09:17.925274 185627 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 43.729158ms I0702 23:09:17.925361 185628 replica.cpp:344] Persisted promised to 1 I0702 23:09:17.925415 185627 replica.cpp:344] Persisted promised to 1 I0702 23:09:17.926515 185624 coordinator.cpp:238] Coordinator attempting to fill missing positions I0702 23:09:17.928660 185608 replica.cpp:391] Replica received explicit promise request from __req_res__(989)@172.17.0.2:39115 for position 0 with proposal 2 I0702 23:09:17.928902 185622 replica.cpp:391] Replica received explicit promise request from __req_res__(990)@172.17.0.2:39115 for position 0 with proposal 2 I0702 23:09:17.975410 185608 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 46.663076ms I0702 23:09:17.975436 185622 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 46.453328ms I0702 23:09:17.975502 185608 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:17.975543 185622 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:17.977198 185629 replica.cpp:541] Replica received write request for position 0 from __req_res__(991)@172.17.0.2:39115 I0702 23:09:17.977313 185610 replica.cpp:541] Replica received write request for position 0 from __req_res__(992)@172.17.0.2:39115 I0702 23:09:17.977355 185629 leveldb.cpp:510] Reading position from leveldb took 83892ns I0702 23:09:17.977444 185610 leveldb.cpp:510] Reading position from leveldb took 74388ns I0702 23:09:18.025490 185629 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 48.066106ms I0702 23:09:18.025494 185610 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 47.990994ms I0702 23:09:18.025581 185629 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:18.025627 185610 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:18.026525 185619 replica.cpp:695] Replica received learned notice for position 0 from log-network(47)@172.17.0.2:39115 I0702 23:09:18.026559 185608 replica.cpp:695] Replica received learned notice for position 0 from log-network(47)@172.17.0.2:39115 I0702 23:09:18.075589 185608 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 48.986236ms I0702 23:09:18.075629 185619 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 49.063515ms I0702 23:09:18.075677 185608 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:18.075712 185619 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:18.077024 185629 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 I0702 23:09:18.078220 185622 replica.cpp:541] Replica received write request for position 1 from __req_res__(993)@172.17.0.2:39115 I0702 23:09:18.078449 185617 replica.cpp:541] Replica received write request for position 1 from __req_res__(994)@172.17.0.2:39115 I0702 23:09:18.125710 185617 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.195535ms I0702 23:09:18.125748 185622 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.45975ms I0702 23:09:18.125799 185617 replica.cpp:712] Persisted action APPEND at position 1 I0702 23:09:18.125833 185622 replica.cpp:712] Persisted action APPEND at position 1 I0702 23:09:18.126757 185624 replica.cpp:695] Replica received learned notice for position 1 from log-network(47)@172.17.0.2:39115 I0702 23:09:18.126756 185631 replica.cpp:695] Replica received learned notice for position 1 from log-network(47)@172.17.0.2:39115 I0702 23:09:18.175866 185631 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.009045ms I0702 23:09:18.175866 185624 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.051898ms I0702 23:09:18.175983 185631 replica.cpp:712] Persisted action APPEND at position 1 I0702 23:09:18.176019 185624 replica.cpp:712] Persisted action APPEND at position 1 I0702 23:09:18.177184 185629 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 2 I0702 23:09:18.178272 185619 replica.cpp:541] Replica received write request for position 2 from __req_res__(995)@172.17.0.2:39115 I0702 23:09:18.178454 185617 replica.cpp:541] Replica received write request for position 2 from __req_res__(996)@172.17.0.2:39115 I0702 23:09:18.225946 185617 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.42789ms I0702 23:09:18.225980 185619 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.621502ms I0702 23:09:18.226034 185617 replica.cpp:712] Persisted action APPEND at position 2 I0702 23:09:18.226064 185619 replica.cpp:712] Persisted action APPEND at position 2 I0702 23:09:18.226938 185614 replica.cpp:695] Replica received learned notice for position 2 from log-network(47)@172.17.0.2:39115 I0702 23:09:18.227069 185626 replica.cpp:695] Replica received learned notice for position 2 from log-network(47)@172.17.0.2:39115 I0702 23:09:18.276089 185626 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 48.974567ms I0702 23:09:18.276093 185614 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.107964ms I0702 23:09:18.276182 185626 replica.cpp:712] Persisted action APPEND at position 2 I0702 23:09:18.276228 185614 replica.cpp:712] Persisted action APPEND at position 2 I0702 23:09:18.277264 185625 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3 I0702 23:09:18.278425 185619 replica.cpp:541] Replica received write request for position 3 from __req_res__(997)@172.17.0.2:39115 I0702 23:09:18.278578 185618 replica.cpp:541] Replica received write request for position 3 from __req_res__(998)@172.17.0.2:39115 I0702 23:09:18.326221 185618 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.57745ms I0702 23:09:18.326223 185619 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.72406ms I0702 23:09:18.326314 185618 replica.cpp:712] Persisted action APPEND at position 3 I0702 23:09:18.326361 185619 replica.cpp:712] Persisted action APPEND at position 3 I0702 23:09:18.327268 185615 replica.cpp:695] Replica received learned notice for position 3 from log-network(47)@172.17.0.2:39115 I0702 23:09:18.327308 185616 replica.cpp:695] Replica received learned notice for position 3 from log-network(47)@172.17.0.2:39115 I0702 23:09:18.376335 185616 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 48.972363ms I0702 23:09:18.376339 185615 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.022474ms I0702 23:09:18.376439 185616 replica.cpp:712] Persisted action APPEND at position 3 I0702 23:09:18.376479 185615 replica.cpp:712] Persisted action APPEND at position 3 I0702 23:09:18.377657 185622 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 4 I0702 23:09:18.378844 185631 replica.cpp:541] Replica received write request for position 4 from __req_res__(999)@172.17.0.2:39115 I0702 23:09:18.379062 185621 replica.cpp:541] Replica received write request for position 4 from __req_res__(1000)@172.17.0.2:39115 I0702 23:09:18.426448 185621 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.306152ms I0702 23:09:18.426450 185631 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.544277ms I0702 23:09:18.426543 185621 replica.cpp:712] Persisted action APPEND at position 4 I0702 23:09:18.426589 185631 replica.cpp:712] Persisted action APPEND at position 4 I0702 23:09:18.427492 185629 replica.cpp:695] Replica received learned notice for position 4 from log-network(47)@172.17.0.2:39115 I0702 23:09:18.427518 185608 replica.cpp:695] Replica received learned notice for position 4 from log-network(47)@172.17.0.2:39115 I0702 23:09:18.476560 185629 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.012109ms I0702 23:09:18.476562 185608 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 48.976697ms I0702 23:09:18.476665 185629 replica.cpp:712] Persisted action APPEND at position 4 I0702 23:09:18.476702 185608 replica.cpp:712] Persisted action APPEND at position 4 I0702 23:09:18.477934 185622 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 5 I0702 23:09:18.479053 185621 replica.cpp:541] Replica received write request for position 5 from __req_res__(1001)@172.17.0.2:39115 I0702 23:09:18.479180 185611 replica.cpp:541] Replica received write request for position 5 from __req_res__(1002)@172.17.0.2:39115 I0702 23:09:18.526672 185611 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.401453ms I0702 23:09:18.526682 185621 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.552927ms I0702 23:09:18.526764 185611 replica.cpp:712] Persisted action APPEND at position 5 I0702 23:09:18.526810 185621 replica.cpp:712] Persisted action APPEND at position 5 I0702 23:09:18.527756 185615 replica.cpp:695] Replica received learned notice for position 5 from log-network(47)@172.17.0.2:39115 I0702 23:09:18.527765 185612 replica.cpp:695] Replica received learned notice for position 5 from log-network(47)@172.17.0.2:39115 I0702 23:09:18.576797 185612 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 48.955451ms I0702 23:09:18.576800 185615 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.000834ms I0702 23:09:18.576892 185612 replica.cpp:712] Persisted action APPEND at position 5 I0702 23:09:18.576936 185615 replica.cpp:712] Persisted action APPEND at position 5 I0702 23:09:18.578128 185622 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 6 I0702 23:09:18.579284 185616 replica.cpp:541] Replica received write request for position 6 from __req_res__(1003)@172.17.0.2:39115 I0702 23:09:18.579442 185608 replica.cpp:541] Replica received write request for position 6 from __req_res__(1004)@172.17.0.2:39115 I0702 23:09:18.626916 185616 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.552317ms I0702 23:09:18.626916 185608 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.411533ms I0702 23:09:18.627034 185616 replica.cpp:712] Persisted action APPEND at position 6 I0702 23:09:18.627069 185608 replica.cpp:712] Persisted action APPEND at position 6 I0702 23:09:18.627987 185620 replica.cpp:695] Replica received learned notice for position 6 from log-network(47)@172.17.0.2:39115 I0702 23:09:18.627986 185619 replica.cpp:695] Replica received learned notice for position 6 from log-network(47)@172.17.0.2:39115 I0702 23:09:18.677038 185620 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 48.98929ms I0702 23:09:18.677038 185619 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 48.94685ms I0702 23:09:18.677156 185620 replica.cpp:712] Persisted action APPEND at position 6 I0702 23:09:18.677196 185619 replica.cpp:712] Persisted action APPEND at position 6 I0702 23:09:18.678366 185609 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 7 I0702 23:09:18.679447 185616 replica.cpp:541] Replica received write request for position 7 from __req_res__(1005)@172.17.0.2:39115 I0702 23:09:18.679605 185608 replica.cpp:541] Replica received write request for position 7 from __req_res__(1006)@172.17.0.2:39115 I0702 23:09:18.727174 185616 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.675966ms I0702 23:09:18.727174 185608 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.529057ms I0702 23:09:18.727316 185616 replica.cpp:712] Persisted action APPEND at position 7 I0702 23:09:18.727355 185608 replica.cpp:712] Persisted action APPEND at position 7 I0702 23:09:18.728302 185623 replica.cpp:695] Replica received learned notice for position 7 from log-network(47)@172.17.0.2:39115 I0702 23:09:18.728330 185620 replica.cpp:695] Replica received learned notice for position 7 from log-network(47)@172.17.0.2:39115 I0702 23:09:18.777284 185623 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 48.932174ms I0702 23:09:18.777289 185620 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 48.897645ms I0702 23:09:18.777376 185623 replica.cpp:712] Persisted action APPEND at position 7 I0702 23:09:18.777422 185620 replica.cpp:712] Persisted action APPEND at position 7 I0702 23:09:18.778621 185609 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 8 I0702 23:09:18.779767 185615 replica.cpp:541] Replica received write request for position 8 from __req_res__(1007)@172.17.0.2:39115 I0702 23:09:18.779934 185612 replica.cpp:541] Replica received write request for position 8 from __req_res__(1008)@172.17.0.2:39115 I0702 23:09:18.827387 185612 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.388501ms I0702 23:09:18.827390 185615 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.558401ms I0702 23:09:18.827491 185612 replica.cpp:712] Persisted action APPEND at position 8 I0702 23:09:18.827530 185615 replica.cpp:712] Persisted action APPEND at position 8 I0702 23:09:18.828442 185624 replica.cpp:695] Replica received learned notice for position 8 from log-network(47)@172.17.0.2:39115 I0702 23:09:18.828442 185613 replica.cpp:695] Replica received learned notice for position 8 from log-network(47)@172.17.0.2:39115 I0702 23:09:18.877496 185613 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 48.941124ms I0702 23:09:18.877497 185624 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.00067ms I0702 23:09:18.877588 185613 replica.cpp:712] Persisted action APPEND at position 8 I0702 23:09:18.877631 185624 replica.cpp:712] Persisted action APPEND at position 8 I0702 23:09:18.878834 185625 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 9 I0702 23:09:18.879959 185623 replica.cpp:541] Replica received write request for position 9 from __req_res__(1009)@172.17.0.2:39115 I0702 23:09:18.880116 185622 replica.cpp:541] Replica received write request for position 9 from __req_res__(1010)@172.17.0.2:39115 I0702 23:09:18.927628 185623 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.603736ms I0702 23:09:18.927628 185622 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.449388ms I0702 23:09:18.927722 185623 replica.cpp:712] Persisted action APPEND at position 9 I0702 23:09:18.927767 185622 replica.cpp:712] Persisted action APPEND at position 9 I0702 23:09:18.928607 185627 replica.cpp:695] Replica received learned notice for position 9 from log-network(47)@172.17.0.2:39115 I0702 23:09:18.928633 185626 replica.cpp:695] Replica received learned notice for position 9 from log-network(47)@172.17.0.2:39115 I0702 23:09:18.977739 185626 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.037325ms I0702 23:09:18.977741 185627 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.082194ms I0702 23:09:18.977834 185626 replica.cpp:712] Persisted action APPEND at position 9 I0702 23:09:18.977900 185627 replica.cpp:712] Persisted action APPEND at position 9 I0702 23:09:18.979035 185625 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 10 I0702 23:09:18.980160 185623 replica.cpp:541] Replica received write request for position 10 from __req_res__(1011)@172.17.0.2:39115 I0702 23:09:18.980263 185620 replica.cpp:541] Replica received write request for position 10 from __req_res__(1012)@172.17.0.2:39115 I0702 23:09:19.027850 185623 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 47.623773ms I0702 23:09:19.027858 185620 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 47.530549ms I0702 23:09:19.027943 185623 replica.cpp:712] Persisted action APPEND at position 10 I0702 23:09:19.027988 185620 replica.cpp:712] Persisted action APPEND at position 10 I0702 23:09:19.028791 185626 replica.cpp:695] Replica received learned notice for position 10 from log-network(47)@172.17.0.2:39115 I0702 23:09:19.028808 185629 replica.cpp:695] Replica received learned notice for position 10 from log-network(47)@172.17.0.2:39115 I0702 23:09:19.077975 185626 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 49.134334ms I0702 23:09:19.077984 185629 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 49.090447ms I0702 23:09:19.078066 185626 replica.cpp:712] Persisted action APPEND at position 10 I0702 23:09:19.078109 185629 replica.cpp:712] Persisted action APPEND at position 10 I0702 23:09:19.196116 185607 leveldb.cpp:217] Opened db in 116.863103ms I0702 23:09:19.307662 185607 leveldb.cpp:224] Compacted db in 111.4984ms I0702 23:09:19.307785 185607 leveldb.cpp:239] Created db iterator in 56416ns I0702 23:09:19.307857 185607 leveldb.cpp:245] Seeked to beginning of db in 44462ns I0702 23:09:19.307937 185607 leveldb.cpp:320] Iterated through 1 keys in the db in 60152ns I0702 23:09:19.308015 185607 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0702 23:09:19.309082 185623 recover.cpp:437] Starting replica recovery I0702 23:09:19.309602 185623 recover.cpp:468] Replica is in VOTING status I0702 23:09:19.309916 185623 recover.cpp:447] Recover process terminated I0702 23:09:19.310575 185620 catchup.cpp:342] Starting missing positions recovery I0702 23:09:19.311055 185620 catchup.cpp:368] Replica is in VOTING status I0702 23:09:19.312803 185616 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(1013)@172.17.0.2:39115 I0702 23:09:19.313021 185615 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(1014)@172.17.0.2:39115 I0702 23:09:19.313208 185622 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(1015)@172.17.0.2:39115 I0702 23:09:19.314285 185610 recover.cpp:197] Received a recover response from a replica in VOTING status I0702 23:09:19.314883 185610 recover.cpp:197] Received a recover response from a replica in VOTING status I0702 23:09:19.316325 185617 catchup.cpp:423] Starting catch-up from position 0 to 9 I0702 23:09:19.318449 185616 replica.cpp:391] Replica received explicit promise request from __req_res__(1016)@172.17.0.2:39115 for position 0 with proposal 0 I0702 23:09:19.318598 185621 replica.cpp:391] Replica received explicit promise request from __req_res__(1017)@172.17.0.2:39115 for position 0 with proposal 0 I0702 23:09:19.318619 185616 leveldb.cpp:510] Reading position from leveldb took 101788ns I0702 23:09:19.318766 185621 leveldb.cpp:510] Reading position from leveldb took 101594ns I0702 23:09:19.318907 185630 replica.cpp:391] Replica received explicit promise request from __req_res__(1018)@172.17.0.2:39115 for position 0 with proposal 0 I0702 23:09:19.458165 185614 replica.cpp:391] Replica received explicit promise request from __req_res__(1019)@172.17.0.2:39115 for position 0 with proposal 3 I0702 23:09:19.458307 185614 leveldb.cpp:510] Reading position from leveldb took 82095ns I0702 23:09:19.458343 185622 replica.cpp:391] Replica received explicit promise request from __req_res__(1020)@172.17.0.2:39115 for position 0 with proposal 3 I0702 23:09:19.458518 185622 leveldb.cpp:510] Reading position from leveldb took 106161ns I0702 23:09:19.458560 185631 replica.cpp:391] Replica received explicit promise request from __req_res__(1021)@172.17.0.2:39115 for position 0 with proposal 3 I0702 23:09:19.513038 185622 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 54.450876ms I0702 23:09:19.513038 185614 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 54.681867ms I0702 23:09:19.513134 185622 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:19.513180 185614 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:19.513876 185616 replica.cpp:695] Replica received learned notice for position 0 from log-network(48)@172.17.0.2:39115 I0702 23:09:19.513933 185608 replica.cpp:695] Replica received learned notice for position 0 from log-network(48)@172.17.0.2:39115 I0702 23:09:19.576529 185631 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 117.905927ms I0702 23:09:19.576614 185631 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:19.576802 185631 replica.cpp:695] Replica received learned notice for position 0 from log-network(48)@172.17.0.2:39115 I0702 23:09:19.606583 185616 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 92.645325ms I0702 23:09:19.606590 185608 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 92.59688ms I0702 23:09:19.606675 185616 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:19.606720 185608 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:19.630021 185631 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 53.186729ms I0702 23:09:19.630110 185631 replica.cpp:712] Persisted action NOP at position 0 I0702 23:09:19.632086 185610 replica.cpp:391] Replica received explicit promise request from __req_res__(1022)@172.17.0.2:39115 for position 1 with proposal 3 I0702 23:09:19.632236 185610 leveldb.cpp:510] Reading position from leveldb took 92961ns I0702 23:09:19.632241 185627 replica.cpp:391] Replica received explicit promise request from __req_res__(1023)@172.17.0.2:39115 for position 1 with proposal 3 I0702 23:09:19.632411 185627 leveldb.cpp:510] Reading position from leveldb took 95718ns I0702 23:09:19.632409 185617 replica.cpp:391] Replica received explicit promise request from __req_res__(1024)@172.17.0.2:39115 for position 1 with proposal 3 I0702 23:09:19.680119 185610 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 47.813791ms I0702 23:09:19.680153 185627 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 47.663731ms I0702 23:09:19.680148 185617 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 47.643245ms I0702 23:09:19.680243 185627 replica.cpp:712] Persisted action APPEND at position 1 I0702 23:09:19.680219 185610 replica.cpp:712] Persisted action APPEND at position 1 I0702 23:09:19.680289 185617 replica.cpp:712] Persisted action NOP at position 1 I0702 23:09:19.681123 185609 replica.cpp:695] Replica received learned notice for position 1 from log-network(48)@172.17.0.2:39115 I0702 23:09:19.681197 185608 replica.cpp:695] Replica received learned notice for position 1 from log-network(48)@172.17.0.2:39115 I0702 23:09:19.681243 185628 replica.cpp:695] Replica received learned notice for position 1 from log-network(48)@172.17.0.2:39115 I0702 23:09:19.730592 185608 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.333199ms I0702 23:09:19.730594 185609 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.4249ms I0702 23:09:19.730685 185608 replica.cpp:712] Persisted action APPEND at position 1 I0702 23:09:19.730595 185628 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.300857ms I0702 23:09:19.730736 185609 replica.cpp:712] Persisted action APPEND at position 1 I0702 23:09:19.730798 185628 replica.cpp:712] Persisted action APPEND at position 1 I0702 23:09:19.732841 185625 replica.cpp:391] Replica received explicit promise request from __req_res__(1025)@172.17.0.2:39115 for position 2 with proposal 3 I0702 23:09:19.733018 185625 leveldb.cpp:510] Reading position from leveldb took 118347ns I0702 23:09:19.733018 185626 replica.cpp:391] Replica received explicit promise request from __req_res__(1026)@172.17.0.2:39115 for position 2 with proposal 3 I0702 23:09:19.733131 185627 replica.cpp:391] Replica received explicit promise request from __req_res__(1027)@172.17.0.2:39115 for position 2 with proposal 3 I0702 23:09:19.733227 185626 leveldb.cpp:510] Reading position from leveldb took 107201ns I0702 23:09:19.780720 185625 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 47.590969ms I0702 23:09:19.780741 185627 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 47.5553ms I0702 23:09:19.780822 185625 replica.cpp:712] Persisted action APPEND at position 2 I0702 23:09:19.780747 185626 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 47.420806ms I0702 23:09:19.780867 185627 replica.cpp:712] Persisted action NOP at position 2 I0702 23:09:19.780915 185626 replica.cpp:712] Persisted action APPEND at position 2 I0702 23:09:19.781769 185609 replica.cpp:695] Replica received learned notice for position 2 from log-network(48)@172.17.0.2:39115 I0702 23:09:19.781898 185629 replica.cpp:695] Replica received learned notice for position 2 from log-network(48)@172.17.0.2:39115 I0702 23:09:19.781926 185618 replica.cpp:695] Replica received learned notice for position 2 from log-network(48)@172.17.0.2:39115 I0702 23:09:19.830884 185629 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 48.942998ms I0702 23:09:19.830894 185609 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.070352ms I0702 23:09:19.830976 185629 replica.cpp:712] Persisted action APPEND at position 2 I0702 23:09:19.830894 185618 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 48.928205ms I0702 23:09:19.831032 185609 replica.cpp:712] Persisted action APPEND at position 2 I0702 23:09:19.831074 185618 replica.cpp:712] Persisted action APPEND at position 2 I0702 23:09:19.833055 185614 replica.cpp:391] Replica received explicit promise request from __req_res__(1028)@172.17.0.2:39115 for position 3 with proposal 3 I0702 23:09:19.833231 185608 replica.cpp:391] Replica received explicit promise request from __req_res__(1029)@172.17.0.2:39115 for position 3 with proposal 3 I0702 23:09:19.833245 185614 leveldb.cpp:510] Reading position from leveldb took 113408ns I0702 23:09:19.833386 185608 leveldb.cpp:510] Reading position from leveldb took 92314ns I0702 23:09:19.833431 185624 replica.cpp:391] Replica received explicit promise request from __req_res__(1030)@172.17.0.2:39115 for position 3 with proposal 3 I0702 23:09:19.881014 185624 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 47.517725ms I0702 23:09:19.881019 185608 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 47.569928ms I0702 23:09:19.881117 185624 replica.cpp:712] Persisted action NOP at position 3 I0702 23:09:19.881019 185614 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 47.637606ms I0702 23:09:19.881163 185608 replica.cpp:712] Persisted action APPEND at position 3 I0702 23:09:19.881244 185614 replica.cpp:712] Persisted action APPEND at position 3 I0702 23:09:19.882046 185611 replica.cpp:695] Replica received learned notice for position 3 from log-network(48)@172.17.0.2:39115 I0702 23:09:19.882082 185627 replica.cpp:695] Replica received learned notice for position 3 from log-network(48)@172.17.0.2:39115 I0702 23:09:19.882122 185612 replica.cpp:695] Replica received learned notice for position 3 from log-network(48)@172.17.0.2:39115 I0702 23:09:19.931151 185611 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.058087ms I0702 23:09:19.931205 185612 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.010158ms I0702 23:09:19.931260 185611 replica.cpp:712] Persisted action APPEND at position 3 I0702 23:09:19.931210 185627 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.08001ms I0702 23:09:19.931298 185612 replica.cpp:712] Persisted action APPEND at position 3 I0702 23:09:19.931365 185627 replica.cpp:712] Persisted action APPEND at position 3 I0702 23:09:19.933223 185619 replica.cpp:391] Replica received explicit promise request from __req_res__(1031)@172.17.0.2:39115 for position 4 with proposal 3 I0702 23:09:19.933348 185631 replica.cpp:391] Replica received explicit promise request from __req_res__(1032)@172.17.0.2:39115 for position 4 with proposal 3 I0702 23:09:19.933403 185619 leveldb.cpp:510] Reading position from leveldb took 123174ns I0702 23:09:19.933498 185631 leveldb.cpp:510] Reading position from leveldb took 89588ns I0702 23:09:19.933517 185615 replica.cpp:391] Replica received explicit promise request from __req_res__(1033)@172.17.0.2:39115 for position 4 with proposal 3 I0702 23:09:19.981352 185631 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 47.78646ms I0702 23:09:19.981371 185619 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 47.871051ms I0702 23:09:19.981446 185631 replica.cpp:712] Persisted action APPEND at position 4 I0702 23:09:19.981372 185615 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 47.801879ms I0702 23:09:19.981493 185619 replica.cpp:712] Persisted action APPEND at position 4 I0702 23:09:19.981545 185615 replica.cpp:712] Persisted action NOP at position 4 I0702 23:09:19.982362 185617 replica.cpp:695] Replica received learned notice for position 4 from log-network(48)@172.17.0.2:39115 I0702 23:09:19.982367 185630 replica.cpp:695] Replica received learned notice for position 4 from log-network(48)@172.17.0.2:39115 I0702 23:09:19.982371 185610 replica.cpp:695] Replica received learned notice for position 4 from log-network(48)@172.17.0.2:39115 I0702 23:09:20.031481 185610 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 48.955826ms I0702 23:09:20.031491 185630 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.026365ms I0702 23:09:20.031574 185610 replica.cpp:712] Persisted action APPEND at position 4 I0702 23:09:20.031494 185617 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.071034ms I0702 23:09:20.031620 185630 replica.cpp:712] Persisted action APPEND at position 4 I0702 23:09:20.031683 185617 replica.cpp:712] Persisted action APPEND at position 4 I0702 23:09:20.033496 185627 replica.cpp:391] Replica received explicit promise request from __req_res__(1034)@172.17.0.2:39115 for position 5 with proposal 3 I0702 23:09:20.033643 185627 leveldb.cpp:510] Reading position from leveldb took 89328ns I0702 23:09:20.033634 185612 replica.cpp:391] Replica received explicit promise request from __req_res__(1035)@172.17.0.2:39115 for position 5 with proposal 3 I0702 23:09:20.033798 185619 replica.cpp:391] Replica received explicit promise request from __req_res__(1036)@172.17.0.2:39115 for position 5 with proposal 3 I0702 23:09:20.033838 185612 leveldb.cpp:510] Reading position from leveldb took 112381ns I0702 23:09:20.081617 185619 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 47.764972ms I0702 23:09:20.081619 185612 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 47.698761ms I0702 23:09:20.081707 185619 replica.cpp:712] Persisted action NOP at position 5 I0702 23:09:20.081633 185627 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 47.906133ms I0702 23:09:20.081763 185612 replica.cpp:712] Persisted action APPEND at position 5 I0702 23:09:20.081799 185627 replica.cpp:712] Persisted action APPEND at position 5 I0702 23:09:20.082571 185625 replica.cpp:695] Replica received learned notice for position 5 from log-network(48)@172.17.0.2:39115 I0702 23:09:20.082716 185611 replica.cpp:695] Replica received learned notice for position 5 from log-network(48)@172.17.0.2:39115 I0702 23:09:20.082726 185615 replica.cpp:695] Replica received learned notice for position 5 from log-network(48)@172.17.0.2:39115 I0702 23:09:20.131711 185611 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 48.942323ms I0702 23:09:20.131748 185615 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 48.925833ms I0702 23:09:20.131723 185625 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.101216ms I0702 23:09:20.131801 185611 replica.cpp:712] Persisted action APPEND at position 5 I0702 23:09:20.131896 185625 replica.cpp:712] Persisted action APPEND at position 5 I0702 23:09:20.131861 185615 replica.cpp:712] Persisted action APPEND at position 5 I0702 23:09:20.133713 185610 replica.cpp:391] Replica received explicit promise request from __req_res__(1037)@172.17.0.2:39115 for position 6 with proposal 3 I0702 23:09:20.133860 185610 leveldb.cpp:510] Reading position from leveldb took 90372ns I0702 23:09:20.133863 185630 replica.cpp:391] Replica received explicit promise request from __req_res__(1038)@172.17.0.2:39115 for position 6 with proposal 3 I0702 23:09:20.134035 185626 replica.cpp:391] Replica received explicit promise request from __req_res__(1039)@172.17.0.2:39115 for position 6 with proposal 3 I0702 23:09:20.134081 185630 leveldb.cpp:510] Reading position from leveldb took 110018ns I0702 23:09:20.293545 185626 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 159.433782ms I0702 23:09:20.293546 185630 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 159.374124ms I0702 23:09:20.293558 185610 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 159.620255ms I0702 23:09:20.293689 185630 replica.cpp:712] Persisted action APPEND at position 6 I0702 23:09:20.293635 185626 replica.cpp:712] Persisted action NOP at position 6 I0702 23:09:20.293735 185610 replica.cpp:712] Persisted action APPEND at position 6 I0702 23:09:20.294520 185610 replica.cpp:695] Replica received learned notice for position 6 from log-network(48)@172.17.0.2:39115 I0702 23:09:20.294560 185611 replica.cpp:695] Replica received learned notice for position 6 from log-network(48)@172.17.0.2:39115 I0702 23:09:20.294603 185613 replica.cpp:695] Replica received learned notice for position 6 from log-network(48)@172.17.0.2:39115 I0702 23:09:20.331977 185610 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 37.401652ms I0702 23:09:20.331984 185611 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 37.365566ms I0702 23:09:20.331984 185613 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 37.327888ms I0702 23:09:20.332068 185610 replica.cpp:712] Persisted action APPEND at position 6 I0702 23:09:20.332166 185613 replica.cpp:712] Persisted action APPEND at position 6 I0702 23:09:20.332126 185611 replica.cpp:712] Persisted action APPEND at position 6 I0702 23:09:20.334103 185628 replica.cpp:391] Replica received explicit promise request from __req_res__(1040)@172.17.0.2:39115 for position 7 with proposal 3 I0702 23:09:20.334251 185620 replica.cpp:391] Replica received explicit promise request from __req_res__(1041)@172.17.0.2:39115 for position 7 with proposal 3 I0702 23:09:20.334272 185628 leveldb.cpp:510] Reading position from leveldb took 112984ns I0702 23:09:20.334419 185620 leveldb.cpp:510] Reading position from leveldb took 112134ns I0702 23:09:20.334417 185615 replica.cpp:391] Replica received explicit promise request from __req_res__(1042)@172.17.0.2:39115 for position 7 with proposal 3 I0702 23:09:20.382139 185628 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 47.7276ms I0702 23:09:20.382169 185615 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 47.651309ms I0702 23:09:20.382225 185628 replica.cpp:712] Persisted action APPEND at position 7 I0702 23:09:20.382169 185620 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 47.643742ms I0702 23:09:20.382278 185615 replica.cpp:712] Persisted action NOP at position 7 I0702 23:09:20.382319 185620 replica.cpp:712] Persisted action APPEND at position 7 I0702 23:09:20.383119 185611 replica.cpp:695] Replica received learned notice for position 7 from log-network(48)@172.17.0.2:39115 I0702 23:09:20.383165 185621 replica.cpp:695] Replica received learned notice for position 7 from log-network(48)@172.17.0.2:39115 I0702 23:09:20.383119 185619 replica.cpp:695] Replica received learned notice for position 7 from log-network(48)@172.17.0.2:39115 I0702 23:09:20.432305 185621 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.048625ms I0702 23:09:20.432329 185619 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.034869ms I0702 23:09:20.432394 185621 replica.cpp:712] Persisted action APPEND at position 7 I0702 23:09:20.432329 185611 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.119774ms I0702 23:09:20.432443 185619 replica.cpp:712] Persisted action APPEND at position 7 I0702 23:09:20.432482 185611 replica.cpp:712] Persisted action APPEND at position 7 I0702 23:09:20.434161 185613 replica.cpp:391] Replica received explicit promise request from __req_res__(1043)@172.17.0.2:39115 for position 8 with proposal 3 I0702 23:09:20.434298 185613 leveldb.cpp:510] Reading position from leveldb took 87245ns I0702 23:09:20.434376 185615 replica.cpp:391] Replica received explicit promise request from __req_res__(1044)@172.17.0.2:39115 for position 8 with proposal 3 I0702 23:09:20.434525 185615 leveldb.cpp:510] Reading position from leveldb took 88625ns I0702 23:09:20.434520 185608 replica.cpp:391] Replica received explicit promise request from __req_res__(1045)@172.17.0.2:39115 for position 8 with proposal 3 I0702 23:09:20.474114 185615 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 39.521764ms I0702 23:09:20.474114 185608 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 39.501055ms I0702 23:09:20.474210 185615 replica.cpp:712] Persisted action APPEND at position 8 I0702 23:09:20.474133 185613 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 39.774319ms I0702 23:09:20.474253 185608 replica.cpp:712] Persisted action NOP at position 8 I0702 23:09:20.474298 185613 replica.cpp:712] Persisted action APPEND at position 8 I0702 23:09:20.475003 185624 replica.cpp:695] Replica received learned notice for position 8 from log-network(48)@172.17.0.2:39115 I0702 23:09:20.475064 185618 replica.cpp:695] Replica received learned notice for position 8 from log-network(48)@172.17.0.2:39115 I0702 23:09:20.475028 185623 replica.cpp:695] Replica received learned notice for position 8 from log-network(48)@172.17.0.2:39115 I0702 23:09:20.515877 185623 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.724586ms I0702 23:09:20.515914 185624 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.84746ms I0702 23:09:20.515914 185618 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.807195ms I0702 23:09:20.516029 185624 replica.cpp:712] Persisted action APPEND at position 8 I0702 23:09:20.516073 185618 replica.cpp:712] Persisted action APPEND at position 8 I0702 23:09:20.515964 185623 replica.cpp:712] Persisted action APPEND at position 8 I0702 23:09:20.517916 185631 replica.cpp:391] Replica received explicit promise request from __req_res__(1046)@172.17.0.2:39115 for position 9 with proposal 3 I0702 23:09:20.518064 185631 leveldb.cpp:510] Reading position from leveldb took 88881ns I0702 23:09:20.518074 185630 replica.cpp:391] Replica received explicit promise request from __req_res__(1047)@172.17.0.2:39115 for position 9 with proposal 3 I0702 23:09:20.518219 185630 leveldb.cpp:510] Reading position from leveldb took 89028ns I0702 23:09:20.518280 185609 replica.cpp:391] Replica received explicit promise request from __req_res__(1048)@172.17.0.2:39115 for position 9 with proposal 3 I0702 23:09:20.557691 185609 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 39.336873ms I0702 23:09:20.557723 185630 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 39.43749ms I0702 23:09:20.557776 185609 replica.cpp:712] Persisted action NOP at position 9 I0702 23:09:20.557725 185631 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 39.597714ms I0702 23:09:20.557813 185630 replica.cpp:712] Persisted action APPEND at position 9 I0702 23:09:20.557883 185631 replica.cpp:712] Persisted action APPEND at position 9 I0702 23:09:20.558632 185628 replica.cpp:695] Replica received learned notice for position 9 from log-network(48)@172.17.0.2:39115 I0702 23:09:20.558665 185627 replica.cpp:695] Replica received learned notice for position 9 from log-network(48)@172.17.0.2:39115 I0702 23:09:20.558732 185608 replica.cpp:695] Replica received learned notice for position 9 from log-network(48)@172.17.0.2:39115 I0702 23:09:20.616176 185628 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 57.507174ms I0702 23:09:20.616206 185627 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 57.479475ms I0702 23:09:20.616269 185628 replica.cpp:712] Persisted action APPEND at position 9 I0702 23:09:20.616197 185608 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 57.429389ms I0702 23:09:20.616318 185627 replica.cpp:712] Persisted action APPEND at position 9 I0702 23:09:20.616370 185608 replica.cpp:712] Persisted action APPEND at position 9 I0702 23:09:20.617266 185610 catchup.cpp:357] Recover process terminated I0702 23:09:20.619994 185615 leveldb.cpp:510] Reading position from leveldb took 94934ns I0702 23:09:20.620165 185615 leveldb.cpp:510] Reading position from leveldb took 77831ns I0702 23:09:20.620309 185615 leveldb.cpp:510] Reading position from leveldb took 69768ns I0702 23:09:20.620452 185615 leveldb.cpp:510] Reading position from leveldb took 70245ns I0702 23:09:20.620592 185615 leveldb.cpp:510] Reading position from leveldb took 69885ns I0702 23:09:20.620730 185615 leveldb.cpp:510] Reading position from leveldb took 68068ns I0702 23:09:20.620869 185615 leveldb.cpp:510] Reading position from leveldb took 69512ns I0702 23:09:20.621009 185615 leveldb.cpp:510] Reading position from leveldb took 69279ns I0702 23:09:20.621148 185615 leveldb.cpp:510] Reading position from leveldb took 68589ns I0702 23:09:20.621292 185615 leveldb.cpp:510] Reading position from leveldb took 69651ns [ OK ] LogTest.ReaderCatchup (3817 ms) [----------] 4 tests from LogTest (6914 ms total) [----------] 2 tests from LogZooKeeperTest I0702 23:09:20.628325 185607 zookeeper.cpp:82] Using Java classpath: -Djava.class.path=/tmp/SRC/build/mesos-1.12.0/_build/sub/3rdparty/zookeeper-3.4.8/zookeeper-3.4.8.jar:/tmp/SRC/build/mesos-1.12.0/_build/sub/3rdparty/zookeeper-3.4.8/lib/log4j-1.2.16.jar:/tmp/SRC/build/mesos-1.12.0/_build/sub/3rdparty/zookeeper-3.4.8/lib/jline-0.9.94.jar:/tmp/SRC/build/mesos-1.12.0/_build/sub/3rdparty/zookeeper-3.4.8/lib/slf4j-log4j12-1.6.1.jar:/tmp/SRC/build/mesos-1.12.0/_build/sub/3rdparty/zookeeper-3.4.8/lib/netty-3.7.0.Final.jar:/tmp/SRC/build/mesos-1.12.0/_build/sub/3rdparty/zookeeper-3.4.8/lib/slf4j-api-1.6.1.jar [ RUN ] LogZooKeeperTest.WriteRead I0702 23:09:20.724597 185607 jvm.cpp:590] Looking up method <init>(Ljava/lang/String;)V I0702 23:09:20.724887 185607 jvm.cpp:590] Looking up method deleteOnExit()V I0702 23:09:20.725827 185607 jvm.cpp:590] Looking up method <init>(Ljava/io/File;Ljava/io/File;)V log4j:WARN No appenders could be found for logger (org.apache.zookeeper.server.persistence.FileTxnSnapLog). log4j:WARN Please initialize the log4j system properly. log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info. I0702 23:09:20.870596 185607 jvm.cpp:590] Looking up method <init>()V I0702 23:09:20.872246 185607 jvm.cpp:590] Looking up method <init>(Lorg/apache/zookeeper/server/persistence/FileTxnSnapLog;Lorg/apache/zookeeper/server/ZooKeeperServer$DataTreeBuilder;)V *** Aborted at 1719961760 (unix time) try "date -d @1719961760" if you are using GNU date *** PC: @ 0x7fbd17914ccd OopStorage::Block::release_entries() *** SIGSEGV (@0x238) received by PID 185607 (TID 0x7fbd92242b40) from PID 568; stack trace: *** @ 0x7fbd17923929 os::Linux::chained_handler() @ 0x7fbd1792963b JVM_handle_linux_signal @ 0x7fbd1791c1dc signalHandler() @ 0x7fbd93895420 (unknown) @ 0x7fbd17914ccd OopStorage::Block::release_entries() @ 0x7fbd17914f26 OopStorage::release() @ 0x7fbd17617b21 jni_DeleteGlobalRef @ 0x7fbda30496c2 JNIEnv_::DeleteGlobalRef() @ 0x7fbda304780a Jvm::deleteGlobalRef() @ 0x55d12f47a6f0 Jvm::Object::~Object() @ 0x55d12f47f516 org::apache::zookeeper::server::ZooKeeperServer::DataTreeBuilder::~DataTreeBuilder() @ 0x55d12f481e1a org::apache::zookeeper::server::ZooKeeperServer::BasicDataTreeBuilder::~BasicDataTreeBuilder() @ 0x55d12f47de35 mesos::internal::tests::ZooKeeperTestServer::ZooKeeperTestServer() @ 0x55d12de24fcc mesos::internal::tests::ZooKeeperTest::ZooKeeperTest() @ 0x55d12de27315 mesos::internal::tests::LogZooKeeperTest::LogZooKeeperTest() @ 0x55d12de27426 mesos::internal::tests::LogZooKeeperTest_WriteRead_Test::LogZooKeeperTest_WriteRead_Test() @ 0x55d12de92328 testing::internal::TestFactoryImpl<>::CreateTest() @ 0x55d12f4c46c2 testing::internal::HandleSehExceptionsInMethodIfSupported<>() @ 0x55d12f4bdc93 testing::internal::HandleExceptionsInMethodIfSupported<>() @ 0x55d12f499ecb testing::TestInfo::Run() @ 0x55d12f49a5d3 testing::TestCase::Run() @ 0x55d12f4a196d testing::internal::UnitTestImpl::RunAllTests() @ 0x55d12f4c58f0 testing::internal::HandleSehExceptionsInMethodIfSupported<>() @ 0x55d12f4be7f9 testing::internal::HandleExceptionsInMethodIfSupported<>() @ 0x55d12f4a0485 testing::UnitTest::Run() @ 0x55d12deafedb RUN_ALL_TESTS() @ 0x55d12deaf8a2 main @ 0x7fbd936b3083 __libc_start_main @ 0x55d12cef575e _start make[4]: *** [Makefile:18022: check-local] Segmentation fault (core dumped) make[4]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub/src' make[3]: *** [Makefile:15951: check-am] Error 2 make[3]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub/src' make[2]: *** [Makefile:15954: check] Error 2 I0702 23:09:23.210475 186650 exec.cpp:560] Agent exited ... shutting down make[2]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub/src' I0702 23:09:23.211505 186647 executor.cpp:190] Received SHUTDOWN event I0702 23:09:23.211575 186647 executor.cpp:843] Shutting down I0702 23:09:23.211643 186647 executor.cpp:956] Sending SIGTERM to process tree at pid 186662 make[1]: *** [Makefile:785: check-recursive] Error 1 make[1]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub' make: *** [Makefile:999: distcheck] Error 1 + copy_out_test_reports + find /tmp/SRC -name '*-tests.xml' -exec cp '{}' /SRC ';' I0702 23:09:23.227856 186647 executor.cpp:969] Sent SIGTERM to the following process trees: [ -+- 186662 sh -c dd if=/dev/zero of=volume_path/file bs=1048576 count=2 && sleep 1000 \--- 186670 sleep 1000 ] I0702 23:09:23.227936 186647 executor.cpp:973] Scheduling escalation to SIGKILL in 3secs from now I0702 23:09:23.253963 186654 executor.cpp:1041] Command terminated with signal Terminated (pid: 186662) W0702 23:09:23.256626 186659 process.cpp:1917] Failed to send 'mesos.internal.StatusUpdateMessage' to '172.17.0.2:39115', connect: Failed to connect to 172.17.0.2:39115: Connection refused I0702 23:09:24.257563 186659 process.cpp:935] Stopped the socket accept loop Untagged: mesos/mesos-build:ubuntu-20.04 Untagged: mesos/mesos-build@sha256:2d3cd7fed451697aba1a3103754b4a46b6a7cad64e8229fb65e5a31e6d4b413d Deleted: sha256:b978a6177f864ec24c8ab237b612c3e5e780d94875752c63681edd80d9a85bbd Deleted: sha256:3ce262d459956fd117307a4cccbe593d59a11fce0e9138bee98d634f3a536bd0 Deleted: sha256:93be824b42681ee74b5ef869b75fb8b4fc0f234ec2135b764d235bb863a722e1 Deleted: sha256:eca0ccc3c9322d20f126a1a390efe2f6862fef535a41044bdb68c492f0dd9392 Deleted: sha256:8ed5c7c631df3c9d418a68532b4957d8c8dbadc69ad70564f6fa45e4748f6957 Deleted: sha256:6988969997d24e5f91cf313970ab25e046d637808cc0d77b19de4fc385e6a0db Deleted: sha256:9a7bfb2ba9f4a5cc05f561ed15dcd86232976d79616d817df9d323b45b4407ca Deleted: sha256:92c98c8577076f502769040fce0770d08a5a5c5d41989fa70986df7b3962a293 Deleted: sha256:3ec3ded77c0ce89e931f92aed086b2a2c774a6fbd51617853decc8afa4e1087a Full log: https://ci-builds.apache.org/job/Mesos/job/Mesos-Reviewbot/33268/console - Mesos Reviewbot On May 28, 2024, 9:20 p.m., Jason Zhou wrote: > > ----------------------------------------------------------- > This is an automatically generated e-mail. To reply, visit: > https://reviews.apache.org/r/75016/ > ----------------------------------------------------------- > > (Updated May 28, 2024, 9:20 p.m.) > > > Review request for mesos and Benjamin Mahler. > > > Repository: mesos > > > Description > ------- > > Passes the device manager to the cgroups2 isolator on > containerizer startup, and sets up the ability for the > manager to be passed to the device controller and GPU isolator > > > Diffs > ----- > > src/slave/containerizer/containerizer.hpp > 691fdfe295850bce1302b4adde127d551f821b89 > src/slave/containerizer/containerizer.cpp > ba3ab43b0d56c6dabd141e40ac706568dccd72f1 > src/slave/containerizer/mesos/containerizer.hpp > 62174dfd056e1d7cc465ebdb29343bdd04de6a10 > src/slave/containerizer/mesos/containerizer.cpp > f7ff6b8e56e80881ac89ba650b7aa4f4eec3484b > src/slave/containerizer/mesos/isolators/cgroups2/cgroups2.hpp > e193f3f1f0dab753b394c409e422aa81097a64b7 > src/slave/containerizer/mesos/isolators/cgroups2/cgroups2.cpp > 2ca3880790be0cd092ec05a359711e2d8e641314 > src/slave/main.cpp 21b8ea74a502478fb73510a7d49bb5f28506ce8d > > > Diff: https://reviews.apache.org/r/75016/diff/3/ > > > Testing > ------- > > > Thanks, > > Jason Zhou > >
