----------------------------------------------------------- This is an automatically generated e-mail. To reply, visit: https://reviews.apache.org/r/75086/#review226671 -----------------------------------------------------------
Bad patch! Reviews applied: [75086] 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_75086"] Error: ...<truncated>... twork(41)@172.17.0.3:35959 I0712 23:22:15.357266 185018 replica.cpp:695] Replica received learned notice for position 11 from log-network(41)@172.17.0.3:35959 I0712 23:22:15.357635 185017 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 402135ns I0712 23:22:15.357905 185018 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 592245ns I0712 23:22:15.358157 185017 leveldb.cpp:460] Deleting ~5 keys from leveldb took 514985ns I0712 23:22:15.358434 185018 leveldb.cpp:460] Deleting ~5 keys from leveldb took 505615ns I0712 23:22:15.364466 185017 leveldb.cpp:527] Compacting range 0-4 took 6.277336ms I0712 23:22:15.364481 185018 leveldb.cpp:527] Compacting range 0-4 took 6.019281ms I0712 23:22:15.364526 185017 replica.cpp:712] Persisted action TRUNCATE at position 11 I0712 23:22:15.364543 185018 replica.cpp:712] Persisted action TRUNCATE at position 11 I0712 23:22:15.370657 184994 leveldb.cpp:217] Opened db in 5.081716ms I0712 23:22:15.373093 184994 leveldb.cpp:224] Compacted db in 2.405803ms I0712 23:22:15.373204 184994 leveldb.cpp:239] Created db iterator in 45104ns I0712 23:22:15.373250 184994 leveldb.cpp:245] Seeked to beginning of db in 36336ns I0712 23:22:15.373303 184994 leveldb.cpp:320] Iterated through 1 keys in the db in 45754ns I0712 23:22:15.373353 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0712 23:22:15.374147 185005 catchup.cpp:342] Starting missing positions recovery I0712 23:22:15.374884 185013 catchup.cpp:368] Replica is in VOTING status I0712 23:22:15.377205 185018 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(887)@172.17.0.3:35959 I0712 23:22:15.377355 185012 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(888)@172.17.0.3:35959 I0712 23:22:15.378438 185015 recover.cpp:197] Received a recover response from a replica in VOTING status I0712 23:22:15.379895 185015 recover.cpp:197] Received a recover response from a replica in VOTING status I0712 23:22:15.381791 185015 catchup.cpp:423] Starting catch-up from position 0 to 10 I0712 23:22:15.384511 184997 replica.cpp:391] Replica received explicit promise request from __req_res__(892)@172.17.0.3:35959 for position 0 with proposal 0 I0712 23:22:15.384595 185012 replica.cpp:391] Replica received explicit promise request from __req_res__(890)@172.17.0.3:35959 for position 0 with proposal 0 I0712 23:22:15.384766 184996 replica.cpp:391] Replica received explicit promise request from __req_res__(891)@172.17.0.3:35959 for position 0 with proposal 0 I0712 23:22:15.571743 185016 replica.cpp:391] Replica received explicit promise request from __req_res__(893)@172.17.0.3:35959 for position 0 with proposal 1 I0712 23:22:15.571964 185007 replica.cpp:391] Replica received explicit promise request from __req_res__(894)@172.17.0.3:35959 for position 0 with proposal 1 I0712 23:22:15.572050 184995 replica.cpp:391] Replica received explicit promise request from __req_res__(895)@172.17.0.3:35959 for position 0 with proposal 1 I0712 23:22:15.573096 185003 replica.cpp:695] Replica received learned notice for position 0 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.573195 185014 replica.cpp:695] Replica received learned notice for position 0 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.573325 184995 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 1.190675ms I0712 23:22:15.573431 184995 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:15.573872 184995 replica.cpp:695] Replica received learned notice for position 0 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.574054 185003 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 905700ns I0712 23:22:15.574118 185003 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:15.574460 185014 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 1.21804ms I0712 23:22:15.574553 185014 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:15.574790 184995 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 893567ns I0712 23:22:15.574888 184995 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:15.577708 185005 replica.cpp:391] Replica received explicit promise request from __req_res__(896)@172.17.0.3:35959 for position 1 with proposal 1 I0712 23:22:15.577726 185007 replica.cpp:391] Replica received explicit promise request from __req_res__(897)@172.17.0.3:35959 for position 1 with proposal 1 I0712 23:22:15.577852 184996 replica.cpp:391] Replica received explicit promise request from __req_res__(898)@172.17.0.3:35959 for position 1 with proposal 1 I0712 23:22:15.578712 184996 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 797852ns I0712 23:22:15.578796 184996 replica.cpp:712] Persisted action NOP at position 1 I0712 23:22:15.579049 184996 replica.cpp:695] Replica received learned notice for position 1 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.579145 184999 replica.cpp:695] Replica received learned notice for position 1 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.579321 185004 replica.cpp:695] Replica received learned notice for position 1 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.579808 184999 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 606590ns I0712 23:22:15.579880 184996 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 814453ns I0712 23:22:15.580024 185004 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 642526ns I0712 23:22:15.580399 184999 leveldb.cpp:460] Deleting ~1 keys from leveldb took 539941ns I0712 23:22:15.580513 184996 leveldb.cpp:460] Deleting ~1 keys from leveldb took 579047ns I0712 23:22:15.580685 185004 leveldb.cpp:460] Deleting ~1 keys from leveldb took 633905ns I0712 23:22:15.588366 184996 leveldb.cpp:527] Compacting range 0-0 took 7.798673ms I0712 23:22:15.588467 184996 replica.cpp:712] Persisted action NOP at position 1 I0712 23:22:15.590031 184999 leveldb.cpp:527] Compacting range 0-0 took 9.61498ms I0712 23:22:15.590133 184999 replica.cpp:712] Persisted action NOP at position 1 I0712 23:22:15.590061 185004 leveldb.cpp:527] Compacting range 0-0 took 9.343132ms I0712 23:22:15.590255 185004 replica.cpp:712] Persisted action NOP at position 1 I0712 23:22:15.591092 185014 replica.cpp:391] Replica received explicit promise request from __req_res__(900)@172.17.0.3:35959 for position 2 with proposal 1 I0712 23:22:15.591444 185002 replica.cpp:391] Replica received explicit promise request from __req_res__(899)@172.17.0.3:35959 for position 2 with proposal 1 I0712 23:22:15.591951 185015 replica.cpp:391] Replica received explicit promise request from __req_res__(901)@172.17.0.3:35959 for position 2 with proposal 1 I0712 23:22:15.592990 185015 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 982896ns I0712 23:22:15.593007 185002 replica.cpp:695] Replica received learned notice for position 2 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.593075 185015 replica.cpp:712] Persisted action NOP at position 2 I0712 23:22:15.593369 185017 replica.cpp:695] Replica received learned notice for position 2 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.593392 185015 replica.cpp:695] Replica received learned notice for position 2 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.593840 185002 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 741812ns I0712 23:22:15.594089 185015 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 637391ns I0712 23:22:15.594199 185017 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 779993ns I0712 23:22:15.594444 185002 leveldb.cpp:460] Deleting ~1 keys from leveldb took 579917ns I0712 23:22:15.594555 185015 leveldb.cpp:460] Deleting ~1 keys from leveldb took 443280ns I0712 23:22:15.594820 185017 leveldb.cpp:460] Deleting ~1 keys from leveldb took 571925ns I0712 23:22:15.601629 185002 leveldb.cpp:527] Compacting range 1-1 took 7.132664ms I0712 23:22:15.601730 185002 replica.cpp:712] Persisted action NOP at position 2 I0712 23:22:15.603189 185017 leveldb.cpp:527] Compacting range 1-1 took 8.3242ms I0712 23:22:15.603216 185015 leveldb.cpp:527] Compacting range 1-1 took 8.650118ms I0712 23:22:15.603293 185017 replica.cpp:712] Persisted action NOP at position 2 I0712 23:22:15.603332 185015 replica.cpp:712] Persisted action NOP at position 2 I0712 23:22:15.605774 184997 replica.cpp:391] Replica received explicit promise request from __req_res__(902)@172.17.0.3:35959 for position 3 with proposal 1 I0712 23:22:15.605798 185000 replica.cpp:391] Replica received explicit promise request from __req_res__(904)@172.17.0.3:35959 for position 3 with proposal 1 I0712 23:22:15.605863 185014 replica.cpp:391] Replica received explicit promise request from __req_res__(903)@172.17.0.3:35959 for position 3 with proposal 1 I0712 23:22:15.606945 185000 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 1.020977ms I0712 23:22:15.607035 185000 replica.cpp:712] Persisted action NOP at position 3 I0712 23:22:15.607326 185000 replica.cpp:695] Replica received learned notice for position 3 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.607404 185005 replica.cpp:695] Replica received learned notice for position 3 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.607717 185011 replica.cpp:695] Replica received learned notice for position 3 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.608063 185000 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 722272ns I0712 23:22:15.608434 185005 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 989841ns I0712 23:22:15.608603 185011 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 835115ns I0712 23:22:15.608717 185000 leveldb.cpp:460] Deleting ~1 keys from leveldb took 618120ns I0712 23:22:15.609175 185005 leveldb.cpp:460] Deleting ~1 keys from leveldb took 698547ns I0712 23:22:15.609256 185011 leveldb.cpp:460] Deleting ~1 keys from leveldb took 602326ns I0712 23:22:15.619094 185000 leveldb.cpp:527] Compacting range 2-2 took 10.314469ms I0712 23:22:15.619115 185005 leveldb.cpp:527] Compacting range 2-2 took 9.886823ms I0712 23:22:15.619149 185000 replica.cpp:712] Persisted action NOP at position 3 I0712 23:22:15.619138 185011 leveldb.cpp:527] Compacting range 2-2 took 9.83146ms I0712 23:22:15.619225 185005 replica.cpp:712] Persisted action NOP at position 3 I0712 23:22:15.619308 185011 replica.cpp:712] Persisted action NOP at position 3 I0712 23:22:15.620988 185010 replica.cpp:391] Replica received explicit promise request from __req_res__(906)@172.17.0.3:35959 for position 4 with proposal 1 I0712 23:22:15.621116 185015 replica.cpp:391] Replica received explicit promise request from __req_res__(905)@172.17.0.3:35959 for position 4 with proposal 1 I0712 23:22:15.621125 185014 replica.cpp:391] Replica received explicit promise request from __req_res__(907)@172.17.0.3:35959 for position 4 with proposal 1 I0712 23:22:15.622014 185005 replica.cpp:695] Replica received learned notice for position 4 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.622090 185014 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 849247ns I0712 23:22:15.622100 184996 replica.cpp:695] Replica received learned notice for position 4 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.622138 185014 replica.cpp:712] Persisted action NOP at position 4 I0712 23:22:15.622337 185014 replica.cpp:695] Replica received learned notice for position 4 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.622992 184996 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 859575ns I0712 23:22:15.623318 185014 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 948244ns I0712 23:22:15.623409 185005 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 1.346588ms I0712 23:22:15.623533 184996 leveldb.cpp:460] Deleting ~1 keys from leveldb took 468548ns I0712 23:22:15.623741 185014 leveldb.cpp:460] Deleting ~1 keys from leveldb took 385808ns I0712 23:22:15.624073 185005 leveldb.cpp:460] Deleting ~1 keys from leveldb took 598557ns I0712 23:22:15.630905 184996 leveldb.cpp:527] Compacting range 3-3 took 7.378067ms I0712 23:22:15.631006 184996 replica.cpp:712] Persisted action NOP at position 4 I0712 23:22:15.632385 185014 leveldb.cpp:527] Compacting range 3-3 took 8.635598ms I0712 23:22:15.632407 185005 leveldb.cpp:527] Compacting range 3-3 took 8.291099ms I0712 23:22:15.632522 185005 replica.cpp:712] Persisted action NOP at position 4 I0712 23:22:15.632438 185014 replica.cpp:712] Persisted action NOP at position 4 I0712 23:22:15.634711 185008 replica.cpp:391] Replica received explicit promise request from __req_res__(909)@172.17.0.3:35959 for position 5 with proposal 1 I0712 23:22:15.634920 185008 leveldb.cpp:510] Reading position from leveldb took 132652ns I0712 23:22:15.635018 185016 replica.cpp:391] Replica received explicit promise request from __req_res__(908)@172.17.0.3:35959 for position 5 with proposal 1 I0712 23:22:15.635048 185000 replica.cpp:391] Replica received explicit promise request from __req_res__(910)@172.17.0.3:35959 for position 5 with proposal 1 I0712 23:22:15.635236 185016 leveldb.cpp:510] Reading position from leveldb took 137282ns I0712 23:22:15.636102 185000 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 967485ns I0712 23:22:15.636186 185000 replica.cpp:712] Persisted action NOP at position 5 I0712 23:22:15.810106 185015 replica.cpp:391] Replica received explicit promise request from __req_res__(911)@172.17.0.3:35959 for position 5 with proposal 2 I0712 23:22:15.810380 185015 leveldb.cpp:510] Reading position from leveldb took 177687ns I0712 23:22:15.810418 185013 replica.cpp:391] Replica received explicit promise request from __req_res__(912)@172.17.0.3:35959 for position 5 with proposal 2 I0712 23:22:15.810448 185012 replica.cpp:391] Replica received explicit promise request from __req_res__(913)@172.17.0.3:35959 for position 5 with proposal 2 I0712 23:22:15.810607 185012 leveldb.cpp:510] Reading position from leveldb took 71050ns I0712 23:22:15.810674 185013 leveldb.cpp:510] Reading position from leveldb took 165079ns I0712 23:22:15.811623 185015 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.164961ms I0712 23:22:15.811643 185012 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 1.010875ms I0712 23:22:15.811725 185015 replica.cpp:712] Persisted action APPEND at position 5 I0712 23:22:15.811790 185012 replica.cpp:712] Persisted action NOP at position 5 I0712 23:22:15.811846 185013 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.112587ms I0712 23:22:15.811944 185013 replica.cpp:712] Persisted action APPEND at position 5 I0712 23:22:15.813225 185009 replica.cpp:695] Replica received learned notice for position 5 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.813266 185007 replica.cpp:695] Replica received learned notice for position 5 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.813428 185000 replica.cpp:695] Replica received learned notice for position 5 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.814162 185007 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 868613ns I0712 23:22:15.814344 185007 replica.cpp:712] Persisted action APPEND at position 5 I0712 23:22:15.814196 185009 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 920979ns I0712 23:22:15.814433 185000 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 939351ns I0712 23:22:15.814481 185000 replica.cpp:712] Persisted action APPEND at position 5 I0712 23:22:15.814486 185009 replica.cpp:712] Persisted action APPEND at position 5 I0712 23:22:15.817111 184998 replica.cpp:391] Replica received explicit promise request from __req_res__(914)@172.17.0.3:35959 for position 6 with proposal 2 I0712 23:22:15.817215 185015 replica.cpp:391] Replica received explicit promise request from __req_res__(916)@172.17.0.3:35959 for position 6 with proposal 2 I0712 23:22:15.817313 184998 leveldb.cpp:510] Reading position from leveldb took 131844ns I0712 23:22:15.817386 185017 replica.cpp:391] Replica received explicit promise request from __req_res__(915)@172.17.0.3:35959 for position 6 with proposal 2 I0712 23:22:15.817589 185017 leveldb.cpp:510] Reading position from leveldb took 131328ns I0712 23:22:15.818382 185015 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 1.108742ms I0712 23:22:15.818384 184998 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.024938ms I0712 23:22:15.818480 185015 replica.cpp:712] Persisted action NOP at position 6 I0712 23:22:15.818547 184998 replica.cpp:712] Persisted action APPEND at position 6 I0712 23:22:15.818873 185017 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.23264ms I0712 23:22:15.818970 185017 replica.cpp:712] Persisted action APPEND at position 6 I0712 23:22:15.820243 184999 replica.cpp:695] Replica received learned notice for position 6 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.820299 185005 replica.cpp:695] Replica received learned notice for position 6 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.820605 184995 replica.cpp:695] Replica received learned notice for position 6 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.821377 184999 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.084578ms I0712 23:22:15.821381 185005 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.036839ms I0712 23:22:15.821475 184999 replica.cpp:712] Persisted action APPEND at position 6 I0712 23:22:15.821516 185005 replica.cpp:712] Persisted action APPEND at position 6 I0712 23:22:15.821588 184995 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 929994ns I0712 23:22:15.821669 184995 replica.cpp:712] Persisted action APPEND at position 6 I0712 23:22:15.823964 185017 replica.cpp:391] Replica received explicit promise request from __req_res__(917)@172.17.0.3:35959 for position 7 with proposal 2 I0712 23:22:15.824057 185000 replica.cpp:391] Replica received explicit promise request from __req_res__(918)@172.17.0.3:35959 for position 7 with proposal 2 I0712 23:22:15.824149 185017 leveldb.cpp:510] Reading position from leveldb took 137353ns I0712 23:22:15.824254 185000 leveldb.cpp:510] Reading position from leveldb took 127402ns I0712 23:22:15.824299 185001 replica.cpp:391] Replica received explicit promise request from __req_res__(919)@172.17.0.3:35959 for position 7 with proposal 2 I0712 23:22:15.825335 185001 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 997880ns I0712 23:22:15.825335 185017 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.125662ms I0712 23:22:15.825436 185001 replica.cpp:712] Persisted action NOP at position 7 I0712 23:22:15.825467 185017 replica.cpp:712] Persisted action APPEND at position 7 I0712 23:22:15.825361 185000 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.056282ms I0712 23:22:15.825641 185000 replica.cpp:712] Persisted action APPEND at position 7 I0712 23:22:15.826659 185001 replica.cpp:695] Replica received learned notice for position 7 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.826815 185013 replica.cpp:695] Replica received learned notice for position 7 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.826901 185004 replica.cpp:695] Replica received learned notice for position 7 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.827623 185013 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 761245ns I0712 23:22:15.827687 185001 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 980184ns I0712 23:22:15.827701 185013 replica.cpp:712] Persisted action APPEND at position 7 I0712 23:22:15.827776 185001 replica.cpp:712] Persisted action APPEND at position 7 I0712 23:22:15.828063 185004 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.098892ms I0712 23:22:15.828131 185004 replica.cpp:712] Persisted action APPEND at position 7 I0712 23:22:15.830638 184995 replica.cpp:391] Replica received explicit promise request from __req_res__(920)@172.17.0.3:35959 for position 8 with proposal 2 I0712 23:22:15.830694 184999 replica.cpp:391] Replica received explicit promise request from __req_res__(921)@172.17.0.3:35959 for position 8 with proposal 2 I0712 23:22:15.830837 184995 leveldb.cpp:510] Reading position from leveldb took 128377ns I0712 23:22:15.830888 184999 leveldb.cpp:510] Reading position from leveldb took 127750ns I0712 23:22:15.831037 185006 replica.cpp:391] Replica received explicit promise request from __req_res__(922)@172.17.0.3:35959 for position 8 with proposal 2 I0712 23:22:15.831595 184999 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 648584ns I0712 23:22:15.831655 184999 replica.cpp:712] Persisted action APPEND at position 8 I0712 23:22:15.831650 184995 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 766172ns I0712 23:22:15.831773 184995 replica.cpp:712] Persisted action APPEND at position 8 I0712 23:22:15.831974 185006 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 874342ns I0712 23:22:15.832057 185006 replica.cpp:712] Persisted action NOP at position 8 I0712 23:22:15.832934 185009 replica.cpp:695] Replica received learned notice for position 8 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.832968 185003 replica.cpp:695] Replica received learned notice for position 8 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.833052 185014 replica.cpp:695] Replica received learned notice for position 8 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.833712 185009 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 713568ns I0712 23:22:15.833743 185003 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 719173ns I0712 23:22:15.833771 185009 replica.cpp:712] Persisted action APPEND at position 8 I0712 23:22:15.833798 185014 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 724027ns I0712 23:22:15.833885 185003 replica.cpp:712] Persisted action APPEND at position 8 I0712 23:22:15.833902 185014 replica.cpp:712] Persisted action APPEND at position 8 I0712 23:22:15.836277 185006 replica.cpp:391] Replica received explicit promise request from __req_res__(923)@172.17.0.3:35959 for position 9 with proposal 2 I0712 23:22:15.836346 185011 replica.cpp:391] Replica received explicit promise request from __req_res__(924)@172.17.0.3:35959 for position 9 with proposal 2 I0712 23:22:15.836411 184995 replica.cpp:391] Replica received explicit promise request from __req_res__(925)@172.17.0.3:35959 for position 9 with proposal 2 I0712 23:22:15.836509 185011 leveldb.cpp:510] Reading position from leveldb took 121804ns I0712 23:22:15.836510 185006 leveldb.cpp:510] Reading position from leveldb took 154135ns I0712 23:22:15.837122 185011 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 536117ns I0712 23:22:15.837122 185006 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 526079ns I0712 23:22:15.837181 185011 replica.cpp:712] Persisted action APPEND at position 9 I0712 23:22:15.837132 184995 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 652917ns I0712 23:22:15.837216 185006 replica.cpp:712] Persisted action APPEND at position 9 I0712 23:22:15.837267 184995 replica.cpp:712] Persisted action NOP at position 9 I0712 23:22:15.838639 185014 replica.cpp:695] Replica received learned notice for position 9 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.838832 184997 replica.cpp:695] Replica received learned notice for position 9 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.838972 185005 replica.cpp:695] Replica received learned notice for position 9 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.839540 185014 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 846988ns I0712 23:22:15.839627 185014 replica.cpp:712] Persisted action APPEND at position 9 I0712 23:22:15.839892 184997 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.011812ms I0712 23:22:15.839921 185005 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 903591ns I0712 23:22:15.839983 184997 replica.cpp:712] Persisted action APPEND at position 9 I0712 23:22:15.840021 185005 replica.cpp:712] Persisted action APPEND at position 9 I0712 23:22:15.842581 185015 replica.cpp:391] Replica received explicit promise request from __req_res__(926)@172.17.0.3:35959 for position 10 with proposal 2 I0712 23:22:15.842788 185015 leveldb.cpp:510] Reading position from leveldb took 135083ns I0712 23:22:15.842788 185018 replica.cpp:391] Replica received explicit promise request from __req_res__(927)@172.17.0.3:35959 for position 10 with proposal 2 I0712 23:22:15.842857 184996 replica.cpp:391] Replica received explicit promise request from __req_res__(928)@172.17.0.3:35959 for position 10 with proposal 2 I0712 23:22:15.843007 185018 leveldb.cpp:510] Reading position from leveldb took 146510ns I0712 23:22:15.843632 185015 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 801477ns I0712 23:22:15.843696 184996 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 781821ns I0712 23:22:15.843729 185015 replica.cpp:712] Persisted action APPEND at position 10 I0712 23:22:15.843782 184996 replica.cpp:712] Persisted action NOP at position 10 I0712 23:22:15.844126 185018 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 1.048573ms I0712 23:22:15.844223 185018 replica.cpp:712] Persisted action APPEND at position 10 I0712 23:22:15.845600 185016 replica.cpp:695] Replica received learned notice for position 10 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.845659 184999 replica.cpp:695] Replica received learned notice for position 10 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.845880 185002 replica.cpp:695] Replica received learned notice for position 10 from log-network(42)@172.17.0.3:35959 I0712 23:22:15.846361 184999 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 664405ns I0712 23:22:15.846467 184999 replica.cpp:712] Persisted action APPEND at position 10 I0712 23:22:15.846485 185016 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 839332ns I0712 23:22:15.846602 185016 replica.cpp:712] Persisted action APPEND at position 10 I0712 23:22:15.846621 185002 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 685957ns I0712 23:22:15.846710 185002 replica.cpp:712] Persisted action APPEND at position 10 I0712 23:22:15.847151 184999 catchup.cpp:357] Recover process terminated I0712 23:22:15.850286 185002 leveldb.cpp:510] Reading position from leveldb took 133764ns I0712 23:22:15.850462 185002 leveldb.cpp:510] Reading position from leveldb took 52753ns I0712 23:22:15.850525 185002 leveldb.cpp:510] Reading position from leveldb took 27395ns I0712 23:22:15.850582 185002 leveldb.cpp:510] Reading position from leveldb took 27363ns I0712 23:22:15.850663 185002 leveldb.cpp:510] Reading position from leveldb took 41329ns I0712 23:22:15.850759 185002 leveldb.cpp:510] Reading position from leveldb took 45692ns [ OK ] RecoverTest.CatchupVotingWithGap (603 ms) [ RUN ] RecoverTest.CatchupVotingOnePosition I0712 23:22:15.862680 184994 leveldb.cpp:217] Opened db in 5.924445ms I0712 23:22:15.864408 184994 leveldb.cpp:224] Compacted db in 1.696287ms I0712 23:22:15.864521 184994 leveldb.cpp:239] Created db iterator in 42955ns I0712 23:22:15.864538 184994 leveldb.cpp:245] Seeked to beginning of db in 6869ns I0712 23:22:15.864552 184994 leveldb.cpp:320] Iterated through 0 keys in the db in 4670ns I0712 23:22:15.864604 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0712 23:22:15.866091 184995 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 936355ns I0712 23:22:15.866171 184995 replica.cpp:322] Persisted replica status to VOTING I0712 23:22:15.871755 184994 leveldb.cpp:217] Opened db in 4.591253ms I0712 23:22:15.873371 184994 leveldb.cpp:224] Compacted db in 1.574634ms I0712 23:22:15.873438 184994 leveldb.cpp:239] Created db iterator in 35362ns I0712 23:22:15.873456 184994 leveldb.cpp:245] Seeked to beginning of db in 6658ns I0712 23:22:15.873468 184994 leveldb.cpp:320] Iterated through 0 keys in the db in 4497ns I0712 23:22:15.873515 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0712 23:22:15.875742 185000 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 1.197374ms I0712 23:22:15.875831 185000 replica.cpp:322] Persisted replica status to VOTING I0712 23:22:15.882143 184994 leveldb.cpp:217] Opened db in 5.311744ms I0712 23:22:15.884160 184994 leveldb.cpp:224] Compacted db in 1.979031ms I0712 23:22:15.884286 184994 leveldb.cpp:239] Created db iterator in 42227ns I0712 23:22:15.884310 184994 leveldb.cpp:245] Seeked to beginning of db in 8527ns I0712 23:22:15.884326 184994 leveldb.cpp:320] Iterated through 0 keys in the db in 6089ns I0712 23:22:15.884384 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0712 23:22:15.886184 185001 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 1.214197ms I0712 23:22:15.886274 185001 replica.cpp:322] Persisted replica status to VOTING I0712 23:22:15.893226 184994 leveldb.cpp:217] Opened db in 6.007666ms I0712 23:22:15.897392 184994 leveldb.cpp:224] Compacted db in 4.12899ms I0712 23:22:15.897522 184994 leveldb.cpp:239] Created db iterator in 49366ns I0712 23:22:15.897580 184994 leveldb.cpp:245] Seeked to beginning of db in 44350ns I0712 23:22:15.897646 184994 leveldb.cpp:320] Iterated through 1 keys in the db in 54274ns I0712 23:22:15.897702 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0712 23:22:15.903478 184994 leveldb.cpp:217] Opened db in 5.426234ms I0712 23:22:15.908459 184994 leveldb.cpp:224] Compacted db in 4.94367ms I0712 23:22:15.908593 184994 leveldb.cpp:239] Created db iterator in 50092ns I0712 23:22:15.908653 184994 leveldb.cpp:245] Seeked to beginning of db in 44528ns I0712 23:22:15.908717 184994 leveldb.cpp:320] Iterated through 1 keys in the db in 53565ns I0712 23:22:15.908774 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0712 23:22:15.915226 184994 leveldb.cpp:217] Opened db in 6.129559ms I0712 23:22:15.919708 184994 leveldb.cpp:224] Compacted db in 4.443886ms I0712 23:22:15.919837 184994 leveldb.cpp:239] Created db iterator in 49107ns I0712 23:22:15.919896 184994 leveldb.cpp:245] Seeked to beginning of db in 44439ns I0712 23:22:15.919961 184994 leveldb.cpp:320] Iterated through 1 keys in the db in 53073ns I0712 23:22:15.920018 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0712 23:22:15.920684 184996 catchup.cpp:342] Starting missing positions recovery I0712 23:22:15.921222 184997 catchup.cpp:368] Replica is in VOTING status I0712 23:22:15.922950 185013 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(929)@172.17.0.3:35959 I0712 23:22:15.923030 185005 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(931)@172.17.0.3:35959 I0712 23:22:15.923030 185016 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(930)@172.17.0.3:35959 I0712 23:22:15.923629 185002 recover.cpp:197] Received a recover response from a replica in VOTING status I0712 23:22:15.924378 185002 recover.cpp:197] Received a recover response from a replica in VOTING status I0712 23:22:15.925669 185006 catchup.cpp:357] Recover process terminated [ OK ] RecoverTest.CatchupVotingOnePosition (73 ms) [----------] 9 tests from RecoverTest (3903 ms total) [----------] 4 tests from LogTest [ RUN ] LogTest.WriteRead I0712 23:22:15.935488 184994 leveldb.cpp:217] Opened db in 4.930678ms I0712 23:22:15.937299 184994 leveldb.cpp:224] Compacted db in 1.759803ms I0712 23:22:15.937371 184994 leveldb.cpp:239] Created db iterator in 36100ns I0712 23:22:15.937392 184994 leveldb.cpp:245] Seeked to beginning of db in 8240ns I0712 23:22:15.937410 184994 leveldb.cpp:320] Iterated through 0 keys in the db in 6074ns I0712 23:22:15.937466 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0712 23:22:15.939260 185015 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 1.253723ms I0712 23:22:15.939352 185015 replica.cpp:322] Persisted replica status to VOTING I0712 23:22:15.945463 184994 leveldb.cpp:217] Opened db in 5.208225ms I0712 23:22:15.947933 184994 leveldb.cpp:224] Compacted db in 2.430323ms I0712 23:22:15.948055 184994 leveldb.cpp:239] Created db iterator in 40557ns I0712 23:22:15.948081 184994 leveldb.cpp:245] Seeked to beginning of db in 12040ns I0712 23:22:15.948112 184994 leveldb.cpp:320] Iterated through 0 keys in the db in 10084ns I0712 23:22:15.948174 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0712 23:22:15.949824 185004 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 1.088119ms I0712 23:22:15.949862 185004 replica.cpp:322] Persisted replica status to VOTING I0712 23:22:15.956151 184994 leveldb.cpp:217] Opened db in 5.433694ms I0712 23:22:15.960117 184994 leveldb.cpp:224] Compacted db in 3.937091ms I0712 23:22:15.960233 184994 leveldb.cpp:239] Created db iterator in 48097ns I0712 23:22:15.960281 184994 leveldb.cpp:245] Seeked to beginning of db in 35806ns I0712 23:22:15.960340 184994 leveldb.cpp:320] Iterated through 1 keys in the db in 46930ns I0712 23:22:15.960387 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0712 23:22:15.965571 184994 leveldb.cpp:217] Opened db in 4.887906ms I0712 23:22:15.969725 184994 leveldb.cpp:224] Compacted db in 4.125324ms I0712 23:22:15.969852 184994 leveldb.cpp:239] Created db iterator in 61241ns I0712 23:22:15.969902 184994 leveldb.cpp:245] Seeked to beginning of db in 35304ns I0712 23:22:15.969956 184994 leveldb.cpp:320] Iterated through 1 keys in the db in 46455ns I0712 23:22:15.970002 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0712 23:22:15.970870 185012 recover.cpp:437] Starting replica recovery I0712 23:22:15.971453 184999 recover.cpp:468] Replica is in VOTING status I0712 23:22:15.971808 184999 recover.cpp:447] Recover process terminated I0712 23:22:15.972587 184996 log.cpp:554] Attempting to start the writer I0712 23:22:15.974185 185008 replica.cpp:497] Replica received implicit promise request from __req_res__(933)@172.17.0.3:35959 with proposal 1 I0712 23:22:15.974182 185001 replica.cpp:497] Replica received implicit promise request from __req_res__(932)@172.17.0.3:35959 with proposal 1 I0712 23:22:15.975250 185008 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 999698ns I0712 23:22:15.975291 185008 replica.cpp:344] Persisted promised to 1 I0712 23:22:15.975345 185001 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 1.034038ms I0712 23:22:15.975436 185001 replica.cpp:344] Persisted promised to 1 I0712 23:22:15.976641 185012 coordinator.cpp:238] Coordinator attempting to fill missing positions I0712 23:22:15.978837 185018 replica.cpp:391] Replica received explicit promise request from __req_res__(935)@172.17.0.3:35959 for position 0 with proposal 2 I0712 23:22:15.978840 184998 replica.cpp:391] Replica received explicit promise request from __req_res__(934)@172.17.0.3:35959 for position 0 with proposal 2 I0712 23:22:15.979463 185018 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 574575ns I0712 23:22:15.979463 184998 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 574546ns I0712 23:22:15.979517 185018 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:15.979522 184998 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:15.981189 184997 replica.cpp:541] Replica received write request for position 0 from __req_res__(936)@172.17.0.3:35959 I0712 23:22:15.981237 185014 replica.cpp:541] Replica received write request for position 0 from __req_res__(937)@172.17.0.3:35959 I0712 23:22:15.981320 185014 leveldb.cpp:510] Reading position from leveldb took 40157ns I0712 23:22:15.981334 184997 leveldb.cpp:510] Reading position from leveldb took 71695ns I0712 23:22:15.981798 185014 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 446748ns I0712 23:22:15.981835 185014 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:15.981900 184997 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 509288ns I0712 23:22:15.981957 184997 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:15.983019 185018 replica.cpp:695] Replica received learned notice for position 0 from log-network(44)@172.17.0.3:35959 I0712 23:22:15.983019 184998 replica.cpp:695] Replica received learned notice for position 0 from log-network(44)@172.17.0.3:35959 I0712 23:22:15.983767 184998 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 695993ns I0712 23:22:15.983767 185018 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 705803ns I0712 23:22:15.983798 184998 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:15.983809 185018 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:15.984701 184996 log.cpp:570] Writer started with ending position 0 I0712 23:22:15.985862 185004 log.cpp:578] Attempting to append 11 bytes to the log I0712 23:22:15.986115 185011 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 I0712 23:22:15.987426 185011 replica.cpp:541] Replica received write request for position 1 from __req_res__(938)@172.17.0.3:35959 I0712 23:22:15.987540 185003 replica.cpp:541] Replica received write request for position 1 from __req_res__(939)@172.17.0.3:35959 I0712 23:22:15.988365 185003 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 755660ns I0712 23:22:15.988412 185011 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 931991ns I0712 23:22:15.988443 185003 replica.cpp:712] Persisted action APPEND at position 1 I0712 23:22:15.988502 185011 replica.cpp:712] Persisted action APPEND at position 1 I0712 23:22:15.989774 185007 replica.cpp:695] Replica received learned notice for position 1 from log-network(44)@172.17.0.3:35959 I0712 23:22:15.989790 185006 replica.cpp:695] Replica received learned notice for position 1 from log-network(44)@172.17.0.3:35959 I0712 23:22:15.990815 185007 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 964124ns I0712 23:22:15.990868 185006 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 947768ns I0712 23:22:15.990906 185007 replica.cpp:712] Persisted action APPEND at position 1 I0712 23:22:15.990952 185006 replica.cpp:712] Persisted action APPEND at position 1 I0712 23:22:15.993527 185001 leveldb.cpp:510] Reading position from leveldb took 130226ns [ OK ] LogTest.WriteRead (69 ms) [ RUN ] LogTest.Position I0712 23:22:16.003610 184994 leveldb.cpp:217] Opened db in 4.925387ms I0712 23:22:16.005136 184994 leveldb.cpp:224] Compacted db in 1.478925ms I0712 23:22:16.005195 184994 leveldb.cpp:239] Created db iterator in 32636ns I0712 23:22:16.005210 184994 leveldb.cpp:245] Seeked to beginning of db in 6890ns I0712 23:22:16.005223 184994 leveldb.cpp:320] Iterated through 0 keys in the db in 4650ns I0712 23:22:16.005270 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0712 23:22:16.007444 185002 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 1.189355ms I0712 23:22:16.007539 185002 replica.cpp:322] Persisted replica status to VOTING I0712 23:22:16.012897 184994 leveldb.cpp:217] Opened db in 4.500967ms I0712 23:22:16.014600 184994 leveldb.cpp:224] Compacted db in 1.672186ms I0712 23:22:16.014706 184994 leveldb.cpp:239] Created db iterator in 36104ns I0712 23:22:16.014724 184994 leveldb.cpp:245] Seeked to beginning of db in 6694ns I0712 23:22:16.014735 184994 leveldb.cpp:320] Iterated through 0 keys in the db in 4511ns I0712 23:22:16.014780 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0712 23:22:16.016604 185000 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 1.204717ms I0712 23:22:16.016696 185000 replica.cpp:322] Persisted replica status to VOTING I0712 23:22:16.022166 184994 leveldb.cpp:217] Opened db in 4.844352ms I0712 23:22:16.026013 184994 leveldb.cpp:224] Compacted db in 3.819613ms I0712 23:22:16.026124 184994 leveldb.cpp:239] Created db iterator in 41767ns I0712 23:22:16.026171 184994 leveldb.cpp:245] Seeked to beginning of db in 39530ns I0712 23:22:16.026232 184994 leveldb.cpp:320] Iterated through 1 keys in the db in 47482ns I0712 23:22:16.026283 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0712 23:22:16.031028 184994 leveldb.cpp:217] Opened db in 4.450274ms I0712 23:22:16.033419 184994 leveldb.cpp:224] Compacted db in 2.36298ms I0712 23:22:16.033532 184994 leveldb.cpp:239] Created db iterator in 46466ns I0712 23:22:16.033581 184994 leveldb.cpp:245] Seeked to beginning of db in 36148ns I0712 23:22:16.033640 184994 leveldb.cpp:320] Iterated through 1 keys in the db in 46885ns I0712 23:22:16.033689 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0712 23:22:16.034538 185018 recover.cpp:437] Starting replica recovery I0712 23:22:16.034994 185002 recover.cpp:468] Replica is in VOTING status I0712 23:22:16.035373 185002 recover.cpp:447] Recover process terminated I0712 23:22:16.036167 185005 log.cpp:554] Attempting to start the writer I0712 23:22:16.038246 185004 replica.cpp:497] Replica received implicit promise request from __req_res__(940)@172.17.0.3:35959 with proposal 1 I0712 23:22:16.038275 184996 replica.cpp:497] Replica received implicit promise request from __req_res__(941)@172.17.0.3:35959 with proposal 1 I0712 23:22:16.039618 185004 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 1.314975ms I0712 23:22:16.039716 185004 replica.cpp:344] Persisted promised to 1 I0712 23:22:16.039630 184996 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 1.277344ms I0712 23:22:16.039855 184996 replica.cpp:344] Persisted promised to 1 I0712 23:22:16.041090 185011 coordinator.cpp:238] Coordinator attempting to fill missing positions I0712 23:22:16.043417 185012 replica.cpp:391] Replica received explicit promise request from __req_res__(942)@172.17.0.3:35959 for position 0 with proposal 2 I0712 23:22:16.043536 184995 replica.cpp:391] Replica received explicit promise request from __req_res__(943)@172.17.0.3:35959 for position 0 with proposal 2 I0712 23:22:16.044456 184995 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 879849ns I0712 23:22:16.044482 185012 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 987159ns I0712 23:22:16.044553 184995 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:16.044592 185012 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:16.046432 185002 replica.cpp:541] Replica received write request for position 0 from __req_res__(944)@172.17.0.3:35959 I0712 23:22:16.046519 185003 replica.cpp:541] Replica received write request for position 0 from __req_res__(945)@172.17.0.3:35959 I0712 23:22:16.046581 185002 leveldb.cpp:510] Reading position from leveldb took 73229ns I0712 23:22:16.046669 185003 leveldb.cpp:510] Reading position from leveldb took 75589ns I0712 23:22:16.047487 185002 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 862713ns I0712 23:22:16.047533 185003 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 811560ns I0712 23:22:16.047575 185002 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:16.047613 185003 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:16.048588 185009 replica.cpp:695] Replica received learned notice for position 0 from log-network(45)@172.17.0.3:35959 I0712 23:22:16.048594 185015 replica.cpp:695] Replica received learned notice for position 0 from log-network(45)@172.17.0.3:35959 I0712 23:22:16.049578 185015 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 852399ns I0712 23:22:16.049598 185009 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 953037ns I0712 23:22:16.049666 185015 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:16.049710 185009 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:16.050735 185001 log.cpp:570] Writer started with ending position 0 I0712 23:22:16.051766 185003 log.cpp:578] Attempting to append 11 bytes to the log I0712 23:22:16.052001 185014 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 I0712 23:22:16.053210 184996 replica.cpp:541] Replica received write request for position 1 from __req_res__(946)@172.17.0.3:35959 I0712 23:22:16.053313 185012 replica.cpp:541] Replica received write request for position 1 from __req_res__(947)@172.17.0.3:35959 I0712 23:22:16.053970 184996 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 681933ns I0712 23:22:16.054018 184996 replica.cpp:712] Persisted action APPEND at position 1 I0712 23:22:16.054080 185012 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 700820ns I0712 23:22:16.054167 185012 replica.cpp:712] Persisted action APPEND at position 1 I0712 23:22:16.055195 185017 replica.cpp:695] Replica received learned notice for position 1 from log-network(45)@172.17.0.3:35959 I0712 23:22:16.055243 185004 replica.cpp:695] Replica received learned notice for position 1 from log-network(45)@172.17.0.3:35959 I0712 23:22:16.056264 185004 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 959685ns I0712 23:22:16.056309 185004 replica.cpp:712] Persisted action APPEND at position 1 I0712 23:22:16.056365 185017 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 1.11528ms I0712 23:22:16.056460 185017 replica.cpp:712] Persisted action APPEND at position 1 [ OK ] LogTest.Position (62 ms) [ RUN ] LogTest.Metrics I0712 23:22:16.067126 184994 leveldb.cpp:217] Opened db in 5.636721ms I0712 23:22:16.069147 184994 leveldb.cpp:224] Compacted db in 1.980291ms I0712 23:22:16.069270 184994 leveldb.cpp:239] Created db iterator in 43604ns I0712 23:22:16.069293 184994 leveldb.cpp:245] Seeked to beginning of db in 8501ns I0712 23:22:16.069310 184994 leveldb.cpp:320] Iterated through 0 keys in the db in 6206ns I0712 23:22:16.069371 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0712 23:22:16.070812 185006 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 846376ns I0712 23:22:16.070894 185006 replica.cpp:322] Persisted replica status to VOTING I0712 23:22:16.076098 184994 leveldb.cpp:217] Opened db in 4.222427ms I0712 23:22:16.079035 184994 leveldb.cpp:224] Compacted db in 2.907806ms I0712 23:22:16.079147 184994 leveldb.cpp:239] Created db iterator in 41907ns I0712 23:22:16.079192 184994 leveldb.cpp:245] Seeked to beginning of db in 35569ns I0712 23:22:16.079244 184994 leveldb.cpp:320] Iterated through 1 keys in the db in 42996ns I0712 23:22:16.079289 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0712 23:22:16.080090 185005 recover.cpp:437] Starting replica recovery I0712 23:22:16.080611 185005 recover.cpp:468] Replica is in VOTING status I0712 23:22:16.080884 185005 recover.cpp:447] Recover process terminated I0712 23:22:16.081262 185018 log.cpp:554] Attempting to start the writer I0712 23:22:16.083352 184997 replica.cpp:497] Replica received implicit promise request from __req_res__(948)@172.17.0.3:35959 with proposal 1 I0712 23:22:16.084462 184997 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 1.046536ms I0712 23:22:16.084522 184997 replica.cpp:344] Persisted promised to 1 I0712 23:22:16.085763 185016 coordinator.cpp:238] Coordinator attempting to fill missing positions I0712 23:22:16.088002 185005 replica.cpp:391] Replica received explicit promise request from __req_res__(949)@172.17.0.3:35959 for position 0 with proposal 2 I0712 23:22:16.088874 185005 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 800094ns I0712 23:22:16.088959 185005 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:16.090814 185016 replica.cpp:541] Replica received write request for position 0 from __req_res__(950)@172.17.0.3:35959 I0712 23:22:16.090962 185016 leveldb.cpp:510] Reading position from leveldb took 72097ns I0712 23:22:16.091761 185016 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 758064ns I0712 23:22:16.091846 185016 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:16.092792 184996 replica.cpp:695] Replica received learned notice for position 0 from log-network(46)@172.17.0.3:35959 I0712 23:22:16.093801 184996 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 982983ns I0712 23:22:16.093914 184996 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:16.094835 185011 log.cpp:570] Writer started with ending position 0 I0712 23:22:16.100436 184998 process.cpp:3671] Handling HTTP event for process 'metrics' with path: '/metrics/snapshot' [ OK ] LogTest.Metrics (50 ms) [ RUN ] LogTest.ReaderCatchup I0712 23:22:16.116216 184994 leveldb.cpp:217] Opened db in 5.247673ms I0712 23:22:16.117590 184994 leveldb.cpp:224] Compacted db in 1.329407ms I0712 23:22:16.117655 184994 leveldb.cpp:239] Created db iterator in 34621ns I0712 23:22:16.117671 184994 leveldb.cpp:245] Seeked to beginning of db in 6744ns I0712 23:22:16.117683 184994 leveldb.cpp:320] Iterated through 0 keys in the db in 4547ns I0712 23:22:16.117734 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0712 23:22:16.119292 185005 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 1.030845ms I0712 23:22:16.119385 185005 replica.cpp:322] Persisted replica status to VOTING I0712 23:22:16.124006 184994 leveldb.cpp:217] Opened db in 3.720038ms I0712 23:22:16.125348 184994 leveldb.cpp:224] Compacted db in 1.301278ms I0712 23:22:16.125408 184994 leveldb.cpp:239] Created db iterator in 31190ns I0712 23:22:16.125425 184994 leveldb.cpp:245] Seeked to beginning of db in 6475ns I0712 23:22:16.125443 184994 leveldb.cpp:320] Iterated through 0 keys in the db in 4480ns I0712 23:22:16.125489 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0712 23:22:16.127163 185012 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 851194ns I0712 23:22:16.127241 185012 replica.cpp:322] Persisted replica status to VOTING I0712 23:22:16.130995 184994 leveldb.cpp:217] Opened db in 2.904985ms I0712 23:22:16.132143 184994 leveldb.cpp:224] Compacted db in 1.11247ms I0712 23:22:16.132210 184994 leveldb.cpp:239] Created db iterator in 29500ns I0712 23:22:16.132226 184994 leveldb.cpp:245] Seeked to beginning of db in 6129ns I0712 23:22:16.132239 184994 leveldb.cpp:320] Iterated through 0 keys in the db in 4748ns I0712 23:22:16.132283 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0712 23:22:16.133579 185015 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 515374ns I0712 23:22:16.133621 185015 replica.cpp:322] Persisted replica status to VOTING I0712 23:22:16.137934 184994 leveldb.cpp:217] Opened db in 3.474491ms I0712 23:22:16.141199 184994 leveldb.cpp:224] Compacted db in 3.236649ms I0712 23:22:16.141305 184994 leveldb.cpp:239] Created db iterator in 40155ns I0712 23:22:16.141352 184994 leveldb.cpp:245] Seeked to beginning of db in 35585ns I0712 23:22:16.141407 184994 leveldb.cpp:320] Iterated through 1 keys in the db in 46141ns I0712 23:22:16.141451 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0712 23:22:16.145159 184994 leveldb.cpp:217] Opened db in 3.44096ms I0712 23:22:16.149015 184994 leveldb.cpp:224] Compacted db in 3.826676ms I0712 23:22:16.149121 184994 leveldb.cpp:239] Created db iterator in 39245ns I0712 23:22:16.149168 184994 leveldb.cpp:245] Seeked to beginning of db in 34837ns I0712 23:22:16.149219 184994 leveldb.cpp:320] Iterated through 1 keys in the db in 43073ns I0712 23:22:16.149262 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0712 23:22:16.152035 185007 replica.cpp:497] Replica received implicit promise request from __req_res__(951)@172.17.0.3:35959 with proposal 1 I0712 23:22:16.152101 185010 replica.cpp:497] Replica received implicit promise request from __req_res__(952)@172.17.0.3:35959 with proposal 1 I0712 23:22:16.153270 185010 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 1.14333ms I0712 23:22:16.153270 185007 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 1.168055ms I0712 23:22:16.153381 185010 replica.cpp:344] Persisted promised to 1 I0712 23:22:16.153419 185007 replica.cpp:344] Persisted promised to 1 I0712 23:22:16.154623 185007 coordinator.cpp:238] Coordinator attempting to fill missing positions I0712 23:22:16.156991 185018 replica.cpp:391] Replica received explicit promise request from __req_res__(953)@172.17.0.3:35959 for position 0 with proposal 2 I0712 23:22:16.157069 185016 replica.cpp:391] Replica received explicit promise request from __req_res__(954)@172.17.0.3:35959 for position 0 with proposal 2 I0712 23:22:16.157605 185018 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 561463ns I0712 23:22:16.157634 185018 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:16.157953 185016 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 812538ns I0712 23:22:16.158048 185016 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:16.159714 185000 replica.cpp:541] Replica received write request for position 0 from __req_res__(955)@172.17.0.3:35959 I0712 23:22:16.159724 184998 replica.cpp:541] Replica received write request for position 0 from __req_res__(956)@172.17.0.3:35959 I0712 23:22:16.159806 185000 leveldb.cpp:510] Reading position from leveldb took 45779ns I0712 23:22:16.159806 184998 leveldb.cpp:510] Reading position from leveldb took 37759ns I0712 23:22:16.160409 185000 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 560868ns I0712 23:22:16.160436 185000 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:16.160480 184998 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 537036ns I0712 23:22:16.160563 184998 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:16.161708 185010 replica.cpp:695] Replica received learned notice for position 0 from log-network(47)@172.17.0.3:35959 I0712 23:22:16.161717 185016 replica.cpp:695] Replica received learned notice for position 0 from log-network(47)@172.17.0.3:35959 I0712 23:22:16.162890 185016 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 1.017755ms I0712 23:22:16.162894 185010 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 1.130351ms I0712 23:22:16.162989 185016 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:16.163079 185010 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:16.164779 184999 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 I0712 23:22:16.166070 184997 replica.cpp:541] Replica received write request for position 1 from __req_res__(957)@172.17.0.3:35959 I0712 23:22:16.166184 185015 replica.cpp:541] Replica received write request for position 1 from __req_res__(958)@172.17.0.3:35959 I0712 23:22:16.167344 184997 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 1.191281ms I0712 23:22:16.167349 185015 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 1.093412ms I0712 23:22:16.167445 184997 replica.cpp:712] Persisted action APPEND at position 1 I0712 23:22:16.167527 185015 replica.cpp:712] Persisted action APPEND at position 1 I0712 23:22:16.168637 184995 replica.cpp:695] Replica received learned notice for position 1 from log-network(47)@172.17.0.3:35959 I0712 23:22:16.168733 184996 replica.cpp:695] Replica received learned notice for position 1 from log-network(47)@172.17.0.3:35959 I0712 23:22:16.169610 184995 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 905322ns I0712 23:22:16.169669 184995 replica.cpp:712] Persisted action APPEND at position 1 I0712 23:22:16.169694 184996 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 907341ns I0712 23:22:16.169780 184996 replica.cpp:712] Persisted action APPEND at position 1 I0712 23:22:16.171267 185006 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 2 I0712 23:22:16.172508 184997 replica.cpp:541] Replica received write request for position 2 from __req_res__(959)@172.17.0.3:35959 I0712 23:22:16.172626 185008 replica.cpp:541] Replica received write request for position 2 from __req_res__(960)@172.17.0.3:35959 I0712 23:22:16.173718 184997 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 1.142576ms I0712 23:22:16.173718 185008 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 1.030906ms I0712 23:22:16.173841 184997 replica.cpp:712] Persisted action APPEND at position 2 I0712 23:22:16.173895 185008 replica.cpp:712] Persisted action APPEND at position 2 I0712 23:22:16.175169 185012 replica.cpp:695] Replica received learned notice for position 2 from log-network(47)@172.17.0.3:35959 I0712 23:22:16.175169 185003 replica.cpp:695] Replica received learned notice for position 2 from log-network(47)@172.17.0.3:35959 I0712 23:22:16.176496 185003 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.228475ms I0712 23:22:16.176496 185012 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.261596ms I0712 23:22:16.176610 185003 replica.cpp:712] Persisted action APPEND at position 2 I0712 23:22:16.176645 185012 replica.cpp:712] Persisted action APPEND at position 2 I0712 23:22:16.177779 184999 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3 I0712 23:22:16.179189 185001 replica.cpp:541] Replica received write request for position 3 from __req_res__(961)@172.17.0.3:35959 I0712 23:22:16.179292 185014 replica.cpp:541] Replica received write request for position 3 from __req_res__(962)@172.17.0.3:35959 I0712 23:22:16.180486 185014 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 1.127526ms I0712 23:22:16.180509 185001 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 1.254216ms I0712 23:22:16.180588 185014 replica.cpp:712] Persisted action APPEND at position 3 I0712 23:22:16.180649 185001 replica.cpp:712] Persisted action APPEND at position 3 I0712 23:22:16.181720 185003 replica.cpp:695] Replica received learned notice for position 3 from log-network(47)@172.17.0.3:35959 I0712 23:22:16.181720 185012 replica.cpp:695] Replica received learned notice for position 3 from log-network(47)@172.17.0.3:35959 I0712 23:22:16.183076 185012 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.248405ms I0712 23:22:16.183076 185003 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.268024ms I0712 23:22:16.183192 185012 replica.cpp:712] Persisted action APPEND at position 3 I0712 23:22:16.183223 185003 replica.cpp:712] Persisted action APPEND at position 3 I0712 23:22:16.184623 185005 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 4 I0712 23:22:16.185987 185011 replica.cpp:541] Replica received write request for position 4 from __req_res__(963)@172.17.0.3:35959 I0712 23:22:16.185993 185001 replica.cpp:541] Replica received write request for position 4 from __req_res__(964)@172.17.0.3:35959 I0712 23:22:16.187003 185011 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 933991ns I0712 23:22:16.187054 185011 replica.cpp:712] Persisted action APPEND at position 4 I0712 23:22:16.187094 185001 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 959283ns I0712 23:22:16.187182 185001 replica.cpp:712] Persisted action APPEND at position 4 I0712 23:22:16.188279 184998 replica.cpp:695] Replica received learned notice for position 4 from log-network(47)@172.17.0.3:35959 I0712 23:22:16.188279 185017 replica.cpp:695] Replica received learned notice for position 4 from log-network(47)@172.17.0.3:35959 I0712 23:22:16.189438 184998 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.094861ms I0712 23:22:16.189438 185017 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.060671ms I0712 23:22:16.189554 184998 replica.cpp:712] Persisted action APPEND at position 4 I0712 23:22:16.189584 185017 replica.cpp:712] Persisted action APPEND at position 4 I0712 23:22:16.191037 185014 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 5 I0712 23:22:16.192130 185001 replica.cpp:541] Replica received write request for position 5 from __req_res__(965)@172.17.0.3:35959 I0712 23:22:16.192189 185014 replica.cpp:541] Replica received write request for position 5 from __req_res__(966)@172.17.0.3:35959 I0712 23:22:16.193259 185014 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 1.016613ms I0712 23:22:16.193260 185001 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 1.066491ms I0712 23:22:16.193358 185014 replica.cpp:712] Persisted action APPEND at position 5 I0712 23:22:16.193449 185001 replica.cpp:712] Persisted action APPEND at position 5 I0712 23:22:16.194491 185008 replica.cpp:695] Replica received learned notice for position 5 from log-network(47)@172.17.0.3:35959 I0712 23:22:16.194921 185017 replica.cpp:695] Replica received learned notice for position 5 from log-network(47)@172.17.0.3:35959 I0712 23:22:16.195549 185008 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.012671ms I0712 23:22:16.195655 185008 replica.cpp:712] Persisted action APPEND at position 5 I0712 23:22:16.195837 185017 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 873209ns I0712 23:22:16.195923 185017 replica.cpp:712] Persisted action APPEND at position 5 I0712 23:22:16.197240 185015 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 6 I0712 23:22:16.198421 185010 replica.cpp:541] Replica received write request for position 6 from __req_res__(967)@172.17.0.3:35959 I0712 23:22:16.198468 185018 replica.cpp:541] Replica received write request for position 6 from __req_res__(968)@172.17.0.3:35959 I0712 23:22:16.198890 185018 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 368747ns I0712 23:22:16.198918 185018 replica.cpp:712] Persisted action APPEND at position 6 I0712 23:22:16.199047 185010 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 554238ns I0712 23:22:16.199137 185010 replica.cpp:712] Persisted action APPEND at position 6 I0712 23:22:16.200229 185016 replica.cpp:695] Replica received learned notice for position 6 from log-network(47)@172.17.0.3:35959 I0712 23:22:16.200301 184997 replica.cpp:695] Replica received learned notice for position 6 from log-network(47)@172.17.0.3:35959 I0712 23:22:16.201308 184997 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 945717ns I0712 23:22:16.201342 185016 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.074918ms I0712 23:22:16.201393 184997 replica.cpp:712] Persisted action APPEND at position 6 I0712 23:22:16.201452 185016 replica.cpp:712] Persisted action APPEND at position 6 I0712 23:22:16.202721 185011 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 7 I0712 23:22:16.203961 185000 replica.cpp:541] Replica received write request for position 7 from __req_res__(969)@172.17.0.3:35959 I0712 23:22:16.204088 185018 replica.cpp:541] Replica received write request for position 7 from __req_res__(970)@172.17.0.3:35959 I0712 23:22:16.204999 185018 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 872751ns I0712 23:22:16.205049 185018 replica.cpp:712] Persisted action APPEND at position 7 I0712 23:22:16.205090 185000 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 1.058321ms I0712 23:22:16.205183 185000 replica.cpp:712] Persisted action APPEND at position 7 I0712 23:22:16.206423 185012 replica.cpp:695] Replica received learned notice for position 7 from log-network(47)@172.17.0.3:35959 I0712 23:22:16.206430 184996 replica.cpp:695] Replica received learned notice for position 7 from log-network(47)@172.17.0.3:35959 I0712 23:22:16.207495 184996 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 952571ns I0712 23:22:16.207554 185012 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.068953ms I0712 23:22:16.207652 185012 replica.cpp:712] Persisted action APPEND at position 7 I0712 23:22:16.207582 184996 replica.cpp:712] Persisted action APPEND at position 7 I0712 23:22:16.209187 184999 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 8 I0712 23:22:16.210428 185018 replica.cpp:541] Replica received write request for position 8 from __req_res__(972)@172.17.0.3:35959 I0712 23:22:16.210491 185000 replica.cpp:541] Replica received write request for position 8 from __req_res__(971)@172.17.0.3:35959 I0712 23:22:16.211330 185018 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 865601ns I0712 23:22:16.211380 185018 replica.cpp:712] Persisted action APPEND at position 8 I0712 23:22:16.211505 185000 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 946713ns I0712 23:22:16.211597 185000 replica.cpp:712] Persisted action APPEND at position 8 I0712 23:22:16.212666 185001 replica.cpp:695] Replica received learned notice for position 8 from log-network(47)@172.17.0.3:35959 I0712 23:22:16.212693 185004 replica.cpp:695] Replica received learned notice for position 8 from log-network(47)@172.17.0.3:35959 I0712 23:22:16.213415 185004 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 658440ns I0712 23:22:16.213433 185001 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 716276ns I0712 23:22:16.213506 185004 replica.cpp:712] Persisted action APPEND at position 8 I0712 23:22:16.213551 185001 replica.cpp:712] Persisted action APPEND at position 8 I0712 23:22:16.215134 185005 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 9 I0712 23:22:16.216406 184995 replica.cpp:541] Replica received write request for position 9 from __req_res__(973)@172.17.0.3:35959 I0712 23:22:16.216419 185005 replica.cpp:541] Replica received write request for position 9 from __req_res__(974)@172.17.0.3:35959 I0712 23:22:16.216926 184995 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 481927ns I0712 23:22:16.216948 184995 replica.cpp:712] Persisted action APPEND at position 9 I0712 23:22:16.217726 185005 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 1.25436ms I0712 23:22:16.217840 185005 replica.cpp:712] Persisted action APPEND at position 9 I0712 23:22:16.218824 185012 replica.cpp:695] Replica received learned notice for position 9 from log-network(47)@172.17.0.3:35959 I0712 23:22:16.218886 185011 replica.cpp:695] Replica received learned notice for position 9 from log-network(47)@172.17.0.3:35959 I0712 23:22:16.219755 185012 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 883074ns I0712 23:22:16.219755 185011 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 823998ns I0712 23:22:16.219846 185012 replica.cpp:712] Persisted action APPEND at position 9 I0712 23:22:16.219919 185011 replica.cpp:712] Persisted action APPEND at position 9 I0712 23:22:16.221462 184999 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 10 I0712 23:22:16.222635 184996 replica.cpp:541] Replica received write request for position 10 from __req_res__(975)@172.17.0.3:35959 I0712 23:22:16.222693 185003 replica.cpp:541] Replica received write request for position 10 from __req_res__(976)@172.17.0.3:35959 I0712 23:22:16.223582 184996 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 878978ns I0712 23:22:16.223589 185003 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 824233ns I0712 23:22:16.223673 184996 replica.cpp:712] Persisted action APPEND at position 10 I0712 23:22:16.223747 185003 replica.cpp:712] Persisted action APPEND at position 10 I0712 23:22:16.224797 185005 replica.cpp:695] Replica received learned notice for position 10 from log-network(47)@172.17.0.3:35959 I0712 23:22:16.224802 185013 replica.cpp:695] Replica received learned notice for position 10 from log-network(47)@172.17.0.3:35959 I0712 23:22:16.225637 185013 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 751820ns I0712 23:22:16.225724 185013 replica.cpp:712] Persisted action APPEND at position 10 I0712 23:22:16.225836 185005 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 986872ns I0712 23:22:16.225922 185005 replica.cpp:712] Persisted action APPEND at position 10 I0712 23:22:16.233156 184994 leveldb.cpp:217] Opened db in 5.659123ms I0712 23:22:16.237803 184994 leveldb.cpp:224] Compacted db in 4.635423ms I0712 23:22:16.237934 184994 leveldb.cpp:239] Created db iterator in 45421ns I0712 23:22:16.237979 184994 leveldb.cpp:245] Seeked to beginning of db in 35450ns I0712 23:22:16.238030 184994 leveldb.cpp:320] Iterated through 1 keys in the db in 43799ns I0712 23:22:16.238077 184994 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0712 23:22:16.239008 184999 recover.cpp:437] Starting replica recovery I0712 23:22:16.239527 184999 recover.cpp:468] Replica is in VOTING status I0712 23:22:16.239800 184999 recover.cpp:447] Recover process terminated I0712 23:22:16.240584 184998 catchup.cpp:342] Starting missing positions recovery I0712 23:22:16.241223 185011 catchup.cpp:368] Replica is in VOTING status I0712 23:22:16.243381 184997 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(977)@172.17.0.3:35959 I0712 23:22:16.243424 185014 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(978)@172.17.0.3:35959 I0712 23:22:16.244243 185001 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(979)@172.17.0.3:35959 I0712 23:22:16.245288 185014 recover.cpp:197] Received a recover response from a replica in VOTING status I0712 23:22:16.245864 185014 recover.cpp:197] Received a recover response from a replica in VOTING status I0712 23:22:16.247092 185003 catchup.cpp:423] Starting catch-up from position 0 to 9 I0712 23:22:16.249437 185016 replica.cpp:391] Replica received explicit promise request from __req_res__(980)@172.17.0.3:35959 for position 0 with proposal 0 I0712 23:22:16.249568 185016 leveldb.cpp:510] Reading position from leveldb took 71979ns I0712 23:22:16.249572 184995 replica.cpp:391] Replica received explicit promise request from __req_res__(982)@172.17.0.3:35959 for position 0 with proposal 0 I0712 23:22:16.249547 185017 replica.cpp:391] Replica received explicit promise request from __req_res__(981)@172.17.0.3:35959 for position 0 with proposal 0 I0712 23:22:16.249841 185017 leveldb.cpp:510] Reading position from leveldb took 140950ns I0712 23:22:16.415975 185000 replica.cpp:391] Replica received explicit promise request from __req_res__(983)@172.17.0.3:35959 for position 0 with proposal 3 I0712 23:22:16.416047 185018 replica.cpp:391] Replica received explicit promise request from __req_res__(984)@172.17.0.3:35959 for position 0 with proposal 3 I0712 23:22:16.416108 185004 replica.cpp:391] Replica received explicit promise request from __req_res__(985)@172.17.0.3:35959 for position 0 with proposal 3 I0712 23:22:16.416147 185000 leveldb.cpp:510] Reading position from leveldb took 89901ns I0712 23:22:16.416224 185018 leveldb.cpp:510] Reading position from leveldb took 108162ns I0712 23:22:16.417258 185018 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 967901ns I0712 23:22:16.417306 185004 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 1.114474ms I0712 23:22:16.417309 185000 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 1.068688ms I0712 23:22:16.417454 185000 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:16.417346 185018 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:16.417404 185004 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:16.418488 185015 replica.cpp:695] Replica received learned notice for position 0 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.418493 185010 replica.cpp:695] Replica received learned notice for position 0 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.418538 184999 replica.cpp:695] Replica received learned notice for position 0 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.419360 185010 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 749300ns I0712 23:22:16.419407 185010 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:16.419412 185015 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 873096ns I0712 23:22:16.419464 184999 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 820535ns I0712 23:22:16.419493 185015 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:16.419559 184999 replica.cpp:712] Persisted action NOP at position 0 I0712 23:22:16.421720 185003 replica.cpp:391] Replica received explicit promise request from __req_res__(986)@172.17.0.3:35959 for position 1 with proposal 3 I0712 23:22:16.421792 185014 replica.cpp:391] Replica received explicit promise request from __req_res__(987)@172.17.0.3:35959 for position 1 with proposal 3 I0712 23:22:16.421838 184998 replica.cpp:391] Replica received explicit promise request from __req_res__(988)@172.17.0.3:35959 for position 1 with proposal 3 I0712 23:22:16.421921 185003 leveldb.cpp:510] Reading position from leveldb took 125578ns I0712 23:22:16.421994 185014 leveldb.cpp:510] Reading position from leveldb took 103311ns I0712 23:22:16.422848 185003 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 878990ns I0712 23:22:16.422852 184998 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 935606ns I0712 23:22:16.422937 185003 replica.cpp:712] Persisted action APPEND at position 1 I0712 23:22:16.423003 185014 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 952935ns I0712 23:22:16.423012 184998 replica.cpp:712] Persisted action NOP at position 1 I0712 23:22:16.423094 185014 replica.cpp:712] Persisted action APPEND at position 1 I0712 23:22:16.424108 185001 replica.cpp:695] Replica received learned notice for position 1 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.424124 185009 replica.cpp:695] Replica received learned notice for position 1 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.424134 185008 replica.cpp:695] Replica received learned notice for position 1 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.425143 185001 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 969028ns I0712 23:22:16.425184 185001 replica.cpp:712] Persisted action APPEND at position 1 I0712 23:22:16.425230 185008 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 853204ns I0712 23:22:16.425257 185009 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.043452ms I0712 23:22:16.425310 185008 replica.cpp:712] Persisted action APPEND at position 1 I0712 23:22:16.425356 185009 replica.cpp:712] Persisted action APPEND at position 1 I0712 23:22:16.427670 185007 replica.cpp:391] Replica received explicit promise request from __req_res__(989)@172.17.0.3:35959 for position 2 with proposal 3 I0712 23:22:16.427693 185005 replica.cpp:391] Replica received explicit promise request from __req_res__(991)@172.17.0.3:35959 for position 2 with proposal 3 I0712 23:22:16.427759 184998 replica.cpp:391] Replica received explicit promise request from __req_res__(990)@172.17.0.3:35959 for position 2 with proposal 3 I0712 23:22:16.427868 185007 leveldb.cpp:510] Reading position from leveldb took 106657ns I0712 23:22:16.428046 184998 leveldb.cpp:510] Reading position from leveldb took 120838ns I0712 23:22:16.428798 185005 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 969657ns I0712 23:22:16.428882 185007 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 862412ns I0712 23:22:16.428889 185005 replica.cpp:712] Persisted action NOP at position 2 I0712 23:22:16.428946 185007 replica.cpp:712] Persisted action APPEND at position 2 I0712 23:22:16.429081 184998 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 985601ns I0712 23:22:16.429167 184998 replica.cpp:712] Persisted action APPEND at position 2 I0712 23:22:16.429925 185016 replica.cpp:695] Replica received learned notice for position 2 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.429956 185013 replica.cpp:695] Replica received learned notice for position 2 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.429955 185011 replica.cpp:695] Replica received learned notice for position 2 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.430984 185011 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 902799ns I0712 23:22:16.431008 185013 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.002957ms I0712 23:22:16.431073 185011 replica.cpp:712] Persisted action APPEND at position 2 I0712 23:22:16.431015 185016 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.033984ms I0712 23:22:16.431109 185013 replica.cpp:712] Persisted action APPEND at position 2 I0712 23:22:16.431193 185016 replica.cpp:712] Persisted action APPEND at position 2 I0712 23:22:16.433526 185009 replica.cpp:391] Replica received explicit promise request from __req_res__(992)@172.17.0.3:35959 for position 3 with proposal 3 I0712 23:22:16.433549 184998 replica.cpp:391] Replica received explicit promise request from __req_res__(994)@172.17.0.3:35959 for position 3 with proposal 3 I0712 23:22:16.433645 184997 replica.cpp:391] Replica received explicit promise request from __req_res__(993)@172.17.0.3:35959 for position 3 with proposal 3 I0712 23:22:16.433702 185009 leveldb.cpp:510] Reading position from leveldb took 98958ns I0712 23:22:16.433840 184997 leveldb.cpp:510] Reading position from leveldb took 118758ns I0712 23:22:16.434407 184997 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 520325ns I0712 23:22:16.434432 185009 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 685179ns I0712 23:22:16.434485 184997 replica.cpp:712] Persisted action APPEND at position 3 I0712 23:22:16.434445 184998 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 814037ns I0712 23:22:16.434523 185009 replica.cpp:712] Persisted action APPEND at position 3 I0712 23:22:16.434603 184998 replica.cpp:712] Persisted action NOP at position 3 I0712 23:22:16.435514 185010 replica.cpp:695] Replica received learned notice for position 3 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.435523 184996 replica.cpp:695] Replica received learned notice for position 3 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.435546 185003 replica.cpp:695] Replica received learned notice for position 3 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.436579 184996 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 923318ns I0712 23:22:16.436587 185010 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.01686ms I0712 23:22:16.436668 184996 replica.cpp:712] Persisted action APPEND at position 3 I0712 23:22:16.436712 185010 replica.cpp:712] Persisted action APPEND at position 3 I0712 23:22:16.437004 185003 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.222158ms I0712 23:22:16.437105 185003 replica.cpp:712] Persisted action APPEND at position 3 I0712 23:22:16.439170 184997 replica.cpp:391] Replica received explicit promise request from __req_res__(995)@172.17.0.3:35959 for position 4 with proposal 3 I0712 23:22:16.439289 184998 replica.cpp:391] Replica received explicit promise request from __req_res__(996)@172.17.0.3:35959 for position 4 with proposal 3 I0712 23:22:16.439339 184997 leveldb.cpp:510] Reading position from leveldb took 93996ns I0712 23:22:16.439374 185016 replica.cpp:391] Replica received explicit promise request from __req_res__(997)@172.17.0.3:35959 for position 4 with proposal 3 I0712 23:22:16.439465 184998 leveldb.cpp:510] Reading position from leveldb took 90685ns I0712 23:22:16.440315 184997 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 903713ns I0712 23:22:16.440384 184998 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 876902ns I0712 23:22:16.440389 185016 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 947557ns I0712 23:22:16.440399 184997 replica.cpp:712] Persisted action APPEND at position 4 I0712 23:22:16.440554 185016 replica.cpp:712] Persisted action NOP at position 4 I0712 23:22:16.440474 184998 replica.cpp:712] Persisted action APPEND at position 4 I0712 23:22:16.441416 185002 replica.cpp:695] Replica received learned notice for position 4 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.441509 184999 replica.cpp:695] Replica received learned notice for position 4 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.441536 185008 replica.cpp:695] Replica received learned notice for position 4 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.442481 185008 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 893993ns I0712 23:22:16.442498 184999 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 950495ns I0712 23:22:16.442629 184999 replica.cpp:712] Persisted action APPEND at position 4 I0712 23:22:16.442502 185002 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.041725ms I0712 23:22:16.442836 185002 replica.cpp:712] Persisted action APPEND at position 4 I0712 23:22:16.442574 185008 replica.cpp:712] Persisted action APPEND at position 4 I0712 23:22:16.445091 185003 replica.cpp:391] Replica received explicit promise request from __req_res__(998)@172.17.0.3:35959 for position 5 with proposal 3 I0712 23:22:16.445241 185006 replica.cpp:391] Replica received explicit promise request from __req_res__(1000)@172.17.0.3:35959 for position 5 with proposal 3 I0712 23:22:16.445251 185003 leveldb.cpp:510] Reading position from leveldb took 89513ns I0712 23:22:16.445238 185010 replica.cpp:391] Replica received explicit promise request from __req_res__(999)@172.17.0.3:35959 for position 5 with proposal 3 I0712 23:22:16.445465 185010 leveldb.cpp:510] Reading position from leveldb took 102111ns I0712 23:22:16.446167 185006 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 901342ns I0712 23:22:16.446218 185003 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 892709ns I0712 23:22:16.446254 185006 replica.cpp:712] Persisted action NOP at position 5 I0712 23:22:16.446300 185003 replica.cpp:712] Persisted action APPEND at position 5 I0712 23:22:16.446712 185010 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.192119ms I0712 23:22:16.446812 185010 replica.cpp:712] Persisted action APPEND at position 5 I0712 23:22:16.447244 185010 replica.cpp:695] Replica received learned notice for position 5 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.447305 185015 replica.cpp:695] Replica received learned notice for position 5 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.447386 185012 replica.cpp:695] Replica received learned notice for position 5 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.448426 185012 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 991258ns I0712 23:22:16.448462 185010 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.193282ms I0712 23:22:16.448510 185012 replica.cpp:712] Persisted action APPEND at position 5 I0712 23:22:16.448468 185015 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.121496ms I0712 23:22:16.448560 185010 replica.cpp:712] Persisted action APPEND at position 5 I0712 23:22:16.448665 185015 replica.cpp:712] Persisted action APPEND at position 5 I0712 23:22:16.450802 185011 replica.cpp:391] Replica received explicit promise request from __req_res__(1001)@172.17.0.3:35959 for position 6 with proposal 3 I0712 23:22:16.450843 185008 replica.cpp:391] Replica received explicit promise request from __req_res__(1003)@172.17.0.3:35959 for position 6 with proposal 3 I0712 23:22:16.450891 185013 replica.cpp:391] Replica received explicit promise request from __req_res__(1002)@172.17.0.3:35959 for position 6 with proposal 3 I0712 23:22:16.450984 185011 leveldb.cpp:510] Reading position from leveldb took 98378ns I0712 23:22:16.451061 185013 leveldb.cpp:510] Reading position from leveldb took 96454ns I0712 23:22:16.451859 185013 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 752652ns I0712 23:22:16.451864 185011 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 838660ns I0712 23:22:16.452031 185011 replica.cpp:712] Persisted action APPEND at position 6 I0712 23:22:16.451872 185008 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 969030ns I0712 23:22:16.451948 185013 replica.cpp:712] Persisted action APPEND at position 6 I0712 23:22:16.452157 185008 replica.cpp:712] Persisted action NOP at position 6 I0712 23:22:16.453131 185018 replica.cpp:695] Replica received learned notice for position 6 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.453131 184995 replica.cpp:695] Replica received learned notice for position 6 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.453155 185014 replica.cpp:695] Replica received learned notice for position 6 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.454048 185018 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 844628ns I0712 23:22:16.454145 185018 replica.cpp:712] Persisted action APPEND at position 6 I0712 23:22:16.454068 184995 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 823009ns I0712 23:22:16.454288 185014 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 889962ns I0712 23:22:16.454298 184995 replica.cpp:712] Persisted action APPEND at position 6 I0712 23:22:16.454335 185014 replica.cpp:712] Persisted action APPEND at position 6 I0712 23:22:16.456435 185000 replica.cpp:391] Replica received explicit promise request from __req_res__(1004)@172.17.0.3:35959 for position 7 with proposal 3 I0712 23:22:16.456497 185005 replica.cpp:391] Replica received explicit promise request from __req_res__(1005)@172.17.0.3:35959 for position 7 with proposal 3 I0712 23:22:16.456528 185010 replica.cpp:391] Replica received explicit promise request from __req_res__(1006)@172.17.0.3:35959 for position 7 with proposal 3 I0712 23:22:16.456614 185000 leveldb.cpp:510] Reading position from leveldb took 97910ns I0712 23:22:16.456661 185005 leveldb.cpp:510] Reading position from leveldb took 92214ns I0712 23:22:16.457470 185005 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 763689ns I0712 23:22:16.457473 185010 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 884574ns I0712 23:22:16.457561 185005 replica.cpp:712] Persisted action APPEND at position 7 I0712 23:22:16.457603 185010 replica.cpp:712] Persisted action NOP at position 7 I0712 23:22:16.457476 185000 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 820779ns I0712 23:22:16.457751 185000 replica.cpp:712] Persisted action APPEND at position 7 I0712 23:22:16.458317 185009 replica.cpp:695] Replica received learned notice for position 7 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.458336 185003 replica.cpp:695] Replica received learned notice for position 7 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.458367 185004 replica.cpp:695] Replica received learned notice for position 7 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.459160 185009 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 805113ns I0712 23:22:16.459178 185004 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 773224ns I0712 23:22:16.459187 185009 replica.cpp:712] Persisted action APPEND at position 7 I0712 23:22:16.459182 185003 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 800040ns I0712 23:22:16.459220 185004 replica.cpp:712] Persisted action APPEND at position 7 I0712 23:22:16.459270 185003 replica.cpp:712] Persisted action APPEND at position 7 I0712 23:22:16.460971 185017 replica.cpp:391] Replica received explicit promise request from __req_res__(1007)@172.17.0.3:35959 for position 8 with proposal 3 I0712 23:22:16.461004 185000 replica.cpp:391] Replica received explicit promise request from __req_res__(1009)@172.17.0.3:35959 for position 8 with proposal 3 I0712 23:22:16.461041 185011 replica.cpp:391] Replica received explicit promise request from __req_res__(1008)@172.17.0.3:35959 for position 8 with proposal 3 I0712 23:22:16.461154 185017 leveldb.cpp:510] Reading position from leveldb took 96838ns I0712 23:22:16.461241 185011 leveldb.cpp:510] Reading position from leveldb took 95603ns I0712 23:22:16.461791 185011 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 487891ns I0712 23:22:16.461802 185017 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 617834ns I0712 23:22:16.461865 185011 replica.cpp:712] Persisted action APPEND at position 8 I0712 23:22:16.461910 185017 replica.cpp:712] Persisted action APPEND at position 8 I0712 23:22:16.461889 185000 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 799965ns I0712 23:22:16.461994 185000 replica.cpp:712] Persisted action NOP at position 8 I0712 23:22:16.462850 185015 replica.cpp:695] Replica received learned notice for position 8 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.462872 185007 replica.cpp:695] Replica received learned notice for position 8 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.462942 184999 replica.cpp:695] Replica received learned notice for position 8 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.463896 185015 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.002736ms I0712 23:22:16.463954 185015 replica.cpp:712] Persisted action APPEND at position 8 I0712 23:22:16.463979 184999 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 986271ns I0712 23:22:16.464004 185007 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.084373ms I0712 23:22:16.464061 184999 replica.cpp:712] Persisted action APPEND at position 8 I0712 23:22:16.464095 185007 replica.cpp:712] Persisted action APPEND at position 8 I0712 23:22:16.466277 185011 replica.cpp:391] Replica received explicit promise request from __req_res__(1010)@172.17.0.3:35959 for position 9 with proposal 3 I0712 23:22:16.466316 185012 replica.cpp:391] Replica received explicit promise request from __req_res__(1011)@172.17.0.3:35959 for position 9 with proposal 3 I0712 23:22:16.466454 185011 leveldb.cpp:510] Reading position from leveldb took 96222ns I0712 23:22:16.466485 185012 leveldb.cpp:510] Reading position from leveldb took 94706ns I0712 23:22:16.466545 184998 replica.cpp:391] Replica received explicit promise request from __req_res__(1012)@172.17.0.3:35959 for position 9 with proposal 3 I0712 23:22:16.467681 185011 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.18479ms I0712 23:22:16.467684 184998 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 1.074793ms I0712 23:22:16.467860 184998 replica.cpp:712] Persisted action NOP at position 9 I0712 23:22:16.467684 185012 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 1.160382ms I0712 23:22:16.467782 185011 replica.cpp:712] Persisted action APPEND at position 9 I0712 23:22:16.467993 185012 replica.cpp:712] Persisted action APPEND at position 9 I0712 23:22:16.469136 184997 replica.cpp:695] Replica received learned notice for position 9 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.469142 185010 replica.cpp:695] Replica received learned notice for position 9 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.469225 185016 replica.cpp:695] Replica received learned notice for position 9 from log-network(48)@172.17.0.3:35959 I0712 23:22:16.469895 185010 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 643565ns I0712 23:22:16.469945 185010 replica.cpp:712] Persisted action APPEND at position 9 I0712 23:22:16.469942 184997 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 749657ns I0712 23:22:16.470001 185016 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 721985ns I0712 23:22:16.470029 184997 replica.cpp:712] Persisted action APPEND at position 9 I0712 23:22:16.470090 185016 replica.cpp:712] Persisted action APPEND at position 9 I0712 23:22:16.471107 185014 catchup.cpp:357] Recover process terminated I0712 23:22:16.474383 184996 leveldb.cpp:510] Reading position from leveldb took 124787ns I0712 23:22:16.474534 184996 leveldb.cpp:510] Reading position from leveldb took 44249ns I0712 23:22:16.474598 184996 leveldb.cpp:510] Reading position from leveldb took 27105ns I0712 23:22:16.474655 184996 leveldb.cpp:510] Reading position from leveldb took 26327ns I0712 23:22:16.474709 184996 leveldb.cpp:510] Reading position from leveldb took 26324ns I0712 23:22:16.474761 184996 leveldb.cpp:510] Reading position from leveldb took 24314ns I0712 23:22:16.474815 184996 leveldb.cpp:510] Reading position from leveldb took 25538ns I0712 23:22:16.474871 184996 leveldb.cpp:510] Reading position from leveldb took 31460ns I0712 23:22:16.474949 184996 leveldb.cpp:510] Reading position from leveldb took 35662ns I0712 23:22:16.475020 184996 leveldb.cpp:510] Reading position from leveldb took 37962ns [ OK ] LogTest.ReaderCatchup (370 ms) [----------] 4 tests from LogTest (552 ms total) [----------] 2 tests from LogZooKeeperTest I0712 23:22:16.481200 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 I0712 23:22:16.565026 184994 jvm.cpp:590] Looking up method <init>(Ljava/lang/String;)V I0712 23:22:16.565356 184994 jvm.cpp:590] Looking up method deleteOnExit()V I0712 23:22:16.566315 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. I0712 23:22:16.645473 184994 jvm.cpp:590] Looking up method <init>()V I0712 23:22:16.646188 184994 jvm.cpp:590] Looking up method <init>(Lorg/apache/zookeeper/server/persistence/FileTxnSnapLog;Lorg/apache/zookeeper/server/ZooKeeperServer$DataTreeBuilder;)V *** Aborted at 1720826536 (unix time) try "date -d @1720826536" if you are using GNU date *** PC: @ 0x7fa713914ccd OopStorage::Block::release_entries() *** SIGSEGV (@0x238) received by PID 184994 (TID 0x7fa78ee64b40) from PID 568; stack trace: *** @ 0x7fa713923929 os::Linux::chained_handler() @ 0x7fa71392963b JVM_handle_linux_signal @ 0x7fa71391c1dc signalHandler() @ 0x7fa7904b7420 (unknown) @ 0x7fa713914ccd OopStorage::Block::release_entries() @ 0x7fa713914f26 OopStorage::release() @ 0x7fa713617b21 jni_DeleteGlobalRef @ 0x7fa79fc0f894 JNIEnv_::DeleteGlobalRef() @ 0x7fa79fc0d9dc Jvm::deleteGlobalRef() @ 0x5591fa3f790c Jvm::Object::~Object() @ 0x5591fa3fc732 org::apache::zookeeper::server::ZooKeeperServer::DataTreeBuilder::~DataTreeBuilder() @ 0x5591fa3ff036 org::apache::zookeeper::server::ZooKeeperServer::BasicDataTreeBuilder::~BasicDataTreeBuilder() @ 0x5591fa3fb051 mesos::internal::tests::ZooKeeperTestServer::ZooKeeperTestServer() @ 0x5591f8d9ef36 mesos::internal::tests::ZooKeeperTest::ZooKeeperTest() @ 0x5591f8da127f mesos::internal::tests::LogZooKeeperTest::LogZooKeeperTest() @ 0x5591f8da1390 mesos::internal::tests::LogZooKeeperTest_WriteRead_Test::LogZooKeeperTest_WriteRead_Test() @ 0x5591f8e0c292 testing::internal::TestFactoryImpl<>::CreateTest() @ 0x5591fa4418de testing::internal::HandleSehExceptionsInMethodIfSupported<>() @ 0x5591fa43aeaf testing::internal::HandleExceptionsInMethodIfSupported<>() @ 0x5591fa4170e7 testing::TestInfo::Run() @ 0x5591fa4177ef testing::TestCase::Run() @ 0x5591fa41eb89 testing::internal::UnitTestImpl::RunAllTests() @ 0x5591fa442b0c testing::internal::HandleSehExceptionsInMethodIfSupported<>() @ 0x5591fa43ba15 testing::internal::HandleExceptionsInMethodIfSupported<>() @ 0x5591fa41d6a1 testing::UnitTest::Run() @ 0x5591f8e29e45 RUN_ALL_TESTS() @ 0x5591f8e2980c main @ 0x7fa7902d5083 __libc_start_main @ 0x5591f7e6f79e _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' I0712 23:22:17.472771 186036 exec.cpp:560] Agent exited ... shutting down I0712 23:22:17.473582 186039 executor.cpp:190] Received SHUTDOWN event I0712 23:22:17.473639 186039 executor.cpp:843] Shutting down make[3]: *** [Makefile:15906: check-am] Error 2 I0712 23:22:17.473707 186039 executor.cpp:956] Sending SIGTERM to process tree at pid 186043 I0712 23:22:17.492715 186039 executor.cpp:969] Sent SIGTERM to the following process trees: [ -+- 186043 sh -c dd if=/dev/zero of=volume_path/file bs=1048576 count=2 && sleep 1000 \--- 186049 sleep 1000 ] I0712 23:22:17.492775 186039 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 I0712 23:22:17.525962 186025 executor.cpp:1041] Command terminated with signal Terminated (pid: 186043) W0712 23:22:17.528493 186040 process.cpp:1917] Failed to send 'mesos.internal.StatusUpdateMessage' to '172.17.0.3:35959', connect: Failed to connect to 172.17.0.3:35959: 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/33498/console - Mesos Reviewbot On July 12, 2024, 9:09 p.m., Jason Zhou wrote: > > ----------------------------------------------------------- > This is an automatically generated e-mail. To reply, visit: > https://reviews.apache.org/r/75086/ > ----------------------------------------------------------- > > (Updated July 12, 2024, 9:09 p.m.) > > > Review request for mesos and Benjamin Mahler. > > > Repository: mesos > > > Description > ------- > > In systems with systemd version above 242, there is a potential data > race where udev will try to update the MAC address of the device at the > same time as us if the systemd's MacAddressPolicy is set to 'persistent'. > To prevent udev from trying to set the veth device's MAC address by > itself, we must set the device MAC address on creation so that > addr_assign_type will be set to NET_ADDR_SET, which prevents udev from > attempting to change the MAC address of the veth device. > see: > https://github.com/torvalds/linux/commit/2afb9b533423a9b97f84181e773cf9361d98fed6 > see: > https://lore.kernel.org/netdev/cahxsexy8lkzocbdbzss_vjopc_tqmyzm87kc192hpmuhmcq...@mail.gmail.com/T/ > > > Diffs > ----- > > src/linux/routing/link/veth.hpp a4acbe9b5c7dd77f3736fc5348743081c04cabf1 > src/linux/routing/link/veth.cpp 6aeb95e710098056b464c2088b0b60cdd3fe3f65 > src/slave/containerizer/mesos/isolators/network/port_mapping.cpp > 3b3b899fb43364f545eb9748ab4215fd5b2e2895 > src/tests/containerizer/routing_tests.cpp > c9fa2e86a52873575c77bd0984d4eaba34282eff > > > Diff: https://reviews.apache.org/r/75086/diff/2/ > > > Testing > ------- > > Added test to check that veth::create with a target MAC address is able to > create a link with that target MAC address. > RoutingVethTest and PortMappingIsolatorTest pass (except > ROOT_ContainerARPExternal which has always failed) > > > Thanks, > > Jason Zhou > >
