----------------------------------------------------------- This is an automatically generated e-mail. To reply, visit: https://reviews.apache.org/r/75016/#review226646 -----------------------------------------------------------
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>... ms I0710 02:57:00.173003 185619 leveldb.cpp:460] Deleting ~5 keys from leveldb took 75.179709ms I0710 02:57:00.582547 185619 leveldb.cpp:527] Compacting range 0-4 took 409.482271ms I0710 02:57:00.582551 185625 leveldb.cpp:527] Compacting range 0-4 took 439.226216ms I0710 02:57:00.582659 185619 replica.cpp:712] Persisted action TRUNCATE at position 11 I0710 02:57:00.582701 185625 replica.cpp:712] Persisted action TRUNCATE at position 11 I0710 02:57:00.703744 185616 leveldb.cpp:217] Opened db in 119.526684ms I0710 02:57:00.799129 185616 leveldb.cpp:224] Compacted db in 95.336674ms I0710 02:57:00.799289 185616 leveldb.cpp:239] Created db iterator in 69771ns I0710 02:57:00.799371 185616 leveldb.cpp:245] Seeked to beginning of db in 50602ns I0710 02:57:00.799465 185616 leveldb.cpp:320] Iterated through 1 keys in the db in 73792ns I0710 02:57:00.799556 185616 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0710 02:57:00.800801 185620 catchup.cpp:342] Starting missing positions recovery I0710 02:57:00.801637 185617 catchup.cpp:368] Replica is in VOTING status I0710 02:57:00.804036 185631 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(926)@172.17.0.2:39989 I0710 02:57:00.804289 185631 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(927)@172.17.0.2:39989 I0710 02:57:00.805708 185628 recover.cpp:197] Received a recover response from a replica in VOTING status I0710 02:57:00.806342 185628 recover.cpp:197] Received a recover response from a replica in VOTING status I0710 02:57:00.808295 185617 catchup.cpp:423] Starting catch-up from position 0 to 10 I0710 02:57:00.811018 185639 replica.cpp:391] Replica received explicit promise request from __req_res__(929)@172.17.0.2:39989 for position 0 with proposal 0 I0710 02:57:00.811259 185622 replica.cpp:391] Replica received explicit promise request from __req_res__(930)@172.17.0.2:39989 for position 0 with proposal 0 I0710 02:57:00.811338 185639 replica.cpp:391] Replica received explicit promise request from __req_res__(931)@172.17.0.2:39989 for position 0 with proposal 0 I0710 02:57:00.812268 185620 replica.cpp:695] Replica received learned notice for position 0 from log-network(42)@172.17.0.2:39989 I0710 02:57:00.812328 185621 replica.cpp:695] Replica received learned notice for position 0 from log-network(42)@172.17.0.2:39989 I0710 02:57:00.812414 185617 replica.cpp:695] Replica received learned notice for position 0 from log-network(42)@172.17.0.2:39989 I0710 02:57:00.873196 185621 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 60.834561ms I0710 02:57:00.873297 185621 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:00.895778 185617 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 83.312037ms I0710 02:57:00.895816 185620 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 83.496696ms I0710 02:57:00.895876 185617 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:00.895905 185620 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:00.898263 185627 replica.cpp:391] Replica received explicit promise request from __req_res__(932)@172.17.0.2:39989 for position 1 with proposal 0 I0710 02:57:00.898478 185630 replica.cpp:391] Replica received explicit promise request from __req_res__(933)@172.17.0.2:39989 for position 1 with proposal 0 I0710 02:57:00.898823 185630 replica.cpp:391] Replica received explicit promise request from __req_res__(934)@172.17.0.2:39989 for position 1 with proposal 0 I0710 02:57:00.899663 185636 replica.cpp:695] Replica received learned notice for position 1 from log-network(42)@172.17.0.2:39989 I0710 02:57:00.899735 185625 replica.cpp:695] Replica received learned notice for position 1 from log-network(42)@172.17.0.2:39989 I0710 02:57:00.899804 185623 replica.cpp:695] Replica received learned notice for position 1 from log-network(42)@172.17.0.2:39989 I0710 02:57:00.987946 185623 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 88.08076ms I0710 02:57:00.987954 185636 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 88.24022ms I0710 02:57:00.987963 185625 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 88.183288ms I0710 02:57:01.063115 185636 leveldb.cpp:460] Deleting ~1 keys from leveldb took 75.056135ms I0710 02:57:01.063120 185623 leveldb.cpp:460] Deleting ~1 keys from leveldb took 75.109563ms I0710 02:57:01.063122 185625 leveldb.cpp:460] Deleting ~1 keys from leveldb took 75.017416ms I0710 02:57:01.307515 185623 leveldb.cpp:527] Compacting range 0-0 took 244.259858ms I0710 02:57:01.307606 185623 replica.cpp:712] Persisted action NOP at position 1 I0710 02:57:01.310542 185624 replica.cpp:391] Replica received explicit promise request from __req_res__(937)@172.17.0.2:39989 for position 2 with proposal 0 I0710 02:57:01.490577 185636 leveldb.cpp:527] Compacting range 0-0 took 427.372941ms I0710 02:57:01.490597 185625 leveldb.cpp:527] Compacting range 0-0 took 427.295622ms I0710 02:57:01.490690 185636 replica.cpp:712] Persisted action NOP at position 1 I0710 02:57:01.490726 185625 replica.cpp:712] Persisted action NOP at position 1 I0710 02:57:01.490916 185636 replica.cpp:391] Replica received explicit promise request from __req_res__(935)@172.17.0.2:39989 for position 2 with proposal 0 I0710 02:57:01.490967 185625 replica.cpp:391] Replica received explicit promise request from __req_res__(936)@172.17.0.2:39989 for position 2 with proposal 0 I0710 02:57:01.678721 185617 replica.cpp:391] Replica received explicit promise request from __req_res__(938)@172.17.0.2:39989 for position 2 with proposal 1 I0710 02:57:01.678978 185617 replica.cpp:391] Replica received explicit promise request from __req_res__(939)@172.17.0.2:39989 for position 2 with proposal 1 I0710 02:57:01.679136 185619 replica.cpp:391] Replica received explicit promise request from __req_res__(940)@172.17.0.2:39989 for position 2 with proposal 1 I0710 02:57:01.679972 185627 replica.cpp:695] Replica received learned notice for position 2 from log-network(42)@172.17.0.2:39989 I0710 02:57:01.680043 185625 replica.cpp:695] Replica received learned notice for position 2 from log-network(42)@172.17.0.2:39989 I0710 02:57:01.746412 185625 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 66.318969ms I0710 02:57:01.746451 185619 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 67.207083ms I0710 02:57:01.746448 185627 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 66.437563ms I0710 02:57:01.746548 185619 replica.cpp:712] Persisted action NOP at position 2 I0710 02:57:01.746805 185619 replica.cpp:695] Replica received learned notice for position 2 from log-network(42)@172.17.0.2:39989 I0710 02:57:01.821679 185619 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 74.838498ms I0710 02:57:01.821676 185627 leveldb.cpp:460] Deleting ~1 keys from leveldb took 75.112999ms I0710 02:57:01.821681 185625 leveldb.cpp:460] Deleting ~1 keys from leveldb took 75.207818ms I0710 02:57:01.866467 185619 leveldb.cpp:460] Deleting ~1 keys from leveldb took 44.733645ms I0710 02:57:02.299221 185625 leveldb.cpp:527] Compacting range 1-1 took 477.387083ms I0710 02:57:02.299228 185627 leveldb.cpp:527] Compacting range 1-1 took 477.446782ms I0710 02:57:02.299321 185625 replica.cpp:712] Persisted action NOP at position 2 I0710 02:57:02.299386 185627 replica.cpp:712] Persisted action NOP at position 2 I0710 02:57:02.457510 185619 leveldb.cpp:527] Compacting range 1-1 took 590.978795ms I0710 02:57:02.457607 185619 replica.cpp:712] Persisted action NOP at position 2 I0710 02:57:02.460649 185630 replica.cpp:391] Replica received explicit promise request from __req_res__(941)@172.17.0.2:39989 for position 3 with proposal 1 I0710 02:57:02.460738 185638 replica.cpp:391] Replica received explicit promise request from __req_res__(942)@172.17.0.2:39989 for position 3 with proposal 1 I0710 02:57:02.461015 185639 replica.cpp:391] Replica received explicit promise request from __req_res__(943)@172.17.0.2:39989 for position 3 with proposal 1 I0710 02:57:02.461887 185617 replica.cpp:695] Replica received learned notice for position 3 from log-network(42)@172.17.0.2:39989 I0710 02:57:02.461973 185633 replica.cpp:695] Replica received learned notice for position 3 from log-network(42)@172.17.0.2:39989 I0710 02:57:02.520846 185639 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 59.772107ms I0710 02:57:02.520932 185639 replica.cpp:712] Persisted action NOP at position 3 I0710 02:57:02.521199 185639 replica.cpp:695] Replica received learned notice for position 3 from log-network(42)@172.17.0.2:39989 I0710 02:57:02.554329 185633 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 92.306957ms I0710 02:57:02.554335 185617 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 92.398023ms I0710 02:57:02.604636 185639 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 83.380757ms I0710 02:57:02.629912 185617 leveldb.cpp:460] Deleting ~1 keys from leveldb took 75.463268ms I0710 02:57:02.629942 185633 leveldb.cpp:460] Deleting ~1 keys from leveldb took 75.546672ms I0710 02:57:02.691537 185639 leveldb.cpp:460] Deleting ~1 keys from leveldb took 86.870973ms I0710 02:57:03.559219 185617 leveldb.cpp:527] Compacting range 2-2 took 929.259316ms I0710 02:57:03.559230 185633 leveldb.cpp:527] Compacting range 2-2 took 929.229458ms I0710 02:57:03.559396 185633 replica.cpp:712] Persisted action NOP at position 3 I0710 02:57:03.559372 185617 replica.cpp:712] Persisted action NOP at position 3 I0710 02:57:03.723798 185639 leveldb.cpp:527] Compacting range 2-2 took 1.032163971secs I0710 02:57:03.723904 185639 replica.cpp:712] Persisted action NOP at position 3 I0710 02:57:03.727392 185631 replica.cpp:391] Replica received explicit promise request from __req_res__(944)@172.17.0.2:39989 for position 4 with proposal 1 I0710 02:57:03.727650 185640 replica.cpp:391] Replica received explicit promise request from __req_res__(945)@172.17.0.2:39989 for position 4 with proposal 1 I0710 02:57:03.727792 185630 replica.cpp:391] Replica received explicit promise request from __req_res__(946)@172.17.0.2:39989 for position 4 with proposal 1 I0710 02:57:03.728760 185624 replica.cpp:695] Replica received learned notice for position 4 from log-network(42)@172.17.0.2:39989 I0710 02:57:03.728766 185639 replica.cpp:695] Replica received learned notice for position 4 from log-network(42)@172.17.0.2:39989 I0710 02:57:03.836853 185639 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 107.978344ms I0710 02:57:03.836853 185630 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 108.985386ms I0710 02:57:03.836853 185624 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 108.04649ms I0710 02:57:03.836992 185630 replica.cpp:712] Persisted action NOP at position 4 I0710 02:57:03.837322 185630 replica.cpp:695] Replica received learned notice for position 4 from log-network(42)@172.17.0.2:39989 I0710 02:57:03.960011 185630 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 122.676059ms I0710 02:57:03.960011 185624 leveldb.cpp:460] Deleting ~1 keys from leveldb took 123.051889ms I0710 02:57:03.960011 185639 leveldb.cpp:460] Deleting ~1 keys from leveldb took 123.127295ms I0710 02:57:04.039557 185630 leveldb.cpp:460] Deleting ~1 keys from leveldb took 79.443809ms I0710 02:57:05.332309 185624 leveldb.cpp:527] Compacting range 3-3 took 1.372154682secs I0710 02:57:05.332393 185639 leveldb.cpp:527] Compacting range 3-3 took 1.372173739secs I0710 02:57:05.332477 185639 replica.cpp:712] Persisted action NOP at position 4 I0710 02:57:05.332470 185624 replica.cpp:712] Persisted action NOP at position 4 I0710 02:57:05.548784 185630 leveldb.cpp:527] Compacting range 3-3 took 1.509112578secs I0710 02:57:05.548878 185630 replica.cpp:712] Persisted action NOP at position 4 I0710 02:57:05.552023 185640 replica.cpp:391] Replica received explicit promise request from __req_res__(947)@172.17.0.2:39989 for position 5 with proposal 1 I0710 02:57:05.552220 185633 replica.cpp:391] Replica received explicit promise request from __req_res__(948)@172.17.0.2:39989 for position 5 with proposal 1 I0710 02:57:05.552281 185631 replica.cpp:391] Replica received explicit promise request from __req_res__(949)@172.17.0.2:39989 for position 5 with proposal 1 I0710 02:57:05.552271 185640 leveldb.cpp:510] Reading position from leveldb took 163699ns I0710 02:57:05.552503 185633 leveldb.cpp:510] Reading position from leveldb took 191453ns I0710 02:57:05.629861 185631 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 77.504873ms I0710 02:57:05.629952 185631 replica.cpp:712] Persisted action NOP at position 5 I0710 02:57:05.738620 185638 replica.cpp:391] Replica received explicit promise request from __req_res__(950)@172.17.0.2:39989 for position 5 with proposal 2 I0710 02:57:05.738775 185621 replica.cpp:391] Replica received explicit promise request from __req_res__(951)@172.17.0.2:39989 for position 5 with proposal 2 I0710 02:57:05.738812 185638 leveldb.cpp:510] Reading position from leveldb took 129878ns I0710 02:57:05.738981 185621 leveldb.cpp:510] Reading position from leveldb took 137326ns I0710 02:57:05.739084 185624 replica.cpp:391] Replica received explicit promise request from __req_res__(952)@172.17.0.2:39989 for position 5 with proposal 2 I0710 02:57:05.739248 185624 leveldb.cpp:510] Reading position from leveldb took 112487ns I0710 02:57:05.789767 185638 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 50.851315ms I0710 02:57:05.789815 185624 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 50.510412ms I0710 02:57:05.789870 185638 replica.cpp:712] Persisted action APPEND at position 5 I0710 02:57:05.789919 185624 replica.cpp:712] Persisted action NOP at position 5 I0710 02:57:05.791227 185628 replica.cpp:695] Replica received learned notice for position 5 from log-network(42)@172.17.0.2:39989 I0710 02:57:05.791280 185632 replica.cpp:695] Replica received learned notice for position 5 from log-network(42)@172.17.0.2:39989 I0710 02:57:05.834504 185621 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 95.438453ms I0710 02:57:05.834625 185621 replica.cpp:712] Persisted action APPEND at position 5 I0710 02:57:05.835018 185621 replica.cpp:695] Replica received learned notice for position 5 from log-network(42)@172.17.0.2:39989 I0710 02:57:05.873785 185632 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 82.462941ms I0710 02:57:05.873785 185628 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 82.527833ms I0710 02:57:05.873921 185632 replica.cpp:712] Persisted action APPEND at position 5 I0710 02:57:05.873944 185628 replica.cpp:712] Persisted action APPEND at position 5 I0710 02:57:05.876929 185637 replica.cpp:391] Replica received explicit promise request from __req_res__(953)@172.17.0.2:39989 for position 6 with proposal 2 I0710 02:57:05.877187 185639 replica.cpp:391] Replica received explicit promise request from __req_res__(955)@172.17.0.2:39989 for position 6 with proposal 2 I0710 02:57:05.877233 185637 leveldb.cpp:510] Reading position from leveldb took 233308ns I0710 02:57:05.909590 185621 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 74.549772ms I0710 02:57:05.909713 185621 replica.cpp:712] Persisted action APPEND at position 5 I0710 02:57:05.909946 185621 replica.cpp:391] Replica received explicit promise request from __req_res__(954)@172.17.0.2:39989 for position 6 with proposal 2 I0710 02:57:05.910169 185621 leveldb.cpp:510] Reading position from leveldb took 166673ns I0710 02:57:05.932729 185637 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 55.35353ms I0710 02:57:05.932729 185639 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 55.458721ms I0710 02:57:05.932826 185637 replica.cpp:712] Persisted action APPEND at position 6 I0710 02:57:05.932869 185639 replica.cpp:712] Persisted action NOP at position 6 I0710 02:57:05.934387 185629 replica.cpp:695] Replica received learned notice for position 6 from log-network(42)@172.17.0.2:39989 I0710 02:57:05.934370 185640 replica.cpp:695] Replica received learned notice for position 6 from log-network(42)@172.17.0.2:39989 I0710 02:57:05.976292 185621 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 66.016542ms I0710 02:57:05.976395 185621 replica.cpp:712] Persisted action APPEND at position 6 I0710 02:57:05.976682 185621 replica.cpp:695] Replica received learned notice for position 6 from log-network(42)@172.17.0.2:39989 I0710 02:57:06.000106 185629 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 65.65847ms I0710 02:57:06.000170 185629 replica.cpp:712] Persisted action APPEND at position 6 I0710 02:57:06.000152 185640 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 65.651703ms I0710 02:57:06.000265 185640 replica.cpp:712] Persisted action APPEND at position 6 I0710 02:57:06.002233 185625 replica.cpp:391] Replica received explicit promise request from __req_res__(956)@172.17.0.2:39989 for position 7 with proposal 2 I0710 02:57:06.002413 185628 replica.cpp:391] Replica received explicit promise request from __req_res__(958)@172.17.0.2:39989 for position 7 with proposal 2 I0710 02:57:06.002457 185625 leveldb.cpp:510] Reading position from leveldb took 156597ns I0710 02:57:06.041963 185621 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 65.222146ms I0710 02:57:06.042052 185621 replica.cpp:712] Persisted action APPEND at position 6 I0710 02:57:06.042197 185621 replica.cpp:391] Replica received explicit promise request from __req_res__(957)@172.17.0.2:39989 for position 7 with proposal 2 I0710 02:57:06.042377 185621 leveldb.cpp:510] Reading position from leveldb took 139832ns I0710 02:57:06.067638 185625 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 65.090578ms I0710 02:57:06.067647 185628 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 65.194286ms I0710 02:57:06.067734 185625 replica.cpp:712] Persisted action APPEND at position 7 I0710 02:57:06.067770 185628 replica.cpp:712] Persisted action NOP at position 7 I0710 02:57:06.069201 185624 replica.cpp:695] Replica received learned notice for position 7 from log-network(42)@172.17.0.2:39989 I0710 02:57:06.069281 185622 replica.cpp:695] Replica received learned notice for position 7 from log-network(42)@172.17.0.2:39989 I0710 02:57:06.109635 185621 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 67.191117ms I0710 02:57:06.109724 185621 replica.cpp:712] Persisted action APPEND at position 7 I0710 02:57:06.109967 185621 replica.cpp:695] Replica received learned notice for position 7 from log-network(42)@172.17.0.2:39989 I0710 02:57:06.151372 185624 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 82.107272ms I0710 02:57:06.151392 185622 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 82.069834ms I0710 02:57:06.151473 185624 replica.cpp:712] Persisted action APPEND at position 7 I0710 02:57:06.151532 185622 replica.cpp:712] Persisted action APPEND at position 7 I0710 02:57:06.153798 185617 replica.cpp:391] Replica received explicit promise request from __req_res__(959)@172.17.0.2:39989 for position 8 with proposal 2 I0710 02:57:06.153996 185617 leveldb.cpp:510] Reading position from leveldb took 135937ns I0710 02:57:06.154161 185623 replica.cpp:391] Replica received explicit promise request from __req_res__(961)@172.17.0.2:39989 for position 8 with proposal 2 I0710 02:57:06.185019 185621 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 75.016109ms I0710 02:57:06.185106 185621 replica.cpp:712] Persisted action APPEND at position 7 I0710 02:57:06.185276 185621 replica.cpp:391] Replica received explicit promise request from __req_res__(960)@172.17.0.2:39989 for position 8 with proposal 2 I0710 02:57:06.185492 185621 leveldb.cpp:510] Reading position from leveldb took 157666ns I0710 02:57:06.207999 185623 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 53.784226ms I0710 02:57:06.208032 185617 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 53.967889ms I0710 02:57:06.208112 185623 replica.cpp:712] Persisted action NOP at position 8 I0710 02:57:06.208155 185617 replica.cpp:712] Persisted action APPEND at position 8 I0710 02:57:06.209276 185622 replica.cpp:695] Replica received learned notice for position 8 from log-network(42)@172.17.0.2:39989 I0710 02:57:06.209357 185635 replica.cpp:695] Replica received learned notice for position 8 from log-network(42)@172.17.0.2:39989 I0710 02:57:06.255712 185621 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 70.129762ms I0710 02:57:06.255801 185621 replica.cpp:712] Persisted action APPEND at position 8 I0710 02:57:06.256044 185621 replica.cpp:695] Replica received learned notice for position 8 from log-network(42)@172.17.0.2:39989 I0710 02:57:06.292953 185622 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 83.642124ms I0710 02:57:06.292985 185635 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 83.581048ms I0710 02:57:06.293063 185622 replica.cpp:712] Persisted action APPEND at position 8 I0710 02:57:06.293116 185635 replica.cpp:712] Persisted action APPEND at position 8 I0710 02:57:06.295831 185634 replica.cpp:391] Replica received explicit promise request from __req_res__(962)@172.17.0.2:39989 for position 9 with proposal 2 I0710 02:57:06.296015 185634 leveldb.cpp:510] Reading position from leveldb took 124978ns I0710 02:57:06.296111 185633 replica.cpp:391] Replica received explicit promise request from __req_res__(964)@172.17.0.2:39989 for position 9 with proposal 2 I0710 02:57:06.327893 185621 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 71.810523ms I0710 02:57:06.327980 185621 replica.cpp:712] Persisted action APPEND at position 8 I0710 02:57:06.328126 185621 replica.cpp:391] Replica received explicit promise request from __req_res__(963)@172.17.0.2:39989 for position 9 with proposal 2 I0710 02:57:06.328284 185621 leveldb.cpp:510] Reading position from leveldb took 114764ns I0710 02:57:06.349606 185634 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 53.523002ms I0710 02:57:06.349607 185633 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 53.44492ms I0710 02:57:06.349705 185634 replica.cpp:712] Persisted action APPEND at position 9 I0710 02:57:06.349747 185633 replica.cpp:712] Persisted action NOP at position 9 I0710 02:57:06.350821 185622 replica.cpp:695] Replica received learned notice for position 9 from log-network(42)@172.17.0.2:39989 I0710 02:57:06.350976 185638 replica.cpp:695] Replica received learned notice for position 9 from log-network(42)@172.17.0.2:39989 I0710 02:57:06.397416 185621 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 69.067031ms I0710 02:57:06.397505 185621 replica.cpp:712] Persisted action APPEND at position 9 I0710 02:57:06.397747 185621 replica.cpp:695] Replica received learned notice for position 9 from log-network(42)@172.17.0.2:39989 I0710 02:57:06.441234 185638 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 90.211588ms I0710 02:57:06.441234 185622 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 90.378005ms I0710 02:57:06.441324 185638 replica.cpp:712] Persisted action APPEND at position 9 I0710 02:57:06.441385 185622 replica.cpp:712] Persisted action APPEND at position 9 I0710 02:57:06.443877 185625 replica.cpp:391] Replica received explicit promise request from __req_res__(965)@172.17.0.2:39989 for position 10 with proposal 2 I0710 02:57:06.444118 185620 replica.cpp:391] Replica received explicit promise request from __req_res__(967)@172.17.0.2:39989 for position 10 with proposal 2 I0710 02:57:06.444160 185625 leveldb.cpp:510] Reading position from leveldb took 199889ns I0710 02:57:06.476167 185621 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 78.387317ms I0710 02:57:06.476258 185621 replica.cpp:712] Persisted action APPEND at position 9 I0710 02:57:06.476402 185621 replica.cpp:391] Replica received explicit promise request from __req_res__(966)@172.17.0.2:39989 for position 10 with proposal 2 I0710 02:57:06.476562 185621 leveldb.cpp:510] Reading position from leveldb took 115645ns I0710 02:57:06.507915 185625 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 63.661441ms I0710 02:57:06.507937 185620 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 63.760969ms I0710 02:57:06.508030 185625 replica.cpp:712] Persisted action APPEND at position 10 I0710 02:57:06.508069 185620 replica.cpp:712] Persisted action NOP at position 10 I0710 02:57:06.509362 185626 replica.cpp:695] Replica received learned notice for position 10 from log-network(42)@172.17.0.2:39989 I0710 02:57:06.509366 185627 replica.cpp:695] Replica received learned notice for position 10 from log-network(42)@172.17.0.2:39989 I0710 02:57:06.546592 185621 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 69.964023ms I0710 02:57:06.546676 185621 replica.cpp:712] Persisted action APPEND at position 10 I0710 02:57:06.546919 185621 replica.cpp:695] Replica received learned notice for position 10 from log-network(42)@172.17.0.2:39989 I0710 02:57:06.587313 185627 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 77.863562ms I0710 02:57:06.587313 185626 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 77.901155ms I0710 02:57:06.587376 185627 replica.cpp:712] Persisted action APPEND at position 10 I0710 02:57:06.587399 185626 replica.cpp:712] Persisted action APPEND at position 10 I0710 02:57:06.587975 185635 catchup.cpp:357] Recover process terminated I0710 02:57:06.589339 185637 leveldb.cpp:510] Reading position from leveldb took 75088ns I0710 02:57:06.589460 185637 leveldb.cpp:510] Reading position from leveldb took 43188ns I0710 02:57:06.589541 185637 leveldb.cpp:510] Reading position from leveldb took 39244ns I0710 02:57:06.589623 185637 leveldb.cpp:510] Reading position from leveldb took 41060ns I0710 02:57:06.589709 185637 leveldb.cpp:510] Reading position from leveldb took 39043ns I0710 02:57:06.589790 185637 leveldb.cpp:510] Reading position from leveldb took 39619ns I0710 02:57:06.605520 185621 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 58.571163ms I0710 02:57:06.605580 185621 replica.cpp:712] Persisted action APPEND at position 10 [ OK ] RecoverTest.CatchupVotingWithGap (9382 ms) [ RUN ] RecoverTest.CatchupVotingOnePosition I0710 02:57:07.067874 185616 leveldb.cpp:217] Opened db in 456.397299ms I0710 02:57:07.131484 185616 leveldb.cpp:224] Compacted db in 63.547657ms I0710 02:57:07.131608 185616 leveldb.cpp:239] Created db iterator in 59375ns I0710 02:57:07.131659 185616 leveldb.cpp:245] Seeked to beginning of db in 23089ns I0710 02:57:07.131708 185616 leveldb.cpp:320] Iterated through 0 keys in the db in 16823ns I0710 02:57:07.131808 185616 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0710 02:57:07.193703 185617 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 61.199283ms I0710 02:57:07.193831 185617 replica.cpp:322] Persisted replica status to VOTING I0710 02:57:07.455749 185616 leveldb.cpp:217] Opened db in 260.904407ms I0710 02:57:07.553452 185616 leveldb.cpp:224] Compacted db in 97.640728ms I0710 02:57:07.553581 185616 leveldb.cpp:239] Created db iterator in 68505ns I0710 02:57:07.553635 185616 leveldb.cpp:245] Seeked to beginning of db in 16093ns I0710 02:57:07.553673 185616 leveldb.cpp:320] Iterated through 0 keys in the db in 19246ns I0710 02:57:07.553776 185616 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0710 02:57:07.625169 185623 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 70.701669ms I0710 02:57:07.625293 185623 replica.cpp:322] Persisted replica status to VOTING I0710 02:57:07.852142 185616 leveldb.cpp:217] Opened db in 225.901745ms I0710 02:57:07.936304 185616 leveldb.cpp:224] Compacted db in 84.11392ms I0710 02:57:07.936416 185616 leveldb.cpp:239] Created db iterator in 53072ns I0710 02:57:07.936473 185616 leveldb.cpp:245] Seeked to beginning of db in 16556ns I0710 02:57:07.936522 185616 leveldb.cpp:320] Iterated through 0 keys in the db in 18209ns I0710 02:57:07.936599 185616 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0710 02:57:07.986291 185636 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 48.744356ms I0710 02:57:07.986406 185636 replica.cpp:322] Persisted replica status to VOTING I0710 02:57:08.206197 185616 leveldb.cpp:217] Opened db in 218.906336ms I0710 02:57:08.328402 185616 leveldb.cpp:224] Compacted db in 122.154569ms I0710 02:57:08.328527 185616 leveldb.cpp:239] Created db iterator in 60396ns I0710 02:57:08.328624 185616 leveldb.cpp:245] Seeked to beginning of db in 59628ns I0710 02:57:08.328743 185616 leveldb.cpp:320] Iterated through 1 keys in the db in 88881ns I0710 02:57:08.328847 185616 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0710 02:57:08.517369 185616 leveldb.cpp:217] Opened db in 188.15181ms I0710 02:57:08.670325 185616 leveldb.cpp:224] Compacted db in 152.893907ms I0710 02:57:08.670451 185616 leveldb.cpp:239] Created db iterator in 62349ns I0710 02:57:08.670524 185616 leveldb.cpp:245] Seeked to beginning of db in 45259ns I0710 02:57:08.670622 185616 leveldb.cpp:320] Iterated through 1 keys in the db in 76451ns I0710 02:57:08.670725 185616 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0710 02:57:08.895048 185616 leveldb.cpp:217] Opened db in 223.810758ms I0710 02:57:09.000118 185616 leveldb.cpp:224] Compacted db in 105.013546ms I0710 02:57:09.000239 185616 leveldb.cpp:239] Created db iterator in 55358ns I0710 02:57:09.000319 185616 leveldb.cpp:245] Seeked to beginning of db in 58109ns I0710 02:57:09.000433 185616 leveldb.cpp:320] Iterated through 1 keys in the db in 82562ns I0710 02:57:09.000535 185616 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0710 02:57:09.001480 185617 catchup.cpp:342] Starting missing positions recovery I0710 02:57:09.002159 185617 catchup.cpp:368] Replica is in VOTING status I0710 02:57:09.004393 185620 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(968)@172.17.0.2:39989 I0710 02:57:09.004572 185629 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(969)@172.17.0.2:39989 I0710 02:57:09.004796 185623 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(970)@172.17.0.2:39989 I0710 02:57:09.006035 185624 recover.cpp:197] Received a recover response from a replica in VOTING status I0710 02:57:09.006656 185624 recover.cpp:197] Received a recover response from a replica in VOTING status I0710 02:57:09.008034 185628 catchup.cpp:357] Recover process terminated [ OK ] RecoverTest.CatchupVotingOnePosition (2403 ms) [----------] 9 tests from RecoverTest (46900 ms total) [----------] 4 tests from LogTest [ RUN ] LogTest.WriteRead I0710 02:57:09.251844 185616 leveldb.cpp:217] Opened db in 237.559949ms I0710 02:57:09.306463 185616 leveldb.cpp:224] Compacted db in 54.568209ms I0710 02:57:09.306591 185616 leveldb.cpp:239] Created db iterator in 50732ns I0710 02:57:09.306659 185616 leveldb.cpp:245] Seeked to beginning of db in 25903ns I0710 02:57:09.306703 185616 leveldb.cpp:320] Iterated through 0 keys in the db in 12663ns I0710 02:57:09.306785 185616 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0710 02:57:09.359081 185626 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 51.664508ms I0710 02:57:09.359218 185626 replica.cpp:322] Persisted replica status to VOTING I0710 02:57:09.568534 185616 leveldb.cpp:217] Opened db in 208.389298ms I0710 02:57:09.623090 185616 leveldb.cpp:224] Compacted db in 54.509221ms I0710 02:57:09.623226 185616 leveldb.cpp:239] Created db iterator in 68012ns I0710 02:57:09.623284 185616 leveldb.cpp:245] Seeked to beginning of db in 23649ns I0710 02:57:09.623327 185616 leveldb.cpp:320] Iterated through 0 keys in the db in 12480ns I0710 02:57:09.623399 185616 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0710 02:57:09.668713 185618 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 44.568364ms I0710 02:57:09.668809 185618 replica.cpp:322] Persisted replica status to VOTING I0710 02:57:10.126821 185616 leveldb.cpp:217] Opened db in 457.119837ms I0710 02:57:10.298148 185616 leveldb.cpp:224] Compacted db in 171.273293ms I0710 02:57:10.298272 185616 leveldb.cpp:239] Created db iterator in 57179ns I0710 02:57:10.298372 185616 leveldb.cpp:245] Seeked to beginning of db in 62512ns I0710 02:57:10.298494 185616 leveldb.cpp:320] Iterated through 1 keys in the db in 86391ns I0710 02:57:10.298600 185616 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0710 02:57:10.533680 185616 leveldb.cpp:217] Opened db in 234.576616ms I0710 02:57:10.709645 185616 leveldb.cpp:224] Compacted db in 175.925581ms I0710 02:57:10.709764 185616 leveldb.cpp:239] Created db iterator in 50209ns I0710 02:57:10.709854 185616 leveldb.cpp:245] Seeked to beginning of db in 59545ns I0710 02:57:10.709955 185616 leveldb.cpp:320] Iterated through 1 keys in the db in 70449ns I0710 02:57:10.710050 185616 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0710 02:57:10.711439 185631 recover.cpp:437] Starting replica recovery I0710 02:57:10.712049 185631 recover.cpp:468] Replica is in VOTING status I0710 02:57:10.712401 185631 recover.cpp:447] Recover process terminated I0710 02:57:10.713088 185631 log.cpp:554] Attempting to start the writer I0710 02:57:10.715785 185630 replica.cpp:497] Replica received implicit promise request from __req_res__(971)@172.17.0.2:39989 with proposal 1 I0710 02:57:10.715926 185626 replica.cpp:497] Replica received implicit promise request from __req_res__(972)@172.17.0.2:39989 with proposal 1 I0710 02:57:10.759501 185626 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 43.514842ms I0710 02:57:10.759516 185630 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 43.673513ms I0710 02:57:10.759598 185626 replica.cpp:344] Persisted promised to 1 I0710 02:57:10.759646 185630 replica.cpp:344] Persisted promised to 1 I0710 02:57:10.760885 185634 coordinator.cpp:238] Coordinator attempting to fill missing positions I0710 02:57:10.763067 185617 replica.cpp:391] Replica received explicit promise request from __req_res__(973)@172.17.0.2:39989 for position 0 with proposal 2 I0710 02:57:10.763226 185629 replica.cpp:391] Replica received explicit promise request from __req_res__(974)@172.17.0.2:39989 for position 0 with proposal 2 I0710 02:57:10.809749 185629 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 46.460497ms I0710 02:57:10.809782 185617 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 46.589118ms I0710 02:57:10.809840 185629 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:10.809866 185617 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:10.811659 185618 replica.cpp:541] Replica received write request for position 0 from __req_res__(975)@172.17.0.2:39989 I0710 02:57:10.811779 185627 replica.cpp:541] Replica received write request for position 0 from __req_res__(976)@172.17.0.2:39989 I0710 02:57:10.811802 185618 leveldb.cpp:510] Reading position from leveldb took 82328ns I0710 02:57:10.811967 185627 leveldb.cpp:510] Reading position from leveldb took 110764ns I0710 02:57:10.874756 185618 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 62.825796ms I0710 02:57:10.874769 185627 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 62.681028ms I0710 02:57:10.874852 185618 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:10.874900 185627 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:10.875938 185630 replica.cpp:695] Replica received learned notice for position 0 from log-network(44)@172.17.0.2:39989 I0710 02:57:10.875977 185638 replica.cpp:695] Replica received learned notice for position 0 from log-network(44)@172.17.0.2:39989 I0710 02:57:10.927254 185630 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 51.266376ms I0710 02:57:10.927258 185638 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 51.232504ms I0710 02:57:10.927348 185630 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:10.927400 185638 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:10.928388 185637 log.cpp:570] Writer started with ending position 0 I0710 02:57:10.929286 185620 log.cpp:578] Attempting to append 11 bytes to the log I0710 02:57:10.929549 185621 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 I0710 02:57:10.930768 185633 replica.cpp:541] Replica received write request for position 1 from __req_res__(977)@172.17.0.2:39989 I0710 02:57:10.930898 185619 replica.cpp:541] Replica received write request for position 1 from __req_res__(978)@172.17.0.2:39989 I0710 02:57:10.983987 185619 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 53.005109ms I0710 02:57:10.983989 185633 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 53.142989ms I0710 02:57:10.984082 185619 replica.cpp:712] Persisted action APPEND at position 1 I0710 02:57:10.984143 185633 replica.cpp:712] Persisted action APPEND at position 1 I0710 02:57:10.985126 185618 replica.cpp:695] Replica received learned notice for position 1 from log-network(44)@172.17.0.2:39989 I0710 02:57:10.985165 185637 replica.cpp:695] Replica received learned notice for position 1 from log-network(44)@172.17.0.2:39989 I0710 02:57:11.044700 185618 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 59.529445ms I0710 02:57:11.044726 185637 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 59.515969ms I0710 02:57:11.044812 185618 replica.cpp:712] Persisted action APPEND at position 1 I0710 02:57:11.044853 185637 replica.cpp:712] Persisted action APPEND at position 1 I0710 02:57:11.047578 185629 leveldb.cpp:510] Reading position from leveldb took 100065ns [ OK ] LogTest.WriteRead (2040 ms) [ RUN ] LogTest.Position I0710 02:57:11.276643 185616 leveldb.cpp:217] Opened db in 222.383455ms I0710 02:57:11.336294 185616 leveldb.cpp:224] Compacted db in 59.595774ms I0710 02:57:11.336417 185616 leveldb.cpp:239] Created db iterator in 59949ns I0710 02:57:11.336479 185616 leveldb.cpp:245] Seeked to beginning of db in 21169ns I0710 02:57:11.336512 185616 leveldb.cpp:320] Iterated through 0 keys in the db in 11043ns I0710 02:57:11.336604 185616 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0710 02:57:11.390302 185619 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 53.00813ms I0710 02:57:11.390388 185619 replica.cpp:322] Persisted replica status to VOTING I0710 02:57:11.601676 185616 leveldb.cpp:217] Opened db in 210.378945ms I0710 02:57:11.653084 185616 leveldb.cpp:224] Compacted db in 51.35855ms I0710 02:57:11.653191 185616 leveldb.cpp:239] Created db iterator in 44249ns I0710 02:57:11.653247 185616 leveldb.cpp:245] Seeked to beginning of db in 22610ns I0710 02:57:11.653286 185616 leveldb.cpp:320] Iterated through 0 keys in the db in 11717ns I0710 02:57:11.653369 185616 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0710 02:57:11.701761 185636 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 47.849882ms I0710 02:57:11.701874 185636 replica.cpp:322] Persisted replica status to VOTING I0710 02:57:11.918277 185616 leveldb.cpp:217] Opened db in 215.558069ms I0710 02:57:12.169891 185616 leveldb.cpp:224] Compacted db in 251.568373ms I0710 02:57:12.170007 185616 leveldb.cpp:239] Created db iterator in 53229ns I0710 02:57:12.170104 185616 leveldb.cpp:245] Seeked to beginning of db in 59865ns I0710 02:57:12.170221 185616 leveldb.cpp:320] Iterated through 1 keys in the db in 84202ns I0710 02:57:12.170321 185616 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0710 02:57:12.367717 185616 leveldb.cpp:217] Opened db in 196.974808ms I0710 02:57:12.494948 185616 leveldb.cpp:224] Compacted db in 127.184922ms I0710 02:57:12.495060 185616 leveldb.cpp:239] Created db iterator in 49825ns I0710 02:57:12.495132 185616 leveldb.cpp:245] Seeked to beginning of db in 46306ns I0710 02:57:12.495252 185616 leveldb.cpp:320] Iterated through 1 keys in the db in 103538ns I0710 02:57:12.495352 185616 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0710 02:57:12.496623 185628 recover.cpp:437] Starting replica recovery I0710 02:57:12.497237 185640 recover.cpp:468] Replica is in VOTING status I0710 02:57:12.497642 185640 recover.cpp:447] Recover process terminated I0710 02:57:12.498389 185617 log.cpp:554] Attempting to start the writer I0710 02:57:12.501055 185624 replica.cpp:497] Replica received implicit promise request from __req_res__(979)@172.17.0.2:39989 with proposal 1 I0710 02:57:12.501165 185632 replica.cpp:497] Replica received implicit promise request from __req_res__(980)@172.17.0.2:39989 with proposal 1 I0710 02:57:12.567243 185624 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 66.102543ms I0710 02:57:12.567342 185624 replica.cpp:344] Persisted promised to 1 I0710 02:57:12.585366 185632 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 84.128916ms I0710 02:57:12.585448 185632 replica.cpp:344] Persisted promised to 1 I0710 02:57:12.586639 185622 coordinator.cpp:238] Coordinator attempting to fill missing positions I0710 02:57:12.588953 185619 replica.cpp:391] Replica received explicit promise request from __req_res__(981)@172.17.0.2:39989 for position 0 with proposal 2 I0710 02:57:12.589056 185625 replica.cpp:391] Replica received explicit promise request from __req_res__(982)@172.17.0.2:39989 for position 0 with proposal 2 I0710 02:57:12.644155 185625 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 55.023338ms I0710 02:57:12.644172 185619 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 55.137694ms I0710 02:57:12.644223 185625 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:12.644256 185619 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:12.645674 185636 replica.cpp:541] Replica received write request for position 0 from __req_res__(983)@172.17.0.2:39989 I0710 02:57:12.645824 185636 leveldb.cpp:510] Reading position from leveldb took 86372ns I0710 02:57:12.645823 185630 replica.cpp:541] Replica received write request for position 0 from __req_res__(984)@172.17.0.2:39989 I0710 02:57:12.645993 185630 leveldb.cpp:510] Reading position from leveldb took 79599ns I0710 02:57:12.702718 185636 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 56.811806ms I0710 02:57:12.702795 185636 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:12.702788 185630 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 56.710578ms I0710 02:57:12.702898 185630 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:12.703819 185632 replica.cpp:695] Replica received learned notice for position 0 from log-network(45)@172.17.0.2:39989 I0710 02:57:12.703835 185621 replica.cpp:695] Replica received learned notice for position 0 from log-network(45)@172.17.0.2:39989 I0710 02:57:12.761327 185621 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 57.420669ms I0710 02:57:12.761327 185632 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 57.457824ms I0710 02:57:12.761443 185621 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:12.761483 185632 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:12.762383 185622 log.cpp:570] Writer started with ending position 0 I0710 02:57:12.763258 185630 log.cpp:578] Attempting to append 11 bytes to the log I0710 02:57:12.763573 185636 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 I0710 02:57:12.764781 185625 replica.cpp:541] Replica received write request for position 1 from __req_res__(985)@172.17.0.2:39989 I0710 02:57:12.764891 185639 replica.cpp:541] Replica received write request for position 1 from __req_res__(986)@172.17.0.2:39989 I0710 02:57:12.819846 185639 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 54.890523ms I0710 02:57:12.819849 185625 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 54.980394ms I0710 02:57:12.819939 185639 replica.cpp:712] Persisted action APPEND at position 1 I0710 02:57:12.819985 185625 replica.cpp:712] Persisted action APPEND at position 1 I0710 02:57:12.820993 185633 replica.cpp:695] Replica received learned notice for position 1 from log-network(45)@172.17.0.2:39989 I0710 02:57:12.821012 185631 replica.cpp:695] Replica received learned notice for position 1 from log-network(45)@172.17.0.2:39989 I0710 02:57:12.878479 185631 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 57.392254ms I0710 02:57:12.878479 185633 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 57.437546ms I0710 02:57:12.878573 185631 replica.cpp:712] Persisted action APPEND at position 1 I0710 02:57:12.878615 185633 replica.cpp:712] Persisted action APPEND at position 1 [ OK ] LogTest.Position (1831 ms) [ RUN ] LogTest.Metrics I0710 02:57:13.072417 185616 leveldb.cpp:217] Opened db in 187.194133ms I0710 02:57:13.131042 185616 leveldb.cpp:224] Compacted db in 58.576849ms I0710 02:57:13.131160 185616 leveldb.cpp:239] Created db iterator in 52612ns I0710 02:57:13.131234 185616 leveldb.cpp:245] Seeked to beginning of db in 30439ns I0710 02:57:13.131304 185616 leveldb.cpp:320] Iterated through 0 keys in the db in 25196ns I0710 02:57:13.131415 185616 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0710 02:57:13.189482 185618 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 57.370747ms I0710 02:57:13.189569 185618 replica.cpp:322] Persisted replica status to VOTING I0710 02:57:13.375110 185616 leveldb.cpp:217] Opened db in 184.610238ms I0710 02:57:13.525875 185616 leveldb.cpp:224] Compacted db in 150.683984ms I0710 02:57:13.526001 185616 leveldb.cpp:239] Created db iterator in 58382ns I0710 02:57:13.526082 185616 leveldb.cpp:245] Seeked to beginning of db in 55819ns I0710 02:57:13.526181 185616 leveldb.cpp:320] Iterated through 1 keys in the db in 78605ns I0710 02:57:13.526266 185616 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0710 02:57:13.527535 185635 recover.cpp:437] Starting replica recovery I0710 02:57:13.528127 185633 recover.cpp:468] Replica is in VOTING status I0710 02:57:13.528591 185633 recover.cpp:447] Recover process terminated I0710 02:57:13.529428 185633 log.cpp:554] Attempting to start the writer I0710 02:57:13.532066 185637 replica.cpp:497] Replica received implicit promise request from __req_res__(987)@172.17.0.2:39989 with proposal 1 I0710 02:57:13.583983 185637 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 51.850987ms I0710 02:57:13.584079 185637 replica.cpp:344] Persisted promised to 1 I0710 02:57:13.585318 185620 coordinator.cpp:238] Coordinator attempting to fill missing positions I0710 02:57:13.587025 185636 replica.cpp:391] Replica received explicit promise request from __req_res__(988)@172.17.0.2:39989 for position 0 with proposal 2 I0710 02:57:13.625932 185636 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 38.857765ms I0710 02:57:13.626021 185636 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:13.627664 185620 replica.cpp:541] Replica received write request for position 0 from __req_res__(989)@172.17.0.2:39989 I0710 02:57:13.627805 185620 leveldb.cpp:510] Reading position from leveldb took 80965ns I0710 02:57:13.667850 185620 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 39.973694ms I0710 02:57:13.667937 185620 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:13.668828 185634 replica.cpp:695] Replica received learned notice for position 0 from log-network(46)@172.17.0.2:39989 I0710 02:57:13.709740 185634 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 40.853493ms I0710 02:57:13.709828 185634 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:13.710781 185625 log.cpp:570] Writer started with ending position 0 I0710 02:57:13.717151 185623 process.cpp:3671] Handling HTTP event for process 'metrics' with path: '/metrics/snapshot' [ OK ] LogTest.Metrics (845 ms) [ RUN ] LogTest.ReaderCatchup I0710 02:57:13.895285 185616 leveldb.cpp:217] Opened db in 164.811395ms I0710 02:57:13.936465 185616 leveldb.cpp:224] Compacted db in 41.122043ms I0710 02:57:13.936581 185616 leveldb.cpp:239] Created db iterator in 51272ns I0710 02:57:13.936630 185616 leveldb.cpp:245] Seeked to beginning of db in 20210ns I0710 02:57:13.936656 185616 leveldb.cpp:320] Iterated through 0 keys in the db in 11037ns I0710 02:57:13.936726 185616 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0710 02:57:13.995379 185635 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 58.062976ms I0710 02:57:13.995473 185635 replica.cpp:322] Persisted replica status to VOTING I0710 02:57:14.231426 185616 leveldb.cpp:217] Opened db in 235.052011ms I0710 02:57:14.303360 185616 leveldb.cpp:224] Compacted db in 71.887972ms I0710 02:57:14.303467 185616 leveldb.cpp:239] Created db iterator in 42216ns I0710 02:57:14.303507 185616 leveldb.cpp:245] Seeked to beginning of db in 12383ns I0710 02:57:14.303534 185616 leveldb.cpp:320] Iterated through 0 keys in the db in 10183ns I0710 02:57:14.303596 185616 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0710 02:57:14.340024 185639 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 35.827657ms I0710 02:57:14.340099 185639 replica.cpp:322] Persisted replica status to VOTING I0710 02:57:14.458088 185616 leveldb.cpp:217] Opened db in 117.163087ms I0710 02:57:14.486740 185616 leveldb.cpp:224] Compacted db in 28.605258ms I0710 02:57:14.486846 185616 leveldb.cpp:239] Created db iterator in 41042ns I0710 02:57:14.486886 185616 leveldb.cpp:245] Seeked to beginning of db in 12373ns I0710 02:57:14.486922 185616 leveldb.cpp:320] Iterated through 0 keys in the db in 18053ns I0710 02:57:14.487018 185616 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0710 02:57:14.550527 185622 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 62.890294ms I0710 02:57:14.550645 185622 replica.cpp:322] Persisted replica status to VOTING I0710 02:57:14.719311 185616 leveldb.cpp:217] Opened db in 167.808723ms I0710 02:57:14.964989 185616 leveldb.cpp:224] Compacted db in 245.629919ms I0710 02:57:14.965111 185616 leveldb.cpp:239] Created db iterator in 52409ns I0710 02:57:14.965201 185616 leveldb.cpp:245] Seeked to beginning of db in 61356ns I0710 02:57:14.965337 185616 leveldb.cpp:320] Iterated through 1 keys in the db in 106548ns I0710 02:57:14.965459 185616 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0710 02:57:15.778936 185616 leveldb.cpp:217] Opened db in 813.017791ms I0710 02:57:16.142062 185616 leveldb.cpp:224] Compacted db in 363.035893ms I0710 02:57:16.142213 185616 leveldb.cpp:239] Created db iterator in 58859ns I0710 02:57:16.142279 185616 leveldb.cpp:245] Seeked to beginning of db in 46754ns I0710 02:57:16.142362 185616 leveldb.cpp:320] Iterated through 1 keys in the db in 68139ns I0710 02:57:16.142437 185616 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0710 02:57:16.146265 185624 replica.cpp:497] Replica received implicit promise request from __req_res__(990)@172.17.0.2:39989 with proposal 1 I0710 02:57:16.146474 185630 replica.cpp:497] Replica received implicit promise request from __req_res__(991)@172.17.0.2:39989 with proposal 1 I0710 02:57:16.283421 185624 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 137.096011ms I0710 02:57:16.283421 185630 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 136.92946ms I0710 02:57:16.283582 185624 replica.cpp:344] Persisted promised to 1 I0710 02:57:16.283622 185630 replica.cpp:344] Persisted promised to 1 I0710 02:57:16.284993 185637 coordinator.cpp:238] Coordinator attempting to fill missing positions I0710 02:57:16.287953 185640 replica.cpp:391] Replica received explicit promise request from __req_res__(992)@172.17.0.2:39989 for position 0 with proposal 2 I0710 02:57:16.288057 185639 replica.cpp:391] Replica received explicit promise request from __req_res__(993)@172.17.0.2:39989 for position 0 with proposal 2 I0710 02:57:16.360998 185640 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 72.941715ms I0710 02:57:16.360999 185639 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 72.88231ms I0710 02:57:16.361105 185640 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:16.361152 185639 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:16.362951 185623 replica.cpp:541] Replica received write request for position 0 from __req_res__(994)@172.17.0.2:39989 I0710 02:57:16.363055 185627 replica.cpp:541] Replica received write request for position 0 from __req_res__(995)@172.17.0.2:39989 I0710 02:57:16.363126 185623 leveldb.cpp:510] Reading position from leveldb took 106068ns I0710 02:57:16.363233 185627 leveldb.cpp:510] Reading position from leveldb took 129271ns I0710 02:57:16.478505 185623 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 115.274939ms I0710 02:57:16.478518 185627 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 115.172769ms I0710 02:57:16.478619 185623 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:16.478662 185627 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:16.479816 185634 replica.cpp:695] Replica received learned notice for position 0 from log-network(47)@172.17.0.2:39989 I0710 02:57:16.479830 185639 replica.cpp:695] Replica received learned notice for position 0 from log-network(47)@172.17.0.2:39989 I0710 02:57:16.581703 185634 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 101.831694ms I0710 02:57:16.581708 185639 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 101.787719ms I0710 02:57:16.581813 185634 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:16.581856 185639 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:16.583781 185637 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 I0710 02:57:16.585182 185636 replica.cpp:541] Replica received write request for position 1 from __req_res__(996)@172.17.0.2:39989 I0710 02:57:16.585346 185628 replica.cpp:541] Replica received write request for position 1 from __req_res__(997)@172.17.0.2:39989 I0710 02:57:16.691107 185628 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 105.680796ms I0710 02:57:16.691118 185636 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 105.864659ms I0710 02:57:16.691236 185628 replica.cpp:712] Persisted action APPEND at position 1 I0710 02:57:16.691280 185636 replica.cpp:712] Persisted action APPEND at position 1 I0710 02:57:16.692262 185639 replica.cpp:695] Replica received learned notice for position 1 from log-network(47)@172.17.0.2:39989 I0710 02:57:16.692334 185620 replica.cpp:695] Replica received learned notice for position 1 from log-network(47)@172.17.0.2:39989 I0710 02:57:16.769601 185620 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 77.215729ms I0710 02:57:16.769615 185639 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 77.31673ms I0710 02:57:16.769709 185620 replica.cpp:712] Persisted action APPEND at position 1 I0710 02:57:16.769763 185639 replica.cpp:712] Persisted action APPEND at position 1 I0710 02:57:16.771910 185633 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 2 I0710 02:57:16.773463 185636 replica.cpp:541] Replica received write request for position 2 from __req_res__(998)@172.17.0.2:39989 I0710 02:57:16.773600 185629 replica.cpp:541] Replica received write request for position 2 from __req_res__(999)@172.17.0.2:39989 I0710 02:57:16.884932 185636 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 111.405849ms I0710 02:57:16.884932 185629 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 111.284617ms I0710 02:57:16.885069 185636 replica.cpp:712] Persisted action APPEND at position 2 I0710 02:57:16.885123 185629 replica.cpp:712] Persisted action APPEND at position 2 I0710 02:57:16.886111 185622 replica.cpp:695] Replica received learned notice for position 2 from log-network(47)@172.17.0.2:39989 I0710 02:57:16.886116 185619 replica.cpp:695] Replica received learned notice for position 2 from log-network(47)@172.17.0.2:39989 I0710 02:57:16.956281 185619 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 70.130743ms I0710 02:57:16.956281 185622 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 70.15991ms I0710 02:57:16.956454 185619 replica.cpp:712] Persisted action APPEND at position 2 I0710 02:57:16.956486 185622 replica.cpp:712] Persisted action APPEND at position 2 I0710 02:57:16.958235 185633 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3 I0710 02:57:16.959720 185632 replica.cpp:541] Replica received write request for position 3 from __req_res__(1000)@172.17.0.2:39989 I0710 02:57:16.959887 185624 replica.cpp:541] Replica received write request for position 3 from __req_res__(1001)@172.17.0.2:39989 I0710 02:57:17.087117 185624 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 127.173472ms I0710 02:57:17.087117 185632 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 127.304776ms I0710 02:57:17.087265 185624 replica.cpp:712] Persisted action APPEND at position 3 I0710 02:57:17.087306 185632 replica.cpp:712] Persisted action APPEND at position 3 I0710 02:57:17.088447 185619 replica.cpp:695] Replica received learned notice for position 3 from log-network(47)@172.17.0.2:39989 I0710 02:57:17.088490 185640 replica.cpp:695] Replica received learned notice for position 3 from log-network(47)@172.17.0.2:39989 I0710 02:57:17.166779 185619 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 78.278923ms I0710 02:57:17.166862 185619 replica.cpp:712] Persisted action APPEND at position 3 I0710 02:57:17.166859 185640 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 78.298673ms I0710 02:57:17.166965 185640 replica.cpp:712] Persisted action APPEND at position 3 I0710 02:57:17.168262 185638 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 4 I0710 02:57:17.169267 185623 replica.cpp:541] Replica received write request for position 4 from __req_res__(1002)@172.17.0.2:39989 I0710 02:57:17.169389 185635 replica.cpp:541] Replica received write request for position 4 from __req_res__(1003)@172.17.0.2:39989 I0710 02:57:17.272733 185623 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 103.417183ms I0710 02:57:17.272738 185635 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 103.309479ms I0710 02:57:17.272830 185623 replica.cpp:712] Persisted action APPEND at position 4 I0710 02:57:17.272871 185635 replica.cpp:712] Persisted action APPEND at position 4 I0710 02:57:17.273825 185622 replica.cpp:695] Replica received learned notice for position 4 from log-network(47)@172.17.0.2:39989 I0710 02:57:17.273873 185625 replica.cpp:695] Replica received learned notice for position 4 from log-network(47)@172.17.0.2:39989 I0710 02:57:17.352576 185625 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 78.656762ms I0710 02:57:17.352589 185622 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 78.721947ms I0710 02:57:17.352670 185625 replica.cpp:712] Persisted action APPEND at position 4 I0710 02:57:17.352730 185622 replica.cpp:712] Persisted action APPEND at position 4 I0710 02:57:17.353929 185639 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 5 I0710 02:57:17.355158 185635 replica.cpp:541] Replica received write request for position 5 from __req_res__(1004)@172.17.0.2:39989 I0710 02:57:17.355437 185621 replica.cpp:541] Replica received write request for position 5 from __req_res__(1005)@172.17.0.2:39989 I0710 02:57:17.458366 185621 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 102.866282ms I0710 02:57:17.458386 185635 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 103.129769ms I0710 02:57:17.458479 185621 replica.cpp:712] Persisted action APPEND at position 5 I0710 02:57:17.458523 185635 replica.cpp:712] Persisted action APPEND at position 5 I0710 02:57:17.459486 185631 replica.cpp:695] Replica received learned notice for position 5 from log-network(47)@172.17.0.2:39989 I0710 02:57:17.459532 185629 replica.cpp:695] Replica received learned notice for position 5 from log-network(47)@172.17.0.2:39989 I0710 02:57:17.527518 185629 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 67.937128ms I0710 02:57:17.527518 185631 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 67.999566ms I0710 02:57:17.527649 185629 replica.cpp:712] Persisted action APPEND at position 5 I0710 02:57:17.527709 185631 replica.cpp:712] Persisted action APPEND at position 5 I0710 02:57:17.529162 185639 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 6 I0710 02:57:17.530501 185622 replica.cpp:541] Replica received write request for position 6 from __req_res__(1006)@172.17.0.2:39989 I0710 02:57:17.530625 185628 replica.cpp:541] Replica received write request for position 6 from __req_res__(1007)@172.17.0.2:39989 I0710 02:57:17.652289 185628 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 121.618369ms I0710 02:57:17.652289 185622 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 121.718178ms I0710 02:57:17.652413 185628 replica.cpp:712] Persisted action APPEND at position 6 I0710 02:57:17.652452 185622 replica.cpp:712] Persisted action APPEND at position 6 I0710 02:57:17.653594 185638 replica.cpp:695] Replica received learned notice for position 6 from log-network(47)@172.17.0.2:39989 I0710 02:57:17.653599 185620 replica.cpp:695] Replica received learned notice for position 6 from log-network(47)@172.17.0.2:39989 I0710 02:57:17.720855 185620 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 67.154228ms I0710 02:57:17.720872 185638 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 67.225366ms I0710 02:57:17.720950 185620 replica.cpp:712] Persisted action APPEND at position 6 I0710 02:57:17.721014 185638 replica.cpp:712] Persisted action APPEND at position 6 I0710 02:57:17.722378 185627 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 7 I0710 02:57:17.723668 185625 replica.cpp:541] Replica received write request for position 7 from __req_res__(1008)@172.17.0.2:39989 I0710 02:57:17.723912 185629 replica.cpp:541] Replica received write request for position 7 from __req_res__(1009)@172.17.0.2:39989 I0710 02:57:17.837618 185625 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 113.885159ms I0710 02:57:17.837657 185629 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 113.672424ms I0710 02:57:17.837723 185625 replica.cpp:712] Persisted action APPEND at position 7 I0710 02:57:17.837765 185629 replica.cpp:712] Persisted action APPEND at position 7 I0710 02:57:17.838737 185630 replica.cpp:695] Replica received learned notice for position 7 from log-network(47)@172.17.0.2:39989 I0710 02:57:17.838754 185618 replica.cpp:695] Replica received learned notice for position 7 from log-network(47)@172.17.0.2:39989 I0710 02:57:17.919232 185618 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 80.404654ms I0710 02:57:17.919260 185630 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 80.478307ms I0710 02:57:17.919327 185618 replica.cpp:712] Persisted action APPEND at position 7 I0710 02:57:17.919361 185630 replica.cpp:712] Persisted action APPEND at position 7 I0710 02:57:17.920720 185627 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 8 I0710 02:57:17.921905 185629 replica.cpp:541] Replica received write request for position 8 from __req_res__(1010)@172.17.0.2:39989 I0710 02:57:17.922127 185620 replica.cpp:541] Replica received write request for position 8 from __req_res__(1011)@172.17.0.2:39989 I0710 02:57:18.031680 185629 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 109.718663ms I0710 02:57:18.031680 185620 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 109.497578ms I0710 02:57:18.031821 185629 replica.cpp:712] Persisted action APPEND at position 8 I0710 02:57:18.031867 185620 replica.cpp:712] Persisted action APPEND at position 8 I0710 02:57:18.033026 185640 replica.cpp:695] Replica received learned notice for position 8 from log-network(47)@172.17.0.2:39989 I0710 02:57:18.033078 185617 replica.cpp:695] Replica received learned notice for position 8 from log-network(47)@172.17.0.2:39989 I0710 02:57:18.107391 185640 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 74.266848ms I0710 02:57:18.107391 185617 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 74.232315ms I0710 02:57:18.107522 185640 replica.cpp:712] Persisted action APPEND at position 8 I0710 02:57:18.107551 185617 replica.cpp:712] Persisted action APPEND at position 8 I0710 02:57:18.109087 185628 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 9 I0710 02:57:18.110340 185637 replica.cpp:541] Replica received write request for position 9 from __req_res__(1012)@172.17.0.2:39989 I0710 02:57:18.110512 185618 replica.cpp:541] Replica received write request for position 9 from __req_res__(1013)@172.17.0.2:39989 I0710 02:57:18.191689 185637 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 81.259827ms I0710 02:57:18.191689 185618 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 81.116557ms I0710 02:57:18.191789 185637 replica.cpp:712] Persisted action APPEND at position 9 I0710 02:57:18.191834 185618 replica.cpp:712] Persisted action APPEND at position 9 I0710 02:57:18.192867 185622 replica.cpp:695] Replica received learned notice for position 9 from log-network(47)@172.17.0.2:39989 I0710 02:57:18.192869 185621 replica.cpp:695] Replica received learned notice for position 9 from log-network(47)@172.17.0.2:39989 I0710 02:57:18.260900 185621 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 67.941017ms I0710 02:57:18.260913 185622 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 67.995099ms I0710 02:57:18.261003 185621 replica.cpp:712] Persisted action APPEND at position 9 I0710 02:57:18.261072 185622 replica.cpp:712] Persisted action APPEND at position 9 I0710 02:57:18.262418 185638 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 10 I0710 02:57:18.263514 185630 replica.cpp:541] Replica received write request for position 10 from __req_res__(1014)@172.17.0.2:39989 I0710 02:57:18.263554 185639 replica.cpp:541] Replica received write request for position 10 from __req_res__(1015)@172.17.0.2:39989 I0710 02:57:18.351768 185630 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 88.209768ms I0710 02:57:18.351788 185639 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 88.201495ms I0710 02:57:18.351876 185630 replica.cpp:712] Persisted action APPEND at position 10 I0710 02:57:18.351934 185639 replica.cpp:712] Persisted action APPEND at position 10 I0710 02:57:18.352946 185633 replica.cpp:695] Replica received learned notice for position 10 from log-network(47)@172.17.0.2:39989 I0710 02:57:18.352949 185627 replica.cpp:695] Replica received learned notice for position 10 from log-network(47)@172.17.0.2:39989 I0710 02:57:18.427491 185633 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 74.489963ms I0710 02:57:18.427507 185627 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 74.44928ms I0710 02:57:18.427585 185633 replica.cpp:712] Persisted action APPEND at position 10 I0710 02:57:18.427628 185627 replica.cpp:712] Persisted action APPEND at position 10 I0710 02:57:18.681658 185616 leveldb.cpp:217] Opened db in 252.936968ms I0710 02:57:18.900331 185616 leveldb.cpp:224] Compacted db in 218.613892ms I0710 02:57:18.900485 185616 leveldb.cpp:239] Created db iterator in 58561ns I0710 02:57:18.900548 185616 leveldb.cpp:245] Seeked to beginning of db in 40803ns I0710 02:57:18.900637 185616 leveldb.cpp:320] Iterated through 1 keys in the db in 75363ns I0710 02:57:18.900723 185616 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0710 02:57:18.902184 185622 recover.cpp:437] Starting replica recovery I0710 02:57:18.902890 185622 recover.cpp:468] Replica is in VOTING status I0710 02:57:18.903313 185622 recover.cpp:447] Recover process terminated I0710 02:57:18.904129 185627 catchup.cpp:342] Starting missing positions recovery I0710 02:57:18.904605 185631 catchup.cpp:368] Replica is in VOTING status I0710 02:57:18.906589 185626 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(1016)@172.17.0.2:39989 I0710 02:57:18.906821 185618 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(1017)@172.17.0.2:39989 I0710 02:57:18.906945 185617 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(1018)@172.17.0.2:39989 I0710 02:57:18.908156 185635 recover.cpp:197] Received a recover response from a replica in VOTING status I0710 02:57:18.908767 185635 recover.cpp:197] Received a recover response from a replica in VOTING status I0710 02:57:18.910153 185635 catchup.cpp:423] Starting catch-up from position 0 to 9 I0710 02:57:18.912477 185620 replica.cpp:391] Replica received explicit promise request from __req_res__(1019)@172.17.0.2:39989 for position 0 with proposal 0 I0710 02:57:18.912654 185620 leveldb.cpp:510] Reading position from leveldb took 115407ns I0710 02:57:18.912637 185630 replica.cpp:391] Replica received explicit promise request from __req_res__(1020)@172.17.0.2:39989 for position 0 with proposal 0 I0710 02:57:18.912814 185640 replica.cpp:391] Replica received explicit promise request from __req_res__(1021)@172.17.0.2:39989 for position 0 with proposal 0 I0710 02:57:18.912859 185630 leveldb.cpp:510] Reading position from leveldb took 104351ns I0710 02:57:19.087327 185626 replica.cpp:391] Replica received explicit promise request from __req_res__(1022)@172.17.0.2:39989 for position 0 with proposal 3 I0710 02:57:19.087507 185626 leveldb.cpp:510] Reading position from leveldb took 109311ns I0710 02:57:19.087500 185617 replica.cpp:391] Replica received explicit promise request from __req_res__(1023)@172.17.0.2:39989 for position 0 with proposal 3 I0710 02:57:19.087666 185640 replica.cpp:391] Replica received explicit promise request from __req_res__(1024)@172.17.0.2:39989 for position 0 with proposal 3 I0710 02:57:19.087774 185617 leveldb.cpp:510] Reading position from leveldb took 156140ns I0710 02:57:19.145138 185626 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 57.558057ms I0710 02:57:19.145140 185617 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 57.256803ms I0710 02:57:19.145242 185626 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:19.145299 185617 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:19.146203 185620 replica.cpp:695] Replica received learned notice for position 0 from log-network(48)@172.17.0.2:39989 I0710 02:57:19.146199 185639 replica.cpp:695] Replica received learned notice for position 0 from log-network(48)@172.17.0.2:39989 I0710 02:57:19.182927 185640 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 95.190089ms I0710 02:57:19.183012 185640 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:19.183257 185640 replica.cpp:695] Replica received learned notice for position 0 from log-network(48)@172.17.0.2:39989 I0710 02:57:19.220515 185639 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 74.201745ms I0710 02:57:19.220548 185620 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 74.289727ms I0710 02:57:19.220605 185639 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:19.220633 185620 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:19.258694 185640 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 75.400851ms I0710 02:57:19.258777 185640 replica.cpp:712] Persisted action NOP at position 0 I0710 02:57:19.261117 185621 replica.cpp:391] Replica received explicit promise request from __req_res__(1025)@172.17.0.2:39989 for position 1 with proposal 3 I0710 02:57:19.261267 185630 replica.cpp:391] Replica received explicit promise request from __req_res__(1026)@172.17.0.2:39989 for position 1 with proposal 3 I0710 02:57:19.261320 185621 leveldb.cpp:510] Reading position from leveldb took 125524ns I0710 02:57:19.261447 185630 leveldb.cpp:510] Reading position from leveldb took 102615ns I0710 02:57:19.261452 185638 replica.cpp:391] Replica received explicit promise request from __req_res__(1027)@172.17.0.2:39989 for position 1 with proposal 3 I0710 02:57:19.338240 185638 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 76.697227ms I0710 02:57:19.338280 185621 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 76.871643ms I0710 02:57:19.338347 185638 replica.cpp:712] Persisted action NOP at position 1 I0710 02:57:19.338280 185630 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 76.734822ms I0710 02:57:19.338398 185621 replica.cpp:712] Persisted action APPEND at position 1 I0710 02:57:19.338459 185630 replica.cpp:712] Persisted action APPEND at position 1 I0710 02:57:19.339380 185636 replica.cpp:695] Replica received learned notice for position 1 from log-network(48)@172.17.0.2:39989 I0710 02:57:19.339457 185627 replica.cpp:695] Replica received learned notice for position 1 from log-network(48)@172.17.0.2:39989 I0710 02:57:19.339486 185617 replica.cpp:695] Replica received learned notice for position 1 from log-network(48)@172.17.0.2:39989 I0710 02:57:19.425406 185636 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 85.977874ms I0710 02:57:19.425410 185617 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 85.877186ms I0710 02:57:19.425426 185627 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 85.923038ms I0710 02:57:19.425573 185617 replica.cpp:712] Persisted action APPEND at position 1 I0710 02:57:19.425621 185627 replica.cpp:712] Persisted action APPEND at position 1 I0710 02:57:19.425503 185636 replica.cpp:712] Persisted action APPEND at position 1 I0710 02:57:19.427654 185618 replica.cpp:391] Replica received explicit promise request from __req_res__(1028)@172.17.0.2:39989 for position 2 with proposal 3 I0710 02:57:19.427806 185618 leveldb.cpp:510] Reading position from leveldb took 90948ns I0710 02:57:19.427845 185639 replica.cpp:391] Replica received explicit promise request from __req_res__(1029)@172.17.0.2:39989 for position 2 with proposal 3 I0710 02:57:19.428004 185639 leveldb.cpp:510] Reading position from leveldb took 101711ns I0710 02:57:19.428002 185637 replica.cpp:391] Replica received explicit promise request from __req_res__(1030)@172.17.0.2:39989 for position 2 with proposal 3 I0710 02:57:19.497565 185639 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 69.479936ms I0710 02:57:19.497592 185637 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 69.495059ms I0710 02:57:19.497660 185639 replica.cpp:712] Persisted action APPEND at position 2 I0710 02:57:19.497586 185618 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 69.714141ms I0710 02:57:19.497706 185637 replica.cpp:712] Persisted action NOP at position 2 I0710 02:57:19.497785 185618 replica.cpp:712] Persisted action APPEND at position 2 I0710 02:57:19.498603 185637 replica.cpp:695] Replica received learned notice for position 2 from log-network(48)@172.17.0.2:39989 I0710 02:57:19.498674 185619 replica.cpp:695] Replica received learned notice for position 2 from log-network(48)@172.17.0.2:39989 I0710 02:57:19.498711 185629 replica.cpp:695] Replica received learned notice for position 2 from log-network(48)@172.17.0.2:39989 I0710 02:57:19.589867 185619 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 91.136975ms I0710 02:57:19.589876 185629 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 91.106726ms I0710 02:57:19.589964 185619 replica.cpp:712] Persisted action APPEND at position 2 I0710 02:57:19.589879 185637 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 91.234583ms I0710 02:57:19.590011 185629 replica.cpp:712] Persisted action APPEND at position 2 I0710 02:57:19.590080 185637 replica.cpp:712] Persisted action APPEND at position 2 I0710 02:57:19.592229 185624 replica.cpp:391] Replica received explicit promise request from __req_res__(1031)@172.17.0.2:39989 for position 3 with proposal 3 I0710 02:57:19.592389 185624 leveldb.cpp:510] Reading position from leveldb took 97265ns I0710 02:57:19.592412 185631 replica.cpp:391] Replica received explicit promise request from __req_res__(1032)@172.17.0.2:39989 for position 3 with proposal 3 I0710 02:57:19.592533 185618 replica.cpp:391] Replica received explicit promise request from __req_res__(1033)@172.17.0.2:39989 for position 3 with proposal 3 I0710 02:57:19.592581 185631 leveldb.cpp:510] Reading position from leveldb took 101724ns I0710 02:57:19.657440 185624 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 64.966424ms I0710 02:57:19.657442 185618 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 64.852096ms I0710 02:57:19.657536 185624 replica.cpp:712] Persisted action APPEND at position 3 I0710 02:57:19.657454 185631 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 64.80782ms I0710 02:57:19.657584 185618 replica.cpp:712] Persisted action NOP at position 3 I0710 02:57:19.657640 185631 replica.cpp:712] Persisted action APPEND at position 3 I0710 02:57:19.658413 185635 replica.cpp:695] Replica received learned notice for position 3 from log-network(48)@172.17.0.2:39989 I0710 02:57:19.658449 185620 replica.cpp:695] Replica received learned notice for position 3 from log-network(48)@172.17.0.2:39989 I0710 02:57:19.658453 185640 replica.cpp:695] Replica received learned notice for position 3 from log-network(48)@172.17.0.2:39989 I0710 02:57:19.733765 185635 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 75.310336ms I0710 02:57:19.733767 185640 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 75.215805ms I0710 02:57:19.733862 185635 replica.cpp:712] Persisted action APPEND at position 3 I0710 02:57:19.733768 185620 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 75.27488ms I0710 02:57:19.733919 185640 replica.cpp:712] Persisted action APPEND at position 3 I0710 02:57:19.733963 185620 replica.cpp:712] Persisted action APPEND at position 3 I0710 02:57:19.736100 185618 replica.cpp:391] Replica received explicit promise request from __req_res__(1034)@172.17.0.2:39989 for position 4 with proposal 3 I0710 02:57:19.736258 185618 leveldb.cpp:510] Reading position from leveldb took 92728ns I0710 02:57:19.736253 185621 replica.cpp:391] Replica received explicit promise request from __req_res__(1035)@172.17.0.2:39989 for position 4 with proposal 3 I0710 02:57:19.736429 185622 replica.cpp:391] Replica received explicit promise request from __req_res__(1036)@172.17.0.2:39989 for position 4 with proposal 3 I0710 02:57:19.736442 185621 leveldb.cpp:510] Reading position from leveldb took 92245ns I0710 02:57:19.816946 185621 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 80.381622ms I0710 02:57:19.816948 185622 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 80.455031ms I0710 02:57:19.817040 185621 replica.cpp:712] Persisted action APPEND at position 4 I0710 02:57:19.816952 185618 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 80.623814ms I0710 02:57:19.817087 185622 replica.cpp:712] Persisted action NOP at position 4 I0710 02:57:19.817147 185618 replica.cpp:712] Persisted action APPEND at position 4 I0710 02:57:19.818004 185634 replica.cpp:695] Replica received learned notice for position 4 from log-network(48)@172.17.0.2:39989 I0710 02:57:19.818038 185617 replica.cpp:695] Replica received learned notice for position 4 from log-network(48)@172.17.0.2:39989 I0710 02:57:19.818073 185636 replica.cpp:695] Replica received learned notice for position 4 from log-network(48)@172.17.0.2:39989 I0710 02:57:19.892066 185636 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 73.947924ms I0710 02:57:19.892071 185634 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 74.029969ms I0710 02:57:19.892163 185636 replica.cpp:712] Persisted action APPEND at position 4 I0710 02:57:19.892067 185617 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 73.989414ms I0710 02:57:19.892211 185634 replica.cpp:712] Persisted action APPEND at position 4 I0710 02:57:19.892256 185617 replica.cpp:712] Persisted action APPEND at position 4 I0710 02:57:19.894150 185635 replica.cpp:391] Replica received explicit promise request from __req_res__(1037)@172.17.0.2:39989 for position 5 with proposal 3 I0710 02:57:19.894243 185628 replica.cpp:391] Replica received explicit promise request from __req_res__(1038)@172.17.0.2:39989 for position 5 with proposal 3 I0710 02:57:19.894300 185635 leveldb.cpp:510] Reading position from leveldb took 89244ns I0710 02:57:19.894425 185628 leveldb.cpp:510] Reading position from leveldb took 114388ns I0710 02:57:19.894490 185640 replica.cpp:391] Replica received explicit promise request from __req_res__(1039)@172.17.0.2:39989 for position 5 with proposal 3 I0710 02:57:19.993139 185635 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 98.779588ms I0710 02:57:19.993152 185640 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 98.599831ms I0710 02:57:19.993261 185635 replica.cpp:712] Persisted action APPEND at position 5 I0710 02:57:19.993299 185640 replica.cpp:712] Persisted action NOP at position 5 I0710 02:57:19.993156 185628 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 98.629164ms I0710 02:57:19.993410 185628 replica.cpp:712] Persisted action APPEND at position 5 I0710 02:57:19.994185 185625 replica.cpp:695] Replica received learned notice for position 5 from log-network(48)@172.17.0.2:39989 I0710 02:57:19.994210 185634 replica.cpp:695] Replica received learned notice for position 5 from log-network(48)@172.17.0.2:39989 I0710 02:57:19.994261 185621 replica.cpp:695] Replica received learned notice for position 5 from log-network(48)@172.17.0.2:39989 I0710 02:57:20.083760 185621 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 89.467797ms I0710 02:57:20.083760 185634 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 89.49563ms I0710 02:57:20.083882 185621 replica.cpp:712] Persisted action APPEND at position 5 I0710 02:57:20.083935 185634 replica.cpp:712] Persisted action APPEND at position 5 I0710 02:57:20.083765 185625 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 89.613308ms I0710 02:57:20.084278 185625 replica.cpp:712] Persisted action APPEND at position 5 I0710 02:57:20.086006 185623 replica.cpp:391] Replica received explicit promise request from __req_res__(1040)@172.17.0.2:39989 for position 6 with proposal 3 I0710 02:57:20.086149 185632 replica.cpp:391] Replica received explicit promise request from __req_res__(1041)@172.17.0.2:39989 for position 6 with proposal 3 I0710 02:57:20.086175 185623 leveldb.cpp:510] Reading position from leveldb took 100565ns I0710 02:57:20.086310 185632 leveldb.cpp:510] Reading position from leveldb took 95698ns I0710 02:57:20.086321 185627 replica.cpp:391] Replica received explicit promise request from __req_res__(1042)@172.17.0.2:39989 for position 6 with proposal 3 I0710 02:57:20.161140 185627 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 74.750485ms I0710 02:57:20.161195 185627 replica.cpp:712] Persisted action NOP at position 6 I0710 02:57:20.161185 185632 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 74.805174ms I0710 02:57:20.161142 185623 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 74.834241ms I0710 02:57:20.161280 185632 replica.cpp:712] Persisted action APPEND at position 6 I0710 02:57:20.161315 185623 replica.cpp:712] Persisted action APPEND at position 6 I0710 02:57:20.162246 185629 replica.cpp:695] Replica received learned notice for position 6 from log-network(48)@172.17.0.2:39989 I0710 02:57:20.162290 185639 replica.cpp:695] Replica received learned notice for position 6 from log-network(48)@172.17.0.2:39989 I0710 02:57:20.162338 185626 replica.cpp:695] Replica received learned notice for position 6 from log-network(48)@172.17.0.2:39989 I0710 02:57:20.250389 185639 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 88.06059ms I0710 02:57:20.250406 185629 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 88.118839ms I0710 02:57:20.250437 185626 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 88.05257ms I0710 02:57:20.250504 185639 replica.cpp:712] Persisted action APPEND at position 6 I0710 02:57:20.250550 185629 replica.cpp:712] Persisted action APPEND at position 6 I0710 02:57:20.250614 185626 replica.cpp:712] Persisted action APPEND at position 6 I0710 02:57:20.252856 185621 replica.cpp:391] Replica received explicit promise request from __req_res__(1043)@172.17.0.2:39989 for position 7 with proposal 3 I0710 02:57:20.253039 185621 leveldb.cpp:510] Reading position from leveldb took 114364ns I0710 02:57:20.253068 185635 replica.cpp:391] Replica received explicit promise request from __req_res__(1044)@172.17.0.2:39989 for position 7 with proposal 3 I0710 02:57:20.253217 185635 leveldb.cpp:510] Reading position from leveldb took 89072ns I0710 02:57:20.253369 185634 replica.cpp:391] Replica received explicit promise request from __req_res__(1045)@172.17.0.2:39989 for position 7 with proposal 3 I0710 02:57:20.337316 185635 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 84.034156ms I0710 02:57:20.337332 185634 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 83.907145ms I0710 02:57:20.337332 185621 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 84.189023ms I0710 02:57:20.337410 185635 replica.cpp:712] Persisted action APPEND at position 7 I0710 02:57:20.337468 185634 replica.cpp:712] Persisted action NOP at position 7 I0710 02:57:20.337513 185621 replica.cpp:712] Persisted action APPEND at position 7 I0710 02:57:20.338470 185617 replica.cpp:695] Replica received learned notice for position 7 from log-network(48)@172.17.0.2:39989 I0710 02:57:20.338508 185632 replica.cpp:695] Replica received learned notice for position 7 from log-network(48)@172.17.0.2:39989 I0710 02:57:20.338546 185623 replica.cpp:695] Replica received learned notice for position 7 from log-network(48)@172.17.0.2:39989 I0710 02:57:20.425374 185617 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 86.857442ms I0710 02:57:20.425410 185623 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 86.819209ms I0710 02:57:20.425464 185617 replica.cpp:712] Persisted action APPEND at position 7 I0710 02:57:20.425503 185623 replica.cpp:712] Persisted action APPEND at position 7 I0710 02:57:20.425379 185632 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 86.827483ms I0710 02:57:20.425647 185632 replica.cpp:712] Persisted action APPEND at position 7 I0710 02:57:20.427490 185626 replica.cpp:391] Replica received explicit promise request from __req_res__(1046)@172.17.0.2:39989 for position 8 with proposal 3 I0710 02:57:20.427604 185639 replica.cpp:391] Replica received explicit promise request from __req_res__(1047)@172.17.0.2:39989 for position 8 with proposal 3 I0710 02:57:20.427635 185626 leveldb.cpp:510] Reading position from leveldb took 91222ns I0710 02:57:20.427753 185639 leveldb.cpp:510] Reading position from leveldb took 88248ns I0710 02:57:20.427848 185619 replica.cpp:391] Replica received explicit promise request from __req_res__(1048)@172.17.0.2:39989 for position 8 with proposal 3 I0710 02:57:20.513523 185626 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 85.75091ms I0710 02:57:20.513530 185639 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 85.716007ms I0710 02:57:20.513553 185619 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 85.634225ms I0710 02:57:20.513682 185639 replica.cpp:712] Persisted action APPEND at position 8 I0710 02:57:20.513620 185626 replica.cpp:712] Persisted action APPEND at position 8 I0710 02:57:20.513728 185619 replica.cpp:712] Persisted action NOP at position 8 I0710 02:57:20.514532 185624 replica.cpp:695] Replica received learned notice for position 8 from log-network(48)@172.17.0.2:39989 I0710 02:57:20.514667 185632 replica.cpp:695] Replica received learned notice for position 8 from log-network(48)@172.17.0.2:39989 I0710 02:57:20.514668 185628 replica.cpp:695] Replica received learned notice for position 8 from log-network(48)@172.17.0.2:39989 I0710 02:57:20.600415 185624 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 85.836287ms I0710 02:57:20.600420 185632 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 85.670763ms I0710 02:57:20.600512 185624 replica.cpp:712] Persisted action APPEND at position 8 I0710 02:57:20.600426 185628 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 85.579445ms I0710 02:57:20.600562 185632 replica.cpp:712] Persisted action APPEND at position 8 I0710 02:57:20.600608 185628 replica.cpp:712] Persisted action APPEND at position 8 I0710 02:57:20.602701 185633 replica.cpp:391] Replica received explicit promise request from __req_res__(1049)@172.17.0.2:39989 for position 9 with proposal 3 I0710 02:57:20.602818 185640 replica.cpp:391] Replica received explicit promise request from __req_res__(1050)@172.17.0.2:39989 for position 9 with proposal 3 I0710 02:57:20.602854 185633 leveldb.cpp:510] Reading position from leveldb took 91655ns I0710 02:57:20.602974 185640 leveldb.cpp:510] Reading position from leveldb took 91878ns I0710 02:57:20.603036 185635 replica.cpp:391] Replica received explicit promise request from __req_res__(1051)@172.17.0.2:39989 for position 9 with proposal 3 I0710 02:57:20.689580 185640 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 86.511883ms I0710 02:57:20.689625 185633 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 86.671213ms I0710 02:57:20.689671 185640 replica.cpp:712] Persisted action APPEND at position 9 I0710 02:57:20.689628 185635 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 86.520626ms I0710 02:57:20.689719 185633 replica.cpp:712] Persisted action APPEND at position 9 I0710 02:57:20.689771 185635 replica.cpp:712] Persisted action NOP at position 9 I0710 02:57:20.690591 185640 replica.cpp:695] Replica received learned notice for position 9 from log-network(48)@172.17.0.2:39989 I0710 02:57:20.690603 185620 replica.cpp:695] Replica received learned notice for position 9 from log-network(48)@172.17.0.2:39989 I0710 02:57:20.690640 185627 replica.cpp:695] Replica received learned notice for position 9 from log-network(48)@172.17.0.2:39989 I0710 02:57:20.775383 185627 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 84.655338ms I0710 02:57:20.775386 185640 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 84.75216ms I0710 02:57:20.775408 185620 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 84.72328ms I0710 02:57:20.775530 185640 replica.cpp:712] Persisted action APPEND at position 9 I0710 02:57:20.775476 185627 replica.cpp:712] Persisted action APPEND at position 9 I0710 02:57:20.775578 185620 replica.cpp:712] Persisted action APPEND at position 9 I0710 02:57:20.776644 185621 catchup.cpp:357] Recover process terminated I0710 02:57:20.779484 185619 leveldb.cpp:510] Reading position from leveldb took 100148ns I0710 02:57:20.779662 185619 leveldb.cpp:510] Reading position from leveldb took 77075ns I0710 02:57:20.779807 185619 leveldb.cpp:510] Reading position from leveldb took 70265ns I0710 02:57:20.780009 185619 leveldb.cpp:510] Reading position from leveldb took 111327ns I0710 02:57:20.780191 185619 leveldb.cpp:510] Reading position from leveldb took 82272ns I0710 02:57:20.780385 185619 leveldb.cpp:510] Reading position from leveldb took 84308ns I0710 02:57:20.780588 185619 leveldb.cpp:510] Reading position from leveldb took 98951ns I0710 02:57:20.780768 185619 leveldb.cpp:510] Reading position from leveldb took 88121ns I0710 02:57:20.780957 185619 leveldb.cpp:510] Reading position from leveldb took 87972ns I0710 02:57:20.781144 185619 leveldb.cpp:510] Reading position from leveldb took 87962ns [ OK ] LogTest.ReaderCatchup (7059 ms) [----------] 4 tests from LogTest (11776 ms total) [----------] 2 tests from LogZooKeeperTest I0710 02:57:20.789276 185616 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 I0710 02:57:20.890748 185616 jvm.cpp:590] Looking up method <init>(Ljava/lang/String;)V I0710 02:57:20.891139 185616 jvm.cpp:590] Looking up method deleteOnExit()V I0710 02:57:20.892158 185616 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. I0710 02:57:21.034785 185616 jvm.cpp:590] Looking up method <init>()V I0710 02:57:21.036851 185616 jvm.cpp:590] Looking up method <init>(Lorg/apache/zookeeper/server/persistence/FileTxnSnapLog;Lorg/apache/zookeeper/server/ZooKeeperServer$DataTreeBuilder;)V *** Aborted at 1720580241 (unix time) try "date -d @1720580241" if you are using GNU date *** PC: @ 0x7faca8f20ccd OopStorage::Block::release_entries() *** SIGSEGV (@0x238) received by PID 185616 (TID 0x7facb7744b40) from PID 568; stack trace: *** @ 0x7faca8f2f929 os::Linux::chained_handler() @ 0x7faca8f3563b JVM_handle_linux_signal @ 0x7faca8f281dc signalHandler() @ 0x7facb8d97420 (unknown) @ 0x7faca8f20ccd OopStorage::Block::release_entries() @ 0x7faca8f20f26 OopStorage::release() @ 0x7faca8c23b21 jni_DeleteGlobalRef @ 0x7facc85591c4 JNIEnv_::DeleteGlobalRef() @ 0x7facc855730c Jvm::deleteGlobalRef() @ 0x555b5a55a628 Jvm::Object::~Object() @ 0x555b5a55f44e org::apache::zookeeper::server::ZooKeeperServer::DataTreeBuilder::~DataTreeBuilder() @ 0x555b5a561d52 org::apache::zookeeper::server::ZooKeeperServer::BasicDataTreeBuilder::~BasicDataTreeBuilder() @ 0x555b5a55dd6d mesos::internal::tests::ZooKeeperTestServer::ZooKeeperTestServer() @ 0x555b58f02fcc mesos::internal::tests::ZooKeeperTest::ZooKeeperTest() @ 0x555b58f05315 mesos::internal::tests::LogZooKeeperTest::LogZooKeeperTest() @ 0x555b58f05426 mesos::internal::tests::LogZooKeeperTest_WriteRead_Test::LogZooKeeperTest_WriteRead_Test() @ 0x555b58f70328 testing::internal::TestFactoryImpl<>::CreateTest() @ 0x555b5a5a45fa testing::internal::HandleSehExceptionsInMethodIfSupported<>() @ 0x555b5a59dbcb testing::internal::HandleExceptionsInMethodIfSupported<>() @ 0x555b5a579e03 testing::TestInfo::Run() @ 0x555b5a57a50b testing::TestCase::Run() @ 0x555b5a5818a5 testing::internal::UnitTestImpl::RunAllTests() @ 0x555b5a5a5828 testing::internal::HandleSehExceptionsInMethodIfSupported<>() @ 0x555b5a59e731 testing::internal::HandleExceptionsInMethodIfSupported<>() @ 0x555b5a5803bd testing::UnitTest::Run() @ 0x555b58f8dedb RUN_ALL_TESTS() @ 0x555b58f8d8a2 main @ 0x7facb8bb5083 __libc_start_main @ 0x555b57fd375e _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 I0710 02:57:25.347417 186662 exec.cpp:560] Agent exited ... shutting down I0710 02:57:25.348320 186664 executor.cpp:190] Received SHUTDOWN event I0710 02:57:25.348421 186664 executor.cpp:843] Shutting down I0710 02:57:25.348547 186664 executor.cpp:956] Sending SIGTERM to process tree at pid 186669 I0710 02:57:25.373580 186664 executor.cpp:969] Sent SIGTERM to the following process trees: [ -+- 186669 sh -c dd if=/dev/zero of=volume_path/file bs=1048576 count=2 && sleep 1000 \--- 186677 sleep 1000 ] I0710 02:57:25.373651 186664 executor.cpp:973] Scheduling escalation to SIGKILL in 3secs from now make[3]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub/src' make[2]: *** [Makefile:15954: check] Error 2 make[2]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub/src' 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 ';' I0710 02:57:25.395821 186648 executor.cpp:1041] Command terminated with signal Terminated (pid: 186669) W0710 02:57:25.397915 186666 process.cpp:1917] Failed to send 'mesos.internal.StatusUpdateMessage' to '172.17.0.2:39989', connect: Failed to connect to 172.17.0.2:39989: Connection refused I0710 02:57:26.399538 186666 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/33434/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 > d60215ec1c722efced2d5c59b9f99cb67d1abbbe > src/slave/containerizer/mesos/isolators/cgroups2/cgroups2.cpp > 2ca3880790be0cd092ec05a359711e2d8e641314 > src/slave/main.cpp 21b8ea74a502478fb73510a7d49bb5f28506ce8d > > > Diff: https://reviews.apache.org/r/75016/diff/4/ > > > Testing > ------- > > > Thanks, > > Jason Zhou > >
