----------------------------------------------------------- This is an automatically generated e-mail. To reply, visit: https://reviews.apache.org/r/75016/#review226645 -----------------------------------------------------------
Bad patch! Reviews applied: [75026, 75006, 75016] Failed command: ['bash', '-c', "set -o pipefail; export OS='ubuntu:20.04' BUILDTOOL='autotools' COMPILER='gcc' CONFIGURATION='--verbose --disable-libtool-wrappers --disable-parallel-test-execution' ENVIRONMENT='GLOG_v=1 MESOS_VERBOSE=1'; ./support/jenkins/buildbot.sh 2>&1 | tee build_75016"] Error: ...<truncated>... 37:47.408100 185419 replica.cpp:712] Persisted action APPEND at position 10 I0709 22:37:47.409257 185411 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 11 I0709 22:37:47.410202 185406 replica.cpp:541] Replica received write request for position 11 from __req_res__(919)@172.17.0.2:37579 I0709 22:37:47.410279 185413 replica.cpp:541] Replica received write request for position 11 from __req_res__(920)@172.17.0.2:37579 I0709 22:37:47.449774 185413 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 39.448851ms I0709 22:37:47.449776 185406 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 39.52524ms I0709 22:37:47.449843 185413 replica.cpp:712] Persisted action TRUNCATE at position 11 I0709 22:37:47.449893 185406 replica.cpp:712] Persisted action TRUNCATE at position 11 I0709 22:37:47.450525 185417 replica.cpp:695] Replica received learned notice for position 11 from log-network(41)@172.17.0.2:37579 I0709 22:37:47.450531 185407 replica.cpp:695] Replica received learned notice for position 11 from log-network(41)@172.17.0.2:37579 I0709 22:37:47.491500 185407 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 40.886321ms I0709 22:37:47.491555 185417 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 40.994154ms I0709 22:37:47.521265 185407 leveldb.cpp:460] Deleting ~5 keys from leveldb took 29.729205ms I0709 22:37:47.521310 185417 leveldb.cpp:460] Deleting ~5 keys from leveldb took 29.717691ms I0709 22:37:47.860069 185407 leveldb.cpp:527] Compacting range 0-4 took 338.750787ms I0709 22:37:47.860138 185407 replica.cpp:712] Persisted action TRUNCATE at position 11 I0709 22:37:47.860152 185417 leveldb.cpp:527] Compacting range 0-4 took 338.811158ms I0709 22:37:47.860245 185417 replica.cpp:712] Persisted action TRUNCATE at position 11 I0709 22:37:47.985383 185403 leveldb.cpp:217] Opened db in 123.794772ms I0709 22:37:48.079965 185403 leveldb.cpp:224] Compacted db in 94.547569ms I0709 22:37:48.080065 185403 leveldb.cpp:239] Created db iterator in 54438ns I0709 22:37:48.080134 185403 leveldb.cpp:245] Seeked to beginning of db in 37114ns I0709 22:37:48.080231 185403 leveldb.cpp:320] Iterated through 1 keys in the db in 73243ns I0709 22:37:48.080312 185403 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0709 22:37:48.081148 185419 catchup.cpp:342] Starting missing positions recovery I0709 22:37:48.081665 185407 catchup.cpp:368] Replica is in VOTING status I0709 22:37:48.083359 185418 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(921)@172.17.0.2:37579 I0709 22:37:48.083454 185411 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(922)@172.17.0.2:37579 I0709 22:37:48.084523 185410 recover.cpp:197] Received a recover response from a replica in VOTING status I0709 22:37:48.084990 185410 recover.cpp:197] Received a recover response from a replica in VOTING status I0709 22:37:48.086374 185406 catchup.cpp:423] Starting catch-up from position 0 to 10 I0709 22:37:48.088339 185412 replica.cpp:391] Replica received explicit promise request from __req_res__(924)@172.17.0.2:37579 for position 0 with proposal 0 I0709 22:37:48.088416 185417 replica.cpp:391] Replica received explicit promise request from __req_res__(925)@172.17.0.2:37579 for position 0 with proposal 0 I0709 22:37:48.088501 185406 replica.cpp:391] Replica received explicit promise request from __req_res__(926)@172.17.0.2:37579 for position 0 with proposal 0 I0709 22:37:48.089257 185414 replica.cpp:695] Replica received learned notice for position 0 from log-network(42)@172.17.0.2:37579 I0709 22:37:48.089322 185418 replica.cpp:695] Replica received learned notice for position 0 from log-network(42)@172.17.0.2:37579 I0709 22:37:48.089349 185410 replica.cpp:695] Replica received learned notice for position 0 from log-network(42)@172.17.0.2:37579 I0709 22:37:48.129745 185414 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 40.458111ms I0709 22:37:48.129815 185414 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:48.146505 185410 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 57.131975ms I0709 22:37:48.146505 185418 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 57.15588ms I0709 22:37:48.146580 185410 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:48.146631 185418 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:48.148528 185411 replica.cpp:391] Replica received explicit promise request from __req_res__(927)@172.17.0.2:37579 for position 1 with proposal 0 I0709 22:37:48.148591 185414 replica.cpp:391] Replica received explicit promise request from __req_res__(928)@172.17.0.2:37579 for position 1 with proposal 0 I0709 22:37:48.148782 185407 replica.cpp:391] Replica received explicit promise request from __req_res__(929)@172.17.0.2:37579 for position 1 with proposal 0 I0709 22:37:48.149451 185416 replica.cpp:695] Replica received learned notice for position 1 from log-network(42)@172.17.0.2:37579 I0709 22:37:48.149513 185417 replica.cpp:695] Replica received learned notice for position 1 from log-network(42)@172.17.0.2:37579 I0709 22:37:48.149673 185418 replica.cpp:695] Replica received learned notice for position 1 from log-network(42)@172.17.0.2:37579 I0709 22:37:48.188305 185416 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 38.817406ms I0709 22:37:48.188305 185417 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 38.768056ms I0709 22:37:48.188525 185418 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 38.815204ms I0709 22:37:48.230198 185418 leveldb.cpp:460] Deleting ~1 keys from leveldb took 41.631896ms I0709 22:37:48.230198 185416 leveldb.cpp:460] Deleting ~1 keys from leveldb took 41.851149ms I0709 22:37:48.230198 185417 leveldb.cpp:460] Deleting ~1 keys from leveldb took 41.825265ms I0709 22:37:48.576714 185418 leveldb.cpp:527] Compacting range 0-0 took 346.471164ms I0709 22:37:48.576728 185417 leveldb.cpp:527] Compacting range 0-0 took 346.413751ms I0709 22:37:48.576792 185418 replica.cpp:712] Persisted action NOP at position 1 I0709 22:37:48.576825 185417 replica.cpp:712] Persisted action NOP at position 1 I0709 22:37:48.576828 185416 leveldb.cpp:527] Compacting range 0-0 took 346.544744ms I0709 22:37:48.576910 185416 replica.cpp:712] Persisted action NOP at position 1 I0709 22:37:48.578835 185410 replica.cpp:391] Replica received explicit promise request from __req_res__(930)@172.17.0.2:37579 for position 2 with proposal 0 I0709 22:37:48.578938 185404 replica.cpp:391] Replica received explicit promise request from __req_res__(931)@172.17.0.2:37579 for position 2 with proposal 0 I0709 22:37:48.579157 185412 replica.cpp:391] Replica received explicit promise request from __req_res__(932)@172.17.0.2:37579 for position 2 with proposal 0 I0709 22:37:48.579773 185416 replica.cpp:695] Replica received learned notice for position 2 from log-network(42)@172.17.0.2:37579 I0709 22:37:48.579908 185418 replica.cpp:695] Replica received learned notice for position 2 from log-network(42)@172.17.0.2:37579 I0709 22:37:48.579962 185404 replica.cpp:695] Replica received learned notice for position 2 from log-network(42)@172.17.0.2:37579 I0709 22:37:48.617545 185416 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 37.733325ms I0709 22:37:48.642707 185418 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 62.779916ms I0709 22:37:48.642712 185416 leveldb.cpp:460] Deleting ~1 keys from leveldb took 25.139803ms I0709 22:37:48.659443 185404 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 79.45536ms I0709 22:37:48.676493 185418 leveldb.cpp:460] Deleting ~1 keys from leveldb took 33.73318ms I0709 22:37:48.687903 185404 leveldb.cpp:460] Deleting ~1 keys from leveldb took 28.416587ms I0709 22:37:49.011389 185416 leveldb.cpp:527] Compacting range 1-1 took 368.595998ms I0709 22:37:49.011471 185416 replica.cpp:712] Persisted action NOP at position 2 I0709 22:37:49.011404 185418 leveldb.cpp:527] Compacting range 1-1 took 334.867865ms I0709 22:37:49.011576 185418 replica.cpp:712] Persisted action NOP at position 2 I0709 22:37:49.063520 185404 leveldb.cpp:527] Compacting range 1-1 took 375.578174ms I0709 22:37:49.063586 185404 replica.cpp:712] Persisted action NOP at position 2 I0709 22:37:49.065622 185405 replica.cpp:391] Replica received explicit promise request from __req_res__(933)@172.17.0.2:37579 for position 3 with proposal 0 I0709 22:37:49.065639 185416 replica.cpp:391] Replica received explicit promise request from __req_res__(934)@172.17.0.2:37579 for position 3 with proposal 0 I0709 22:37:49.065955 185409 replica.cpp:391] Replica received explicit promise request from __req_res__(935)@172.17.0.2:37579 for position 3 with proposal 0 I0709 22:37:49.066529 185415 replica.cpp:695] Replica received learned notice for position 3 from log-network(42)@172.17.0.2:37579 I0709 22:37:49.066617 185404 replica.cpp:695] Replica received learned notice for position 3 from log-network(42)@172.17.0.2:37579 I0709 22:37:49.066663 185410 replica.cpp:695] Replica received learned notice for position 3 from log-network(42)@172.17.0.2:37579 I0709 22:37:49.118216 185415 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 51.648401ms I0709 22:37:49.134967 185404 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 68.315983ms I0709 22:37:49.135033 185410 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 68.336048ms I0709 22:37:49.179163 185415 leveldb.cpp:460] Deleting ~1 keys from leveldb took 60.905332ms I0709 22:37:49.231148 185404 leveldb.cpp:460] Deleting ~1 keys from leveldb took 96.137144ms I0709 22:37:49.231205 185410 leveldb.cpp:460] Deleting ~1 keys from leveldb took 96.133909ms I0709 22:37:49.762765 185415 leveldb.cpp:527] Compacting range 2-2 took 583.571081ms I0709 22:37:49.762871 185415 replica.cpp:712] Persisted action NOP at position 3 I0709 22:37:49.846645 185410 leveldb.cpp:527] Compacting range 2-2 took 615.413492ms I0709 22:37:49.846736 185404 leveldb.cpp:527] Compacting range 2-2 took 615.539326ms I0709 22:37:49.846756 185410 replica.cpp:712] Persisted action NOP at position 3 I0709 22:37:49.846798 185404 replica.cpp:712] Persisted action NOP at position 3 I0709 22:37:49.849086 185419 replica.cpp:391] Replica received explicit promise request from __req_res__(936)@172.17.0.2:37579 for position 4 with proposal 0 I0709 22:37:49.849181 185405 replica.cpp:391] Replica received explicit promise request from __req_res__(937)@172.17.0.2:37579 for position 4 with proposal 0 I0709 22:37:49.849275 185410 replica.cpp:391] Replica received explicit promise request from __req_res__(938)@172.17.0.2:37579 for position 4 with proposal 0 I0709 22:37:49.850118 185417 replica.cpp:695] Replica received learned notice for position 4 from log-network(42)@172.17.0.2:37579 I0709 22:37:49.850160 185415 replica.cpp:695] Replica received learned notice for position 4 from log-network(42)@172.17.0.2:37579 I0709 22:37:49.850281 185418 replica.cpp:695] Replica received learned notice for position 4 from log-network(42)@172.17.0.2:37579 I0709 22:37:49.925392 185417 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 75.244717ms I0709 22:37:49.975443 185415 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 125.255224ms I0709 22:37:49.975500 185418 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 125.162529ms I0709 22:37:50.042292 185417 leveldb.cpp:460] Deleting ~1 keys from leveldb took 116.862366ms I0709 22:37:50.067514 185415 leveldb.cpp:460] Deleting ~1 keys from leveldb took 92.025656ms I0709 22:37:50.067564 185418 leveldb.cpp:460] Deleting ~1 keys from leveldb took 92.017767ms I0709 22:37:50.427855 185417 leveldb.cpp:527] Compacting range 3-3 took 385.527231ms I0709 22:37:50.427964 185417 replica.cpp:712] Persisted action NOP at position 4 I0709 22:37:50.494601 185418 leveldb.cpp:527] Compacting range 3-3 took 427.005375ms I0709 22:37:50.494623 185415 leveldb.cpp:527] Compacting range 3-3 took 427.063094ms I0709 22:37:50.494707 185418 replica.cpp:712] Persisted action NOP at position 4 I0709 22:37:50.494740 185415 replica.cpp:712] Persisted action NOP at position 4 I0709 22:37:50.496694 185414 replica.cpp:391] Replica received explicit promise request from __req_res__(939)@172.17.0.2:37579 for position 5 with proposal 0 I0709 22:37:50.496762 185417 replica.cpp:391] Replica received explicit promise request from __req_res__(940)@172.17.0.2:37579 for position 5 with proposal 0 I0709 22:37:50.496834 185405 replica.cpp:391] Replica received explicit promise request from __req_res__(941)@172.17.0.2:37579 for position 5 with proposal 0 I0709 22:37:50.496879 185414 leveldb.cpp:510] Reading position from leveldb took 122600ns I0709 22:37:50.496915 185417 leveldb.cpp:510] Reading position from leveldb took 113485ns I0709 22:37:50.636978 185406 replica.cpp:391] Replica received explicit promise request from __req_res__(942)@172.17.0.2:37579 for position 5 with proposal 2 I0709 22:37:50.637020 185419 replica.cpp:391] Replica received explicit promise request from __req_res__(943)@172.17.0.2:37579 for position 5 with proposal 2 I0709 22:37:50.637118 185408 replica.cpp:391] Replica received explicit promise request from __req_res__(944)@172.17.0.2:37579 for position 5 with proposal 2 I0709 22:37:50.637231 185419 leveldb.cpp:510] Reading position from leveldb took 147668ns I0709 22:37:50.637231 185406 leveldb.cpp:510] Reading position from leveldb took 164440ns I0709 22:37:50.686926 185406 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.598761ms I0709 22:37:50.686995 185406 replica.cpp:712] Persisted action APPEND at position 5 I0709 22:37:50.688059 185411 replica.cpp:695] Replica received learned notice for position 5 from log-network(42)@172.17.0.2:37579 I0709 22:37:50.728678 185408 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 91.512296ms I0709 22:37:50.728678 185419 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 91.353635ms I0709 22:37:50.728741 185408 replica.cpp:712] Persisted action NOP at position 5 I0709 22:37:50.728799 185419 replica.cpp:712] Persisted action APPEND at position 5 I0709 22:37:50.728998 185408 replica.cpp:695] Replica received learned notice for position 5 from log-network(42)@172.17.0.2:37579 I0709 22:37:50.729032 185419 replica.cpp:695] Replica received learned notice for position 5 from log-network(42)@172.17.0.2:37579 I0709 22:37:50.770504 185411 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 82.404624ms I0709 22:37:50.770570 185411 replica.cpp:712] Persisted action APPEND at position 5 I0709 22:37:50.787340 185408 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 58.314059ms I0709 22:37:50.787343 185419 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 58.285315ms I0709 22:37:50.787406 185408 replica.cpp:712] Persisted action APPEND at position 5 I0709 22:37:50.787441 185419 replica.cpp:712] Persisted action APPEND at position 5 I0709 22:37:50.789471 185416 replica.cpp:391] Replica received explicit promise request from __req_res__(945)@172.17.0.2:37579 for position 6 with proposal 2 I0709 22:37:50.789536 185408 replica.cpp:391] Replica received explicit promise request from __req_res__(946)@172.17.0.2:37579 for position 6 with proposal 2 I0709 22:37:50.789621 185416 leveldb.cpp:510] Reading position from leveldb took 103202ns I0709 22:37:50.789633 185409 replica.cpp:391] Replica received explicit promise request from __req_res__(947)@172.17.0.2:37579 for position 6 with proposal 2 I0709 22:37:50.789671 185408 leveldb.cpp:510] Reading position from leveldb took 94425ns I0709 22:37:50.841228 185416 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 51.534521ms I0709 22:37:50.841276 185409 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 51.58322ms I0709 22:37:50.841279 185408 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 51.529164ms I0709 22:37:50.841385 185408 replica.cpp:712] Persisted action APPEND at position 6 I0709 22:37:50.841295 185416 replica.cpp:712] Persisted action APPEND at position 6 I0709 22:37:50.841339 185409 replica.cpp:712] Persisted action NOP at position 6 I0709 22:37:50.842314 185417 replica.cpp:695] Replica received learned notice for position 6 from log-network(42)@172.17.0.2:37579 I0709 22:37:50.842344 185409 replica.cpp:695] Replica received learned notice for position 6 from log-network(42)@172.17.0.2:37579 I0709 22:37:50.842398 185406 replica.cpp:695] Replica received learned notice for position 6 from log-network(42)@172.17.0.2:37579 I0709 22:37:50.924829 185406 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 82.394446ms I0709 22:37:50.924831 185409 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 82.45987ms I0709 22:37:50.924831 185417 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 82.476625ms I0709 22:37:50.924940 185409 replica.cpp:712] Persisted action APPEND at position 6 I0709 22:37:50.924973 185417 replica.cpp:712] Persisted action APPEND at position 6 I0709 22:37:50.924897 185406 replica.cpp:712] Persisted action APPEND at position 6 I0709 22:37:50.926937 185412 replica.cpp:391] Replica received explicit promise request from __req_res__(948)@172.17.0.2:37579 for position 7 with proposal 2 I0709 22:37:50.927039 185416 replica.cpp:391] Replica received explicit promise request from __req_res__(949)@172.17.0.2:37579 for position 7 with proposal 2 I0709 22:37:50.927068 185412 leveldb.cpp:510] Reading position from leveldb took 91765ns I0709 22:37:50.927165 185416 leveldb.cpp:510] Reading position from leveldb took 85942ns I0709 22:37:50.927224 185415 replica.cpp:391] Replica received explicit promise request from __req_res__(950)@172.17.0.2:37579 for position 7 with proposal 2 I0709 22:37:50.974916 185416 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 47.700712ms I0709 22:37:50.974934 185415 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 47.67078ms I0709 22:37:50.975015 185416 replica.cpp:712] Persisted action APPEND at position 7 I0709 22:37:50.974934 185412 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 47.816419ms I0709 22:37:50.975064 185415 replica.cpp:712] Persisted action NOP at position 7 I0709 22:37:50.975101 185412 replica.cpp:712] Persisted action APPEND at position 7 I0709 22:37:50.976045 185407 replica.cpp:695] Replica received learned notice for position 7 from log-network(42)@172.17.0.2:37579 I0709 22:37:50.976065 185409 replica.cpp:695] Replica received learned notice for position 7 from log-network(42)@172.17.0.2:37579 I0709 22:37:50.976238 185405 replica.cpp:695] Replica received learned notice for position 7 from log-network(42)@172.17.0.2:37579 I0709 22:37:51.008458 185405 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 32.148015ms I0709 22:37:51.008494 185409 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 32.363359ms I0709 22:37:51.008474 185407 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 32.385564ms I0709 22:37:51.008585 185409 replica.cpp:712] Persisted action APPEND at position 7 I0709 22:37:51.008545 185405 replica.cpp:712] Persisted action APPEND at position 7 I0709 22:37:51.008618 185407 replica.cpp:712] Persisted action APPEND at position 7 I0709 22:37:51.010474 185411 replica.cpp:391] Replica received explicit promise request from __req_res__(951)@172.17.0.2:37579 for position 8 with proposal 2 I0709 22:37:51.010565 185405 replica.cpp:391] Replica received explicit promise request from __req_res__(952)@172.17.0.2:37579 for position 8 with proposal 2 I0709 22:37:51.010663 185411 leveldb.cpp:510] Reading position from leveldb took 142046ns I0709 22:37:51.010713 185405 leveldb.cpp:510] Reading position from leveldb took 130091ns I0709 22:37:51.010826 185418 replica.cpp:391] Replica received explicit promise request from __req_res__(953)@172.17.0.2:37579 for position 8 with proposal 2 I0709 22:37:51.050304 185405 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 39.503237ms I0709 22:37:51.050348 185411 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 39.58763ms I0709 22:37:51.050320 185418 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 39.441986ms I0709 22:37:51.050415 185411 replica.cpp:712] Persisted action APPEND at position 8 I0709 22:37:51.050396 185405 replica.cpp:712] Persisted action APPEND at position 8 I0709 22:37:51.050458 185418 replica.cpp:712] Persisted action NOP at position 8 I0709 22:37:51.051340 185411 replica.cpp:695] Replica received learned notice for position 8 from log-network(42)@172.17.0.2:37579 I0709 22:37:51.051419 185419 replica.cpp:695] Replica received learned notice for position 8 from log-network(42)@172.17.0.2:37579 I0709 22:37:51.051501 185412 replica.cpp:695] Replica received learned notice for position 8 from log-network(42)@172.17.0.2:37579 I0709 22:37:51.083894 185411 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 32.514514ms I0709 22:37:51.083894 185419 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 32.444815ms I0709 22:37:51.083981 185411 replica.cpp:712] Persisted action APPEND at position 8 I0709 22:37:51.084010 185419 replica.cpp:712] Persisted action APPEND at position 8 I0709 22:37:51.083879 185412 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 32.362581ms I0709 22:37:51.084110 185412 replica.cpp:712] Persisted action APPEND at position 8 I0709 22:37:51.086184 185419 replica.cpp:391] Replica received explicit promise request from __req_res__(954)@172.17.0.2:37579 for position 9 with proposal 2 I0709 22:37:51.086278 185411 replica.cpp:391] Replica received explicit promise request from __req_res__(955)@172.17.0.2:37579 for position 9 with proposal 2 I0709 22:37:51.086338 185406 replica.cpp:391] Replica received explicit promise request from __req_res__(956)@172.17.0.2:37579 for position 9 with proposal 2 I0709 22:37:51.086356 185419 leveldb.cpp:510] Reading position from leveldb took 124589ns I0709 22:37:51.086416 185411 leveldb.cpp:510] Reading position from leveldb took 98667ns I0709 22:37:51.125782 185411 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 39.324535ms I0709 22:37:51.125782 185419 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 39.334772ms I0709 22:37:51.125820 185406 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 39.445885ms I0709 22:37:51.125869 185411 replica.cpp:712] Persisted action APPEND at position 9 I0709 22:37:51.125900 185419 replica.cpp:712] Persisted action APPEND at position 9 I0709 22:37:51.125945 185406 replica.cpp:712] Persisted action NOP at position 9 I0709 22:37:51.127060 185413 replica.cpp:695] Replica received learned notice for position 9 from log-network(42)@172.17.0.2:37579 I0709 22:37:51.127102 185404 replica.cpp:695] Replica received learned notice for position 9 from log-network(42)@172.17.0.2:37579 I0709 22:37:51.127177 185412 replica.cpp:695] Replica received learned notice for position 9 from log-network(42)@172.17.0.2:37579 I0709 22:37:51.167652 185412 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.44364ms I0709 22:37:51.167659 185404 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.525071ms I0709 22:37:51.167775 185404 replica.cpp:712] Persisted action APPEND at position 9 I0709 22:37:51.167661 185413 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.562115ms I0709 22:37:51.167902 185413 replica.cpp:712] Persisted action APPEND at position 9 I0709 22:37:51.167721 185412 replica.cpp:712] Persisted action APPEND at position 9 I0709 22:37:51.170104 185418 replica.cpp:391] Replica received explicit promise request from __req_res__(957)@172.17.0.2:37579 for position 10 with proposal 2 I0709 22:37:51.170164 185411 replica.cpp:391] Replica received explicit promise request from __req_res__(958)@172.17.0.2:37579 for position 10 with proposal 2 I0709 22:37:51.170261 185418 leveldb.cpp:510] Reading position from leveldb took 111737ns I0709 22:37:51.170315 185411 leveldb.cpp:510] Reading position from leveldb took 110872ns I0709 22:37:51.170406 185414 replica.cpp:391] Replica received explicit promise request from __req_res__(959)@172.17.0.2:37579 for position 10 with proposal 2 I0709 22:37:51.209527 185418 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 39.199701ms I0709 22:37:51.209532 185414 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 39.075142ms I0709 22:37:51.209633 185414 replica.cpp:712] Persisted action NOP at position 10 I0709 22:37:51.209533 185411 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 39.15363ms I0709 22:37:51.209753 185411 replica.cpp:712] Persisted action APPEND at position 10 I0709 22:37:51.209595 185418 replica.cpp:712] Persisted action APPEND at position 10 I0709 22:37:51.210639 185417 replica.cpp:695] Replica received learned notice for position 10 from log-network(42)@172.17.0.2:37579 I0709 22:37:51.210777 185406 replica.cpp:695] Replica received learned notice for position 10 from log-network(42)@172.17.0.2:37579 I0709 22:37:51.210896 185413 replica.cpp:695] Replica received learned notice for position 10 from log-network(42)@172.17.0.2:37579 I0709 22:37:51.262509 185406 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 51.693272ms I0709 22:37:51.262514 185417 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 51.84048ms I0709 22:37:51.262636 185417 replica.cpp:712] Persisted action APPEND at position 10 I0709 22:37:51.262514 185413 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 51.584095ms I0709 22:37:51.262578 185406 replica.cpp:712] Persisted action APPEND at position 10 I0709 22:37:51.262739 185413 replica.cpp:712] Persisted action APPEND at position 10 I0709 22:37:51.263417 185415 catchup.cpp:357] Recover process terminated I0709 22:37:51.265594 185416 leveldb.cpp:510] Reading position from leveldb took 74001ns I0709 22:37:51.265722 185416 leveldb.cpp:510] Reading position from leveldb took 56261ns I0709 22:37:51.265831 185416 leveldb.cpp:510] Reading position from leveldb took 53563ns I0709 22:37:51.265975 185416 leveldb.cpp:510] Reading position from leveldb took 68751ns I0709 22:37:51.266114 185416 leveldb.cpp:510] Reading position from leveldb took 73905ns I0709 22:37:51.266268 185416 leveldb.cpp:510] Reading position from leveldb took 72643ns [ OK ] RecoverTest.CatchupVotingWithGap (6079 ms) [ RUN ] RecoverTest.CatchupVotingOnePosition I0709 22:37:51.414534 185403 leveldb.cpp:217] Opened db in 142.347836ms I0709 22:37:51.448020 185403 leveldb.cpp:224] Compacted db in 33.413065ms I0709 22:37:51.448122 185403 leveldb.cpp:239] Created db iterator in 49469ns I0709 22:37:51.448163 185403 leveldb.cpp:245] Seeked to beginning of db in 14952ns I0709 22:37:51.448196 185403 leveldb.cpp:320] Iterated through 0 keys in the db in 12467ns I0709 22:37:51.448277 185403 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0709 22:37:51.493314 185411 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 44.404015ms I0709 22:37:51.493379 185411 replica.cpp:322] Persisted replica status to VOTING I0709 22:37:51.611389 185403 leveldb.cpp:217] Opened db in 117.177957ms I0709 22:37:51.648083 185403 leveldb.cpp:224] Compacted db in 36.63193ms I0709 22:37:51.648169 185403 leveldb.cpp:239] Created db iterator in 40407ns I0709 22:37:51.648197 185403 leveldb.cpp:245] Seeked to beginning of db in 9717ns I0709 22:37:51.648218 185403 leveldb.cpp:320] Iterated through 0 keys in the db in 7952ns I0709 22:37:51.648281 185403 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0709 22:37:51.689460 185407 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 40.638443ms I0709 22:37:51.689517 185407 replica.cpp:322] Persisted replica status to VOTING I0709 22:37:51.807732 185403 leveldb.cpp:217] Opened db in 117.44143ms I0709 22:37:51.847872 185403 leveldb.cpp:224] Compacted db in 40.096721ms I0709 22:37:51.847952 185403 leveldb.cpp:239] Created db iterator in 32984ns I0709 22:37:51.847985 185403 leveldb.cpp:245] Seeked to beginning of db in 10732ns I0709 22:37:51.848008 185403 leveldb.cpp:320] Iterated through 0 keys in the db in 8779ns I0709 22:37:51.848057 185403 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0709 22:37:51.874578 185404 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 26.124801ms I0709 22:37:51.874636 185404 replica.cpp:322] Persisted replica status to VOTING I0709 22:37:51.997138 185403 leveldb.cpp:217] Opened db in 121.841702ms I0709 22:37:52.089548 185403 leveldb.cpp:224] Compacted db in 92.344695ms I0709 22:37:52.089637 185403 leveldb.cpp:239] Created db iterator in 44099ns I0709 22:37:52.089689 185403 leveldb.cpp:245] Seeked to beginning of db in 33754ns I0709 22:37:52.089766 185403 leveldb.cpp:320] Iterated through 1 keys in the db in 62111ns I0709 22:37:52.089839 185403 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0709 22:37:52.184813 185403 leveldb.cpp:217] Opened db in 94.603747ms I0709 22:37:52.273263 185403 leveldb.cpp:224] Compacted db in 88.41135ms I0709 22:37:52.273376 185403 leveldb.cpp:239] Created db iterator in 47451ns I0709 22:37:52.273434 185403 leveldb.cpp:245] Seeked to beginning of db in 40112ns I0709 22:37:52.273510 185403 leveldb.cpp:320] Iterated through 1 keys in the db in 59501ns I0709 22:37:52.273579 185403 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0709 22:37:52.411525 185403 leveldb.cpp:217] Opened db in 137.598182ms I0709 22:37:52.521397 185403 leveldb.cpp:224] Compacted db in 109.832302ms I0709 22:37:52.521490 185403 leveldb.cpp:239] Created db iterator in 43156ns I0709 22:37:52.521545 185403 leveldb.cpp:245] Seeked to beginning of db in 34864ns I0709 22:37:52.521618 185403 leveldb.cpp:320] Iterated through 1 keys in the db in 54009ns I0709 22:37:52.521687 185403 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0709 22:37:52.522408 185418 catchup.cpp:342] Starting missing positions recovery I0709 22:37:52.522907 185407 catchup.cpp:368] Replica is in VOTING status I0709 22:37:52.524446 185411 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(960)@172.17.0.2:37579 I0709 22:37:52.524636 185413 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(961)@172.17.0.2:37579 I0709 22:37:52.524678 185406 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(962)@172.17.0.2:37579 I0709 22:37:52.525552 185409 recover.cpp:197] Received a recover response from a replica in VOTING status I0709 22:37:52.526018 185409 recover.cpp:197] Received a recover response from a replica in VOTING status I0709 22:37:52.527282 185417 catchup.cpp:357] Recover process terminated [ OK ] RecoverTest.CatchupVotingOnePosition (1262 ms) [----------] 9 tests from RecoverTest (32814 ms total) [----------] 4 tests from LogTest [ RUN ] LogTest.WriteRead I0709 22:37:52.633843 185403 leveldb.cpp:217] Opened db in 99.91286ms I0709 22:37:52.667346 185403 leveldb.cpp:224] Compacted db in 33.461981ms I0709 22:37:52.667471 185403 leveldb.cpp:239] Created db iterator in 54940ns I0709 22:37:52.667526 185403 leveldb.cpp:245] Seeked to beginning of db in 20885ns I0709 22:37:52.667567 185403 leveldb.cpp:320] Iterated through 0 keys in the db in 15072ns I0709 22:37:52.667666 185403 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0709 22:37:52.712098 185418 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 43.721741ms I0709 22:37:52.712206 185418 replica.cpp:322] Persisted replica status to VOTING I0709 22:37:52.805229 185403 leveldb.cpp:217] Opened db in 92.029772ms I0709 22:37:52.825752 185403 leveldb.cpp:224] Compacted db in 20.47877ms I0709 22:37:52.825899 185403 leveldb.cpp:239] Created db iterator in 53705ns I0709 22:37:52.825937 185403 leveldb.cpp:245] Seeked to beginning of db in 14305ns I0709 22:37:52.825963 185403 leveldb.cpp:320] Iterated through 0 keys in the db in 8875ns I0709 22:37:52.826035 185403 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0709 22:37:52.867175 185414 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 40.556202ms I0709 22:37:52.867266 185414 replica.cpp:322] Persisted replica status to VOTING I0709 22:37:52.985769 185403 leveldb.cpp:217] Opened db in 117.528882ms I0709 22:37:53.101187 185403 leveldb.cpp:224] Compacted db in 115.371642ms I0709 22:37:53.101351 185403 leveldb.cpp:239] Created db iterator in 61924ns I0709 22:37:53.101416 185403 leveldb.cpp:245] Seeked to beginning of db in 48486ns I0709 22:37:53.101492 185403 leveldb.cpp:320] Iterated through 1 keys in the db in 62442ns I0709 22:37:53.101562 185403 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0709 22:37:53.201364 185403 leveldb.cpp:217] Opened db in 99.403563ms I0709 22:37:53.317880 185403 leveldb.cpp:224] Compacted db in 116.470503ms I0709 22:37:53.318033 185403 leveldb.cpp:239] Created db iterator in 58398ns I0709 22:37:53.318095 185403 leveldb.cpp:245] Seeked to beginning of db in 47301ns I0709 22:37:53.318171 185403 leveldb.cpp:320] Iterated through 1 keys in the db in 61936ns I0709 22:37:53.318240 185403 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0709 22:37:53.319394 185405 recover.cpp:437] Starting replica recovery I0709 22:37:53.319840 185405 recover.cpp:468] Replica is in VOTING status I0709 22:37:53.320093 185405 recover.cpp:447] Recover process terminated I0709 22:37:53.320600 185408 log.cpp:554] Attempting to start the writer I0709 22:37:53.322465 185406 replica.cpp:497] Replica received implicit promise request from __req_res__(963)@172.17.0.2:37579 with proposal 1 I0709 22:37:53.322592 185416 replica.cpp:497] Replica received implicit promise request from __req_res__(964)@172.17.0.2:37579 with proposal 1 I0709 22:37:53.369951 185406 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 47.469473ms I0709 22:37:53.370054 185406 replica.cpp:344] Persisted promised to 1 I0709 22:37:53.386708 185416 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 64.083673ms I0709 22:37:53.386790 185416 replica.cpp:344] Persisted promised to 1 I0709 22:37:53.387744 185411 coordinator.cpp:238] Coordinator attempting to fill missing positions I0709 22:37:53.389461 185416 replica.cpp:391] Replica received explicit promise request from __req_res__(965)@172.17.0.2:37579 for position 0 with proposal 2 I0709 22:37:53.389518 185417 replica.cpp:391] Replica received explicit promise request from __req_res__(966)@172.17.0.2:37579 for position 0 with proposal 2 I0709 22:37:53.428519 185417 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 38.951072ms I0709 22:37:53.428519 185416 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 39.00332ms I0709 22:37:53.428586 185417 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:53.428627 185416 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:53.430004 185409 replica.cpp:541] Replica received write request for position 0 from __req_res__(967)@172.17.0.2:37579 I0709 22:37:53.430095 185407 replica.cpp:541] Replica received write request for position 0 from __req_res__(968)@172.17.0.2:37579 I0709 22:37:53.430107 185409 leveldb.cpp:510] Reading position from leveldb took 59776ns I0709 22:37:53.430205 185407 leveldb.cpp:510] Reading position from leveldb took 63506ns I0709 22:37:53.470301 185409 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 40.073184ms I0709 22:37:53.470302 185407 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 40.038197ms I0709 22:37:53.470367 185409 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:53.470422 185407 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:53.471108 185406 replica.cpp:695] Replica received learned notice for position 0 from log-network(44)@172.17.0.2:37579 I0709 22:37:53.471128 185408 replica.cpp:695] Replica received learned notice for position 0 from log-network(44)@172.17.0.2:37579 I0709 22:37:53.512153 185408 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 40.964481ms I0709 22:37:53.512153 185406 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 40.998481ms I0709 22:37:53.512235 185408 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:53.512264 185406 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:53.512962 185411 log.cpp:570] Writer started with ending position 0 I0709 22:37:53.513772 185419 log.cpp:578] Attempting to append 11 bytes to the log I0709 22:37:53.513972 185415 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 I0709 22:37:53.514881 185404 replica.cpp:541] Replica received write request for position 1 from __req_res__(969)@172.17.0.2:37579 I0709 22:37:53.514940 185411 replica.cpp:541] Replica received write request for position 1 from __req_res__(970)@172.17.0.2:37579 I0709 22:37:53.559159 185404 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 44.222418ms I0709 22:37:53.559168 185411 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 44.178449ms I0709 22:37:53.559229 185404 replica.cpp:712] Persisted action APPEND at position 1 I0709 22:37:53.559283 185411 replica.cpp:712] Persisted action APPEND at position 1 I0709 22:37:53.560112 185407 replica.cpp:695] Replica received learned notice for position 1 from log-network(44)@172.17.0.2:37579 I0709 22:37:53.560174 185415 replica.cpp:695] Replica received learned notice for position 1 from log-network(44)@172.17.0.2:37579 I0709 22:37:53.600956 185407 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 40.808319ms I0709 22:37:53.600962 185415 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 40.753247ms I0709 22:37:53.601024 185407 replica.cpp:712] Persisted action APPEND at position 1 I0709 22:37:53.601081 185415 replica.cpp:712] Persisted action APPEND at position 1 I0709 22:37:53.603147 185418 leveldb.cpp:510] Reading position from leveldb took 79928ns [ OK ] LogTest.WriteRead (1075 ms) [ RUN ] LogTest.Position I0709 22:37:53.686172 185403 leveldb.cpp:217] Opened db in 77.303381ms I0709 22:37:53.722685 185403 leveldb.cpp:224] Compacted db in 36.44999ms I0709 22:37:53.722823 185403 leveldb.cpp:239] Created db iterator in 47478ns I0709 22:37:53.722862 185403 leveldb.cpp:245] Seeked to beginning of db in 15108ns I0709 22:37:53.722890 185403 leveldb.cpp:320] Iterated through 0 keys in the db in 11240ns I0709 22:37:53.722970 185403 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0709 22:37:53.754308 185417 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 30.714665ms I0709 22:37:53.754410 185417 replica.cpp:322] Persisted replica status to VOTING I0709 22:37:53.914907 185403 leveldb.cpp:217] Opened db in 159.578517ms I0709 22:37:53.947948 185403 leveldb.cpp:224] Compacted db in 32.968983ms I0709 22:37:53.948064 185403 leveldb.cpp:239] Created db iterator in 42028ns I0709 22:37:53.948089 185403 leveldb.cpp:245] Seeked to beginning of db in 9212ns I0709 22:37:53.948107 185403 leveldb.cpp:320] Iterated through 0 keys in the db in 6888ns I0709 22:37:53.948168 185403 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0709 22:37:53.986217 185416 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 37.496366ms I0709 22:37:53.986306 185416 replica.cpp:322] Persisted replica status to VOTING I0709 22:37:54.121261 185403 leveldb.cpp:217] Opened db in 134.014971ms I0709 22:37:54.231534 185403 leveldb.cpp:224] Compacted db in 110.218105ms I0709 22:37:54.231662 185403 leveldb.cpp:239] Created db iterator in 53119ns I0709 22:37:54.231724 185403 leveldb.cpp:245] Seeked to beginning of db in 38676ns I0709 22:37:54.231808 185403 leveldb.cpp:320] Iterated through 1 keys in the db in 67203ns I0709 22:37:54.231889 185403 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0709 22:37:54.366964 185403 leveldb.cpp:217] Opened db in 134.655381ms I0709 22:37:54.498136 185403 leveldb.cpp:224] Compacted db in 131.146332ms I0709 22:37:54.498267 185403 leveldb.cpp:239] Created db iterator in 54786ns I0709 22:37:54.498342 185403 leveldb.cpp:245] Seeked to beginning of db in 59634ns I0709 22:37:54.498435 185403 leveldb.cpp:320] Iterated through 1 keys in the db in 68596ns I0709 22:37:54.498513 185403 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0709 22:37:54.499585 185405 recover.cpp:437] Starting replica recovery I0709 22:37:54.500139 185417 recover.cpp:468] Replica is in VOTING status I0709 22:37:54.500424 185417 recover.cpp:447] Recover process terminated I0709 22:37:54.501013 185412 log.cpp:554] Attempting to start the writer I0709 22:37:54.503021 185405 replica.cpp:497] Replica received implicit promise request from __req_res__(971)@172.17.0.2:37579 with proposal 1 I0709 22:37:54.503077 185409 replica.cpp:497] Replica received implicit promise request from __req_res__(972)@172.17.0.2:37579 with proposal 1 I0709 22:37:54.537735 185409 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 34.628821ms I0709 22:37:54.537838 185409 replica.cpp:344] Persisted promised to 1 I0709 22:37:54.554502 185405 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 51.419159ms I0709 22:37:54.554572 185405 replica.cpp:344] Persisted promised to 1 I0709 22:37:54.555572 185408 coordinator.cpp:238] Coordinator attempting to fill missing positions I0709 22:37:54.557354 185415 replica.cpp:391] Replica received explicit promise request from __req_res__(973)@172.17.0.2:37579 for position 0 with proposal 2 I0709 22:37:54.557471 185411 replica.cpp:391] Replica received explicit promise request from __req_res__(974)@172.17.0.2:37579 for position 0 with proposal 2 I0709 22:37:54.622754 185411 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 65.24259ms I0709 22:37:54.622777 185415 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 65.370944ms I0709 22:37:54.622860 185411 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:54.622905 185415 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:54.624506 185418 replica.cpp:541] Replica received write request for position 0 from __req_res__(975)@172.17.0.2:37579 I0709 22:37:54.624536 185404 replica.cpp:541] Replica received write request for position 0 from __req_res__(976)@172.17.0.2:37579 I0709 22:37:54.624644 185404 leveldb.cpp:510] Reading position from leveldb took 69734ns I0709 22:37:54.624644 185418 leveldb.cpp:510] Reading position from leveldb took 89862ns I0709 22:37:54.666781 185404 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 42.059428ms I0709 22:37:54.666785 185418 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 42.044149ms I0709 22:37:54.666852 185404 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:54.666888 185418 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:54.667579 185419 replica.cpp:695] Replica received learned notice for position 0 from log-network(45)@172.17.0.2:37579 I0709 22:37:54.667670 185416 replica.cpp:695] Replica received learned notice for position 0 from log-network(45)@172.17.0.2:37579 I0709 22:37:54.708576 185419 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 40.963421ms I0709 22:37:54.708580 185416 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 40.865022ms I0709 22:37:54.708652 185419 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:54.708696 185416 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:54.709538 185410 log.cpp:570] Writer started with ending position 0 I0709 22:37:54.710278 185415 log.cpp:578] Attempting to append 11 bytes to the log I0709 22:37:54.710436 185409 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 I0709 22:37:54.711373 185414 replica.cpp:541] Replica received write request for position 1 from __req_res__(977)@172.17.0.2:37579 I0709 22:37:54.711448 185404 replica.cpp:541] Replica received write request for position 1 from __req_res__(978)@172.17.0.2:37579 I0709 22:37:54.750396 185414 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 38.96009ms I0709 22:37:54.750398 185404 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 38.896684ms I0709 22:37:54.750461 185414 replica.cpp:712] Persisted action APPEND at position 1 I0709 22:37:54.750507 185404 replica.cpp:712] Persisted action APPEND at position 1 I0709 22:37:54.751332 185411 replica.cpp:695] Replica received learned notice for position 1 from log-network(45)@172.17.0.2:37579 I0709 22:37:54.751441 185408 replica.cpp:695] Replica received learned notice for position 1 from log-network(45)@172.17.0.2:37579 I0709 22:37:54.792212 185411 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 40.840275ms I0709 22:37:54.792212 185408 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 40.738766ms I0709 22:37:54.792282 185411 replica.cpp:712] Persisted action APPEND at position 1 I0709 22:37:54.792330 185408 replica.cpp:712] Persisted action APPEND at position 1 [ OK ] LogTest.Position (1189 ms) [ RUN ] LogTest.Metrics I0709 22:37:54.957059 185403 leveldb.cpp:217] Opened db in 159.462277ms I0709 22:37:55.006381 185403 leveldb.cpp:224] Compacted db in 49.25026ms I0709 22:37:55.006472 185403 leveldb.cpp:239] Created db iterator in 43964ns I0709 22:37:55.006502 185403 leveldb.cpp:245] Seeked to beginning of db in 10052ns I0709 22:37:55.006521 185403 leveldb.cpp:320] Iterated through 0 keys in the db in 8157ns I0709 22:37:55.006592 185403 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0709 22:37:55.039261 185416 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 32.007381ms I0709 22:37:55.039352 185416 replica.cpp:322] Persisted replica status to VOTING I0709 22:37:55.142076 185403 leveldb.cpp:217] Opened db in 101.907879ms I0709 22:37:55.301357 185403 leveldb.cpp:224] Compacted db in 159.238712ms I0709 22:37:55.301494 185403 leveldb.cpp:239] Created db iterator in 53068ns I0709 22:37:55.301554 185403 leveldb.cpp:245] Seeked to beginning of db in 41946ns I0709 22:37:55.301635 185403 leveldb.cpp:320] Iterated through 1 keys in the db in 65176ns I0709 22:37:55.301728 185403 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0709 22:37:55.302693 185405 recover.cpp:437] Starting replica recovery I0709 22:37:55.303256 185416 recover.cpp:468] Replica is in VOTING status I0709 22:37:55.303579 185416 recover.cpp:447] Recover process terminated I0709 22:37:55.304216 185406 log.cpp:554] Attempting to start the writer I0709 22:37:55.306221 185411 replica.cpp:497] Replica received implicit promise request from __req_res__(979)@172.17.0.2:37579 with proposal 1 I0709 22:37:55.336311 185411 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 30.046654ms I0709 22:37:55.336380 185411 replica.cpp:344] Persisted promised to 1 I0709 22:37:55.337342 185416 coordinator.cpp:238] Coordinator attempting to fill missing positions I0709 22:37:55.339184 185411 replica.cpp:391] Replica received explicit promise request from __req_res__(980)@172.17.0.2:37579 for position 0 with proposal 2 I0709 22:37:55.378191 185411 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 38.963915ms I0709 22:37:55.378271 185411 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:55.379704 185413 replica.cpp:541] Replica received write request for position 0 from __req_res__(981)@172.17.0.2:37579 I0709 22:37:55.379845 185413 leveldb.cpp:510] Reading position from leveldb took 78675ns I0709 22:37:55.428643 185413 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 48.739589ms I0709 22:37:55.428712 185413 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:55.429551 185408 replica.cpp:695] Replica received learned notice for position 0 from log-network(46)@172.17.0.2:37579 I0709 22:37:55.458372 185408 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 28.787089ms I0709 22:37:55.458438 185408 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:55.459241 185413 log.cpp:570] Writer started with ending position 0 I0709 22:37:55.463765 185418 process.cpp:3671] Handling HTTP event for process 'metrics' with path: '/metrics/snapshot' [ OK ] LogTest.Metrics (676 ms) [ RUN ] LogTest.ReaderCatchup I0709 22:37:55.594249 185403 leveldb.cpp:217] Opened db in 120.411364ms I0709 22:37:55.626125 185403 leveldb.cpp:224] Compacted db in 31.817657ms I0709 22:37:55.626217 185403 leveldb.cpp:239] Created db iterator in 43956ns I0709 22:37:55.626248 185403 leveldb.cpp:245] Seeked to beginning of db in 9983ns I0709 22:37:55.626268 185403 leveldb.cpp:320] Iterated through 0 keys in the db in 8217ns I0709 22:37:55.626339 185403 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0709 22:37:55.662225 185405 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 35.235507ms I0709 22:37:55.662317 185405 replica.cpp:322] Persisted replica status to VOTING I0709 22:37:55.798161 185403 leveldb.cpp:217] Opened db in 134.951104ms I0709 22:37:55.823319 185403 leveldb.cpp:224] Compacted db in 25.105744ms I0709 22:37:55.823413 185403 leveldb.cpp:239] Created db iterator in 45272ns I0709 22:37:55.823447 185403 leveldb.cpp:245] Seeked to beginning of db in 11410ns I0709 22:37:55.823472 185403 leveldb.cpp:320] Iterated through 0 keys in the db in 12305ns I0709 22:37:55.823555 185403 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0709 22:37:55.861387 185411 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 37.278797ms I0709 22:37:55.861450 185411 replica.cpp:322] Persisted replica status to VOTING I0709 22:37:56.004662 185403 leveldb.cpp:217] Opened db in 142.576035ms I0709 22:37:56.057665 185403 leveldb.cpp:224] Compacted db in 52.943442ms I0709 22:37:56.057771 185403 leveldb.cpp:239] Created db iterator in 44884ns I0709 22:37:56.057806 185403 leveldb.cpp:245] Seeked to beginning of db in 11645ns I0709 22:37:56.057827 185403 leveldb.cpp:320] Iterated through 0 keys in the db in 9540ns I0709 22:37:56.057904 185403 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0709 22:37:56.098572 185408 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 40.079368ms I0709 22:37:56.098654 185408 replica.cpp:322] Persisted replica status to VOTING I0709 22:37:56.191866 185403 leveldb.cpp:217] Opened db in 92.393608ms I0709 22:37:56.304618 185403 leveldb.cpp:224] Compacted db in 112.723792ms I0709 22:37:56.304706 185403 leveldb.cpp:239] Created db iterator in 36552ns I0709 22:37:56.304757 185403 leveldb.cpp:245] Seeked to beginning of db in 32971ns I0709 22:37:56.304831 185403 leveldb.cpp:320] Iterated through 1 keys in the db in 56898ns I0709 22:37:56.304884 185403 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0709 22:37:56.425411 185403 leveldb.cpp:217] Opened db in 120.312347ms I0709 22:37:56.529567 185403 leveldb.cpp:224] Compacted db in 104.120466ms I0709 22:37:56.529659 185403 leveldb.cpp:239] Created db iterator in 46969ns I0709 22:37:56.529734 185403 leveldb.cpp:245] Seeked to beginning of db in 48447ns I0709 22:37:56.529816 185403 leveldb.cpp:320] Iterated through 1 keys in the db in 56408ns I0709 22:37:56.529891 185403 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0709 22:37:56.532225 185419 replica.cpp:497] Replica received implicit promise request from __req_res__(982)@172.17.0.2:37579 with proposal 1 I0709 22:37:56.532291 185411 replica.cpp:497] Replica received implicit promise request from __req_res__(983)@172.17.0.2:37579 with proposal 1 I0709 22:37:56.559458 185419 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 27.183906ms I0709 22:37:56.559516 185419 replica.cpp:344] Persisted promised to 1 I0709 22:37:56.576304 185411 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 43.97737ms I0709 22:37:56.576365 185411 replica.cpp:344] Persisted promised to 1 I0709 22:37:56.577281 185410 coordinator.cpp:238] Coordinator attempting to fill missing positions I0709 22:37:56.579001 185411 replica.cpp:391] Replica received explicit promise request from __req_res__(984)@172.17.0.2:37579 for position 0 with proposal 2 I0709 22:37:56.579082 185404 replica.cpp:391] Replica received explicit promise request from __req_res__(985)@172.17.0.2:37579 for position 0 with proposal 2 I0709 22:37:56.601478 185404 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 22.3236ms I0709 22:37:56.601552 185404 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:56.604259 185411 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 25.204246ms I0709 22:37:56.604319 185411 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:56.605711 185407 replica.cpp:541] Replica received write request for position 0 from __req_res__(986)@172.17.0.2:37579 I0709 22:37:56.605787 185409 replica.cpp:541] Replica received write request for position 0 from __req_res__(987)@172.17.0.2:37579 I0709 22:37:56.605823 185407 leveldb.cpp:510] Reading position from leveldb took 65581ns I0709 22:37:56.605885 185409 leveldb.cpp:510] Reading position from leveldb took 58388ns I0709 22:37:56.626549 185407 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 20.662313ms I0709 22:37:56.626610 185407 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:56.629657 185409 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 23.713308ms I0709 22:37:56.629719 185409 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:56.630424 185413 replica.cpp:695] Replica received learned notice for position 0 from log-network(47)@172.17.0.2:37579 I0709 22:37:56.630421 185408 replica.cpp:695] Replica received learned notice for position 0 from log-network(47)@172.17.0.2:37579 I0709 22:37:56.698125 185413 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 67.670086ms I0709 22:37:56.698127 185408 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 67.630507ms I0709 22:37:56.698195 185413 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:56.698254 185408 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:56.699445 185414 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 I0709 22:37:56.700428 185407 replica.cpp:541] Replica received write request for position 1 from __req_res__(988)@172.17.0.2:37579 I0709 22:37:56.700480 185408 replica.cpp:541] Replica received write request for position 1 from __req_res__(989)@172.17.0.2:37579 I0709 22:37:56.756613 185407 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 56.130141ms I0709 22:37:56.756618 185408 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 56.094145ms I0709 22:37:56.756682 185407 replica.cpp:712] Persisted action APPEND at position 1 I0709 22:37:56.756717 185408 replica.cpp:712] Persisted action APPEND at position 1 I0709 22:37:56.757392 185416 replica.cpp:695] Replica received learned notice for position 1 from log-network(47)@172.17.0.2:37579 I0709 22:37:56.757387 185414 replica.cpp:695] Replica received learned notice for position 1 from log-network(47)@172.17.0.2:37579 I0709 22:37:56.806810 185414 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.347807ms I0709 22:37:56.806810 185416 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.381321ms I0709 22:37:56.806890 185414 replica.cpp:712] Persisted action APPEND at position 1 I0709 22:37:56.806922 185416 replica.cpp:712] Persisted action APPEND at position 1 I0709 22:37:56.808115 185417 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 2 I0709 22:37:56.808957 185407 replica.cpp:541] Replica received write request for position 2 from __req_res__(990)@172.17.0.2:37579 I0709 22:37:56.809082 185418 replica.cpp:541] Replica received write request for position 2 from __req_res__(991)@172.17.0.2:37579 I0709 22:37:56.856958 185418 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.82883ms I0709 22:37:56.856958 185407 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.94787ms I0709 22:37:56.857036 185418 replica.cpp:712] Persisted action APPEND at position 2 I0709 22:37:56.857064 185407 replica.cpp:712] Persisted action APPEND at position 2 I0709 22:37:56.857751 185415 replica.cpp:695] Replica received learned notice for position 2 from log-network(47)@172.17.0.2:37579 I0709 22:37:56.857755 185419 replica.cpp:695] Replica received learned notice for position 2 from log-network(47)@172.17.0.2:37579 I0709 22:37:56.907119 185415 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.336675ms I0709 22:37:56.907120 185419 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.304786ms I0709 22:37:56.907186 185415 replica.cpp:712] Persisted action APPEND at position 2 I0709 22:37:56.907238 185419 replica.cpp:712] Persisted action APPEND at position 2 I0709 22:37:56.908288 185408 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3 I0709 22:37:56.909313 185417 replica.cpp:541] Replica received write request for position 3 from __req_res__(992)@172.17.0.2:37579 I0709 22:37:56.909400 185415 replica.cpp:541] Replica received write request for position 3 from __req_res__(993)@172.17.0.2:37579 I0709 22:37:56.957254 185415 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.802036ms I0709 22:37:56.957255 185417 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.889431ms I0709 22:37:56.957321 185415 replica.cpp:712] Persisted action APPEND at position 3 I0709 22:37:56.957369 185417 replica.cpp:712] Persisted action APPEND at position 3 I0709 22:37:56.958165 185411 replica.cpp:695] Replica received learned notice for position 3 from log-network(47)@172.17.0.2:37579 I0709 22:37:56.958197 185413 replica.cpp:695] Replica received learned notice for position 3 from log-network(47)@172.17.0.2:37579 I0709 22:37:57.007433 185413 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.205581ms I0709 22:37:57.007433 185411 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.228723ms I0709 22:37:57.007501 185413 replica.cpp:712] Persisted action APPEND at position 3 I0709 22:37:57.007555 185411 replica.cpp:712] Persisted action APPEND at position 3 I0709 22:37:57.008661 185404 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 4 I0709 22:37:57.009676 185407 replica.cpp:541] Replica received write request for position 4 from __req_res__(994)@172.17.0.2:37579 I0709 22:37:57.009721 185416 replica.cpp:541] Replica received write request for position 4 from __req_res__(995)@172.17.0.2:37579 I0709 22:37:57.057509 185407 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.775867ms I0709 22:37:57.057564 185416 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.798726ms I0709 22:37:57.057576 185407 replica.cpp:712] Persisted action APPEND at position 4 I0709 22:37:57.057629 185416 replica.cpp:712] Persisted action APPEND at position 4 I0709 22:37:57.058421 185404 replica.cpp:695] Replica received learned notice for position 4 from log-network(47)@172.17.0.2:37579 I0709 22:37:57.058435 185405 replica.cpp:695] Replica received learned notice for position 4 from log-network(47)@172.17.0.2:37579 I0709 22:37:57.107736 185404 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.269013ms I0709 22:37:57.107736 185405 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.236104ms I0709 22:37:57.107810 185404 replica.cpp:712] Persisted action APPEND at position 4 I0709 22:37:57.107858 185405 replica.cpp:712] Persisted action APPEND at position 4 I0709 22:37:57.108953 185416 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 5 I0709 22:37:57.109915 185404 replica.cpp:541] Replica received write request for position 5 from __req_res__(996)@172.17.0.2:37579 I0709 22:37:57.109987 185405 replica.cpp:541] Replica received write request for position 5 from __req_res__(997)@172.17.0.2:37579 I0709 22:37:57.157801 185404 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.83608ms I0709 22:37:57.157821 185405 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 47.783522ms I0709 22:37:57.157864 185404 replica.cpp:712] Persisted action APPEND at position 5 I0709 22:37:57.157888 185405 replica.cpp:712] Persisted action APPEND at position 5 I0709 22:37:57.158639 185419 replica.cpp:695] Replica received learned notice for position 5 from log-network(47)@172.17.0.2:37579 I0709 22:37:57.158710 185418 replica.cpp:695] Replica received learned notice for position 5 from log-network(47)@172.17.0.2:37579 I0709 22:37:57.208025 185418 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.268352ms I0709 22:37:57.208025 185419 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 49.349872ms I0709 22:37:57.208092 185418 replica.cpp:712] Persisted action APPEND at position 5 I0709 22:37:57.208141 185419 replica.cpp:712] Persisted action APPEND at position 5 I0709 22:37:57.209213 185405 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 6 I0709 22:37:57.210027 185419 replica.cpp:541] Replica received write request for position 6 from __req_res__(998)@172.17.0.2:37579 I0709 22:37:57.210212 185411 replica.cpp:541] Replica received write request for position 6 from __req_res__(999)@172.17.0.2:37579 I0709 22:37:57.266505 185419 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 56.430378ms I0709 22:37:57.266505 185411 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 56.248521ms I0709 22:37:57.266572 185419 replica.cpp:712] Persisted action APPEND at position 6 I0709 22:37:57.266626 185411 replica.cpp:712] Persisted action APPEND at position 6 I0709 22:37:57.267372 185408 replica.cpp:695] Replica received learned notice for position 6 from log-network(47)@172.17.0.2:37579 I0709 22:37:57.267477 185416 replica.cpp:695] Replica received learned notice for position 6 from log-network(47)@172.17.0.2:37579 I0709 22:37:57.318462 185416 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 50.954783ms I0709 22:37:57.318464 185408 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 51.059834ms I0709 22:37:57.318532 185416 replica.cpp:712] Persisted action APPEND at position 6 I0709 22:37:57.318589 185408 replica.cpp:712] Persisted action APPEND at position 6 I0709 22:37:57.319691 185407 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 7 I0709 22:37:57.320657 185405 replica.cpp:541] Replica received write request for position 7 from __req_res__(1000)@172.17.0.2:37579 I0709 22:37:57.320720 185409 replica.cpp:541] Replica received write request for position 7 from __req_res__(1001)@172.17.0.2:37579 I0709 22:37:57.351912 185405 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 31.203171ms I0709 22:37:57.351980 185405 replica.cpp:712] Persisted action APPEND at position 7 I0709 22:37:57.354665 185409 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 33.903803ms I0709 22:37:57.354741 185409 replica.cpp:712] Persisted action APPEND at position 7 I0709 22:37:57.355595 185412 replica.cpp:695] Replica received learned notice for position 7 from log-network(47)@172.17.0.2:37579 I0709 22:37:57.355618 185414 replica.cpp:695] Replica received learned notice for position 7 from log-network(47)@172.17.0.2:37579 I0709 22:37:57.377063 185414 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 21.395088ms I0709 22:37:57.377126 185414 replica.cpp:712] Persisted action APPEND at position 7 I0709 22:37:57.378142 185418 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 8 I0709 22:37:57.379113 185411 replica.cpp:541] Replica received write request for position 8 from __req_res__(1003)@172.17.0.2:37579 I0709 22:37:57.379242 185412 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 23.606579ms I0709 22:37:57.379321 185412 replica.cpp:712] Persisted action APPEND at position 7 I0709 22:37:57.379423 185412 replica.cpp:541] Replica received write request for position 8 from __req_res__(1002)@172.17.0.2:37579 I0709 22:37:57.410547 185411 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 31.378846ms I0709 22:37:57.410611 185411 replica.cpp:712] Persisted action APPEND at position 8 I0709 22:37:57.412590 185412 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 33.131857ms I0709 22:37:57.412654 185412 replica.cpp:712] Persisted action APPEND at position 8 I0709 22:37:57.413343 185415 replica.cpp:695] Replica received learned notice for position 8 from log-network(47)@172.17.0.2:37579 I0709 22:37:57.413406 185406 replica.cpp:695] Replica received learned notice for position 8 from log-network(47)@172.17.0.2:37579 I0709 22:37:57.435685 185415 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 22.302752ms I0709 22:37:57.435748 185415 replica.cpp:712] Persisted action APPEND at position 8 I0709 22:37:57.437995 185406 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 24.561797ms I0709 22:37:57.438058 185406 replica.cpp:712] Persisted action APPEND at position 8 I0709 22:37:57.439031 185408 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 9 I0709 22:37:57.439941 185404 replica.cpp:541] Replica received write request for position 9 from __req_res__(1004)@172.17.0.2:37579 I0709 22:37:57.440023 185411 replica.cpp:541] Replica received write request for position 9 from __req_res__(1005)@172.17.0.2:37579 I0709 22:37:57.460839 185411 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 20.77489ms I0709 22:37:57.460902 185411 replica.cpp:712] Persisted action APPEND at position 9 I0709 22:37:57.462595 185404 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 22.604166ms I0709 22:37:57.462658 185404 replica.cpp:712] Persisted action APPEND at position 9 I0709 22:37:57.463364 185406 replica.cpp:695] Replica received learned notice for position 9 from log-network(47)@172.17.0.2:37579 I0709 22:37:57.463390 185419 replica.cpp:695] Replica received learned notice for position 9 from log-network(47)@172.17.0.2:37579 I0709 22:37:57.485997 185406 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 22.58337ms I0709 22:37:57.486061 185406 replica.cpp:712] Persisted action APPEND at position 9 I0709 22:37:57.487985 185419 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 24.544688ms I0709 22:37:57.488049 185419 replica.cpp:712] Persisted action APPEND at position 9 I0709 22:37:57.489111 185414 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 10 I0709 22:37:57.490054 185408 replica.cpp:541] Replica received write request for position 10 from __req_res__(1006)@172.17.0.2:37579 I0709 22:37:57.490135 185409 replica.cpp:541] Replica received write request for position 10 from __req_res__(1007)@172.17.0.2:37579 I0709 22:37:57.511134 185409 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 20.959117ms I0709 22:37:57.511199 185409 replica.cpp:712] Persisted action APPEND at position 10 I0709 22:37:57.512593 185408 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 22.487914ms I0709 22:37:57.512657 185408 replica.cpp:712] Persisted action APPEND at position 10 I0709 22:37:57.513317 185417 replica.cpp:695] Replica received learned notice for position 10 from log-network(47)@172.17.0.2:37579 I0709 22:37:57.513350 185410 replica.cpp:695] Replica received learned notice for position 10 from log-network(47)@172.17.0.2:37579 I0709 22:37:57.536285 185417 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 22.9324ms I0709 22:37:57.536350 185417 replica.cpp:712] Persisted action APPEND at position 10 I0709 22:37:57.537982 185410 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 24.605816ms I0709 22:37:57.538045 185410 replica.cpp:712] Persisted action APPEND at position 10 I0709 22:37:57.676082 185403 leveldb.cpp:217] Opened db in 136.992401ms I0709 22:37:57.783020 185403 leveldb.cpp:224] Compacted db in 106.906555ms I0709 22:37:57.783118 185403 leveldb.cpp:239] Created db iterator in 45421ns I0709 22:37:57.783170 185403 leveldb.cpp:245] Seeked to beginning of db in 33074ns I0709 22:37:57.783236 185403 leveldb.cpp:320] Iterated through 1 keys in the db in 50011ns I0709 22:37:57.783301 185403 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0709 22:37:57.784128 185419 recover.cpp:437] Starting replica recovery I0709 22:37:57.784570 185419 recover.cpp:468] Replica is in VOTING status I0709 22:37:57.784813 185419 recover.cpp:447] Recover process terminated I0709 22:37:57.785449 185415 catchup.cpp:342] Starting missing positions recovery I0709 22:37:57.785823 185416 catchup.cpp:368] Replica is in VOTING status I0709 22:37:57.787252 185407 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(1008)@172.17.0.2:37579 I0709 22:37:57.787454 185407 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(1009)@172.17.0.2:37579 I0709 22:37:57.787616 185411 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(1010)@172.17.0.2:37579 I0709 22:37:57.788447 185409 recover.cpp:197] Received a recover response from a replica in VOTING status I0709 22:37:57.788872 185409 recover.cpp:197] Received a recover response from a replica in VOTING status I0709 22:37:57.789911 185419 catchup.cpp:423] Starting catch-up from position 0 to 9 I0709 22:37:57.791813 185410 replica.cpp:391] Replica received explicit promise request from __req_res__(1011)@172.17.0.2:37579 for position 0 with proposal 0 I0709 22:37:57.791862 185411 replica.cpp:391] Replica received explicit promise request from __req_res__(1012)@172.17.0.2:37579 for position 0 with proposal 0 I0709 22:37:57.791934 185410 leveldb.cpp:510] Reading position from leveldb took 76368ns I0709 22:37:57.791958 185411 leveldb.cpp:510] Reading position from leveldb took 58938ns I0709 22:37:57.791987 185414 replica.cpp:391] Replica received explicit promise request from __req_res__(1013)@172.17.0.2:37579 for position 0 with proposal 0 I0709 22:37:57.932495 185412 replica.cpp:391] Replica received explicit promise request from __req_res__(1014)@172.17.0.2:37579 for position 0 with proposal 3 I0709 22:37:57.932533 185414 replica.cpp:391] Replica received explicit promise request from __req_res__(1015)@172.17.0.2:37579 for position 0 with proposal 3 I0709 22:37:57.932605 185412 leveldb.cpp:510] Reading position from leveldb took 60871ns I0709 22:37:57.932642 185414 leveldb.cpp:510] Reading position from leveldb took 61236ns I0709 22:37:57.932636 185406 replica.cpp:391] Replica received explicit promise request from __req_res__(1016)@172.17.0.2:37579 for position 0 with proposal 3 I0709 22:37:57.985756 185414 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 53.052149ms I0709 22:37:57.985755 185412 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 53.109433ms I0709 22:37:57.985826 185414 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:57.985873 185412 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:57.986660 185410 replica.cpp:695] Replica received learned notice for position 0 from log-network(48)@172.17.0.2:37579 I0709 22:37:57.986712 185405 replica.cpp:695] Replica received learned notice for position 0 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.011873 185406 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 79.149323ms I0709 22:37:58.011936 185406 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:58.012092 185406 replica.cpp:695] Replica received learned notice for position 0 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.045418 185410 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 58.719142ms I0709 22:37:58.045490 185410 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:58.045414 185405 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 58.632119ms I0709 22:37:58.045604 185405 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:58.062204 185406 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 50.0852ms I0709 22:37:58.062270 185406 replica.cpp:712] Persisted action NOP at position 0 I0709 22:37:58.063890 185404 replica.cpp:391] Replica received explicit promise request from __req_res__(1017)@172.17.0.2:37579 for position 1 with proposal 3 I0709 22:37:58.063992 185418 replica.cpp:391] Replica received explicit promise request from __req_res__(1018)@172.17.0.2:37579 for position 1 with proposal 3 I0709 22:37:58.064023 185412 replica.cpp:391] Replica received explicit promise request from __req_res__(1019)@172.17.0.2:37579 for position 1 with proposal 3 I0709 22:37:58.064014 185404 leveldb.cpp:510] Reading position from leveldb took 77808ns I0709 22:37:58.064106 185418 leveldb.cpp:510] Reading position from leveldb took 68466ns I0709 22:37:58.104077 185412 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 40.011508ms I0709 22:37:58.104100 185418 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 39.93474ms I0709 22:37:58.104143 185412 replica.cpp:712] Persisted action NOP at position 1 I0709 22:37:58.104100 185404 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 39.956212ms I0709 22:37:58.104171 185418 replica.cpp:712] Persisted action APPEND at position 1 I0709 22:37:58.104225 185404 replica.cpp:712] Persisted action APPEND at position 1 I0709 22:37:58.104843 185410 replica.cpp:695] Replica received learned notice for position 1 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.104907 185405 replica.cpp:695] Replica received learned notice for position 1 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.104988 185408 replica.cpp:695] Replica received learned notice for position 1 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.145928 185410 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 41.054786ms I0709 22:37:58.145928 185408 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.904778ms I0709 22:37:58.145934 185405 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.998273ms I0709 22:37:58.146116 185405 replica.cpp:712] Persisted action APPEND at position 1 I0709 22:37:58.145998 185410 replica.cpp:712] Persisted action APPEND at position 1 I0709 22:37:58.146052 185408 replica.cpp:712] Persisted action APPEND at position 1 I0709 22:37:58.147792 185404 replica.cpp:391] Replica received explicit promise request from __req_res__(1020)@172.17.0.2:37579 for position 2 with proposal 3 I0709 22:37:58.147894 185410 replica.cpp:391] Replica received explicit promise request from __req_res__(1021)@172.17.0.2:37579 for position 2 with proposal 3 I0709 22:37:58.147902 185404 leveldb.cpp:510] Reading position from leveldb took 67075ns I0709 22:37:58.147964 185409 replica.cpp:391] Replica received explicit promise request from __req_res__(1022)@172.17.0.2:37579 for position 2 with proposal 3 I0709 22:37:58.148010 185410 leveldb.cpp:510] Reading position from leveldb took 67708ns I0709 22:37:58.187772 185404 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 39.752001ms I0709 22:37:58.187773 185409 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 39.741489ms I0709 22:37:58.187892 185409 replica.cpp:712] Persisted action NOP at position 2 I0709 22:37:58.187778 185410 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 39.698354ms I0709 22:37:58.188002 185410 replica.cpp:712] Persisted action APPEND at position 2 I0709 22:37:58.187841 185404 replica.cpp:712] Persisted action APPEND at position 2 I0709 22:37:58.188730 185419 replica.cpp:695] Replica received learned notice for position 2 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.188759 185415 replica.cpp:695] Replica received learned notice for position 2 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.188845 185413 replica.cpp:695] Replica received learned notice for position 2 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.229640 185419 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.880146ms I0709 22:37:58.229641 185413 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.764845ms I0709 22:37:58.229763 185413 replica.cpp:712] Persisted action APPEND at position 2 I0709 22:37:58.229643 185415 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.857902ms I0709 22:37:58.229871 185415 replica.cpp:712] Persisted action APPEND at position 2 I0709 22:37:58.229707 185419 replica.cpp:712] Persisted action APPEND at position 2 I0709 22:37:58.231249 185408 replica.cpp:391] Replica received explicit promise request from __req_res__(1023)@172.17.0.2:37579 for position 3 with proposal 3 I0709 22:37:58.231353 185412 replica.cpp:391] Replica received explicit promise request from __req_res__(1024)@172.17.0.2:37579 for position 3 with proposal 3 I0709 22:37:58.231362 185408 leveldb.cpp:510] Reading position from leveldb took 68898ns I0709 22:37:58.231431 185419 replica.cpp:391] Replica received explicit promise request from __req_res__(1025)@172.17.0.2:37579 for position 3 with proposal 3 I0709 22:37:58.231460 185412 leveldb.cpp:510] Reading position from leveldb took 63131ns I0709 22:37:58.271435 185412 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 39.906681ms I0709 22:37:58.271436 185419 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 39.954542ms I0709 22:37:58.271555 185419 replica.cpp:712] Persisted action NOP at position 3 I0709 22:37:58.271438 185408 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 39.982104ms I0709 22:37:58.271658 185408 replica.cpp:712] Persisted action APPEND at position 3 I0709 22:37:58.271503 185412 replica.cpp:712] Persisted action APPEND at position 3 I0709 22:37:58.272475 185413 replica.cpp:695] Replica received learned notice for position 3 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.272512 185408 replica.cpp:695] Replica received learned notice for position 3 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.272513 185407 replica.cpp:695] Replica received learned notice for position 3 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.313241 185407 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.66355ms I0709 22:37:58.313289 185408 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.744159ms I0709 22:37:58.313302 185407 replica.cpp:712] Persisted action APPEND at position 3 I0709 22:37:58.313354 185408 replica.cpp:712] Persisted action APPEND at position 3 I0709 22:37:58.313308 185413 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.796626ms I0709 22:37:58.313464 185413 replica.cpp:712] Persisted action APPEND at position 3 I0709 22:37:58.314982 185411 replica.cpp:391] Replica received explicit promise request from __req_res__(1026)@172.17.0.2:37579 for position 4 with proposal 3 I0709 22:37:58.315037 185413 replica.cpp:391] Replica received explicit promise request from __req_res__(1027)@172.17.0.2:37579 for position 4 with proposal 3 I0709 22:37:58.315091 185411 leveldb.cpp:510] Reading position from leveldb took 64368ns I0709 22:37:58.315141 185406 replica.cpp:391] Replica received explicit promise request from __req_res__(1028)@172.17.0.2:37579 for position 4 with proposal 3 I0709 22:37:58.315152 185413 leveldb.cpp:510] Reading position from leveldb took 70578ns I0709 22:37:58.355136 185413 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 39.879434ms I0709 22:37:58.355144 185411 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.006629ms I0709 22:37:58.355204 185413 replica.cpp:712] Persisted action APPEND at position 4 I0709 22:37:58.355144 185406 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 39.954328ms I0709 22:37:58.355243 185411 replica.cpp:712] Persisted action APPEND at position 4 I0709 22:37:58.355273 185406 replica.cpp:712] Persisted action NOP at position 4 I0709 22:37:58.355898 185416 replica.cpp:695] Replica received learned notice for position 4 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.355953 185406 replica.cpp:695] Replica received learned notice for position 4 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.356011 185407 replica.cpp:695] Replica received learned notice for position 4 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.397012 185407 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 40.956476ms I0709 22:37:58.397020 185416 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 41.079408ms I0709 22:37:58.397140 185416 replica.cpp:712] Persisted action APPEND at position 4 I0709 22:37:58.397022 185406 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 41.030626ms I0709 22:37:58.397082 185407 replica.cpp:712] Persisted action APPEND at position 4 I0709 22:37:58.397243 185406 replica.cpp:712] Persisted action APPEND at position 4 I0709 22:37:58.398835 185405 replica.cpp:391] Replica received explicit promise request from __req_res__(1029)@172.17.0.2:37579 for position 5 with proposal 3 I0709 22:37:58.398941 185405 leveldb.cpp:510] Reading position from leveldb took 62468ns I0709 22:37:58.398942 185408 replica.cpp:391] Replica received explicit promise request from __req_res__(1030)@172.17.0.2:37579 for position 5 with proposal 3 I0709 22:37:58.399050 185406 replica.cpp:391] Replica received explicit promise request from __req_res__(1031)@172.17.0.2:37579 for position 5 with proposal 3 I0709 22:37:58.399068 185408 leveldb.cpp:510] Reading position from leveldb took 68825ns I0709 22:37:58.460842 185408 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 61.692494ms I0709 22:37:58.460877 185406 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 61.785636ms I0709 22:37:58.460881 185405 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 61.894688ms I0709 22:37:58.460906 185408 replica.cpp:712] Persisted action APPEND at position 5 I0709 22:37:58.460942 185406 replica.cpp:712] Persisted action NOP at position 5 I0709 22:37:58.461001 185405 replica.cpp:712] Persisted action APPEND at position 5 I0709 22:37:58.461681 185410 replica.cpp:695] Replica received learned notice for position 5 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.461709 185417 replica.cpp:695] Replica received learned notice for position 5 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.461721 185419 replica.cpp:695] Replica received learned notice for position 5 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.519397 185419 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 57.610362ms I0709 22:37:58.519400 185417 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 57.649333ms I0709 22:37:58.519517 185417 replica.cpp:712] Persisted action APPEND at position 5 I0709 22:37:58.519402 185410 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 57.681205ms I0709 22:37:58.519626 185410 replica.cpp:712] Persisted action APPEND at position 5 I0709 22:37:58.519464 185419 replica.cpp:712] Persisted action APPEND at position 5 I0709 22:37:58.521188 185415 replica.cpp:391] Replica received explicit promise request from __req_res__(1032)@172.17.0.2:37579 for position 6 with proposal 3 I0709 22:37:58.521230 185410 replica.cpp:391] Replica received explicit promise request from __req_res__(1033)@172.17.0.2:37579 for position 6 with proposal 3 I0709 22:37:58.521291 185415 leveldb.cpp:510] Reading position from leveldb took 62580ns I0709 22:37:58.521328 185410 leveldb.cpp:510] Reading position from leveldb took 61463ns I0709 22:37:58.521375 185419 replica.cpp:391] Replica received explicit promise request from __req_res__(1034)@172.17.0.2:37579 for position 6 with proposal 3 I0709 22:37:58.577894 185419 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 56.473144ms I0709 22:37:58.577899 185410 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 56.529966ms I0709 22:37:58.578018 185410 replica.cpp:712] Persisted action APPEND at position 6 I0709 22:37:58.577960 185419 replica.cpp:712] Persisted action NOP at position 6 I0709 22:37:58.577903 185415 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 56.569763ms I0709 22:37:58.578277 185415 replica.cpp:712] Persisted action APPEND at position 6 I0709 22:37:58.578743 185416 replica.cpp:695] Replica received learned notice for position 6 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.578797 185406 replica.cpp:695] Replica received learned notice for position 6 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.578934 185413 replica.cpp:695] Replica received learned notice for position 6 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.645048 185406 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 66.126759ms I0709 22:37:58.645049 185416 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 66.17591ms I0709 22:37:58.645244 185406 replica.cpp:712] Persisted action APPEND at position 6 I0709 22:37:58.645314 185416 replica.cpp:712] Persisted action APPEND at position 6 I0709 22:37:58.645049 185413 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 66.096658ms I0709 22:37:58.645445 185413 replica.cpp:712] Persisted action APPEND at position 6 I0709 22:37:58.648319 185419 replica.cpp:391] Replica received explicit promise request from __req_res__(1035)@172.17.0.2:37579 for position 7 with proposal 3 I0709 22:37:58.648439 185407 replica.cpp:391] Replica received explicit promise request from __req_res__(1036)@172.17.0.2:37579 for position 7 with proposal 3 I0709 22:37:58.648473 185419 leveldb.cpp:510] Reading position from leveldb took 107337ns I0709 22:37:58.648555 185407 leveldb.cpp:510] Reading position from leveldb took 77803ns I0709 22:37:58.648623 185404 replica.cpp:391] Replica received explicit promise request from __req_res__(1037)@172.17.0.2:37579 for position 7 with proposal 3 I0709 22:37:58.718972 185404 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 70.303568ms I0709 22:37:58.718976 185407 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 70.350557ms I0709 22:37:58.719101 185407 replica.cpp:712] Persisted action APPEND at position 7 I0709 22:37:58.718978 185419 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 70.431216ms I0709 22:37:58.719188 185419 replica.cpp:712] Persisted action APPEND at position 7 I0709 22:37:58.719038 185404 replica.cpp:712] Persisted action NOP at position 7 I0709 22:37:58.719854 185404 replica.cpp:695] Replica received learned notice for position 7 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.719933 185406 replica.cpp:695] Replica received learned notice for position 7 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.719940 185417 replica.cpp:695] Replica received learned notice for position 7 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.786770 185417 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 66.76726ms I0709 22:37:58.786772 185404 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 66.891051ms I0709 22:37:58.786886 185404 replica.cpp:712] Persisted action APPEND at position 7 I0709 22:37:58.786775 185406 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 66.813733ms I0709 22:37:58.786988 185406 replica.cpp:712] Persisted action APPEND at position 7 I0709 22:37:58.786836 185417 replica.cpp:712] Persisted action APPEND at position 7 I0709 22:37:58.788664 185409 replica.cpp:391] Replica received explicit promise request from __req_res__(1038)@172.17.0.2:37579 for position 8 with proposal 3 I0709 22:37:58.788738 185407 replica.cpp:391] Replica received explicit promise request from __req_res__(1039)@172.17.0.2:37579 for position 8 with proposal 3 I0709 22:37:58.788822 185405 replica.cpp:391] Replica received explicit promise request from __req_res__(1040)@172.17.0.2:37579 for position 8 with proposal 3 I0709 22:37:58.788834 185407 leveldb.cpp:510] Reading position from leveldb took 60028ns I0709 22:37:58.788842 185409 leveldb.cpp:510] Reading position from leveldb took 108744ns I0709 22:37:58.860994 185405 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 72.13387ms I0709 22:37:58.860996 185407 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 72.081106ms I0709 22:37:58.861027 185409 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 72.079794ms I0709 22:37:58.861181 185409 replica.cpp:712] Persisted action APPEND at position 8 I0709 22:37:58.861061 185405 replica.cpp:712] Persisted action NOP at position 8 I0709 22:37:58.861119 185407 replica.cpp:712] Persisted action APPEND at position 8 I0709 22:37:58.862082 185416 replica.cpp:695] Replica received learned notice for position 8 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.862193 185406 replica.cpp:695] Replica received learned notice for position 8 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.862243 185417 replica.cpp:695] Replica received learned notice for position 8 from log-network(48)@172.17.0.2:37579 I0709 22:37:58.944530 185416 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 82.417324ms I0709 22:37:58.944531 185417 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 82.256972ms I0709 22:37:58.944653 185417 replica.cpp:712] Persisted action APPEND at position 8 I0709 22:37:58.944536 185406 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 82.307738ms I0709 22:37:58.944603 185416 replica.cpp:712] Persisted action APPEND at position 8 I0709 22:37:58.944757 185406 replica.cpp:712] Persisted action APPEND at position 8 I0709 22:37:58.946497 185409 replica.cpp:391] Replica received explicit promise request from __req_res__(1042)@172.17.0.2:37579 for position 9 with proposal 3 I0709 22:37:58.946497 185413 replica.cpp:391] Replica received explicit promise request from __req_res__(1041)@172.17.0.2:37579 for position 9 with proposal 3 I0709 22:37:58.946588 185411 replica.cpp:391] Replica received explicit promise request from __req_res__(1043)@172.17.0.2:37579 for position 9 with proposal 3 I0709 22:37:58.946704 185409 leveldb.cpp:510] Reading position from leveldb took 134951ns I0709 22:37:58.946705 185413 leveldb.cpp:510] Reading position from leveldb took 99292ns I0709 22:37:59.003942 185411 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 57.270694ms I0709 22:37:59.003949 185409 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 57.157161ms I0709 22:37:59.003950 185413 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 57.141837ms I0709 22:37:59.004070 185409 replica.cpp:712] Persisted action APPEND at position 9 I0709 22:37:59.004009 185411 replica.cpp:712] Persisted action NOP at position 9 I0709 22:37:59.004108 185413 replica.cpp:712] Persisted action APPEND at position 9 I0709 22:37:59.004833 185409 replica.cpp:695] Replica received learned notice for position 9 from log-network(48)@172.17.0.2:37579 I0709 22:37:59.004889 185415 replica.cpp:695] Replica received learned notice for position 9 from log-network(48)@172.17.0.2:37579 I0709 22:37:59.004909 185419 replica.cpp:695] Replica received learned notice for position 9 from log-network(48)@172.17.0.2:37579 I0709 22:37:59.062448 185415 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 57.527312ms I0709 22:37:59.062470 185419 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 57.527766ms I0709 22:37:59.062530 185415 replica.cpp:712] Persisted action APPEND at position 9 I0709 22:37:59.062558 185419 replica.cpp:712] Persisted action APPEND at position 9 I0709 22:37:59.062500 185409 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 57.650511ms I0709 22:37:59.062666 185409 replica.cpp:712] Persisted action APPEND at position 9 I0709 22:37:59.063596 185410 catchup.cpp:357] Recover process terminated I0709 22:37:59.066191 185416 leveldb.cpp:510] Reading position from leveldb took 171420ns I0709 22:37:59.066350 185416 leveldb.cpp:510] Reading position from leveldb took 70751ns I0709 22:37:59.066485 185416 leveldb.cpp:510] Reading position from leveldb took 60712ns I0709 22:37:59.066638 185416 leveldb.cpp:510] Reading position from leveldb took 62545ns I0709 22:37:59.066781 185416 leveldb.cpp:510] Reading position from leveldb took 79683ns I0709 22:37:59.066926 185416 leveldb.cpp:510] Reading position from leveldb took 80061ns I0709 22:37:59.067050 185416 leveldb.cpp:510] Reading position from leveldb took 58467ns I0709 22:37:59.067234 185416 leveldb.cpp:510] Reading position from leveldb took 126423ns I0709 22:37:59.067365 185416 leveldb.cpp:510] Reading position from leveldb took 63990ns I0709 22:37:59.067492 185416 leveldb.cpp:510] Reading position from leveldb took 62080ns [ OK ] LogTest.ReaderCatchup (3601 ms) [----------] 4 tests from LogTest (6541 ms total) [----------] 2 tests from LogZooKeeperTest I0709 22:37:59.074353 185403 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/netty-3.7.0.Final.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/slf4j-api-1.6.1.jar [ RUN ] LogZooKeeperTest.WriteRead I0709 22:37:59.151335 185403 jvm.cpp:590] Looking up method <init>(Ljava/lang/String;)V I0709 22:37:59.151628 185403 jvm.cpp:590] Looking up method deleteOnExit()V I0709 22:37:59.152390 185403 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. I0709 22:37:59.261493 185403 jvm.cpp:590] Looking up method <init>()V I0709 22:37:59.262390 185403 jvm.cpp:590] Looking up method <init>(Lorg/apache/zookeeper/server/persistence/FileTxnSnapLog;Lorg/apache/zookeeper/server/ZooKeeperServer$DataTreeBuilder;)V *** Aborted at 1720564679 (unix time) try "date -d @1720564679" if you are using GNU date *** PC: @ 0x7f76be912ccd OopStorage::Block::release_entries() *** SIGSEGV (@0x238) received by PID 185403 (TID 0x7f770d359b40) from PID 568; stack trace: *** @ 0x7f76be921929 os::Linux::chained_handler() @ 0x7f76be92763b JVM_handle_linux_signal @ 0x7f76be91a1dc signalHandler() @ 0x7f770e9ac420 (unknown) @ 0x7f76be912ccd OopStorage::Block::release_entries() @ 0x7f76be912f26 OopStorage::release() @ 0x7f76be615b21 jni_DeleteGlobalRef @ 0x7f771e16e446 JNIEnv_::DeleteGlobalRef() @ 0x7f771e16c58e Jvm::deleteGlobalRef() @ 0x563361623628 Jvm::Object::~Object() @ 0x56336162844e org::apache::zookeeper::server::ZooKeeperServer::DataTreeBuilder::~DataTreeBuilder() @ 0x56336162ad52 org::apache::zookeeper::server::ZooKeeperServer::BasicDataTreeBuilder::~BasicDataTreeBuilder() @ 0x563361626d6d mesos::internal::tests::ZooKeeperTestServer::ZooKeeperTestServer() @ 0x56335ffcbfcc mesos::internal::tests::ZooKeeperTest::ZooKeeperTest() @ 0x56335ffce315 mesos::internal::tests::LogZooKeeperTest::LogZooKeeperTest() @ 0x56335ffce426 mesos::internal::tests::LogZooKeeperTest_WriteRead_Test::LogZooKeeperTest_WriteRead_Test() @ 0x563360039328 testing::internal::TestFactoryImpl<>::CreateTest() @ 0x56336166d5fa testing::internal::HandleSehExceptionsInMethodIfSupported<>() @ 0x563361666bcb testing::internal::HandleExceptionsInMethodIfSupported<>() @ 0x563361642e03 testing::TestInfo::Run() @ 0x56336164350b testing::TestCase::Run() @ 0x56336164a8a5 testing::internal::UnitTestImpl::RunAllTests() @ 0x56336166e828 testing::internal::HandleSehExceptionsInMethodIfSupported<>() @ 0x563361667731 testing::internal::HandleExceptionsInMethodIfSupported<>() @ 0x5633616493bd testing::UnitTest::Run() @ 0x563360056edb RUN_ALL_TESTS() @ 0x5633600568a2 main @ 0x7f770e7ca083 __libc_start_main @ 0x56335f09c75e _start make[4]: *** [Makefile:18022: check-local] Segmentation fault (core dumped) make[4]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub/src' I0709 22:38:01.577430 186210 exec.cpp:560] Agent exited ... shutting down I0709 22:38:01.578168 186203 executor.cpp:190] Received SHUTDOWN event I0709 22:38:01.578233 186203 executor.cpp:843] Shutting down I0709 22:38:01.578311 186203 executor.cpp:956] Sending SIGTERM to process tree at pid 186215 make[3]: *** [Makefile:15951: check-am] Error 2 I0709 22:38:01.593848 186203 executor.cpp:969] Sent SIGTERM to the following process trees: [ -+- 186215 sh -c dd if=/dev/zero of=volume_path/file bs=1048576 count=2 && sleep 1000 \--- 186223 sleep 1000 ] I0709 22:38:01.593919 186203 executor.cpp:973] Scheduling escalation to SIGKILL in 3secs from now I0709 22:38:01.680097 186196 executor.cpp:1041] Command terminated with signal Terminated (pid: 186215) W0709 22:38:01.682132 186212 process.cpp:1917] Failed to send 'mesos.internal.StatusUpdateMessage' to '172.17.0.2:37579', connect: Failed to connect to 172.17.0.2:37579: Connection refused make[3]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub/src' make[2]: *** [Makefile:15954: check] Error 2 make[2]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub/src' make[1]: *** [Makefile:785: check-recursive] Error 1 make[1]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub' I0709 22:38:02.683117 186212 process.cpp:935] Stopped the socket accept loop make: *** [Makefile:999: distcheck] Error 1 + copy_out_test_reports + find /tmp/SRC -name '*-tests.xml' -exec cp '{}' /SRC ';' Untagged: mesos/mesos-build:ubuntu-20.04 Untagged: mesos/mesos-build@sha256:2d3cd7fed451697aba1a3103754b4a46b6a7cad64e8229fb65e5a31e6d4b413d Deleted: sha256:b978a6177f864ec24c8ab237b612c3e5e780d94875752c63681edd80d9a85bbd Deleted: sha256:3ce262d459956fd117307a4cccbe593d59a11fce0e9138bee98d634f3a536bd0 Deleted: sha256:93be824b42681ee74b5ef869b75fb8b4fc0f234ec2135b764d235bb863a722e1 Deleted: sha256:eca0ccc3c9322d20f126a1a390efe2f6862fef535a41044bdb68c492f0dd9392 Deleted: sha256:8ed5c7c631df3c9d418a68532b4957d8c8dbadc69ad70564f6fa45e4748f6957 Deleted: sha256:6988969997d24e5f91cf313970ab25e046d637808cc0d77b19de4fc385e6a0db Deleted: sha256:9a7bfb2ba9f4a5cc05f561ed15dcd86232976d79616d817df9d323b45b4407ca Deleted: sha256:92c98c8577076f502769040fce0770d08a5a5c5d41989fa70986df7b3962a293 Deleted: sha256:3ec3ded77c0ce89e931f92aed086b2a2c774a6fbd51617853decc8afa4e1087a Full log: https://ci-builds.apache.org/job/Mesos/job/Mesos-Reviewbot/33431/console - Mesos Reviewbot On May 28, 2024, 9:20 p.m., Jason Zhou wrote: > > ----------------------------------------------------------- > This is an automatically generated e-mail. To reply, visit: > https://reviews.apache.org/r/75016/ > ----------------------------------------------------------- > > (Updated May 28, 2024, 9:20 p.m.) > > > Review request for mesos and Benjamin Mahler. > > > Repository: mesos > > > Description > ------- > > Passes the device manager to the cgroups2 isolator on > containerizer startup, and sets up the ability for the > manager to be passed to the device controller and GPU isolator > > > Diffs > ----- > > src/slave/containerizer/containerizer.hpp > 691fdfe295850bce1302b4adde127d551f821b89 > src/slave/containerizer/containerizer.cpp > ba3ab43b0d56c6dabd141e40ac706568dccd72f1 > src/slave/containerizer/mesos/containerizer.hpp > 62174dfd056e1d7cc465ebdb29343bdd04de6a10 > src/slave/containerizer/mesos/containerizer.cpp > f7ff6b8e56e80881ac89ba650b7aa4f4eec3484b > src/slave/containerizer/mesos/isolators/cgroups2/cgroups2.hpp > d60215ec1c722efced2d5c59b9f99cb67d1abbbe > src/slave/containerizer/mesos/isolators/cgroups2/cgroups2.cpp > 2ca3880790be0cd092ec05a359711e2d8e641314 > src/slave/main.cpp 21b8ea74a502478fb73510a7d49bb5f28506ce8d > > > Diff: https://reviews.apache.org/r/75016/diff/4/ > > > Testing > ------- > > > Thanks, > > Jason Zhou > >
