Skip to content
This repository has been archived by the owner on Aug 2, 2023. It is now read-only.

xjson-server: Clustered mode causes errors #1091

Open
AndrewGorton opened this issue Jan 22, 2016 · 8 comments
Open

xjson-server: Clustered mode causes errors #1091

AndrewGorton opened this issue Jan 22, 2016 · 8 comments
Assignees
@pphaneuf
Milestone
production

Comments

@AndrewGorton
Copy link

xjson-server still unhappy running in clustered mode.

I run three nodes with

$ xjson-server \
        --port=8080 \
        --tree_signing_frequency_seconds=30 \
        --guard_window_seconds=10 \
        --leveldb_db=/data/log.ldb \
        --etcd_servers="$ETCD_ALL" \
        --etcd_delete_concurrency=100 \
        --num_http_server_threads=32 \
        --key=ct.key &

I then post data to the first node with

$ curl -X POST -d '{ "a" : "b" }' localhost:8080/ct/v1/add-json

and the 2nd and third nodes eventually coredump. Top of node2 logfile is:-

$ tail -f /tmp/xjson-server.INFO
Log file created at: 2016/01/22 11:48:59
Running on machine: 9d5c8cfa65f7
Log line format: [IWEF]mmdd hh:mm:ss.uuuuuu threadid file:line] msg
I0122 11:48:59.767704    16 init.cc:71] Build version: 2016-01-14-250672b5aef3666edbdfc9a75b95a09e7a57ed08
tail: unrecognized file system type 0x794c7630 for '/tmp/xjson-server.INFO'. please report this to bug-coreutils@gnu.org. reverting to polling
I0122 11:48:59.768297    16 init.cc:73] Binary built with hardening enabled.
I0122 11:48:59.768652    16 leveldb_db.cc:131] Opening /data/log.ldb
I0122 11:48:59.793521    16 thread_pool.cc:146] ThreadPool starting with 8 threads
W0122 11:48:59.794241    16 connection_pool.cc:257] Setting client minimum TLS protocol to tlsv12
I0122 11:48:59.794584    16 connection_pool.cc:289] Loading openssl default trusted root certificates...
I0122 11:48:59.806995    16 xjson-server.cc:116] Running in CLUSTERED mode.
I0122 11:48:59.807114    16 thread_pool.cc:146] ThreadPool starting with 32 threads
I0122 11:48:59.808822    16 server.cc:99] Initializing Node DB with UUID: 55f8ff76-3eee-4c87-9d08-bba8969cd73a
I0122 11:48:59.812978    20 etcd.cc:1034] Etcd version: {"etcdserver":"2.2.0","etcdcluster":"2.2.0"}
I0122 11:48:59.855008    19 cluster_state_controller-inl.h:322] Received new ClusterConfig:
minimum_serving_nodes: 2
minimum_serving_fraction: 0.75
W0122 11:48:59.855945    19 cluster_state_controller-inl.h:495] Failed to determine suitable serving STH.
W0122 11:48:59.856338    23 cluster_state_controller-inl.h:495] Failed to determine suitable serving STH.
I0122 11:48:59.856498    21 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\305\364\007\021=q\327\312\016=\253\221\"\'\253\204DI\177k\002\262p\'\326#A\021k\200\3015" } timestamp: 1453463197007 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0F\002!\000\256i\344$^\270.\000\305^k\211\326\263\257\313\343\222\353\271\257\004\367\027\374\330a\325\202\350\337\'\002!\000\303p_\223\304\234\244\253\202<v\262\004\003\253\273\027\332\306\330\'\262X\221\006T\t\360\311 q\342" }
W0122 11:48:59.856618    21 cluster_state_controller-inl.h:382] Local DB doesn't have any STH, new node?
I0122 11:48:59.865228    21 log_lookup.cc:105] Found 0 new log entries
I0122 11:48:59.865248    21 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 11:46:37 2016
W0122 11:48:59.882787    18 cluster_state_controller-inl.h:495] Failed to determine suitable serving STH.
W0122 11:48:59.883651    17 cluster_state_controller-inl.h:495] Failed to determine suitable serving STH.
I0122 11:48:59.907912    20 cluster_state_controller-inl.h:477] Can serve @0 with 2 nodes (100% of cluster)
I0122 11:48:59.927569    18 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\305\364\007\021=q\327\312\016=\253\221\"\'\253\204DI\177k\002\262p\'\326#A\021k\200\3015" } timestamp: 1453463339883 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0D\002 l\002M\231\241\262\224v\022t\242\341\215Id\371\331x\340\267\3577\032\366E \340i\364\014\241\030\002 F\n\364\204\304\350\305\326\321\177\310w\236\253\336A\325\346\260\201\027^\330\324\002\315>d\260~\326}" }
I0122 11:48:59.933338    18 log_lookup.cc:105] Found 0 new log entries
I0122 11:48:59.933360    18 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 11:48:59 2016
I0122 11:49:18.837689    23 cluster_state_controller-inl.h:477] Can serve @0 with 2 nodes (100% of cluster)
I0122 11:49:18.863029    23 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\305\364\007\021=q\327\312\016=\253\221\"\'\253\204DI\177k\002\262p\'\326#A\021k\200\3015" } timestamp: 1453463358815 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0D\002 )\362v\331\347O\0258\262\202;\336\201\031\357\353\371\246\2328\203y\017:v\203-i\353\232\340A\002 (\254r\001\200Y;M\311\304#$+\346\212\n)\'p\267\033\257_\321\020\251\375mgT\256\326" }
I0122 11:49:18.880853    23 log_lookup.cc:105] Found 0 new log entries
I0122 11:49:18.880867    23 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 11:49:18 2016
W0122 11:49:24.681349    19 cluster_state_controller-inl.h:495] Failed to determine suitable serving STH.
W0122 11:49:24.702924    24 cluster_state_controller-inl.h:495] Failed to determine suitable serving STH.
I0122 11:49:24.723665    17 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 11:49:24.738621    17 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\305\364\007\021=q\327\312\016=\253\221\"\'\253\204DI\177k\002\262p\'\326#A\021k\200\3015" } timestamp: 1453463364698 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0F\002!\000\277\030O\305\375\306\037\016XZ\261\014\370\330L\001u\323\230\t2\243\371~\351#\3349\263:\037\307\002!\000\3563\362\262\\\251\375Md[v\355\217\2307\320\260\262\343U|\353B\312\325\226\031#\355\n\353\033" }
I0122 11:49:24.744542    17 log_lookup.cc:105] Found 0 new log entries
I0122 11:49:24.744562    17 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 11:49:24 2016
I0122 11:49:29.897878    22 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 11:49:29.913183    17 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\305\364\007\021=q\327\312\016=\253\221\"\'\253\204DI\177k\002\262p\'\326#A\021k\200\3015" } timestamp: 1453463369883 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0D\002 \025\024\304Mi\345p\233\377XWF\215\035\257\316V\244@\213BZ\250\377\022e\365\223\223\027\003\254\002 ay1a\345\3408r\342\312\322;]\211\351i\366e{r\252b\201\023M\0356!|\366\215B" }
I0122 11:49:29.919925    17 log_lookup.cc:105] Found 0 new log entries
I0122 11:49:29.919946    17 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 11:49:29 2016
I0122 11:49:48.838886    21 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 11:49:48.865428    21 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\305\364\007\021=q\327\312\016=\253\221\"\'\253\204DI\177k\002\262p\'\326#A\021k\200\3015" } timestamp: 1453463388816 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0F\002!\000\235\376{u\350\256\023\217P\226\274\2735\246\2410\234\234)\235\240+\274\301\310\306\356\300\033z\232\010\002!\000\225\000m\225\004\324MIb\354a7\331\0201\243W\343#\272\271\312\361P{\241\230\'\254\020\222\327" }
I0122 11:49:48.869974    21 log_lookup.cc:105] Found 0 new log entries
I0122 11:49:48.869988    21 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 11:49:48 2016
I0122 11:49:54.718438    17 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 11:49:54.734836    17 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\305\364\007\021=q\327\312\016=\253\221\"\'\253\204DI\177k\002\262p\'\326#A\021k\200\3015" } timestamp: 1453463394698 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0E\002 A\344\356\027Y(=\2279\203\304\311\260\220Y\373\3237\202L1 \260\177\252\274Q\376|w\313Z\002!\000\317\335(\343\235\233\347\232\027e\345\343\006uu\\!\\\305\233\311\254DXv\334\244\204\370`\361w" }
I0122 11:49:54.741317    17 log_lookup.cc:105] Found 0 new log entries
I0122 11:49:54.741333    17 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 11:49:54 2016
W0122 11:49:59.834594    16 connection_pool.cc:335] Releasing errored connection to ip-172-20-10-143.eu-west-1.compute.internal:4001
W0122 11:49:59.834717    16 connection_pool.cc:360] error flag (0x41): READING TIMEOUT : Success
W0122 11:49:59.857952    16 connection_pool.cc:335] Releasing errored connection to ip-172-20-10-143.eu-west-1.compute.internal:4001
W0122 11:49:59.857986    16 connection_pool.cc:360] error flag (0x41): READING TIMEOUT : Resource temporarily unavailable
I0122 11:49:59.898356    23 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 11:49:59.914801    24 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\305\364\007\021=q\327\312\016=\253\221\"\'\253\204DI\177k\002\262p\'\326#A\021k\200\3015" } timestamp: 1453463399883 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0F\002!\000\323I9*\374\263\261\265Th\375\256\005G\233\353a\211\00152v\336\3371\333\211.\240\346\244]\002!\000\375:\306\216\251#\260\237\363\233B\243\234\\F\223\211\2315\342\005n\000\246S\247{\327\325\242\336y" }
I0122 11:49:59.925294    24 log_lookup.cc:105] Found 0 new log entries
I0122 11:49:59.925307    24 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 11:49:59 2016
I0122 11:50:24.684877    19 fetcher.cc:227] error fetching entries at index 0: UNKNOWN: 
I0122 11:50:24.685230    24 fetcher.cc:227] error fetching entries at index 0: UNKNOWN: 
I0122 11:50:24.685561    21 fetcher.cc:227] error fetching entries at index 0: UNKNOWN: 
I0122 11:50:24.685845    23 fetcher.cc:227] error fetching entries at index 0: UNKNOWN: 
I0122 11:50:24.686137    18 fetcher.cc:227] error fetching entries at index 0: UNKNOWN: 
I0122 11:50:24.689988    22 fetcher.cc:227] error fetching entries at index 0: UNKNOWN: 
I0122 11:50:24.690284    17 fetcher.cc:227] error fetching entries at index 0: UNKNOWN: 

<snip>

F0122 11:51:59.874542    16 masterelection.cc:362] Check failed: task->status().ok() /root/election/55f8ff76-3eee-4c87-9d08-bba8969cd73a: DEADLINE_EXCEEDED: connection timed out
*** Check failure stack trace: ***
    @     0x7fe6c9fe8c8d  google::LogMessage::Fail()
    @     0x7fe6c9feaaf5  google::LogMessage::SendToLog()
    @     0x7fe6c9fe8809  google::LogMessage::Flush()
    @     0x7fe6c9feb58e  google::LogMessageFatal::~LogMessageFatal()
    @     0x55e639579029  cert_trans::MasterElection::ProposalUpdateDone()
    @     0x55e63957a395  std::_Function_handler<>::_M_invoke()
    @     0x55e63957d5bd  util::Task::RunCleanupAndDoneCallbacks()
    @     0x55e63957da9a  std::_Function_handler<>::_M_invoke()
    @     0x55e639573001  cert_trans::libevent::Base::RunClosures()
    @     0x7fe6cb32fe51  event_base_loop
    @     0x55e639573920  cert_trans::libevent::Base::Dispatch()
    @     0x55e63955bd9d  cert_trans::Server::Run()
    @     0x55e639519b13  main
    @     0x7fe6c8be1995  __libc_start_main
    @     0x55e639506c19  _start

[1]+  Aborted                 (core dumped) xjson-server --port=8080 --tree_signing_frequency_seconds=30 --guard_window_seconds=10 --leveldb_db=/data/log.ldb --etcd_servers="$ETCD_ALL" --etcd_delete_concurrency=100 --num_http_server_threads=32 --key=ct.key
@AlCutter
Copy link
Member

I can't reproduce this...

I'm on master at HEAD (250672b - you can see that on the first line of the server log below):

make -j 24

I start an fresh etcd:

rm -fr default.etcd/
 ./etcd

initialise it:

$ ../cpp/tools/prepare_etcd.sh localhost 4001 testdata/ct-server-key.pem 
{"action":"set","node":{"key":"/root","dir":true,"modifiedIndex":3,"createdIndex":3}}
{"action":"set","node":{"key":"/root/entries","dir":true,"modifiedIndex":4,"createdIndex":4}}
{"action":"set","node":{"key":"/root/nodes","dir":true,"modifiedIndex":5,"createdIndex":5}}
{"action":"set","node":{"key":"/root/serving_sth","value":"","modifiedIndex":6,"createdIndex":6}}
{"action":"set","node":{"key":"/root/cluster_config","value":"","modifiedIndex":7,"createdIndex":7}}
{"action":"set","node":{"key":"/root/sequence_mapping","value":"","modifiedIndex":8,"createdIndex":8}}
I0122 12:15:06.863653 15014 init.cc:71] Build version: 250672b5aef3666edbdfc9a75b95a09e7a57ed08
W0122 12:15:06.863736 15014 init.cc:75] Binary built with hardening DISABLED.
I0122 12:15:06.864011 15014 thread_pool.cc:146] ThreadPool starting with 12 threads
W0122 12:15:06.864347 15014 connection_pool.cc:257] Setting client minimum TLS protocol to tlsv12
I0122 12:15:06.864433 15014 connection_pool.cc:289] Loading openssl default trusted root certificates...
I0122 12:15:06.865279 15019 etcd.cc:1034] Etcd version: etcd 2.0.10
I0122 12:15:07.020087 15015 masterelection.cc:546] /election/clustertool: Became master
I0122 12:15:07.020222 15014 thread_pool.cc:146] ThreadPool starting with 4 threads
W0122 12:15:07.076969 15014 sqlite_db.cc:143] SQLite "synchronous" pragma set to FULL
W0122 12:15:07.077006 15014 sqlite_db.cc:146] SQLite running with batched transactions, you should set sqlite_synchronous_mode = FULL !
W0122 12:15:07.162147 15014 clustertool_main.cc:113] Using default ClusterConfig
I0122 12:15:07.164176 15014 clustertool_main.cc:127] Using config:
minimum_serving_nodes: 2
minimum_serving_fraction: 0.75
I0122 12:15:07.279165 15014 clustertool_main.cc:182] OK

Start 3 servers:

cd test
./run_xjson_server.sh /tmp/json0.ldb --etcd_servers=localhost:4001 --port=8880
# in separate shells:
./run_xjson_server.sh /tmp/json1.ldb --etcd_servers=localhost:4001 --port=8881
./run_xjson_server.sh /tmp/json2.ldb --etcd_servers=localhost:4001 --port=8882

and I add items and check the STH:

# empty tree:
curl localhost:8880/ct/v1/get-sth
{ "tree_size": 0, "timestamp": 1453465005736, "sha256_root_hash": "47DEQpj8HBSa+\/TImW+5JCeuQeRkm5NMpJWZG3hSuFU=", "tree_head_signature": "BAMARjBEAiBcgPELKmpDhmhc\/Jo2WK4t13hp6pel8Vr7B7vfH2DtYwIgW0UmM0mBNgnNpAC7l3KcTplS\/9pEgYyZ8V0EsSO3Vwk=" }

# add a thing:
curl -X POST -d '{ "a" : "b" }' localhost:8880/ct/v1/add-json
{ "sct_version": 0, "id": "3xwuwRUAlFJHqWFoMl3cXHlZ6PfG04j8AC4LvT9012Q=", "timestamp": 1453465023693, "extensions": "", "signature": "BAMARzBFAiAGYrKrZNkhFimkWnFoYXqeJjW8sF9BE1YqXboPRNrBQQIhAKe5nE\/QjufWWNB46QtP11KybM5LmaTWNjC27tVHia\/G" }

# time passes, Thorin sings about gold
curl localhost:8880/ct/v1/get-sth
{ "tree_size": 1, "timestamp": 1453465045736, "sha256_root_hash": "D3GDkY4yXr+hH5CARyjelnSDW3r9aEIrekpJNZq\/8i4=", "tree_head_signature": "BAMARzBFAiEAjpdhgWyvFNe\/HSw38lKanFDJKSDXvpDReTTry83UiR4CIAkVFBDFrnIIjQuIhwIiUBRo0whuneKd82JV+gqRu5qn" }

# add another thing:
curl -X POST -d '{ "c" : "d" }' localhost:8880/ct/v1/add-json
{ "sct_version": 0, "id": "3xwuwRUAlFJHqWFoMl3cXHlZ6PfG04j8AC4LvT9012Q=", "timestamp": 1453465067767, "extensions": "", "signature": "BAMASDBGAiEAmk+bfvsVJhLIJygrKkbrcHAjhYMTd2XkydIXA0AqFWQCIQCL1nro3+B9fQpAEaeHx1cDF5qOqxT7N+0gkKbRhQhMoA==" }

# more time passes
curl localhost:8880/ct/v1/get-sth
{ "tree_size": 2, "timestamp": 1453465115736, "sha256_root_hash": "5xkD+YPWegfFTtzL6nnxg8bW4FnIwVFrZHIWBkOR9uM=", "tree_head_signature": "BAMARzBFAiBdvWOqxHak6JSObxLQoFox6ZfOBliYlvuKeuUDm0y+vwIhAJeCqxVO4HaUxGPCq2BSnNnTaknujFIsbCHL2nRKoyG1" }

First node's log:

./run_xjson_server.sh /tmp/json0.ldb --etcd_servers=localhost:4001 --port=8880
I0122 12:15:22.259860 15045 init.cc:71] Build version: 250672b5aef3666edbdfc9a75b95a09e7a57ed08
W0122 12:15:22.259939 15045 init.cc:75] Binary built with hardening DISABLED.
I0122 12:15:22.260133 15045 leveldb_db.cc:131] Opening /tmp/json0.ldb
I0122 12:15:22.383870 15045 thread_pool.cc:146] ThreadPool starting with 8 threads
W0122 12:15:22.384385 15045 connection_pool.cc:257] Setting client minimum TLS protocol to tlsv12
I0122 12:15:22.384551 15045 connection_pool.cc:289] Loading openssl default trusted root certificates...
I0122 12:15:22.384603 15045 xjson-server.cc:116] Running in CLUSTERED mode.
I0122 12:15:22.384727 15045 thread_pool.cc:146] ThreadPool starting with 16 threads
I0122 12:15:22.385179 15045 server.cc:102] Found DB with Node UUID: 94d3331d-bca3-48ff-bdee-c079e56aa35a
I0122 12:15:22.385903 15050 etcd.cc:1034] Etcd version: etcd 2.0.10
I0122 12:15:22.518426 15047 cluster_state_controller-inl.h:322] Received new ClusterConfig:
minimum_serving_nodes: 2
minimum_serving_fraction: 0.75
W0122 12:15:22.519356 15047 cluster_state_controller-inl.h:495] Failed to determine suitable serving STH.
I0122 12:15:22.519438 15051 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453464907164 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0E\002!\000\300\373\301\203\312\037f]H\342\031\001\356{\266Kn\337\301J\260x\244\324\205\204\361\035\226\262\273\013\002 }\327\304\274|\003D\rS\005\206~3\322u\027\376\351\304\344\2410\273\265\000&\375)\335{\267c" }
W0122 12:15:22.519542 15051 cluster_state_controller-inl.h:382] Local DB doesn't have any STH, new node?
I0122 12:15:22.593191 15051 log_lookup.cc:105] Found 0 new log entries
I0122 12:15:22.593235 15051 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:15:07 2016
W0122 12:15:22.642906 15050 cluster_state_controller-inl.h:495] Failed to determine suitable serving STH.
I0122 12:15:22.692842 15045 masterelection.cc:546] /root/election/94d3331d-bca3-48ff-bdee-c079e56aa35a: Became master
W0122 12:15:22.734833 15047 cluster_state_controller-inl.h:495] Failed to determine suitable serving STH.
W0122 12:15:22.735597 15053 cluster_state_controller-inl.h:495] Failed to determine suitable serving STH.
W0122 12:15:32.570909 15049 cluster_state_controller-inl.h:495] Failed to determine suitable serving STH.
I0122 12:15:32.643148 15074 etcd_consistent_store-inl.h:823] Cleaning old entries up to and including sequence number: -1
W0122 12:15:32.721019 15049 cluster_state_controller-inl.h:495] Failed to determine suitable serving STH.
I0122 12:15:35.553064 15045 masterelection.cc:546] /root/election/94d3331d-bca3-48ff-bdee-c079e56aa35a: Became master
W0122 12:15:35.553478 15053 cluster_state_controller-inl.h:495] Failed to determine suitable serving STH.
I0122 12:15:35.686311 15045 masterelection.cc:546] /root/election/94d3331d-bca3-48ff-bdee-c079e56aa35a: Became master
W0122 12:15:35.736541 15052 cluster_state_controller-inl.h:495] Failed to determine suitable serving STH.
I0122 12:15:35.836598 15049 cluster_state_controller-inl.h:477] Can serve @0 with 2 nodes (100% of cluster)
I0122 12:15:35.836774 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453464935736
I0122 12:15:35.886639 15048 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453464935736 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0E\002!\000\235Wd\027\200\225H&\213}\272\374({\221\0227\t\213\026\034\2033\2206\007\236\200\020\236\343\301\002 lt\326\235\323\234\207\330-\204\323b\260\034\240\220!\t>\021}\337\211/\200\227+\2739\365$W" }
I0122 12:15:35.932322 15048 log_lookup.cc:105] Found 0 new log entries
I0122 12:15:35.932364 15048 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:15:35 2016
I0122 12:15:42.643201 15074 etcd_consistent_store-inl.h:823] Cleaning old entries up to and including sequence number: -1
I0122 12:15:42.724294 15046 cluster_state_controller-inl.h:477] Can serve @0 with 2 nodes (100% of cluster)
I0122 12:15:42.724452 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453464942643
I0122 12:15:42.799093 15047 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453464942643 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0D\002 \014\270\362\027\0323\343i\022\212\325\017\2076*\307b\365x\010\316\tgJ\230\257s\030\262P\216\226\002 c\354Hx\203P\246\251\2044\262\020\2726J\022i\254\026\\\027\240bC\242\237\273\301\303\201\272\306" }
I0122 12:15:42.875870 15047 log_lookup.cc:105] Found 0 new log entries
I0122 12:15:42.875919 15047 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:15:42 2016
I0122 12:15:45.773370 15051 cluster_state_controller-inl.h:477] Can serve @0 with 2 nodes (100% of cluster)
I0122 12:15:45.773430 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453464945736
I0122 12:15:45.831794 15049 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453464945736 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0F\002!\000\207\254\364\315^I.\331)vX\253\337\030\327\357\024\217z\231>\311\006]t\213\254r7\032\233\023\002!\000\360\021Dg\322\r\361\267Ps\3756\365\246\341p\3028\345\254\356ap\333\227\264\232\205\241\363(S" }
I0122 12:15:45.881759 15049 log_lookup.cc:105] Found 0 new log entries
I0122 12:15:45.881803 15049 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:15:45 2016
I0122 12:15:52.643198 15074 etcd_consistent_store-inl.h:823] Cleaning old entries up to and including sequence number: -1
I0122 12:15:52.737473 15050 cluster_state_controller-inl.h:477] Can serve @0 with 2 nodes (100% of cluster)
I0122 12:15:52.737601 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453464952643
I0122 12:15:52.829077 15053 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453464952643 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0F\002!\000\244\350A8\221\2224\214\267\300\273\211\237\200%p\023-\362\225\262}\262\215!\211\\E3\312$\320\002!\000\250:\246\177\025=\323Eq\005\317\210\230\336P\311}&\3359\262\212\035\244\227\3665\0339\036\224\'" }
I0122 12:15:52.903506 15053 log_lookup.cc:105] Found 0 new log entries
I0122 12:15:52.903549 15053 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:15:52 2016
I0122 12:15:54.419729 15045 masterelection.cc:546] /root/election/94d3331d-bca3-48ff-bdee-c079e56aa35a: Became master
W0122 12:15:54.461838 15046 cluster_state_controller-inl.h:495] Failed to determine suitable serving STH.
I0122 12:15:54.603066 15045 masterelection.cc:546] /root/election/94d3331d-bca3-48ff-bdee-c079e56aa35a: Became master
W0122 12:15:54.645028 15047 cluster_state_controller-inl.h:495] Failed to determine suitable serving STH.
I0122 12:15:54.678447 15049 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:15:54.678520 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453464954645
I0122 12:15:54.761756 15050 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453464954645 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0D\002 .\334\315\207>\263\005\275`p\246\320\3712\375\000\036Y\037\235\326u!\257\374\322\024m\006q\326\345\002 g;\020\332\036\026\'\351\313\347H\303\\\307\205\024\237>A\274\305\247T*\320O\027\237\032X\207F" }
I0122 12:15:54.809079 15050 log_lookup.cc:105] Found 0 new log entries
I0122 12:15:54.809115 15050 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:15:54 2016
I0122 12:15:55.778069 15053 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:15:55.778234 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453464955736
I0122 12:15:55.820044 15046 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453464955736 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0F\002!\000\313h\231\206\277\272\332\3336\233O\210z\002\230@\250\373\376;\350\277\372\321\021\232\256`\337\243\347\234\002!\000\205g\346\263^\223j\344&\345\266\017\225H^D\244uhT\364\016\353K\357\250u\274\347\023\253\335" }
I0122 12:15:55.874832 15046 log_lookup.cc:105] Found 0 new log entries
I0122 12:15:55.874877 15046 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:15:55 2016
I0122 12:16:02.643149 15074 etcd_consistent_store-inl.h:823] Cleaning old entries up to and including sequence number: -1
I0122 12:16:02.725272 15049 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:16:02.725350 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453464962643
I0122 12:16:02.791635 15053 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453464962643 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0D\002 O\255\350{\245\323.\027\250w\376D@\230\332\364\270\200\231\311\355\336\013\226\"\241oS!\2441\357\002 \016\235\267|eW\311j\3363\370z/a\202|\213\261\232T\311\340\220\201\230\372}D\200\3516\213" }
I0122 12:16:02.882918 15053 log_lookup.cc:105] Found 0 new log entries
I0122 12:16:02.882964 15053 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:16:02 2016
I0122 12:16:04.857197 15052 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:16:04.857280 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453464964645
I0122 12:16:04.948990 15050 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453464964645 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0E\002 =\026\r\352\t?m\016\316\0171\201X\303\215Dp[\370\211\241,\301\366\244Q<\013\307D\233\024\002!\000\362\211W$\322Q{j\277M\234\352nh\267\264w\355-\004\205\371\262\351\247\227\333\301\321\304\017\267" }
I0122 12:16:05.047289 15050 log_lookup.cc:105] Found 0 new log entries
I0122 12:16:05.047332 15050 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:16:04 2016
I0122 12:16:05.774271 15050 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:16:05.774384 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453464965736
I0122 12:16:05.816020 15053 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453464965736 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0E\002 p\272\037W k\360_e\276\272\211\334^\330\244\273\300\271\367\254,i+\203\266g\355\211r)\275\002!\000\274\316\375[\037\353\212\246_hK\241T\224\203*\017\372\271\274x\240\223\365\267|SH\000\223\206\360" }
I0122 12:16:05.867128 15053 log_lookup.cc:105] Found 0 new log entries
I0122 12:16:05.867172 15053 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:16:05 2016
I0122 12:16:12.643149 15074 etcd_consistent_store-inl.h:823] Cleaning old entries up to and including sequence number: -1
I0122 12:16:12.720748 15047 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:16:12.720836 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453464972643
I0122 12:16:12.795739 15046 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453464972643 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0F\002!\000\370V75Y\002\364rlm\223*\355\2367(}Ph\355mL\344\341\363y\326\342a\026\375\340\002!\000\355S\003\212\260B8\375/\ta\246A\014d\360\3463^\335/\013J\235\255\'\303\002\367\301\312\n" }
I0122 12:16:12.886726 15046 log_lookup.cc:105] Found 0 new log entries
I0122 12:16:12.886776 15046 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:16:12 2016
I0122 12:16:14.689009 15052 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:16:14.689095 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453464974645
I0122 12:16:14.780802 15047 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453464974645 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0E\002 \030\346\314\022B\271\001\316\276\\\010i\032+\316h+\r\344\302\270\254BF\342*V\371\220\030|\003\002!\000\271\242\226Z\202U\221.\033\266\3034?F\032\215\372\372\365Xt\271\3260 \247\027J\t\024\334\010" }
I0122 12:16:14.833325 15047 log_lookup.cc:105] Found 0 new log entries
I0122 12:16:14.833369 15047 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:16:14 2016
I0122 12:16:15.771970 15046 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:16:15.772048 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453464975736
I0122 12:16:15.814040 15048 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453464975736 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0E\002 \"\301\200\371\246\2643\263\000\302\224\214\013\030\267\340\304\212\223!\235\202Z\317\016\277\300\336\210g\206G\002!\000\347\345s-\242\022V\214\272W\034\305b\355\304\035\247\352\337\374\220\rm\215p\2324\315\037\341}{" }
I0122 12:16:15.865684 15048 log_lookup.cc:105] Found 0 new log entries
I0122 12:16:15.865722 15048 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:16:15 2016
W0122 12:16:22.476902 15045 connection_pool.cc:335] Releasing errored connection to localhost:4001
W0122 12:16:25.743394 15045 connection_pool.cc:360] error flag (0x41): READING TIMEOUT : Success
I0122 12:16:22.643153 15074 etcd_consistent_store-inl.h:823] Cleaning old entries up to and including sequence number: -1
W0122 12:16:25.743758 15045 connection_pool.cc:335] Releasing errored connection to localhost:4001
W0122 12:16:25.743791 15045 connection_pool.cc:360] error flag (0x41): READING TIMEOUT : Success
I0122 12:16:25.817814 15045 masterelection.cc:546] /root/election/94d3331d-bca3-48ff-bdee-c079e56aa35a: Became master
I0122 12:16:25.861299 15047 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:16:25.861414 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453464984645
I0122 12:16:25.861948 15046 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:16:25.862498 15050 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:16:25.862901 15051 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:16:25.863237 15047 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:16:25.935664 15052 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453464984645 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0D\002 /\2354\321\344\374a7\275Smtv\3579\001?\327\317\036\256O\342\340[3\214g|A\236\350\002 \010I\321\332\347{&\241Sx\026M\213d\2300o&\025\r9\251\330;v\212&\336\027\313\2662" }
I0122 12:16:25.936081 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453464985736
I0122 12:16:26.026743 15052 log_lookup.cc:105] Found 0 new log entries
I0122 12:16:26.026789 15052 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:16:24 2016
I0122 12:16:26.069030 15046 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453464985736 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0F\002!\000\277UuD\226\375\376\035\237\2758\035\373\232T1L\200r\350\007fD\n*/\221\004\374\255\313Z\002!\000\271s\367\267\031\335\271}%\231\241(G?\232\233\325\374\261Z\265%\230Z\332\233vp\306\322$M" }
I0122 12:16:26.164468 15046 log_lookup.cc:105] Found 0 new log entries
I0122 12:16:26.164511 15046 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:16:25 2016
I0122 12:16:32.643164 15074 etcd_consistent_store-inl.h:823] Cleaning old entries up to and including sequence number: -1
I0122 12:16:32.731704 15050 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:16:32.731787 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453464992643
I0122 12:16:32.823109 15051 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453464992643 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0F\002!\000\345\233\0321\211O\2769\033\235B@ i\243\377\373}\016\017\234[\260\277\016\234\235\317\360\305\030~\002!\000\256?\364\362\235\232\315\220\335\031\306\300g~{\006\277Rx\371\240\354\216\0360Wz\237ss\010(" }
I0122 12:16:32.924959 15051 log_lookup.cc:105] Found 0 new log entries
I0122 12:16:32.925004 15051 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:16:32 2016
I0122 12:16:34.696961 15047 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:16:34.697052 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453464994645
I0122 12:16:34.788722 15052 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453464994645 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0E\002!\000\362;\375\"\267X1\365O\3100(\0173\350 \266Q\033W\356\240\300\355\244\227>@\245\330\232*\002 \'\322\005BMs\264\000`\"n&a1\032\341\244\356\230V\372mf\373ur`\365D\007@\232" }
I0122 12:16:34.839874 15052 log_lookup.cc:105] Found 0 new log entries
I0122 12:16:34.839915 15052 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:16:34 2016
I0122 12:16:35.605160 15045 masterelection.cc:546] /root/election/94d3331d-bca3-48ff-bdee-c079e56aa35a: Became master
I0122 12:16:35.771975 15053 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:16:35.772018 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453464995736
I0122 12:16:35.813798 15053 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453464995736 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0D\002 3\356^\341Fn\342D \"\342\326y\237\333\000S\200\032-\310\236\317\362\323\327\001\210\323 *\033\002 --<\364\037we\026\0173\010D7\256\204\023h\200d\220\363+\250Cwr\314\010\375Jr\336" }
I0122 12:16:35.872578 15053 log_lookup.cc:105] Found 0 new log entries
I0122 12:16:35.872619 15053 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:16:35 2016
I0122 12:16:42.643116 15074 etcd_consistent_store-inl.h:823] Cleaning old entries up to and including sequence number: -1
I0122 12:16:42.734274 15050 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:16:42.734359 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465002643
I0122 12:16:42.817611 15048 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465002643 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0F\002!\000\235<|\373\014!O\307\361\265RCU@aI\33226?\377k\225\242\031\256 \031\210R\215\221\002!\000\261\342l\341\241\256\237?\2734\230N_v\221\027\376\320u.j\300n\352\010*]\024\275n\313l" }
I0122 12:16:42.907506 15048 log_lookup.cc:105] Found 0 new log entries
I0122 12:16:42.907551 15048 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:16:42 2016
I0122 12:16:44.692873 15051 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:16:44.693053 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465004645
I0122 12:16:44.792814 15048 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465004645 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0D\002 R\030\243\225\2346\"\207\367;0\30340+=\256=\316\326\272\202\223\307\260Z\262\355+\215\230\347\002 \\\267\302\224E\307\004\323\263.g\224\3020\314\177\334\223\025\326\371\245p\270M\nM\270\361kf\r" }
I0122 12:16:44.865144 15048 log_lookup.cc:105] Found 0 new log entries
I0122 12:16:44.865182 15048 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:16:44 2016
I0122 12:16:45.784324 15050 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:16:45.784414 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465005736
I0122 12:16:45.834352 15048 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465005736 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0D\002 \\\200\361\013*jC\206h\\\374\2326X\256-\327xi\352\227\245\361Z\373\007\273\337\037`\355c\002 [E&3I\2016\t\315\244\000\273\227r\234N\231R\377\332D\201\214\231\361]\004\261#\267W\t" }
I0122 12:16:45.913312 15048 log_lookup.cc:105] Found 0 new log entries
I0122 12:16:45.913357 15048 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:16:45 2016
I0122 12:16:52.643164 15074 etcd_consistent_store-inl.h:823] Cleaning old entries up to and including sequence number: -1
I0122 12:16:52.714845 15046 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:16:52.714953 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465012643
I0122 12:16:52.797981 15050 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465012643 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0E\002!\000\302D\345\263\226\023\006\330g\253#\271\326\333\227\313\230]\027ggp\354y\021\245{\264\310ZE;\002 \000\247\317\n\376\331%\005\207\244\310\037~&4\267\230\243\363\375\2003\325g\270\247\3548\253 J+" }
I0122 12:16:52.902258 15050 log_lookup.cc:105] Found 0 new log entries
I0122 12:16:52.902299 15050 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:16:52 2016
I0122 12:16:54.455457 15045 masterelection.cc:546] /root/election/94d3331d-bca3-48ff-bdee-c079e56aa35a: Became master
I0122 12:16:54.688805 15049 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:16:54.688887 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465014645
I0122 12:16:54.755712 15048 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465014645 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0D\002 c`z6f\231*\352\177\241\351G\315\n\003L\231\031\267\'\312\340a)=\030\233M{\317\335E\002 $\224\"\251\251\026\366xx\001-\355\373\206o\206IT!Y/\364\232IzY\016\362(4J\232" }
I0122 12:16:54.805308 15048 log_lookup.cc:105] Found 0 new log entries
I0122 12:16:54.805354 15048 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:16:54 2016
I0122 12:16:55.771813 15052 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:16:55.771908 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465015736
I0122 12:16:55.813614 15046 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465015736 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0E\002!\000\332\213\307\212`\235E\237r\001gr\255\372<\337\333\013WGl\273\330\214\333l\212\230?L\313P\002 `\007`\361\303\304nvZ\304\225Gg8Y?\205\275\277\324gj\340K\343qa\316\230\177_}" }
I0122 12:16:55.862884 15046 log_lookup.cc:105] Found 0 new log entries
I0122 12:16:55.862926 15046 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:16:55 2016
I0122 12:17:02.643165 15074 etcd_consistent_store-inl.h:823] Cleaning old entries up to and including sequence number: -1
I0122 12:17:02.727318 15046 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:17:02.727421 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465022643
I0122 12:17:02.802330 15047 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465022643 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0F\002!\000\350\270\356\243\036\304jS\032\220\237\275\013\225\'r\243(\341\3719\027\367v/\025ojn%\352\315\002!\000\206\237~\357\311\035\277\256l\215\003\t\017\307\326K\246\031\020J\226nSk\344\343e\322\272Wb\265" }
I0122 12:17:02.906358 15047 log_lookup.cc:105] Found 0 new log entries
I0122 12:17:02.906404 15047 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:17:02 2016
I0122 12:17:04.692708 15050 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:17:04.692791 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465024645
I0122 12:17:04.785035 15050 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465024645 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0D\002 up\203v\200\323\232I\270>^\000,\tP_\233\001)\003\220+M[Z\302\267a{\\|-\002 A\017J \360\345q^\274;\333=\363cB\224\342}i\366\304\264-\366c\3347\214.[\002\257" }
I0122 12:17:04.854795 15050 log_lookup.cc:105] Found 0 new log entries
I0122 12:17:04.854832 15050 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:17:04 2016
I0122 12:17:05.776010 15050 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:17:05.776126 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465025736
I0122 12:17:05.817912 15052 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465025736 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0E\002!\000\240a<\246\000H\302\275\246\244\3211\316U\245M\202\270_}(\234\tr/\213\025\326\010Oa%\002 |{g\tq\271\276\351X\007\253\243\271)V\363\177\304b\230\316\354\343g\001T\355\332\347\020\335$" }
I0122 12:17:05.870806 15052 log_lookup.cc:105] Found 0 new log entries
I0122 12:17:05.870851 15052 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:17:05 2016
I0122 12:17:12.643167 15074 etcd_consistent_store-inl.h:823] Cleaning old entries up to and including sequence number: -1
I0122 12:17:12.721760 15046 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:17:12.721837 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465032643
I0122 12:17:12.796576 15053 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465032643 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0D\002 7\347\337n\255\014*d:\336\261\325\377T\nzF\262\304\213\330)*\024w\325\035\376S\221\260\261\002 !\262\253\014#\313\313E\223\343\"\311\277\307\303\354R6\257\233\357\014 \211\313<\000\225\331\366h\352" }
I0122 12:17:12.879374 15053 log_lookup.cc:105] Found 0 new log entries
I0122 12:17:12.879420 15053 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:17:12 2016
I0122 12:17:14.836791 15051 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:17:14.836952 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465034645
I0122 12:17:14.920225 15053 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465034645 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0F\002!\000\314\325\204&\220\364\017tC\002\004\244\254\025_\335\244\\&\265\360\332T\272\377\202\277 NtV0\002!\000\210\351$\373t6\272\006\250\255\260\336\364\362\334\225\334\037c\030\214\267\313NGr\327\001\316\321v\255" }
I0122 12:17:14.961972 15053 log_lookup.cc:105] Found 0 new log entries
I0122 12:17:14.962018 15053 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:17:14 2016
I0122 12:17:15.778007 15046 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:17:15.778205 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465035736
I0122 12:17:15.819906 15051 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465035736 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0F\002!\000\204k<\275\024L\304\211\203\305\332\2340UT\277\'\315\032j\314B\220r\033\202\332\302\240\215\302^\002!\000\332\3330G\346,\336b\rm\217\243iu\312\367\021\367\260~\364\027A\363\353\312d\205\340^u6" }
I0122 12:17:15.861219 15051 log_lookup.cc:105] Found 0 new log entries
I0122 12:17:15.861261 15051 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:17:15 2016
I0122 12:17:22.558851 15045 masterelection.cc:546] /root/election/94d3331d-bca3-48ff-bdee-c079e56aa35a: Became master
I0122 12:17:22.643123 15074 etcd_consistent_store-inl.h:823] Cleaning old entries up to and including sequence number: -1
W0122 12:17:25.745311 15045 connection_pool.cc:335] Releasing errored connection to localhost:4001
W0122 12:17:25.745365 15045 connection_pool.cc:360] error flag (0x41): READING TIMEOUT : Success
W0122 12:17:25.745460 15045 connection_pool.cc:335] Releasing errored connection to localhost:4001
W0122 12:17:25.745553 15045 connection_pool.cc:335] Releasing errored connection to localhost:4001
W0122 12:17:25.745595 15045 connection_pool.cc:360] error flag (0x41): READING TIMEOUT : Success
I0122 12:17:25.773762 15053 cluster_state_controller-inl.h:477] Can serve @1 with 3 nodes (100% of cluster)
I0122 12:17:25.773834 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465045736
I0122 12:17:25.815747 15050 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465045736 tree_size: 1 sha256_root_hash: "\017q\203\221\2162^\277\241\037\220\200G(\336\226t\203[z\375hB+zJI5\232\277\362." signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0E\002!\000\216\227a\201l\257\024\327\277\035,7\362R\232\234P\311) \327\276\220\321y4\353\313\315\324\211\036\002 \t\025\024\020\305\256r\010\215\013\210\207\002\"P\024h\323\010n\235\342\235\363bU\372\n\221\273\232\247" }
I0122 12:17:25.861003 15050 log_lookup.cc:105] Found 1 new log entries
I0122 12:17:25.861044 15050 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:17:25 2016
I0122 12:17:32.643115 15074 etcd_consistent_store-inl.h:823] Cleaning old entries up to and including sequence number: 0
I0122 12:17:32.719229 15050 cluster_state_controller-inl.h:477] Can serve @1 with 3 nodes (100% of cluster)
I0122 12:17:32.719367 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465052643
I0122 12:17:32.819092 15046 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465052643 tree_size: 1 sha256_root_hash: "\017q\203\221\2162^\277\241\037\220\200G(\336\226t\203[z\375hB+zJI5\232\277\362." signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0E\002 H\277\005\337\t*\355\327\n\0259\\cIP\237\300\213G\001W\227\023\331A\2055$\262\304\247\305\002!\000\261\010\254\251\315\247\351\300\321\206\343\035\340\216\006\031\316H\006yz%\212\001\004\256\347\035+/,f" }
I0122 12:17:32.819811 15074 etcd_consistent_store-inl.h:823] Cleaning old entries up to and including sequence number: 0
I0122 12:17:32.904587 15046 log_lookup.cc:105] Found 0 new log entries
I0122 12:17:32.904634 15046 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:17:32 2016
I0122 12:17:33.043948 15074 etcd_consistent_store-inl.h:823] Cleaning old entries up to and including sequence number: 0
I0122 12:17:34.684831 15050 cluster_state_controller-inl.h:477] Can serve @1 with 3 nodes (100% of cluster)
I0122 12:17:34.684909 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465054645
I0122 12:17:34.818217 15047 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465054645 tree_size: 1 sha256_root_hash: "\017q\203\221\2162^\277\241\037\220\200G(\336\226t\203[z\375hB+zJI5\232\277\362." signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0E\002!\000\230\214^\013A\311\304+\363\356s\000~x\234\2030\007 \020\236\030bo\231\004\177\002H\337w\242\002 0\010\230\315\032\364\276`\213>\373\211\325C\262\300\032\030\nO@asY\240\313-l\337fU\234" }
I0122 12:17:34.861021 15047 log_lookup.cc:105] Found 0 new log entries
I0122 12:17:34.861063 15047 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:17:34 2016
I0122 12:17:35.642441 15045 masterelection.cc:546] /root/election/94d3331d-bca3-48ff-bdee-c079e56aa35a: Became master
I0122 12:17:35.777222 15047 cluster_state_controller-inl.h:477] Can serve @1 with 3 nodes (100% of cluster)
I0122 12:17:35.777269 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465055736
I0122 12:17:35.810608 15046 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465055736 tree_size: 1 sha256_root_hash: "\017q\203\221\2162^\277\241\037\220\200G(\336\226t\203[z\375hB+zJI5\232\277\362." signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0C\002 [\334\262{!f\243\245r\000y\033\240\243\347<\371\240\001\021\301\213*zD\220Kl\010\320\022\263\002\037%\022\341d\362\r\3502\271\347\220\215\324rV\340a3\3762B9q\220\222\010<p`\"0" }
I0122 12:17:35.860290 15046 log_lookup.cc:105] Found 0 new log entries
I0122 12:17:35.860318 15046 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:17:35 2016
I0122 12:17:42.643115 15074 etcd_consistent_store-inl.h:823] Cleaning old entries up to and including sequence number: 0
I0122 12:17:42.715329 15046 cluster_state_controller-inl.h:477] Can serve @1 with 3 nodes (100% of cluster)
I0122 12:17:42.715373 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465062643
I0122 12:17:42.798710 15052 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465062643 tree_size: 1 sha256_root_hash: "\017q\203\221\2162^\277\241\037\220\200G(\336\226t\203[z\375hB+zJI5\232\277\362." signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0E\002!\000\347\373-\302~\273\201,<\301\300z[\004)\372\205\\\022\302\3761\322\343\236\003\206\206\260\365\331\205\002 av\367\020\340y\036\260\205\317\030_\360\314\201\376\355\334\017\323\207TY\032P\214\370\302\372\237J\021" }
I0122 12:17:42.873072 15052 log_lookup.cc:105] Found 0 new log entries
I0122 12:17:42.873128 15052 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:17:42 2016
I0122 12:17:44.680822 15047 cluster_state_controller-inl.h:477] Can serve @1 with 3 nodes (100% of cluster)
I0122 12:17:44.680938 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465064645
I0122 12:17:44.747994 15048 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465064645 tree_size: 1 sha256_root_hash: "\017q\203\221\2162^\277\241\037\220\200G(\336\226t\203[z\375hB+zJI5\232\277\362." signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0F\002!\000\301\030\301\\\260dk/uf\266x\220UZi\341\n\310\347\361\000\016\274\257{\225K\255+\255Y\002!\000\332\200}X\307\rTT?\316\354\\\'\317?\322\024\261L*\"&\212^\353\373\234\317\364\336\024Z" }
I0122 12:17:44.796730 15048 log_lookup.cc:105] Found 0 new log entries
I0122 12:17:44.796769 15048 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:17:44 2016
I0122 12:17:45.772068 15049 cluster_state_controller-inl.h:477] Can serve @1 with 3 nodes (100% of cluster)
I0122 12:17:45.772163 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465065736
I0122 12:17:45.814009 15051 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465065736 tree_size: 1 sha256_root_hash: "\017q\203\221\2162^\277\241\037\220\200G(\336\226t\203[z\375hB+zJI5\232\277\362." signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0D\002 Z\210\031E\313~\177\300\265\242\214\274\315\037-?)\353\347\367\267\366\300\324iD*\264\014VB\024\002 U\016\357\373\005\324\234\321\025\214\323\303\221\340\314\020\332]\3120\254\363.\023\265\245\203)\374Q\367\216" }
I0122 12:17:45.859261 15051 log_lookup.cc:105] Found 0 new log entries
I0122 12:17:45.859303 15051 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:17:45 2016
I0122 12:17:52.643182 15074 etcd_consistent_store-inl.h:823] Cleaning old entries up to and including sequence number: 0
I0122 12:17:52.725841 15049 cluster_state_controller-inl.h:477] Can serve @1 with 3 nodes (100% of cluster)
I0122 12:17:52.725883 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465072643
I0122 12:17:52.801039 15051 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465072643 tree_size: 1 sha256_root_hash: "\017q\203\221\2162^\277\241\037\220\200G(\336\226t\203[z\375hB+zJI5\232\277\362." signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0D\002 V\332\254(\0310\325\032~\"?\273\032\306]\371\301\375\346\336\374wm\265\227\307\237\330\365\223\216\r\002 bTou\027[\347\365\250\216/5\373\245&E\251\222\010B\366\344\354\255\343\320(\223\271\360*\200" }
I0122 12:17:52.894016 15051 log_lookup.cc:105] Found 0 new log entries
I0122 12:17:52.894057 15051 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:17:52 2016
I0122 12:17:54.458004 15045 masterelection.cc:546] /root/election/94d3331d-bca3-48ff-bdee-c079e56aa35a: Became master
I0122 12:17:54.684438 15053 cluster_state_controller-inl.h:477] Can serve @1 with 3 nodes (100% of cluster)
I0122 12:17:54.684568 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465074645
I0122 12:17:54.759452 15050 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465074645 tree_size: 1 sha256_root_hash: "\017q\203\221\2162^\277\241\037\220\200G(\336\226t\203[z\375hB+zJI5\232\277\362." signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0E\002!\000\370\022\304r\211w\2735\002\241a\256\307\340\305\340\3010\337d\207P\014\216.\337\321\0065g\210n\002 -\025\254k\215Z\3079R\324@I\t\2042\2254\333\230\245\246\231\240t\357D\332i\254\237\000\346" }
I0122 12:17:54.808962 15050 log_lookup.cc:105] Found 0 new log entries
I0122 12:17:54.809002 15050 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:17:54 2016
I0122 12:17:55.775861 15053 cluster_state_controller-inl.h:477] Can serve @1 with 3 nodes (100% of cluster)
I0122 12:17:55.775949 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465075736
I0122 12:17:55.817812 15050 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465075736 tree_size: 1 sha256_root_hash: "\017q\203\221\2162^\277\241\037\220\200G(\336\226t\203[z\375hB+zJI5\232\277\362." signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0E\002 \026\034\245\260\327\237\031w\235\336\347p\343\234\227\035jy\330\360hl\213\001\315\017J9V\306\224k\002!\000\235\234\265=\203:\206wD\343\370\346\206\212R\027\231\240^$\275\000\310.yusd8\267\307\256" }
I0122 12:17:55.866261 15050 log_lookup.cc:105] Found 0 new log entries
I0122 12:17:55.866294 15050 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:17:55 2016
I0122 12:18:02.643101 15074 etcd_consistent_store-inl.h:823] Cleaning old entries up to and including sequence number: 0
I0122 12:18:02.858237 15050 cluster_state_controller-inl.h:477] Can serve @1 with 3 nodes (100% of cluster)
I0122 12:18:02.858289 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465082643
I0122 12:18:03.024806 15049 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465082643 tree_size: 1 sha256_root_hash: "\017q\203\221\2162^\277\241\037\220\200G(\336\226t\203[z\375hB+zJI5\232\277\362." signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0E\002!\000\234$\365+j\336\'\240\314\272\tw\031E:\263\354\377\t\316^\3552\221\341\257Z\341\\\003\2556\002 O\325\247t\2265\242\375\033\247\362R\200\035.|\353\306\255\206\202=q\0040O\270\227\0178x\034" }
I0122 12:18:03.191277 15049 log_lookup.cc:105] Found 0 new log entries
I0122 12:18:03.191486 15049 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:18:02 2016
I0122 12:18:04.678385 15047 cluster_state_controller-inl.h:477] Can serve @1 with 3 nodes (100% of cluster)
I0122 12:18:04.678453 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465084645
I0122 12:18:04.762015 15046 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465084645 tree_size: 1 sha256_root_hash: "\017q\203\221\2162^\277\241\037\220\200G(\336\226t\203[z\375hB+zJI5\232\277\362." signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0D\002 y\014\273\312\230\267\210\271\301\330o\365\033\342\276\177@\353\246=\353#\316\336-\340hL\345O\264\255\002 \n\271Ue\031\226\241\0055\337\257\335\014X\266\302\304\"l\267\354\237\377\270\032\241\336,.\034\277\244" }
I0122 12:18:04.825682 15046 log_lookup.cc:105] Found 0 new log entries
I0122 12:18:04.825724 15046 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:18:04 2016
I0122 12:18:05.777832 15046 cluster_state_controller-inl.h:477] Can serve @1 with 3 nodes (100% of cluster)
I0122 12:18:05.777957 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465085736
I0122 12:18:05.819594 15049 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465085736 tree_size: 1 sha256_root_hash: "\017q\203\221\2162^\277\241\037\220\200G(\336\226t\203[z\375hB+zJI5\232\277\362." signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0F\002!\000\213\301x@\333\352\t\236\031^8g\272\001\240#wsP3\"g\251\305\240\020\236Y\214\276h\365\002!\000\311\203\020B\006\372\350\003]O\027-\037\333\274Z\320\325^\004\027\037\367\003\203\034\207Tg\234\311\276" }
I0122 12:18:05.895397 15049 log_lookup.cc:105] Found 0 new log entries
I0122 12:18:05.895445 15049 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:18:05 2016
I0122 12:18:12.643110 15074 etcd_consistent_store-inl.h:823] Cleaning old entries up to and including sequence number: 0
I0122 12:18:14.686105 15051 cluster_state_controller-inl.h:477] Can serve @1 with 3 nodes (100% of cluster)
I0122 12:18:14.686192 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465094645
I0122 12:18:14.790110 15052 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465094645 tree_size: 1 sha256_root_hash: "\017q\203\221\2162^\277\241\037\220\200G(\336\226t\203[z\375hB+zJI5\232\277\362." signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0D\002 ;\231\271\221p{\226\255\004\377.CMy\374\036F\375\274$|\333\223[W8\270%\247\313\352\n\002 \"a\276\244U\334\301i\005\326\210t\207F\036|q#q\307?\315\333\201\337\206\222\273\221\307{{" }
I0122 12:18:14.832681 15052 log_lookup.cc:105] Found 0 new log entries
I0122 12:18:14.832717 15052 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:18:14 2016
I0122 12:18:15.777184 15053 cluster_state_controller-inl.h:477] Can serve @1 with 3 nodes (100% of cluster)
I0122 12:18:15.777271 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465095736
I0122 12:18:15.810636 15051 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465095736 tree_size: 1 sha256_root_hash: "\017q\203\221\2162^\277\241\037\220\200G(\336\226t\203[z\375hB+zJI5\232\277\362." signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0F\002!\000\222=\r\020.eu\0239%\023O\331\255\241]Y\245u\031\325\n\252\361W\377\375S@\024\000\315\002!\000\363\236\234\3254h\341\344\307\020\373\'\207\24071%\333\330,\232\031\242G&\303F\371\\*\261\254" }
I0122 12:18:15.901775 15051 log_lookup.cc:105] Found 0 new log entries
I0122 12:18:15.901814 15051 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:18:15 2016
I0122 12:18:22.643105 15074 etcd_consistent_store-inl.h:823] Cleaning old entries up to and including sequence number: 0
I0122 12:18:22.673221 15045 masterelection.cc:546] /root/election/94d3331d-bca3-48ff-bdee-c079e56aa35a: Became master
W0122 12:18:25.747107 15045 connection_pool.cc:335] Releasing errored connection to localhost:4001
W0122 12:18:25.747162 15045 connection_pool.cc:360] error flag (0x41): READING TIMEOUT : Success
W0122 12:18:25.747269 15045 connection_pool.cc:335] Releasing errored connection to localhost:4001
W0122 12:18:25.747301 15045 connection_pool.cc:360] error flag (0x41): READING TIMEOUT : Success
I0122 12:18:25.777055 15047 cluster_state_controller-inl.h:477] Can serve @2 with 3 nodes (100% of cluster)
I0122 12:18:25.777186 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465105736
I0122 12:18:25.810390 15049 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465105736 tree_size: 2 sha256_root_hash: "\347\031\003\371\203\326z\007\305N\334\313\352y\361\203\306\326\340Y\310\301Qkdr\026\006C\221\366\343" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0E\002!\000\225\311\267G\274&\n/Dc\000\267\216a\351~\255\245\007\365\316s\230a6\360\275\262\t\366\321Y\002 \020|t\022\023H\205H\'\341\337\276\\\326v#\246\237\343\277\0032a\031\354\257\313|\334UK\037" }
I0122 12:18:25.901706 15049 log_lookup.cc:105] Found 1 new log entries
I0122 12:18:25.901749 15049 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:18:25 2016
I0122 12:18:32.643138 15074 etcd_consistent_store-inl.h:823] Cleaning old entries up to and including sequence number: 1
I0122 12:18:32.809929 15050 cluster_state_controller-inl.h:477] Can serve @2 with 3 nodes (100% of cluster)
I0122 12:18:32.809972 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465112643
I0122 12:18:32.937204 15047 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465112643 tree_size: 2 sha256_root_hash: "\347\031\003\371\203\326z\007\305N\334\313\352y\361\203\306\326\340Y\310\301Qkdr\026\006C\221\366\343" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0D\002 \004\016`E\240nh1\247\360c\342\2061\311Z}\340\032\0076}Nh\216\241&F+i\357\325\002 \006|eMm\t^\007oA\267\024\222\333\354u\"\2605\271\'\314\375\240\023\323\374\306\240\227\301\304" }
I0122 12:18:32.937647 15074 etcd_consistent_store-inl.h:823] Cleaning old entries up to and including sequence number: 1
I0122 12:18:33.007923 15047 log_lookup.cc:105] Found 0 new log entries
I0122 12:18:33.007967 15047 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:18:32 2016
I0122 12:18:33.193778 15074 etcd_consistent_store-inl.h:823] Cleaning old entries up to and including sequence number: 1
I0122 12:18:34.693960 15051 cluster_state_controller-inl.h:477] Can serve @2 with 3 nodes (100% of cluster)
I0122 12:18:34.694196 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465114645
I0122 12:18:34.777415 15046 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465114645 tree_size: 2 sha256_root_hash: "\347\031\003\371\203\326z\007\305N\334\313\352y\361\203\306\326\340Y\310\301Qkdr\026\006C\221\366\343" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0F\002!\000\235W\327\230t\314\332GsGH\207.\335\027\376\224U7\344\032j\027\177hW\032?\030\204N\377\002!\000\315x\206\357\316x`C\233WE\300\231\021t\2742m\270\2330\004\016/\005\2624@q1\361\313" }
I0122 12:18:34.855973 15046 log_lookup.cc:105] Found 0 new log entries
I0122 12:18:34.856015 15046 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:18:34 2016
I0122 12:18:35.685689 15045 masterelection.cc:546] /root/election/94d3331d-bca3-48ff-bdee-c079e56aa35a: Became master
I0122 12:18:35.777433 15052 cluster_state_controller-inl.h:477] Can serve @2 with 3 nodes (100% of cluster)
I0122 12:18:35.777483 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465115736
I0122 12:18:35.811002 15050 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465115736 tree_size: 2 sha256_root_hash: "\347\031\003\371\203\326z\007\305N\334\313\352y\361\203\306\326\340Y\310\301Qkdr\026\006C\221\366\343" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0E\002 ]\275c\252\304v\244\350\224\216o\022\320\240Z1\351\227\316\006X\230\226\373\212z\345\003\233L\276\277\002!\000\227\202\253\025N\340v\224\304c\302\253`R\234\331\323jI\356\214R,l!\313\332tJ\243!\265" }
I0122 12:18:35.893841 15050 log_lookup.cc:105] Found 0 new log entries
I0122 12:18:35.893880 15050 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:18:35 2016
I0122 12:18:42.643141 15074 etcd_consistent_store-inl.h:823] Cleaning old entries up to and including sequence number: 1
I0122 12:18:42.724253 15051 cluster_state_controller-inl.h:477] Can serve @2 with 3 nodes (100% of cluster)
I0122 12:18:42.724371 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465122643
I0122 12:18:42.799142 15053 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465122643 tree_size: 2 sha256_root_hash: "\347\031\003\371\203\326z\007\305N\334\313\352y\361\203\306\326\340Y\310\301Qkdr\026\006C\221\366\343" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0F\002!\000\242W\200\244}w\272#09\034 }\325\271Es\031\272\307\016\264+=\344\tl^\334\236\264\214\002!\000\256\261\203X\301m\006\033\027\276\276\305\233\016\\\233F\t\205[\\\273Q\030\331\331_\251\023oq\232" }
I0122 12:18:42.873599 15053 log_lookup.cc:105] Found 0 new log entries
I0122 12:18:42.873653 15053 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:18:42 2016
I0122 12:18:44.681383 15048 cluster_state_controller-inl.h:477] Can serve @2 with 3 nodes (100% of cluster)
I0122 12:18:44.681470 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465124645
I0122 12:18:44.757020 15048 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465124645 tree_size: 2 sha256_root_hash: "\347\031\003\371\203\326z\007\305N\334\313\352y\361\203\306\326\340Y\310\301Qkdr\026\006C\221\366\343" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0F\002!\000\253-\250]\370\326d\314\034\177\\g\251E\237\211NN\032)R\260\232\345\355S\200\032l\')\266\002!\000\216\373\216\216>)\237\353\342wJo\256J\240\261\231\213\\\371C\352F\002\313\227\216\243E&\340\025" }
I0122 12:18:44.814585 15048 log_lookup.cc:105] Found 0 new log entries
I0122 12:18:44.814627 15048 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:18:44 2016
I0122 12:18:45.773937 15048 cluster_state_controller-inl.h:477] Can serve @2 with 3 nodes (100% of cluster)
I0122 12:18:45.774034 15071 cluster_state_controller-inl.h:528] Setting cluster serving STH @ 1453465125736
I0122 12:18:45.815841 15052 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465125736 tree_size: 2 sha256_root_hash: "\347\031\003\371\203\326z\007\305N\334\313\352y\361\203\306\326\340Y\310\301Qkdr\026\006C\221\366\343" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0D\002 !\211\032w4N\302q\223+\263\226{}\270Cd\230\313\000:\300_\371p\373\017\"\312?\230\320\002 ]DJ\023\232\340\357\267\341\272\'\"B\220\n\203`\244aGV%\253\n\311Z\324\035\3013\215*" }
---8<-----snip-------8<------

