----------------------------------------------------------- This is an automatically generated e-mail. To reply, visit: https://reviews.apache.org/r/75087/#review226673 -----------------------------------------------------------
Bad patch! Reviews applied: [75087] 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_75087"] Error: ...<truncated>... Replica received learned notice for position 11 from log-network(41)@172.17.0.3:33167 I0713 00:45:38.730839 185009 replica.cpp:695] Replica received learned notice for position 11 from log-network(41)@172.17.0.3:33167 I0713 00:45:38.731748 185009 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 860161ns I0713 00:45:38.731840 185011 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 1.00362ms I0713 00:45:38.732656 185009 leveldb.cpp:460] Deleting ~5 keys from leveldb took 884342ns I0713 00:45:38.732712 185011 leveldb.cpp:460] Deleting ~5 keys from leveldb took 813021ns I0713 00:45:38.744637 185009 leveldb.cpp:527] Compacting range 0-4 took 11.92971ms I0713 00:45:38.744642 185011 leveldb.cpp:527] Compacting range 0-4 took 11.879672ms I0713 00:45:38.744743 185009 replica.cpp:712] Persisted action TRUNCATE at position 11 I0713 00:45:38.744784 185011 replica.cpp:712] Persisted action TRUNCATE at position 11 I0713 00:45:38.751961 184994 leveldb.cpp:217] Opened db in 5.838232ms I0713 00:45:38.756469 184994 leveldb.cpp:224] Compacted db in 4.467673ms I0713 00:45:38.756604 184994 leveldb.cpp:239] Created db iterator in 54669ns I0713 00:45:38.756662 184994 leveldb.cpp:245] Seeked to beginning of db in 45017ns I0713 00:45:38.756742 184994 leveldb.cpp:320] Iterated through 1 keys in the db in 57775ns I0713 00:45:38.756803 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0713 00:45:38.757671 185001 catchup.cpp:342] Starting missing positions recovery I0713 00:45:38.758340 185016 catchup.cpp:368] Replica is in VOTING status I0713 00:45:38.760522 185010 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(881)@172.17.0.3:33167 I0713 00:45:38.760772 185012 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(882)@172.17.0.3:33167 I0713 00:45:38.761467 185002 recover.cpp:197] Received a recover response from a replica in VOTING status I0713 00:45:38.762106 185002 recover.cpp:197] Received a recover response from a replica in VOTING status I0713 00:45:38.763830 185017 catchup.cpp:423] Starting catch-up from position 0 to 10 I0713 00:45:38.765852 185000 replica.cpp:391] Replica received explicit promise request from __req_res__(886)@172.17.0.3:33167 for position 0 with proposal 0 I0713 00:45:38.765964 185012 replica.cpp:391] Replica received explicit promise request from __req_res__(884)@172.17.0.3:33167 for position 0 with proposal 0 I0713 00:45:38.766036 184997 replica.cpp:391] Replica received explicit promise request from __req_res__(885)@172.17.0.3:33167 for position 0 with proposal 0 I0713 00:45:38.963313 185011 replica.cpp:391] Replica received explicit promise request from __req_res__(887)@172.17.0.3:33167 for position 0 with proposal 1 I0713 00:45:38.963369 185007 replica.cpp:391] Replica received explicit promise request from __req_res__(889)@172.17.0.3:33167 for position 0 with proposal 1 I0713 00:45:38.963491 185004 replica.cpp:391] Replica received explicit promise request from __req_res__(888)@172.17.0.3:33167 for position 0 with proposal 1 I0713 00:45:38.964650 185007 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 1.210308ms I0713 00:45:38.964744 185007 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:38.964900 185002 replica.cpp:695] Replica received learned notice for position 0 from log-network(42)@172.17.0.3:33167 I0713 00:45:38.964987 185017 replica.cpp:695] Replica received learned notice for position 0 from log-network(42)@172.17.0.3:33167 I0713 00:45:38.965015 185007 replica.cpp:695] Replica received learned notice for position 0 from log-network(42)@172.17.0.3:33167 I0713 00:45:38.965907 185007 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 846943ns I0713 00:45:38.966001 185007 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:38.966130 185017 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 1.095077ms I0713 00:45:38.966135 185002 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 1.194046ms I0713 00:45:38.966236 185017 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:38.966287 185002 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:38.968510 185013 replica.cpp:391] Replica received explicit promise request from __req_res__(890)@172.17.0.3:33167 for position 1 with proposal 1 I0713 00:45:38.968858 185000 replica.cpp:391] Replica received explicit promise request from __req_res__(891)@172.17.0.3:33167 for position 1 with proposal 1 I0713 00:45:38.968910 185011 replica.cpp:391] Replica received explicit promise request from __req_res__(892)@172.17.0.3:33167 for position 1 with proposal 1 I0713 00:45:38.969596 185011 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 610971ns I0713 00:45:38.969640 185011 replica.cpp:712] Persisted action NOP at position 1 I0713 00:45:38.969681 185006 replica.cpp:695] Replica received learned notice for position 1 from log-network(42)@172.17.0.3:33167 I0713 00:45:38.969770 185013 replica.cpp:695] Replica received learned notice for position 1 from log-network(42)@172.17.0.3:33167 I0713 00:45:38.970048 185011 replica.cpp:695] Replica received learned notice for position 1 from log-network(42)@172.17.0.3:33167 I0713 00:45:38.970317 185006 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 617357ns I0713 00:45:38.970619 185013 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 757580ns I0713 00:45:38.970726 185011 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 653714ns I0713 00:45:38.970829 185006 leveldb.cpp:460] Deleting ~1 keys from leveldb took 468491ns I0713 00:45:38.971304 185013 leveldb.cpp:460] Deleting ~1 keys from leveldb took 641503ns I0713 00:45:38.971411 185011 leveldb.cpp:460] Deleting ~1 keys from leveldb took 622882ns I0713 00:45:38.981225 185006 leveldb.cpp:527] Compacting range 0-0 took 10.366749ms I0713 00:45:38.981227 185013 leveldb.cpp:527] Compacting range 0-0 took 9.898281ms I0713 00:45:38.981284 185011 leveldb.cpp:527] Compacting range 0-0 took 9.824332ms I0713 00:45:38.981340 185013 replica.cpp:712] Persisted action NOP at position 1 I0713 00:45:38.981318 185006 replica.cpp:712] Persisted action NOP at position 1 I0713 00:45:38.981384 185011 replica.cpp:712] Persisted action NOP at position 1 I0713 00:45:38.983713 185018 replica.cpp:391] Replica received explicit promise request from __req_res__(893)@172.17.0.3:33167 for position 2 with proposal 1 I0713 00:45:38.984023 185017 replica.cpp:391] Replica received explicit promise request from __req_res__(894)@172.17.0.3:33167 for position 2 with proposal 1 I0713 00:45:38.984195 185010 replica.cpp:391] Replica received explicit promise request from __req_res__(895)@172.17.0.3:33167 for position 2 with proposal 1 I0713 00:45:38.984839 185011 replica.cpp:695] Replica received learned notice for position 2 from log-network(42)@172.17.0.3:33167 I0713 00:45:38.984922 185005 replica.cpp:695] Replica received learned notice for position 2 from log-network(42)@172.17.0.3:33167 I0713 00:45:38.985419 185010 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 1.165819ms I0713 00:45:38.985520 185010 replica.cpp:712] Persisted action NOP at position 2 I0713 00:45:38.985745 185011 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 852061ns I0713 00:45:38.985790 185010 replica.cpp:695] Replica received learned notice for position 2 from log-network(42)@172.17.0.3:33167 I0713 00:45:38.985832 185005 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 867678ns I0713 00:45:38.986289 185011 leveldb.cpp:460] Deleting ~1 keys from leveldb took 504698ns I0713 00:45:38.986312 185010 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 465576ns I0713 00:45:38.986601 185005 leveldb.cpp:460] Deleting ~1 keys from leveldb took 718619ns I0713 00:45:38.986799 185010 leveldb.cpp:460] Deleting ~1 keys from leveldb took 460594ns I0713 00:45:38.993197 185011 leveldb.cpp:527] Compacting range 1-1 took 6.906235ms I0713 00:45:38.993203 185005 leveldb.cpp:527] Compacting range 1-1 took 6.549871ms I0713 00:45:38.993302 185011 replica.cpp:712] Persisted action NOP at position 2 I0713 00:45:38.993345 185005 replica.cpp:712] Persisted action NOP at position 2 I0713 00:45:38.994589 185010 leveldb.cpp:527] Compacting range 1-1 took 7.769547ms I0713 00:45:38.994691 185010 replica.cpp:712] Persisted action NOP at position 2 I0713 00:45:38.996850 185016 replica.cpp:391] Replica received explicit promise request from __req_res__(896)@172.17.0.3:33167 for position 3 with proposal 1 I0713 00:45:38.996910 184995 replica.cpp:391] Replica received explicit promise request from __req_res__(898)@172.17.0.3:33167 for position 3 with proposal 1 I0713 00:45:38.997073 184997 replica.cpp:391] Replica received explicit promise request from __req_res__(897)@172.17.0.3:33167 for position 3 with proposal 1 I0713 00:45:38.997766 184995 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 797129ns I0713 00:45:38.997781 185005 replica.cpp:695] Replica received learned notice for position 3 from log-network(42)@172.17.0.3:33167 I0713 00:45:38.997879 184995 replica.cpp:712] Persisted action NOP at position 3 I0713 00:45:38.997996 185002 replica.cpp:695] Replica received learned notice for position 3 from log-network(42)@172.17.0.3:33167 I0713 00:45:38.998338 184995 replica.cpp:695] Replica received learned notice for position 3 from log-network(42)@172.17.0.3:33167 I0713 00:45:38.998907 185005 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 999417ns I0713 00:45:38.999164 184995 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 796196ns I0713 00:45:38.999188 185002 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 1.142804ms I0713 00:45:38.999600 185005 leveldb.cpp:460] Deleting ~1 keys from leveldb took 636408ns I0713 00:45:38.999939 185002 leveldb.cpp:460] Deleting ~1 keys from leveldb took 690051ns I0713 00:45:38.999948 184995 leveldb.cpp:460] Deleting ~1 keys from leveldb took 736880ns I0713 00:45:39.007602 185005 leveldb.cpp:527] Compacting range 2-2 took 7.958556ms I0713 00:45:39.007705 185005 replica.cpp:712] Persisted action NOP at position 3 I0713 00:45:39.007604 185002 leveldb.cpp:527] Compacting range 2-2 took 7.609004ms I0713 00:45:39.007890 185002 replica.cpp:712] Persisted action NOP at position 3 I0713 00:45:39.009339 184995 leveldb.cpp:527] Compacting range 2-2 took 9.284908ms I0713 00:45:39.009433 184995 replica.cpp:712] Persisted action NOP at position 3 I0713 00:45:39.011682 185009 replica.cpp:391] Replica received explicit promise request from __req_res__(899)@172.17.0.3:33167 for position 4 with proposal 1 I0713 00:45:39.011775 185010 replica.cpp:391] Replica received explicit promise request from __req_res__(901)@172.17.0.3:33167 for position 4 with proposal 1 I0713 00:45:39.011831 185009 replica.cpp:391] Replica received explicit promise request from __req_res__(900)@172.17.0.3:33167 for position 4 with proposal 1 I0713 00:45:39.012586 185010 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 742116ns I0713 00:45:39.012650 185010 replica.cpp:712] Persisted action NOP at position 4 I0713 00:45:39.012717 184996 replica.cpp:695] Replica received learned notice for position 4 from log-network(42)@172.17.0.3:33167 I0713 00:45:39.012796 184995 replica.cpp:695] Replica received learned notice for position 4 from log-network(42)@172.17.0.3:33167 I0713 00:45:39.012848 185010 replica.cpp:695] Replica received learned notice for position 4 from log-network(42)@172.17.0.3:33167 I0713 00:45:39.013466 184996 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 698667ns I0713 00:45:39.013504 185010 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 653673ns I0713 00:45:39.013633 184995 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 779099ns I0713 00:45:39.013875 184996 leveldb.cpp:460] Deleting ~1 keys from leveldb took 372294ns I0713 00:45:39.014077 185010 leveldb.cpp:460] Deleting ~1 keys from leveldb took 516675ns I0713 00:45:39.014178 184995 leveldb.cpp:460] Deleting ~1 keys from leveldb took 533209ns I0713 00:45:39.021173 184996 leveldb.cpp:527] Compacting range 3-3 took 7.280187ms I0713 00:45:39.021234 184996 replica.cpp:712] Persisted action NOP at position 4 I0713 00:45:39.023022 184995 leveldb.cpp:527] Compacting range 3-3 took 8.78496ms I0713 00:45:39.023048 185010 leveldb.cpp:527] Compacting range 3-3 took 8.949092ms I0713 00:45:39.023123 184995 replica.cpp:712] Persisted action NOP at position 4 I0713 00:45:39.023164 185010 replica.cpp:712] Persisted action NOP at position 4 I0713 00:45:39.025501 185002 replica.cpp:391] Replica received explicit promise request from __req_res__(902)@172.17.0.3:33167 for position 5 with proposal 1 I0713 00:45:39.025630 184999 replica.cpp:391] Replica received explicit promise request from __req_res__(903)@172.17.0.3:33167 for position 5 with proposal 1 I0713 00:45:39.025724 185002 leveldb.cpp:510] Reading position from leveldb took 157553ns I0713 00:45:39.025748 185018 replica.cpp:391] Replica received explicit promise request from __req_res__(904)@172.17.0.3:33167 for position 5 with proposal 1 I0713 00:45:39.025882 184999 leveldb.cpp:510] Reading position from leveldb took 176234ns I0713 00:45:39.026906 185018 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 1.095634ms I0713 00:45:39.027002 185018 replica.cpp:712] Persisted action NOP at position 5 I0713 00:45:39.214557 185006 replica.cpp:391] Replica received explicit promise request from __req_res__(905)@172.17.0.3:33167 for position 5 with proposal 2 I0713 00:45:39.214712 185012 replica.cpp:391] Replica received explicit promise request from __req_res__(906)@172.17.0.3:33167 for position 5 with proposal 2 I0713 00:45:39.214782 185006 leveldb.cpp:510] Reading position from leveldb took 141595ns I0713 00:45:39.214824 184998 replica.cpp:391] Replica received explicit promise request from __req_res__(907)@172.17.0.3:33167 for position 5 with proposal 2 I0713 00:45:39.214939 185012 leveldb.cpp:510] Reading position from leveldb took 147706ns I0713 00:45:39.214967 184998 leveldb.cpp:510] Reading position from leveldb took 70743ns I0713 00:45:39.216034 184998 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 1.033835ms I0713 00:45:39.216065 185006 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.225843ms I0713 00:45:39.216115 184998 replica.cpp:712] Persisted action NOP at position 5 I0713 00:45:39.216178 185006 replica.cpp:712] Persisted action APPEND at position 5 I0713 00:45:39.216369 185012 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.376069ms I0713 00:45:39.216466 185012 replica.cpp:712] Persisted action APPEND at position 5 I0713 00:45:39.217626 185018 replica.cpp:695] Replica received learned notice for position 5 from log-network(42)@172.17.0.3:33167 I0713 00:45:39.217695 185000 replica.cpp:695] Replica received learned notice for position 5 from log-network(42)@172.17.0.3:33167 I0713 00:45:39.217715 185015 replica.cpp:695] Replica received learned notice for position 5 from log-network(42)@172.17.0.3:33167 I0713 00:45:39.218429 185015 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 638839ns I0713 00:45:39.218472 185015 replica.cpp:712] Persisted action APPEND at position 5 I0713 00:45:39.218551 185018 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 882450ns I0713 00:45:39.218551 185000 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 813033ns I0713 00:45:39.218658 185018 replica.cpp:712] Persisted action APPEND at position 5 I0713 00:45:39.218693 185000 replica.cpp:712] Persisted action APPEND at position 5 I0713 00:45:39.220660 184996 replica.cpp:391] Replica received explicit promise request from __req_res__(908)@172.17.0.3:33167 for position 6 with proposal 2 I0713 00:45:39.220856 184996 leveldb.cpp:510] Reading position from leveldb took 123891ns I0713 00:45:39.220855 185013 replica.cpp:391] Replica received explicit promise request from __req_res__(909)@172.17.0.3:33167 for position 6 with proposal 2 I0713 00:45:39.221060 185013 leveldb.cpp:510] Reading position from leveldb took 129426ns I0713 00:45:39.221166 184997 replica.cpp:391] Replica received explicit promise request from __req_res__(910)@172.17.0.3:33167 for position 6 with proposal 2 I0713 00:45:39.221563 184996 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 657223ns I0713 00:45:39.221616 184996 replica.cpp:712] Persisted action APPEND at position 6 I0713 00:45:39.221776 184997 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 525278ns I0713 00:45:39.221851 184997 replica.cpp:712] Persisted action NOP at position 6 I0713 00:45:39.221909 185013 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 768660ns I0713 00:45:39.221997 185013 replica.cpp:712] Persisted action APPEND at position 6 I0713 00:45:39.222956 185002 replica.cpp:695] Replica received learned notice for position 6 from log-network(42)@172.17.0.3:33167 I0713 00:45:39.223204 185018 replica.cpp:695] Replica received learned notice for position 6 from log-network(42)@172.17.0.3:33167 I0713 00:45:39.223351 185001 replica.cpp:695] Replica received learned notice for position 6 from log-network(42)@172.17.0.3:33167 I0713 00:45:39.223954 185018 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 723847ns I0713 00:45:39.223954 185002 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 955825ns I0713 00:45:39.224061 185018 replica.cpp:712] Persisted action APPEND at position 6 I0713 00:45:39.224085 185002 replica.cpp:712] Persisted action APPEND at position 6 I0713 00:45:39.224098 185001 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 726074ns I0713 00:45:39.224164 185001 replica.cpp:712] Persisted action APPEND at position 6 I0713 00:45:39.226483 185014 replica.cpp:391] Replica received explicit promise request from __req_res__(912)@172.17.0.3:33167 for position 7 with proposal 2 I0713 00:45:39.226562 185015 replica.cpp:391] Replica received explicit promise request from __req_res__(913)@172.17.0.3:33167 for position 7 with proposal 2 I0713 00:45:39.226658 185005 replica.cpp:391] Replica received explicit promise request from __req_res__(911)@172.17.0.3:33167 for position 7 with proposal 2 I0713 00:45:39.226691 185014 leveldb.cpp:510] Reading position from leveldb took 136990ns I0713 00:45:39.226871 185005 leveldb.cpp:510] Reading position from leveldb took 133278ns I0713 00:45:39.227207 185015 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 589425ns I0713 00:45:39.227290 185015 replica.cpp:712] Persisted action NOP at position 7 I0713 00:45:39.227332 185014 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 529432ns I0713 00:45:39.227397 185014 replica.cpp:712] Persisted action APPEND at position 7 I0713 00:45:39.227411 185005 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 480548ns I0713 00:45:39.227473 185005 replica.cpp:712] Persisted action APPEND at position 7 I0713 00:45:39.228781 185012 replica.cpp:695] Replica received learned notice for position 7 from log-network(42)@172.17.0.3:33167 I0713 00:45:39.228873 184999 replica.cpp:695] Replica received learned notice for position 7 from log-network(42)@172.17.0.3:33167 I0713 00:45:39.229032 184995 replica.cpp:695] Replica received learned notice for position 7 from log-network(42)@172.17.0.3:33167 I0713 00:45:39.229314 185012 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 494326ns I0713 00:45:39.229358 185012 replica.cpp:712] Persisted action APPEND at position 7 I0713 00:45:39.229496 184995 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 408367ns I0713 00:45:39.229501 184999 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 572034ns I0713 00:45:39.229547 184995 replica.cpp:712] Persisted action APPEND at position 7 I0713 00:45:39.229588 184999 replica.cpp:712] Persisted action APPEND at position 7 I0713 00:45:39.231752 185006 replica.cpp:391] Replica received explicit promise request from __req_res__(914)@172.17.0.3:33167 for position 8 with proposal 2 I0713 00:45:39.231860 185006 leveldb.cpp:510] Reading position from leveldb took 69817ns I0713 00:45:39.232079 185001 replica.cpp:391] Replica received explicit promise request from __req_res__(916)@172.17.0.3:33167 for position 8 with proposal 2 I0713 00:45:39.232229 185006 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 342469ns I0713 00:45:39.232228 185014 replica.cpp:391] Replica received explicit promise request from __req_res__(915)@172.17.0.3:33167 for position 8 with proposal 2 I0713 00:45:39.232251 185006 replica.cpp:712] Persisted action APPEND at position 8 I0713 00:45:39.232481 185014 leveldb.cpp:510] Reading position from leveldb took 170835ns I0713 00:45:39.232717 185001 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 585685ns I0713 00:45:39.232803 185001 replica.cpp:712] Persisted action NOP at position 8 I0713 00:45:39.233135 185014 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 583340ns I0713 00:45:39.233223 185014 replica.cpp:712] Persisted action APPEND at position 8 I0713 00:45:39.233317 185000 replica.cpp:695] Replica received learned notice for position 8 from log-network(42)@172.17.0.3:33167 I0713 00:45:39.233453 184999 replica.cpp:695] Replica received learned notice for position 8 from log-network(42)@172.17.0.3:33167 I0713 00:45:39.233582 185014 replica.cpp:695] Replica received learned notice for position 8 from log-network(42)@172.17.0.3:33167 I0713 00:45:39.233676 185000 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 330205ns I0713 00:45:39.233700 185000 replica.cpp:712] Persisted action APPEND at position 8 I0713 00:45:39.234117 185014 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 513484ns I0713 00:45:39.234117 184999 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 611870ns I0713 00:45:39.234185 185014 replica.cpp:712] Persisted action APPEND at position 8 I0713 00:45:39.234239 184999 replica.cpp:712] Persisted action APPEND at position 8 I0713 00:45:39.236886 185003 replica.cpp:391] Replica received explicit promise request from __req_res__(917)@172.17.0.3:33167 for position 9 with proposal 2 I0713 00:45:39.237087 185003 leveldb.cpp:510] Reading position from leveldb took 132706ns I0713 00:45:39.237191 185015 replica.cpp:391] Replica received explicit promise request from __req_res__(918)@172.17.0.3:33167 for position 9 with proposal 2 I0713 00:45:39.237354 185008 replica.cpp:391] Replica received explicit promise request from __req_res__(919)@172.17.0.3:33167 for position 9 with proposal 2 I0713 00:45:39.237418 185015 leveldb.cpp:510] Reading position from leveldb took 149169ns I0713 00:45:39.237769 185003 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 624034ns I0713 00:45:39.237835 185003 replica.cpp:712] Persisted action APPEND at position 9 I0713 00:45:39.237960 185008 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 539997ns I0713 00:45:39.238015 185008 replica.cpp:712] Persisted action NOP at position 9 I0713 00:45:39.238078 185015 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 598622ns I0713 00:45:39.238181 185015 replica.cpp:712] Persisted action APPEND at position 9 I0713 00:45:39.238873 185002 replica.cpp:695] Replica received learned notice for position 9 from log-network(42)@172.17.0.3:33167 I0713 00:45:39.238988 184998 replica.cpp:695] Replica received learned notice for position 9 from log-network(42)@172.17.0.3:33167 I0713 00:45:39.239001 185017 replica.cpp:695] Replica received learned notice for position 9 from log-network(42)@172.17.0.3:33167 I0713 00:45:39.239264 185002 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 362070ns I0713 00:45:39.239296 185002 replica.cpp:712] Persisted action APPEND at position 9 I0713 00:45:39.239548 184998 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 493717ns I0713 00:45:39.239554 185017 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 459619ns I0713 00:45:39.239600 184998 replica.cpp:712] Persisted action APPEND at position 9 I0713 00:45:39.239640 185017 replica.cpp:712] Persisted action APPEND at position 9 I0713 00:45:39.242074 185010 replica.cpp:391] Replica received explicit promise request from __req_res__(920)@172.17.0.3:33167 for position 10 with proposal 2 I0713 00:45:39.242190 185008 replica.cpp:391] Replica received explicit promise request from __req_res__(921)@172.17.0.3:33167 for position 10 with proposal 2 I0713 00:45:39.242215 185002 replica.cpp:391] Replica received explicit promise request from __req_res__(922)@172.17.0.3:33167 for position 10 with proposal 2 I0713 00:45:39.242280 185010 leveldb.cpp:510] Reading position from leveldb took 131055ns I0713 00:45:39.242419 185008 leveldb.cpp:510] Reading position from leveldb took 144252ns I0713 00:45:39.242686 185002 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 398532ns I0713 00:45:39.242714 185002 replica.cpp:712] Persisted action NOP at position 10 I0713 00:45:39.243014 185008 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 533197ns I0713 00:45:39.243062 185010 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 739819ns I0713 00:45:39.243108 185008 replica.cpp:712] Persisted action APPEND at position 10 I0713 00:45:39.243153 185010 replica.cpp:712] Persisted action APPEND at position 10 I0713 00:45:39.244611 185009 replica.cpp:695] Replica received learned notice for position 10 from log-network(42)@172.17.0.3:33167 I0713 00:45:39.244652 185013 replica.cpp:695] Replica received learned notice for position 10 from log-network(42)@172.17.0.3:33167 I0713 00:45:39.244822 185003 replica.cpp:695] Replica received learned notice for position 10 from log-network(42)@172.17.0.3:33167 I0713 00:45:39.244999 185009 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 363866ns I0713 00:45:39.245023 185009 replica.cpp:712] Persisted action APPEND at position 10 I0713 00:45:39.245261 185013 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 559289ns I0713 00:45:39.245333 185013 replica.cpp:712] Persisted action APPEND at position 10 I0713 00:45:39.245518 185003 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 648860ns I0713 00:45:39.245605 185003 replica.cpp:712] Persisted action APPEND at position 10 I0713 00:45:39.245887 185003 catchup.cpp:357] Recover process terminated I0713 00:45:39.249073 185004 leveldb.cpp:510] Reading position from leveldb took 123929ns I0713 00:45:39.249220 185004 leveldb.cpp:510] Reading position from leveldb took 35960ns I0713 00:45:39.249279 185004 leveldb.cpp:510] Reading position from leveldb took 27031ns I0713 00:45:39.249336 185004 leveldb.cpp:510] Reading position from leveldb took 26698ns I0713 00:45:39.249393 185004 leveldb.cpp:510] Reading position from leveldb took 27648ns I0713 00:45:39.249450 185004 leveldb.cpp:510] Reading position from leveldb took 27212ns [ OK ] RecoverTest.CatchupVotingWithGap (643 ms) [ RUN ] RecoverTest.CatchupVotingOnePosition I0713 00:45:39.260215 184994 leveldb.cpp:217] Opened db in 4.854545ms I0713 00:45:39.261708 184994 leveldb.cpp:224] Compacted db in 1.439998ms I0713 00:45:39.261788 184994 leveldb.cpp:239] Created db iterator in 44585ns I0713 00:45:39.261831 184994 leveldb.cpp:245] Seeked to beginning of db in 30681ns I0713 00:45:39.261850 184994 leveldb.cpp:320] Iterated through 0 keys in the db in 6882ns I0713 00:45:39.261911 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0713 00:45:39.263525 185000 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 1.045986ms I0713 00:45:39.263613 185000 replica.cpp:322] Persisted replica status to VOTING I0713 00:45:39.268826 184994 leveldb.cpp:217] Opened db in 4.229978ms I0713 00:45:39.270450 184994 leveldb.cpp:224] Compacted db in 1.595329ms I0713 00:45:39.270557 184994 leveldb.cpp:239] Created db iterator in 39110ns I0713 00:45:39.270574 184994 leveldb.cpp:245] Seeked to beginning of db in 6922ns I0713 00:45:39.270586 184994 leveldb.cpp:320] Iterated through 0 keys in the db in 4909ns I0713 00:45:39.270633 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0713 00:45:39.272292 185010 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 940056ns I0713 00:45:39.272370 185010 replica.cpp:322] Persisted replica status to VOTING I0713 00:45:39.276199 184994 leveldb.cpp:217] Opened db in 3.189288ms I0713 00:45:39.277558 184994 leveldb.cpp:224] Compacted db in 1.31981ms I0713 00:45:39.277612 184994 leveldb.cpp:239] Created db iterator in 28692ns I0713 00:45:39.277628 184994 leveldb.cpp:245] Seeked to beginning of db in 6411ns I0713 00:45:39.277640 184994 leveldb.cpp:320] Iterated through 0 keys in the db in 4909ns I0713 00:45:39.277683 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0713 00:45:39.279171 185016 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 1.00502ms I0713 00:45:39.279263 185016 replica.cpp:322] Persisted replica status to VOTING I0713 00:45:39.284037 184994 leveldb.cpp:217] Opened db in 3.904631ms I0713 00:45:39.288218 184994 leveldb.cpp:224] Compacted db in 4.151484ms I0713 00:45:39.288323 184994 leveldb.cpp:239] Created db iterator in 40360ns I0713 00:45:39.288368 184994 leveldb.cpp:245] Seeked to beginning of db in 35013ns I0713 00:45:39.288422 184994 leveldb.cpp:320] Iterated through 1 keys in the db in 43333ns I0713 00:45:39.288465 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0713 00:45:39.292644 184994 leveldb.cpp:217] Opened db in 3.926238ms I0713 00:45:39.296613 184994 leveldb.cpp:224] Compacted db in 3.938906ms I0713 00:45:39.296718 184994 leveldb.cpp:239] Created db iterator in 39714ns I0713 00:45:39.296763 184994 leveldb.cpp:245] Seeked to beginning of db in 34639ns I0713 00:45:39.296813 184994 leveldb.cpp:320] Iterated through 1 keys in the db in 42409ns I0713 00:45:39.296856 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0713 00:45:39.300647 184994 leveldb.cpp:217] Opened db in 3.539618ms I0713 00:45:39.304474 184994 leveldb.cpp:224] Compacted db in 3.802236ms I0713 00:45:39.304610 184994 leveldb.cpp:239] Created db iterator in 51349ns I0713 00:45:39.304667 184994 leveldb.cpp:245] Seeked to beginning of db in 44837ns I0713 00:45:39.304733 184994 leveldb.cpp:320] Iterated through 1 keys in the db in 53869ns I0713 00:45:39.304788 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0713 00:45:39.305451 185012 catchup.cpp:342] Starting missing positions recovery I0713 00:45:39.305967 185012 catchup.cpp:368] Replica is in VOTING status I0713 00:45:39.308022 185017 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(923)@172.17.0.3:33167 I0713 00:45:39.308028 184995 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(924)@172.17.0.3:33167 I0713 00:45:39.308035 185001 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(925)@172.17.0.3:33167 I0713 00:45:39.309043 185013 recover.cpp:197] Received a recover response from a replica in VOTING status I0713 00:45:39.309603 185013 recover.cpp:197] Received a recover response from a replica in VOTING status I0713 00:45:39.310765 185004 catchup.cpp:357] Recover process terminated [ OK ] RecoverTest.CatchupVotingOnePosition (61 ms) [----------] 9 tests from RecoverTest (2816 ms total) [----------] 4 tests from LogTest [ RUN ] LogTest.WriteRead I0713 00:45:39.320946 184994 leveldb.cpp:217] Opened db in 4.750151ms I0713 00:45:39.323069 184994 leveldb.cpp:224] Compacted db in 2.084121ms I0713 00:45:39.323199 184994 leveldb.cpp:239] Created db iterator in 43865ns I0713 00:45:39.323222 184994 leveldb.cpp:245] Seeked to beginning of db in 9134ns I0713 00:45:39.323239 184994 leveldb.cpp:320] Iterated through 0 keys in the db in 6651ns I0713 00:45:39.323298 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0713 00:45:39.324815 185012 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 892475ns I0713 00:45:39.324893 185012 replica.cpp:322] Persisted replica status to VOTING I0713 00:45:39.329388 184994 leveldb.cpp:217] Opened db in 3.697822ms I0713 00:45:39.331312 184994 leveldb.cpp:224] Compacted db in 1.894188ms I0713 00:45:39.331419 184994 leveldb.cpp:239] Created db iterator in 35218ns I0713 00:45:39.331436 184994 leveldb.cpp:245] Seeked to beginning of db in 6746ns I0713 00:45:39.331449 184994 leveldb.cpp:320] Iterated through 0 keys in the db in 4740ns I0713 00:45:39.331494 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0713 00:45:39.332919 185008 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 786101ns I0713 00:45:39.333004 185008 replica.cpp:322] Persisted replica status to VOTING I0713 00:45:39.337081 184994 leveldb.cpp:217] Opened db in 3.41222ms I0713 00:45:39.340718 184994 leveldb.cpp:224] Compacted db in 3.609174ms I0713 00:45:39.340828 184994 leveldb.cpp:239] Created db iterator in 41207ns I0713 00:45:39.340873 184994 leveldb.cpp:245] Seeked to beginning of db in 35685ns I0713 00:45:39.340924 184994 leveldb.cpp:320] Iterated through 1 keys in the db in 42860ns I0713 00:45:39.340970 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0713 00:45:39.346138 184994 leveldb.cpp:217] Opened db in 4.887938ms I0713 00:45:39.350984 184994 leveldb.cpp:224] Compacted db in 4.816214ms I0713 00:45:39.351099 184994 leveldb.cpp:239] Created db iterator in 42707ns I0713 00:45:39.351145 184994 leveldb.cpp:245] Seeked to beginning of db in 35989ns I0713 00:45:39.351194 184994 leveldb.cpp:320] Iterated through 1 keys in the db in 42381ns I0713 00:45:39.351239 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0713 00:45:39.352191 185010 recover.cpp:437] Starting replica recovery I0713 00:45:39.352802 184998 recover.cpp:468] Replica is in VOTING status I0713 00:45:39.353163 184998 recover.cpp:447] Recover process terminated I0713 00:45:39.354099 185009 log.cpp:554] Attempting to start the writer I0713 00:45:39.356316 184995 replica.cpp:497] Replica received implicit promise request from __req_res__(926)@172.17.0.3:33167 with proposal 1 I0713 00:45:39.356362 185008 replica.cpp:497] Replica received implicit promise request from __req_res__(927)@172.17.0.3:33167 with proposal 1 I0713 00:45:39.357777 184995 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 1.412362ms I0713 00:45:39.357779 185008 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 1.350605ms I0713 00:45:39.357892 184995 replica.cpp:344] Persisted promised to 1 I0713 00:45:39.357954 185008 replica.cpp:344] Persisted promised to 1 I0713 00:45:39.359108 185018 coordinator.cpp:238] Coordinator attempting to fill missing positions I0713 00:45:39.361394 185016 replica.cpp:391] Replica received explicit promise request from __req_res__(928)@172.17.0.3:33167 for position 0 with proposal 2 I0713 00:45:39.361502 185007 replica.cpp:391] Replica received explicit promise request from __req_res__(929)@172.17.0.3:33167 for position 0 with proposal 2 I0713 00:45:39.362555 185007 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 983272ns I0713 00:45:39.362555 185016 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 1.081517ms I0713 00:45:39.362648 185007 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.362709 185016 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.364655 184996 replica.cpp:541] Replica received write request for position 0 from __req_res__(930)@172.17.0.3:33167 I0713 00:45:39.364758 185004 replica.cpp:541] Replica received write request for position 0 from __req_res__(931)@172.17.0.3:33167 I0713 00:45:39.364820 184996 leveldb.cpp:510] Reading position from leveldb took 77533ns I0713 00:45:39.364899 185004 leveldb.cpp:510] Reading position from leveldb took 70548ns I0713 00:45:39.365593 185004 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 650200ns I0713 00:45:39.365654 184996 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 788704ns I0713 00:45:39.365686 185004 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.365741 184996 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.366613 185000 replica.cpp:695] Replica received learned notice for position 0 from log-network(44)@172.17.0.3:33167 I0713 00:45:39.366623 184999 replica.cpp:695] Replica received learned notice for position 0 from log-network(44)@172.17.0.3:33167 I0713 00:45:39.367697 185000 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 1.025528ms I0713 00:45:39.367738 184999 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 991470ns I0713 00:45:39.367802 185000 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.367842 184999 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.368815 185006 log.cpp:570] Writer started with ending position 0 I0713 00:45:39.369765 184996 log.cpp:578] Attempting to append 11 bytes to the log I0713 00:45:39.370036 185009 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 I0713 00:45:39.371322 184997 replica.cpp:541] Replica received write request for position 1 from __req_res__(932)@172.17.0.3:33167 I0713 00:45:39.371407 184995 replica.cpp:541] Replica received write request for position 1 from __req_res__(933)@172.17.0.3:33167 I0713 00:45:39.372323 184997 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 922819ns I0713 00:45:39.372385 184997 replica.cpp:712] Persisted action APPEND at position 1 I0713 00:45:39.372391 184995 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 915415ns I0713 00:45:39.372473 184995 replica.cpp:712] Persisted action APPEND at position 1 I0713 00:45:39.373478 185013 replica.cpp:695] Replica received learned notice for position 1 from log-network(44)@172.17.0.3:33167 I0713 00:45:39.373608 185018 replica.cpp:695] Replica received learned notice for position 1 from log-network(44)@172.17.0.3:33167 I0713 00:45:39.374431 185018 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 760532ns I0713 00:45:39.374485 185013 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 960039ns I0713 00:45:39.374518 185018 replica.cpp:712] Persisted action APPEND at position 1 I0713 00:45:39.374572 185013 replica.cpp:712] Persisted action APPEND at position 1 I0713 00:45:39.377115 184999 leveldb.cpp:510] Reading position from leveldb took 130328ns [ OK ] LogTest.WriteRead (66 ms) [ RUN ] LogTest.Position I0713 00:45:39.387874 184994 leveldb.cpp:217] Opened db in 5.629157ms I0713 00:45:39.390247 184994 leveldb.cpp:224] Compacted db in 2.323022ms I0713 00:45:39.390376 184994 leveldb.cpp:239] Created db iterator in 46061ns I0713 00:45:39.390399 184994 leveldb.cpp:245] Seeked to beginning of db in 9247ns I0713 00:45:39.390415 184994 leveldb.cpp:320] Iterated through 0 keys in the db in 6668ns I0713 00:45:39.390475 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0713 00:45:39.392491 184995 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 1.425077ms I0713 00:45:39.392580 184995 replica.cpp:322] Persisted replica status to VOTING I0713 00:45:39.399330 184994 leveldb.cpp:217] Opened db in 5.729586ms I0713 00:45:39.401212 184994 leveldb.cpp:224] Compacted db in 1.852133ms I0713 00:45:39.401321 184994 leveldb.cpp:239] Created db iterator in 37124ns I0713 00:45:39.401337 184994 leveldb.cpp:245] Seeked to beginning of db in 7036ns I0713 00:45:39.401350 184994 leveldb.cpp:320] Iterated through 0 keys in the db in 5090ns I0713 00:45:39.401396 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0713 00:45:39.403515 185015 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 1.115999ms I0713 00:45:39.403607 185015 replica.cpp:322] Persisted replica status to VOTING I0713 00:45:39.409740 184994 leveldb.cpp:217] Opened db in 5.294246ms I0713 00:45:39.415331 184994 leveldb.cpp:224] Compacted db in 5.558058ms I0713 00:45:39.415468 184994 leveldb.cpp:239] Created db iterator in 51307ns I0713 00:45:39.415527 184994 leveldb.cpp:245] Seeked to beginning of db in 44147ns I0713 00:45:39.415594 184994 leveldb.cpp:320] Iterated through 1 keys in the db in 56705ns I0713 00:45:39.415665 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0713 00:45:39.422170 184994 leveldb.cpp:217] Opened db in 6.082784ms I0713 00:45:39.427155 184994 leveldb.cpp:224] Compacted db in 4.946685ms I0713 00:45:39.427285 184994 leveldb.cpp:239] Created db iterator in 50374ns I0713 00:45:39.427345 184994 leveldb.cpp:245] Seeked to beginning of db in 44298ns I0713 00:45:39.427409 184994 leveldb.cpp:320] Iterated through 1 keys in the db in 52960ns I0713 00:45:39.427465 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0713 00:45:39.428421 185014 recover.cpp:437] Starting replica recovery I0713 00:45:39.428998 185011 recover.cpp:468] Replica is in VOTING status I0713 00:45:39.429363 185011 recover.cpp:447] Recover process terminated I0713 00:45:39.430194 185012 log.cpp:554] Attempting to start the writer I0713 00:45:39.432423 184996 replica.cpp:497] Replica received implicit promise request from __req_res__(934)@172.17.0.3:33167 with proposal 1 I0713 00:45:39.432636 185009 replica.cpp:497] Replica received implicit promise request from __req_res__(935)@172.17.0.3:33167 with proposal 1 I0713 00:45:39.433768 184996 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 1.281473ms I0713 00:45:39.433879 184996 replica.cpp:344] Persisted promised to 1 I0713 00:45:39.434373 185009 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 1.666962ms I0713 00:45:39.434449 185009 replica.cpp:344] Persisted promised to 1 I0713 00:45:39.435834 185002 coordinator.cpp:238] Coordinator attempting to fill missing positions I0713 00:45:39.438033 185008 replica.cpp:391] Replica received explicit promise request from __req_res__(936)@172.17.0.3:33167 for position 0 with proposal 2 I0713 00:45:39.438079 185006 replica.cpp:391] Replica received explicit promise request from __req_res__(937)@172.17.0.3:33167 for position 0 with proposal 2 I0713 00:45:39.439051 185008 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 944531ns I0713 00:45:39.439112 185006 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 956951ns I0713 00:45:39.439133 185008 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.439198 185006 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.440912 185010 replica.cpp:541] Replica received write request for position 0 from __req_res__(938)@172.17.0.3:33167 I0713 00:45:39.441051 185010 leveldb.cpp:510] Reading position from leveldb took 69767ns I0713 00:45:39.441036 185018 replica.cpp:541] Replica received write request for position 0 from __req_res__(939)@172.17.0.3:33167 I0713 00:45:39.441213 185018 leveldb.cpp:510] Reading position from leveldb took 74984ns I0713 00:45:39.441700 185010 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 591050ns I0713 00:45:39.441738 185010 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.441958 185018 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 689445ns I0713 00:45:39.442003 185018 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.442992 184998 replica.cpp:695] Replica received learned notice for position 0 from log-network(45)@172.17.0.3:33167 I0713 00:45:39.443079 185006 replica.cpp:695] Replica received learned notice for position 0 from log-network(45)@172.17.0.3:33167 I0713 00:45:39.443635 184998 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 585729ns I0713 00:45:39.443686 184998 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.443682 185006 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 547236ns I0713 00:45:39.443760 185006 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.444814 185002 log.cpp:570] Writer started with ending position 0 I0713 00:45:39.445852 185004 log.cpp:578] Attempting to append 11 bytes to the log I0713 00:45:39.446137 185016 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 I0713 00:45:39.447485 185009 replica.cpp:541] Replica received write request for position 1 from __req_res__(940)@172.17.0.3:33167 I0713 00:45:39.447584 184998 replica.cpp:541] Replica received write request for position 1 from __req_res__(941)@172.17.0.3:33167 I0713 00:45:39.448303 184998 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 664182ns I0713 00:45:39.448308 185009 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 752748ns I0713 00:45:39.448393 184998 replica.cpp:712] Persisted action APPEND at position 1 I0713 00:45:39.448475 185009 replica.cpp:712] Persisted action APPEND at position 1 I0713 00:45:39.449702 185012 replica.cpp:695] Replica received learned notice for position 1 from log-network(45)@172.17.0.3:33167 I0713 00:45:39.449775 185001 replica.cpp:695] Replica received learned notice for position 1 from log-network(45)@172.17.0.3:33167 I0713 00:45:39.450392 185001 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 537007ns I0713 00:45:39.450450 185012 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 707396ns I0713 00:45:39.450470 185001 replica.cpp:712] Persisted action APPEND at position 1 I0713 00:45:39.450551 185012 replica.cpp:712] Persisted action APPEND at position 1 [ OK ] LogTest.Position (73 ms) [ RUN ] LogTest.Metrics I0713 00:45:39.459254 184994 leveldb.cpp:217] Opened db in 4.078593ms I0713 00:45:39.460839 184994 leveldb.cpp:224] Compacted db in 1.544164ms I0713 00:45:39.460896 184994 leveldb.cpp:239] Created db iterator in 30259ns I0713 00:45:39.460911 184994 leveldb.cpp:245] Seeked to beginning of db in 6486ns I0713 00:45:39.460923 184994 leveldb.cpp:320] Iterated through 0 keys in the db in 5042ns I0713 00:45:39.460968 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0713 00:45:39.462636 185007 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 884724ns I0713 00:45:39.462720 185007 replica.cpp:322] Persisted replica status to VOTING I0713 00:45:39.467514 184994 leveldb.cpp:217] Opened db in 3.823837ms I0713 00:45:39.470827 184994 leveldb.cpp:224] Compacted db in 3.28256ms I0713 00:45:39.470932 184994 leveldb.cpp:239] Created db iterator in 41226ns I0713 00:45:39.470978 184994 leveldb.cpp:245] Seeked to beginning of db in 34959ns I0713 00:45:39.471027 184994 leveldb.cpp:320] Iterated through 1 keys in the db in 42600ns I0713 00:45:39.471071 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0713 00:45:39.471916 185000 recover.cpp:437] Starting replica recovery I0713 00:45:39.472405 185009 recover.cpp:468] Replica is in VOTING status I0713 00:45:39.472708 185009 recover.cpp:447] Recover process terminated I0713 00:45:39.473554 184998 log.cpp:554] Attempting to start the writer I0713 00:45:39.475543 185007 replica.cpp:497] Replica received implicit promise request from __req_res__(942)@172.17.0.3:33167 with proposal 1 I0713 00:45:39.476497 185007 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 908747ns I0713 00:45:39.476565 185007 replica.cpp:344] Persisted promised to 1 I0713 00:45:39.477623 185000 coordinator.cpp:238] Coordinator attempting to fill missing positions I0713 00:45:39.479462 185003 replica.cpp:391] Replica received explicit promise request from __req_res__(943)@172.17.0.3:33167 for position 0 with proposal 2 I0713 00:45:39.480278 185003 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 749124ns I0713 00:45:39.480360 185003 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.482064 185005 replica.cpp:541] Replica received write request for position 0 from __req_res__(944)@172.17.0.3:33167 I0713 00:45:39.482210 185005 leveldb.cpp:510] Reading position from leveldb took 73207ns I0713 00:45:39.482993 185005 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 743136ns I0713 00:45:39.483079 185005 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.484073 184998 replica.cpp:695] Replica received learned notice for position 0 from log-network(46)@172.17.0.3:33167 I0713 00:45:39.484872 184998 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 748128ns I0713 00:45:39.484957 184998 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.486186 185010 log.cpp:570] Writer started with ending position 0 I0713 00:45:39.490482 185002 process.cpp:3671] Handling HTTP event for process 'metrics' with path: '/metrics/snapshot' [ OK ] LogTest.Metrics (47 ms) [ RUN ] LogTest.ReaderCatchup I0713 00:45:39.505293 184994 leveldb.cpp:217] Opened db in 3.676601ms I0713 00:45:39.507225 184994 leveldb.cpp:224] Compacted db in 1.895356ms I0713 00:45:39.507328 184994 leveldb.cpp:239] Created db iterator in 39291ns I0713 00:45:39.507345 184994 leveldb.cpp:245] Seeked to beginning of db in 6558ns I0713 00:45:39.507357 184994 leveldb.cpp:320] Iterated through 0 keys in the db in 4898ns I0713 00:45:39.507408 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0713 00:45:39.509037 185012 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 758861ns I0713 00:45:39.509119 185012 replica.cpp:322] Persisted replica status to VOTING I0713 00:45:39.513060 184994 leveldb.cpp:217] Opened db in 3.184188ms I0713 00:45:39.514739 184994 leveldb.cpp:224] Compacted db in 1.648347ms I0713 00:45:39.514838 184994 leveldb.cpp:239] Created db iterator in 35511ns I0713 00:45:39.514855 184994 leveldb.cpp:245] Seeked to beginning of db in 6692ns I0713 00:45:39.514868 184994 leveldb.cpp:320] Iterated through 0 keys in the db in 4804ns I0713 00:45:39.514912 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0713 00:45:39.516189 185009 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 581769ns I0713 00:45:39.516225 185009 replica.cpp:322] Persisted replica status to VOTING I0713 00:45:39.519889 184994 leveldb.cpp:217] Opened db in 3.15009ms I0713 00:45:39.521066 184994 leveldb.cpp:224] Compacted db in 1.141088ms I0713 00:45:39.521116 184994 leveldb.cpp:239] Created db iterator in 26046ns I0713 00:45:39.521131 184994 leveldb.cpp:245] Seeked to beginning of db in 6391ns I0713 00:45:39.521143 184994 leveldb.cpp:320] Iterated through 0 keys in the db in 4816ns I0713 00:45:39.521183 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0713 00:45:39.522790 184999 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 876308ns I0713 00:45:39.522876 184999 replica.cpp:322] Persisted replica status to VOTING I0713 00:45:39.527052 184994 leveldb.cpp:217] Opened db in 3.556933ms I0713 00:45:39.530970 184994 leveldb.cpp:224] Compacted db in 3.893734ms I0713 00:45:39.531078 184994 leveldb.cpp:239] Created db iterator in 41589ns I0713 00:45:39.531126 184994 leveldb.cpp:245] Seeked to beginning of db in 35509ns I0713 00:45:39.531181 184994 leveldb.cpp:320] Iterated through 1 keys in the db in 45747ns I0713 00:45:39.531225 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0713 00:45:39.535444 184994 leveldb.cpp:217] Opened db in 3.96423ms I0713 00:45:39.538892 184994 leveldb.cpp:224] Compacted db in 3.419582ms I0713 00:45:39.539003 184994 leveldb.cpp:239] Created db iterator in 47376ns I0713 00:45:39.539059 184994 leveldb.cpp:245] Seeked to beginning of db in 41349ns I0713 00:45:39.539119 184994 leveldb.cpp:320] Iterated through 1 keys in the db in 49187ns I0713 00:45:39.539175 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0713 00:45:39.541792 185015 replica.cpp:497] Replica received implicit promise request from __req_res__(946)@172.17.0.3:33167 with proposal 1 I0713 00:45:39.541800 185011 replica.cpp:497] Replica received implicit promise request from __req_res__(945)@172.17.0.3:33167 with proposal 1 I0713 00:45:39.542944 185011 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 1.046733ms I0713 00:45:39.543035 185011 replica.cpp:344] Persisted promised to 1 I0713 00:45:39.542749 185015 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 1.388571ms I0713 00:45:39.543346 185015 replica.cpp:344] Persisted promised to 1 I0713 00:45:39.544543 184995 coordinator.cpp:238] Coordinator attempting to fill missing positions I0713 00:45:39.546514 185009 replica.cpp:391] Replica received explicit promise request from __req_res__(947)@172.17.0.3:33167 for position 0 with proposal 2 I0713 00:45:39.546696 184998 replica.cpp:391] Replica received explicit promise request from __req_res__(948)@172.17.0.3:33167 for position 0 with proposal 2 I0713 00:45:39.547256 185009 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 665500ns I0713 00:45:39.547343 185009 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.547417 184998 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 642546ns I0713 00:45:39.547498 184998 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.549126 185002 replica.cpp:541] Replica received write request for position 0 from __req_res__(949)@172.17.0.3:33167 I0713 00:45:39.549203 184999 replica.cpp:541] Replica received write request for position 0 from __req_res__(950)@172.17.0.3:33167 I0713 00:45:39.549271 185002 leveldb.cpp:510] Reading position from leveldb took 72790ns I0713 00:45:39.549350 184999 leveldb.cpp:510] Reading position from leveldb took 72843ns I0713 00:45:39.549897 184999 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 488475ns I0713 00:45:39.549899 185002 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 576773ns I0713 00:45:39.549948 184999 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.549984 185002 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.551026 185015 replica.cpp:695] Replica received learned notice for position 0 from log-network(47)@172.17.0.3:33167 I0713 00:45:39.551026 185005 replica.cpp:695] Replica received learned notice for position 0 from log-network(47)@172.17.0.3:33167 I0713 00:45:39.552004 185015 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 927635ns I0713 00:45:39.552004 185005 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 903065ns I0713 00:45:39.552089 185015 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.552104 185005 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.553381 185017 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 I0713 00:45:39.554687 185018 replica.cpp:541] Replica received write request for position 1 from __req_res__(951)@172.17.0.3:33167 I0713 00:45:39.554756 185000 replica.cpp:541] Replica received write request for position 1 from __req_res__(952)@172.17.0.3:33167 I0713 00:45:39.555238 185000 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 445740ns I0713 00:45:39.555297 185000 replica.cpp:712] Persisted action APPEND at position 1 I0713 00:45:39.555341 185018 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 571595ns I0713 00:45:39.555433 185018 replica.cpp:712] Persisted action APPEND at position 1 I0713 00:45:39.556422 185012 replica.cpp:695] Replica received learned notice for position 1 from log-network(47)@172.17.0.3:33167 I0713 00:45:39.556546 184996 replica.cpp:695] Replica received learned notice for position 1 from log-network(47)@172.17.0.3:33167 I0713 00:45:39.557158 185012 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 691119ns I0713 00:45:39.557251 185012 replica.cpp:712] Persisted action APPEND at position 1 I0713 00:45:39.557380 184996 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 783273ns I0713 00:45:39.557479 184996 replica.cpp:712] Persisted action APPEND at position 1 I0713 00:45:39.558856 185017 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 2 I0713 00:45:39.560299 185008 replica.cpp:541] Replica received write request for position 2 from __req_res__(953)@172.17.0.3:33167 I0713 00:45:39.560479 185015 replica.cpp:541] Replica received write request for position 2 from __req_res__(954)@172.17.0.3:33167 I0713 00:45:39.561201 185008 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 868773ns I0713 00:45:39.561271 185008 replica.cpp:712] Persisted action APPEND at position 2 I0713 00:45:39.561437 185015 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 887492ns I0713 00:45:39.561481 185015 replica.cpp:712] Persisted action APPEND at position 2 I0713 00:45:39.562480 185012 replica.cpp:695] Replica received learned notice for position 2 from log-network(47)@172.17.0.3:33167 I0713 00:45:39.562489 185006 replica.cpp:695] Replica received learned notice for position 2 from log-network(47)@172.17.0.3:33167 I0713 00:45:39.563726 185006 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.155234ms I0713 00:45:39.563728 185012 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.202047ms I0713 00:45:39.563827 185006 replica.cpp:712] Persisted action APPEND at position 2 I0713 00:45:39.563901 185012 replica.cpp:712] Persisted action APPEND at position 2 I0713 00:45:39.565519 185000 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3 I0713 00:45:39.566665 185015 replica.cpp:541] Replica received write request for position 3 from __req_res__(956)@172.17.0.3:33167 I0713 00:45:39.566669 184995 replica.cpp:541] Replica received write request for position 3 from __req_res__(955)@172.17.0.3:33167 I0713 00:45:39.567620 185015 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 881551ns I0713 00:45:39.567659 185015 replica.cpp:712] Persisted action APPEND at position 3 I0713 00:45:39.567714 184995 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 936860ns I0713 00:45:39.567796 184995 replica.cpp:712] Persisted action APPEND at position 3 I0713 00:45:39.568827 185010 replica.cpp:695] Replica received learned notice for position 3 from log-network(47)@172.17.0.3:33167 I0713 00:45:39.568904 184998 replica.cpp:695] Replica received learned notice for position 3 from log-network(47)@172.17.0.3:33167 I0713 00:45:39.569447 184998 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 480802ns I0713 00:45:39.569455 185010 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 567829ns I0713 00:45:39.569491 184998 replica.cpp:712] Persisted action APPEND at position 3 I0713 00:45:39.569512 185010 replica.cpp:712] Persisted action APPEND at position 3 I0713 00:45:39.570875 185008 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 4 I0713 00:45:39.572198 185007 replica.cpp:541] Replica received write request for position 4 from __req_res__(957)@172.17.0.3:33167 I0713 00:45:39.572214 185016 replica.cpp:541] Replica received write request for position 4 from __req_res__(958)@172.17.0.3:33167 I0713 00:45:39.573036 185016 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 710147ns I0713 00:45:39.573040 185007 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 774257ns I0713 00:45:39.573127 185016 replica.cpp:712] Persisted action APPEND at position 4 I0713 00:45:39.573213 185007 replica.cpp:712] Persisted action APPEND at position 4 I0713 00:45:39.574321 185000 replica.cpp:695] Replica received learned notice for position 4 from log-network(47)@172.17.0.3:33167 I0713 00:45:39.574400 185004 replica.cpp:695] Replica received learned notice for position 4 from log-network(47)@172.17.0.3:33167 I0713 00:45:39.574889 185000 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 538981ns I0713 00:45:39.574918 185000 replica.cpp:712] Persisted action APPEND at position 4 I0713 00:45:39.575212 185004 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 763052ns I0713 00:45:39.575299 185004 replica.cpp:712] Persisted action APPEND at position 4 I0713 00:45:39.576808 184996 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 5 I0713 00:45:39.578238 185017 replica.cpp:541] Replica received write request for position 5 from __req_res__(959)@172.17.0.3:33167 I0713 00:45:39.578349 185007 replica.cpp:541] Replica received write request for position 5 from __req_res__(960)@172.17.0.3:33167 I0713 00:45:39.579334 185007 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 911557ns I0713 00:45:39.579334 185017 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 1.034992ms I0713 00:45:39.579429 185007 replica.cpp:712] Persisted action APPEND at position 5 I0713 00:45:39.579509 185017 replica.cpp:712] Persisted action APPEND at position 5 I0713 00:45:39.580488 185001 replica.cpp:695] Replica received learned notice for position 5 from log-network(47)@172.17.0.3:33167 I0713 00:45:39.580580 185017 replica.cpp:695] Replica received learned notice for position 5 from log-network(47)@172.17.0.3:33167 I0713 00:45:39.581311 185001 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 762722ns I0713 00:45:39.581337 185001 replica.cpp:712] Persisted action APPEND at position 5 I0713 00:45:39.581422 185017 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 806926ns I0713 00:45:39.581516 185017 replica.cpp:712] Persisted action APPEND at position 5 I0713 00:45:39.583062 185003 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 6 I0713 00:45:39.584290 185010 replica.cpp:541] Replica received write request for position 6 from __req_res__(961)@172.17.0.3:33167 I0713 00:45:39.584379 185005 replica.cpp:541] Replica received write request for position 6 from __req_res__(962)@172.17.0.3:33167 I0713 00:45:39.585060 185010 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 737159ns I0713 00:45:39.585117 185010 replica.cpp:712] Persisted action APPEND at position 6 I0713 00:45:39.585422 185005 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 971935ns I0713 00:45:39.585516 185005 replica.cpp:712] Persisted action APPEND at position 6 I0713 00:45:39.586680 184995 replica.cpp:695] Replica received learned notice for position 6 from log-network(47)@172.17.0.3:33167 I0713 00:45:39.586699 185006 replica.cpp:695] Replica received learned notice for position 6 from log-network(47)@172.17.0.3:33167 I0713 00:45:39.587280 185006 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 496090ns I0713 00:45:39.587286 184995 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 540023ns I0713 00:45:39.587325 185006 replica.cpp:712] Persisted action APPEND at position 6 I0713 00:45:39.587353 184995 replica.cpp:712] Persisted action APPEND at position 6 I0713 00:45:39.588650 185011 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 7 I0713 00:45:39.589967 185011 replica.cpp:541] Replica received write request for position 7 from __req_res__(963)@172.17.0.3:33167 I0713 00:45:39.589983 184997 replica.cpp:541] Replica received write request for position 7 from __req_res__(964)@172.17.0.3:33167 I0713 00:45:39.590817 184997 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 742034ns I0713 00:45:39.590826 185011 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 796213ns I0713 00:45:39.590906 184997 replica.cpp:712] Persisted action APPEND at position 7 I0713 00:45:39.590991 185011 replica.cpp:712] Persisted action APPEND at position 7 I0713 00:45:39.591955 185001 replica.cpp:695] Replica received learned notice for position 7 from log-network(47)@172.17.0.3:33167 I0713 00:45:39.592062 184996 replica.cpp:695] Replica received learned notice for position 7 from log-network(47)@172.17.0.3:33167 I0713 00:45:39.592785 184996 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 672837ns I0713 00:45:39.592810 185001 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 816980ns I0713 00:45:39.592876 184996 replica.cpp:712] Persisted action APPEND at position 7 I0713 00:45:39.592933 185001 replica.cpp:712] Persisted action APPEND at position 7 I0713 00:45:39.594200 185007 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 8 I0713 00:45:39.595450 185011 replica.cpp:541] Replica received write request for position 8 from __req_res__(965)@172.17.0.3:33167 I0713 00:45:39.595649 185002 replica.cpp:541] Replica received write request for position 8 from __req_res__(966)@172.17.0.3:33167 I0713 00:45:39.596455 185002 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 740643ns I0713 00:45:39.596490 185011 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 961551ns I0713 00:45:39.596516 185002 replica.cpp:712] Persisted action APPEND at position 8 I0713 00:45:39.596589 185011 replica.cpp:712] Persisted action APPEND at position 8 I0713 00:45:39.597378 185013 replica.cpp:695] Replica received learned notice for position 8 from log-network(47)@172.17.0.3:33167 I0713 00:45:39.597378 185009 replica.cpp:695] Replica received learned notice for position 8 from log-network(47)@172.17.0.3:33167 I0713 00:45:39.597918 185009 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 489695ns I0713 00:45:39.597951 185009 replica.cpp:712] Persisted action APPEND at position 8 I0713 00:45:39.598060 185013 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 660552ns I0713 00:45:39.598147 185013 replica.cpp:712] Persisted action APPEND at position 8 I0713 00:45:39.599071 185018 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 9 I0713 00:45:39.600191 185006 replica.cpp:541] Replica received write request for position 9 from __req_res__(968)@172.17.0.3:33167 I0713 00:45:39.600188 185017 replica.cpp:541] Replica received write request for position 9 from __req_res__(967)@172.17.0.3:33167 I0713 00:45:39.600715 185006 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 472137ns I0713 00:45:39.600739 185006 replica.cpp:712] Persisted action APPEND at position 9 I0713 00:45:39.601125 185017 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 806762ns I0713 00:45:39.601217 185017 replica.cpp:712] Persisted action APPEND at position 9 I0713 00:45:39.601964 185009 replica.cpp:695] Replica received learned notice for position 9 from log-network(47)@172.17.0.3:33167 I0713 00:45:39.602048 185000 replica.cpp:695] Replica received learned notice for position 9 from log-network(47)@172.17.0.3:33167 I0713 00:45:39.602455 185009 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 463733ns I0713 00:45:39.602480 185009 replica.cpp:712] Persisted action APPEND at position 9 I0713 00:45:39.602665 185000 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 553627ns I0713 00:45:39.602725 185000 replica.cpp:712] Persisted action APPEND at position 9 I0713 00:45:39.603932 184997 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 10 I0713 00:45:39.605057 185011 replica.cpp:541] Replica received write request for position 10 from __req_res__(969)@172.17.0.3:33167 I0713 00:45:39.605078 184995 replica.cpp:541] Replica received write request for position 10 from __req_res__(970)@172.17.0.3:33167 I0713 00:45:39.605775 184995 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 584174ns I0713 00:45:39.605834 185011 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 706591ns I0713 00:45:39.605854 184995 replica.cpp:712] Persisted action APPEND at position 10 I0713 00:45:39.605937 185011 replica.cpp:712] Persisted action APPEND at position 10 I0713 00:45:39.606905 185005 replica.cpp:695] Replica received learned notice for position 10 from log-network(47)@172.17.0.3:33167 I0713 00:45:39.606926 185016 replica.cpp:695] Replica received learned notice for position 10 from log-network(47)@172.17.0.3:33167 I0713 00:45:39.608021 185016 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 981446ns I0713 00:45:39.608016 185005 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 1.058448ms I0713 00:45:39.608110 185016 replica.cpp:712] Persisted action APPEND at position 10 I0713 00:45:39.608173 185005 replica.cpp:712] Persisted action APPEND at position 10 I0713 00:45:39.615840 184994 leveldb.cpp:217] Opened db in 6.295634ms I0713 00:45:39.621150 184994 leveldb.cpp:224] Compacted db in 5.277376ms I0713 00:45:39.621304 184994 leveldb.cpp:239] Created db iterator in 57743ns I0713 00:45:39.621366 184994 leveldb.cpp:245] Seeked to beginning of db in 45075ns I0713 00:45:39.621434 184994 leveldb.cpp:320] Iterated through 1 keys in the db in 56459ns I0713 00:45:39.621495 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0713 00:45:39.622599 185002 recover.cpp:437] Starting replica recovery I0713 00:45:39.623167 185002 recover.cpp:468] Replica is in VOTING status I0713 00:45:39.623469 185002 recover.cpp:447] Recover process terminated I0713 00:45:39.624228 185011 catchup.cpp:342] Starting missing positions recovery I0713 00:45:39.624775 185011 catchup.cpp:368] Replica is in VOTING status I0713 00:45:39.626816 185015 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(971)@172.17.0.3:33167 I0713 00:45:39.626942 185016 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(972)@172.17.0.3:33167 I0713 00:45:39.627072 185004 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(973)@172.17.0.3:33167 I0713 00:45:39.627910 184999 recover.cpp:197] Received a recover response from a replica in VOTING status I0713 00:45:39.629179 184999 recover.cpp:197] Received a recover response from a replica in VOTING status I0713 00:45:39.630563 185000 catchup.cpp:423] Starting catch-up from position 0 to 9 I0713 00:45:39.632858 185016 replica.cpp:391] Replica received explicit promise request from __req_res__(974)@172.17.0.3:33167 for position 0 with proposal 0 I0713 00:45:39.632906 185006 replica.cpp:391] Replica received explicit promise request from __req_res__(976)@172.17.0.3:33167 for position 0 with proposal 0 I0713 00:45:39.632906 185008 replica.cpp:391] Replica received explicit promise request from __req_res__(975)@172.17.0.3:33167 for position 0 with proposal 0 I0713 00:45:39.633049 185016 leveldb.cpp:510] Reading position from leveldb took 107882ns I0713 00:45:39.633081 185008 leveldb.cpp:510] Reading position from leveldb took 88551ns I0713 00:45:39.818686 185012 replica.cpp:391] Replica received explicit promise request from __req_res__(977)@172.17.0.3:33167 for position 0 with proposal 3 I0713 00:45:39.818748 185002 replica.cpp:391] Replica received explicit promise request from __req_res__(979)@172.17.0.3:33167 for position 0 with proposal 3 I0713 00:45:39.818759 185015 replica.cpp:391] Replica received explicit promise request from __req_res__(978)@172.17.0.3:33167 for position 0 with proposal 3 I0713 00:45:39.818862 185012 leveldb.cpp:510] Reading position from leveldb took 99245ns I0713 00:45:39.818964 185015 leveldb.cpp:510] Reading position from leveldb took 93133ns I0713 00:45:39.820084 185002 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 1.25907ms I0713 00:45:39.820129 185012 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 1.21379ms I0713 00:45:39.820089 185015 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 1.079636ms I0713 00:45:39.820221 185012 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.820185 185002 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.820273 185015 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.821276 185000 replica.cpp:695] Replica received learned notice for position 0 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.821295 185018 replica.cpp:695] Replica received learned notice for position 0 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.821301 185006 replica.cpp:695] Replica received learned notice for position 0 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.822487 185018 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 1.107158ms I0713 00:45:39.822521 185000 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 1.189779ms I0713 00:45:39.822587 185018 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.822630 185000 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.822954 185006 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 1.433593ms I0713 00:45:39.823050 185006 replica.cpp:712] Persisted action NOP at position 0 I0713 00:45:39.825286 184999 replica.cpp:391] Replica received explicit promise request from __req_res__(980)@172.17.0.3:33167 for position 1 with proposal 3 I0713 00:45:39.825367 185012 replica.cpp:391] Replica received explicit promise request from __req_res__(982)@172.17.0.3:33167 for position 1 with proposal 3 I0713 00:45:39.825403 185016 replica.cpp:391] Replica received explicit promise request from __req_res__(981)@172.17.0.3:33167 for position 1 with proposal 3 I0713 00:45:39.825464 184999 leveldb.cpp:510] Reading position from leveldb took 99058ns I0713 00:45:39.825572 185016 leveldb.cpp:510] Reading position from leveldb took 95648ns I0713 00:45:39.826431 184999 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 922829ns I0713 00:45:39.826457 185012 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 1.032588ms I0713 00:45:39.826519 184999 replica.cpp:712] Persisted action APPEND at position 1 I0713 00:45:39.826553 185012 replica.cpp:712] Persisted action NOP at position 1 I0713 00:45:39.826833 185016 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.216289ms I0713 00:45:39.826930 185016 replica.cpp:712] Persisted action APPEND at position 1 I0713 00:45:39.827517 185007 replica.cpp:695] Replica received learned notice for position 1 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.827522 185008 replica.cpp:695] Replica received learned notice for position 1 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.827533 185014 replica.cpp:695] Replica received learned notice for position 1 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.828353 185014 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 672521ns I0713 00:45:39.828358 185008 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 731889ns I0713 00:45:39.828408 185014 replica.cpp:712] Persisted action APPEND at position 1 I0713 00:45:39.828437 185008 replica.cpp:712] Persisted action APPEND at position 1 I0713 00:45:39.828452 185007 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 884290ns I0713 00:45:39.828536 185007 replica.cpp:712] Persisted action APPEND at position 1 I0713 00:45:39.830520 185004 replica.cpp:391] Replica received explicit promise request from __req_res__(983)@172.17.0.3:33167 for position 2 with proposal 3 I0713 00:45:39.830619 185004 leveldb.cpp:510] Reading position from leveldb took 52708ns I0713 00:45:39.830650 185017 replica.cpp:391] Replica received explicit promise request from __req_res__(984)@172.17.0.3:33167 for position 2 with proposal 3 I0713 00:45:39.830680 185016 replica.cpp:391] Replica received explicit promise request from __req_res__(985)@172.17.0.3:33167 for position 2 with proposal 3 I0713 00:45:39.830849 185017 leveldb.cpp:510] Reading position from leveldb took 112934ns I0713 00:45:39.831422 185004 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 786005ns I0713 00:45:39.831473 185004 replica.cpp:712] Persisted action APPEND at position 2 I0713 00:45:39.831530 185016 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 765590ns I0713 00:45:39.831615 185016 replica.cpp:712] Persisted action NOP at position 2 I0713 00:45:39.831688 185017 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 778459ns I0713 00:45:39.831773 185017 replica.cpp:712] Persisted action APPEND at position 2 I0713 00:45:39.832237 185009 replica.cpp:695] Replica received learned notice for position 2 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.832329 185015 replica.cpp:695] Replica received learned notice for position 2 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.832392 185010 replica.cpp:695] Replica received learned notice for position 2 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.832777 185009 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 489216ns I0713 00:45:39.832811 185009 replica.cpp:712] Persisted action APPEND at position 2 I0713 00:45:39.833077 185010 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 635036ns I0713 00:45:39.833084 185015 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 712891ns I0713 00:45:39.833165 185010 replica.cpp:712] Persisted action APPEND at position 2 I0713 00:45:39.833254 185015 replica.cpp:712] Persisted action APPEND at position 2 I0713 00:45:39.835494 185002 replica.cpp:391] Replica received explicit promise request from __req_res__(986)@172.17.0.3:33167 for position 3 with proposal 3 I0713 00:45:39.835572 184998 replica.cpp:391] Replica received explicit promise request from __req_res__(988)@172.17.0.3:33167 for position 3 with proposal 3 I0713 00:45:39.835589 184996 replica.cpp:391] Replica received explicit promise request from __req_res__(987)@172.17.0.3:33167 for position 3 with proposal 3 I0713 00:45:39.835671 185002 leveldb.cpp:510] Reading position from leveldb took 97378ns I0713 00:45:39.835808 184996 leveldb.cpp:510] Reading position from leveldb took 104214ns I0713 00:45:39.836541 185002 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 790020ns I0713 00:45:39.836592 184998 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 956620ns I0713 00:45:39.836632 185002 replica.cpp:712] Persisted action APPEND at position 3 I0713 00:45:39.836673 184998 replica.cpp:712] Persisted action NOP at position 3 I0713 00:45:39.836987 184996 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.1318ms I0713 00:45:39.837085 184996 replica.cpp:712] Persisted action APPEND at position 3 I0713 00:45:39.837622 185003 replica.cpp:695] Replica received learned notice for position 3 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.837659 185006 replica.cpp:695] Replica received learned notice for position 3 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.837637 185018 replica.cpp:695] Replica received learned notice for position 3 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.838656 185018 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 893770ns I0713 00:45:39.838699 185018 replica.cpp:712] Persisted action APPEND at position 3 I0713 00:45:39.838768 185006 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.058156ms I0713 00:45:39.838802 185003 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.132654ms I0713 00:45:39.838866 185006 replica.cpp:712] Persisted action APPEND at position 3 I0713 00:45:39.838904 185003 replica.cpp:712] Persisted action APPEND at position 3 I0713 00:45:39.840523 185009 replica.cpp:391] Replica received explicit promise request from __req_res__(989)@172.17.0.3:33167 for position 4 with proposal 3 I0713 00:45:39.840668 185009 leveldb.cpp:510] Reading position from leveldb took 85273ns I0713 00:45:39.840796 184998 replica.cpp:391] Replica received explicit promise request from __req_res__(990)@172.17.0.3:33167 for position 4 with proposal 3 I0713 00:45:39.840934 185010 replica.cpp:391] Replica received explicit promise request from __req_res__(991)@172.17.0.3:33167 for position 4 with proposal 3 I0713 00:45:39.840972 184998 leveldb.cpp:510] Reading position from leveldb took 104505ns I0713 00:45:39.841400 185009 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 681116ns I0713 00:45:39.841444 185009 replica.cpp:712] Persisted action APPEND at position 4 I0713 00:45:39.841625 184998 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 552678ns I0713 00:45:39.841665 184998 replica.cpp:712] Persisted action APPEND at position 4 I0713 00:45:39.841742 185010 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 746593ns I0713 00:45:39.841845 185010 replica.cpp:712] Persisted action NOP at position 4 I0713 00:45:39.842502 184999 replica.cpp:695] Replica received learned notice for position 4 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.842628 185007 replica.cpp:695] Replica received learned notice for position 4 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.842649 185011 replica.cpp:695] Replica received learned notice for position 4 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.843550 185007 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 864686ns I0713 00:45:39.843575 184999 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.016029ms I0713 00:45:39.843639 185011 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 909255ns I0713 00:45:39.843640 185007 replica.cpp:712] Persisted action APPEND at position 4 I0713 00:45:39.843670 184999 replica.cpp:712] Persisted action APPEND at position 4 I0713 00:45:39.843740 185011 replica.cpp:712] Persisted action APPEND at position 4 I0713 00:45:39.846066 185013 replica.cpp:391] Replica received explicit promise request from __req_res__(992)@172.17.0.3:33167 for position 5 with proposal 3 I0713 00:45:39.846258 185013 leveldb.cpp:510] Reading position from leveldb took 113751ns I0713 00:45:39.846307 185018 replica.cpp:391] Replica received explicit promise request from __req_res__(993)@172.17.0.3:33167 for position 5 with proposal 3 I0713 00:45:39.846442 185008 replica.cpp:391] Replica received explicit promise request from __req_res__(994)@172.17.0.3:33167 for position 5 with proposal 3 I0713 00:45:39.846475 185018 leveldb.cpp:510] Reading position from leveldb took 94401ns I0713 00:45:39.847332 185008 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 844810ns I0713 00:45:39.847332 185013 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.012888ms I0713 00:45:39.847434 185008 replica.cpp:712] Persisted action NOP at position 5 I0713 00:45:39.847469 185013 replica.cpp:712] Persisted action APPEND at position 5 I0713 00:45:39.847466 185018 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 918410ns I0713 00:45:39.847571 185018 replica.cpp:712] Persisted action APPEND at position 5 I0713 00:45:39.848476 184999 replica.cpp:695] Replica received learned notice for position 5 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.848508 184995 replica.cpp:695] Replica received learned notice for position 5 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.848547 185014 replica.cpp:695] Replica received learned notice for position 5 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.849285 185014 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 686879ns I0713 00:45:39.849354 185014 replica.cpp:712] Persisted action APPEND at position 5 I0713 00:45:39.849366 184999 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 846917ns I0713 00:45:39.849366 184995 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 811999ns I0713 00:45:39.849455 184999 replica.cpp:712] Persisted action APPEND at position 5 I0713 00:45:39.849498 184995 replica.cpp:712] Persisted action APPEND at position 5 I0713 00:45:39.851302 185000 replica.cpp:391] Replica received explicit promise request from __req_res__(996)@172.17.0.3:33167 for position 6 with proposal 3 I0713 00:45:39.851310 185013 replica.cpp:391] Replica received explicit promise request from __req_res__(997)@172.17.0.3:33167 for position 6 with proposal 3 I0713 00:45:39.851289 185008 replica.cpp:391] Replica received explicit promise request from __req_res__(995)@172.17.0.3:33167 for position 6 with proposal 3 I0713 00:45:39.851395 185000 leveldb.cpp:510] Reading position from leveldb took 49852ns I0713 00:45:39.851537 185008 leveldb.cpp:510] Reading position from leveldb took 103431ns I0713 00:45:39.852185 185000 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 618472ns I0713 00:45:39.852243 185000 replica.cpp:712] Persisted action APPEND at position 6 I0713 00:45:39.852275 185013 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 913424ns I0713 00:45:39.852275 185008 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 695413ns I0713 00:45:39.852375 185013 replica.cpp:712] Persisted action NOP at position 6 I0713 00:45:39.852412 185008 replica.cpp:712] Persisted action APPEND at position 6 I0713 00:45:39.853219 185008 replica.cpp:695] Replica received learned notice for position 6 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.853276 185012 replica.cpp:695] Replica received learned notice for position 6 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.853355 185009 replica.cpp:695] Replica received learned notice for position 6 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.853875 185008 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 602133ns I0713 00:45:39.853920 185008 replica.cpp:712] Persisted action APPEND at position 6 I0713 00:45:39.853910 185012 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 598529ns I0713 00:45:39.854004 185012 replica.cpp:712] Persisted action APPEND at position 6 I0713 00:45:39.854189 185009 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 784761ns I0713 00:45:39.854276 185009 replica.cpp:712] Persisted action APPEND at position 6 I0713 00:45:39.856514 185014 replica.cpp:391] Replica received explicit promise request from __req_res__(998)@172.17.0.3:33167 for position 7 with proposal 3 I0713 00:45:39.856618 185007 replica.cpp:391] Replica received explicit promise request from __req_res__(999)@172.17.0.3:33167 for position 7 with proposal 3 I0713 00:45:39.856624 185017 replica.cpp:391] Replica received explicit promise request from __req_res__(1000)@172.17.0.3:33167 for position 7 with proposal 3 I0713 00:45:39.856662 185014 leveldb.cpp:510] Reading position from leveldb took 95445ns I0713 00:45:39.856791 185007 leveldb.cpp:510] Reading position from leveldb took 102230ns I0713 00:45:39.857443 185014 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 654462ns I0713 00:45:39.857453 185007 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 583982ns I0713 00:45:39.857487 185014 replica.cpp:712] Persisted action APPEND at position 7 I0713 00:45:39.857470 185017 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 740100ns I0713 00:45:39.857518 185007 replica.cpp:712] Persisted action APPEND at position 7 I0713 00:45:39.857570 185017 replica.cpp:712] Persisted action NOP at position 7 I0713 00:45:39.858510 185004 replica.cpp:695] Replica received learned notice for position 7 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.858556 184999 replica.cpp:695] Replica received learned notice for position 7 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.858554 184997 replica.cpp:695] Replica received learned notice for position 7 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.859122 185004 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 568863ns I0713 00:45:39.859161 185004 replica.cpp:712] Persisted action APPEND at position 7 I0713 00:45:39.859500 184997 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 824289ns I0713 00:45:39.859524 184999 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 916579ns I0713 00:45:39.859589 184997 replica.cpp:712] Persisted action APPEND at position 7 I0713 00:45:39.859632 184999 replica.cpp:712] Persisted action APPEND at position 7 I0713 00:45:39.861757 185012 replica.cpp:391] Replica received explicit promise request from __req_res__(1001)@172.17.0.3:33167 for position 8 with proposal 3 I0713 00:45:39.861861 185012 leveldb.cpp:510] Reading position from leveldb took 65887ns I0713 00:45:39.861965 185014 replica.cpp:391] Replica received explicit promise request from __req_res__(1002)@172.17.0.3:33167 for position 8 with proposal 3 I0713 00:45:39.862043 185014 leveldb.cpp:510] Reading position from leveldb took 52797ns I0713 00:45:39.862023 185005 replica.cpp:391] Replica received explicit promise request from __req_res__(1003)@172.17.0.3:33167 for position 8 with proposal 3 I0713 00:45:39.862416 185012 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 519982ns I0713 00:45:39.862439 185012 replica.cpp:712] Persisted action APPEND at position 8 I0713 00:45:39.862680 185014 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 616018ns I0713 00:45:39.862709 185014 replica.cpp:712] Persisted action APPEND at position 8 I0713 00:45:39.862813 185005 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 736223ns I0713 00:45:39.862905 185005 replica.cpp:712] Persisted action NOP at position 8 I0713 00:45:39.863134 185005 replica.cpp:695] Replica received learned notice for position 8 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.863142 184998 replica.cpp:695] Replica received learned notice for position 8 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.863158 185000 replica.cpp:695] Replica received learned notice for position 8 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.863945 185000 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 695223ns I0713 00:45:39.863945 184998 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 749666ns I0713 00:45:39.864114 184998 replica.cpp:712] Persisted action APPEND at position 8 I0713 00:45:39.863950 185005 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 796506ns I0713 00:45:39.864034 185000 replica.cpp:712] Persisted action APPEND at position 8 I0713 00:45:39.864248 185005 replica.cpp:712] Persisted action APPEND at position 8 I0713 00:45:39.866509 185012 replica.cpp:391] Replica received explicit promise request from __req_res__(1004)@172.17.0.3:33167 for position 9 with proposal 3 I0713 00:45:39.866509 185014 replica.cpp:391] Replica received explicit promise request from __req_res__(1005)@172.17.0.3:33167 for position 9 with proposal 3 I0713 00:45:39.866667 185016 replica.cpp:391] Replica received explicit promise request from __req_res__(1006)@172.17.0.3:33167 for position 9 with proposal 3 I0713 00:45:39.866717 185012 leveldb.cpp:510] Reading position from leveldb took 115388ns I0713 00:45:39.866717 185014 leveldb.cpp:510] Reading position from leveldb took 88203ns I0713 00:45:39.867692 185014 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 870099ns I0713 00:45:39.867692 185012 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 889972ns I0713 00:45:39.867748 185014 replica.cpp:712] Persisted action APPEND at position 9 I0713 00:45:39.867755 185012 replica.cpp:712] Persisted action APPEND at position 9 I0713 00:45:39.867781 185016 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 1.055189ms I0713 00:45:39.867871 185016 replica.cpp:712] Persisted action NOP at position 9 I0713 00:45:39.868549 184999 replica.cpp:695] Replica received learned notice for position 9 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.868616 184998 replica.cpp:695] Replica received learned notice for position 9 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.868702 185001 replica.cpp:695] Replica received learned notice for position 9 from log-network(48)@172.17.0.3:33167 I0713 00:45:39.869365 185001 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 615855ns I0713 00:45:39.869372 184999 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 768262ns I0713 00:45:39.869390 184998 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 731599ns I0713 00:45:39.869506 184999 replica.cpp:712] Persisted action APPEND at position 9 I0713 00:45:39.869553 184998 replica.cpp:712] Persisted action APPEND at position 9 I0713 00:45:39.869453 185001 replica.cpp:712] Persisted action APPEND at position 9 I0713 00:45:39.870776 184997 catchup.cpp:357] Recover process terminated I0713 00:45:39.873478 184999 leveldb.cpp:510] Reading position from leveldb took 125993ns I0713 00:45:39.873632 184999 leveldb.cpp:510] Reading position from leveldb took 44753ns I0713 00:45:39.873695 184999 leveldb.cpp:510] Reading position from leveldb took 27252ns I0713 00:45:39.873754 184999 leveldb.cpp:510] Reading position from leveldb took 26876ns I0713 00:45:39.873836 184999 leveldb.cpp:510] Reading position from leveldb took 56412ns I0713 00:45:39.873926 184999 leveldb.cpp:510] Reading position from leveldb took 42436ns I0713 00:45:39.873999 184999 leveldb.cpp:510] Reading position from leveldb took 39145ns I0713 00:45:39.874097 184999 leveldb.cpp:510] Reading position from leveldb took 50635ns I0713 00:45:39.874202 184999 leveldb.cpp:510] Reading position from leveldb took 49499ns I0713 00:45:39.874298 184999 leveldb.cpp:510] Reading position from leveldb took 46269ns [ OK ] LogTest.ReaderCatchup (379 ms) [----------] 4 tests from LogTest (565 ms total) [----------] 2 tests from LogZooKeeperTest I0713 00:45:39.880517 184994 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/slf4j-api-1.6.1.jar:/tmp/SRC/build/mesos-1.12.0/_build/sub/3rdparty/zookeeper-3.4.8/lib/log4j-1.2.16.jar:/tmp/SRC/build/mesos-1.12.0/_build/sub/3rdparty/zookeeper-3.4.8/lib/jline-0.9.94.jar:/tmp/SRC/build/mesos-1.12.0/_build/sub/3rdparty/zookeeper-3.4.8/lib/slf4j-log4j12-1.6.1.jar:/tmp/SRC/build/mesos-1.12.0/_build/sub/3rdparty/zookeeper-3.4.8/lib/netty-3.7.0.Final.jar [ RUN ] LogZooKeeperTest.WriteRead I0713 00:45:39.965709 184994 jvm.cpp:590] Looking up method <init>(Ljava/lang/String;)V I0713 00:45:39.966073 184994 jvm.cpp:590] Looking up method deleteOnExit()V I0713 00:45:39.967031 184994 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. I0713 00:45:40.047159 184994 jvm.cpp:590] Looking up method <init>()V I0713 00:45:40.047821 184994 jvm.cpp:590] Looking up method <init>(Lorg/apache/zookeeper/server/persistence/FileTxnSnapLog;Lorg/apache/zookeeper/server/ZooKeeperServer$DataTreeBuilder;)V *** Aborted at 1720831540 (unix time) try "date -d @1720831540" if you are using GNU date *** PC: @ 0x7fd8f2912ccd OopStorage::Block::release_entries() *** SIGSEGV (@0x238) received by PID 184994 (TID 0x7fd965776b40) from PID 568; stack trace: *** @ 0x7fd8f2921929 os::Linux::chained_handler() @ 0x7fd8f292763b JVM_handle_linux_signal @ 0x7fd8f291a1dc signalHandler() @ 0x7fd966dc9420 (unknown) @ 0x7fd8f2912ccd OopStorage::Block::release_entries() @ 0x7fd8f2912f26 OopStorage::release() @ 0x7fd8f2615b21 jni_DeleteGlobalRef @ 0x7fd976521894 JNIEnv_::DeleteGlobalRef() @ 0x7fd97651f9dc Jvm::deleteGlobalRef() @ 0x55ddb572490c Jvm::Object::~Object() @ 0x55ddb5729732 org::apache::zookeeper::server::ZooKeeperServer::DataTreeBuilder::~DataTreeBuilder() @ 0x55ddb572c036 org::apache::zookeeper::server::ZooKeeperServer::BasicDataTreeBuilder::~BasicDataTreeBuilder() @ 0x55ddb5728051 mesos::internal::tests::ZooKeeperTestServer::ZooKeeperTestServer() @ 0x55ddb40cbf36 mesos::internal::tests::ZooKeeperTest::ZooKeeperTest() @ 0x55ddb40ce27f mesos::internal::tests::LogZooKeeperTest::LogZooKeeperTest() @ 0x55ddb40ce390 mesos::internal::tests::LogZooKeeperTest_WriteRead_Test::LogZooKeeperTest_WriteRead_Test() @ 0x55ddb4139292 testing::internal::TestFactoryImpl<>::CreateTest() @ 0x55ddb576e8de testing::internal::HandleSehExceptionsInMethodIfSupported<>() @ 0x55ddb5767eaf testing::internal::HandleExceptionsInMethodIfSupported<>() @ 0x55ddb57440e7 testing::TestInfo::Run() @ 0x55ddb57447ef testing::TestCase::Run() @ 0x55ddb574bb89 testing::internal::UnitTestImpl::RunAllTests() @ 0x55ddb576fb0c testing::internal::HandleSehExceptionsInMethodIfSupported<>() @ 0x55ddb5768a15 testing::internal::HandleExceptionsInMethodIfSupported<>() @ 0x55ddb574a6a1 testing::UnitTest::Run() @ 0x55ddb4156e45 RUN_ALL_TESTS() @ 0x55ddb415680c main @ 0x7fd966be7083 __libc_start_main @ 0x55ddb319c79e _start make[4]: *** [Makefile:17971: check-local] Segmentation fault (core dumped) make[4]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub/src' I0713 00:45:40.850889 186033 exec.cpp:560] Agent exited ... shutting down make[3]: *** [Makefile:15906: check-am] Error 2 I0713 00:45:40.851505 186035 executor.cpp:190] Received SHUTDOWN event I0713 00:45:40.851565 186035 executor.cpp:843] Shutting down I0713 00:45:40.851612 186035 executor.cpp:956] Sending SIGTERM to process tree at pid 186044 I0713 00:45:40.861075 186035 executor.cpp:969] Sent SIGTERM to the following process trees: [ -+- 186044 sh -c dd if=/dev/zero of=volume_path/file bs=1048576 count=2 && sleep 1000 \--- 186050 sleep 1000 ] I0713 00:45:40.861112 186035 executor.cpp:973] Scheduling escalation to SIGKILL in 3secs from now make[3]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub/src' make[2]: *** [Makefile:15909: check] Error 2 I0713 00:45:40.914566 186040 executor.cpp:1041] Command terminated with signal Terminated (pid: 186044) W0713 00:45:40.917232 186041 process.cpp:1917] Failed to send 'mesos.internal.StatusUpdateMessage' to '172.17.0.3:33167', connect: Failed to connect to 172.17.0.3:33167: Connection refused make[2]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub/src' make[1]: *** [Makefile:785: check-recursive] Error 1 make[1]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub' make: *** [Makefile:999: distcheck] Error 1 + copy_out_test_reports + find /tmp/SRC -name '*-tests.xml' -exec cp '{}' /SRC ';' 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/33499/console - Mesos Reviewbot On July 12, 2024, 9:27 p.m., Jason Zhou wrote: > > ----------------------------------------------------------- > This is an automatically generated e-mail. To reply, visit: > https://reviews.apache.org/r/75087/ > ----------------------------------------------------------- > > (Updated July 12, 2024, 9:27 p.m.) > > > Review request for mesos and Benjamin Mahler. > > > Repository: mesos > > > Description > ------- > > Due to a systemd-induced race-condition related to the MacAddressPolicy > being set to 'persistent' on versions >= 242, we will have to set the > peer link MAC address of the peer link (eth0) when we create the eth0 > peer link so that the udev will not try to overwrite it when it is > notified that this device was created, which would lead to a race > condition here where us and udev are racing to see who is the last one > to write our MAC address to eth0. > > > Diffs > ----- > > src/slave/containerizer/mesos/isolators/network/port_mapping.cpp > 3b3b899fb43364f545eb9748ab4215fd5b2e2895 > > > Diff: https://reviews.apache.org/r/75087/diff/1/ > > > Testing > ------- > > > Thanks, > > Jason Zhou > >
