----------------------------------------------------------- This is an automatically generated e-mail. To reply, visit: https://reviews.apache.org/r/75016/#review226631 -----------------------------------------------------------
Bad patch! Reviews applied: [75026, 75006, 75016] Failed command: ['bash', '-c', "set -o pipefail; export OS='ubuntu:20.04' BUILDTOOL='autotools' COMPILER='gcc' CONFIGURATION='--verbose --disable-libtool-wrappers --disable-parallel-test-execution' ENVIRONMENT='GLOG_v=1 MESOS_VERBOSE=1'; ./support/jenkins/buildbot.sh 2>&1 | tee build_75016"] Error: ...<truncated>... 4 185604 replica.cpp:712] Persisted action APPEND at position 10 I0704 00:06:26.355876 185619 coordinator.cpp:348] Coordinator attempting to write TRUNCATE action at position 11 I0704 00:06:26.357553 185618 replica.cpp:541] Replica received write request for position 11 from __req_res__(924)@172.17.0.2:39851 I0704 00:06:26.357707 185607 replica.cpp:541] Replica received write request for position 11 from __req_res__(925)@172.17.0.2:39851 I0704 00:06:26.408078 185618 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 50.455046ms I0704 00:06:26.408092 185607 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 50.310863ms I0704 00:06:26.408198 185618 replica.cpp:712] Persisted action TRUNCATE at position 11 I0704 00:06:26.408249 185607 replica.cpp:712] Persisted action TRUNCATE at position 11 I0704 00:06:26.409245 185603 replica.cpp:695] Replica received learned notice for position 11 from log-network(41)@172.17.0.2:39851 I0704 00:06:26.409250 185615 replica.cpp:695] Replica received learned notice for position 11 from log-network(41)@172.17.0.2:39851 I0704 00:06:26.492528 185615 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 83.199206ms I0704 00:06:26.492528 185603 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 83.239721ms I0704 00:06:26.542479 185603 leveldb.cpp:460] Deleting ~5 keys from leveldb took 49.837953ms I0704 00:06:26.542479 185615 leveldb.cpp:460] Deleting ~5 keys from leveldb took 49.883502ms I0704 00:06:26.994128 185603 leveldb.cpp:527] Compacting range 0-4 took 451.592136ms I0704 00:06:26.994114 185615 leveldb.cpp:527] Compacting range 0-4 took 451.539743ms I0704 00:06:26.994252 185603 replica.cpp:712] Persisted action TRUNCATE at position 11 I0704 00:06:26.994287 185615 replica.cpp:712] Persisted action TRUNCATE at position 11 I0704 00:06:27.427867 185598 leveldb.cpp:217] Opened db in 431.923997ms I0704 00:06:27.646831 185598 leveldb.cpp:224] Compacted db in 218.8965ms I0704 00:06:27.647015 185598 leveldb.cpp:239] Created db iterator in 89702ns I0704 00:06:27.647128 185598 leveldb.cpp:245] Seeked to beginning of db in 68205ns I0704 00:06:27.647274 185598 leveldb.cpp:320] Iterated through 1 keys in the db in 120034ns I0704 00:06:27.647406 185598 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0704 00:06:27.648643 185622 catchup.cpp:342] Starting missing positions recovery I0704 00:06:27.649253 185606 catchup.cpp:368] Replica is in VOTING status I0704 00:06:27.651227 185603 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(926)@172.17.0.2:39851 I0704 00:06:27.651849 185611 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(927)@172.17.0.2:39851 I0704 00:06:27.652997 185600 recover.cpp:197] Received a recover response from a replica in VOTING status I0704 00:06:27.653614 185600 recover.cpp:197] Received a recover response from a replica in VOTING status I0704 00:06:27.655622 185622 catchup.cpp:423] Starting catch-up from position 0 to 10 I0704 00:06:27.658196 185612 replica.cpp:391] Replica received explicit promise request from __req_res__(929)@172.17.0.2:39851 for position 0 with proposal 0 I0704 00:06:27.658227 185620 replica.cpp:391] Replica received explicit promise request from __req_res__(930)@172.17.0.2:39851 for position 0 with proposal 0 I0704 00:06:27.658471 185611 replica.cpp:391] Replica received explicit promise request from __req_res__(931)@172.17.0.2:39851 for position 0 with proposal 0 I0704 00:06:27.659479 185601 replica.cpp:695] Replica received learned notice for position 0 from log-network(42)@172.17.0.2:39851 I0704 00:06:27.659521 185606 replica.cpp:695] Replica received learned notice for position 0 from log-network(42)@172.17.0.2:39851 I0704 00:06:27.659575 185599 replica.cpp:695] Replica received learned notice for position 0 from log-network(42)@172.17.0.2:39851 I0704 00:06:27.705204 185599 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 45.600513ms I0704 00:06:27.705204 185606 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 45.669472ms I0704 00:06:27.705204 185601 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 45.697201ms I0704 00:06:27.705363 185599 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:27.705396 185606 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:27.705476 185601 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:27.708631 185608 replica.cpp:391] Replica received explicit promise request from __req_res__(932)@172.17.0.2:39851 for position 1 with proposal 0 I0704 00:06:27.708784 185600 replica.cpp:391] Replica received explicit promise request from __req_res__(933)@172.17.0.2:39851 for position 1 with proposal 0 I0704 00:06:27.709010 185622 replica.cpp:391] Replica received explicit promise request from __req_res__(934)@172.17.0.2:39851 for position 1 with proposal 0 I0704 00:06:27.709978 185609 replica.cpp:695] Replica received learned notice for position 1 from log-network(42)@172.17.0.2:39851 I0704 00:06:27.710032 185620 replica.cpp:695] Replica received learned notice for position 1 from log-network(42)@172.17.0.2:39851 I0704 00:06:27.710096 185607 replica.cpp:695] Replica received learned notice for position 1 from log-network(42)@172.17.0.2:39851 I0704 00:06:27.798230 185609 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 88.204436ms I0704 00:06:27.798231 185620 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 88.1592ms I0704 00:06:27.798231 185607 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 88.094568ms I0704 00:06:27.848697 185620 leveldb.cpp:460] Deleting ~1 keys from leveldb took 50.354311ms I0704 00:06:27.848702 185607 leveldb.cpp:460] Deleting ~1 keys from leveldb took 50.314389ms I0704 00:06:27.848698 185609 leveldb.cpp:460] Deleting ~1 keys from leveldb took 50.41919ms I0704 00:06:28.472038 185607 leveldb.cpp:527] Compacting range 0-0 took 623.245134ms I0704 00:06:28.472097 185609 leveldb.cpp:527] Compacting range 0-0 took 623.248614ms I0704 00:06:28.472097 185620 leveldb.cpp:527] Compacting range 0-0 took 623.340039ms I0704 00:06:28.472188 185607 replica.cpp:712] Persisted action NOP at position 1 I0704 00:06:28.472225 185609 replica.cpp:712] Persisted action NOP at position 1 I0704 00:06:28.472290 185620 replica.cpp:712] Persisted action NOP at position 1 I0704 00:06:28.475239 185619 replica.cpp:391] Replica received explicit promise request from __req_res__(935)@172.17.0.2:39851 for position 2 with proposal 0 I0704 00:06:28.475662 185604 replica.cpp:391] Replica received explicit promise request from __req_res__(936)@172.17.0.2:39851 for position 2 with proposal 0 I0704 00:06:28.475791 185617 replica.cpp:391] Replica received explicit promise request from __req_res__(937)@172.17.0.2:39851 for position 2 with proposal 0 I0704 00:06:28.476810 185615 replica.cpp:695] Replica received learned notice for position 2 from log-network(42)@172.17.0.2:39851 I0704 00:06:28.476855 185604 replica.cpp:695] Replica received learned notice for position 2 from log-network(42)@172.17.0.2:39851 I0704 00:06:28.476900 185599 replica.cpp:695] Replica received learned notice for position 2 from log-network(42)@172.17.0.2:39851 I0704 00:06:28.563086 185615 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 86.218952ms I0704 00:06:28.591398 185599 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 114.457108ms I0704 00:06:28.591519 185604 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 114.63181ms I0704 00:06:28.614854 185615 leveldb.cpp:460] Deleting ~1 keys from leveldb took 51.65138ms I0704 00:06:28.637499 185599 leveldb.cpp:460] Deleting ~1 keys from leveldb took 46.047823ms I0704 00:06:28.637538 185604 leveldb.cpp:460] Deleting ~1 keys from leveldb took 45.899224ms I0704 00:06:29.329059 185615 leveldb.cpp:527] Compacting range 1-1 took 714.156724ms I0704 00:06:29.329074 185604 leveldb.cpp:527] Compacting range 1-1 took 691.446067ms I0704 00:06:29.329210 185615 replica.cpp:712] Persisted action NOP at position 2 I0704 00:06:29.329238 185604 replica.cpp:712] Persisted action NOP at position 2 I0704 00:06:29.444156 185599 leveldb.cpp:527] Compacting range 1-1 took 806.58777ms I0704 00:06:29.444273 185599 replica.cpp:712] Persisted action NOP at position 2 I0704 00:06:29.447072 185618 replica.cpp:391] Replica received explicit promise request from __req_res__(938)@172.17.0.2:39851 for position 3 with proposal 0 I0704 00:06:29.447301 185614 replica.cpp:391] Replica received explicit promise request from __req_res__(939)@172.17.0.2:39851 for position 3 with proposal 0 I0704 00:06:29.447834 185615 replica.cpp:391] Replica received explicit promise request from __req_res__(940)@172.17.0.2:39851 for position 3 with proposal 0 I0704 00:06:29.448369 185608 replica.cpp:695] Replica received learned notice for position 3 from log-network(42)@172.17.0.2:39851 I0704 00:06:29.448451 185605 replica.cpp:695] Replica received learned notice for position 3 from log-network(42)@172.17.0.2:39851 I0704 00:06:29.448383 185607 replica.cpp:695] Replica received learned notice for position 3 from log-network(42)@172.17.0.2:39851 I0704 00:06:29.535351 185607 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 86.799306ms I0704 00:06:29.535351 185608 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 86.917244ms I0704 00:06:29.535352 185605 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 86.854201ms I0704 00:06:29.627557 185608 leveldb.cpp:460] Deleting ~1 keys from leveldb took 92.080493ms I0704 00:06:29.627558 185607 leveldb.cpp:460] Deleting ~1 keys from leveldb took 92.140556ms I0704 00:06:29.627575 185605 leveldb.cpp:460] Deleting ~1 keys from leveldb took 92.053064ms I0704 00:06:30.513314 185607 leveldb.cpp:527] Compacting range 2-2 took 885.653339ms I0704 00:06:30.513449 185608 leveldb.cpp:527] Compacting range 2-2 took 885.819456ms I0704 00:06:30.513470 185607 replica.cpp:712] Persisted action NOP at position 3 I0704 00:06:30.513501 185605 leveldb.cpp:527] Compacting range 2-2 took 885.78711ms I0704 00:06:30.513556 185608 replica.cpp:712] Persisted action NOP at position 3 I0704 00:06:30.513631 185605 replica.cpp:712] Persisted action NOP at position 3 I0704 00:06:30.516513 185606 replica.cpp:391] Replica received explicit promise request from __req_res__(941)@172.17.0.2:39851 for position 4 with proposal 0 I0704 00:06:30.516669 185611 replica.cpp:391] Replica received explicit promise request from __req_res__(942)@172.17.0.2:39851 for position 4 with proposal 0 I0704 00:06:30.516814 185618 replica.cpp:391] Replica received explicit promise request from __req_res__(943)@172.17.0.2:39851 for position 4 with proposal 0 I0704 00:06:30.517881 185621 replica.cpp:695] Replica received learned notice for position 4 from log-network(42)@172.17.0.2:39851 I0704 00:06:30.517920 185613 replica.cpp:695] Replica received learned notice for position 4 from log-network(42)@172.17.0.2:39851 I0704 00:06:30.518059 185605 replica.cpp:695] Replica received learned notice for position 4 from log-network(42)@172.17.0.2:39851 I0704 00:06:30.624145 185621 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 106.204603ms I0704 00:06:30.624146 185613 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 106.1791ms I0704 00:06:30.624195 185605 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 106.066839ms I0704 00:06:30.734187 185621 leveldb.cpp:460] Deleting ~1 keys from leveldb took 109.954893ms I0704 00:06:30.734208 185605 leveldb.cpp:460] Deleting ~1 keys from leveldb took 109.891612ms I0704 00:06:30.734198 185613 leveldb.cpp:460] Deleting ~1 keys from leveldb took 109.922657ms I0704 00:06:31.454238 185613 leveldb.cpp:527] Compacting range 3-3 took 719.89094ms I0704 00:06:31.454238 185621 leveldb.cpp:527] Compacting range 3-3 took 719.994328ms I0704 00:06:31.454380 185613 replica.cpp:712] Persisted action NOP at position 4 I0704 00:06:31.454411 185621 replica.cpp:712] Persisted action NOP at position 4 I0704 00:06:31.602012 185605 leveldb.cpp:527] Compacting range 3-3 took 867.714568ms I0704 00:06:31.602218 185605 replica.cpp:712] Persisted action NOP at position 4 I0704 00:06:31.605618 185609 replica.cpp:391] Replica received explicit promise request from __req_res__(944)@172.17.0.2:39851 for position 5 with proposal 0 I0704 00:06:31.605753 185602 replica.cpp:391] Replica received explicit promise request from __req_res__(945)@172.17.0.2:39851 for position 5 with proposal 0 I0704 00:06:31.605861 185609 leveldb.cpp:510] Reading position from leveldb took 159853ns I0704 00:06:31.605973 185602 leveldb.cpp:510] Reading position from leveldb took 142394ns I0704 00:06:31.606042 185614 replica.cpp:391] Replica received explicit promise request from __req_res__(946)@172.17.0.2:39851 for position 5 with proposal 0 I0704 00:06:31.788002 185599 replica.cpp:391] Replica received explicit promise request from __req_res__(947)@172.17.0.2:39851 for position 5 with proposal 2 I0704 00:06:31.788166 185622 replica.cpp:391] Replica received explicit promise request from __req_res__(948)@172.17.0.2:39851 for position 5 with proposal 2 I0704 00:06:31.788347 185622 leveldb.cpp:510] Reading position from leveldb took 124697ns I0704 00:06:31.788350 185599 leveldb.cpp:510] Reading position from leveldb took 220878ns I0704 00:06:31.788494 185600 replica.cpp:391] Replica received explicit promise request from __req_res__(949)@172.17.0.2:39851 for position 5 with proposal 2 I0704 00:06:31.867589 185599 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 79.137966ms I0704 00:06:31.867591 185622 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 79.160402ms I0704 00:06:31.867740 185599 replica.cpp:712] Persisted action APPEND at position 5 I0704 00:06:31.867592 185600 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 79.068763ms I0704 00:06:31.867774 185622 replica.cpp:712] Persisted action APPEND at position 5 I0704 00:06:31.867882 185600 replica.cpp:712] Persisted action NOP at position 5 I0704 00:06:31.869378 185618 replica.cpp:695] Replica received learned notice for position 5 from log-network(42)@172.17.0.2:39851 I0704 00:06:31.869442 185607 replica.cpp:695] Replica received learned notice for position 5 from log-network(42)@172.17.0.2:39851 I0704 00:06:31.869515 185615 replica.cpp:695] Replica received learned notice for position 5 from log-network(42)@172.17.0.2:39851 I0704 00:06:31.937028 185607 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 67.52671ms I0704 00:06:31.937052 185615 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 67.488528ms I0704 00:06:31.937116 185607 replica.cpp:712] Persisted action APPEND at position 5 I0704 00:06:31.937052 185618 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 67.612842ms I0704 00:06:31.937165 185615 replica.cpp:712] Persisted action APPEND at position 5 I0704 00:06:31.937209 185618 replica.cpp:712] Persisted action APPEND at position 5 I0704 00:06:31.941990 185614 replica.cpp:391] Replica received explicit promise request from __req_res__(950)@172.17.0.2:39851 for position 6 with proposal 2 I0704 00:06:31.942548 185613 replica.cpp:391] Replica received explicit promise request from __req_res__(951)@172.17.0.2:39851 for position 6 with proposal 2 I0704 00:06:31.942620 185614 leveldb.cpp:510] Reading position from leveldb took 465660ns I0704 00:06:31.942690 185611 replica.cpp:391] Replica received explicit promise request from __req_res__(952)@172.17.0.2:39851 for position 6 with proposal 2 I0704 00:06:31.943024 185613 leveldb.cpp:510] Reading position from leveldb took 348612ns I0704 00:06:32.010578 185614 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 67.781459ms I0704 00:06:32.010579 185611 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 67.826481ms I0704 00:06:32.010624 185613 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 67.513665ms I0704 00:06:32.010739 185611 replica.cpp:712] Persisted action NOP at position 6 I0704 00:06:32.010681 185614 replica.cpp:712] Persisted action APPEND at position 6 I0704 00:06:32.010826 185613 replica.cpp:712] Persisted action APPEND at position 6 I0704 00:06:32.012544 185609 replica.cpp:695] Replica received learned notice for position 6 from log-network(42)@172.17.0.2:39851 I0704 00:06:32.012671 185622 replica.cpp:695] Replica received learned notice for position 6 from log-network(42)@172.17.0.2:39851 I0704 00:06:32.012729 185599 replica.cpp:695] Replica received learned notice for position 6 from log-network(42)@172.17.0.2:39851 I0704 00:06:32.086294 185599 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 73.534902ms I0704 00:06:32.086310 185622 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 73.581657ms I0704 00:06:32.086416 185599 replica.cpp:712] Persisted action APPEND at position 6 I0704 00:06:32.086457 185622 replica.cpp:712] Persisted action APPEND at position 6 I0704 00:06:32.086323 185609 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 73.721314ms I0704 00:06:32.086560 185609 replica.cpp:712] Persisted action APPEND at position 6 I0704 00:06:32.089375 185611 replica.cpp:391] Replica received explicit promise request from __req_res__(953)@172.17.0.2:39851 for position 7 with proposal 2 I0704 00:06:32.089601 185611 leveldb.cpp:510] Reading position from leveldb took 182946ns I0704 00:06:32.089674 185610 replica.cpp:391] Replica received explicit promise request from __req_res__(954)@172.17.0.2:39851 for position 7 with proposal 2 I0704 00:06:32.089869 185610 leveldb.cpp:510] Reading position from leveldb took 143374ns I0704 00:06:32.089867 185600 replica.cpp:391] Replica received explicit promise request from __req_res__(955)@172.17.0.2:39851 for position 7 with proposal 2 I0704 00:06:32.373423 185610 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 283.490694ms I0704 00:06:32.373423 185611 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 283.72468ms I0704 00:06:32.373572 185610 replica.cpp:712] Persisted action APPEND at position 7 I0704 00:06:32.373623 185611 replica.cpp:712] Persisted action APPEND at position 7 I0704 00:06:32.373423 185600 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 283.501667ms I0704 00:06:32.373739 185600 replica.cpp:712] Persisted action NOP at position 7 I0704 00:06:32.375309 185621 replica.cpp:695] Replica received learned notice for position 7 from log-network(42)@172.17.0.2:39851 I0704 00:06:32.375378 185613 replica.cpp:695] Replica received learned notice for position 7 from log-network(42)@172.17.0.2:39851 I0704 00:06:32.375499 185618 replica.cpp:695] Replica received learned notice for position 7 from log-network(42)@172.17.0.2:39851 I0704 00:06:32.546833 185613 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 171.394108ms I0704 00:06:32.546828 185621 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 171.465907ms I0704 00:06:32.546819 185618 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 171.28833ms I0704 00:06:32.546963 185613 replica.cpp:712] Persisted action APPEND at position 7 I0704 00:06:32.547001 185621 replica.cpp:712] Persisted action APPEND at position 7 I0704 00:06:32.547045 185618 replica.cpp:712] Persisted action APPEND at position 7 I0704 00:06:32.549909 185609 replica.cpp:391] Replica received explicit promise request from __req_res__(956)@172.17.0.2:39851 for position 8 with proposal 2 I0704 00:06:32.550156 185609 leveldb.cpp:510] Reading position from leveldb took 180816ns I0704 00:06:32.550374 185619 replica.cpp:391] Replica received explicit promise request from __req_res__(958)@172.17.0.2:39851 for position 8 with proposal 2 I0704 00:06:32.550441 185614 replica.cpp:391] Replica received explicit promise request from __req_res__(957)@172.17.0.2:39851 for position 8 with proposal 2 I0704 00:06:32.550630 185614 leveldb.cpp:510] Reading position from leveldb took 123634ns I0704 00:06:32.696453 185614 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 145.766583ms I0704 00:06:32.696453 185609 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 146.214846ms I0704 00:06:32.696585 185614 replica.cpp:712] Persisted action APPEND at position 8 I0704 00:06:32.696453 185619 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 146.054356ms I0704 00:06:32.696626 185609 replica.cpp:712] Persisted action APPEND at position 8 I0704 00:06:32.696702 185619 replica.cpp:712] Persisted action NOP at position 8 I0704 00:06:32.697947 185602 replica.cpp:695] Replica received learned notice for position 8 from log-network(42)@172.17.0.2:39851 I0704 00:06:32.697983 185601 replica.cpp:695] Replica received learned notice for position 8 from log-network(42)@172.17.0.2:39851 I0704 00:06:32.697981 185622 replica.cpp:695] Replica received learned notice for position 8 from log-network(42)@172.17.0.2:39851 I0704 00:06:32.791127 185601 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 93.089731ms I0704 00:06:32.791127 185622 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 93.062213ms I0704 00:06:32.791256 185601 replica.cpp:712] Persisted action APPEND at position 8 I0704 00:06:32.791127 185602 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 93.14577ms I0704 00:06:32.791307 185622 replica.cpp:712] Persisted action APPEND at position 8 I0704 00:06:32.791364 185602 replica.cpp:712] Persisted action APPEND at position 8 I0704 00:06:32.794283 185613 replica.cpp:391] Replica received explicit promise request from __req_res__(959)@172.17.0.2:39851 for position 9 with proposal 2 I0704 00:06:32.794427 185607 replica.cpp:391] Replica received explicit promise request from __req_res__(960)@172.17.0.2:39851 for position 9 with proposal 2 I0704 00:06:32.794545 185613 leveldb.cpp:510] Reading position from leveldb took 198136ns I0704 00:06:32.794615 185607 leveldb.cpp:510] Reading position from leveldb took 130877ns I0704 00:06:32.794669 185603 replica.cpp:391] Replica received explicit promise request from __req_res__(961)@172.17.0.2:39851 for position 9 with proposal 2 I0704 00:06:32.859207 185607 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 64.525955ms I0704 00:06:32.859248 185603 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 64.523579ms I0704 00:06:32.859299 185607 replica.cpp:712] Persisted action APPEND at position 9 I0704 00:06:32.859237 185613 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 64.580283ms I0704 00:06:32.859347 185603 replica.cpp:712] Persisted action NOP at position 9 I0704 00:06:32.859395 185613 replica.cpp:712] Persisted action APPEND at position 9 I0704 00:06:32.860348 185608 replica.cpp:695] Replica received learned notice for position 9 from log-network(42)@172.17.0.2:39851 I0704 00:06:32.860391 185606 replica.cpp:695] Replica received learned notice for position 9 from log-network(42)@172.17.0.2:39851 I0704 00:06:32.860433 185615 replica.cpp:695] Replica received learned notice for position 9 from log-network(42)@172.17.0.2:39851 I0704 00:06:32.926438 185608 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 66.082862ms I0704 00:06:32.926438 185606 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 66.040572ms I0704 00:06:32.926438 185615 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 65.987434ms I0704 00:06:32.926651 185606 replica.cpp:712] Persisted action APPEND at position 9 I0704 00:06:32.926694 185615 replica.cpp:712] Persisted action APPEND at position 9 I0704 00:06:32.926626 185608 replica.cpp:712] Persisted action APPEND at position 9 I0704 00:06:32.930258 185601 replica.cpp:391] Replica received explicit promise request from __req_res__(962)@172.17.0.2:39851 for position 10 with proposal 2 I0704 00:06:32.930351 185612 replica.cpp:391] Replica received explicit promise request from __req_res__(963)@172.17.0.2:39851 for position 10 with proposal 2 I0704 00:06:32.930536 185601 leveldb.cpp:510] Reading position from leveldb took 208455ns I0704 00:06:32.930541 185612 leveldb.cpp:510] Reading position from leveldb took 133444ns I0704 00:06:32.930610 185617 replica.cpp:391] Replica received explicit promise request from __req_res__(964)@172.17.0.2:39851 for position 10 with proposal 2 I0704 00:06:33.044047 185617 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 113.382108ms I0704 00:06:33.044024 185612 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 113.385975ms I0704 00:06:33.044164 185617 replica.cpp:712] Persisted action NOP at position 10 I0704 00:06:33.044024 185601 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 113.406517ms I0704 00:06:33.044224 185612 replica.cpp:712] Persisted action APPEND at position 10 I0704 00:06:33.044273 185601 replica.cpp:712] Persisted action APPEND at position 10 I0704 00:06:33.045717 185605 replica.cpp:695] Replica received learned notice for position 10 from log-network(42)@172.17.0.2:39851 I0704 00:06:33.045751 185611 replica.cpp:695] Replica received learned notice for position 10 from log-network(42)@172.17.0.2:39851 I0704 00:06:33.045805 185600 replica.cpp:695] Replica received learned notice for position 10 from log-network(42)@172.17.0.2:39851 I0704 00:06:33.119889 185611 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 74.064164ms I0704 00:06:33.119897 185605 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 74.113602ms I0704 00:06:33.119982 185611 replica.cpp:712] Persisted action APPEND at position 10 I0704 00:06:33.119904 185600 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 74.040601ms I0704 00:06:33.120033 185605 replica.cpp:712] Persisted action APPEND at position 10 I0704 00:06:33.120077 185600 replica.cpp:712] Persisted action APPEND at position 10 I0704 00:06:33.120921 185604 catchup.cpp:357] Recover process terminated I0704 00:06:33.122679 185610 leveldb.cpp:510] Reading position from leveldb took 144257ns I0704 00:06:33.122874 185610 leveldb.cpp:510] Reading position from leveldb took 83968ns I0704 00:06:33.123051 185610 leveldb.cpp:510] Reading position from leveldb took 102951ns I0704 00:06:33.123260 185610 leveldb.cpp:510] Reading position from leveldb took 118538ns I0704 00:06:33.123432 185610 leveldb.cpp:510] Reading position from leveldb took 91301ns I0704 00:06:33.123642 185610 leveldb.cpp:510] Reading position from leveldb took 106551ns [ OK ] RecoverTest.CatchupVotingWithGap (10509 ms) [ RUN ] RecoverTest.CatchupVotingOnePosition I0704 00:06:33.387291 185598 leveldb.cpp:217] Opened db in 256.237261ms I0704 00:06:33.475729 185598 leveldb.cpp:224] Compacted db in 88.363635ms I0704 00:06:33.475872 185598 leveldb.cpp:239] Created db iterator in 72809ns I0704 00:06:33.475939 185598 leveldb.cpp:245] Seeked to beginning of db in 25349ns I0704 00:06:33.475991 185598 leveldb.cpp:320] Iterated through 0 keys in the db in 20937ns I0704 00:06:33.476114 185598 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0704 00:06:33.586405 185610 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 109.604412ms I0704 00:06:33.586571 185610 replica.cpp:322] Persisted replica status to VOTING I0704 00:06:33.862305 185598 leveldb.cpp:217] Opened db in 274.537434ms I0704 00:06:33.923552 185598 leveldb.cpp:224] Compacted db in 61.140345ms I0704 00:06:33.923645 185598 leveldb.cpp:239] Created db iterator in 42030ns I0704 00:06:33.923673 185598 leveldb.cpp:245] Seeked to beginning of db in 9078ns I0704 00:06:33.923693 185598 leveldb.cpp:320] Iterated through 0 keys in the db in 7842ns I0704 00:06:33.923756 185598 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0704 00:06:33.998643 185601 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 74.381823ms I0704 00:06:33.998749 185601 replica.cpp:322] Persisted replica status to VOTING I0704 00:06:34.260692 185598 leveldb.cpp:217] Opened db in 260.971814ms I0704 00:06:34.305466 185598 leveldb.cpp:224] Compacted db in 44.699969ms I0704 00:06:34.305588 185598 leveldb.cpp:239] Created db iterator in 54349ns I0704 00:06:34.305629 185598 leveldb.cpp:245] Seeked to beginning of db in 12773ns I0704 00:06:34.305655 185598 leveldb.cpp:320] Iterated through 0 keys in the db in 10426ns I0704 00:06:34.305734 185598 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0704 00:06:34.378225 185613 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 71.825642ms I0704 00:06:34.378288 185613 replica.cpp:322] Persisted replica status to VOTING I0704 00:06:34.653892 185598 leveldb.cpp:217] Opened db in 275.000593ms I0704 00:06:35.003345 185598 leveldb.cpp:224] Compacted db in 349.378845ms I0704 00:06:35.003511 185598 leveldb.cpp:239] Created db iterator in 66412ns I0704 00:06:35.003600 185598 leveldb.cpp:245] Seeked to beginning of db in 62829ns I0704 00:06:35.003705 185598 leveldb.cpp:320] Iterated through 1 keys in the db in 79935ns I0704 00:06:35.003798 185598 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0704 00:06:35.312747 185598 leveldb.cpp:217] Opened db in 308.489798ms I0704 00:06:35.532652 185598 leveldb.cpp:224] Compacted db in 219.827914ms I0704 00:06:35.532778 185598 leveldb.cpp:239] Created db iterator in 47187ns I0704 00:06:35.532832 185598 leveldb.cpp:245] Seeked to beginning of db in 39965ns I0704 00:06:35.532900 185598 leveldb.cpp:320] Iterated through 1 keys in the db in 55677ns I0704 00:06:35.532963 185598 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0704 00:06:35.752638 185598 leveldb.cpp:217] Opened db in 219.362904ms I0704 00:06:35.938299 185598 leveldb.cpp:224] Compacted db in 185.56223ms I0704 00:06:35.938423 185598 leveldb.cpp:239] Created db iterator in 47041ns I0704 00:06:35.938478 185598 leveldb.cpp:245] Seeked to beginning of db in 39601ns I0704 00:06:35.938546 185598 leveldb.cpp:320] Iterated through 1 keys in the db in 56280ns I0704 00:06:35.938608 185598 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0704 00:06:35.939296 185607 catchup.cpp:342] Starting missing positions recovery I0704 00:06:35.939723 185607 catchup.cpp:368] Replica is in VOTING status I0704 00:06:35.940975 185608 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(965)@172.17.0.2:39851 I0704 00:06:35.941118 185601 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(966)@172.17.0.2:39851 I0704 00:06:35.941347 185618 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(967)@172.17.0.2:39851 I0704 00:06:35.942106 185601 recover.cpp:197] Received a recover response from a replica in VOTING status I0704 00:06:35.942463 185601 recover.cpp:197] Received a recover response from a replica in VOTING status I0704 00:06:35.943310 185613 catchup.cpp:357] Recover process terminated [ OK ] RecoverTest.CatchupVotingOnePosition (2816 ms) [----------] 9 tests from RecoverTest (59839 ms total) [----------] 4 tests from LogTest [ RUN ] LogTest.WriteRead I0704 00:06:36.191605 185598 leveldb.cpp:217] Opened db in 244.158451ms I0704 00:06:36.279634 185598 leveldb.cpp:224] Compacted db in 87.946747ms I0704 00:06:36.279757 185598 leveldb.cpp:239] Created db iterator in 53735ns I0704 00:06:36.279800 185598 leveldb.cpp:245] Seeked to beginning of db in 13176ns I0704 00:06:36.279827 185598 leveldb.cpp:320] Iterated through 0 keys in the db in 10540ns I0704 00:06:36.279922 185598 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0704 00:06:36.352916 185600 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 72.308908ms I0704 00:06:36.353030 185600 replica.cpp:322] Persisted replica status to VOTING I0704 00:06:36.650336 185598 leveldb.cpp:217] Opened db in 296.49992ms I0704 00:06:36.754881 185598 leveldb.cpp:224] Compacted db in 104.465394ms I0704 00:06:36.755012 185598 leveldb.cpp:239] Created db iterator in 54808ns I0704 00:06:36.755055 185598 leveldb.cpp:245] Seeked to beginning of db in 13363ns I0704 00:06:36.755082 185598 leveldb.cpp:320] Iterated through 0 keys in the db in 10480ns I0704 00:06:36.755167 185598 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0704 00:06:36.877876 185618 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 122.010705ms I0704 00:06:36.877964 185618 replica.cpp:322] Persisted replica status to VOTING I0704 00:06:37.187602 185598 leveldb.cpp:217] Opened db in 308.735042ms I0704 00:06:37.429852 185598 leveldb.cpp:224] Compacted db in 242.159777ms I0704 00:06:37.430013 185598 leveldb.cpp:239] Created db iterator in 64282ns I0704 00:06:37.430088 185598 leveldb.cpp:245] Seeked to beginning of db in 48309ns I0704 00:06:37.430187 185598 leveldb.cpp:320] Iterated through 1 keys in the db in 78375ns I0704 00:06:37.430281 185598 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0704 00:06:37.902931 185598 leveldb.cpp:217] Opened db in 472.12892ms I0704 00:06:38.080061 185598 leveldb.cpp:224] Compacted db in 177.059397ms I0704 00:06:38.080227 185598 leveldb.cpp:239] Created db iterator in 63655ns I0704 00:06:38.080300 185598 leveldb.cpp:245] Seeked to beginning of db in 47052ns I0704 00:06:38.080401 185598 leveldb.cpp:320] Iterated through 1 keys in the db in 77875ns I0704 00:06:38.080494 185598 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0704 00:06:38.081848 185619 recover.cpp:437] Starting replica recovery I0704 00:06:38.082445 185619 recover.cpp:468] Replica is in VOTING status I0704 00:06:38.082793 185619 recover.cpp:447] Recover process terminated I0704 00:06:38.083513 185619 log.cpp:554] Attempting to start the writer I0704 00:06:38.086134 185620 replica.cpp:497] Replica received implicit promise request from __req_res__(968)@172.17.0.2:39851 with proposal 1 I0704 00:06:38.086272 185616 replica.cpp:497] Replica received implicit promise request from __req_res__(969)@172.17.0.2:39851 with proposal 1 I0704 00:06:38.185950 185620 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 99.740495ms I0704 00:06:38.185983 185616 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 99.66051ms I0704 00:06:38.186043 185620 replica.cpp:344] Persisted promised to 1 I0704 00:06:38.186091 185616 replica.cpp:344] Persisted promised to 1 I0704 00:06:38.187222 185620 coordinator.cpp:238] Coordinator attempting to fill missing positions I0704 00:06:38.189311 185614 replica.cpp:391] Replica received explicit promise request from __req_res__(970)@172.17.0.2:39851 for position 0 with proposal 2 I0704 00:06:38.189453 185602 replica.cpp:391] Replica received explicit promise request from __req_res__(971)@172.17.0.2:39851 for position 0 with proposal 2 I0704 00:06:38.238692 185614 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 49.291125ms I0704 00:06:38.238693 185602 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 49.160842ms I0704 00:06:38.238786 185614 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:38.238829 185602 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:38.240464 185600 replica.cpp:541] Replica received write request for position 0 from __req_res__(972)@172.17.0.2:39851 I0704 00:06:38.240617 185600 leveldb.cpp:510] Reading position from leveldb took 98598ns I0704 00:06:38.240679 185604 replica.cpp:541] Replica received write request for position 0 from __req_res__(973)@172.17.0.2:39851 I0704 00:06:38.240839 185604 leveldb.cpp:510] Reading position from leveldb took 87905ns I0704 00:06:38.347719 185600 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 107.029357ms I0704 00:06:38.347719 185604 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 106.81586ms I0704 00:06:38.347874 185600 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:38.347903 185604 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:38.348907 185602 replica.cpp:695] Replica received learned notice for position 0 from log-network(44)@172.17.0.2:39851 I0704 00:06:38.348959 185616 replica.cpp:695] Replica received learned notice for position 0 from log-network(44)@172.17.0.2:39851 I0704 00:06:38.407325 185602 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 58.370269ms I0704 00:06:38.407370 185616 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 58.356103ms I0704 00:06:38.407423 185602 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:38.407454 185616 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:38.408480 185601 log.cpp:570] Writer started with ending position 0 I0704 00:06:38.409359 185604 log.cpp:578] Attempting to append 11 bytes to the log I0704 00:06:38.409592 185600 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 I0704 00:06:38.410944 185614 replica.cpp:541] Replica received write request for position 1 from __req_res__(974)@172.17.0.2:39851 I0704 00:06:38.411029 185602 replica.cpp:541] Replica received write request for position 1 from __req_res__(975)@172.17.0.2:39851 I0704 00:06:38.474794 185602 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 63.680468ms I0704 00:06:38.474794 185614 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 63.76984ms I0704 00:06:38.474865 185602 replica.cpp:712] Persisted action APPEND at position 1 I0704 00:06:38.474898 185614 replica.cpp:712] Persisted action APPEND at position 1 I0704 00:06:38.475647 185607 replica.cpp:695] Replica received learned notice for position 1 from log-network(44)@172.17.0.2:39851 I0704 00:06:38.475653 185603 replica.cpp:695] Replica received learned notice for position 1 from log-network(44)@172.17.0.2:39851 I0704 00:06:38.533360 185607 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 57.680868ms I0704 00:06:38.533360 185603 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 57.652161ms I0704 00:06:38.533454 185607 replica.cpp:712] Persisted action APPEND at position 1 I0704 00:06:38.533499 185603 replica.cpp:712] Persisted action APPEND at position 1 I0704 00:06:38.535992 185610 leveldb.cpp:510] Reading position from leveldb took 116124ns [ OK ] LogTest.WriteRead (2595 ms) [ RUN ] LogTest.Position I0704 00:06:38.745956 185598 leveldb.cpp:217] Opened db in 203.330379ms I0704 00:06:38.812799 185598 leveldb.cpp:224] Compacted db in 66.763431ms I0704 00:06:38.812925 185598 leveldb.cpp:239] Created db iterator in 54865ns I0704 00:06:38.812973 185598 leveldb.cpp:245] Seeked to beginning of db in 12869ns I0704 00:06:38.813000 185598 leveldb.cpp:320] Iterated through 0 keys in the db in 10893ns I0704 00:06:38.813082 185598 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0704 00:06:38.854772 185609 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 41.047613ms I0704 00:06:38.854859 185609 replica.cpp:322] Persisted replica status to VOTING I0704 00:06:39.150266 185598 leveldb.cpp:217] Opened db in 294.385392ms I0704 00:06:39.236619 185598 leveldb.cpp:224] Compacted db in 86.293109ms I0704 00:06:39.236726 185598 leveldb.cpp:239] Created db iterator in 38500ns I0704 00:06:39.236766 185598 leveldb.cpp:245] Seeked to beginning of db in 11053ns I0704 00:06:39.236785 185598 leveldb.cpp:320] Iterated through 0 keys in the db in 7154ns I0704 00:06:39.236853 185598 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0704 00:06:39.293466 185621 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 56.130222ms I0704 00:06:39.293630 185621 replica.cpp:322] Persisted replica status to VOTING I0704 00:06:39.555083 185598 leveldb.cpp:217] Opened db in 260.375836ms I0704 00:06:39.771521 185598 leveldb.cpp:224] Compacted db in 216.364812ms I0704 00:06:39.771667 185598 leveldb.cpp:239] Created db iterator in 63115ns I0704 00:06:39.771742 185598 leveldb.cpp:245] Seeked to beginning of db in 48639ns I0704 00:06:39.771844 185598 leveldb.cpp:320] Iterated through 1 keys in the db in 79125ns I0704 00:06:39.771950 185598 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0704 00:06:39.993666 185598 leveldb.cpp:217] Opened db in 221.291992ms I0704 00:06:40.155128 185598 leveldb.cpp:224] Compacted db in 161.387975ms I0704 00:06:40.155310 185598 leveldb.cpp:239] Created db iterator in 65849ns I0704 00:06:40.155391 185598 leveldb.cpp:245] Seeked to beginning of db in 48846ns I0704 00:06:40.155491 185598 leveldb.cpp:320] Iterated through 1 keys in the db in 79455ns I0704 00:06:40.155583 185598 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0704 00:06:40.156901 185606 recover.cpp:437] Starting replica recovery I0704 00:06:40.157590 185621 recover.cpp:468] Replica is in VOTING status I0704 00:06:40.158214 185621 recover.cpp:447] Recover process terminated I0704 00:06:40.158903 185617 log.cpp:554] Attempting to start the writer I0704 00:06:40.161341 185599 replica.cpp:497] Replica received implicit promise request from __req_res__(976)@172.17.0.2:39851 with proposal 1 I0704 00:06:40.161485 185604 replica.cpp:497] Replica received implicit promise request from __req_res__(977)@172.17.0.2:39851 with proposal 1 I0704 00:06:40.237846 185599 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 76.447687ms I0704 00:06:40.237854 185604 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 76.311942ms I0704 00:06:40.237932 185599 replica.cpp:344] Persisted promised to 1 I0704 00:06:40.237964 185604 replica.cpp:344] Persisted promised to 1 I0704 00:06:40.238880 185599 coordinator.cpp:238] Coordinator attempting to fill missing positions I0704 00:06:40.240600 185620 replica.cpp:391] Replica received explicit promise request from __req_res__(978)@172.17.0.2:39851 for position 0 with proposal 2 I0704 00:06:40.240728 185602 replica.cpp:391] Replica received explicit promise request from __req_res__(979)@172.17.0.2:39851 for position 0 with proposal 2 I0704 00:06:40.289151 185620 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 48.50057ms I0704 00:06:40.289151 185602 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 48.379878ms I0704 00:06:40.289243 185620 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:40.289286 185602 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:40.291030 185611 replica.cpp:541] Replica received write request for position 0 from __req_res__(980)@172.17.0.2:39851 I0704 00:06:40.291167 185611 leveldb.cpp:510] Reading position from leveldb took 110227ns I0704 00:06:40.291167 185614 replica.cpp:541] Replica received write request for position 0 from __req_res__(981)@172.17.0.2:39851 I0704 00:06:40.291379 185614 leveldb.cpp:510] Reading position from leveldb took 95721ns I0704 00:06:40.352833 185611 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 61.550475ms I0704 00:06:40.352833 185614 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 61.364082ms I0704 00:06:40.352902 185611 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:40.352932 185614 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:40.353668 185604 replica.cpp:695] Replica received learned notice for position 0 from log-network(45)@172.17.0.2:39851 I0704 00:06:40.353674 185620 replica.cpp:695] Replica received learned notice for position 0 from log-network(45)@172.17.0.2:39851 I0704 00:06:40.415532 185604 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 61.804303ms I0704 00:06:40.415532 185620 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 61.761234ms I0704 00:06:40.415654 185604 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:40.415692 185620 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:40.416662 185621 log.cpp:570] Writer started with ending position 0 I0704 00:06:40.417552 185601 log.cpp:578] Attempting to append 11 bytes to the log I0704 00:06:40.417778 185618 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 I0704 00:06:40.418985 185622 replica.cpp:541] Replica received write request for position 1 from __req_res__(982)@172.17.0.2:39851 I0704 00:06:40.419126 185612 replica.cpp:541] Replica received write request for position 1 from __req_res__(983)@172.17.0.2:39851 I0704 00:06:40.490986 185612 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 71.764148ms I0704 00:06:40.490986 185622 leveldb.cpp:390] Persisting action (27 bytes) to leveldb took 71.933637ms I0704 00:06:40.491099 185612 replica.cpp:712] Persisted action APPEND at position 1 I0704 00:06:40.491147 185622 replica.cpp:712] Persisted action APPEND at position 1 I0704 00:06:40.492246 185603 replica.cpp:695] Replica received learned notice for position 1 from log-network(45)@172.17.0.2:39851 I0704 00:06:40.492245 185610 replica.cpp:695] Replica received learned notice for position 1 from log-network(45)@172.17.0.2:39851 I0704 00:06:40.549770 185603 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 57.462019ms I0704 00:06:40.549798 185610 leveldb.cpp:390] Persisting action (29 bytes) to leveldb took 57.444219ms I0704 00:06:40.549894 185603 replica.cpp:712] Persisted action APPEND at position 1 I0704 00:06:40.549937 185610 replica.cpp:712] Persisted action APPEND at position 1 [ OK ] LogTest.Position (2014 ms) [ RUN ] LogTest.Metrics I0704 00:06:40.787034 185598 leveldb.cpp:217] Opened db in 230.488271ms I0704 00:06:40.846107 185598 leveldb.cpp:224] Compacted db in 58.997665ms I0704 00:06:40.846230 185598 leveldb.cpp:239] Created db iterator in 54138ns I0704 00:06:40.846272 185598 leveldb.cpp:245] Seeked to beginning of db in 12573ns I0704 00:06:40.846299 185598 leveldb.cpp:320] Iterated through 0 keys in the db in 10413ns I0704 00:06:40.846381 185598 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0704 00:06:40.893076 185619 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 46.030153ms I0704 00:06:40.893160 185619 replica.cpp:322] Persisted replica status to VOTING I0704 00:06:41.107930 185598 leveldb.cpp:217] Opened db in 213.762849ms I0704 00:06:41.274494 185598 leveldb.cpp:224] Compacted db in 166.487356ms I0704 00:06:41.274631 185598 leveldb.cpp:239] Created db iterator in 61349ns I0704 00:06:41.274703 185598 leveldb.cpp:245] Seeked to beginning of db in 44859ns I0704 00:06:41.274799 185598 leveldb.cpp:320] Iterated through 1 keys in the db in 76785ns I0704 00:06:41.274890 185598 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0704 00:06:41.276084 185621 recover.cpp:437] Starting replica recovery I0704 00:06:41.276572 185610 recover.cpp:468] Replica is in VOTING status I0704 00:06:41.276957 185610 recover.cpp:447] Recover process terminated I0704 00:06:41.277669 185602 log.cpp:554] Attempting to start the writer I0704 00:06:41.280005 185614 replica.cpp:497] Replica received implicit promise request from __req_res__(984)@172.17.0.2:39851 with proposal 1 I0704 00:06:41.322993 185614 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 42.932329ms I0704 00:06:41.323081 185614 replica.cpp:344] Persisted promised to 1 I0704 00:06:41.324218 185607 coordinator.cpp:238] Coordinator attempting to fill missing positions I0704 00:06:41.326395 185619 replica.cpp:391] Replica received explicit promise request from __req_res__(985)@172.17.0.2:39851 for position 0 with proposal 2 I0704 00:06:41.371480 185619 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 45.028626ms I0704 00:06:41.371619 185619 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:41.373402 185620 replica.cpp:541] Replica received write request for position 0 from __req_res__(986)@172.17.0.2:39851 I0704 00:06:41.373554 185620 leveldb.cpp:510] Reading position from leveldb took 88075ns I0704 00:06:41.454181 185620 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 80.543299ms I0704 00:06:41.454249 185620 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:41.454977 185611 replica.cpp:695] Replica received learned notice for position 0 from log-network(46)@172.17.0.2:39851 I0704 00:06:41.499598 185611 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 44.590215ms I0704 00:06:41.499684 185611 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:41.500717 185619 log.cpp:570] Writer started with ending position 0 I0704 00:06:41.506518 185601 process.cpp:3671] Handling HTTP event for process 'metrics' with path: '/metrics/snapshot' [ OK ] LogTest.Metrics (963 ms) [ RUN ] LogTest.ReaderCatchup I0704 00:06:41.727005 185598 leveldb.cpp:217] Opened db in 207.7044ms I0704 00:06:41.787925 185598 leveldb.cpp:224] Compacted db in 60.843907ms I0704 00:06:41.788053 185598 leveldb.cpp:239] Created db iterator in 54892ns I0704 00:06:41.788095 185598 leveldb.cpp:245] Seeked to beginning of db in 12850ns I0704 00:06:41.788121 185598 leveldb.cpp:320] Iterated through 0 keys in the db in 10553ns I0704 00:06:41.788204 185598 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0704 00:06:41.827353 185600 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 38.456227ms I0704 00:06:41.827441 185600 replica.cpp:322] Persisted replica status to VOTING I0704 00:06:42.132337 185598 leveldb.cpp:217] Opened db in 303.940365ms I0704 00:06:42.200342 185598 leveldb.cpp:224] Compacted db in 67.929241ms I0704 00:06:42.200464 185598 leveldb.cpp:239] Created db iterator in 53889ns I0704 00:06:42.200505 185598 leveldb.cpp:245] Seeked to beginning of db in 12693ns I0704 00:06:42.200531 185598 leveldb.cpp:320] Iterated through 0 keys in the db in 10510ns I0704 00:06:42.200611 185598 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0704 00:06:42.233676 185611 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 32.40878ms I0704 00:06:42.233762 185611 replica.cpp:322] Persisted replica status to VOTING I0704 00:06:42.538532 185598 leveldb.cpp:217] Opened db in 303.632015ms I0704 00:06:42.614581 185598 leveldb.cpp:224] Compacted db in 75.950266ms I0704 00:06:42.614696 185598 leveldb.cpp:239] Created db iterator in 45661ns I0704 00:06:42.614727 185598 leveldb.cpp:245] Seeked to beginning of db in 10460ns I0704 00:06:42.614748 185598 leveldb.cpp:320] Iterated through 0 keys in the db in 8130ns I0704 00:06:42.614813 185598 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0704 00:06:42.916112 185609 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 300.722949ms I0704 00:06:42.916235 185609 replica.cpp:322] Persisted replica status to VOTING I0704 00:06:44.387284 185598 leveldb.cpp:217] Opened db in 1.469976847secs I0704 00:06:45.272655 185598 leveldb.cpp:224] Compacted db in 885.279695ms I0704 00:06:45.272822 185598 leveldb.cpp:239] Created db iterator in 65445ns I0704 00:06:45.272900 185598 leveldb.cpp:245] Seeked to beginning of db in 51379ns I0704 00:06:45.273000 185598 leveldb.cpp:320] Iterated through 1 keys in the db in 78521ns I0704 00:06:45.273093 185598 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0704 00:06:45.611806 185598 leveldb.cpp:217] Opened db in 338.20583ms I0704 00:06:45.896063 185598 leveldb.cpp:224] Compacted db in 284.193809ms I0704 00:06:45.896229 185598 leveldb.cpp:239] Created db iterator in 64145ns I0704 00:06:45.896303 185598 leveldb.cpp:245] Seeked to beginning of db in 48282ns I0704 00:06:45.896404 185598 leveldb.cpp:320] Iterated through 1 keys in the db in 78872ns I0704 00:06:45.896497 185598 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0704 00:06:45.899574 185615 replica.cpp:497] Replica received implicit promise request from __req_res__(987)@172.17.0.2:39851 with proposal 1 I0704 00:06:45.899775 185604 replica.cpp:497] Replica received implicit promise request from __req_res__(988)@172.17.0.2:39851 with proposal 1 I0704 00:06:46.000773 185615 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 101.129695ms I0704 00:06:46.000873 185615 replica.cpp:344] Persisted promised to 1 I0704 00:06:46.000773 185604 leveldb.cpp:353] Persisting metadata (8 bytes) to leveldb took 100.955542ms I0704 00:06:46.000968 185604 replica.cpp:344] Persisted promised to 1 I0704 00:06:46.001997 185611 coordinator.cpp:238] Coordinator attempting to fill missing positions I0704 00:06:46.004227 185621 replica.cpp:391] Replica received explicit promise request from __req_res__(989)@172.17.0.2:39851 for position 0 with proposal 2 I0704 00:06:46.004379 185619 replica.cpp:391] Replica received explicit promise request from __req_res__(990)@172.17.0.2:39851 for position 0 with proposal 2 I0704 00:06:46.084033 185621 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 79.740665ms I0704 00:06:46.084033 185619 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 79.593189ms I0704 00:06:46.084139 185621 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:46.084197 185619 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:46.085918 185601 replica.cpp:541] Replica received write request for position 0 from __req_res__(991)@172.17.0.2:39851 I0704 00:06:46.086024 185599 replica.cpp:541] Replica received write request for position 0 from __req_res__(992)@172.17.0.2:39851 I0704 00:06:46.086066 185601 leveldb.cpp:510] Reading position from leveldb took 86688ns I0704 00:06:46.086160 185599 leveldb.cpp:510] Reading position from leveldb took 89538ns I0704 00:06:46.184154 185601 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 98.021123ms I0704 00:06:46.184156 185599 leveldb.cpp:390] Persisting action (14 bytes) to leveldb took 97.894566ms I0704 00:06:46.184258 185601 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:46.184304 185599 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:46.185242 185604 replica.cpp:695] Replica received learned notice for position 0 from log-network(47)@172.17.0.2:39851 I0704 00:06:46.185292 185612 replica.cpp:695] Replica received learned notice for position 0 from log-network(47)@172.17.0.2:39851 I0704 00:06:46.260154 185604 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 74.870128ms I0704 00:06:46.260162 185612 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 74.830519ms I0704 00:06:46.260246 185604 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:46.260306 185612 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:46.261988 185608 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 1 I0704 00:06:46.263159 185618 replica.cpp:541] Replica received write request for position 1 from __req_res__(993)@172.17.0.2:39851 I0704 00:06:46.263339 185619 replica.cpp:541] Replica received write request for position 1 from __req_res__(994)@172.17.0.2:39851 I0704 00:06:46.340567 185619 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 77.172749ms I0704 00:06:46.340567 185618 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 77.305922ms I0704 00:06:46.340668 185619 replica.cpp:712] Persisted action APPEND at position 1 I0704 00:06:46.340705 185618 replica.cpp:712] Persisted action APPEND at position 1 I0704 00:06:46.341557 185607 replica.cpp:695] Replica received learned notice for position 1 from log-network(47)@172.17.0.2:39851 I0704 00:06:46.341560 185620 replica.cpp:695] Replica received learned notice for position 1 from log-network(47)@172.17.0.2:39851 I0704 00:06:46.428752 185620 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 87.131695ms I0704 00:06:46.428754 185607 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 87.164498ms I0704 00:06:46.428849 185620 replica.cpp:712] Persisted action APPEND at position 1 I0704 00:06:46.428900 185607 replica.cpp:712] Persisted action APPEND at position 1 I0704 00:06:46.430223 185609 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 2 I0704 00:06:46.431635 185606 replica.cpp:541] Replica received write request for position 2 from __req_res__(995)@172.17.0.2:39851 I0704 00:06:46.431862 185612 replica.cpp:541] Replica received write request for position 2 from __req_res__(996)@172.17.0.2:39851 I0704 00:06:46.512701 185612 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 80.742687ms I0704 00:06:46.512730 185606 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 80.984318ms I0704 00:06:46.512843 185612 replica.cpp:712] Persisted action APPEND at position 2 I0704 00:06:46.512874 185606 replica.cpp:712] Persisted action APPEND at position 2 I0704 00:06:46.513978 185616 replica.cpp:695] Replica received learned notice for position 2 from log-network(47)@172.17.0.2:39851 I0704 00:06:46.513999 185617 replica.cpp:695] Replica received learned notice for position 2 from log-network(47)@172.17.0.2:39851 I0704 00:06:46.620111 185616 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 106.069956ms I0704 00:06:46.620121 185617 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 106.021383ms I0704 00:06:46.620209 185616 replica.cpp:712] Persisted action APPEND at position 2 I0704 00:06:46.620254 185617 replica.cpp:712] Persisted action APPEND at position 2 I0704 00:06:46.621758 185609 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 3 I0704 00:06:46.623054 185606 replica.cpp:541] Replica received write request for position 3 from __req_res__(997)@172.17.0.2:39851 I0704 00:06:46.623248 185620 replica.cpp:541] Replica received write request for position 3 from __req_res__(998)@172.17.0.2:39851 I0704 00:06:46.681687 185606 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 58.562825ms I0704 00:06:46.681687 185620 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 58.334269ms I0704 00:06:46.681865 185606 replica.cpp:712] Persisted action APPEND at position 3 I0704 00:06:46.681888 185620 replica.cpp:712] Persisted action APPEND at position 3 I0704 00:06:46.683614 185608 replica.cpp:695] Replica received learned notice for position 3 from log-network(47)@172.17.0.2:39851 I0704 00:06:46.683718 185621 replica.cpp:695] Replica received learned notice for position 3 from log-network(47)@172.17.0.2:39851 I0704 00:06:46.770057 185608 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 86.401358ms I0704 00:06:46.770080 185621 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 86.313901ms I0704 00:06:46.770162 185608 replica.cpp:712] Persisted action APPEND at position 3 I0704 00:06:46.770226 185621 replica.cpp:712] Persisted action APPEND at position 3 I0704 00:06:46.772007 185615 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 4 I0704 00:06:46.773468 185620 replica.cpp:541] Replica received write request for position 4 from __req_res__(999)@172.17.0.2:39851 I0704 00:06:46.773571 185606 replica.cpp:541] Replica received write request for position 4 from __req_res__(1000)@172.17.0.2:39851 I0704 00:06:46.866437 185606 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 92.812317ms I0704 00:06:46.866437 185620 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 92.904886ms I0704 00:06:46.866549 185606 replica.cpp:712] Persisted action APPEND at position 4 I0704 00:06:46.866592 185620 replica.cpp:712] Persisted action APPEND at position 4 I0704 00:06:46.867646 185619 replica.cpp:695] Replica received learned notice for position 4 from log-network(47)@172.17.0.2:39851 I0704 00:06:46.867792 185605 replica.cpp:695] Replica received learned notice for position 4 from log-network(47)@172.17.0.2:39851 I0704 00:06:46.968504 185605 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 100.666619ms I0704 00:06:46.968505 185619 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 100.798775ms I0704 00:06:46.968600 185605 replica.cpp:712] Persisted action APPEND at position 4 I0704 00:06:46.968670 185619 replica.cpp:712] Persisted action APPEND at position 4 I0704 00:06:46.970212 185614 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 5 I0704 00:06:46.971801 185606 replica.cpp:541] Replica received write request for position 5 from __req_res__(1001)@172.17.0.2:39851 I0704 00:06:46.972079 185608 replica.cpp:541] Replica received write request for position 5 from __req_res__(1002)@172.17.0.2:39851 I0704 00:06:47.344806 185608 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 372.643063ms I0704 00:06:47.344811 185606 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 372.93045ms I0704 00:06:47.344949 185608 replica.cpp:712] Persisted action APPEND at position 5 I0704 00:06:47.344987 185606 replica.cpp:712] Persisted action APPEND at position 5 I0704 00:06:47.346148 185609 replica.cpp:695] Replica received learned notice for position 5 from log-network(47)@172.17.0.2:39851 I0704 00:06:47.346221 185616 replica.cpp:695] Replica received learned notice for position 5 from log-network(47)@172.17.0.2:39851 I0704 00:06:47.654740 185616 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 308.480108ms I0704 00:06:47.654740 185609 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 308.548763ms I0704 00:06:47.654855 185616 replica.cpp:712] Persisted action APPEND at position 5 I0704 00:06:47.654897 185609 replica.cpp:712] Persisted action APPEND at position 5 I0704 00:06:47.656406 185621 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 6 I0704 00:06:47.657756 185606 replica.cpp:541] Replica received write request for position 6 from __req_res__(1003)@172.17.0.2:39851 I0704 00:06:47.657891 185615 replica.cpp:541] Replica received write request for position 6 from __req_res__(1004)@172.17.0.2:39851 I0704 00:06:47.704715 185606 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 46.873412ms I0704 00:06:47.704715 185615 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 46.762438ms I0704 00:06:47.704833 185606 replica.cpp:712] Persisted action APPEND at position 6 I0704 00:06:47.704875 185615 replica.cpp:712] Persisted action APPEND at position 6 I0704 00:06:47.705919 185620 replica.cpp:695] Replica received learned notice for position 6 from log-network(47)@172.17.0.2:39851 I0704 00:06:47.705940 185599 replica.cpp:695] Replica received learned notice for position 6 from log-network(47)@172.17.0.2:39851 I0704 00:06:47.793771 185599 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 87.758489ms I0704 00:06:47.793773 185620 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 87.805567ms I0704 00:06:47.793864 185599 replica.cpp:712] Persisted action APPEND at position 6 I0704 00:06:47.793926 185620 replica.cpp:712] Persisted action APPEND at position 6 I0704 00:06:47.795295 185605 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 7 I0704 00:06:47.796640 185600 replica.cpp:541] Replica received write request for position 7 from __req_res__(1005)@172.17.0.2:39851 I0704 00:06:47.796752 185609 replica.cpp:541] Replica received write request for position 7 from __req_res__(1006)@172.17.0.2:39851 I0704 00:06:47.869952 185609 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 73.137017ms I0704 00:06:47.869952 185600 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 73.234861ms I0704 00:06:47.870082 185609 replica.cpp:712] Persisted action APPEND at position 7 I0704 00:06:47.870119 185600 replica.cpp:712] Persisted action APPEND at position 7 I0704 00:06:47.871177 185599 replica.cpp:695] Replica received learned notice for position 7 from log-network(47)@172.17.0.2:39851 I0704 00:06:47.871269 185613 replica.cpp:695] Replica received learned notice for position 7 from log-network(47)@172.17.0.2:39851 I0704 00:06:47.956661 185599 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 85.4113ms I0704 00:06:47.956692 185613 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 85.378285ms I0704 00:06:47.956751 185599 replica.cpp:712] Persisted action APPEND at position 7 I0704 00:06:47.956782 185613 replica.cpp:712] Persisted action APPEND at position 7 I0704 00:06:47.958009 185608 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 8 I0704 00:06:47.959285 185609 replica.cpp:541] Replica received write request for position 8 from __req_res__(1007)@172.17.0.2:39851 I0704 00:06:47.959558 185616 replica.cpp:541] Replica received write request for position 8 from __req_res__(1008)@172.17.0.2:39851 I0704 00:06:48.019968 185616 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 60.351015ms I0704 00:06:48.019968 185609 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 60.620412ms I0704 00:06:48.020087 185616 replica.cpp:712] Persisted action APPEND at position 8 I0704 00:06:48.020126 185609 replica.cpp:712] Persisted action APPEND at position 8 I0704 00:06:48.021049 185621 replica.cpp:695] Replica received learned notice for position 8 from log-network(47)@172.17.0.2:39851 I0704 00:06:48.021102 185611 replica.cpp:695] Replica received learned notice for position 8 from log-network(47)@172.17.0.2:39851 I0704 00:06:48.075786 185621 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 54.689133ms I0704 00:06:48.075790 185611 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 54.633847ms I0704 00:06:48.075881 185621 replica.cpp:712] Persisted action APPEND at position 8 I0704 00:06:48.075942 185611 replica.cpp:712] Persisted action APPEND at position 8 I0704 00:06:48.077258 185608 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 9 I0704 00:06:48.078404 185609 replica.cpp:541] Replica received write request for position 9 from __req_res__(1009)@172.17.0.2:39851 I0704 00:06:48.078578 185613 replica.cpp:541] Replica received write request for position 9 from __req_res__(1010)@172.17.0.2:39851 I0704 00:06:48.153628 185609 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 75.146713ms I0704 00:06:48.153631 185613 leveldb.cpp:390] Persisting action (17 bytes) to leveldb took 74.97729ms I0704 00:06:48.153723 185609 replica.cpp:712] Persisted action APPEND at position 9 I0704 00:06:48.153769 185613 replica.cpp:712] Persisted action APPEND at position 9 I0704 00:06:48.154673 185619 replica.cpp:695] Replica received learned notice for position 9 from log-network(47)@172.17.0.2:39851 I0704 00:06:48.154718 185602 replica.cpp:695] Replica received learned notice for position 9 from log-network(47)@172.17.0.2:39851 I0704 00:06:48.212706 185619 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 57.987644ms I0704 00:06:48.212725 185602 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 57.962344ms I0704 00:06:48.212813 185619 replica.cpp:712] Persisted action APPEND at position 9 I0704 00:06:48.212855 185602 replica.cpp:712] Persisted action APPEND at position 9 I0704 00:06:48.214217 185615 coordinator.cpp:348] Coordinator attempting to write APPEND action at position 10 I0704 00:06:48.215694 185607 replica.cpp:541] Replica received write request for position 10 from __req_res__(1011)@172.17.0.2:39851 I0704 00:06:48.215849 185605 replica.cpp:541] Replica received write request for position 10 from __req_res__(1012)@172.17.0.2:39851 I0704 00:06:48.285778 185607 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 70.014476ms I0704 00:06:48.285801 185605 leveldb.cpp:390] Persisting action (18 bytes) to leveldb took 69.873236ms I0704 00:06:48.285887 185607 replica.cpp:712] Persisted action APPEND at position 10 I0704 00:06:48.285943 185605 replica.cpp:712] Persisted action APPEND at position 10 I0704 00:06:48.286896 185617 replica.cpp:695] Replica received learned notice for position 10 from log-network(47)@172.17.0.2:39851 I0704 00:06:48.286922 185606 replica.cpp:695] Replica received learned notice for position 10 from log-network(47)@172.17.0.2:39851 I0704 00:06:48.347859 185617 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 60.920916ms I0704 00:06:48.347904 185606 leveldb.cpp:390] Persisting action (20 bytes) to leveldb took 60.920869ms I0704 00:06:48.347945 185617 replica.cpp:712] Persisted action APPEND at position 10 I0704 00:06:48.347990 185606 replica.cpp:712] Persisted action APPEND at position 10 I0704 00:06:48.628000 185598 leveldb.cpp:217] Opened db in 278.766368ms I0704 00:06:48.815292 185598 leveldb.cpp:224] Compacted db in 187.221636ms I0704 00:06:48.815456 185598 leveldb.cpp:239] Created db iterator in 91488ns I0704 00:06:48.815572 185598 leveldb.cpp:245] Seeked to beginning of db in 78725ns I0704 00:06:48.815707 185598 leveldb.cpp:320] Iterated through 1 keys in the db in 103547ns I0704 00:06:48.815831 185598 replica.cpp:795] Replica recovered with log positions 0 -> 0 with 1 holes and 0 unlearned I0704 00:06:48.817202 185602 recover.cpp:437] Starting replica recovery I0704 00:06:48.817762 185602 recover.cpp:468] Replica is in VOTING status I0704 00:06:48.818115 185602 recover.cpp:447] Recover process terminated I0704 00:06:48.818862 185606 catchup.cpp:342] Starting missing positions recovery I0704 00:06:48.819361 185606 catchup.cpp:368] Replica is in VOTING status I0704 00:06:48.821275 185599 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(1013)@172.17.0.2:39851 I0704 00:06:48.821420 185615 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(1014)@172.17.0.2:39851 I0704 00:06:48.821643 185607 replica.cpp:677] Replica in VOTING status received a broadcasted recover request from __req_res__(1015)@172.17.0.2:39851 I0704 00:06:48.822765 185614 recover.cpp:197] Received a recover response from a replica in VOTING status I0704 00:06:48.823398 185614 recover.cpp:197] Received a recover response from a replica in VOTING status I0704 00:06:48.824774 185608 catchup.cpp:423] Starting catch-up from position 0 to 9 I0704 00:06:48.827029 185619 replica.cpp:391] Replica received explicit promise request from __req_res__(1016)@172.17.0.2:39851 for position 0 with proposal 0 I0704 00:06:48.827234 185619 leveldb.cpp:510] Reading position from leveldb took 144847ns I0704 00:06:48.827257 185615 replica.cpp:391] Replica received explicit promise request from __req_res__(1017)@172.17.0.2:39851 for position 0 with proposal 0 I0704 00:06:48.827399 185615 leveldb.cpp:510] Reading position from leveldb took 83445ns I0704 00:06:48.827433 185603 replica.cpp:391] Replica received explicit promise request from __req_res__(1018)@172.17.0.2:39851 for position 0 with proposal 0 I0704 00:06:48.967446 185609 replica.cpp:391] Replica received explicit promise request from __req_res__(1019)@172.17.0.2:39851 for position 0 with proposal 3 I0704 00:06:48.967613 185604 replica.cpp:391] Replica received explicit promise request from __req_res__(1020)@172.17.0.2:39851 for position 0 with proposal 3 I0704 00:06:48.967649 185609 leveldb.cpp:510] Reading position from leveldb took 114531ns I0704 00:06:48.967792 185604 leveldb.cpp:510] Reading position from leveldb took 104895ns I0704 00:06:48.967824 185607 replica.cpp:391] Replica received explicit promise request from __req_res__(1021)@172.17.0.2:39851 for position 0 with proposal 3 I0704 00:06:49.055392 185609 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 87.631475ms I0704 00:06:49.055388 185607 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 87.485775ms I0704 00:06:49.055493 185609 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:49.055418 185604 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 87.560027ms I0704 00:06:49.055553 185607 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:49.055608 185604 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:49.056481 185611 replica.cpp:695] Replica received learned notice for position 0 from log-network(48)@172.17.0.2:39851 I0704 00:06:49.056488 185622 replica.cpp:695] Replica received learned notice for position 0 from log-network(48)@172.17.0.2:39851 I0704 00:06:49.056564 185600 replica.cpp:695] Replica received learned notice for position 0 from log-network(48)@172.17.0.2:39851 I0704 00:06:49.131038 185611 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 74.504097ms I0704 00:06:49.131052 185600 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 74.395019ms I0704 00:06:49.131131 185611 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:49.131057 185622 leveldb.cpp:390] Persisting action (16 bytes) to leveldb took 74.460891ms I0704 00:06:49.131213 185600 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:49.131270 185622 replica.cpp:712] Persisted action NOP at position 0 I0704 00:06:49.133414 185610 replica.cpp:391] Replica received explicit promise request from __req_res__(1022)@172.17.0.2:39851 for position 1 with proposal 3 I0704 00:06:49.133476 185607 replica.cpp:391] Replica received explicit promise request from __req_res__(1023)@172.17.0.2:39851 for position 1 with proposal 3 I0704 00:06:49.133606 185610 leveldb.cpp:510] Reading position from leveldb took 119894ns I0704 00:06:49.133620 185607 leveldb.cpp:510] Reading position from leveldb took 88875ns I0704 00:06:49.133834 185618 replica.cpp:391] Replica received explicit promise request from __req_res__(1024)@172.17.0.2:39851 for position 1 with proposal 3 I0704 00:06:49.224112 185618 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 90.22789ms I0704 00:06:49.224112 185610 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 90.414086ms I0704 00:06:49.224112 185607 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 90.376867ms I0704 00:06:49.224215 185618 replica.cpp:712] Persisted action NOP at position 1 I0704 00:06:49.224323 185607 replica.cpp:712] Persisted action APPEND at position 1 I0704 00:06:49.224282 185610 replica.cpp:712] Persisted action APPEND at position 1 I0704 00:06:49.225281 185610 replica.cpp:695] Replica received learned notice for position 1 from log-network(48)@172.17.0.2:39851 I0704 00:06:49.225329 185620 replica.cpp:695] Replica received learned notice for position 1 from log-network(48)@172.17.0.2:39851 I0704 00:06:49.225340 185602 replica.cpp:695] Replica received learned notice for position 1 from log-network(48)@172.17.0.2:39851 I0704 00:06:49.291253 185620 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 65.871561ms I0704 00:06:49.291266 185610 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 65.941816ms I0704 00:06:49.291345 185620 replica.cpp:712] Persisted action APPEND at position 1 I0704 00:06:49.291268 185602 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 65.843395ms I0704 00:06:49.291393 185610 replica.cpp:712] Persisted action APPEND at position 1 I0704 00:06:49.291462 185602 replica.cpp:712] Persisted action APPEND at position 1 I0704 00:06:49.293655 185605 replica.cpp:391] Replica received explicit promise request from __req_res__(1025)@172.17.0.2:39851 for position 2 with proposal 3 I0704 00:06:49.293808 185605 leveldb.cpp:510] Reading position from leveldb took 94988ns I0704 00:06:49.293912 185601 replica.cpp:391] Replica received explicit promise request from __req_res__(1026)@172.17.0.2:39851 for position 2 with proposal 3 I0704 00:06:49.294078 185601 leveldb.cpp:510] Reading position from leveldb took 109698ns I0704 00:06:49.294081 185612 replica.cpp:391] Replica received explicit promise request from __req_res__(1027)@172.17.0.2:39851 for position 2 with proposal 3 I0704 00:06:49.375160 185612 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 80.975934ms I0704 00:06:49.375208 185605 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 81.327674ms I0704 00:06:49.375237 185612 replica.cpp:712] Persisted action NOP at position 2 I0704 00:06:49.375219 185601 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 81.056455ms I0704 00:06:49.375291 185605 replica.cpp:712] Persisted action APPEND at position 2 I0704 00:06:49.375334 185601 replica.cpp:712] Persisted action APPEND at position 2 I0704 00:06:49.376204 185615 replica.cpp:695] Replica received learned notice for position 2 from log-network(48)@172.17.0.2:39851 I0704 00:06:49.376276 185616 replica.cpp:695] Replica received learned notice for position 2 from log-network(48)@172.17.0.2:39851 I0704 00:06:49.376322 185613 replica.cpp:695] Replica received learned notice for position 2 from log-network(48)@172.17.0.2:39851 I0704 00:06:49.493288 185613 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 116.910384ms I0704 00:06:49.493289 185616 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 116.972532ms I0704 00:06:49.493388 185613 replica.cpp:712] Persisted action APPEND at position 2 I0704 00:06:49.493292 185615 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 117.029934ms I0704 00:06:49.493434 185616 replica.cpp:712] Persisted action APPEND at position 2 I0704 00:06:49.493484 185615 replica.cpp:712] Persisted action APPEND at position 2 I0704 00:06:49.495834 185610 replica.cpp:391] Replica received explicit promise request from __req_res__(1028)@172.17.0.2:39851 for position 3 with proposal 3 I0704 00:06:49.495940 185608 replica.cpp:391] Replica received explicit promise request from __req_res__(1029)@172.17.0.2:39851 for position 3 with proposal 3 I0704 00:06:49.496028 185610 leveldb.cpp:510] Reading position from leveldb took 123737ns I0704 00:06:49.496090 185608 leveldb.cpp:510] Reading position from leveldb took 91725ns I0704 00:06:49.496266 185611 replica.cpp:391] Replica received explicit promise request from __req_res__(1030)@172.17.0.2:39851 for position 3 with proposal 3 I0704 00:06:49.552258 185611 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 55.920866ms I0704 00:06:49.552258 185608 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 56.108792ms I0704 00:06:49.552354 185611 replica.cpp:712] Persisted action NOP at position 3 I0704 00:06:49.552270 185610 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 56.137398ms I0704 00:06:49.552404 185608 replica.cpp:712] Persisted action APPEND at position 3 I0704 00:06:49.552454 185610 replica.cpp:712] Persisted action APPEND at position 3 I0704 00:06:49.553627 185612 replica.cpp:695] Replica received learned notice for position 3 from log-network(48)@172.17.0.2:39851 I0704 00:06:49.553715 185601 replica.cpp:695] Replica received learned notice for position 3 from log-network(48)@172.17.0.2:39851 I0704 00:06:49.553766 185621 replica.cpp:695] Replica received learned notice for position 3 from log-network(48)@172.17.0.2:39851 I0704 00:06:49.643359 185601 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 89.596652ms I0704 00:06:49.643393 185612 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 89.719832ms I0704 00:06:49.643445 185601 replica.cpp:712] Persisted action APPEND at position 3 I0704 00:06:49.643476 185612 replica.cpp:712] Persisted action APPEND at position 3 I0704 00:06:49.643469 185621 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 89.617738ms I0704 00:06:49.643651 185621 replica.cpp:712] Persisted action APPEND at position 3 I0704 00:06:49.645467 185616 replica.cpp:391] Replica received explicit promise request from __req_res__(1031)@172.17.0.2:39851 for position 4 with proposal 3 I0704 00:06:49.645612 185616 leveldb.cpp:510] Reading position from leveldb took 91121ns I0704 00:06:49.645697 185605 replica.cpp:391] Replica received explicit promise request from __req_res__(1032)@172.17.0.2:39851 for position 4 with proposal 3 I0704 00:06:49.645865 185605 leveldb.cpp:510] Reading position from leveldb took 105918ns I0704 00:06:49.645882 185600 replica.cpp:391] Replica received explicit promise request from __req_res__(1033)@172.17.0.2:39851 for position 4 with proposal 3 I0704 00:06:49.744675 185616 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 98.998391ms I0704 00:06:49.744707 185600 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 98.750384ms I0704 00:06:49.744760 185616 replica.cpp:712] Persisted action APPEND at position 4 I0704 00:06:49.744720 185605 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 98.7596ms I0704 00:06:49.744796 185600 replica.cpp:712] Persisted action NOP at position 4 I0704 00:06:49.744865 185605 replica.cpp:712] Persisted action APPEND at position 4 I0704 00:06:49.745496 185616 replica.cpp:695] Replica received learned notice for position 4 from log-network(48)@172.17.0.2:39851 I0704 00:06:49.745519 185607 replica.cpp:695] Replica received learned notice for position 4 from log-network(48)@172.17.0.2:39851 I0704 00:06:49.745594 185613 replica.cpp:695] Replica received learned notice for position 4 from log-network(48)@172.17.0.2:39851 I0704 00:06:49.817004 185613 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 71.363206ms I0704 00:06:49.817018 185616 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 71.46878ms I0704 00:06:49.817018 185607 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 71.419788ms I0704 00:06:49.817097 185613 replica.cpp:712] Persisted action APPEND at position 4 I0704 00:06:49.817198 185607 replica.cpp:712] Persisted action APPEND at position 4 I0704 00:06:49.817157 185616 replica.cpp:712] Persisted action APPEND at position 4 I0704 00:06:49.819144 185602 replica.cpp:391] Replica received explicit promise request from __req_res__(1034)@172.17.0.2:39851 for position 5 with proposal 3 I0704 00:06:49.819308 185601 replica.cpp:391] Replica received explicit promise request from __req_res__(1035)@172.17.0.2:39851 for position 5 with proposal 3 I0704 00:06:49.819325 185602 leveldb.cpp:510] Reading position from leveldb took 94238ns I0704 00:06:49.819463 185601 leveldb.cpp:510] Reading position from leveldb took 89462ns I0704 00:06:49.819697 185611 replica.cpp:391] Replica received explicit promise request from __req_res__(1036)@172.17.0.2:39851 for position 5 with proposal 3 I0704 00:06:49.893527 185602 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 74.081534ms I0704 00:06:49.893563 185611 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 73.810446ms I0704 00:06:49.893617 185602 replica.cpp:712] Persisted action APPEND at position 5 I0704 00:06:49.893568 185601 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 74.040267ms I0704 00:06:49.893651 185611 replica.cpp:712] Persisted action NOP at position 5 I0704 00:06:49.893726 185601 replica.cpp:712] Persisted action APPEND at position 5 I0704 00:06:49.894626 185619 replica.cpp:695] Replica received learned notice for position 5 from log-network(48)@172.17.0.2:39851 I0704 00:06:49.894704 185615 replica.cpp:695] Replica received learned notice for position 5 from log-network(48)@172.17.0.2:39851 I0704 00:06:49.894714 185620 replica.cpp:695] Replica received learned notice for position 5 from log-network(48)@172.17.0.2:39851 I0704 00:06:49.976379 185620 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 81.563522ms I0704 00:06:49.976399 185619 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 81.716992ms I0704 00:06:49.976469 185620 replica.cpp:712] Persisted action APPEND at position 5 I0704 00:06:49.976399 185615 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 81.649949ms I0704 00:06:49.976518 185619 replica.cpp:712] Persisted action APPEND at position 5 I0704 00:06:49.976558 185615 replica.cpp:712] Persisted action APPEND at position 5 I0704 00:06:49.978466 185606 replica.cpp:391] Replica received explicit promise request from __req_res__(1037)@172.17.0.2:39851 for position 6 with proposal 3 I0704 00:06:49.978621 185604 replica.cpp:391] Replica received explicit promise request from __req_res__(1038)@172.17.0.2:39851 for position 6 with proposal 3 I0704 00:06:49.978641 185606 leveldb.cpp:510] Reading position from leveldb took 109561ns I0704 00:06:49.978801 185604 leveldb.cpp:510] Reading position from leveldb took 111558ns I0704 00:06:49.978857 185617 replica.cpp:391] Replica received explicit promise request from __req_res__(1039)@172.17.0.2:39851 for position 6 with proposal 3 I0704 00:06:50.063827 185617 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 84.904845ms I0704 00:06:50.063867 185606 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 85.086861ms I0704 00:06:50.063867 185604 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 84.969913ms I0704 00:06:50.063911 185617 replica.cpp:712] Persisted action NOP at position 6 I0704 00:06:50.064025 185604 replica.cpp:712] Persisted action APPEND at position 6 I0704 00:06:50.063984 185606 replica.cpp:712] Persisted action APPEND at position 6 I0704 00:06:50.064945 185612 replica.cpp:695] Replica received learned notice for position 6 from log-network(48)@172.17.0.2:39851 I0704 00:06:50.064982 185609 replica.cpp:695] Replica received learned notice for position 6 from log-network(48)@172.17.0.2:39851 I0704 00:06:50.065026 185610 replica.cpp:695] Replica received learned notice for position 6 from log-network(48)@172.17.0.2:39851 I0704 00:06:50.148463 185612 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 83.45485ms I0704 00:06:50.148464 185609 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 83.414361ms I0704 00:06:50.148555 185612 replica.cpp:712] Persisted action APPEND at position 6 I0704 00:06:50.148475 185610 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 83.391508ms I0704 00:06:50.148604 185609 replica.cpp:712] Persisted action APPEND at position 6 I0704 00:06:50.148646 185610 replica.cpp:712] Persisted action APPEND at position 6 I0704 00:06:50.150724 185599 replica.cpp:391] Replica received explicit promise request from __req_res__(1040)@172.17.0.2:39851 for position 7 with proposal 3 I0704 00:06:50.150890 185599 leveldb.cpp:510] Reading position from leveldb took 104805ns I0704 00:06:50.150880 185604 replica.cpp:391] Replica received explicit promise request from __req_res__(1041)@172.17.0.2:39851 for position 7 with proposal 3 I0704 00:06:50.151068 185617 replica.cpp:391] Replica received explicit promise request from __req_res__(1042)@172.17.0.2:39851 for position 7 with proposal 3 I0704 00:06:50.151093 185604 leveldb.cpp:510] Reading position from leveldb took 106437ns I0704 00:06:50.223574 185617 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 72.430746ms I0704 00:06:50.223625 185604 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 72.356605ms I0704 00:06:50.223625 185599 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 72.634605ms I0704 00:06:50.223661 185617 replica.cpp:712] Persisted action NOP at position 7 I0704 00:06:50.223780 185599 replica.cpp:712] Persisted action APPEND at position 7 I0704 00:06:50.223742 185604 replica.cpp:712] Persisted action APPEND at position 7 I0704 00:06:50.224656 185605 replica.cpp:695] Replica received learned notice for position 7 from log-network(48)@172.17.0.2:39851 I0704 00:06:50.224689 185622 replica.cpp:695] Replica received learned notice for position 7 from log-network(48)@172.17.0.2:39851 I0704 00:06:50.224754 185600 replica.cpp:695] Replica received learned notice for position 7 from log-network(48)@172.17.0.2:39851 I0704 00:06:50.353884 185622 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 129.143258ms I0704 00:06:50.353884 185605 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 129.210767ms I0704 00:06:50.353884 185600 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 129.126145ms I0704 00:06:50.354029 185622 replica.cpp:712] Persisted action APPEND at position 7 I0704 00:06:50.354110 185600 replica.cpp:712] Persisted action APPEND at position 7 I0704 00:06:50.354075 185605 replica.cpp:712] Persisted action APPEND at position 7 I0704 00:06:50.356540 185617 replica.cpp:391] Replica received explicit promise request from __req_res__(1043)@172.17.0.2:39851 for position 8 with proposal 3 I0704 00:06:50.356655 185609 replica.cpp:391] Replica received explicit promise request from __req_res__(1044)@172.17.0.2:39851 for position 8 with proposal 3 I0704 00:06:50.356729 185617 leveldb.cpp:510] Reading position from leveldb took 120367ns I0704 00:06:50.356833 185609 leveldb.cpp:510] Reading position from leveldb took 111461ns I0704 00:06:50.356912 185613 replica.cpp:391] Replica received explicit promise request from __req_res__(1045)@172.17.0.2:39851 for position 8 with proposal 3 I0704 00:06:50.508788 185609 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 151.856495ms I0704 00:06:50.508802 185617 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 151.990838ms I0704 00:06:50.508884 185609 replica.cpp:712] Persisted action APPEND at position 8 I0704 00:06:50.508803 185613 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 151.834742ms I0704 00:06:50.508950 185617 replica.cpp:712] Persisted action APPEND at position 8 I0704 00:06:50.508982 185613 replica.cpp:712] Persisted action NOP at position 8 I0704 00:06:50.509778 185605 replica.cpp:695] Replica received learned notice for position 8 from log-network(48)@172.17.0.2:39851 I0704 00:06:50.509832 185618 replica.cpp:695] Replica received learned notice for position 8 from log-network(48)@172.17.0.2:39851 I0704 00:06:50.509840 185607 replica.cpp:695] Replica received learned notice for position 8 from log-network(48)@172.17.0.2:39851 I0704 00:06:50.600893 185618 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 91.021723ms I0704 00:06:50.600893 185607 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 90.943582ms I0704 00:06:50.600987 185618 replica.cpp:712] Persisted action APPEND at position 8 I0704 00:06:50.601040 185607 replica.cpp:712] Persisted action APPEND at position 8 I0704 00:06:50.600896 185605 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 91.073859ms I0704 00:06:50.601147 185605 replica.cpp:712] Persisted action APPEND at position 8 I0704 00:06:50.602968 185621 replica.cpp:391] Replica received explicit promise request from __req_res__(1046)@172.17.0.2:39851 for position 9 with proposal 3 I0704 00:06:50.603073 185609 replica.cpp:391] Replica received explicit promise request from __req_res__(1047)@172.17.0.2:39851 for position 9 with proposal 3 I0704 00:06:50.603147 185621 leveldb.cpp:510] Reading position from leveldb took 122687ns I0704 00:06:50.603261 185609 leveldb.cpp:510] Reading position from leveldb took 134181ns I0704 00:06:50.603308 185622 replica.cpp:391] Replica received explicit promise request from __req_res__(1048)@172.17.0.2:39851 for position 9 with proposal 3 I0704 00:06:50.668253 185622 leveldb.cpp:390] Persisting action (8 bytes) to leveldb took 64.907685ms I0704 00:06:50.668253 185609 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 64.921088ms I0704 00:06:50.668361 185622 replica.cpp:712] Persisted action NOP at position 9 I0704 00:06:50.668255 185621 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 65.012436ms I0704 00:06:50.668417 185609 replica.cpp:712] Persisted action APPEND at position 9 I0704 00:06:50.668469 185621 replica.cpp:712] Persisted action APPEND at position 9 I0704 00:06:50.669296 185620 replica.cpp:695] Replica received learned notice for position 9 from log-network(48)@172.17.0.2:39851 I0704 00:06:50.669296 185604 replica.cpp:695] Replica received learned notice for position 9 from log-network(48)@172.17.0.2:39851 I0704 00:06:50.669384 185606 replica.cpp:695] Replica received learned notice for position 9 from log-network(48)@172.17.0.2:39851 I0704 00:06:50.751529 185606 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 82.089099ms I0704 00:06:50.751536 185620 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 82.182791ms I0704 00:06:50.751634 185606 replica.cpp:712] Persisted action APPEND at position 9 I0704 00:06:50.751536 185604 leveldb.cpp:390] Persisting action (19 bytes) to leveldb took 82.134072ms I0704 00:06:50.751685 185620 replica.cpp:712] Persisted action APPEND at position 9 I0704 00:06:50.751766 185604 replica.cpp:712] Persisted action APPEND at position 9 I0704 00:06:50.752774 185603 catchup.cpp:357] Recover process terminated I0704 00:06:50.755455 185614 leveldb.cpp:510] Reading position from leveldb took 105541ns I0704 00:06:50.755673 185614 leveldb.cpp:510] Reading position from leveldb took 97415ns I0704 00:06:50.755879 185614 leveldb.cpp:510] Reading position from leveldb took 94208ns I0704 00:06:50.756068 185614 leveldb.cpp:510] Reading position from leveldb took 82062ns I0704 00:06:50.756254 185614 leveldb.cpp:510] Reading position from leveldb took 81012ns I0704 00:06:50.756438 185614 leveldb.cpp:510] Reading position from leveldb took 79798ns I0704 00:06:50.756625 185614 leveldb.cpp:510] Reading position from leveldb took 80419ns I0704 00:06:50.756820 185614 leveldb.cpp:510] Reading position from leveldb took 91565ns I0704 00:06:50.757007 185614 leveldb.cpp:510] Reading position from leveldb took 80511ns I0704 00:06:50.757194 185614 leveldb.cpp:510] Reading position from leveldb took 79398ns [ OK ] LogTest.ReaderCatchup (9246 ms) [----------] 4 tests from LogTest (14818 ms total) [----------] 2 tests from LogZooKeeperTest I0704 00:06:50.765290 185598 zookeeper.cpp:82] Using Java classpath: -Djava.class.path=/tmp/SRC/build/mesos-1.12.0/_build/sub/3rdparty/zookeeper-3.4.8/zookeeper-3.4.8.jar:/tmp/SRC/build/mesos-1.12.0/_build/sub/3rdparty/zookeeper-3.4.8/lib/log4j-1.2.16.jar:/tmp/SRC/build/mesos-1.12.0/_build/sub/3rdparty/zookeeper-3.4.8/lib/jline-0.9.94.jar:/tmp/SRC/build/mesos-1.12.0/_build/sub/3rdparty/zookeeper-3.4.8/lib/slf4j-log4j12-1.6.1.jar:/tmp/SRC/build/mesos-1.12.0/_build/sub/3rdparty/zookeeper-3.4.8/lib/netty-3.7.0.Final.jar:/tmp/SRC/build/mesos-1.12.0/_build/sub/3rdparty/zookeeper-3.4.8/lib/slf4j-api-1.6.1.jar [ RUN ] LogZooKeeperTest.WriteRead I0704 00:06:50.856209 185598 jvm.cpp:590] Looking up method <init>(Ljava/lang/String;)V I0704 00:06:50.856491 185598 jvm.cpp:590] Looking up method deleteOnExit()V I0704 00:06:50.857384 185598 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. I0704 00:06:51.018013 185598 jvm.cpp:590] Looking up method <init>()V I0704 00:06:51.018975 185598 jvm.cpp:590] Looking up method <init>(Lorg/apache/zookeeper/server/persistence/FileTxnSnapLog;Lorg/apache/zookeeper/server/ZooKeeperServer$DataTreeBuilder;)V *** Aborted at 1720051611 (unix time) try "date -d @1720051611" if you are using GNU date *** PC: @ 0x7fa02b096ccd OopStorage::Block::release_entries() *** SIGSEGV (@0x238) received by PID 185598 (TID 0x7fa09d8e8b40) from PID 568; stack trace: *** @ 0x7fa02b0a5929 os::Linux::chained_handler() @ 0x7fa02b0ab63b JVM_handle_linux_signal @ 0x7fa02b09e1dc signalHandler() @ 0x7fa09ef3b420 (unknown) @ 0x7fa02b096ccd OopStorage::Block::release_entries() @ 0x7fa02b096f26 OopStorage::release() @ 0x7fa02ad99b21 jni_DeleteGlobalRef @ 0x7fa0ae6f0044 JNIEnv_::DeleteGlobalRef() @ 0x7fa0ae6ee18c Jvm::deleteGlobalRef() @ 0x558965adf628 Jvm::Object::~Object() @ 0x558965ae444e org::apache::zookeeper::server::ZooKeeperServer::DataTreeBuilder::~DataTreeBuilder() @ 0x558965ae6d52 org::apache::zookeeper::server::ZooKeeperServer::BasicDataTreeBuilder::~BasicDataTreeBuilder() @ 0x558965ae2d6d mesos::internal::tests::ZooKeeperTestServer::ZooKeeperTestServer() @ 0x558964487fcc mesos::internal::tests::ZooKeeperTest::ZooKeeperTest() @ 0x55896448a315 mesos::internal::tests::LogZooKeeperTest::LogZooKeeperTest() @ 0x55896448a426 mesos::internal::tests::LogZooKeeperTest_WriteRead_Test::LogZooKeeperTest_WriteRead_Test() @ 0x5589644f5328 testing::internal::TestFactoryImpl<>::CreateTest() @ 0x558965b295fa testing::internal::HandleSehExceptionsInMethodIfSupported<>() @ 0x558965b22bcb testing::internal::HandleExceptionsInMethodIfSupported<>() @ 0x558965afee03 testing::TestInfo::Run() @ 0x558965aff50b testing::TestCase::Run() @ 0x558965b068a5 testing::internal::UnitTestImpl::RunAllTests() @ 0x558965b2a828 testing::internal::HandleSehExceptionsInMethodIfSupported<>() @ 0x558965b23731 testing::internal::HandleExceptionsInMethodIfSupported<>() @ 0x558965b053bd testing::UnitTest::Run() @ 0x558964512edb RUN_ALL_TESTS() @ 0x5589645128a2 main @ 0x7fa09ed59083 __libc_start_main @ 0x55896355875e _start make[4]: *** [Makefile:18022: check-local] Segmentation fault (core dumped) make[4]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub/src' make[3]: *** [Makefile:15951: check-am] Error 2 make[3]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub/src' make[2]: *** [Makefile:15954: check] Error 2 make[2]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub/src' make[1]: *** [Makefile:785: check-recursive] Error 1 make[1]: Leaving directory '/tmp/SRC/build/mesos-1.12.0/_build/sub' I0704 00:06:53.353088 186637 exec.cpp:560] Agent exited ... shutting down make: *** [Makefile:999: distcheck] Error 1 I0704 00:06:53.354125 186641 executor.cpp:190] Received SHUTDOWN event I0704 00:06:53.354178 186641 executor.cpp:843] Shutting down I0704 00:06:53.354236 186641 executor.cpp:956] Sending SIGTERM to process tree at pid 186656 + copy_out_test_reports + find /tmp/SRC -name '*-tests.xml' -exec cp '{}' /SRC ';' I0704 00:06:53.366303 186641 executor.cpp:969] Sent SIGTERM to the following process trees: [ -+- 186656 sh -c dd if=/dev/zero of=volume_path/file bs=1048576 count=2 && sleep 1000 \--- 186666 sleep 1000 ] I0704 00:06:53.366343 186641 executor.cpp:973] Scheduling escalation to SIGKILL in 3secs from now I0704 00:06:53.427820 186643 executor.cpp:1041] Command terminated with signal Terminated (pid: 186656) W0704 00:06:53.430588 186651 process.cpp:1917] Failed to send 'mesos.internal.StatusUpdateMessage' to '172.17.0.2:39851', connect: Failed to connect to 172.17.0.2:39851: Connection refused I0704 00:06:54.432015 186651 process.cpp:935] Stopped the socket accept loop Untagged: mesos/mesos-build:ubuntu-20.04 Untagged: mesos/mesos-build@sha256:2d3cd7fed451697aba1a3103754b4a46b6a7cad64e8229fb65e5a31e6d4b413d Deleted: sha256:b978a6177f864ec24c8ab237b612c3e5e780d94875752c63681edd80d9a85bbd Deleted: sha256:3ce262d459956fd117307a4cccbe593d59a11fce0e9138bee98d634f3a536bd0 Deleted: sha256:93be824b42681ee74b5ef869b75fb8b4fc0f234ec2135b764d235bb863a722e1 Deleted: sha256:eca0ccc3c9322d20f126a1a390efe2f6862fef535a41044bdb68c492f0dd9392 Deleted: sha256:8ed5c7c631df3c9d418a68532b4957d8c8dbadc69ad70564f6fa45e4748f6957 Deleted: sha256:6988969997d24e5f91cf313970ab25e046d637808cc0d77b19de4fc385e6a0db Deleted: sha256:9a7bfb2ba9f4a5cc05f561ed15dcd86232976d79616d817df9d323b45b4407ca Deleted: sha256:92c98c8577076f502769040fce0770d08a5a5c5d41989fa70986df7b3962a293 Full log: https://ci-builds.apache.org/job/Mesos/job/Mesos-Reviewbot/33290/console - Mesos Reviewbot On May 28, 2024, 9:20 p.m., Jason Zhou wrote: > > ----------------------------------------------------------- > This is an automatically generated e-mail. To reply, visit: > https://reviews.apache.org/r/75016/ > ----------------------------------------------------------- > > (Updated May 28, 2024, 9:20 p.m.) > > > Review request for mesos and Benjamin Mahler. > > > Repository: mesos > > > Description > ------- > > Passes the device manager to the cgroups2 isolator on > containerizer startup, and sets up the ability for the > manager to be passed to the device controller and GPU isolator > > > Diffs > ----- > > src/slave/containerizer/containerizer.hpp > 691fdfe295850bce1302b4adde127d551f821b89 > src/slave/containerizer/containerizer.cpp > ba3ab43b0d56c6dabd141e40ac706568dccd72f1 > src/slave/containerizer/mesos/containerizer.hpp > 62174dfd056e1d7cc465ebdb29343bdd04de6a10 > src/slave/containerizer/mesos/containerizer.cpp > f7ff6b8e56e80881ac89ba650b7aa4f4eec3484b > src/slave/containerizer/mesos/isolators/cgroups2/cgroups2.hpp > e193f3f1f0dab753b394c409e422aa81097a64b7 > src/slave/containerizer/mesos/isolators/cgroups2/cgroups2.cpp > 2ca3880790be0cd092ec05a359711e2d8e641314 > src/slave/main.cpp 21b8ea74a502478fb73510a7d49bb5f28506ce8d > > > Diff: https://reviews.apache.org/r/75016/diff/3/ > > > Testing > ------- > > > Thanks, > > Jason Zhou > >