The other nodes are similar:

---8<-----snip-------8<------
I0122 12:17:14.961881 15096 log_lookup.cc:105] Found 0 new log entries
I0122 12:17:14.961920 15096 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:17:14 2016
I0122 12:17:15.778302 15092 cluster_state_controller-inl.h:477] Can serve @0 with 3 nodes (100% of cluster)
I0122 12:17:15.820073 15096 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465035736 tree_size: 0 sha256_root_hash: "\343\260\304B\230\374\034\024\232\373\364\310\231o\271$\'\256A\344d\233\223L\244\225\231\033xR\270U" signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0F\002!\000\204k<\275\024L\304\211\203\305\332\2340UT\277\'\315\032j\314B\220r\033\202\332\302\240\215\302^\002!\000\332\3330G\346,\336b\rm\217\243iu\312\367\021\367\260~\364\027A\363\353\312d\205\340^u6" }
I0122 12:17:15.861212 15096 log_lookup.cc:105] Found 0 new log entries
I0122 12:17:15.861255 15096 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:17:15 2016
I0122 12:17:25.773950 15091 cluster_state_controller-inl.h:477] Can serve @1 with 3 nodes (100% of cluster)
I0122 12:17:25.815917 15097 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465045736 tree_size: 1 sha256_root_hash: "\017q\203\221\2162^\277\241\037\220\200G(\336\226t\203[z\375hB+zJI5\232\277\362." signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0E\002!\000\216\227a\201l\257\024\327\277\035,7\362R\232\234P\311) \327\276\220\321y4\353\313\315\324\211\036\002 \t\025\024\020\305\256r\010\215\013\210\207\002\"P\024h\323\010n\235\342\235\363bU\372\n\221\273\232\247" }
I0122 12:17:25.860997 15097 log_lookup.cc:105] Found 1 new log entries
I0122 12:17:25.861038 15097 log_lookup.cc:112] Tree successfully updated at Fri Jan 22 12:17:25 2016
I0122 12:17:32.719032 15096 cluster_state_controller-inl.h:477] Can serve @1 with 3 nodes (100% of cluster)
I0122 12:17:32.819262 15097 cluster_state_controller-inl.h:350] Received new Serving STH: version: V1 id { key_id: "\337\034.\301\025\000\224RG\251ah2]\334\\yY\350\367\306\323\210\374\000.\013\275?t\327d" } timestamp: 1453465052643 tree_size: 1 sha256_root_hash: "\017q\203\221\2162^\277\241\037\220\200G(\336\226t\203[z\375hB+zJI5\232\277\362." signature { hash_algorithm: SHA256 sig_algorithm: ECDSA signature: "0E\002 H\277\005\337\t*\355\327\n\0259\\cIP\237\300\213G\001W\227\023\331A\2055$\262\304\247\305\002!\000\261\010\254\251\315\247\351\300\321\206\343\035\340\216\006\031\316H\006yz%\212\001\004\256\347\035+/,f" }
---8<-----snip-------8<------

