----------------------------------------------------------- This is an automatically generated e-mail. To reply, visit: https://reviews.apache.org/r/75081/#review226655 -----------------------------------------------------------
Bad patch! Reviews applied: [75081] 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_75081"] Error: ...<truncated>... g action (18 bytes) to leveldb took 40.805251ms I0711 02:51:10.369835 185124 leveldb.cpp:460] Deleting ~5 keys from leveldb took 41.678616ms I0711 02:51:10.369874 185113 leveldb.cpp:460] Deleting ~5 keys from leveldb took 41.672752ms I0711 02:51:10.607851 185113 leveldb.cpp:527] Compacting range 0-4 took 237.924584ms I0711 02:51:10.607856 185124 leveldb.cpp:527] Compacting range 0-4 took 237.959454ms I0711 02:51:10.607944 185113 replica.cpp:712] Persisted action TRUNCATE at position 11 I0711 02:51:10.607983 185124 replica.cpp:712] Persisted action TRUNCATE at position 11 I0711 02:51:10.706566 185100 leveldb.cpp:217] Opened db in 97.430731ms I0711 02:51:10.791908 185100 leveldb.cpp:224] Compacted db in 85.296293ms I0711 02:51:10.792032 185100 leveldb.cpp:239] Created db iterator in 58549ns I0711 02:51:10.792099 185100 leveldb.cpp:245] Seeked to beginning of db in 42993ns I0711 02:51:10.792186 185100 leveldb.cpp:320] Iterated through 1 keys in the db in 64066ns I0711 02:51:10.792270 185100 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0711 02:51:10.793299 185117 catchup.cpp:342] Starting missing positions recovery I0711 02:51:10.793867 185120 catchup.cpp:368] Replica is in VOTING status I0711 02:51:10.795835 185118 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(920)@172.17.0.2:39617 I0711 02:51:10.796044 185124 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(921)@172.17.0.2:39617 I0711 02:51:10.797286 185122 recover.cpp:197] Received a recover response from a replica in VOTING status I0711 02:51:10.797907 185122 recover.cpp:197] Received a recover response from a replica in VOTING status I0711 02:51:10.800045 185117 catchup.cpp:423] Starting catch-up from position 0 to 10 I0711 02:51:10.802515 185114 replica.cpp:391] Replica received explicit promise request from __req_res__(923)@172.17.0.2:39617 for position 0 with proposal 0 I0711 02:51:10.802680 185118 replica.cpp:391] Replica received explicit promise request from __req_res__(924)@172.17.0.2:39617 for position 0 with proposal 0 I0711 02:51:10.802959 185110 replica.cpp:391] Replica received explicit promise request from __req_res__(925)@172.17.0.2:39617 for position 0 with proposal 0 I0711 02:51:10.803663 185116 replica.cpp:695] Replica received learned notice for position 0 from log-network(42)@172.17.0.2:39617 I0711 02:51:10.803690 185117 replica.cpp:695] Replica received learned notice for position 0 from log-network(42)@172.17.0.2:39617 I0711 02:51:10.803778 185104 replica.cpp:695] Replica received learned notice for position 0 from log-network(42)@172.17.0.2:39617 I0711 02:51:10.848601 185116 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 44.884963ms I0711 02:51:10.848706 185116 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:10.865296 185117 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 61.493144ms I0711 02:51:10.865309 185104 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 61.467381ms I0711 02:51:10.865394 185117 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:10.865438 185104 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:10.867738 185120 replica.cpp:391] Replica received explicit promise request from __req_res__(926)@172.17.0.2:39617 for position 1 with proposal 0 I0711 02:51:10.868299 185107 replica.cpp:391] Replica received explicit promise request from __req_res__(927)@172.17.0.2:39617 for position 1 with proposal 0 I0711 02:51:10.868352 185102 replica.cpp:391] Replica received explicit promise request from __req_res__(928)@172.17.0.2:39617 for position 1 with proposal 0 I0711 02:51:10.868873 185102 replica.cpp:695] Replica received learned notice for position 1 from log-network(42)@172.17.0.2:39617 I0711 02:51:10.869017 185112 replica.cpp:695] Replica received learned notice for position 1 from log-network(42)@172.17.0.2:39617 I0711 02:51:10.869155 185118 replica.cpp:695] Replica received learned notice for position 1 from log-network(42)@172.17.0.2:39617 I0711 02:51:10.947154 185102 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 78.243756ms I0711 02:51:10.947268 185112 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 78.223873ms I0711 02:51:10.947402 185118 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 78.18646ms I0711 02:51:10.999013 185102 leveldb.cpp:460] Deleting ~1 keys from leveldb took 51.768724ms I0711 02:51:10.999013 185118 leveldb.cpp:460] Deleting ~1 keys from leveldb took 51.552479ms I0711 02:51:10.999078 185112 leveldb.cpp:460] Deleting ~1 keys from leveldb took 51.704083ms I0711 02:51:11.274411 185118 leveldb.cpp:527] Compacting range 0-0 took 275.295483ms I0711 02:51:11.274530 185118 replica.cpp:712] Persisted action NOP at position 1 I0711 02:51:11.277838 185101 replica.cpp:391] Replica received explicit promise request from __req_res__(931)@172.17.0.2:39617 for position 2 with proposal 0 I0711 02:51:11.332710 185102 leveldb.cpp:527] Compacting range 0-0 took 333.635332ms I0711 02:51:11.332813 185102 replica.cpp:712] Persisted action NOP at position 1 I0711 02:51:11.332801 185112 leveldb.cpp:527] Compacting range 0-0 took 333.585752ms I0711 02:51:11.332928 185112 replica.cpp:712] Persisted action NOP at position 1 I0711 02:51:11.332971 185102 replica.cpp:391] Replica received explicit promise request from __req_res__(929)@172.17.0.2:39617 for position 2 with proposal 0 I0711 02:51:11.333165 185112 replica.cpp:391] Replica received explicit promise request from __req_res__(930)@172.17.0.2:39617 for position 2 with proposal 0 I0711 02:51:11.527937 185113 replica.cpp:391] Replica received explicit promise request from __req_res__(932)@172.17.0.2:39617 for position 2 with proposal 1 I0711 02:51:11.528172 185119 replica.cpp:391] Replica received explicit promise request from __req_res__(933)@172.17.0.2:39617 for position 2 with proposal 1 I0711 02:51:11.528326 185101 replica.cpp:391] Replica received explicit promise request from __req_res__(934)@172.17.0.2:39617 for position 2 with proposal 1 I0711 02:51:11.529280 185115 replica.cpp:695] Replica received learned notice for position 2 from log-network(42)@172.17.0.2:39617 I0711 02:51:11.529294 185118 replica.cpp:695] Replica received learned notice for position 2 from log-network(42)@172.17.0.2:39617 I0711 02:51:11.585297 185101 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 56.912117ms I0711 02:51:11.585386 185101 replica.cpp:712] Persisted action NOP at position 2 I0711 02:51:11.585611 185101 replica.cpp:695] Replica received learned notice for position 2 from log-network(42)@172.17.0.2:39617 I0711 02:51:11.618678 185115 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 89.331026ms I0711 02:51:11.618690 185118 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 89.30862ms I0711 02:51:11.663770 185101 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 78.124362ms I0711 02:51:11.693935 185115 leveldb.cpp:460] Deleting ~1 keys from leveldb took 75.199498ms I0711 02:51:11.693961 185118 leveldb.cpp:460] Deleting ~1 keys from leveldb took 75.175448ms I0711 02:51:11.727404 185101 leveldb.cpp:460] Deleting ~1 keys from leveldb took 63.575943ms I0711 02:51:12.016028 185118 leveldb.cpp:527] Compacting range 1-1 took 321.982961ms I0711 02:51:12.016055 185115 leveldb.cpp:527] Compacting range 1-1 took 322.047632ms I0711 02:51:12.016127 185118 replica.cpp:712] Persisted action NOP at position 2 I0711 02:51:12.016168 185115 replica.cpp:712] Persisted action NOP at position 2 I0711 02:51:12.075287 185101 leveldb.cpp:527] Compacting range 1-1 took 347.818462ms I0711 02:51:12.075373 185101 replica.cpp:712] Persisted action NOP at position 2 I0711 02:51:12.077877 185105 replica.cpp:391] Replica received explicit promise request from __req_res__(935)@172.17.0.2:39617 for position 3 with proposal 1 I0711 02:51:12.077942 185107 replica.cpp:391] Replica received explicit promise request from __req_res__(936)@172.17.0.2:39617 for position 3 with proposal 1 I0711 02:51:12.078163 185124 replica.cpp:391] Replica received explicit promise request from __req_res__(937)@172.17.0.2:39617 for position 3 with proposal 1 I0711 02:51:12.079082 185122 replica.cpp:695] Replica received learned notice for position 3 from log-network(42)@172.17.0.2:39617 I0711 02:51:12.079164 185114 replica.cpp:695] Replica received learned notice for position 3 from log-network(42)@172.17.0.2:39617 I0711 02:51:12.126804 185124 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 48.565907ms I0711 02:51:12.126888 185124 replica.cpp:712] Persisted action NOP at position 3 I0711 02:51:12.127110 185124 replica.cpp:695] Replica received learned notice for position 3 from log-network(42)@172.17.0.2:39617 I0711 02:51:12.155791 185114 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 76.556409ms I0711 02:51:12.155812 185122 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 76.678089ms I0711 02:51:12.365696 185124 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 238.553514ms I0711 02:51:12.397686 185114 leveldb.cpp:460] Deleting ~1 keys from leveldb took 241.829319ms I0711 02:51:12.397703 185122 leveldb.cpp:460] Deleting ~1 keys from leveldb took 241.781104ms I0711 02:51:12.422808 185124 leveldb.cpp:460] Deleting ~1 keys from leveldb took 57.05543ms I0711 02:51:12.724642 185122 leveldb.cpp:527] Compacting range 2-2 took 326.822142ms I0711 02:51:12.724627 185114 leveldb.cpp:527] Compacting range 2-2 took 326.880078ms I0711 02:51:12.724805 185114 replica.cpp:712] Persisted action NOP at position 3 I0711 02:51:12.724781 185122 replica.cpp:712] Persisted action NOP at position 3 I0711 02:51:12.783491 185124 leveldb.cpp:527] Compacting range 2-2 took 360.624606ms I0711 02:51:12.783574 185124 replica.cpp:712] Persisted action NOP at position 3 I0711 02:51:12.786389 185119 replica.cpp:391] Replica received explicit promise request from __req_res__(938)@172.17.0.2:39617 for position 4 with proposal 1 I0711 02:51:12.786554 185103 replica.cpp:391] Replica received explicit promise request from __req_res__(939)@172.17.0.2:39617 for position 4 with proposal 1 I0711 02:51:12.786689 185104 replica.cpp:391] Replica received explicit promise request from __req_res__(940)@172.17.0.2:39617 for position 4 with proposal 1 I0711 02:51:12.787642 185124 replica.cpp:695] Replica received learned notice for position 4 from log-network(42)@172.17.0.2:39617 I0711 02:51:12.787684 185105 replica.cpp:695] Replica received learned notice for position 4 from log-network(42)@172.17.0.2:39617 I0711 02:51:12.817451 185104 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 30.705693ms I0711 02:51:12.817538 185104 replica.cpp:712] Persisted action NOP at position 4 I0711 02:51:12.817762 185104 replica.cpp:695] Replica received learned notice for position 4 from log-network(42)@172.17.0.2:39617 I0711 02:51:12.842584 185105 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 54.857864ms I0711 02:51:12.842584 185124 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 54.90766ms I0711 02:51:12.867727 185104 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 49.931438ms I0711 02:51:12.892839 185124 leveldb.cpp:460] Deleting ~1 keys from leveldb took 50.145256ms I0711 02:51:12.892843 185105 leveldb.cpp:460] Deleting ~1 keys from leveldb took 50.193946ms I0711 02:51:12.920557 185104 leveldb.cpp:460] Deleting ~1 keys from leveldb took 52.770113ms I0711 02:51:13.182543 185124 leveldb.cpp:527] Compacting range 3-3 took 289.641333ms I0711 02:51:13.182544 185105 leveldb.cpp:527] Compacting range 3-3 took 289.602644ms I0711 02:51:13.182634 185124 replica.cpp:712] Persisted action NOP at position 4 I0711 02:51:13.182696 185105 replica.cpp:712] Persisted action NOP at position 4 I0711 02:51:13.241734 185104 leveldb.cpp:527] Compacting range 3-3 took 321.119286ms I0711 02:51:13.241819 185104 replica.cpp:712] Persisted action NOP at position 4 I0711 02:51:13.244264 185106 replica.cpp:391] Replica received explicit promise request from __req_res__(941)@172.17.0.2:39617 for position 5 with proposal 1 I0711 02:51:13.244453 185106 leveldb.cpp:510] Reading position from leveldb took 127580ns I0711 02:51:13.244812 185114 replica.cpp:391] Replica received explicit promise request from __req_res__(942)@172.17.0.2:39617 for position 5 with proposal 1 I0711 02:51:13.244983 185114 leveldb.cpp:510] Reading position from leveldb took 115821ns I0711 02:51:13.245101 185121 replica.cpp:391] Replica received explicit promise request from __req_res__(943)@172.17.0.2:39617 for position 5 with proposal 1 I0711 02:51:13.279328 185121 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 34.172077ms I0711 02:51:13.279421 185121 replica.cpp:712] Persisted action NOP at position 5 I0711 02:51:13.370534 185123 replica.cpp:391] Replica received explicit promise request from __req_res__(944)@172.17.0.2:39617 for position 5 with proposal 2 I0711 02:51:13.370676 185101 replica.cpp:391] Replica received explicit promise request from __req_res__(945)@172.17.0.2:39617 for position 5 with proposal 2 I0711 02:51:13.370769 185123 leveldb.cpp:510] Reading position from leveldb took 166536ns I0711 02:51:13.370906 185101 leveldb.cpp:510] Reading position from leveldb took 158390ns I0711 02:51:13.370980 185110 replica.cpp:391] Replica received explicit promise request from __req_res__(946)@172.17.0.2:39617 for position 5 with proposal 2 I0711 02:51:13.371290 185110 leveldb.cpp:510] Reading position from leveldb took 176546ns I0711 02:51:13.412900 185123 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 42.040585ms I0711 02:51:13.412989 185123 replica.cpp:712] Persisted action APPEND at position 5 I0711 02:51:13.414278 185105 replica.cpp:695] Replica received learned notice for position 5 from log-network(42)@172.17.0.2:39617 I0711 02:51:13.445073 185101 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 74.06681ms I0711 02:51:13.445079 185110 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 73.693367ms I0711 02:51:13.445179 185101 replica.cpp:712] Persisted action APPEND at position 5 I0711 02:51:13.445214 185110 replica.cpp:712] Persisted action NOP at position 5 I0711 02:51:13.445464 185101 replica.cpp:695] Replica received learned notice for position 5 from log-network(42)@172.17.0.2:39617 I0711 02:51:13.445533 185110 replica.cpp:695] Replica received learned notice for position 5 from log-network(42)@172.17.0.2:39617 I0711 02:51:13.478367 185105 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 64.043742ms I0711 02:51:13.478457 185105 replica.cpp:712] Persisted action APPEND at position 5 I0711 02:51:13.496578 185101 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 51.063343ms I0711 02:51:13.496634 185101 replica.cpp:712] Persisted action APPEND at position 5 I0711 02:51:13.496618 185110 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 51.072814ms I0711 02:51:13.496722 185110 replica.cpp:712] Persisted action APPEND at position 5 I0711 02:51:13.499310 185104 replica.cpp:391] Replica received explicit promise request from __req_res__(947)@172.17.0.2:39617 for position 6 with proposal 2 I0711 02:51:13.499487 185104 leveldb.cpp:510] Reading position from leveldb took 118864ns I0711 02:51:13.499482 185108 replica.cpp:391] Replica received explicit promise request from __req_res__(948)@172.17.0.2:39617 for position 6 with proposal 2 I0711 02:51:13.499614 185121 replica.cpp:391] Replica received explicit promise request from __req_res__(949)@172.17.0.2:39617 for position 6 with proposal 2 I0711 02:51:13.499732 185108 leveldb.cpp:510] Reading position from leveldb took 159540ns I0711 02:51:13.530063 185104 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 30.503194ms I0711 02:51:13.530092 185121 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 30.412963ms I0711 02:51:13.530149 185104 replica.cpp:712] Persisted action APPEND at position 6 I0711 02:51:13.530098 185108 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 30.296295ms I0711 02:51:13.530195 185121 replica.cpp:712] Persisted action NOP at position 6 I0711 02:51:13.530251 185108 replica.cpp:712] Persisted action APPEND at position 6 I0711 02:51:13.531313 185118 replica.cpp:695] Replica received learned notice for position 6 from log-network(42)@172.17.0.2:39617 I0711 02:51:13.531410 185102 replica.cpp:695] Replica received learned notice for position 6 from log-network(42)@172.17.0.2:39617 I0711 02:51:13.531471 185117 replica.cpp:695] Replica received learned notice for position 6 from log-network(42)@172.17.0.2:39617 I0711 02:51:13.563551 185118 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 32.202348ms I0711 02:51:13.563544 185117 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 32.037918ms I0711 02:51:13.563645 185118 replica.cpp:712] Persisted action APPEND at position 6 I0711 02:51:13.563544 185102 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 32.078107ms I0711 02:51:13.563702 185117 replica.cpp:712] Persisted action APPEND at position 6 I0711 02:51:13.563733 185102 replica.cpp:712] Persisted action APPEND at position 6 I0711 02:51:13.566143 185107 replica.cpp:391] Replica received explicit promise request from __req_res__(950)@172.17.0.2:39617 for position 7 with proposal 2 I0711 02:51:13.566357 185107 leveldb.cpp:510] Reading position from leveldb took 160176ns I0711 02:51:13.566373 185103 replica.cpp:391] Replica received explicit promise request from __req_res__(951)@172.17.0.2:39617 for position 7 with proposal 2 I0711 02:51:13.566632 185103 leveldb.cpp:510] Reading position from leveldb took 162073ns I0711 02:51:13.566637 185109 replica.cpp:391] Replica received explicit promise request from __req_res__(952)@172.17.0.2:39617 for position 7 with proposal 2 I0711 02:51:13.605419 185109 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 38.687274ms I0711 02:51:13.605428 185107 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 38.962351ms I0711 02:51:13.605428 185103 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 38.700437ms I0711 02:51:13.605507 185109 replica.cpp:712] Persisted action NOP at position 7 I0711 02:51:13.605604 185103 replica.cpp:712] Persisted action APPEND at position 7 I0711 02:51:13.605567 185107 replica.cpp:712] Persisted action APPEND at position 7 I0711 02:51:13.606806 185116 replica.cpp:695] Replica received learned notice for position 7 from log-network(42)@172.17.0.2:39617 I0711 02:51:13.606858 185102 replica.cpp:695] Replica received learned notice for position 7 from log-network(42)@172.17.0.2:39617 I0711 02:51:13.606925 185117 replica.cpp:695] Replica received learned notice for position 7 from log-network(42)@172.17.0.2:39617 I0711 02:51:13.647229 185116 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.363774ms I0711 02:51:13.647236 185117 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.272703ms I0711 02:51:13.647236 185102 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.325499ms I0711 02:51:13.647320 185116 replica.cpp:712] Persisted action APPEND at position 7 I0711 02:51:13.647420 185102 replica.cpp:712] Persisted action APPEND at position 7 I0711 02:51:13.647384 185117 replica.cpp:712] Persisted action APPEND at position 7 I0711 02:51:13.649935 185110 replica.cpp:391] Replica received explicit promise request from __req_res__(953)@172.17.0.2:39617 for position 8 with proposal 2 I0711 02:51:13.649998 185124 replica.cpp:391] Replica received explicit promise request from __req_res__(954)@172.17.0.2:39617 for position 8 with proposal 2 I0711 02:51:13.650175 185110 leveldb.cpp:510] Reading position from leveldb took 158862ns I0711 02:51:13.650171 185124 leveldb.cpp:510] Reading position from leveldb took 119044ns I0711 02:51:13.650168 185112 replica.cpp:391] Replica received explicit promise request from __req_res__(955)@172.17.0.2:39617 for position 8 with proposal 2 I0711 02:51:13.689028 185124 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 38.752566ms I0711 02:51:13.689054 185110 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 38.826766ms I0711 02:51:13.689038 185112 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 38.740793ms I0711 02:51:13.689183 185110 replica.cpp:712] Persisted action APPEND at position 8 I0711 02:51:13.689121 185124 replica.cpp:712] Persisted action APPEND at position 8 I0711 02:51:13.689230 185112 replica.cpp:712] Persisted action NOP at position 8 I0711 02:51:13.690323 185117 replica.cpp:695] Replica received learned notice for position 8 from log-network(42)@172.17.0.2:39617 I0711 02:51:13.690374 185105 replica.cpp:695] Replica received learned notice for position 8 from log-network(42)@172.17.0.2:39617 I0711 02:51:13.690465 185115 replica.cpp:695] Replica received learned notice for position 8 from log-network(42)@172.17.0.2:39617 I0711 02:51:13.730837 185117 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.469945ms I0711 02:51:13.730839 185105 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.423856ms I0711 02:51:13.730932 185117 replica.cpp:712] Persisted action APPEND at position 8 I0711 02:51:13.730880 185115 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.397191ms I0711 02:51:13.730983 185105 replica.cpp:712] Persisted action APPEND at position 8 I0711 02:51:13.731066 185115 replica.cpp:712] Persisted action APPEND at position 8 I0711 02:51:13.733553 185111 replica.cpp:391] Replica received explicit promise request from __req_res__(956)@172.17.0.2:39617 for position 9 with proposal 2 I0711 02:51:13.733628 185114 replica.cpp:391] Replica received explicit promise request from __req_res__(957)@172.17.0.2:39617 for position 9 with proposal 2 I0711 02:51:13.733779 185111 leveldb.cpp:510] Reading position from leveldb took 154503ns I0711 02:51:13.733800 185114 leveldb.cpp:510] Reading position from leveldb took 117861ns I0711 02:51:13.733893 185107 replica.cpp:391] Replica received explicit promise request from __req_res__(958)@172.17.0.2:39617 for position 9 with proposal 2 I0711 02:51:13.772619 185111 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 38.755093ms I0711 02:51:13.772622 185107 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 38.679124ms I0711 02:51:13.772711 185111 replica.cpp:712] Persisted action APPEND at position 9 I0711 02:51:13.772624 185114 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 38.727753ms I0711 02:51:13.772758 185107 replica.cpp:712] Persisted action NOP at position 9 I0711 02:51:13.772806 185114 replica.cpp:712] Persisted action APPEND at position 9 I0711 02:51:13.773911 185115 replica.cpp:695] Replica received learned notice for position 9 from log-network(42)@172.17.0.2:39617 I0711 02:51:13.773926 185106 replica.cpp:695] Replica received learned notice for position 9 from log-network(42)@172.17.0.2:39617 I0711 02:51:13.773939 185110 replica.cpp:695] Replica received learned notice for position 9 from log-network(42)@172.17.0.2:39617 I0711 02:51:13.814451 185106 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.439919ms I0711 02:51:13.814476 185110 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.454579ms I0711 02:51:13.814476 185115 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.521019ms I0711 02:51:13.814539 185106 replica.cpp:712] Persisted action APPEND at position 9 I0711 02:51:13.814605 185110 replica.cpp:712] Persisted action APPEND at position 9 I0711 02:51:13.814622 185115 replica.cpp:712] Persisted action APPEND at position 9 I0711 02:51:13.816978 185107 replica.cpp:391] Replica received explicit promise request from __req_res__(959)@172.17.0.2:39617 for position 10 with proposal 2 I0711 02:51:13.817201 185107 leveldb.cpp:510] Reading position from leveldb took 154223ns I0711 02:51:13.817227 185109 replica.cpp:391] Replica received explicit promise request from __req_res__(960)@172.17.0.2:39617 for position 10 with proposal 2 I0711 02:51:13.817422 185109 leveldb.cpp:510] Reading position from leveldb took 132367ns I0711 02:51:13.817416 185103 replica.cpp:391] Replica received explicit promise request from __req_res__(961)@172.17.0.2:39617 for position 10 with proposal 2 I0711 02:51:13.856257 185103 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 38.747056ms I0711 02:51:13.856257 185107 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 38.971751ms I0711 02:51:13.856257 185109 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 38.759966ms I0711 02:51:13.856408 185107 replica.cpp:712] Persisted action APPEND at position 10 I0711 02:51:13.856351 185103 replica.cpp:712] Persisted action NOP at position 10 I0711 02:51:13.856469 185109 replica.cpp:712] Persisted action APPEND at position 10 I0711 02:51:13.857591 185119 replica.cpp:695] Replica received learned notice for position 10 from log-network(42)@172.17.0.2:39617 I0711 02:51:13.857636 185104 replica.cpp:695] Replica received learned notice for position 10 from log-network(42)@172.17.0.2:39617 I0711 02:51:13.857731 185102 replica.cpp:695] Replica received learned notice for position 10 from log-network(42)@172.17.0.2:39617 I0711 02:51:13.898038 185104 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 40.360935ms I0711 02:51:13.898038 185102 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 40.281906ms I0711 02:51:13.898145 185104 replica.cpp:712] Persisted action APPEND at position 10 I0711 02:51:13.898038 185119 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 40.426643ms I0711 02:51:13.898188 185102 replica.cpp:712] Persisted action APPEND at position 10 I0711 02:51:13.898252 185119 replica.cpp:712] Persisted action APPEND at position 10 I0711 02:51:13.899065 185123 catchup.cpp:357] Recover process terminated I0711 02:51:13.900712 185115 leveldb.cpp:510] Reading position from leveldb took 155065ns I0711 02:51:13.900894 185115 leveldb.cpp:510] Reading position from leveldb took 54182ns I0711 02:51:13.901002 185115 leveldb.cpp:510] Reading position from leveldb took 50915ns I0711 02:51:13.901104 185115 leveldb.cpp:510] Reading position from leveldb took 49824ns I0711 02:51:13.901211 185115 leveldb.cpp:510] Reading position from leveldb took 50786ns I0711 02:51:13.901335 185115 leveldb.cpp:510] Reading position from leveldb took 59601ns [ OK ] RecoverTest.CatchupVotingWithGap (5683 ms) [ RUN ] RecoverTest.CatchupVotingOnePosition I0711 02:51:14.016404 185100 leveldb.cpp:217] Opened db in 108.256004ms I0711 02:51:14.041343 185100 leveldb.cpp:224] Compacted db in 24.896592ms I0711 02:51:14.041465 185100 leveldb.cpp:239] Created db iterator in 54108ns I0711 02:51:14.041507 185100 leveldb.cpp:245] Seeked to beginning of db in 13223ns I0711 02:51:14.041535 185100 leveldb.cpp:320] Iterated through 0 keys in the db in 10244ns I0711 02:51:14.041610 185100 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0711 02:51:14.066526 185110 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 24.302425ms I0711 02:51:14.066665 185110 replica.cpp:322] Persisted replica status to VOTING I0711 02:51:14.159505 185100 leveldb.cpp:217] Opened db in 91.697222ms I0711 02:51:14.183157 185100 leveldb.cpp:224] Compacted db in 23.605766ms I0711 02:51:14.183285 185100 leveldb.cpp:239] Created db iterator in 40886ns I0711 02:51:14.183331 185100 leveldb.cpp:245] Seeked to beginning of db in 12409ns I0711 02:51:14.183358 185100 leveldb.cpp:320] Iterated through 0 keys in the db in 9840ns I0711 02:51:14.183418 185100 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0711 02:51:14.217876 185121 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 33.948987ms I0711 02:51:14.217958 185121 replica.cpp:322] Persisted replica status to VOTING I0711 02:51:14.311074 185100 leveldb.cpp:217] Opened db in 92.23705ms I0711 02:51:14.333232 185100 leveldb.cpp:224] Compacted db in 22.110815ms I0711 02:51:14.333335 185100 leveldb.cpp:239] Created db iterator in 39163ns I0711 02:51:14.333376 185100 leveldb.cpp:245] Seeked to beginning of db in 12473ns I0711 02:51:14.333402 185100 leveldb.cpp:320] Iterated through 0 keys in the db in 9676ns I0711 02:51:14.333461 185100 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0711 02:51:14.369422 185118 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 35.493499ms I0711 02:51:14.369506 185118 replica.cpp:322] Persisted replica status to VOTING I0711 02:51:14.462535 185100 leveldb.cpp:217] Opened db in 92.085103ms I0711 02:51:14.541446 185100 leveldb.cpp:224] Compacted db in 78.857978ms I0711 02:51:14.541517 185100 leveldb.cpp:239] Created db iterator in 37231ns I0711 02:51:14.541566 185100 leveldb.cpp:245] Seeked to beginning of db in 27405ns I0711 02:51:14.541646 185100 leveldb.cpp:320] Iterated through 1 keys in the db in 73650ns I0711 02:51:14.541743 185100 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0711 02:51:14.664191 185100 leveldb.cpp:217] Opened db in 122.106644ms I0711 02:51:14.750130 185100 leveldb.cpp:224] Compacted db in 85.892053ms I0711 02:51:14.750252 185100 leveldb.cpp:239] Created db iterator in 62916ns I0711 02:51:14.750341 185100 leveldb.cpp:245] Seeked to beginning of db in 56992ns I0711 02:51:14.750442 185100 leveldb.cpp:320] Iterated through 1 keys in the db in 69819ns I0711 02:51:14.750532 185100 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0711 02:51:14.865907 185100 leveldb.cpp:217] Opened db in 115.026377ms I0711 02:51:14.958513 185100 leveldb.cpp:224] Compacted db in 92.519556ms I0711 02:51:14.958653 185100 leveldb.cpp:239] Created db iterator in 73288ns I0711 02:51:14.958745 185100 leveldb.cpp:245] Seeked to beginning of db in 61766ns I0711 02:51:14.958863 185100 leveldb.cpp:320] Iterated through 1 keys in the db in 92931ns I0711 02:51:14.958985 185100 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0711 02:51:14.959993 185124 catchup.cpp:342] Starting missing positions recovery I0711 02:51:14.960556 185106 catchup.cpp:368] Replica is in VOTING status I0711 02:51:14.962409 185118 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(962)@172.17.0.2:39617 I0711 02:51:14.962597 185111 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(963)@172.17.0.2:39617 I0711 02:51:14.962944 185114 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(964)@172.17.0.2:39617 I0711 02:51:14.963886 185111 recover.cpp:197] Received a recover response from a replica in VOTING status I0711 02:51:14.964485 185111 recover.cpp:197] Received a recover response from a replica in VOTING status I0711 02:51:14.965790 185103 catchup.cpp:357] Recover process terminated [ OK ] RecoverTest.CatchupVotingOnePosition (1063 ms) [----------] 9 tests from RecoverTest (41793 ms total) [----------] 4 tests from LogTest [ RUN ] LogTest.WriteRead I0711 02:51:15.092280 185100 leveldb.cpp:217] Opened db in 120.793719ms I0711 02:51:15.125072 185100 leveldb.cpp:224] Compacted db in 32.743842ms I0711 02:51:15.125178 185100 leveldb.cpp:239] Created db iterator in 41399ns I0711 02:51:15.125217 185100 leveldb.cpp:245] Seeked to beginning of db in 12217ns I0711 02:51:15.125244 185100 leveldb.cpp:320] Iterated through 0 keys in the db in 9837ns I0711 02:51:15.125304 185100 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0711 02:51:15.150655 185109 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 24.838973ms I0711 02:51:15.150738 185109 replica.cpp:322] Persisted replica status to VOTING I0711 02:51:15.276847 185100 leveldb.cpp:217] Opened db in 125.236736ms I0711 02:51:15.316690 185100 leveldb.cpp:224] Compacted db in 39.79583ms I0711 02:51:15.316793 185100 leveldb.cpp:239] Created db iterator in 39766ns I0711 02:51:15.316839 185100 leveldb.cpp:245] Seeked to beginning of db in 12617ns I0711 02:51:15.316866 185100 leveldb.cpp:320] Iterated through 0 keys in the db in 9710ns I0711 02:51:15.316928 185100 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0711 02:51:15.344045 185102 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 26.641028ms I0711 02:51:15.344128 185102 replica.cpp:322] Persisted replica status to VOTING I0711 02:51:15.461999 185100 leveldb.cpp:217] Opened db in 116.855324ms I0711 02:51:15.550225 185100 leveldb.cpp:224] Compacted db in 88.197205ms I0711 02:51:15.550336 185100 leveldb.cpp:239] Created db iterator in 47579ns I0711 02:51:15.550406 185100 leveldb.cpp:245] Seeked to beginning of db in 43493ns I0711 02:51:15.550486 185100 leveldb.cpp:320] Iterated through 1 keys in the db in 59462ns I0711 02:51:15.550560 185100 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0711 02:51:15.663460 185100 leveldb.cpp:217] Opened db in 112.532787ms I0711 02:51:15.774894 185100 leveldb.cpp:224] Compacted db in 111.391116ms I0711 02:51:15.774966 185100 leveldb.cpp:239] Created db iterator in 33420ns I0711 02:51:15.775007 185100 leveldb.cpp:245] Seeked to beginning of db in 25207ns I0711 02:51:15.775063 185100 leveldb.cpp:320] Iterated through 1 keys in the db in 44252ns I0711 02:51:15.775118 185100 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0711 02:51:15.776080 185116 recover.cpp:437] Starting replica recovery I0711 02:51:15.776625 185116 recover.cpp:468] Replica is in VOTING status I0711 02:51:15.776989 185116 recover.cpp:447] Recover process terminated I0711 02:51:15.777694 185105 log.cpp:554] Attempting to start the writer I0711 02:51:15.780043 185108 replica.cpp:497] Replica received implicit promise request from __req_res__(965)@172.17.0.2:39617 with proposal 1 I0711 02:51:15.780169 185123 replica.cpp:497] Replica received implicit promise request from __req_res__(966)@172.17.0.2:39617 with proposal 1 I0711 02:51:15.822424 185108 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 42.325505ms I0711 02:51:15.822512 185108 replica.cpp:344] Persisted promised to 1 I0711 02:51:15.839345 185123 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 59.106983ms I0711 02:51:15.839427 185123 replica.cpp:344] Persisted promised to 1 I0711 02:51:15.840590 185120 coordinator.cpp:238] Coordinator attempting to fill missing positions I0711 02:51:15.842658 185121 replica.cpp:391] Replica received explicit promise request from __req_res__(967)@172.17.0.2:39617 for position 0 with proposal 2 I0711 02:51:15.842909 185106 replica.cpp:391] Replica received explicit promise request from __req_res__(968)@172.17.0.2:39617 for position 0 with proposal 2 I0711 02:51:15.880985 185121 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 38.255229ms I0711 02:51:15.880986 185106 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 38.006379ms I0711 02:51:15.881076 185121 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:15.881117 185106 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:15.882719 185118 replica.cpp:541] Replica received write request for position 0 from __req_res__(969)@172.17.0.2:39617 I0711 02:51:15.882858 185118 leveldb.cpp:510] Reading position from leveldb took 78105ns I0711 02:51:15.882849 185105 replica.cpp:541] Replica received write request for position 0 from __req_res__(970)@172.17.0.2:39617 I0711 02:51:15.883042 185105 leveldb.cpp:510] Reading position from leveldb took 94722ns I0711 02:51:15.922801 185105 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 39.673523ms I0711 02:51:15.922803 185118 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 39.876205ms I0711 02:51:15.922891 185105 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:15.922937 185118 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:15.923884 185106 replica.cpp:695] Replica received learned notice for position 0 from log-network(44)@172.17.0.2:39617 I0711 02:51:15.923918 185109 replica.cpp:695] Replica received learned notice for position 0 from log-network(44)@172.17.0.2:39617 I0711 02:51:15.964599 185109 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 40.628461ms I0711 02:51:15.964599 185106 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 40.67485ms I0711 02:51:15.964705 185109 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:15.964740 185106 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:15.965720 185123 log.cpp:570] Writer started with ending position 0 I0711 02:51:15.966789 185117 log.cpp:578] Attempting to append 11 bytes to the log I0711 02:51:15.967161 185112 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 I0711 02:51:15.968397 185101 replica.cpp:541] Replica received write request for position 1 from __req_res__(971)@172.17.0.2:39617 I0711 02:51:15.968616 185122 replica.cpp:541] Replica received write request for position 1 from __req_res__(972)@172.17.0.2:39617 I0711 02:51:16.006415 185101 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 37.952509ms I0711 02:51:16.006521 185101 replica.cpp:712] Persisted action APPEND at position 1 I0711 02:51:16.073343 185122 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 104.653942ms I0711 02:51:16.073516 185122 replica.cpp:712] Persisted action APPEND at position 1 I0711 02:51:16.074757 185113 replica.cpp:695] Replica received learned notice for position 1 from log-network(44)@172.17.0.2:39617 I0711 02:51:16.074755 185118 replica.cpp:695] Replica received learned notice for position 1 from log-network(44)@172.17.0.2:39617 I0711 02:51:16.115119 185118 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 40.243974ms I0711 02:51:16.115123 185113 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 40.303516ms I0711 02:51:16.115238 185118 replica.cpp:712] Persisted action APPEND at position 1 I0711 02:51:16.115306 185113 replica.cpp:712] Persisted action APPEND at position 1 I0711 02:51:16.117692 185111 leveldb.cpp:510] Reading position from leveldb took 108471ns [ OK ] LogTest.WriteRead (1153 ms) [ RUN ] LogTest.Position I0711 02:51:16.241760 185100 leveldb.cpp:217] Opened db in 117.811667ms I0711 02:51:16.274978 185100 leveldb.cpp:224] Compacted db in 33.171553ms I0711 02:51:16.275089 185100 leveldb.cpp:239] Created db iterator in 46766ns I0711 02:51:16.275130 185100 leveldb.cpp:245] Seeked to beginning of db in 12593ns I0711 02:51:16.275158 185100 leveldb.cpp:320] Iterated through 0 keys in the db in 10203ns I0711 02:51:16.275260 185100 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0711 02:51:16.308421 185107 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 32.569416ms I0711 02:51:16.308504 185107 replica.cpp:322] Persisted replica status to VOTING I0711 02:51:16.434760 185100 leveldb.cpp:217] Opened db in 125.417889ms I0711 02:51:16.466907 185100 leveldb.cpp:224] Compacted db in 32.111056ms I0711 02:51:16.467069 185100 leveldb.cpp:239] Created db iterator in 59052ns I0711 02:51:16.467113 185100 leveldb.cpp:245] Seeked to beginning of db in 14546ns I0711 02:51:16.467140 185100 leveldb.cpp:320] Iterated through 0 keys in the db in 10373ns I0711 02:51:16.467257 185100 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0711 02:51:16.501531 185115 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 33.51742ms I0711 02:51:16.501580 185115 replica.cpp:322] Persisted replica status to VOTING I0711 02:51:16.620008 185100 leveldb.cpp:217] Opened db in 117.85581ms I0711 02:51:16.708557 185100 leveldb.cpp:224] Compacted db in 88.503007ms I0711 02:51:16.708667 185100 leveldb.cpp:239] Created db iterator in 47768ns I0711 02:51:16.708738 185100 leveldb.cpp:245] Seeked to beginning of db in 43636ns I0711 02:51:16.708827 185100 leveldb.cpp:320] Iterated through 1 keys in the db in 66942ns I0711 02:51:16.708899 185100 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0711 02:51:16.821413 185100 leveldb.cpp:217] Opened db in 112.155186ms I0711 02:51:16.908561 185100 leveldb.cpp:224] Compacted db in 87.103277ms I0711 02:51:16.908670 185100 leveldb.cpp:239] Created db iterator in 46423ns I0711 02:51:16.908746 185100 leveldb.cpp:245] Seeked to beginning of db in 42176ns I0711 02:51:16.908820 185100 leveldb.cpp:320] Iterated through 1 keys in the db in 54002ns I0711 02:51:16.908893 185100 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0711 02:51:16.909927 185123 recover.cpp:437] Starting replica recovery I0711 02:51:16.910359 185123 recover.cpp:468] Replica is in VOTING status I0711 02:51:16.910701 185123 recover.cpp:447] Recover process terminated I0711 02:51:16.911397 185113 log.cpp:554] Attempting to start the writer I0711 02:51:16.914486 185111 replica.cpp:497] Replica received implicit promise request from __req_res__(973)@172.17.0.2:39617 with proposal 1 I0711 02:51:16.914620 185109 replica.cpp:497] Replica received implicit promise request from __req_res__(974)@172.17.0.2:39617 with proposal 1 I0711 02:51:16.955099 185111 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 40.557617ms I0711 02:51:16.955181 185111 replica.cpp:344] Persisted promised to 1 I0711 02:51:16.971817 185109 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 57.135915ms I0711 02:51:16.971908 185109 replica.cpp:344] Persisted promised to 1 I0711 02:51:16.973217 185107 coordinator.cpp:238] Coordinator attempting to fill missing positions I0711 02:51:16.975380 185102 replica.cpp:391] Replica received explicit promise request from __req_res__(975)@172.17.0.2:39617 for position 0 with proposal 2 I0711 02:51:16.975558 185101 replica.cpp:391] Replica received explicit promise request from __req_res__(976)@172.17.0.2:39617 for position 0 with proposal 2 I0711 02:51:17.013659 185102 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 38.208045ms I0711 02:51:17.013659 185101 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 38.039674ms I0711 02:51:17.013751 185102 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:17.013794 185101 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:17.015542 185123 replica.cpp:541] Replica received write request for position 0 from __req_res__(977)@172.17.0.2:39617 I0711 02:51:17.015652 185113 replica.cpp:541] Replica received write request for position 0 from __req_res__(978)@172.17.0.2:39617 I0711 02:51:17.015705 185123 leveldb.cpp:510] Reading position from leveldb took 94291ns I0711 02:51:17.015785 185113 leveldb.cpp:510] Reading position from leveldb took 74058ns I0711 02:51:17.055441 185123 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 39.653986ms I0711 02:51:17.055444 185113 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 39.60029ms I0711 02:51:17.055532 185123 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:17.055593 185113 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:17.056361 185104 replica.cpp:695] Replica received learned notice for position 0 from log-network(45)@172.17.0.2:39617 I0711 02:51:17.056408 185111 replica.cpp:695] Replica received learned notice for position 0 from log-network(45)@172.17.0.2:39617 I0711 02:51:17.097201 185104 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 40.800465ms I0711 02:51:17.097201 185111 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 40.746769ms I0711 02:51:17.097293 185104 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:17.097337 185111 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:17.098194 185107 log.cpp:570] Writer started with ending position 0 I0711 02:51:17.099151 185103 log.cpp:578] Attempting to append 11 bytes to the log I0711 02:51:17.099519 185120 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 I0711 02:51:17.100699 185105 replica.cpp:541] Replica received write request for position 1 from __req_res__(979)@172.17.0.2:39617 I0711 02:51:17.100834 185104 replica.cpp:541] Replica received write request for position 1 from __req_res__(980)@172.17.0.2:39617 I0711 02:51:17.139071 185104 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 38.170725ms I0711 02:51:17.139073 185105 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 38.298235ms I0711 02:51:17.139163 185104 replica.cpp:712] Persisted action APPEND at position 1 I0711 02:51:17.139264 185105 replica.cpp:712] Persisted action APPEND at position 1 I0711 02:51:17.140209 185121 replica.cpp:695] Replica received learned notice for position 1 from log-network(45)@172.17.0.2:39617 I0711 02:51:17.140313 185118 replica.cpp:695] Replica received learned notice for position 1 from log-network(45)@172.17.0.2:39617 I0711 02:51:17.180884 185121 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 40.631238ms I0711 02:51:17.180884 185118 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 40.530844ms I0711 02:51:17.180977 185121 replica.cpp:712] Persisted action APPEND at position 1 I0711 02:51:17.181022 185118 replica.cpp:712] Persisted action APPEND at position 1 [ OK ] LogTest.Position (1063 ms) [ RUN ] LogTest.Metrics I0711 02:51:17.307487 185100 leveldb.cpp:217] Opened db in 120.519951ms I0711 02:51:17.333484 185100 leveldb.cpp:224] Compacted db in 25.948409ms I0711 02:51:17.333592 185100 leveldb.cpp:239] Created db iterator in 42619ns I0711 02:51:17.333631 185100 leveldb.cpp:245] Seeked to beginning of db in 12710ns I0711 02:51:17.333659 185100 leveldb.cpp:320] Iterated through 0 keys in the db in 9906ns I0711 02:51:17.333722 185100 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0711 02:51:17.365823 185106 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 31.576257ms I0711 02:51:17.365906 185106 replica.cpp:322] Persisted replica status to VOTING I0711 02:51:17.483963 185100 leveldb.cpp:217] Opened db in 117.135381ms I0711 02:51:17.760033 185100 leveldb.cpp:224] Compacted db in 276.024641ms I0711 02:51:17.760146 185100 leveldb.cpp:239] Created db iterator in 48639ns I0711 02:51:17.760214 185100 leveldb.cpp:245] Seeked to beginning of db in 42712ns I0711 02:51:17.760295 185100 leveldb.cpp:320] Iterated through 1 keys in the db in 60242ns I0711 02:51:17.760370 185100 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0711 02:51:17.761333 185124 recover.cpp:437] Starting replica recovery I0711 02:51:17.761801 185124 recover.cpp:468] Replica is in VOTING status I0711 02:51:17.762110 185124 recover.cpp:447] Recover process terminated I0711 02:51:17.762738 185124 log.cpp:554] Attempting to start the writer I0711 02:51:17.765105 185113 replica.cpp:497] Replica received implicit promise request from __req_res__(981)@172.17.0.2:39617 with proposal 1 I0711 02:51:17.792857 185113 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 27.669375ms I0711 02:51:17.792939 185113 replica.cpp:344] Persisted promised to 1 I0711 02:51:17.794106 185119 coordinator.cpp:238] Coordinator attempting to fill missing positions I0711 02:51:17.796304 185120 replica.cpp:391] Replica received explicit promise request from __req_res__(982)@172.17.0.2:39617 for position 0 with proposal 2 I0711 02:51:17.818099 185120 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 21.725344ms I0711 02:51:17.818185 185120 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:17.820101 185117 replica.cpp:541] Replica received write request for position 0 from __req_res__(983)@172.17.0.2:39617 I0711 02:51:17.820313 185117 leveldb.cpp:510] Reading position from leveldb took 112735ns I0711 02:51:17.843297 185117 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 22.905163ms I0711 02:51:17.843434 185117 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:17.844358 185101 replica.cpp:695] Replica received learned notice for position 0 from log-network(46)@172.17.0.2:39617 I0711 02:51:17.868373 185101 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 23.964492ms I0711 02:51:17.868459 185101 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:17.869284 185109 log.cpp:570] Writer started with ending position 0 I0711 02:51:17.874938 185111 process.cpp:3671] Handling HTTP event for process 'metrics' with path: '/metrics/snapshot' [ OK ] LogTest.Metrics (700 ms) [ RUN ] LogTest.ReaderCatchup I0711 02:51:18.053736 185100 leveldb.cpp:217] Opened db in 166.284839ms I0711 02:51:18.083758 185100 leveldb.cpp:224] Compacted db in 29.967369ms I0711 02:51:18.083873 185100 leveldb.cpp:239] Created db iterator in 50493ns I0711 02:51:18.083912 185100 leveldb.cpp:245] Seeked to beginning of db in 12753ns I0711 02:51:18.083940 185100 leveldb.cpp:320] Iterated through 0 keys in the db in 10153ns I0711 02:51:18.084013 185100 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0711 02:51:18.112109 185105 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 27.488866ms I0711 02:51:18.112160 185105 replica.cpp:322] Persisted replica status to VOTING I0711 02:51:18.230249 185100 leveldb.cpp:217] Opened db in 117.486699ms I0711 02:51:18.258433 185100 leveldb.cpp:224] Compacted db in 28.118244ms I0711 02:51:18.258534 185100 leveldb.cpp:239] Created db iterator in 44123ns I0711 02:51:18.258570 185100 leveldb.cpp:245] Seeked to beginning of db in 12095ns I0711 02:51:18.258595 185100 leveldb.cpp:320] Iterated through 0 keys in the db in 10017ns I0711 02:51:18.258672 185100 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0711 02:51:18.297143 185103 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 37.882009ms I0711 02:51:18.297200 185103 replica.cpp:322] Persisted replica status to VOTING I0711 02:51:18.496383 185100 leveldb.cpp:217] Opened db in 198.464678ms I0711 02:51:18.542151 185100 leveldb.cpp:224] Compacted db in 45.714235ms I0711 02:51:18.542322 185100 leveldb.cpp:239] Created db iterator in 69808ns I0711 02:51:18.542387 185100 leveldb.cpp:245] Seeked to beginning of db in 22846ns I0711 02:51:18.542439 185100 leveldb.cpp:320] Iterated through 0 keys in the db in 18846ns I0711 02:51:18.542559 185100 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0711 02:51:18.599397 185119 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 55.918065ms I0711 02:51:18.599550 185119 replica.cpp:322] Persisted replica status to VOTING I0711 02:51:18.811125 185100 leveldb.cpp:217] Opened db in 210.02554ms I0711 02:51:18.900835 185100 leveldb.cpp:224] Compacted db in 89.587874ms I0711 02:51:18.901023 185100 leveldb.cpp:239] Created db iterator in 80551ns I0711 02:51:18.901132 185100 leveldb.cpp:245] Seeked to beginning of db in 71225ns I0711 02:51:18.901265 185100 leveldb.cpp:320] Iterated through 1 keys in the db in 101738ns I0711 02:51:18.901396 185100 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0711 02:51:19.012828 185100 leveldb.cpp:217] Opened db in 110.821252ms I0711 02:51:19.109297 185100 leveldb.cpp:224] Compacted db in 96.376003ms I0711 02:51:19.109455 185100 leveldb.cpp:239] Created db iterator in 63246ns I0711 02:51:19.109526 185100 leveldb.cpp:245] Seeked to beginning of db in 45952ns I0711 02:51:19.109624 185100 leveldb.cpp:320] Iterated through 1 keys in the db in 79169ns I0711 02:51:19.109722 185100 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0711 02:51:19.112987 185117 replica.cpp:497] Replica received implicit promise request from __req_res__(984)@172.17.0.2:39617 with proposal 1 I0711 02:51:19.113162 185121 replica.cpp:497] Replica received implicit promise request from __req_res__(985)@172.17.0.2:39617 with proposal 1 I0711 02:51:19.154685 185117 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 41.63747ms I0711 02:51:19.154768 185117 replica.cpp:344] Persisted promised to 1 I0711 02:51:19.171394 185121 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 58.177329ms I0711 02:51:19.171476 185121 replica.cpp:344] Persisted promised to 1 I0711 02:51:19.172497 185115 coordinator.cpp:238] Coordinator attempting to fill missing positions I0711 02:51:19.174597 185124 replica.cpp:391] Replica received explicit promise request from __req_res__(986)@172.17.0.2:39617 for position 0 with proposal 2 I0711 02:51:19.174834 185106 replica.cpp:391] Replica received explicit promise request from __req_res__(987)@172.17.0.2:39617 for position 0 with proposal 2 I0711 02:51:19.213181 185106 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 38.278863ms I0711 02:51:19.213188 185124 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 38.520074ms I0711 02:51:19.213274 185106 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:19.213320 185124 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:19.214936 185112 replica.cpp:541] Replica received write request for position 0 from __req_res__(988)@172.17.0.2:39617 I0711 02:51:19.215098 185112 leveldb.cpp:510] Reading position from leveldb took 102155ns I0711 02:51:19.215144 185101 replica.cpp:541] Replica received write request for position 0 from __req_res__(989)@172.17.0.2:39617 I0711 02:51:19.215302 185101 leveldb.cpp:510] Reading position from leveldb took 76672ns I0711 02:51:19.255064 185112 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 39.843679ms I0711 02:51:19.255064 185101 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 39.708398ms I0711 02:51:19.255169 185112 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:19.255234 185101 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:19.256104 185117 replica.cpp:695] Replica received learned notice for position 0 from log-network(47)@172.17.0.2:39617 I0711 02:51:19.256161 185103 replica.cpp:695] Replica received learned notice for position 0 from log-network(47)@172.17.0.2:39617 I0711 02:51:19.288524 185117 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 32.370181ms I0711 02:51:19.288525 185103 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 32.308828ms I0711 02:51:19.288616 185117 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:19.288661 185103 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:19.290059 185114 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 I0711 02:51:19.291222 185121 replica.cpp:541] Replica received write request for position 1 from __req_res__(990)@172.17.0.2:39617 I0711 02:51:19.291380 185110 replica.cpp:541] Replica received write request for position 1 from __req_res__(991)@172.17.0.2:39617 I0711 02:51:19.322012 185110 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 30.564863ms I0711 02:51:19.322011 185121 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 30.714356ms I0711 02:51:19.322129 185110 replica.cpp:712] Persisted action APPEND at position 1 I0711 02:51:19.322166 185121 replica.cpp:712] Persisted action APPEND at position 1 I0711 02:51:19.323148 185113 replica.cpp:695] Replica received learned notice for position 1 from log-network(47)@172.17.0.2:39617 I0711 02:51:19.323155 185108 replica.cpp:695] Replica received learned notice for position 1 from log-network(47)@172.17.0.2:39617 I0711 02:51:19.372130 185108 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 48.844427ms I0711 02:51:19.372159 185113 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 48.930172ms I0711 02:51:19.372234 185108 replica.cpp:712] Persisted action APPEND at position 1 I0711 02:51:19.372270 185113 replica.cpp:712] Persisted action APPEND at position 1 I0711 02:51:19.373606 185101 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 2 I0711 02:51:19.374752 185103 replica.cpp:541] Replica received write request for position 2 from __req_res__(992)@172.17.0.2:39617 I0711 02:51:19.374966 185102 replica.cpp:541] Replica received write request for position 2 from __req_res__(993)@172.17.0.2:39617 I0711 02:51:19.422276 185102 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.242646ms I0711 02:51:19.422286 185103 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.448545ms I0711 02:51:19.422365 185102 replica.cpp:712] Persisted action APPEND at position 2 I0711 02:51:19.422410 185103 replica.cpp:712] Persisted action APPEND at position 2 I0711 02:51:19.423300 185122 replica.cpp:695] Replica received learned notice for position 2 from log-network(47)@172.17.0.2:39617 I0711 02:51:19.423307 185112 replica.cpp:695] Replica received learned notice for position 2 from log-network(47)@172.17.0.2:39617 I0711 02:51:19.472445 185112 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.042573ms I0711 02:51:19.472445 185122 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.087109ms I0711 02:51:19.472560 185112 replica.cpp:712] Persisted action APPEND at position 2 I0711 02:51:19.472596 185122 replica.cpp:712] Persisted action APPEND at position 2 I0711 02:51:19.473929 185119 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3 I0711 02:51:19.475080 185103 replica.cpp:541] Replica received write request for position 3 from __req_res__(994)@172.17.0.2:39617 I0711 02:51:19.475255 185110 replica.cpp:541] Replica received write request for position 3 from __req_res__(995)@172.17.0.2:39617 I0711 02:51:19.522588 185103 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.426478ms I0711 02:51:19.522590 185110 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.252103ms I0711 02:51:19.522680 185103 replica.cpp:712] Persisted action APPEND at position 3 I0711 02:51:19.522725 185110 replica.cpp:712] Persisted action APPEND at position 3 I0711 02:51:19.523622 185114 replica.cpp:695] Replica received learned notice for position 3 from log-network(47)@172.17.0.2:39617 I0711 02:51:19.523648 185113 replica.cpp:695] Replica received learned notice for position 3 from log-network(47)@172.17.0.2:39617 I0711 02:51:19.572710 185113 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 48.990898ms I0711 02:51:19.572723 185114 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.048946ms I0711 02:51:19.572799 185113 replica.cpp:712] Persisted action APPEND at position 3 I0711 02:51:19.572844 185114 replica.cpp:712] Persisted action APPEND at position 3 I0711 02:51:19.573995 185117 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 4 I0711 02:51:19.575070 185109 replica.cpp:541] Replica received write request for position 4 from __req_res__(996)@172.17.0.2:39617 I0711 02:51:19.575309 185121 replica.cpp:541] Replica received write request for position 4 from __req_res__(997)@172.17.0.2:39617 I0711 02:51:19.614511 185121 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 39.138037ms I0711 02:51:19.614521 185109 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 39.387345ms I0711 02:51:19.614602 185121 replica.cpp:712] Persisted action APPEND at position 4 I0711 02:51:19.614647 185109 replica.cpp:712] Persisted action APPEND at position 4 I0711 02:51:19.615572 185120 replica.cpp:695] Replica received learned notice for position 4 from log-network(47)@172.17.0.2:39617 I0711 02:51:19.615643 185118 replica.cpp:695] Replica received learned notice for position 4 from log-network(47)@172.17.0.2:39617 I0711 02:51:19.656327 185120 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.708577ms I0711 02:51:19.656328 185118 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.623289ms I0711 02:51:19.656421 185120 replica.cpp:712] Persisted action APPEND at position 4 I0711 02:51:19.656469 185118 replica.cpp:712] Persisted action APPEND at position 4 I0711 02:51:19.657680 185102 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 5 I0711 02:51:19.658932 185122 replica.cpp:541] Replica received write request for position 5 from __req_res__(998)@172.17.0.2:39617 I0711 02:51:19.659034 185121 replica.cpp:541] Replica received write request for position 5 from __req_res__(999)@172.17.0.2:39617 I0711 02:51:19.698132 185121 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 39.038327ms I0711 02:51:19.698132 185122 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 39.124758ms I0711 02:51:19.698248 185121 replica.cpp:712] Persisted action APPEND at position 5 I0711 02:51:19.698285 185122 replica.cpp:712] Persisted action APPEND at position 5 I0711 02:51:19.699221 185113 replica.cpp:695] Replica received learned notice for position 5 from log-network(47)@172.17.0.2:39617 I0711 02:51:19.699303 185123 replica.cpp:695] Replica received learned notice for position 5 from log-network(47)@172.17.0.2:39617 I0711 02:51:19.756546 185123 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 57.170466ms I0711 02:51:19.756547 185113 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 57.271364ms I0711 02:51:19.756598 185123 replica.cpp:712] Persisted action APPEND at position 5 I0711 02:51:19.756624 185113 replica.cpp:712] Persisted action APPEND at position 5 I0711 02:51:19.757768 185105 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 6 I0711 02:51:19.759052 185101 replica.cpp:541] Replica received write request for position 6 from __req_res__(1000)@172.17.0.2:39617 I0711 02:51:19.759227 185121 replica.cpp:541] Replica received write request for position 6 from __req_res__(1001)@172.17.0.2:39617 I0711 02:51:19.798489 185121 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 39.213652ms I0711 02:51:19.798488 185101 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 39.393938ms I0711 02:51:19.798646 185121 replica.cpp:712] Persisted action APPEND at position 6 I0711 02:51:19.798681 185101 replica.cpp:712] Persisted action APPEND at position 6 I0711 02:51:19.800045 185110 replica.cpp:695] Replica received learned notice for position 6 from log-network(47)@172.17.0.2:39617 I0711 02:51:19.800045 185120 replica.cpp:695] Replica received learned notice for position 6 from log-network(47)@172.17.0.2:39617 I0711 02:51:19.840219 185110 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.10237ms I0711 02:51:19.840219 185120 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.059741ms I0711 02:51:19.840334 185110 replica.cpp:712] Persisted action APPEND at position 6 I0711 02:51:19.840370 185120 replica.cpp:712] Persisted action APPEND at position 6 I0711 02:51:19.841921 185107 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 7 I0711 02:51:19.843466 185118 replica.cpp:541] Replica received write request for position 7 from __req_res__(1002)@172.17.0.2:39617 I0711 02:51:19.843713 185121 replica.cpp:541] Replica received write request for position 7 from __req_res__(1003)@172.17.0.2:39617 I0711 02:51:19.881999 185121 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 38.219007ms I0711 02:51:19.882004 185118 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 38.445089ms I0711 02:51:19.882089 185121 replica.cpp:712] Persisted action APPEND at position 7 I0711 02:51:19.882135 185118 replica.cpp:712] Persisted action APPEND at position 7 I0711 02:51:19.883008 185108 replica.cpp:695] Replica received learned notice for position 7 from log-network(47)@172.17.0.2:39617 I0711 02:51:19.883077 185103 replica.cpp:695] Replica received learned notice for position 7 from log-network(47)@172.17.0.2:39617 I0711 02:51:19.923797 185108 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.733983ms I0711 02:51:19.923817 185103 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.692657ms I0711 02:51:19.923888 185108 replica.cpp:712] Persisted action APPEND at position 7 I0711 02:51:19.923928 185103 replica.cpp:712] Persisted action APPEND at position 7 I0711 02:51:19.925130 185109 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 8 I0711 02:51:19.926290 185117 replica.cpp:541] Replica received write request for position 8 from __req_res__(1004)@172.17.0.2:39617 I0711 02:51:19.926465 185102 replica.cpp:541] Replica received write request for position 8 from __req_res__(1005)@172.17.0.2:39617 I0711 02:51:19.965626 185117 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 39.247841ms I0711 02:51:19.965627 185102 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 39.096658ms I0711 02:51:19.965716 185117 replica.cpp:712] Persisted action APPEND at position 8 I0711 02:51:19.965761 185102 replica.cpp:712] Persisted action APPEND at position 8 I0711 02:51:19.966629 185118 replica.cpp:695] Replica received learned notice for position 8 from log-network(47)@172.17.0.2:39617 I0711 02:51:19.966682 185112 replica.cpp:695] Replica received learned notice for position 8 from log-network(47)@172.17.0.2:39617 I0711 02:51:20.007431 185118 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.757132ms I0711 02:51:20.007431 185112 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.688638ms I0711 02:51:20.007524 185118 replica.cpp:712] Persisted action APPEND at position 8 I0711 02:51:20.007589 185112 replica.cpp:712] Persisted action APPEND at position 8 I0711 02:51:20.009008 185109 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 9 I0711 02:51:20.010056 185117 replica.cpp:541] Replica received write request for position 9 from __req_res__(1006)@172.17.0.2:39617 I0711 02:51:20.010320 185115 replica.cpp:541] Replica received write request for position 9 from __req_res__(1007)@172.17.0.2:39617 I0711 02:51:20.049234 185117 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 39.114081ms I0711 02:51:20.049240 185115 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 38.836398ms I0711 02:51:20.049327 185117 replica.cpp:712] Persisted action APPEND at position 9 I0711 02:51:20.049372 185115 replica.cpp:712] Persisted action APPEND at position 9 I0711 02:51:20.050276 185106 replica.cpp:695] Replica received learned notice for position 9 from log-network(47)@172.17.0.2:39617 I0711 02:51:20.050340 185103 replica.cpp:695] Replica received learned notice for position 9 from log-network(47)@172.17.0.2:39617 I0711 02:51:20.091022 185103 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.634079ms I0711 02:51:20.091024 185106 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.688547ms I0711 02:51:20.091075 185103 replica.cpp:712] Persisted action APPEND at position 9 I0711 02:51:20.091110 185106 replica.cpp:712] Persisted action APPEND at position 9 I0711 02:51:20.091840 185121 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 10 I0711 02:51:20.092434 185117 replica.cpp:541] Replica received write request for position 10 from __req_res__(1008)@172.17.0.2:39617 I0711 02:51:20.092567 185114 replica.cpp:541] Replica received write request for position 10 from __req_res__(1009)@172.17.0.2:39617 I0711 02:51:20.132858 185114 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 40.263629ms I0711 02:51:20.132858 185117 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 40.403195ms I0711 02:51:20.132962 185114 replica.cpp:712] Persisted action APPEND at position 10 I0711 02:51:20.133013 185117 replica.cpp:712] Persisted action APPEND at position 10 I0711 02:51:20.134171 185103 replica.cpp:695] Replica received learned notice for position 10 from log-network(47)@172.17.0.2:39617 I0711 02:51:20.134186 185116 replica.cpp:695] Replica received learned notice for position 10 from log-network(47)@172.17.0.2:39617 I0711 02:51:20.174597 185103 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 40.357453ms I0711 02:51:20.174597 185116 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 40.301393ms I0711 02:51:20.174662 185103 replica.cpp:712] Persisted action APPEND at position 10 I0711 02:51:20.174687 185116 replica.cpp:712] Persisted action APPEND at position 10 I0711 02:51:20.267664 185100 leveldb.cpp:217] Opened db in 92.099053ms I0711 02:51:20.332562 185100 leveldb.cpp:224] Compacted db in 64.844362ms I0711 02:51:20.332670 185100 leveldb.cpp:239] Created db iterator in 43584ns I0711 02:51:20.332718 185100 leveldb.cpp:245] Seeked to beginning of db in 32814ns I0711 02:51:20.332787 185100 leveldb.cpp:320] Iterated through 1 keys in the db in 56336ns I0711 02:51:20.332851 185100 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0711 02:51:20.333684 185104 recover.cpp:437] Starting replica recovery I0711 02:51:20.334146 185123 recover.cpp:468] Replica is in VOTING status I0711 02:51:20.334374 185123 recover.cpp:447] Recover process terminated I0711 02:51:20.334929 185119 catchup.cpp:342] Starting missing positions recovery I0711 02:51:20.335253 185116 catchup.cpp:368] Replica is in VOTING status I0711 02:51:20.336374 185122 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(1010)@172.17.0.2:39617 I0711 02:51:20.336517 185118 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(1011)@172.17.0.2:39617 I0711 02:51:20.336625 185117 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(1012)@172.17.0.2:39617 I0711 02:51:20.337301 185118 recover.cpp:197] Received a recover response from a replica in VOTING status I0711 02:51:20.337649 185118 recover.cpp:197] Received a recover response from a replica in VOTING status I0711 02:51:20.338521 185107 catchup.cpp:423] Starting catch-up from position 0 to 9 I0711 02:51:20.340052 185106 replica.cpp:391] Replica received explicit promise request from __req_res__(1013)@172.17.0.2:39617 for position 0 with proposal 0 I0711 02:51:20.340131 185101 replica.cpp:391] Replica received explicit promise request from __req_res__(1014)@172.17.0.2:39617 for position 0 with proposal 0 I0711 02:51:20.340165 185106 leveldb.cpp:510] Reading position from leveldb took 75573ns I0711 02:51:20.340214 185101 leveldb.cpp:510] Reading position from leveldb took 48208ns I0711 02:51:20.340253 185111 replica.cpp:391] Replica received explicit promise request from __req_res__(1015)@172.17.0.2:39617 for position 0 with proposal 0 I0711 02:51:20.521663 185117 replica.cpp:391] Replica received explicit promise request from __req_res__(1016)@172.17.0.2:39617 for position 0 with proposal 3 I0711 02:51:20.521770 185122 replica.cpp:391] Replica received explicit promise request from __req_res__(1017)@172.17.0.2:39617 for position 0 with proposal 3 I0711 02:51:20.521924 185117 leveldb.cpp:510] Reading position from leveldb took 147053ns I0711 02:51:20.521930 185122 leveldb.cpp:510] Reading position from leveldb took 99554ns I0711 02:51:20.521981 185114 replica.cpp:391] Replica received explicit promise request from __req_res__(1018)@172.17.0.2:39617 for position 0 with proposal 3 I0711 02:51:20.576830 185117 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 54.804908ms I0711 02:51:20.576830 185122 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 54.773622ms I0711 02:51:20.576967 185117 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:20.577016 185122 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:20.578030 185107 replica.cpp:695] Replica received learned notice for position 0 from log-network(48)@172.17.0.2:39617 I0711 02:51:20.578099 185105 replica.cpp:695] Replica received learned notice for position 0 from log-network(48)@172.17.0.2:39617 I0711 02:51:20.622323 185114 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 100.240846ms I0711 02:51:20.622455 185114 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:20.622786 185114 replica.cpp:695] Replica received learned notice for position 0 from log-network(48)@172.17.0.2:39617 I0711 02:51:20.657419 185105 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 79.280726ms I0711 02:51:20.657419 185107 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 79.340302ms I0711 02:51:20.657517 185105 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:20.657580 185107 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:20.677608 185114 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 54.776396ms I0711 02:51:20.677704 185114 replica.cpp:712] Persisted action NOP at position 0 I0711 02:51:20.680150 185123 replica.cpp:391] Replica received explicit promise request from __req_res__(1019)@172.17.0.2:39617 for position 1 with proposal 3 I0711 02:51:20.680253 185104 replica.cpp:391] Replica received explicit promise request from __req_res__(1020)@172.17.0.2:39617 for position 1 with proposal 3 I0711 02:51:20.680322 185123 leveldb.cpp:510] Reading position from leveldb took 111084ns I0711 02:51:20.680430 185104 leveldb.cpp:510] Reading position from leveldb took 106151ns I0711 02:51:20.680433 185119 replica.cpp:391] Replica received explicit promise request from __req_res__(1021)@172.17.0.2:39617 for position 1 with proposal 3 I0711 02:51:20.727540 185119 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 47.012217ms I0711 02:51:20.727576 185104 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 47.045666ms I0711 02:51:20.727622 185119 replica.cpp:712] Persisted action NOP at position 1 I0711 02:51:20.727583 185123 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 47.181527ms I0711 02:51:20.727665 185104 replica.cpp:712] Persisted action APPEND at position 1 I0711 02:51:20.727741 185123 replica.cpp:712] Persisted action APPEND at position 1 I0711 02:51:20.728715 185112 replica.cpp:695] Replica received learned notice for position 1 from log-network(48)@172.17.0.2:39617 I0711 02:51:20.728778 185110 replica.cpp:695] Replica received learned notice for position 1 from log-network(48)@172.17.0.2:39617 I0711 02:51:20.728843 185122 replica.cpp:695] Replica received learned notice for position 1 from log-network(48)@172.17.0.2:39617 I0711 02:51:20.777812 185112 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.06045ms I0711 02:51:20.777817 185110 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.01294ms I0711 02:51:20.777905 185112 replica.cpp:712] Persisted action APPEND at position 1 I0711 02:51:20.777812 185122 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 48.952549ms I0711 02:51:20.777951 185110 replica.cpp:712] Persisted action APPEND at position 1 I0711 02:51:20.778010 185122 replica.cpp:712] Persisted action APPEND at position 1 I0711 02:51:20.780153 185104 replica.cpp:391] Replica received explicit promise request from __req_res__(1022)@172.17.0.2:39617 for position 2 with proposal 3 I0711 02:51:20.780292 185108 replica.cpp:391] Replica received explicit promise request from __req_res__(1023)@172.17.0.2:39617 for position 2 with proposal 3 I0711 02:51:20.780324 185104 leveldb.cpp:510] Reading position from leveldb took 115331ns I0711 02:51:20.780445 185108 leveldb.cpp:510] Reading position from leveldb took 93391ns I0711 02:51:20.780516 185114 replica.cpp:391] Replica received explicit promise request from __req_res__(1024)@172.17.0.2:39617 for position 2 with proposal 3 I0711 02:51:20.828003 185114 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 47.412068ms I0711 02:51:20.828006 185108 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 47.474938ms I0711 02:51:20.828066 185114 replica.cpp:712] Persisted action NOP at position 2 I0711 02:51:20.828022 185104 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 47.584111ms I0711 02:51:20.828104 185108 replica.cpp:712] Persisted action APPEND at position 2 I0711 02:51:20.828155 185104 replica.cpp:712] Persisted action APPEND at position 2 I0711 02:51:20.829021 185121 replica.cpp:695] Replica received learned notice for position 2 from log-network(48)@172.17.0.2:39617 I0711 02:51:20.829087 185113 replica.cpp:695] Replica received learned notice for position 2 from log-network(48)@172.17.0.2:39617 I0711 02:51:20.829098 185123 replica.cpp:695] Replica received learned notice for position 2 from log-network(48)@172.17.0.2:39617 I0711 02:51:20.878396 185113 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.257557ms I0711 02:51:20.878397 185123 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.216889ms I0711 02:51:20.878449 185113 replica.cpp:712] Persisted action APPEND at position 2 I0711 02:51:20.878401 185121 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.349966ms I0711 02:51:20.878477 185123 replica.cpp:712] Persisted action APPEND at position 2 I0711 02:51:20.878517 185121 replica.cpp:712] Persisted action APPEND at position 2 I0711 02:51:20.880041 185109 replica.cpp:391] Replica received explicit promise request from __req_res__(1025)@172.17.0.2:39617 for position 3 with proposal 3 I0711 02:51:20.880203 185102 replica.cpp:391] Replica received explicit promise request from __req_res__(1026)@172.17.0.2:39617 for position 3 with proposal 3 I0711 02:51:20.880226 185109 leveldb.cpp:510] Reading position from leveldb took 112174ns I0711 02:51:20.880354 185108 replica.cpp:391] Replica received explicit promise request from __req_res__(1027)@172.17.0.2:39617 for position 3 with proposal 3 I0711 02:51:20.880380 185102 leveldb.cpp:510] Reading position from leveldb took 112241ns I0711 02:51:20.928506 185108 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 48.093207ms I0711 02:51:20.928514 185102 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 47.996486ms I0711 02:51:20.928593 185108 replica.cpp:712] Persisted action NOP at position 3 I0711 02:51:20.928560 185109 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 48.203145ms I0711 02:51:20.928642 185102 replica.cpp:712] Persisted action APPEND at position 3 I0711 02:51:20.928687 185109 replica.cpp:712] Persisted action APPEND at position 3 I0711 02:51:20.929526 185118 replica.cpp:695] Replica received learned notice for position 3 from log-network(48)@172.17.0.2:39617 I0711 02:51:20.929584 185114 replica.cpp:695] Replica received learned notice for position 3 from log-network(48)@172.17.0.2:39617 I0711 02:51:20.929608 185104 replica.cpp:695] Replica received learned notice for position 3 from log-network(48)@172.17.0.2:39617 I0711 02:51:20.978705 185114 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.068262ms I0711 02:51:20.978708 185118 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.121236ms I0711 02:51:20.978794 185114 replica.cpp:712] Persisted action APPEND at position 3 I0711 02:51:20.978698 185104 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.022377ms I0711 02:51:20.978832 185118 replica.cpp:712] Persisted action APPEND at position 3 I0711 02:51:20.978897 185104 replica.cpp:712] Persisted action APPEND at position 3 I0711 02:51:20.980716 185117 replica.cpp:391] Replica received explicit promise request from __req_res__(1028)@172.17.0.2:39617 for position 4 with proposal 3 I0711 02:51:20.980769 185113 replica.cpp:391] Replica received explicit promise request from __req_res__(1029)@172.17.0.2:39617 for position 4 with proposal 3 I0711 02:51:20.980875 185117 leveldb.cpp:510] Reading position from leveldb took 103715ns I0711 02:51:20.980895 185113 leveldb.cpp:510] Reading position from leveldb took 85309ns I0711 02:51:20.980935 185105 replica.cpp:391] Replica received explicit promise request from __req_res__(1030)@172.17.0.2:39617 for position 4 with proposal 3 I0711 02:51:21.028810 185117 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 47.832017ms I0711 02:51:21.028831 185105 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 47.821109ms I0711 02:51:21.028873 185117 replica.cpp:712] Persisted action APPEND at position 4 I0711 02:51:21.028896 185105 replica.cpp:712] Persisted action NOP at position 4 I0711 02:51:21.028831 185113 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 47.818579ms I0711 02:51:21.028972 185113 replica.cpp:712] Persisted action APPEND at position 4 I0711 02:51:21.029745 185116 replica.cpp:695] Replica received learned notice for position 4 from log-network(48)@172.17.0.2:39617 I0711 02:51:21.029772 185109 replica.cpp:695] Replica received learned notice for position 4 from log-network(48)@172.17.0.2:39617 I0711 02:51:21.029834 185121 replica.cpp:695] Replica received learned notice for position 4 from log-network(48)@172.17.0.2:39617 I0711 02:51:21.079120 185109 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.330364ms I0711 02:51:21.079120 185121 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.266722ms I0711 02:51:21.079120 185116 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.365549ms I0711 02:51:21.079221 185121 replica.cpp:712] Persisted action APPEND at position 4 I0711 02:51:21.079182 185109 replica.cpp:712] Persisted action APPEND at position 4 I0711 02:51:21.079247 185116 replica.cpp:712] Persisted action APPEND at position 4 I0711 02:51:21.080474 185118 replica.cpp:391] Replica received explicit promise request from __req_res__(1031)@172.17.0.2:39617 for position 5 with proposal 3 I0711 02:51:21.080574 185118 leveldb.cpp:510] Reading position from leveldb took 66852ns I0711 02:51:21.080579 185113 replica.cpp:391] Replica received explicit promise request from __req_res__(1032)@172.17.0.2:39617 for position 5 with proposal 3 I0711 02:51:21.080688 185113 leveldb.cpp:510] Reading position from leveldb took 53700ns I0711 02:51:21.080693 185106 replica.cpp:391] Replica received explicit promise request from __req_res__(1033)@172.17.0.2:39617 for position 5 with proposal 3 I0711 02:51:21.162593 185118 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 81.953738ms I0711 02:51:21.162612 185106 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 81.875013ms I0711 02:51:21.162642 185118 replica.cpp:712] Persisted action APPEND at position 5 I0711 02:51:21.162618 185113 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 81.877551ms I0711 02:51:21.162662 185106 replica.cpp:712] Persisted action NOP at position 5 I0711 02:51:21.162712 185113 replica.cpp:712] Persisted action APPEND at position 5 I0711 02:51:21.163430 185111 replica.cpp:695] Replica received learned notice for position 5 from log-network(48)@172.17.0.2:39617 I0711 02:51:21.163487 185105 replica.cpp:695] Replica received learned notice for position 5 from log-network(48)@172.17.0.2:39617 I0711 02:51:21.163537 185114 replica.cpp:695] Replica received learned notice for position 5 from log-network(48)@172.17.0.2:39617 I0711 02:51:21.237867 185105 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 74.349613ms I0711 02:51:21.237893 185114 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 74.298815ms I0711 02:51:21.237972 185105 replica.cpp:712] Persisted action APPEND at position 5 I0711 02:51:21.237896 185111 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 74.426145ms I0711 02:51:21.238013 185114 replica.cpp:712] Persisted action APPEND at position 5 I0711 02:51:21.238077 185111 replica.cpp:712] Persisted action APPEND at position 5 I0711 02:51:21.239969 185115 replica.cpp:391] Replica received explicit promise request from __req_res__(1034)@172.17.0.2:39617 for position 6 with proposal 3 I0711 02:51:21.240118 185115 leveldb.cpp:510] Reading position from leveldb took 90688ns I0711 02:51:21.240126 185109 replica.cpp:391] Replica received explicit promise request from __req_res__(1035)@172.17.0.2:39617 for position 6 with proposal 3 I0711 02:51:21.240309 185109 leveldb.cpp:510] Reading position from leveldb took 116818ns I0711 02:51:21.240327 185121 replica.cpp:391] Replica received explicit promise request from __req_res__(1036)@172.17.0.2:39617 for position 6 with proposal 3 I0711 02:51:21.313154 185109 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 72.737341ms I0711 02:51:21.313154 185115 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 72.974619ms I0711 02:51:21.313154 185121 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 72.775473ms I0711 02:51:21.313247 185115 replica.cpp:712] Persisted action APPEND at position 6 I0711 02:51:21.313226 185109 replica.cpp:712] Persisted action APPEND at position 6 I0711 02:51:21.313268 185121 replica.cpp:712] Persisted action NOP at position 6 I0711 02:51:21.313977 185103 replica.cpp:695] Replica received learned notice for position 6 from log-network(48)@172.17.0.2:39617 I0711 02:51:21.313984 185122 replica.cpp:695] Replica received learned notice for position 6 from log-network(48)@172.17.0.2:39617 I0711 02:51:21.314040 185119 replica.cpp:695] Replica received learned notice for position 6 from log-network(48)@172.17.0.2:39617 I0711 02:51:21.355273 185103 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 41.243809ms I0711 02:51:21.355276 185119 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 41.160487ms I0711 02:51:21.355365 185103 replica.cpp:712] Persisted action APPEND at position 6 I0711 02:51:21.355276 185122 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 41.215062ms I0711 02:51:21.355422 185119 replica.cpp:712] Persisted action APPEND at position 6 I0711 02:51:21.355460 185122 replica.cpp:712] Persisted action APPEND at position 6 I0711 02:51:21.357445 185114 replica.cpp:391] Replica received explicit promise request from __req_res__(1037)@172.17.0.2:39617 for position 7 with proposal 3 I0711 02:51:21.357594 185110 replica.cpp:391] Replica received explicit promise request from __req_res__(1038)@172.17.0.2:39617 for position 7 with proposal 3 I0711 02:51:21.357635 185114 leveldb.cpp:510] Reading position from leveldb took 127354ns I0711 02:51:21.357744 185110 leveldb.cpp:510] Reading position from leveldb took 92758ns I0711 02:51:21.357744 185104 replica.cpp:391] Replica received explicit promise request from __req_res__(1039)@172.17.0.2:39617 for position 7 with proposal 3 I0711 02:51:21.397073 185110 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 39.258411ms I0711 02:51:21.397076 185114 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 39.335867ms I0711 02:51:21.397176 185110 replica.cpp:712] Persisted action APPEND at position 7 I0711 02:51:21.397078 185104 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 39.248795ms I0711 02:51:21.397240 185114 replica.cpp:712] Persisted action APPEND at position 7 I0711 02:51:21.397290 185104 replica.cpp:712] Persisted action NOP at position 7 I0711 02:51:21.398103 185114 replica.cpp:695] Replica received learned notice for position 7 from log-network(48)@172.17.0.2:39617 I0711 02:51:21.398156 185108 replica.cpp:695] Replica received learned notice for position 7 from log-network(48)@172.17.0.2:39617 I0711 02:51:21.398242 185101 replica.cpp:695] Replica received learned notice for position 7 from log-network(48)@172.17.0.2:39617 I0711 02:51:21.438858 185101 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.565377ms I0711 02:51:21.438875 185108 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.676491ms I0711 02:51:21.438875 185114 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.736886ms I0711 02:51:21.438951 185101 replica.cpp:712] Persisted action APPEND at position 7 I0711 02:51:21.439060 185114 replica.cpp:712] Persisted action APPEND at position 7 I0711 02:51:21.439020 185108 replica.cpp:712] Persisted action APPEND at position 7 I0711 02:51:21.441094 185119 replica.cpp:391] Replica received explicit promise request from __req_res__(1040)@172.17.0.2:39617 for position 8 with proposal 3 I0711 02:51:21.441234 185116 replica.cpp:391] Replica received explicit promise request from __req_res__(1041)@172.17.0.2:39617 for position 8 with proposal 3 I0711 02:51:21.441277 185119 leveldb.cpp:510] Reading position from leveldb took 111554ns I0711 02:51:21.441392 185116 leveldb.cpp:510] Reading position from leveldb took 90028ns I0711 02:51:21.441430 185117 replica.cpp:391] Replica received explicit promise request from __req_res__(1042)@172.17.0.2:39617 for position 8 with proposal 3 I0711 02:51:21.497334 185119 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 55.956137ms I0711 02:51:21.497335 185116 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 55.881679ms I0711 02:51:21.497433 185119 replica.cpp:712] Persisted action APPEND at position 8 I0711 02:51:21.497340 185117 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 55.838889ms I0711 02:51:21.497483 185116 replica.cpp:712] Persisted action APPEND at position 8 I0711 02:51:21.497517 185117 replica.cpp:712] Persisted action NOP at position 8 I0711 02:51:21.498402 185114 replica.cpp:695] Replica received learned notice for position 8 from log-network(48)@172.17.0.2:39617 I0711 02:51:21.498466 185111 replica.cpp:695] Replica received learned notice for position 8 from log-network(48)@172.17.0.2:39617 I0711 02:51:21.498538 185102 replica.cpp:695] Replica received learned notice for position 8 from log-network(48)@172.17.0.2:39617 I0711 02:51:21.555830 185114 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 57.381006ms I0711 02:51:21.555832 185111 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 57.323624ms I0711 02:51:21.555922 185114 replica.cpp:712] Persisted action APPEND at position 8 I0711 02:51:21.555832 185102 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 57.234689ms I0711 02:51:21.555971 185111 replica.cpp:712] Persisted action APPEND at position 8 I0711 02:51:21.556021 185102 replica.cpp:712] Persisted action APPEND at position 8 I0711 02:51:21.557921 185109 replica.cpp:391] Replica received explicit promise request from __req_res__(1043)@172.17.0.2:39617 for position 9 with proposal 3 I0711 02:51:21.558091 185112 replica.cpp:391] Replica received explicit promise request from __req_res__(1044)@172.17.0.2:39617 for position 9 with proposal 3 I0711 02:51:21.558107 185109 leveldb.cpp:510] Reading position from leveldb took 121081ns I0711 02:51:21.558243 185112 leveldb.cpp:510] Reading position from leveldb took 89948ns I0711 02:51:21.558297 185108 replica.cpp:391] Replica received explicit promise request from __req_res__(1045)@172.17.0.2:39617 for position 9 with proposal 3 I0711 02:51:21.614324 185108 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 55.947827ms I0711 02:51:21.614327 185112 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 56.020016ms I0711 02:51:21.614425 185108 replica.cpp:712] Persisted action NOP at position 9 I0711 02:51:21.614470 185112 replica.cpp:712] Persisted action APPEND at position 9 I0711 02:51:21.614336 185109 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 56.087391ms I0711 02:51:21.614575 185109 replica.cpp:712] Persisted action APPEND at position 9 I0711 02:51:21.615365 185106 replica.cpp:695] Replica received learned notice for position 9 from log-network(48)@172.17.0.2:39617 I0711 02:51:21.615392 185109 replica.cpp:695] Replica received learned notice for position 9 from log-network(48)@172.17.0.2:39617 I0711 02:51:21.615433 185122 replica.cpp:695] Replica received learned notice for position 9 from log-network(48)@172.17.0.2:39617 I0711 02:51:21.672751 185122 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 57.252986ms I0711 02:51:21.672775 185109 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 57.315474ms I0711 02:51:21.672777 185106 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 57.358873ms I0711 02:51:21.672914 185109 replica.cpp:712] Persisted action APPEND at position 9 I0711 02:51:21.672873 185122 replica.cpp:712] Persisted action APPEND at position 9 I0711 02:51:21.672964 185106 replica.cpp:712] Persisted action APPEND at position 9 I0711 02:51:21.673946 185121 catchup.cpp:357] Recover process terminated I0711 02:51:21.676892 185119 leveldb.cpp:510] Reading position from leveldb took 96418ns I0711 02:51:21.677064 185119 leveldb.cpp:510] Reading position from leveldb took 78601ns I0711 02:51:21.677209 185119 leveldb.cpp:510] Reading position from leveldb took 71342ns I0711 02:51:21.677351 185119 leveldb.cpp:510] Reading position from leveldb took 71325ns I0711 02:51:21.677492 185119 leveldb.cpp:510] Reading position from leveldb took 71355ns I0711 02:51:21.677630 185119 leveldb.cpp:510] Reading position from leveldb took 69252ns I0711 02:51:21.677771 185119 leveldb.cpp:510] Reading position from leveldb took 71022ns I0711 02:51:21.677913 185119 leveldb.cpp:510] Reading position from leveldb took 72398ns I0711 02:51:21.678054 185119 leveldb.cpp:510] Reading position from leveldb took 71112ns I0711 02:51:21.678193 185119 leveldb.cpp:510] Reading position from leveldb took 69845ns [ OK ] LogTest.ReaderCatchup (3799 ms) [----------] 4 tests from LogTest (6715 ms total) [----------] 2 tests from LogZooKeeperTest I0711 02:51:21.685662 185100 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 I0711 02:51:21.772837 185100 jvm.cpp:590] Looking up method <init>(Ljava/lang/String;)V I0711 02:51:21.773208 185100 jvm.cpp:590] Looking up method deleteOnExit()V I0711 02:51:21.774470 185100 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. I0711 02:51:21.957701 185100 jvm.cpp:590] Looking up method <init>()V I0711 02:51:21.959353 185100 jvm.cpp:590] Looking up method <init>(Lorg/apache/zookeeper/server/persistence/FileTxnSnapLog;Lorg/apache/zookeeper/server/ZooKeeperServer$DataTreeBuilder;)V *** Aborted at 1720666282 (unix time) try "date -d @1720666282" if you are using GNU date *** PC: @ 0x7fbef3914ccd OopStorage::Block::release_entries() *** SIGSEGV (@0x238) received by PID 185100 (TID 0x7fbf6f1b4b40) from PID 568; stack trace: *** @ 0x7fbef3923929 os::Linux::chained_handler() @ 0x7fbef392963b JVM_handle_linux_signal @ 0x7fbef391c1dc signalHandler() @ 0x7fbf70807420 (unknown) @ 0x7fbef3914ccd OopStorage::Block::release_entries() @ 0x7fbef3914f26 OopStorage::release() @ 0x7fbef3617b21 jni_DeleteGlobalRef @ 0x7fbf7ff5f6f8 JNIEnv_::DeleteGlobalRef() @ 0x7fbf7ff5d840 Jvm::deleteGlobalRef() @ 0x559dc5273536 Jvm::Object::~Object() @ 0x559dc527835c org::apache::zookeeper::server::ZooKeeperServer::DataTreeBuilder::~DataTreeBuilder() @ 0x559dc527ac60 org::apache::zookeeper::server::ZooKeeperServer::BasicDataTreeBuilder::~BasicDataTreeBuilder() @ 0x559dc5276c7b mesos::internal::tests::ZooKeeperTestServer::ZooKeeperTestServer() @ 0x559dc3c1bef6 mesos::internal::tests::ZooKeeperTest::ZooKeeperTest() @ 0x559dc3c1e23f mesos::internal::tests::LogZooKeeperTest::LogZooKeeperTest() @ 0x559dc3c1e350 mesos::internal::tests::LogZooKeeperTest_WriteRead_Test::LogZooKeeperTest_WriteRead_Test() @ 0x559dc3c89252 testing::internal::TestFactoryImpl<>::CreateTest() @ 0x559dc52bd508 testing::internal::HandleSehExceptionsInMethodIfSupported<>() @ 0x559dc52b6ad9 testing::internal::HandleExceptionsInMethodIfSupported<>() @ 0x559dc5292d11 testing::TestInfo::Run() @ 0x559dc5293419 testing::TestCase::Run() @ 0x559dc529a7b3 testing::internal::UnitTestImpl::RunAllTests() @ 0x559dc52be736 testing::internal::HandleSehExceptionsInMethodIfSupported<>() @ 0x559dc52b763f testing::internal::HandleExceptionsInMethodIfSupported<>() @ 0x559dc52992cb testing::UnitTest::Run() @ 0x559dc3ca6e05 RUN_ALL_TESTS() @ 0x559dc3ca67cc main @ 0x7fbf70625083 __libc_start_main @ 0x559dc2cec75e _start make[4]: *** [Makefile:17971: check-local] Segmentation fault (core dumped) make[4]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub/src' I0711 02:51:24.268554 186140 exec.cpp:560] Agent exited ... shutting down make[3]: *** [Makefile:15906: check-am] Error 2 make[3]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub/src' I0711 02:51:24.269474 186136 executor.cpp:190] Received SHUTDOWN event I0711 02:51:24.269526 186136 executor.cpp:843] Shutting down I0711 02:51:24.269608 186136 executor.cpp:956] Sending SIGTERM to process tree at pid 186154 make[2]: *** [Makefile:15909: 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 ';' I0711 02:51:24.281984 186136 executor.cpp:969] Sent SIGTERM to the following process trees: [ -+- 186154 sh -c dd if=/dev/zero of=volume_path/file bs=1048576 count=2 && sleep 1000 \--- 186162 sleep 1000 ] I0711 02:51:24.282052 186136 executor.cpp:973] Scheduling escalation to SIGKILL in 3secs from now I0711 02:51:24.295521 186146 executor.cpp:1041] Command terminated with signal Terminated (pid: 186154) W0711 02:51:24.297983 186151 process.cpp:1917] Failed to send 'mesos.internal.StatusUpdateMessage' to '172.17.0.2:39617', connect: Failed to connect to 172.17.0.2:39617: Connection refused I0711 02:51:25.300379 186151 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 Full log: https://ci-builds.apache.org/job/Mesos/job/Mesos-Reviewbot/33457/console - Mesos Reviewbot On July 10, 2024, 11:37 p.m., Jason Zhou wrote: > > ----------------------------------------------------------- > This is an automatically generated e-mail. To reply, visit: > https://reviews.apache.org/r/75081/ > ----------------------------------------------------------- > > (Updated July 10, 2024, 11:37 p.m.) > > > Review request for mesos and Benjamin Mahler. > > > Repository: mesos > > > Description > ------- > > Currently, cgroups2::path assumes the path in the argument is relative. > We want the function to be able to distinguish between absolute and > relative paths, where we only prepend the mounting point on the > relative path. > > > Diffs > ----- > > src/linux/cgroups2.cpp d1fc2638cdf9a07199f90952e04998072021011c > src/tests/containerizer/cgroups2_tests.cpp > cb1e229f7f40aa71f57417c33fccb2cfb313a1f5 > > > Diff: https://reviews.apache.org/r/75081/diff/1/ > > > Testing > ------- > > Test case for absolute path argument added in CGROUPS2_Path test and passes > > > Thanks, > > Jason Zhou > >