@AlCutter
Copy link
Member

Hmm, upon closer inspection of your log, it looks like the xjson/adding elements stuff is actually a red herring - your node died because of a CHECK fail in part of the masterelection process (due to a connection expiring underneath.)

That's something we should definitely look at.

@AlCutter AlCutter added this to the production milestone Jan 22, 2016
@AlCutter
Copy link
Member

@pphaneuf, this looks like it's kinda related to your TODO at etcd.cc:233

@AndrewGorton
Copy link
Author

Log files retrieved.

ERROR.txt
FATAL.txt
INFO-filtered.txt
WARNING.txt

@AlCutter
Copy link
Member

One hypothesis is that a timeout gets set on the underlying connection, which is used and then dropped back into the connection pool, pulled out, reused, returned, etc. Meanwhile the timeout bomb sits there ticking away, and at some point in the future fires, even when there's an in-flight request happening. If that happens to be the proposal update request then it causes this CHECK.

@pphaneuf is going to take a look.

@razeencheng
Copy link

razeencheng commented Dec 28, 2017 •
edited
Loading

@AndrewGorton Hi, I've got the same problem. How can you solve it? Here is my logs

./prepare_etcd.sh

{"action":"set","node":{"key":"/root","dir":true,"modifiedIndex":8,"createdIndex":8}}
{"action":"set","node":{"key":"/root/entries","dir":true,"modifiedIndex":9,"createdIndex":9}}
{"action":"set","node":{"key":"/root/nodes","dir":true,"modifiedIndex":10,"createdIndex":10}}
{"action":"set","node":{"key":"/root/serving_sth","value":"","modifiedIndex":11,"createdIndex":11}}
{"action":"set","node":{"key":"/root/cluster_config","value":"","modifiedIndex":12,"createdIndex":12}}
{"action":"set","node":{"key":"/root/sequence_mapping","value":"","modifiedIndex":13,"createdIndex":13}}
I1228 09:11:42.020866    21 init.cc:71] Build version: 2ad95c3ae999cb0e65d505afc9fb5c6aa0d14cb4
I1228 09:11:42.020962    21 init.cc:73] Binary built with hardening enabled.
I1228 09:11:42.021451    21 thread_pool.cc:146] ThreadPool starting with 1 threads
W1228 09:11:42.021751    21 connection_pool.cc:261] Setting client minimum TLS protocol to tlsv12
I1228 09:11:42.021878    21 connection_pool.cc:293] Loading openssl default trusted root certificates...
I1228 09:11:42.023432    23 etcd.cc:1042] Etcd version: {"etcdserver":"2.1.3","etcdcluster":"2.1.0"}
I1228 09:11:42.046692    22 masterelection.cc:546] /election/clustertool: Became master
I1228 09:11:42.046767    21 thread_pool.cc:146] ThreadPool starting with 4 threads
I1228 09:11:42.075084    21 sqlite_db.cc:94] New SQLite database created in /tmp/clustertooldb
W1228 09:11:42.075184    21 sqlite_db.cc:145] SQLite "synchronous" pragma set to FULL
W1228 09:11:42.075208    21 sqlite_db.cc:148] SQLite running with batched transactions, you should set sqlite_synchronous_mode = FULL !
W1228 09:11:42.086040    21 clustertool_main.cc:114] Using default ClusterConfig
I1228 09:11:42.087329    21 clustertool_main.cc:128] Using config:
minimum_serving_nodes: 2
minimum_serving_fraction: 0.75
I1228 09:11:42.104226    21 clustertool_main.cc:181] OK
W1228 09:12:42.048451    22 connection_pool.cc:339] Releasing errored connection to etcdhost:4001
W1228 09:12:42.048554    22 connection_pool.cc:364] error flag (0x41): READING TIMEOUT : Success
W1228 09:12:42.048751    22 etcd.cc:798] Got invalid JSON:

main node logs after post data

I1228 09:27:14.926509    49 cluster_state_controller.cc:517] Setting cluster serving STH @ 1514453234915
I1228 09:27:14.936142    12 cluster_state_controller.cc:341] Received new Serving STH: version: V1 id { key_id: "Rx@`\363yB\312\247cz\273\243!\r\260\257\266\261\335m\032\303\362:\327\256~\364Sz(" } timestamp: 1514453234915 tree_size: 0 sha256_root_hash: "xxxxxxx" }
I1228 09:27:14.937818    12 log_lookup.cc:105] Found 0 new log entries
I1228 09:27:14.937829    12 log_lookup.cc:112] Tree successfully updated at Thu Dec 28 09:27:14 2017
I1228 09:27:24.308213    52 etcd_consistent_store.cc:784] Cleaning old entries up to and including sequence number: -1
I1228 09:27:34.308158    52 etcd_consistent_store.cc:784] Cleaning old entries up to and including sequence number: -1
I1228 09:27:44.308199    52 etcd_consistent_store.cc:784] Cleaning old entries up to and including sequence number: -1
I1228 09:27:44.308787     7 masterelection.cc:546] /root/election/7c9a77d1-f571-4efa-b31e-e21b9444ed9d: Became master
W1228 09:27:44.333364     7 connection_pool.cc:339] Releasing errored connection to node1:4001
W1228 09:27:44.333395     7 connection_pool.cc:364] error flag (0x41): READING TIMEOUT : Success
W1228 09:27:44.333447    11 etcd.cc:798] Got invalid JSON:
W1228 09:27:44.720068     7 connection_pool.cc:339] Releasing errored connection to node1:4001
W1228 09:27:44.720129     7 connection_pool.cc:364] error flag (0x41): READING TIMEOUT : Success
W1228 09:27:44.720213    12 etcd.cc:798] Got invalid JSON:
I1228 09:27:44.872859     7 masterelection.cc:546] /root/election/7c9a77d1-f571-4efa-b31e-e21b9444ed9d: Became master
I1228 09:27:44.950831    15 cluster_state_controller.cc:467] Can serve @0 with 2 nodes (100% of cluster)

another

I1228 09:30:09.295418     8 fetcher.cc:225] error fetching entries at index 0: UNKNOWN:
I1228 09:30:09.295658    10 fetcher.cc:225] error fetching entries at index 0: UNKNOWN:
I1228 09:30:09.332808    13 fetcher.cc:225] error fetching entries at index 0: UNKNOWN:
I1228 09:30:09.333170    14 fetcher.cc:225] error fetching entries at index 0: UNKNOWN:
I1228 09:30:09.333434    12 fetcher.cc:225] error fetching entries at index 0: UNKNOWN:
I1228 09:30:09.333684     9 fetcher.cc:225] error fetching entries at index 0: UNKNOWN:
I1228 09:30:09.333931    11 fetcher.cc:225] error fetching entries at index 0: UNKNOWN:
I1228 09:30:09.334175    15 fetcher.cc:225] error fetching entries at index 0: UNKNOWN:
I1228 09:30:09.334420     8 fetcher.cc:225] error fetching entries at index 0: UNKNOWN:
I1228 09:30:09.334666    10 fetcher.cc:225] error fetching entries at index 0: UNKNOWN:
I1228 09:30:09.334946    13 fetcher.cc:225] error fetching entries at index 0: UNKNOWN:

then , LogServer Fill the CPU !!!

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
12773 root      20   0  589m 196m  10m R 98.9 19.8   5:34.14 ct-server
12627 root      20   0 53732  38m 8416 S  0.7  3.9   4:44.50 etcd

@AndrewGorton
Copy link
Author

@razeencheng I never got it fixed and have moved on to something else. I hope you get it sorted somehow.

@AlCutter
Copy link
Member

AlCutter commented Jan 2, 2018

Hi @razeencheng, @AndrewGorton

I wanted to point you towards Trillian, which is an implementation of General Transparency (as opposed to xjson which was intended as an interim hack to experiment with transparency for non-certificate-like things).

We're actively working on Trillian, and you should find it a lot easier to work with.
There's also an implementation of a CT "personality" layer for Trillian, which should serve as a helpful example if you decided to build a personality for your transparency application on top of Trillian too.

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@pphaneuf pphaneuf

Labels
None yet
Projects
None yet
Milestone
production
Development

No branches or pull requests
4 participants
@pphaneuf @AndrewGorton @AlCutter @razeencheng