I'm trying to run eventstore in cluster mode under mono.
1. CentOS6 x86_64 (up to date);
2. mono-3.2.5;
3. eventstore build from git master branch (5433fdc82895c181e0325a5730d36424de8eb28f);
4. all cluster nodes (3 instances) running on the same machine.
1. nodes run in this order: run instance1, then wait 10 seconds and run instance2, then wait 10 seconds again and run instance3;
2. database is empty (all directories clean before start);
3. each instance running by follow cmdlines:
4. when run 1 or 2 any instances all looks like OK.
5. when run 3rd instance cluster falls to election loop (every few seconds cluster trying to elect new master).
6. no any failed processes occured while this experiment (no exits, no sigfaults, no core dumps).
7. no any writes from occurs in cluster from outside during all experiment time.Â
Logs for each instance follow.
# cat /srv/eventsore/db-cluster1-logs/2014-01-14/10.80.10.11-11004-cluster-node.logÂ
[PID:21080:001 2014.01.14 11:00:02.697 INFO Â ProgramBase`1 Â Â Â ]Â
ES VERSION: Â Â Â Â Â Â Â no-werror (master/5433fdc82895c181e0325a5730d36424de8eb28f, Fri, 10 Jan 2014 13:48:40 +0000)
OS: Â Â Â Â Â Â Â Â Â Â Â Unknown (Unix 2.6.32.431)
RUNTIME: Â Â Â Â Â Â Â Â Â 3.2.5 (tarball Thu Dec 12 12:56:24 MSK 2013) (64-bit)
GC: Â Â Â Â Â Â Â Â Â Â Â 2 GENERATIONS
LOGS: Â Â Â Â Â Â Â Â Â Â /srv/eventsore/db-cluster1-logs
SHOW HELP: Â Â Â Â Â Â Â Â False (<DEFAULT>)
SHOW VERSION: Â Â Â Â Â Â False (<DEFAULT>)
LOGS DIR: Â Â Â Â Â Â Â Â /srv/eventsore/db-cluster1-logs (--logsdir from command line)
CONFIGS: Â Â Â Â Â Â Â Â Â <empty> (<DEFAULT>)
DEFINES: Â Â Â Â Â Â Â Â Â <empty> (<DEFAULT>)
INTERNAL IP: Â Â Â Â Â Â Â 10.80.10.11 (--internal-ip from command line)
EXTERNAL IP: Â Â Â Â Â Â Â 10.80.10.11 (--external-ip from command line)
INTERNAL HTTP PORT: Â Â Â 11003 (--internal-http-port from command line)
EXTERNAL HTTP PORT: Â Â Â 11004 (--external-http-port from command line)
INTERNAL TCP PORT: Â Â Â Â 11001 (--internal-tcp-port from command line)
INTERNAL SECURE TCP PORT: 0 (<DEFAULT>)
EXTERNAL TCP PORT: Â Â Â Â 11002 (--external-tcp-port from command line)
EXTERNAL SECURE TCP PORT: 0 (<DEFAULT>)
FORCE: Â Â Â Â Â Â Â Â Â Â False (<DEFAULT>)
CLUSTER SIZE: Â Â Â Â Â Â 3 (--cluster-size from command line)
MIN FLUSH DELAY MS: Â Â Â 2 (<DEFAULT>)
NODE PRIORITY: Â Â Â Â Â Â 0 (<DEFAULT>)
COMMIT COUNT: Â Â Â Â Â Â 2 (<DEFAULT>)
PREPARE COUNT: Â Â Â Â Â Â 2 (<DEFAULT>)
DISCOVER VIA DNS: Â Â Â Â False (--use-dns-discovery from command line)
CLUSTER DNS: Â Â Â Â Â Â Â fake.dns (<DEFAULT>)
CLUSTER GOSSIP PORT: Â Â Â 30777 (<DEFAULT>)
STATS PERIOD SEC: Â Â Â Â 300 (--stats-period-sec from command line)
CACHED CHUNKS: Â Â Â Â Â Â -1 (<DEFAULT>)
CHUNKS CACHE SIZE: Â Â Â Â 536871424 (<DEFAULT>)
DB PATH: Â Â Â Â Â Â Â Â Â /srv/eventsore/db-cluster1 (--db from command line)
IN MEM DB: Â Â Â Â Â Â Â Â False (<DEFAULT>)
SKIP DB VERIFY: Â Â Â Â Â False (<DEFAULT>)
RUN PROJECTIONS: Â Â Â Â Â All (--run-projections from command line)
PROJECTION THREADS: Â Â Â 3 (<DEFAULT>)
WORKER THREADS: Â Â Â Â Â 5 (<DEFAULT>)
HTTP PREFIXES: Â Â Â Â Â Â <empty> (<DEFAULT>)
ENABLE TRUSTED AUTH: Â Â Â True (--enable-trusted-auth from command line)
CERTIFICATE STORE: Â Â Â Â <empty> (<DEFAULT>)
CERTIFICATE NAME: Â Â Â Â <empty> (<DEFAULT>)
CERTIFICATE FILE: Â Â Â Â <empty> (<DEFAULT>)
CERTIFICATE PASSWORD: Â Â <empty> (<DEFAULT>)
USE INTERNAL SSL: Â Â Â Â False (<DEFAULT>)
SSL TARGET HOST: Â Â Â Â Â n/a (<DEFAULT>)
SSL VALIDATE SERVER: Â Â Â True (<DEFAULT>)
AUTHENTICATION TYPE: Â Â Â internal (<DEFAULT>)
AUTHENTICATION CONFIG FILE: <empty> (<DEFAULT>)
PREPARE TIMEOUT MS: Â Â Â 2000 (<DEFAULT>)
COMMIT TIMEOUT MS: Â Â Â Â 2000 (<DEFAULT>)
DISABLE SCAVENGE MERGING: False (<DEFAULT>)
[PID:21080:001 2014.01.14 11:00:02.782 INFO Â ProgramBase`1 Â Â Â ] Quorum size set to 2
[PID:21080:001 2014.01.14 11:00:02.798 INFO Â ProgramBase`1 Â Â Â ] Can't find plugins path: /opt/eventstore/eventstore-mono-20140114.1110/plugins
[PID:21080:001 2014.01.14 11:00:02.874 INFO Â ProgramBase`1 Â Â Â ]Â
INSTANCE ID: Â Â Â Â Â Â Â 46577878-07ac-4f88-9a42-8889a62e649e
DATABASE: Â Â Â Â Â Â Â Â /srv/eventsore/db-cluster1
WRITER CHECKPOINT: Â Â Â Â 0 (0x0)
CHASER CHECKPOINT: Â Â Â Â 0 (0x0)
EPOCH CHECKPOINT: Â Â Â Â -1 (0xFFFFFFFFFFFFFFFF)
TRUNCATE CHECKPOINT: Â Â Â -1 (0xFFFFFFFFFFFFFFFF)
[PID:21080:001 2014.01.14 11:00:03.165 TRACE MessageHierarchy   ] MessageHierarchy initialization took 00:00:00.2243466.
[PID:21080:001 2014.01.14 11:00:03.325 TRACE TFChunk       ] CACHED TFChunk #0-0 (chunk-000000.000000) in 00:00:00.0040912.
[PID:21080:001 2014.01.14 11:00:03.563 INFO  MiniWeb       ] Starting MiniWeb for /web/es/js/projections ==> /opt/eventstore/current/singlenode-web/js/projections
[PID:21080:001 2014.01.14 11:00:03.565 INFO  MiniWeb       ] Starting MiniWeb for /web/es/js/projections/v8/Prelude ==> /opt/eventstore/current/Prelude
[PID:21080:001 2014.01.14 11:00:03.565 INFO  MiniWeb       ] Starting MiniWeb for /web/es/js/projections/resources ==> /opt/eventstore/current/web-resources/js
[PID:21080:001 2014.01.14 11:00:03.567 TRACE MiniWeb       ] Binding MiniWeb to /web/es/js/projections/{*remaining_path}
[PID:21080:001 2014.01.14 11:00:03.567 TRACE MiniWeb       ] Binding MiniWeb to /web/es/js/projections/v8/Prelude/{*remaining_path}
[PID:21080:001 2014.01.14 11:00:03.568 TRACE MiniWeb       ] Binding MiniWeb to /web/es/js/projections/resources/{*remaining_path}
[PID:21080:001 2014.01.14 11:00:03.569 TRACE MiniWeb       ] Binding MiniWeb to /web/es/js/projections/{*remaining_path}
[PID:21080:001 2014.01.14 11:00:03.569 TRACE MiniWeb       ] Binding MiniWeb to /web/es/js/projections/v8/Prelude/{*remaining_path}
[PID:21080:001 2014.01.14 11:00:03.569 TRACE MiniWeb       ] Binding MiniWeb to /web/es/js/projections/resources/{*remaining_path}
[PID:21080:001 2014.01.14 11:00:03.575 INFO  MiniWeb       ] Starting MiniWeb for /web ==> /opt/eventstore/current/clusternode-web
[PID:21080:001 2014.01.14 11:00:03.575 INFO  MiniWeb       ] Starting MiniWeb for /web/es ==> /opt/eventstore/current/es-common-web
[PID:21080:001 2014.01.14 11:00:03.575 TRACE MiniWeb       ] Binding MiniWeb to /web/{*remaining_path}
[PID:21080:001 2014.01.14 11:00:03.575 TRACE MiniWeb       ] Binding MiniWeb to /web/es/{*remaining_path}
[PID:21080:001 2014.01.14 11:00:03.576 INFO  MiniWeb       ] Starting MiniWeb for /web ==> /opt/eventstore/current/clusternode-web
[PID:21080:001 2014.01.14 11:00:03.576 INFO  MiniWeb       ] Starting MiniWeb for /web/es ==> /opt/eventstore/current/es-common-web
[PID:21080:001 2014.01.14 11:00:03.576 TRACE MiniWeb       ] Binding MiniWeb to /web/{*remaining_path}
[PID:21080:001 2014.01.14 11:00:03.576 TRACE MiniWeb       ] Binding MiniWeb to /web/es/{*remaining_path}
[PID:21080:001 2014.01.14 11:00:03.577 INFO  MiniWeb       ] Starting MiniWeb for /web/users ==> /opt/eventstore/current/Users/web
[PID:21080:001 2014.01.14 11:00:03.577 TRACE MiniWeb       ] Binding MiniWeb to /web/users/{*remaining_path}
[PID:21080:001 2014.01.14 11:00:03.577 INFO  MiniWeb       ] Starting MiniWeb for /web/users ==> /opt/eventstore/current/Users/web
[PID:21080:001 2014.01.14 11:00:03.577 TRACE MiniWeb       ] Binding MiniWeb to /web/users/{*remaining_path}
[PID:21080:010 2014.01.14 11:00:03.623 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:11003] SYSTEM INIT...
[PID:21080:010 2014.01.14 11:00:03.664 INFO  TcpServerListener  ] Starting Normal TCP listening on TCP endpoint:
10.80.10.11:11002.
[PID:21080:015 2014.01.14 11:00:03.703 INFO  IndexCommitter    ] TableIndex initialization...
[PID:21080:015 2014.01.14 11:00:03.728 INFO  IndexCommitter    ] ReadIndex building...
[PID:21080:015 2014.01.14 11:00:03.732 DEBUG IndexCommitter    ] ReadIndex rebuilding done: total processed 0 records, time elapsed: 00:00:00.0034520.
[PID:21080:010 2014.01.14 11:00:03.749 TRACE InMemoryBus     ] SLOW BUS MSG [MainBus]: SystemInit - 53ms. Handler: TcpService.
[PID:21080:010 2014.01.14 11:00:03.749 INFO  TcpServerListener  ] Starting Normal TCP listening on TCP endpoint:
10.80.10.11:11001.
[PID:21080:010 2014.01.14 11:00:03.789 INFO  HttpAsyncServer   ] HTTP server is up and listening on [
http://10.80.10.11:11004/]
[PID:21080:010 2014.01.14 11:00:03.790 INFO  HttpAsyncServer   ] HTTP server is up and listening on [
http://10.80.10.11:11003/]
[PID:21080:010 2014.01.14 11:00:03.830 TRACE QueuedHandlerAutoRes] SLOW QUEUE MSG [MainQueue]: SystemInit - 214ms. Q: 0/7.
[PID:21080:010 2014.01.14 11:00:03.832 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:11003] Service 'StorageReader' initialized.
[PID:21080:010 2014.01.14 11:00:03.832 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:11003] Service 'StorageWriter' initialized.
[PID:21080:010 2014.01.14 11:00:03.832 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:11003] Service 'StorageChaser' initialized.
[PID:21080:010 2014.01.14 11:00:03.895 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:03.899 TRACE InMemoryBus     ] SLOW BUS MSG [MainBus]: GotGossipSeedSources - 64ms. Handler: NodeGossipService.
[PID:21080:010 2014.01.14 11:00:03.899 TRACE QueuedHandlerAutoRes] SLOW QUEUE MSG [MainQueue]: GotGossipSeedSources - 65ms. Q: 1/3.
[PID:21080:010 2014.01.14 11:00:03.900 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:11003] SYSTEM START...
[PID:21080:010 2014.01.14 11:00:03.904 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:11003] IS UNKNOWN!!! WHOA!!!
[PID:21080:010 2014.01.14 11:00:03.977 DEBUG ElectionsService   ] ELECTIONS: STARTING ELECTIONS.
[PID:21080:010 2014.01.14 11:00:03.978 DEBUG ElectionsService   ] ELECTIONS: (V=0) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:03.981 DEBUG ElectionsService   ] ELECTIONS: (V=0) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:03.987 TRACE InMemoryBus     ] SLOW BUS MSG [MainBus]: StartElections - 75ms. Handler: ElectionsService.
[PID:21080:010 2014.01.14 11:00:03.987 TRACE QueuedHandlerAutoRes] SLOW QUEUE MSG [MainQueue]: StartElections - 75ms. Q: 0/2.
[PID:21080:006 2014.01.14 11:00:04.199 TRACE InMemoryBus     ] SLOW BUS MSG [Worker #1 Bus]: SendOverHttp - 290ms. Handler: HttpSendService.
[PID:21080:006 2014.01.14 11:00:04.239 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [Worker #1]: SendOverHttp - 290ms. Q: 0/0.
[PID:21080:010 2014.01.14 11:00:04.726 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:12003] is DEAD (Gossip send failed).
[PID:21080:010 2014.01.14 11:00:04.727 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip send failed to [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:04.740 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:13003] is DEAD (Gossip send failed).
[PID:21080:010 2014.01.14 11:00:04.740 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip send failed to [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:04.989 DEBUG ElectionsService   ] ELECTIONS: (V=0) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:04.989 DEBUG ElectionsService   ] ELECTIONS: (V=1) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:04.989 DEBUG ElectionsService   ] ELECTIONS: (V=1) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:05.991 DEBUG ElectionsService   ] ELECTIONS: (V=1) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:05.991 DEBUG ElectionsService   ] ELECTIONS: (V=2) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:05.991 DEBUG ElectionsService   ] ELECTIONS: (V=2) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:06.991 DEBUG ElectionsService   ] ELECTIONS: (V=2) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:06.991 DEBUG ElectionsService   ] ELECTIONS: (V=3) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:06.991 DEBUG ElectionsService   ] ELECTIONS: (V=3) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:07.992 DEBUG ElectionsService   ] ELECTIONS: (V=3) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:07.992 DEBUG ElectionsService   ] ELECTIONS: (V=4) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:07.992 DEBUG ElectionsService   ] ELECTIONS: (V=4) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:08.994 DEBUG ElectionsService   ] ELECTIONS: (V=4) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:08.994 DEBUG ElectionsService   ] ELECTIONS: (V=5) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:08.994 DEBUG ElectionsService   ] ELECTIONS: (V=5) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:09.995 DEBUG ElectionsService   ] ELECTIONS: (V=5) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:09.995 DEBUG ElectionsService   ] ELECTIONS: (V=6) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:09.995 DEBUG ElectionsService   ] ELECTIONS: (V=6) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:10.996 DEBUG ElectionsService   ] ELECTIONS: (V=6) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:10.996 DEBUG ElectionsService   ] ELECTIONS: (V=7) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:10.996 DEBUG ElectionsService   ] ELECTIONS: (V=7) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:11.998 DEBUG ElectionsService   ] ELECTIONS: (V=7) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:11.998 DEBUG ElectionsService   ] ELECTIONS: (V=8) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:11.998 DEBUG ElectionsService   ] ELECTIONS: (V=8) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:12.999 DEBUG ElectionsService   ] ELECTIONS: (V=8) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:12.999 DEBUG ElectionsService   ] ELECTIONS: (V=9) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:12.999 DEBUG ElectionsService   ] ELECTIONS: (V=9) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:14.000 DEBUG ElectionsService   ] ELECTIONS: (V=9) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:14.000 DEBUG ElectionsService   ] ELECTIONS: (V=10) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:14.000 DEBUG ElectionsService   ] ELECTIONS: (V=10) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:15.001 DEBUG ElectionsService   ] ELECTIONS: (V=10) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:15.001 DEBUG ElectionsService   ] ELECTIONS: (V=11) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:15.001 DEBUG ElectionsService   ] ELECTIONS: (V=11) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:16.002 DEBUG ElectionsService   ] ELECTIONS: (V=11) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:16.002 DEBUG ElectionsService   ] ELECTIONS: (V=12) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:16.002 DEBUG ElectionsService   ] ELECTIONS: (V=12) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:019 2014.01.14 11:00:16.106 ERROR GossipController   ] Received as POST invalid ClusterInfo from [
http://10.80.10.11:11003/gossip]. Content-Type: application/json, Body:
.
[PID:21080:010 2014.01.14 11:00:17.003 DEBUG ElectionsService   ] ELECTIONS: (V=12) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:17.003 DEBUG ElectionsService   ] ELECTIONS: (V=13) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:17.003 DEBUG ElectionsService   ] ELECTIONS: (V=13) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:18.005 DEBUG ElectionsService   ] ELECTIONS: (V=13) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:18.005 DEBUG ElectionsService   ] ELECTIONS: (V=14) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:18.005 DEBUG ElectionsService   ] ELECTIONS: (V=14) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:18.485 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:18.493 DEBUG ElectionsService   ] ELECTIONS: (V=3) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21080:010 2014.01.14 11:00:18.493 DEBUG ElectionsService   ] ELECTIONS: (V=3) MAJORITY OF VIEWCHANGE.
[PID:21080:010 2014.01.14 11:00:19.005 DEBUG ElectionsService   ] ELECTIONS: (V=14) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:19.005 DEBUG ElectionsService   ] ELECTIONS: (V=15) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:19.005 DEBUG ElectionsService   ] ELECTIONS: (V=15) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:19.019 DEBUG ElectionsService   ] ELECTIONS: (V=15) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21080:010 2014.01.14 11:00:19.019 DEBUG ElectionsService   ] ELECTIONS: (V=15) MAJORITY OF VIEWCHANGE.
[PID:21080:010 2014.01.14 11:00:19.019 DEBUG ElectionsService   ] ELECTIONS: (V=15) SHIFT TO PREPARE PHASE.
[PID:21080:010 2014.01.14 11:00:19.021 DEBUG ElectionsService   ] ELECTIONS: (V=15) PREPARE_OK FROM [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=-1,W=0,C=0,E-1@-1:{00000000-0000-0000-0000-000000000000}).
[PID:21080:010 2014.01.14 11:00:19.051 DEBUG ElectionsService   ] ELECTIONS: (V=15) PREPARE_OK FROM [
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}](L=-1,W=0,C=0,E-1@-1:{00000000-0000-0000-0000-000000000000}).
[PID:21080:010 2014.01.14 11:00:19.051 DEBUG ElectionsService   ] ELECTIONS: (V=15) SHIFT TO REG_LEADER.
[PID:21080:010 2014.01.14 11:00:19.066 DEBUG ElectionsService   ] ELECTIONS: (V=15) SENDING PROPOSAL CANDIDATE: [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=-1,W=0,C=0,E-1@-1:{00000000-0000-0000-0000-000000000000}), ME: [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=-1,W=0,C=0,E-1@-1:{00000000-0000-0000-0000-000000000000}).
[PID:21080:010 2014.01.14 11:00:19.067 DEBUG ElectionsService   ] ELECTIONS: (V=15) ACCEPT FROM [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]).
[PID:21080:010 2014.01.14 11:00:19.140 DEBUG ElectionsService   ] ELECTIONS: (V=15) ACCEPT FROM [
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]).
[PID:21080:010 2014.01.14 11:00:19.140 INFO  ElectionsService   ] ELECTIONS: (V=15) DONE. ELECTED MASTER = [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=-1,W=0,C=0,E-1@-1:{00000000-0000-0000-0000-000000000000}). ME=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=-1,W=0,C=0,E-1@-1:{00000000-0000-0000-0000-000000000000}).
[PID:21080:010 2014.01.14 11:00:19.143 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:11003] PRE-MASTER STATE, WAITING FOR CHASER TO CATCH UP...
[PID:21080:010 2014.01.14 11:00:19.147 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:11003] IS MASTER!!! SPARTA!!!
[PID:21080:007 2014.01.14 11:00:19.280 DEBUG EpochManager     ] === Writing E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691} (previous epoch at -1).
[PID:21080:010 2014.01.14 11:00:19.305 TRACE InMemoryBus     ] SLOW BUS MSG [MainBus]: ReadStreamEventsBackwardCompleted - 91ms. Handler: RequestResponseDispatcher`2.
[PID:21080:010 2014.01.14 11:00:19.305 TRACE QueuedHandlerAutoRes] SLOW QUEUE MSG [MainQueue]: ReadStreamEventsBackwardCompleted - 91ms. Q: 0/4.
[PID:21080:007 2014.01.14 11:00:19.314 DEBUG EpochManager     ] === Update Last Epoch E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691} (previous epoch at -1).
[PID:21080:010 2014.01.14 11:00:19.317 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:011 2014.01.14 11:00:19.359 INFO  ProjectionManager  ] Projection manager is initializing from the empty $projections-$all stream
[PID:21080:011 2014.01.14 11:00:19.361 TRACE InMemoryBus     ] SLOW BUS MSG [manager input bus]: ReadStreamEventsBackwardCompleted - 118ms. Handler: ProjectionManager.
[PID:21080:011 2014.01.14 11:00:19.361 TRACE QueuedHandlerAutoRes] SLOW QUEUE MSG [Projections Master]: ReadStreamEventsBackwardCompleted - 118ms. Q: 0/1.
[PID:21080:020 2014.01.14 11:00:19.417 INFO  TcpService      ] Internal TCP connection accepted: [Normal,
10.80.10.11:58542, L10.80.10.11:11001, {d7625929-cb01-4cc5-9564-90ca98ddff82}].
[PID:21080:010 2014.01.14 11:00:19.626 INFO Â MasterReplicationSer] SUBSCRIBE REQUEST from [
10.80.10.11:12001,C:{d7625929-cb01-4cc5-9564-90ca98ddff82},S:{c06aaa47-83d5-426a-9bc5-514cddc08970},0(0x0),]...
[PID:21080:010 2014.01.14 11:00:19.632 INFO Â MasterReplicationSer] Subscribed replica [
10.80.10.11:12001,S:c06aaa47-83d5-426a-9bc5-514cddc08970] for data send at 0 (0x0).
[PID:21080:010 2014.01.14 11:00:19.648 TRACE InMemoryBus     ] SLOW BUS MSG [MainBus]: ReplicaSubscriptionRequest - 63ms. Handler: MasterReplicationService.
[PID:21080:010 2014.01.14 11:00:19.653 TRACE QueuedHandlerAutoRes] SLOW QUEUE MSG [MainQueue]: ReplicaSubscriptionRequest - 69ms. Q: 0/1.
[PID:21080:010 2014.01.14 11:00:19.940 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:011 2014.01.14 11:00:21.884 FATAL ProjectionManager  ] Cannot initialize projections subsystem. Cannot write a fake projection
[PID:21080:024 2014.01.14 11:00:21.909 DEBUG MonitoringService  ] Failed to create stats stream '$stats-10.80.10.11:11004'. Reason : CommitTimeout(Commit phase timeout.). Retrying...
[PID:21080:019 2014.01.14 11:00:21.912 TRACE MonitoringService  ] Created stats stream '$stats-10.80.10.11:11004', code = WrongExpectedVersion
[PID:21080:010 2014.01.14 11:00:21.978 INFO Â UserManagementServic] 'admin' user account has been created
[PID:21080:010 2014.01.14 11:00:22.940 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:29.650 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:30.925 DEBUG ElectionsService   ] ELECTIONS: (V=15) PREPARE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21080:010 2014.01.14 11:00:33.074 DEBUG ElectionsService   ] ELECTIONS: (V=16) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21080:010 2014.01.14 11:00:33.074 DEBUG ElectionsService   ] ELECTIONS: (V=16) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:33.074 DEBUG ElectionsService   ] ELECTIONS: (V=16) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:33.074 DEBUG ElectionsService   ] ELECTIONS: (V=16) MAJORITY OF VIEWCHANGE.
[PID:21080:010 2014.01.14 11:00:33.075 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:33.921 DEBUG ElectionsService   ] ELECTIONS: (V=18) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21080:010 2014.01.14 11:00:33.921 DEBUG ElectionsService   ] ELECTIONS: (V=18) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:33.921 DEBUG ElectionsService   ] ELECTIONS: (V=18) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:33.921 DEBUG ElectionsService   ] ELECTIONS: (V=18) MAJORITY OF VIEWCHANGE.
[PID:21080:010 2014.01.14 11:00:33.925 DEBUG ElectionsService   ] ELECTIONS: (V=18) PREPARE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21080:010 2014.01.14 11:00:33.925 DEBUG ElectionsService   ] ELECTIONS: (V=18) SHIFT TO REG_NONLEADER.
[PID:21080:010 2014.01.14 11:00:33.931 DEBUG ElectionsService   ] ELECTIONS: (V=18) PROPOSAL FROM [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1115,C=1115,E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}). ME=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1115,C=1115,E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}).
[PID:21080:010 2014.01.14 11:00:33.931 DEBUG ElectionsService   ] ELECTIONS: (V=18) ACCEPT FROM [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]).
[PID:21080:010 2014.01.14 11:00:33.931 DEBUG ElectionsService   ] ELECTIONS: (V=18) ACCEPT FROM [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]).
[PID:21080:010 2014.01.14 11:00:33.931 INFO  ElectionsService   ] ELECTIONS: (V=18) DONE. ELECTED MASTER = [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1115,C=1115,E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}). ME=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1115,C=1115,E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}).
[PID:21080:007 2014.01.14 11:00:33.933 DEBUG EpochManager     ] === Writing E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09} (previous epoch at 0).
[PID:21080:007 2014.01.14 11:00:33.937 DEBUG EpochManager     ] === Update Last Epoch E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09} (previous epoch at 0).
[PID:21080:024 2014.01.14 11:00:33.973 INFO  TcpService      ] Internal TCP connection accepted: [Normal,
10.80.10.11:58563, L10.80.10.11:11001, {0ffeb680-6923-4487-a0a7-9ef5b0e81688}].
[PID:21080:010 2014.01.14 11:00:34.165 INFO Â MasterReplicationSer] SUBSCRIBE REQUEST from [
10.80.10.11:13001,C:{0ffeb680-6923-4487-a0a7-9ef5b0e81688},S:{16525da7-0533-4bdc-b46c-24e639a186fc},0(0x0),]...
[PID:21080:010 2014.01.14 11:00:34.165 INFO Â MasterReplicationSer] Subscribed replica [
10.80.10.11:13001,S:16525da7-0533-4bdc-b46c-24e639a186fc] for data send at 0 (0x0).
[PID:21080:010 2014.01.14 11:00:34.360 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:025 2014.01.14 11:00:35.065 INFO  TcpConnection    ] ES TcpConnection closed [11:00:35.025: N10.80.10.11:58542, L10.80.10.11:11001, {d7625929-cb01-4cc5-9564-90ca98ddff82}]:
Received bytes: 815, Sent bytes: 2292
Send calls: 26, callbacks: 26
Receive calls: 21, callbacks: 21
Close reason: [Success] Socket closed
[PID:21080:025 2014.01.14 11:00:35.109 INFO Â TcpConnectionManager] Connection 'internal-normal' [
10.80.10.11:58542, {d7625929-cb01-4cc5-9564-90ca98ddff82}] closed: Success.
[PID:21080:024 2014.01.14 11:00:35.528 INFO  TcpService      ] Internal TCP connection accepted: [Normal,
10.80.10.11:58565, L10.80.10.11:11001, {bc820394-d79a-4f78-9766-10e1b446e4e8}].
[PID:21080:010 2014.01.14 11:00:35.916 INFO Â MasterReplicationSer] SUBSCRIBE REQUEST from [
10.80.10.11:12001,C:{bc820394-d79a-4f78-9766-10e1b446e4e8},S:{d38466a5-b4e0-49e2-9d62-9346d9dc28cf},1115(0x45B),E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}]...
[PID:21080:010 2014.01.14 11:00:35.917 INFO Â MasterReplicationSer] Subscribed replica [
10.80.10.11:12001,S:d38466a5-b4e0-49e2-9d62-9346d9dc28cf] for data send at 1115 (0x45B).
[PID:21080:010 2014.01.14 11:00:35.917 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:35.926 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:35.929 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:35.953 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:36.083 DEBUG ElectionsService   ] ELECTIONS: (V=20) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21080:010 2014.01.14 11:00:36.083 DEBUG ElectionsService   ] ELECTIONS: (V=20) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:36.083 DEBUG ElectionsService   ] ELECTIONS: (V=20) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:36.083 DEBUG ElectionsService   ] ELECTIONS: (V=20) MAJORITY OF VIEWCHANGE.
[PID:21080:010 2014.01.14 11:00:36.084 DEBUG ElectionsService   ] ELECTIONS: (V=20) SHIFT TO PREPARE PHASE.
[PID:21080:010 2014.01.14 11:00:36.084 DEBUG ElectionsService   ] ELECTIONS: (V=20) PREPARE_OK FROM [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1327,C=1327,E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}).
[PID:21080:010 2014.01.14 11:00:37.085 DEBUG ElectionsService   ] ELECTIONS: (V=20) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:37.085 DEBUG ElectionsService   ] ELECTIONS: (V=21) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:37.085 DEBUG ElectionsService   ] ELECTIONS: (V=21) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:37.751 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:12003] is DEAD (Gossip send failed).
[PID:21080:010 2014.01.14 11:00:37.751 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip send failed to [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:008 2014.01.14 11:00:37.934 TRACE TcpConnectionManager] Closing connection 'internal-normal' [
10.80.10.11:58565, L10.80.10.11:11001, {bc820394-d79a-4f78-9766-10e1b446e4e8}] cleanly. Reason: HEARTBEAT TIMEOUT at msgNum 2
[PID:21080:008 2014.01.14 11:00:37.934 INFO  TcpConnection    ] ES TcpConnection closed [11:00:37.934: N10.80.10.11:58565, L10.80.10.11:11001, {bc820394-d79a-4f78-9766-10e1b446e4e8}]:
Received bytes: 470, Sent bytes: 639
Send calls: 5, callbacks: 4
Receive calls: 3, callbacks: 2
Close reason: [Success] HEARTBEAT TIMEOUT at msgNum 2
[PID:21080:008 2014.01.14 11:00:37.935 INFO Â TcpConnectionManager] Connection 'internal-normal' [
10.80.10.11:58565, {bc820394-d79a-4f78-9766-10e1b446e4e8}] closed: Success.
[PID:21080:025 2014.01.14 11:00:38.086 INFO  TcpConnection    ] ES TcpConnection closed [11:00:38.086: N10.80.10.11:58563, L10.80.10.11:11001, {0ffeb680-6923-4487-a0a7-9ef5b0e81688}]:
Received bytes: 635, Sent bytes: 1856
Send calls: 9, callbacks: 8
Receive calls: 11, callbacks: 11
Close reason: [Success] Socket closed
[PID:21080:025 2014.01.14 11:00:38.086 INFO Â TcpConnectionManager] Connection 'internal-normal' [
10.80.10.11:58563, {0ffeb680-6923-4487-a0a7-9ef5b0e81688}] closed: Success.
[PID:21080:025 2014.01.14 11:00:38.087 INFO  TcpService      ] Internal TCP connection accepted: [Normal,
10.80.10.11:58574, L10.80.10.11:11001, {00188fce-2f0b-4592-89ef-828491f74017}].
[PID:21080:010 2014.01.14 11:00:38.090 DEBUG ElectionsService   ] ELECTIONS: (V=21) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21080:010 2014.01.14 11:00:38.090 DEBUG ElectionsService   ] ELECTIONS: (V=21) MAJORITY OF VIEWCHANGE.
[PID:21080:010 2014.01.14 11:00:38.090 DEBUG ElectionsService   ] ELECTIONS: (V=21) SHIFT TO PREPARE PHASE.
[PID:21080:010 2014.01.14 11:00:38.090 DEBUG ElectionsService   ] ELECTIONS: (V=21) PREPARE_OK FROM [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1327,C=1327,E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}).
[PID:21080:010 2014.01.14 11:00:38.097 DEBUG ElectionsService   ] ELECTIONS: (V=21) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:38.097 DEBUG ElectionsService   ] ELECTIONS: (V=22) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:38.097 DEBUG ElectionsService   ] ELECTIONS: (V=22) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:38.098 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:13001] is DEAD (TCP connection lost).
[PID:21080:010 2014.01.14 11:00:38.099 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (TCP connection lost to [
10.80.10.11:13001])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:38.247 INFO Â MasterReplicationSer] SUBSCRIBE REQUEST from [
10.80.10.11:13001,C:{00188fce-2f0b-4592-89ef-828491f74017},S:{5cb33487-749b-4dfe-b6e3-9a0adbe4a384},1327(0x52F),E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}, E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}]...
[PID:21080:010 2014.01.14 11:00:38.247 INFO Â MasterReplicationSer] Subscribed replica [
10.80.10.11:13001,S:5cb33487-749b-4dfe-b6e3-9a0adbe4a384] for data send at 1327 (0x52F).
[PID:21080:010 2014.01.14 11:00:38.247 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (TCP connection established to [
10.80.10.11:13001])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:38.259 DEBUG ElectionsService   ] ELECTIONS: (V=22) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21080:010 2014.01.14 11:00:38.264 DEBUG ElectionsService   ] ELECTIONS: (V=22) MAJORITY OF VIEWCHANGE.
[PID:21080:010 2014.01.14 11:00:38.366 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:027 2014.01.14 11:00:38.437 INFO  TcpService      ] Internal TCP connection accepted: [Normal,
10.80.10.11:58584, L10.80.10.11:11001, {ea965b9a-9857-4b15-a335-e9a3c7a89e0a}].
[PID:21080:010 2014.01.14 11:00:38.912 INFO Â MasterReplicationSer] SUBSCRIBE REQUEST from [
10.80.10.11:12001,C:{ea965b9a-9857-4b15-a335-e9a3c7a89e0a},S:{7bf45ec7-421b-457d-9788-ffcbb1fb5437},1327(0x52F),E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}, E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}]...
[PID:21080:010 2014.01.14 11:00:38.912 INFO Â MasterReplicationSer] Subscribed replica [
10.80.10.11:12001,S:7bf45ec7-421b-457d-9788-ffcbb1fb5437] for data send at 1327 (0x52F).
[PID:21080:010 2014.01.14 11:00:39.099 DEBUG ElectionsService   ] ELECTIONS: (V=22) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:39.099 DEBUG ElectionsService   ] ELECTIONS: (V=23) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:39.099 DEBUG ElectionsService   ] ELECTIONS: (V=23) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:39.414 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:40.079 DEBUG ElectionsService   ] ELECTIONS: (V=23) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21080:010 2014.01.14 11:00:40.079 DEBUG ElectionsService   ] ELECTIONS: (V=23) MAJORITY OF VIEWCHANGE.
[PID:21080:010 2014.01.14 11:00:40.079 DEBUG ElectionsService   ] ELECTIONS: (V=23) SHIFT TO PREPARE PHASE.
[PID:21080:010 2014.01.14 11:00:40.079 DEBUG ElectionsService   ] ELECTIONS: (V=23) PREPARE_OK FROM [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1327,C=1327,E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}).
[PID:21080:010 2014.01.14 11:00:40.100 DEBUG ElectionsService   ] ELECTIONS: (V=23) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:40.100 DEBUG ElectionsService   ] ELECTIONS: (V=24) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:40.100 DEBUG ElectionsService   ] ELECTIONS: (V=24) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:008 2014.01.14 11:00:40.839 TRACE TcpConnectionManager] Closing connection 'internal-normal' [
10.80.10.11:58584, L10.80.10.11:11001, {ea965b9a-9857-4b15-a335-e9a3c7a89e0a}] cleanly. Reason: HEARTBEAT TIMEOUT at msgNum 1
[PID:21080:008 2014.01.14 11:00:40.839 INFO  TcpConnection    ] ES TcpConnection closed [11:00:40.840: N10.80.10.11:58584, L10.80.10.11:11001, {ea965b9a-9857-4b15-a335-e9a3c7a89e0a}]:
Received bytes: 135, Sent bytes: 199
Send calls: 3, callbacks: 3
Receive calls: 2, callbacks: 1
Close reason: [Success] HEARTBEAT TIMEOUT at msgNum 1
[PID:21080:008 2014.01.14 11:00:40.839 INFO Â TcpConnectionManager] Connection 'internal-normal' [
10.80.10.11:58584, {ea965b9a-9857-4b15-a335-e9a3c7a89e0a}] closed: Success.
[PID:21080:010 2014.01.14 11:00:40.841 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:12001] is DEAD (TCP connection lost).
[PID:21080:010 2014.01.14 11:00:40.841 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (TCP connection lost to [
10.80.10.11:12001])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:41.101 DEBUG ElectionsService   ] ELECTIONS: (V=24) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:41.101 DEBUG ElectionsService   ] ELECTIONS: (V=25) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:41.101 DEBUG ElectionsService   ] ELECTIONS: (V=25) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:41.761 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:13003] is DEAD (Gossip send failed).
[PID:21080:010 2014.01.14 11:00:41.761 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip send failed to [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:41.761 DEBUG ElectionsService   ] ELECTIONS: (V=24) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21080:010 2014.01.14 11:00:41.761 DEBUG ElectionsService   ] ELECTIONS: (V=24) MAJORITY OF VIEWCHANGE.
[PID:21080:010 2014.01.14 11:00:41.761 DEBUG ElectionsService   ] ELECTIONS: (V=25) SHIFT TO PREPARE PHASE.
[PID:21080:010 2014.01.14 11:00:41.761 DEBUG ElectionsService   ] ELECTIONS: (V=25) PREPARE_OK FROM [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1327,C=1327,E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}).
[PID:21080:010 2014.01.14 11:00:42.088 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:42.088 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:42.101 DEBUG ElectionsService   ] ELECTIONS: (V=25) PREPARE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21080:010 2014.01.14 11:00:42.101 DEBUG ElectionsService   ] ELECTIONS: (V=25) SHIFT TO REG_NONLEADER.
[PID:21080:010 2014.01.14 11:00:42.101 DEBUG ElectionsService   ] ELECTIONS: (V=25) PROPOSAL FROM [
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1327,C=1327,E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}). ME=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1327,C=1327,E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}).
[PID:21080:010 2014.01.14 11:00:42.101 DEBUG ElectionsService   ] ELECTIONS: (V=25) ACCEPT FROM [
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]).
[PID:21080:010 2014.01.14 11:00:42.101 DEBUG ElectionsService   ] ELECTIONS: (V=25) ACCEPT FROM [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]).
[PID:21080:010 2014.01.14 11:00:42.101 INFO  ElectionsService   ] ELECTIONS: (V=25) DONE. ELECTED MASTER = [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1327,C=1327,E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}). ME=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1327,C=1327,E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}).
[PID:21080:007 2014.01.14 11:00:42.108 DEBUG EpochManager     ] === Writing E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843} (previous epoch at 1115).
[PID:21080:007 2014.01.14 11:00:42.114 DEBUG EpochManager     ] === Update Last Epoch E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843} (previous epoch at 1115).
[PID:21080:029 2014.01.14 11:00:42.419 INFO  TcpService      ] Internal TCP connection accepted: [Normal,
10.80.10.11:58601, L10.80.10.11:11001, {ee53eee2-d810-49d7-b173-7f68b31e87f1}].
[PID:21080:010 2014.01.14 11:00:42.923 INFO Â MasterReplicationSer] SUBSCRIBE REQUEST from [
10.80.10.11:12001,C:{ee53eee2-d810-49d7-b173-7f68b31e87f1},S:{d404f63a-cc2f-4a44-a073-a0c1e8876c50},1327(0x52F),E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}, E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}]...
[PID:21080:010 2014.01.14 11:00:42.923 INFO Â MasterReplicationSer] Subscribed replica [
10.80.10.11:12001,S:d404f63a-cc2f-4a44-a073-a0c1e8876c50] for data send at 1327 (0x52F).
[PID:21080:010 2014.01.14 11:00:42.927 DEBUG ElectionsService   ] ELECTIONS: (V=26) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21080:010 2014.01.14 11:00:42.927 DEBUG ElectionsService   ] ELECTIONS: (V=26) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:42.927 DEBUG ElectionsService   ] ELECTIONS: (V=26) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:42.927 DEBUG ElectionsService   ] ELECTIONS: (V=26) MAJORITY OF VIEWCHANGE.
[PID:21080:010 2014.01.14 11:00:42.927 DEBUG ElectionsService   ] ELECTIONS: (V=26) SHIFT TO PREPARE PHASE.
[PID:21080:010 2014.01.14 11:00:42.927 DEBUG ElectionsService   ] ELECTIONS: (V=26) PREPARE_OK FROM [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1542,C=1542,E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}).
[PID:21080:008 2014.01.14 11:00:43.893 TRACE TcpConnectionManager] Closing connection 'internal-normal' [
10.80.10.11:58574, L10.80.10.11:11001, {00188fce-2f0b-4592-89ef-828491f74017}] cleanly. Reason: HEARTBEAT TIMEOUT at msgNum 7
[PID:21080:008 2014.01.14 11:00:43.893 INFO  TcpConnection    ] ES TcpConnection closed [11:00:43.893: N10.80.10.11:58574, L10.80.10.11:11001, {00188fce-2f0b-4592-89ef-828491f74017}]:
Received bytes: 583, Sent bytes: 752
Send calls: 10, callbacks: 10
Receive calls: 8, callbacks: 7
Close reason: [Success] HEARTBEAT TIMEOUT at msgNum 7
[PID:21080:008 2014.01.14 11:00:43.893 INFO Â TcpConnectionManager] Connection 'internal-normal' [
10.80.10.11:58574, {00188fce-2f0b-4592-89ef-828491f74017}] closed: Success.
[PID:21080:010 2014.01.14 11:00:43.895 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:13001] is DEAD (TCP connection lost).
[PID:21080:010 2014.01.14 11:00:43.895 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (TCP connection lost to [
10.80.10.11:13001])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:43.928 DEBUG ElectionsService   ] ELECTIONS: (V=26) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:43.928 DEBUG ElectionsService   ] ELECTIONS: (V=27) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:43.928 DEBUG ElectionsService   ] ELECTIONS: (V=27) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:44.762 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:44.932 DEBUG ElectionsService   ] ELECTIONS: (V=27) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:44.932 DEBUG ElectionsService   ] ELECTIONS: (V=28) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:44.932 DEBUG ElectionsService   ] ELECTIONS: (V=28) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:040 2014.01.14 11:00:45.263 INFO  TcpService      ] Internal TCP connection accepted: [Normal,
10.80.10.11:58604, L10.80.10.11:11001, {5946c083-c595-4960-8458-c5299e486b7b}].
[PID:21080:010 2014.01.14 11:00:45.430 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:12003] is DEAD (Gossip send failed).
[PID:21080:010 2014.01.14 11:00:45.430 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip send failed to [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:45.432 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:45.432 DEBUG ElectionsService   ] ELECTIONS: (V=27) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21080:010 2014.01.14 11:00:45.433 DEBUG ElectionsService   ] ELECTIONS: (V=27) MAJORITY OF VIEWCHANGE.
[PID:21080:010 2014.01.14 11:00:45.433 INFO Â MasterReplicationSer] SUBSCRIBE REQUEST from [
10.80.10.11:13001,C:{5946c083-c595-4960-8458-c5299e486b7b},S:{a852f1c1-e057-41ad-ba50-41870d273838},1542(0x606),E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}, E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}, E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}]...
[PID:21080:010 2014.01.14 11:00:45.433 INFO Â MasterReplicationSer] Subscribed replica [
10.80.10.11:13001,S:a852f1c1-e057-41ad-ba50-41870d273838] for data send at 1542 (0x606).
[PID:21080:010 2014.01.14 11:00:45.605 INFO Â MasterReplicationSer] SUBSCRIBE REQUEST from [
10.80.10.11:13001,C:{5946c083-c595-4960-8458-c5299e486b7b},S:{d9429626-89cd-48a2-afd3-e6f190f92bdd},1542(0x606),E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}, E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}, E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}]...
[PID:21080:010 2014.01.14 11:00:45.605 INFO Â MasterReplicationSer] Subscribed replica [
10.80.10.11:13001,S:d9429626-89cd-48a2-afd3-e6f190f92bdd] for data send at 1542 (0x606).
[PID:21080:010 2014.01.14 11:00:45.934 DEBUG ElectionsService   ] ELECTIONS: (V=28) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:45.934 DEBUG ElectionsService   ] ELECTIONS: (V=29) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:45.934 DEBUG ElectionsService   ] ELECTIONS: (V=29) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:040 2014.01.14 11:00:46.100 INFO  TcpConnection    ] ES TcpConnection closed [11:00:46.100: N10.80.10.11:58604, L10.80.10.11:11001, {5946c083-c595-4960-8458-c5299e486b7b}]:
Received bytes: 342, Sent bytes: 376
Send calls: 5, callbacks: 5
Receive calls: 3, callbacks: 3
Close reason: [Success] Socket closed
[PID:21080:040 2014.01.14 11:00:46.100 INFO Â TcpConnectionManager] Connection 'internal-normal' [
10.80.10.11:58604, {5946c083-c595-4960-8458-c5299e486b7b}] closed: Success.
[PID:21080:010 2014.01.14 11:00:46.100 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:13001] is DEAD (TCP connection lost).
[PID:21080:010 2014.01.14 11:00:46.100 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (TCP connection lost to [
10.80.10.11:13001])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:46.118 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:46.119 DEBUG ElectionsService   ] ELECTIONS: (V=28) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21080:010 2014.01.14 11:00:46.119 DEBUG ElectionsService   ] ELECTIONS: (V=28) MAJORITY OF VIEWCHANGE.
[PID:21080:010 2014.01.14 11:00:46.119 DEBUG ElectionsService   ] ELECTIONS: (V=29) SHIFT TO PREPARE PHASE.
[PID:21080:010 2014.01.14 11:00:46.119 DEBUG ElectionsService   ] ELECTIONS: (V=29) PREPARE_OK FROM [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1542,C=1542,E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}).
[PID:21080:010 2014.01.14 11:00:46.128 DEBUG ElectionsService   ] ELECTIONS: (V=29) PREPARE_OK FROM [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=803,W=1542,C=1542,E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}).
[PID:21080:010 2014.01.14 11:00:46.128 DEBUG ElectionsService   ] ELECTIONS: (V=29) SHIFT TO REG_LEADER.
[PID:21080:010 2014.01.14 11:00:46.129 DEBUG ElectionsService   ] ELECTIONS: (V=29) SENDING PROPOSAL CANDIDATE: [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1542,C=1542,E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}), ME: [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1542,C=1542,E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}).
[PID:21080:010 2014.01.14 11:00:46.129 DEBUG ElectionsService   ] ELECTIONS: (V=29) ACCEPT FROM [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]).
[PID:21080:010 2014.01.14 11:00:46.141 DEBUG ElectionsService   ] ELECTIONS: (V=29) ACCEPT FROM [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]).
[PID:21080:010 2014.01.14 11:00:46.141 INFO  ElectionsService   ] ELECTIONS: (V=29) DONE. ELECTED MASTER = [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1542,C=1542,E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}). ME=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1542,C=1542,E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}).
[PID:21080:007 2014.01.14 11:00:46.141 DEBUG EpochManager     ] === Writing E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc} (previous epoch at 1327).
[PID:21080:007 2014.01.14 11:00:46.145 DEBUG EpochManager     ] === Update Last Epoch E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc} (previous epoch at 1327).
[PID:21080:037 2014.01.14 11:00:46.602 INFO  TcpService      ] Internal TCP connection accepted: [Normal,
10.80.10.11:58612, L10.80.10.11:11001, {a64bd2c5-ecb2-4f29-ba77-a8d07f530a4c}].
[PID:21080:010 2014.01.14 11:00:47.401 INFO Â MasterReplicationSer] SUBSCRIBE REQUEST from [
10.80.10.11:13001,C:{a64bd2c5-ecb2-4f29-ba77-a8d07f530a4c},S:{06602b5f-6aae-498f-9dc6-c268d0c1f6b0},1542(0x606),E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}, E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}, E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}]...
[PID:21080:010 2014.01.14 11:00:47.401 INFO Â MasterReplicationSer] Subscribed replica [
10.80.10.11:13001,S:06602b5f-6aae-498f-9dc6-c268d0c1f6b0] for data send at 1542 (0x606).
[PID:21080:010 2014.01.14 11:00:47.931 DEBUG ElectionsService   ] ELECTIONS: (V=30) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21080:010 2014.01.14 11:00:47.931 DEBUG ElectionsService   ] ELECTIONS: (V=30) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:47.931 DEBUG ElectionsService   ] ELECTIONS: (V=30) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:47.931 DEBUG ElectionsService   ] ELECTIONS: (V=30) MAJORITY OF VIEWCHANGE.
[PID:21080:010 2014.01.14 11:00:47.935 DEBUG ElectionsService   ] ELECTIONS: (V=31) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21080:010 2014.01.14 11:00:47.935 DEBUG ElectionsService   ] ELECTIONS: (V=31) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:47.935 DEBUG ElectionsService   ] ELECTIONS: (V=31) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:47.935 DEBUG ElectionsService   ] ELECTIONS: (V=31) MAJORITY OF VIEWCHANGE.
[PID:21080:010 2014.01.14 11:00:47.935 DEBUG ElectionsService   ] ELECTIONS: (V=31) SHIFT TO PREPARE PHASE.
[PID:21080:010 2014.01.14 11:00:47.935 DEBUG ElectionsService   ] ELECTIONS: (V=31) PREPARE_OK FROM [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1757,C=1757,E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}).
[PID:21080:010 2014.01.14 11:00:48.271 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:48.774 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:13003] is DEAD (Gossip send failed).
[PID:21080:010 2014.01.14 11:00:48.774 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip send failed to [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:48.776 DEBUG ElectionsService   ] ELECTIONS: (V=32) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21080:010 2014.01.14 11:00:48.776 DEBUG ElectionsService   ] ELECTIONS: (V=32) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:48.776 DEBUG ElectionsService   ] ELECTIONS: (V=32) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:48.776 DEBUG ElectionsService   ] ELECTIONS: (V=32) MAJORITY OF VIEWCHANGE.
[PID:21080:010 2014.01.14 11:00:49.778 DEBUG ElectionsService   ] ELECTIONS: (V=32) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:49.778 DEBUG ElectionsService   ] ELECTIONS: (V=33) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:49.778 DEBUG ElectionsService   ] ELECTIONS: (V=33) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:50.120 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:50.125 DEBUG ElectionsService   ] ELECTIONS: (V=32) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21080:010 2014.01.14 11:00:50.125 DEBUG ElectionsService   ] ELECTIONS: (V=32) MAJORITY OF VIEWCHANGE.
[PID:21080:010 2014.01.14 11:00:50.780 DEBUG ElectionsService   ] ELECTIONS: (V=33) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:50.780 DEBUG ElectionsService   ] ELECTIONS: (V=34) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:50.780 DEBUG ElectionsService   ] ELECTIONS: (V=34) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:51.780 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:12003] is DEAD (Gossip send failed).
[PID:21080:010 2014.01.14 11:00:51.780 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip send failed to [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:51.780 DEBUG ElectionsService   ] ELECTIONS: (V=33) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21080:010 2014.01.14 11:00:51.780 DEBUG ElectionsService   ] ELECTIONS: (V=33) MAJORITY OF VIEWCHANGE.
[PID:21080:010 2014.01.14 11:00:51.780 DEBUG ElectionsService   ] ELECTIONS: (V=34) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:51.780 DEBUG ElectionsService   ] ELECTIONS: (V=35) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:51.780 DEBUG ElectionsService   ] ELECTIONS: (V=35) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:043 2014.01.14 11:00:52.452 DEBUG GossipController   ] Error while reading request (gossip): EndRead failure
[PID:21080:010 2014.01.14 11:00:52.452 DEBUG ElectionsService   ] ELECTIONS: (V=34) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21080:010 2014.01.14 11:00:52.452 DEBUG ElectionsService   ] ELECTIONS: (V=34) MAJORITY OF VIEWCHANGE.
[PID:21080:010 2014.01.14 11:00:52.452 DEBUG ElectionsService   ] ELECTIONS: (V=35) SHIFT TO PREPARE PHASE.
[PID:21080:010 2014.01.14 11:00:52.452 DEBUG ElectionsService   ] ELECTIONS: (V=35) PREPARE_OK FROM [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1757,C=1757,E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}).
[PID:21080:010 2014.01.14 11:00:52.782 DEBUG ElectionsService   ] ELECTIONS: (V=35) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:52.782 DEBUG ElectionsService   ] ELECTIONS: (V=36) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:52.782 DEBUG ElectionsService   ] ELECTIONS: (V=36) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:52.954 DEBUG ElectionsService   ] ELECTIONS: (V=36) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21080:010 2014.01.14 11:00:52.954 DEBUG ElectionsService   ] ELECTIONS: (V=36) MAJORITY OF VIEWCHANGE.
[PID:21080:010 2014.01.14 11:00:52.964 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:53.341 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:53.783 DEBUG ElectionsService   ] ELECTIONS: (V=36) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:53.783 DEBUG ElectionsService   ] ELECTIONS: (V=37) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:53.783 DEBUG ElectionsService   ] ELECTIONS: (V=37) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:54.785 DEBUG ElectionsService   ] ELECTIONS: (V=37) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:54.785 DEBUG ElectionsService   ] ELECTIONS: (V=38) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:54.785 DEBUG ElectionsService   ] ELECTIONS: (V=38) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:008 2014.01.14 11:00:55.131 TRACE TcpConnectionManager] Closing connection 'internal-normal' [
10.80.10.11:58601, L10.80.10.11:11001, {ee53eee2-d810-49d7-b173-7f68b31e87f1}] cleanly. Reason: HEARTBEAT TIMEOUT at msgNum 12
[PID:21080:008 2014.01.14 11:00:55.131 INFO  TcpConnection    ] ES TcpConnection closed [11:00:55.131: N10.80.10.11:58601, L10.80.10.11:11001, {ee53eee2-d810-49d7-b173-7f68b31e87f1}]:
Received bytes: 693, Sent bytes: 1119
Send calls: 16, callbacks: 15
Receive calls: 13, callbacks: 12
Close reason: [Success] HEARTBEAT TIMEOUT at msgNum 12
[PID:21080:008 2014.01.14 11:00:55.131 INFO Â TcpConnectionManager] Connection 'internal-normal' [
10.80.10.11:58601, {ee53eee2-d810-49d7-b173-7f68b31e87f1}] closed: Success.
[PID:21080:010 2014.01.14 11:00:55.131 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:12001] is DEAD (TCP connection lost).
[PID:21080:010 2014.01.14 11:00:55.132 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (TCP connection lost to [
10.80.10.11:12001])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:008 2014.01.14 11:00:55.510 TRACE TcpConnectionManager] Closing connection 'internal-normal' [
10.80.10.11:58612, L10.80.10.11:11001, {a64bd2c5-ecb2-4f29-ba77-a8d07f530a4c}] cleanly. Reason: HEARTBEAT TIMEOUT at msgNum 10
[PID:21080:008 2014.01.14 11:00:55.510 INFO  TcpConnection    ] ES TcpConnection closed [11:00:55.510: N10.80.10.11:58612, L10.80.10.11:11001, {a64bd2c5-ecb2-4f29-ba77-a8d07f530a4c}]:
Received bytes: 652, Sent bytes: 774
Send calls: 13, callbacks: 12
Receive calls: 11, callbacks: 10
Close reason: [Success] HEARTBEAT TIMEOUT at msgNum 10
[PID:21080:008 2014.01.14 11:00:55.510 INFO Â TcpConnectionManager] Connection 'internal-normal' [
10.80.10.11:58612, {a64bd2c5-ecb2-4f29-ba77-a8d07f530a4c}] closed: Success.
[PID:21080:010 2014.01.14 11:00:55.510 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:13001] is DEAD (TCP connection lost).
[PID:21080:010 2014.01.14 11:00:55.511 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (TCP connection lost to [
10.80.10.11:13001])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:55.786 DEBUG ElectionsService   ] ELECTIONS: (V=38) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:55.786 DEBUG ElectionsService   ] ELECTIONS: (V=39) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:55.786 DEBUG ElectionsService   ] ELECTIONS: (V=39) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:55.788 DEBUG ElectionsService   ] ELECTIONS: (V=36) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21080:010 2014.01.14 11:00:55.788 DEBUG ElectionsService   ] ELECTIONS: (V=36) MAJORITY OF VIEWCHANGE.
[PID:21080:010 2014.01.14 11:00:55.788 DEBUG ElectionsService   ] ELECTIONS: (V=39) SHIFT TO PREPARE PHASE.
[PID:21080:010 2014.01.14 11:00:55.788 DEBUG ElectionsService   ] ELECTIONS: (V=39) PREPARE_OK FROM [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1757,C=1757,E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}).
[PID:21080:010 2014.01.14 11:00:55.790 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:044 2014.01.14 11:00:56.460 INFO  TcpService      ] Internal TCP connection accepted: [Normal,
10.80.10.11:58644, L10.80.10.11:11001, {e60ebf30-53ba-444d-8e74-526e67682cd2}].
[PID:21080:047 2014.01.14 11:00:56.717 INFO  TcpService      ] Internal TCP connection accepted: [Normal,
10.80.10.11:58645, L10.80.10.11:11001, {a59bbc63-34a8-43d3-a2a7-a6e97a8e3f61}].
[PID:21080:010 2014.01.14 11:00:56.787 DEBUG ElectionsService   ] ELECTIONS: (V=39) TIMED OUT! (S=ElectingLeader, M=).
[PID:21080:010 2014.01.14 11:00:56.787 DEBUG ElectionsService   ] ELECTIONS: (V=40) SHIFT TO LEADER ELECTION.
[PID:21080:010 2014.01.14 11:00:56.787 DEBUG ElectionsService   ] ELECTIONS: (V=40) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21080:010 2014.01.14 11:00:57.133 INFO Â MasterReplicationSer] SUBSCRIBE REQUEST from [
10.80.10.11:13001,C:{a59bbc63-34a8-43d3-a2a7-a6e97a8e3f61},S:{c740f553-910c-4c06-af77-067a6c6861c9},1757(0x6DD),E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}, E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}, E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}, E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}]...
[PID:21080:010 2014.01.14 11:00:57.133 INFO Â MasterReplicationSer] Subscribed replica [
10.80.10.11:13001,S:c740f553-910c-4c06-af77-067a6c6861c9] for data send at 1757 (0x6DD).
[PID:21080:010 2014.01.14 11:00:57.138 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21080:010 2014.01.14 11:00:57.346 DEBUG ElectionsService   ] ELECTIONS: (V=40) PREPARE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21080:010 2014.01.14 11:00:57.346 DEBUG ElectionsService   ] ELECTIONS: (V=40) SHIFT TO REG_NONLEADER.
[PID:21080:010 2014.01.14 11:00:57.351 DEBUG ElectionsService   ] ELECTIONS: (V=40) PROPOSAL FROM [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1757,C=1757,E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}). ME=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1757,C=1757,E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}).
[PID:21080:010 2014.01.14 11:00:57.351 DEBUG ElectionsService   ] ELECTIONS: (V=40) ACCEPT FROM [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]).
[PID:21080:010 2014.01.14 11:00:57.351 DEBUG ElectionsService   ] ELECTIONS: (V=40) ACCEPT FROM [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]).
[PID:21080:010 2014.01.14 11:00:57.351 INFO  ElectionsService   ] ELECTIONS: (V=40) DONE. ELECTED MASTER = [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1757,C=1757,E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}). ME=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1757,C=1757,E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}).
[PID:21080:007 2014.01.14 11:00:57.351 DEBUG EpochManager     ] === Writing E4@1757:{8668e607-7c93-4b0c-b7a6-3102ae249983} (previous epoch at 1542).
[PID:21080:007 2014.01.14 11:00:57.356 DEBUG EpochManager     ] === Update Last Epoch E4@1757:{8668e607-7c93-4b0c-b7a6-3102ae249983} (previous epoch at 1542).
# cat /srv/eventsore/db-cluster2-logs/2014-01-14/10.80.10.11-12004-cluster-node.logÂ
[PID:21182:001 2014.01.14 11:00:13.855 INFO Â ProgramBase`1 Â Â Â ]Â
ES VERSION: Â Â Â Â Â Â Â no-werror (master/5433fdc82895c181e0325a5730d36424de8eb28f, Fri, 10 Jan 2014 13:48:40 +0000)
OS: Â Â Â Â Â Â Â Â Â Â Â Unknown (Unix 2.6.32.431)
RUNTIME: Â Â Â Â Â Â Â Â Â 3.2.5 (tarball Thu Dec 12 12:56:24 MSK 2013) (64-bit)
GC: Â Â Â Â Â Â Â Â Â Â Â 2 GENERATIONS
LOGS: Â Â Â Â Â Â Â Â Â Â /srv/eventsore/db-cluster2-logs
SHOW HELP: Â Â Â Â Â Â Â Â False (<DEFAULT>)
SHOW VERSION: Â Â Â Â Â Â False (<DEFAULT>)
LOGS DIR: Â Â Â Â Â Â Â Â /srv/eventsore/db-cluster2-logs (--logsdir from command line)
CONFIGS: Â Â Â Â Â Â Â Â Â <empty> (<DEFAULT>)
DEFINES: Â Â Â Â Â Â Â Â Â <empty> (<DEFAULT>)
INTERNAL IP: Â Â Â Â Â Â Â 10.80.10.11 (--internal-ip from command line)
EXTERNAL IP: Â Â Â Â Â Â Â 10.80.10.11 (--external-ip from command line)
INTERNAL HTTP PORT: Â Â Â 12003 (--internal-http-port from command line)
EXTERNAL HTTP PORT: Â Â Â 12004 (--external-http-port from command line)
INTERNAL TCP PORT: Â Â Â Â 12001 (--internal-tcp-port from command line)
INTERNAL SECURE TCP PORT: 0 (<DEFAULT>)
EXTERNAL TCP PORT: Â Â Â Â 12002 (--external-tcp-port from command line)
EXTERNAL SECURE TCP PORT: 0 (<DEFAULT>)
FORCE: Â Â Â Â Â Â Â Â Â Â False (<DEFAULT>)
CLUSTER SIZE: Â Â Â Â Â Â 3 (--cluster-size from command line)
MIN FLUSH DELAY MS: Â Â Â 2 (<DEFAULT>)
NODE PRIORITY: Â Â Â Â Â Â 0 (<DEFAULT>)
COMMIT COUNT: Â Â Â Â Â Â 2 (<DEFAULT>)
PREPARE COUNT: Â Â Â Â Â Â 2 (<DEFAULT>)
DISCOVER VIA DNS: Â Â Â Â False (--use-dns-discovery from command line)
CLUSTER DNS: Â Â Â Â Â Â Â fake.dns (<DEFAULT>)
CLUSTER GOSSIP PORT: Â Â Â 30777 (<DEFAULT>)
STATS PERIOD SEC: Â Â Â Â 300 (--stats-period-sec from command line)
CACHED CHUNKS: Â Â Â Â Â Â -1 (<DEFAULT>)
CHUNKS CACHE SIZE: Â Â Â Â 536871424 (<DEFAULT>)
DB PATH: Â Â Â Â Â Â Â Â Â /srv/eventsore/db-cluster2 (--db from command line)
IN MEM DB: Â Â Â Â Â Â Â Â False (<DEFAULT>)
SKIP DB VERIFY: Â Â Â Â Â False (<DEFAULT>)
RUN PROJECTIONS: Â Â Â Â Â All (--run-projections from command line)
PROJECTION THREADS: Â Â Â 3 (<DEFAULT>)
WORKER THREADS: Â Â Â Â Â 5 (<DEFAULT>)
HTTP PREFIXES: Â Â Â Â Â Â <empty> (<DEFAULT>)
ENABLE TRUSTED AUTH: Â Â Â True (--enable-trusted-auth from command line)
CERTIFICATE STORE: Â Â Â Â <empty> (<DEFAULT>)
CERTIFICATE NAME: Â Â Â Â <empty> (<DEFAULT>)
CERTIFICATE FILE: Â Â Â Â <empty> (<DEFAULT>)
CERTIFICATE PASSWORD: Â Â <empty> (<DEFAULT>)
USE INTERNAL SSL: Â Â Â Â False (<DEFAULT>)
SSL TARGET HOST: Â Â Â Â Â n/a (<DEFAULT>)
SSL VALIDATE SERVER: Â Â Â True (<DEFAULT>)
AUTHENTICATION TYPE: Â Â Â internal (<DEFAULT>)
AUTHENTICATION CONFIG FILE: <empty> (<DEFAULT>)
PREPARE TIMEOUT MS: Â Â Â 2000 (<DEFAULT>)
COMMIT TIMEOUT MS: Â Â Â Â 2000 (<DEFAULT>)
DISABLE SCAVENGE MERGING: False (<DEFAULT>)
[PID:21182:001 2014.01.14 11:00:13.946 INFO Â ProgramBase`1 Â Â Â ] Quorum size set to 2
[PID:21182:001 2014.01.14 11:00:13.962 INFO Â ProgramBase`1 Â Â Â ] Can't find plugins path: /opt/eventstore/eventstore-mono-20140114.1110/plugins
[PID:21182:001 2014.01.14 11:00:14.042 INFO Â ProgramBase`1 Â Â Â ]Â
INSTANCE ID: Â Â Â Â Â Â Â 382eac31-36d3-43ac-a3d6-74f363b8fb15
DATABASE: Â Â Â Â Â Â Â Â /srv/eventsore/db-cluster2
WRITER CHECKPOINT: Â Â Â Â 0 (0x0)
CHASER CHECKPOINT: Â Â Â Â 0 (0x0)
EPOCH CHECKPOINT: Â Â Â Â -1 (0xFFFFFFFFFFFFFFFF)
TRUNCATE CHECKPOINT: Â Â Â -1 (0xFFFFFFFFFFFFFFFF)
[PID:21182:001 2014.01.14 11:00:14.364 TRACE MessageHierarchy   ] MessageHierarchy initialization took 00:00:00.2496381.
[PID:21182:001 2014.01.14 11:00:14.544 TRACE TFChunk       ] CACHED TFChunk #0-0 (chunk-000000.000000) in 00:00:00.0043780.
[PID:21182:001 2014.01.14 11:00:14.810 INFO  MiniWeb       ] Starting MiniWeb for /web/es/js/projections ==> /opt/eventstore/current/singlenode-web/js/projections
[PID:21182:001 2014.01.14 11:00:14.811 INFO  MiniWeb       ] Starting MiniWeb for /web/es/js/projections/v8/Prelude ==> /opt/eventstore/current/Prelude
[PID:21182:001 2014.01.14 11:00:14.811 INFO  MiniWeb       ] Starting MiniWeb for /web/es/js/projections/resources ==> /opt/eventstore/current/web-resources/js
[PID:21182:001 2014.01.14 11:00:14.813 TRACE MiniWeb       ] Binding MiniWeb to /web/es/js/projections/{*remaining_path}
[PID:21182:001 2014.01.14 11:00:14.813 TRACE MiniWeb       ] Binding MiniWeb to /web/es/js/projections/v8/Prelude/{*remaining_path}
[PID:21182:001 2014.01.14 11:00:14.814 TRACE MiniWeb       ] Binding MiniWeb to /web/es/js/projections/resources/{*remaining_path}
[PID:21182:001 2014.01.14 11:00:14.816 TRACE MiniWeb       ] Binding MiniWeb to /web/es/js/projections/{*remaining_path}
[PID:21182:001 2014.01.14 11:00:14.816 TRACE MiniWeb       ] Binding MiniWeb to /web/es/js/projections/v8/Prelude/{*remaining_path}
[PID:21182:001 2014.01.14 11:00:14.816 TRACE MiniWeb       ] Binding MiniWeb to /web/es/js/projections/resources/{*remaining_path}
[PID:21182:001 2014.01.14 11:00:14.822 INFO  MiniWeb       ] Starting MiniWeb for /web ==> /opt/eventstore/current/clusternode-web
[PID:21182:001 2014.01.14 11:00:14.822 INFO  MiniWeb       ] Starting MiniWeb for /web/es ==> /opt/eventstore/current/es-common-web
[PID:21182:001 2014.01.14 11:00:14.822 TRACE MiniWeb       ] Binding MiniWeb to /web/{*remaining_path}
[PID:21182:001 2014.01.14 11:00:14.823 TRACE MiniWeb       ] Binding MiniWeb to /web/es/{*remaining_path}
[PID:21182:001 2014.01.14 11:00:14.824 INFO  MiniWeb       ] Starting MiniWeb for /web ==> /opt/eventstore/current/clusternode-web
[PID:21182:001 2014.01.14 11:00:14.824 INFO  MiniWeb       ] Starting MiniWeb for /web/es ==> /opt/eventstore/current/es-common-web
[PID:21182:001 2014.01.14 11:00:14.824 TRACE MiniWeb       ] Binding MiniWeb to /web/{*remaining_path}
[PID:21182:001 2014.01.14 11:00:14.824 TRACE MiniWeb       ] Binding MiniWeb to /web/es/{*remaining_path}
[PID:21182:001 2014.01.14 11:00:14.825 INFO  MiniWeb       ] Starting MiniWeb for /web/users ==> /opt/eventstore/current/Users/web
[PID:21182:001 2014.01.14 11:00:14.825 TRACE MiniWeb       ] Binding MiniWeb to /web/users/{*remaining_path}
[PID:21182:001 2014.01.14 11:00:14.825 INFO  MiniWeb       ] Starting MiniWeb for /web/users ==> /opt/eventstore/current/Users/web
[PID:21182:001 2014.01.14 11:00:14.826 TRACE MiniWeb       ] Binding MiniWeb to /web/users/{*remaining_path}
[PID:21182:010 2014.01.14 11:00:14.871 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] SYSTEM INIT...
[PID:21182:010 2014.01.14 11:00:14.913 INFO  TcpServerListener  ] Starting Normal TCP listening on TCP endpoint:
10.80.10.11:12002.
[PID:21182:015 2014.01.14 11:00:14.951 INFO  IndexCommitter    ] TableIndex initialization...
[PID:21182:015 2014.01.14 11:00:14.978 INFO  IndexCommitter    ] ReadIndex building...
[PID:21182:015 2014.01.14 11:00:14.981 DEBUG IndexCommitter    ] ReadIndex rebuilding done: total processed 0 records, time elapsed: 00:00:00.0021270.
[PID:21182:010 2014.01.14 11:00:14.997 TRACE InMemoryBus     ] SLOW BUS MSG [MainBus]: SystemInit - 57ms. Handler: TcpService.
[PID:21182:010 2014.01.14 11:00:14.997 INFO  TcpServerListener  ] Starting Normal TCP listening on TCP endpoint:
10.80.10.11:12001.
[PID:21182:010 2014.01.14 11:00:15.045 INFO  HttpAsyncServer   ] HTTP server is up and listening on [
http://10.80.10.11:12004/]
[PID:21182:010 2014.01.14 11:00:15.045 INFO  HttpAsyncServer   ] HTTP server is up and listening on [
http://10.80.10.11:12003/]
[PID:21182:010 2014.01.14 11:00:15.083 TRACE QueuedHandlerAutoRes] SLOW QUEUE MSG [MainQueue]: SystemInit - 222ms. Q: 0/7.
[PID:21182:010 2014.01.14 11:00:15.085 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] Service 'StorageWriter' initialized.
[PID:21182:010 2014.01.14 11:00:15.085 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] Service 'StorageReader' initialized.
[PID:21182:010 2014.01.14 11:00:15.085 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] Service 'StorageChaser' initialized.
[PID:21182:010 2014.01.14 11:00:15.147 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:15.151 TRACE InMemoryBus     ] SLOW BUS MSG [MainBus]: GotGossipSeedSources - 63ms. Handler: NodeGossipService.
[PID:21182:010 2014.01.14 11:00:15.151 TRACE QueuedHandlerAutoRes] SLOW QUEUE MSG [MainQueue]: GotGossipSeedSources - 63ms. Q: 1/3.
[PID:21182:010 2014.01.14 11:00:15.151 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] SYSTEM START...
[PID:21182:010 2014.01.14 11:00:15.154 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] IS UNKNOWN!!! WHOA!!!
[PID:21182:010 2014.01.14 11:00:15.232 DEBUG ElectionsService   ] ELECTIONS: STARTING ELECTIONS.
[PID:21182:010 2014.01.14 11:00:15.233 DEBUG ElectionsService   ] ELECTIONS: (V=0) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:15.235 DEBUG ElectionsService   ] ELECTIONS: (V=0) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:15.239 TRACE InMemoryBus     ] SLOW BUS MSG [MainBus]: StartElections - 74ms. Handler: ElectionsService.
[PID:21182:010 2014.01.14 11:00:15.239 TRACE QueuedHandlerAutoRes] SLOW QUEUE MSG [MainQueue]: StartElections - 74ms. Q: 0/2.
[PID:21182:006 2014.01.14 11:00:15.452 TRACE InMemoryBus     ] SLOW BUS MSG [Worker #1 Bus]: SendOverHttp - 294ms. Handler: HttpSendService.
[PID:21182:006 2014.01.14 11:00:15.490 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [Worker #1]: SendOverHttp - 294ms. Q: 0/0.
[PID:21182:010 2014.01.14 11:00:15.964 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:11003] is DEAD (Gossip send failed).
[PID:21182:010 2014.01.14 11:00:15.966 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip send failed to [
10.80.10.11:11003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:16.241 DEBUG ElectionsService   ] ELECTIONS: (V=0) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:16.241 DEBUG ElectionsService   ] ELECTIONS: (V=1) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:16.241 DEBUG ElectionsService   ] ELECTIONS: (V=1) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:16.374 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:13003] is DEAD (Gossip send failed).
[PID:21182:010 2014.01.14 11:00:16.374 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip send failed to [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:17.242 DEBUG ElectionsService   ] ELECTIONS: (V=1) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:17.242 DEBUG ElectionsService   ] ELECTIONS: (V=2) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:17.242 DEBUG ElectionsService   ] ELECTIONS: (V=2) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:18.132 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:11003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:18.243 DEBUG ElectionsService   ] ELECTIONS: (V=2) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:18.243 DEBUG ElectionsService   ] ELECTIONS: (V=3) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:18.243 DEBUG ElectionsService   ] ELECTIONS: (V=3) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:18.376 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:11003] is DEAD (Gossip send failed).
[PID:21182:010 2014.01.14 11:00:18.376 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip send failed to [
10.80.10.11:11003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:18.515 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:11003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:19.015 DEBUG ElectionsService   ] ELECTIONS: (V=15) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21182:010 2014.01.14 11:00:19.015 DEBUG ElectionsService   ] ELECTIONS: (V=15) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:19.015 DEBUG ElectionsService   ] ELECTIONS: (V=15) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:19.015 DEBUG ElectionsService   ] ELECTIONS: (V=15) MAJORITY OF VIEWCHANGE.
[PID:21182:010 2014.01.14 11:00:19.036 DEBUG ElectionsService   ] ELECTIONS: (V=15) PREPARE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21182:010 2014.01.14 11:00:19.036 DEBUG ElectionsService   ] ELECTIONS: (V=15) SHIFT TO REG_NONLEADER.
[PID:21182:010 2014.01.14 11:00:19.087 DEBUG ElectionsService   ] ELECTIONS: (V=15) PROPOSAL FROM [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=-1,W=0,C=0,E-1@-1:{00000000-0000-0000-0000-000000000000}). ME=[
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}](L=-1,W=0,C=0,E-1@-1:{00000000-0000-0000-0000-000000000000}).
[PID:21182:010 2014.01.14 11:00:19.088 DEBUG ElectionsService   ] ELECTIONS: (V=15) ACCEPT FROM [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]).
[PID:21182:010 2014.01.14 11:00:19.088 DEBUG ElectionsService   ] ELECTIONS: (V=15) ACCEPT FROM [
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]).
[PID:21182:010 2014.01.14 11:00:19.088 INFO  ElectionsService   ] ELECTIONS: (V=15) DONE. ELECTED MASTER = [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=-1,W=0,C=0,E-1@-1:{00000000-0000-0000-0000-000000000000}). ME=[
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}](L=-1,W=0,C=0,E-1@-1:{00000000-0000-0000-0000-000000000000}).
[PID:21182:010 2014.01.14 11:00:19.091 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] PRE-REPLICA STATE, WAITING FOR CHASER TO CATCH UP... MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21182:019 2014.01.14 11:00:19.194 INFO Â TcpConnectionManager] Connection 'master-normal' ({d46f1bee-7442-4905-bb88-6daf87cf3b8a}) to [
10.80.10.11:11001] established.
[PID:21182:010 2014.01.14 11:00:19.252 INFO  ReplicaService    ] Subscribing at LogPosition: 0 (0x0) to MASTER [
10.80.10.11:11001, {46577878-07ac-4f88-9a42-8889a62e649e}] as replica with SubscriptionId: {c06aaa47-83d5-426a-9bc5-514cddc08970}, ConnectionId: {d46f1bee-7442-4905-bb88-6daf87cf3b8a}, LocalEndPoint: [
10.80.10.11:58542], Epochs:
...
.
[PID:21182:010 2014.01.14 11:00:19.263 TRACE InMemoryBus     ] SLOW BUS MSG [MainBus]: SubscribeToMaster - 134ms. Handler: ReplicaService.
[PID:21182:010 2014.01.14 11:00:19.263 TRACE QueuedHandlerAutoRes] SLOW QUEUE MSG [MainQueue]: ChaserCaughtUp - 138ms. Q: 0/6.
[PID:21182:010 2014.01.14 11:00:19.319 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:11003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:19.687 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] IS CATCHING UP!!! BANZAI!!! MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21182:010 2014.01.14 11:00:19.719 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] CLONE ASSIGNMENT RECEIVED FROM [
10.80.10.11:11001,n/a,{46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21182:010 2014.01.14 11:00:19.722 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] IS CLONE!!! SPARTA!!! MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21182:007 2014.01.14 11:00:19.759 INFO Â ClusterStorageWriter] === SUBSCRIBED to [
10.80.10.11:11001,{46577878-07ac-4f88-9a42-8889a62e649e}] at 0 (0x0). SubscriptionId: {c06aaa47-83d5-426a-9bc5-514cddc08970}.
[PID:21182:015 2014.01.14 11:00:19.847 DEBUG EpochManager     ] === Update Last Epoch E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691} (previous epoch at -1).
[PID:21182:010 2014.01.14 11:00:19.940 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:11003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:20.651 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] SLAVE ASSIGNMENT RECEIVED FROM [
10.80.10.11:11001,n/a,{46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21182:010 2014.01.14 11:00:20.651 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] IS SLAVE!!! SPARTA!!! MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21182:010 2014.01.14 11:00:29.659 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:30.901 TRACE GossipServiceBase  ] Looks like master [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}] is DEAD (Gossip send failed), though we wait for TCP to decide.
[PID:21182:010 2014.01.14 11:00:30.922 DEBUG ElectionsService   ] ELECTIONS: (V=15) PREPARE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21182:010 2014.01.14 11:00:31.061 DEBUG ElectionsService   ] ELECTIONS: (V=15) NOT LEGITIMATE MASTER PROPOSAL FROM [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}] M=[
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}](L=803,W=1115,C=1115,E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}). PREVIOUS MASTER IS ALIVE: [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21182:010 2014.01.14 11:00:33.069 DEBUG ElectionsService   ] ELECTIONS: (V=16) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21182:010 2014.01.14 11:00:33.069 DEBUG ElectionsService   ] ELECTIONS: (V=16) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:33.069 DEBUG ElectionsService   ] ELECTIONS: (V=16) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:33.069 DEBUG ElectionsService   ] ELECTIONS: (V=16) MAJORITY OF VIEWCHANGE.
[PID:21182:010 2014.01.14 11:00:33.070 DEBUG ElectionsService   ] ELECTIONS: (V=16) SHIFT TO PREPARE PHASE.
[PID:21182:010 2014.01.14 11:00:33.071 DEBUG ElectionsService   ] ELECTIONS: (V=16) PREPARE_OK FROM [
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}](L=803,W=1115,C=1115,E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}).
[PID:21182:010 2014.01.14 11:00:33.076 DEBUG ElectionsService   ] ELECTIONS: (V=17) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21182:010 2014.01.14 11:00:33.076 DEBUG ElectionsService   ] ELECTIONS: (V=17) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:33.076 DEBUG ElectionsService   ] ELECTIONS: (V=17) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:33.076 DEBUG ElectionsService   ] ELECTIONS: (V=17) MAJORITY OF VIEWCHANGE.
[PID:21182:010 2014.01.14 11:00:34.076 DEBUG ElectionsService   ] ELECTIONS: (V=17) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:34.076 DEBUG ElectionsService   ] ELECTIONS: (V=18) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:34.076 DEBUG ElectionsService   ] ELECTIONS: (V=18) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:34.903 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:13003] is DEAD (Gossip send failed).
[PID:21182:010 2014.01.14 11:00:34.904 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip send failed to [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:008 2014.01.14 11:00:34.983 TRACE TcpConnectionManager] Closing connection 'master-normal' [
10.80.10.11:11001, L10.80.10.11:58542, {d46f1bee-7442-4905-bb88-6daf87cf3b8a}] cleanly. Reason: HEARTBEAT TIMEOUT at msgNum 21
[PID:21182:008 2014.01.14 11:00:35.018 INFO  TcpConnection    ] ES TcpConnection closed [11:00:34.986: N10.80.10.11:11001, L10.80.10.11:58542, {d46f1bee-7442-4905-bb88-6daf87cf3b8a}]:
Received bytes: 1950, Sent bytes: 793
Send calls: 20, callbacks: 19
Receive calls: 23, callbacks: 22
Close reason: [Success] HEARTBEAT TIMEOUT at msgNum 21
[PID:21182:008 2014.01.14 11:00:35.021 INFO Â TcpConnectionManager] Connection 'master-normal' [
10.80.10.11:11001, {d46f1bee-7442-4905-bb88-6daf87cf3b8a}] closed: Success.
[PID:21182:010 2014.01.14 11:00:35.024 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:11001] is DEAD (TCP connection lost).
[PID:21182:010 2014.01.14 11:00:35.024 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (TCP connection lost to [
10.80.10.11:11001])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:35.024 DEBUG ClusterVNodeControll] There is NO MASTER or MASTER is DEAD according to GOSSIP. Starting new elections. MASTER: [InstanceId: {46577878-07ac-4f88-9a42-8889a62e649e}, InternalTcp:
10.80.10.11:11001, InternalSecureTcp: , ExternalTcp:
10.80.10.11:11002, ExternalSecureTcp: , InternalHttp:
10.80.10.11:11003, ExternalHttp:
10.80.10.11:11004].
[PID:21182:010 2014.01.14 11:00:35.077 DEBUG ElectionsService   ] ELECTIONS: (V=18) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:35.077 DEBUG ElectionsService   ] ELECTIONS: (V=19) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:35.077 DEBUG ElectionsService   ] ELECTIONS: (V=19) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:35.525 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] PRE-REPLICA STATE, WAITING FOR CHASER TO CATCH UP... MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21182:010 2014.01.14 11:00:35.525 TRACE TcpConnectionManager] Closing connection 'master-normal' [
10.80.10.11:11001, L10.80.10.11:58542, {d46f1bee-7442-4905-bb88-6daf87cf3b8a}] cleanly. Reason: Reconnecting from old master [
10.80.10.11:11001] to new master: [
10.80.10.11:11001].
[PID:21182:010 2014.01.14 11:00:35.526 DEBUG ClusterVNodeControll] There is NO MASTER or MASTER is DEAD according to GOSSIP. Starting new elections. MASTER: [InstanceId: {46577878-07ac-4f88-9a42-8889a62e649e}, InternalTcp:
10.80.10.11:11001, InternalSecureTcp: , ExternalTcp:
10.80.10.11:11002, ExternalSecureTcp: , InternalHttp:
10.80.10.11:11003, ExternalHttp:
10.80.10.11:11004].
[PID:21182:010 2014.01.14 11:00:35.527 INFO  ReplicaService    ] Subscribing at LogPosition: 1115 (0x45B) to MASTER [
10.80.10.11:11001, {46577878-07ac-4f88-9a42-8889a62e649e}] as replica with SubscriptionId: {d38466a5-b4e0-49e2-9d62-9346d9dc28cf}, ConnectionId: {581d65d9-8d47-4da9-a50f-88a931682e8d}, LocalEndPoint: [], Epochs:
E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}...
.
[PID:21182:010 2014.01.14 11:00:35.908 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:11003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:028 2014.01.14 11:00:35.908 INFO Â TcpConnectionManager] Connection 'master-normal' ({581d65d9-8d47-4da9-a50f-88a931682e8d}) to [
10.80.10.11:11001] established.
[PID:21182:010 2014.01.14 11:00:35.914 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:007 2014.01.14 11:00:35.927 INFO Â ClusterStorageWriter] === SUBSCRIBED to [
10.80.10.11:11001,{46577878-07ac-4f88-9a42-8889a62e649e}] at 1115 (0x45B). SubscriptionId: {d38466a5-b4e0-49e2-9d62-9346d9dc28cf}.
[PID:21182:010 2014.01.14 11:00:35.927 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] IS CATCHING UP!!! BANZAI!!! MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21182:010 2014.01.14 11:00:35.930 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] CLONE ASSIGNMENT RECEIVED FROM [
10.80.10.11:11001,n/a,{46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21182:010 2014.01.14 11:00:35.930 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] IS CLONE!!! SPARTA!!! MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21182:010 2014.01.14 11:00:35.930 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] SLAVE ASSIGNMENT RECEIVED FROM [
10.80.10.11:11001,n/a,{46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21182:010 2014.01.14 11:00:35.930 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] IS SLAVE!!! SPARTA!!! MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21182:015 2014.01.14 11:00:35.936 DEBUG EpochManager     ] === Update Last Epoch E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09} (previous epoch at 0).
[PID:21182:010 2014.01.14 11:00:36.079 DEBUG ElectionsService   ] ELECTIONS: (V=19) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:36.079 DEBUG ElectionsService   ] ELECTIONS: (V=20) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:36.079 DEBUG ElectionsService   ] ELECTIONS: (V=20) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:37.082 DEBUG ElectionsService   ] ELECTIONS: (V=20) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:37.082 DEBUG ElectionsService   ] ELECTIONS: (V=21) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:37.082 DEBUG ElectionsService   ] ELECTIONS: (V=21) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:031 2014.01.14 11:00:37.934 INFO  TcpConnection    ] ES TcpConnection closed [11:00:37.934: N10.80.10.11:11001, L10.80.10.11:58565, {581d65d9-8d47-4da9-a50f-88a931682e8d}]:
Received bytes: 661, Sent bytes: 492
Send calls: 4, callbacks: 4
Receive calls: 6, callbacks: 6
Close reason: [Success] Socket closed
[PID:21182:031 2014.01.14 11:00:37.934 INFO Â TcpConnectionManager] Connection 'master-normal' [
10.80.10.11:11001, {581d65d9-8d47-4da9-a50f-88a931682e8d}] closed: Success.
[PID:21182:010 2014.01.14 11:00:37.935 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:11001] is DEAD (TCP connection lost).
[PID:21182:010 2014.01.14 11:00:37.935 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (TCP connection lost to [
10.80.10.11:11001])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:37.935 DEBUG ClusterVNodeControll] There is NO MASTER or MASTER is DEAD according to GOSSIP. Starting new elections. MASTER: [InstanceId: {46577878-07ac-4f88-9a42-8889a62e649e}, InternalTcp:
10.80.10.11:11001, InternalSecureTcp: , ExternalTcp:
10.80.10.11:11002, ExternalSecureTcp: , InternalHttp:
10.80.10.11:11003, ExternalHttp:
10.80.10.11:11004].
[PID:21182:010 2014.01.14 11:00:38.083 DEBUG ElectionsService   ] ELECTIONS: (V=21) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:38.083 DEBUG ElectionsService   ] ELECTIONS: (V=22) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:38.083 DEBUG ElectionsService   ] ELECTIONS: (V=22) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:38.093 DEBUG ElectionsService   ] ELECTIONS: (IV=18) VIEWCHANGEPROOF FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}]. JUMPING TO NON-LEADER STATE.
[PID:21182:010 2014.01.14 11:00:38.093 DEBUG ElectionsService   ] ELECTIONS: (V=18) SHIFT TO REG_NONLEADER.
[PID:21182:010 2014.01.14 11:00:38.093 DEBUG ElectionsService   ] ELECTIONS: (V=21) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21182:010 2014.01.14 11:00:38.093 DEBUG ElectionsService   ] ELECTIONS: (V=21) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:38.093 DEBUG ElectionsService   ] ELECTIONS: (V=21) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:38.093 DEBUG ElectionsService   ] ELECTIONS: (V=21) MAJORITY OF VIEWCHANGE.
[PID:21182:010 2014.01.14 11:00:38.093 DEBUG ElectionsService   ] ELECTIONS: (V=21) SHIFT TO PREPARE PHASE.
[PID:21182:010 2014.01.14 11:00:38.093 DEBUG ElectionsService   ] ELECTIONS: (V=21) PREPARE_OK FROM [
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}](L=803,W=1327,C=1327,E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}).
[PID:21182:010 2014.01.14 11:00:38.093 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:38.094 DEBUG ClusterVNodeControll] There is NO MASTER or MASTER is DEAD according to GOSSIP. Starting new elections. MASTER: [InstanceId: {46577878-07ac-4f88-9a42-8889a62e649e}, InternalTcp:
10.80.10.11:11001, InternalSecureTcp: , ExternalTcp:
10.80.10.11:11002, ExternalSecureTcp: , InternalHttp:
10.80.10.11:11003, ExternalHttp:
10.80.10.11:11004].
[PID:21182:010 2014.01.14 11:00:38.094 DEBUG ClusterVNodeControll] There is NO MASTER or MASTER is DEAD according to GOSSIP. Starting new elections. MASTER: [InstanceId: {46577878-07ac-4f88-9a42-8889a62e649e}, InternalTcp:
10.80.10.11:11001, InternalSecureTcp: , ExternalTcp:
10.80.10.11:11002, ExternalSecureTcp: , InternalHttp:
10.80.10.11:11003, ExternalHttp:
10.80.10.11:11004].
[PID:21182:010 2014.01.14 11:00:38.436 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] PRE-REPLICA STATE, WAITING FOR CHASER TO CATCH UP... MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21182:010 2014.01.14 11:00:38.436 TRACE TcpConnectionManager] Closing connection 'master-normal' [
10.80.10.11:11001, L10.80.10.11:58565, {581d65d9-8d47-4da9-a50f-88a931682e8d}] cleanly. Reason: Reconnecting from old master [
10.80.10.11:11001] to new master: [
10.80.10.11:11001].
[PID:21182:010 2014.01.14 11:00:38.437 DEBUG ClusterVNodeControll] There is NO MASTER or MASTER is DEAD according to GOSSIP. Starting new elections. MASTER: [InstanceId: {46577878-07ac-4f88-9a42-8889a62e649e}, InternalTcp:
10.80.10.11:11001, InternalSecureTcp: , ExternalTcp:
10.80.10.11:11002, ExternalSecureTcp: , InternalHttp:
10.80.10.11:11003, ExternalHttp:
10.80.10.11:11004].
[PID:21182:010 2014.01.14 11:00:38.437 INFO  ReplicaService    ] Subscribing at LogPosition: 1327 (0x52F) to MASTER [
10.80.10.11:11001, {46577878-07ac-4f88-9a42-8889a62e649e}] as replica with SubscriptionId: {7bf45ec7-421b-457d-9788-ffcbb1fb5437}, ConnectionId: {a252966f-405f-4bef-937e-b42cfd396eda}, LocalEndPoint: [], Epochs:
E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}
E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}...
.
[PID:21182:034 2014.01.14 11:00:38.912 INFO Â TcpConnectionManager] Connection 'master-normal' ({a252966f-405f-4bef-937e-b42cfd396eda}) to [
10.80.10.11:11001] established.
[PID:21182:010 2014.01.14 11:00:38.914 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (TCP connection established to [
10.80.10.11:11001])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:38.914 TRACE GossipServiceBase  ] Looks like master [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}] is DEAD (Gossip send failed), though we wait for TCP to decide.
[PID:21182:010 2014.01.14 11:00:38.914 DEBUG ElectionsService   ] ELECTIONS: (V=22) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21182:010 2014.01.14 11:00:38.914 DEBUG ElectionsService   ] ELECTIONS: (V=22) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:38.914 DEBUG ElectionsService   ] ELECTIONS: (V=22) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:38.914 DEBUG ElectionsService   ] ELECTIONS: (V=22) MAJORITY OF VIEWCHANGE.
[PID:21182:010 2014.01.14 11:00:39.084 DEBUG ElectionsService   ] ELECTIONS: (V=22) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:39.084 DEBUG ElectionsService   ] ELECTIONS: (V=23) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:39.084 DEBUG ElectionsService   ] ELECTIONS: (V=23) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:39.411 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] IS CATCHING UP!!! BANZAI!!! MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21182:007 2014.01.14 11:00:39.411 INFO Â ClusterStorageWriter] === SUBSCRIBED to [
10.80.10.11:11001,{46577878-07ac-4f88-9a42-8889a62e649e}] at 1327 (0x52F). SubscriptionId: {7bf45ec7-421b-457d-9788-ffcbb1fb5437}.
[PID:21182:010 2014.01.14 11:00:40.086 DEBUG ElectionsService   ] ELECTIONS: (V=23) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:40.086 DEBUG ElectionsService   ] ELECTIONS: (V=24) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:40.086 DEBUG ElectionsService   ] ELECTIONS: (V=24) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:40.412 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] CLONE ASSIGNMENT RECEIVED FROM [
10.80.10.11:11001,n/a,{46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21182:010 2014.01.14 11:00:40.412 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] IS CLONE!!! SPARTA!!! MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21182:010 2014.01.14 11:00:40.413 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] SLAVE ASSIGNMENT RECEIVED FROM [
10.80.10.11:11001,n/a,{46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21182:010 2014.01.14 11:00:40.413 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] IS SLAVE!!! SPARTA!!! MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21182:010 2014.01.14 11:00:41.087 DEBUG ElectionsService   ] ELECTIONS: (V=24) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:41.087 DEBUG ElectionsService   ] ELECTIONS: (V=25) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:41.087 DEBUG ElectionsService   ] ELECTIONS: (V=25) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:41.417 TRACE GossipServiceBase  ] Looks like master [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}] is DEAD (Gossip send failed), though we wait for TCP to decide.
[PID:21182:010 2014.01.14 11:00:41.417 DEBUG ElectionsService   ] ELECTIONS: (V=23) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21182:010 2014.01.14 11:00:41.417 DEBUG ElectionsService   ] ELECTIONS: (V=23) MAJORITY OF VIEWCHANGE.
[PID:21182:010 2014.01.14 11:00:41.417 DEBUG ElectionsService   ] ELECTIONS: (V=25) SHIFT TO PREPARE PHASE.
[PID:21182:010 2014.01.14 11:00:41.417 DEBUG ElectionsService   ] ELECTIONS: (V=25) PREPARE_OK FROM [
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}](L=803,W=1327,C=1327,E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}).
[PID:21182:036 2014.01.14 11:00:41.914 INFO  TcpConnection    ] ES TcpConnection closed [11:00:41.914: N10.80.10.11:11001, L10.80.10.11:58584, {a252966f-405f-4bef-937e-b42cfd396eda}]:
Received bytes: 199, Sent bytes: 517
Send calls: 4, callbacks: 3
Receive calls: 4, callbacks: 4
Close reason: [Success] Socket closed
[PID:21182:036 2014.01.14 11:00:41.914 INFO Â TcpConnectionManager] Connection 'master-normal' [
10.80.10.11:11001, {a252966f-405f-4bef-937e-b42cfd396eda}] closed: Success.
[PID:21182:010 2014.01.14 11:00:41.915 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:11001] is DEAD (TCP connection lost).
[PID:21182:010 2014.01.14 11:00:41.915 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (TCP connection lost to [
10.80.10.11:11001])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:41.916 DEBUG ClusterVNodeControll] There is NO MASTER or MASTER is DEAD according to GOSSIP. Starting new elections. MASTER: [InstanceId: {46577878-07ac-4f88-9a42-8889a62e649e}, InternalTcp:
10.80.10.11:11001, InternalSecureTcp: , ExternalTcp:
10.80.10.11:11002, ExternalSecureTcp: , InternalHttp:
10.80.10.11:11003, ExternalHttp:
10.80.10.11:11004].
[PID:21182:010 2014.01.14 11:00:41.925 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:41.926 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:11003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:41.926 DEBUG ClusterVNodeControll] There is NO MASTER or MASTER is DEAD according to GOSSIP. Starting new elections. MASTER: [InstanceId: {46577878-07ac-4f88-9a42-8889a62e649e}, InternalTcp:
10.80.10.11:11001, InternalSecureTcp: , ExternalTcp:
10.80.10.11:11002, ExternalSecureTcp: , InternalHttp:
10.80.10.11:11003, ExternalHttp:
10.80.10.11:11004].
[PID:21182:010 2014.01.14 11:00:41.949 DEBUG ElectionsService   ] ELECTIONS: (V=25) PREPARE_OK FROM [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=803,W=1327,C=1327,E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}).
[PID:21182:010 2014.01.14 11:00:41.949 DEBUG ElectionsService   ] ELECTIONS: (V=25) SHIFT TO REG_LEADER.
[PID:21182:010 2014.01.14 11:00:41.954 DEBUG ElectionsService   ] ELECTIONS: (V=25) SENDING PROPOSAL CANDIDATE: [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1327,C=1327,E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}), ME: [
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}](L=803,W=1327,C=1327,E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}).
[PID:21182:010 2014.01.14 11:00:41.954 DEBUG ElectionsService   ] ELECTIONS: (V=25) ACCEPT FROM [
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]).
[PID:21182:010 2014.01.14 11:00:42.095 DEBUG ElectionsService   ] ELECTIONS: (V=25) TIMED OUT! (S=Leader, M=).
[PID:21182:010 2014.01.14 11:00:42.095 DEBUG ElectionsService   ] ELECTIONS: (V=26) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:42.095 DEBUG ElectionsService   ] ELECTIONS: (V=26) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:42.417 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] PRE-REPLICA STATE, WAITING FOR CHASER TO CATCH UP... MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21182:010 2014.01.14 11:00:42.417 TRACE TcpConnectionManager] Closing connection 'master-normal' [
10.80.10.11:11001, L10.80.10.11:58584, {a252966f-405f-4bef-937e-b42cfd396eda}] cleanly. Reason: Reconnecting from old master [
10.80.10.11:11001] to new master: [
10.80.10.11:11001].
[PID:21182:010 2014.01.14 11:00:42.419 INFO  ReplicaService    ] Subscribing at LogPosition: 1327 (0x52F) to MASTER [
10.80.10.11:11001, {46577878-07ac-4f88-9a42-8889a62e649e}] as replica with SubscriptionId: {d404f63a-cc2f-4a44-a073-a0c1e8876c50}, ConnectionId: {d39d94a1-4c3f-4457-82ec-94671b489b58}, LocalEndPoint: [], Epochs:
E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}
E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}...
.
[PID:21182:042 2014.01.14 11:00:42.922 INFO Â TcpConnectionManager] Connection 'master-normal' ({d39d94a1-4c3f-4457-82ec-94671b489b58}) to [
10.80.10.11:11001] established.
[PID:21182:010 2014.01.14 11:00:42.926 TRACE GossipServiceBase  ] Looks like master [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}] is DEAD (Gossip send failed), though we wait for TCP to decide.
[PID:21182:010 2014.01.14 11:00:42.927 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:11003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:42.927 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] IS CATCHING UP!!! BANZAI!!! MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21182:007 2014.01.14 11:00:42.927 INFO Â ClusterStorageWriter] === SUBSCRIBED to [
10.80.10.11:11001,{46577878-07ac-4f88-9a42-8889a62e649e}] at 1327 (0x52F). SubscriptionId: {d404f63a-cc2f-4a44-a073-a0c1e8876c50}.
[PID:21182:010 2014.01.14 11:00:43.096 DEBUG ElectionsService   ] ELECTIONS: (V=26) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:43.096 DEBUG ElectionsService   ] ELECTIONS: (V=27) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:43.096 DEBUG ElectionsService   ] ELECTIONS: (V=27) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:43.108 DEBUG ElectionsService   ] ELECTIONS: (V=26) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21182:010 2014.01.14 11:00:43.108 DEBUG ElectionsService   ] ELECTIONS: (V=26) MAJORITY OF VIEWCHANGE.
[PID:21182:010 2014.01.14 11:00:43.293 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:44.098 DEBUG ElectionsService   ] ELECTIONS: (V=27) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:44.098 DEBUG ElectionsService   ] ELECTIONS: (V=28) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:44.098 DEBUG ElectionsService   ] ELECTIONS: (V=28) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:44.921 DEBUG ElectionsService   ] ELECTIONS: (V=27) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21182:010 2014.01.14 11:00:44.921 DEBUG ElectionsService   ] ELECTIONS: (V=27) MAJORITY OF VIEWCHANGE.
[PID:21182:010 2014.01.14 11:00:44.921 DEBUG ElectionsService   ] ELECTIONS: (V=28) SHIFT TO PREPARE PHASE.
[PID:21182:010 2014.01.14 11:00:44.921 DEBUG ElectionsService   ] ELECTIONS: (V=28) PREPARE_OK FROM [
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}](L=803,W=1327,C=1327,E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}).
[PID:21182:010 2014.01.14 11:00:44.922 TRACE GossipServiceBase  ] Looks like master [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}] is DEAD (Gossip send failed), though we wait for TCP to decide.
[PID:21182:010 2014.01.14 11:00:45.099 DEBUG ElectionsService   ] ELECTIONS: (V=28) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:45.099 DEBUG ElectionsService   ] ELECTIONS: (V=29) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:45.099 DEBUG ElectionsService   ] ELECTIONS: (V=29) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:45.922 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] CLONE ASSIGNMENT RECEIVED FROM [
10.80.10.11:11001,n/a,{46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21182:010 2014.01.14 11:00:45.922 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] IS CLONE!!! SPARTA!!! MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21182:010 2014.01.14 11:00:45.922 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:13003] is DEAD (Gossip send failed).
[PID:21182:010 2014.01.14 11:00:45.922 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip send failed to [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:45.924 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] SLAVE ASSIGNMENT RECEIVED FROM [
10.80.10.11:11001,n/a,{46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21182:010 2014.01.14 11:00:45.924 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] IS SLAVE!!! SPARTA!!! MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21182:015 2014.01.14 11:00:45.925 DEBUG EpochManager     ] === Update Last Epoch E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843} (previous epoch at 1115).
[PID:21182:010 2014.01.14 11:00:46.101 DEBUG ElectionsService   ] ELECTIONS: (V=29) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:46.101 DEBUG ElectionsService   ] ELECTIONS: (V=30) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:46.101 DEBUG ElectionsService   ] ELECTIONS: (V=30) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:47.102 DEBUG ElectionsService   ] ELECTIONS: (V=30) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:47.102 DEBUG ElectionsService   ] ELECTIONS: (V=31) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:47.102 DEBUG ElectionsService   ] ELECTIONS: (V=31) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:47.431 TRACE GossipServiceBase  ] Looks like master [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}] is DEAD (Gossip send failed), though we wait for TCP to decide.
[PID:21182:015 2014.01.14 11:00:47.436 DEBUG EpochManager     ] === Update Last Epoch E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc} (previous epoch at 1327).
[PID:21182:010 2014.01.14 11:00:47.926 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:48.104 DEBUG ElectionsService   ] ELECTIONS: (V=31) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:48.104 DEBUG ElectionsService   ] ELECTIONS: (V=32) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:48.104 DEBUG ElectionsService   ] ELECTIONS: (V=32) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:48.779 DEBUG ElectionsService   ] ELECTIONS: (V=32) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21182:010 2014.01.14 11:00:48.779 DEBUG ElectionsService   ] ELECTIONS: (V=32) MAJORITY OF VIEWCHANGE.
[PID:21182:010 2014.01.14 11:00:48.999 DEBUG ElectionsService   ] ELECTIONS: (IV=31) VIEWCHANGEPROOF FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}]. JUMPING TO LEADER STATE.
[PID:21182:010 2014.01.14 11:00:48.999 DEBUG ElectionsService   ] ELECTIONS: (V=31) SHIFT TO PREPARE PHASE.
[PID:21182:010 2014.01.14 11:00:48.999 DEBUG ElectionsService   ] ELECTIONS: (V=31) PREPARE_OK FROM [
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}](L=803,W=1757,C=1757,E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}).
[PID:21182:010 2014.01.14 11:00:49.439 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:49.940 TRACE GossipServiceBase  ] Looks like master [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}] is DEAD (Gossip send failed), though we wait for TCP to decide.
[PID:21182:010 2014.01.14 11:00:49.942 DEBUG ElectionsService   ] ELECTIONS: (V=33) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21182:010 2014.01.14 11:00:49.942 DEBUG ElectionsService   ] ELECTIONS: (V=33) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:49.942 DEBUG ElectionsService   ] ELECTIONS: (V=33) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:49.942 DEBUG ElectionsService   ] ELECTIONS: (V=33) MAJORITY OF VIEWCHANGE.
[PID:21182:010 2014.01.14 11:00:50.943 DEBUG ElectionsService   ] ELECTIONS: (V=33) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:50.943 DEBUG ElectionsService   ] ELECTIONS: (V=34) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:50.943 DEBUG ElectionsService   ] ELECTIONS: (V=34) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:51.439 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:51.500 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:13003] is DEAD (Gossip send failed).
[PID:21182:010 2014.01.14 11:00:51.500 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip send failed to [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:51.944 DEBUG ElectionsService   ] ELECTIONS: (V=34) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:51.944 DEBUG ElectionsService   ] ELECTIONS: (V=35) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:51.944 DEBUG ElectionsService   ] ELECTIONS: (V=35) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:52.445 TRACE GossipServiceBase  ] Looks like master [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}] is DEAD (Gossip send failed), though we wait for TCP to decide.
[PID:21182:010 2014.01.14 11:00:52.445 DEBUG ElectionsService   ] ELECTIONS: (V=33) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21182:010 2014.01.14 11:00:52.445 DEBUG ElectionsService   ] ELECTIONS: (V=33) MAJORITY OF VIEWCHANGE.
[PID:21182:010 2014.01.14 11:00:52.445 DEBUG ElectionsService   ] ELECTIONS: (V=32) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21182:010 2014.01.14 11:00:52.446 DEBUG ElectionsService   ] ELECTIONS: (V=35) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21182:010 2014.01.14 11:00:52.446 DEBUG ElectionsService   ] ELECTIONS: (V=34) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21182:010 2014.01.14 11:00:52.945 DEBUG ElectionsService   ] ELECTIONS: (V=35) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:52.951 DEBUG ElectionsService   ] ELECTIONS: (V=36) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:52.951 DEBUG ElectionsService   ] ELECTIONS: (V=36) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:53.619 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:53.955 DEBUG ElectionsService   ] ELECTIONS: (V=36) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:53.955 DEBUG ElectionsService   ] ELECTIONS: (V=37) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:53.955 DEBUG ElectionsService   ] ELECTIONS: (V=37) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:54.956 DEBUG ElectionsService   ] ELECTIONS: (V=37) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:54.956 DEBUG ElectionsService   ] ELECTIONS: (V=38) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:54.956 DEBUG ElectionsService   ] ELECTIONS: (V=38) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:55.447 TRACE GossipServiceBase  ] Looks like master [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}] is DEAD (Gossip send failed), though we wait for TCP to decide.
[PID:21182:010 2014.01.14 11:00:55.447 DEBUG ElectionsService   ] ELECTIONS: (V=36) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21182:010 2014.01.14 11:00:55.447 DEBUG ElectionsService   ] ELECTIONS: (V=36) MAJORITY OF VIEWCHANGE.
[PID:21182:057 2014.01.14 11:00:55.956 INFO  TcpConnection    ] ES TcpConnection closed [11:00:55.956: N10.80.10.11:11001, L10.80.10.11:58601, {d39d94a1-4c3f-4457-82ec-94671b489b58}]:
Received bytes: 1141, Sent bytes: 715
Send calls: 14, callbacks: 13
Receive calls: 13, callbacks: 13
Close reason: [Success] Socket closed
[PID:21182:057 2014.01.14 11:00:55.956 INFO Â TcpConnectionManager] Connection 'master-normal' [
10.80.10.11:11001, {d39d94a1-4c3f-4457-82ec-94671b489b58}] closed: Success.
[PID:21182:010 2014.01.14 11:00:55.956 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:11001] is DEAD (TCP connection lost).
[PID:21182:010 2014.01.14 11:00:55.958 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (TCP connection lost to [
10.80.10.11:11001])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:55.958 DEBUG ElectionsService   ] ELECTIONS: (V=38) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:55.958 DEBUG ElectionsService   ] ELECTIONS: (V=39) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:55.958 DEBUG ElectionsService   ] ELECTIONS: (V=39) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:55.958 DEBUG ClusterVNodeControll] There is NO MASTER or MASTER is DEAD according to GOSSIP. Starting new elections. MASTER: [InstanceId: {46577878-07ac-4f88-9a42-8889a62e649e}, InternalTcp:
10.80.10.11:11001, InternalSecureTcp: , ExternalTcp:
10.80.10.11:11002, ExternalSecureTcp: , InternalHttp:
10.80.10.11:11003, ExternalHttp:
10.80.10.11:11004].
[PID:21182:010 2014.01.14 11:00:56.458 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] PRE-REPLICA STATE, WAITING FOR CHASER TO CATCH UP... MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21182:010 2014.01.14 11:00:56.458 TRACE TcpConnectionManager] Closing connection 'master-normal' [
10.80.10.11:11001, L10.80.10.11:58601, {d39d94a1-4c3f-4457-82ec-94671b489b58}] cleanly. Reason: Reconnecting from old master [
10.80.10.11:11001] to new master: [
10.80.10.11:11001].
[PID:21182:010 2014.01.14 11:00:56.459 DEBUG ClusterVNodeControll] There is NO MASTER or MASTER is DEAD according to GOSSIP. Starting new elections. MASTER: [InstanceId: {46577878-07ac-4f88-9a42-8889a62e649e}, InternalTcp:
10.80.10.11:11001, InternalSecureTcp: , ExternalTcp:
10.80.10.11:11002, ExternalSecureTcp: , InternalHttp:
10.80.10.11:11003, ExternalHttp:
10.80.10.11:11004].
[PID:21182:010 2014.01.14 11:00:56.459 INFO  ReplicaService    ] Subscribing at LogPosition: 1757 (0x6DD) to MASTER [
10.80.10.11:11001, {46577878-07ac-4f88-9a42-8889a62e649e}] as replica with SubscriptionId: {2ac16b4b-eac2-4ac0-a457-9cb6c34691c9}, ConnectionId: {04cf5cf3-0933-422d-ae32-79cef06334db}, LocalEndPoint: [], Epochs:
E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}
E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}
E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}
E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}...
.
[PID:21182:010 2014.01.14 11:00:56.947 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:13003] is DEAD (Gossip send failed).
[PID:21182:010 2014.01.14 11:00:56.947 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip send failed to [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:56.947 DEBUG ClusterVNodeControll] There is NO MASTER or MASTER is DEAD according to GOSSIP. Starting new elections. MASTER: [InstanceId: {46577878-07ac-4f88-9a42-8889a62e649e}, InternalTcp:
10.80.10.11:11001, InternalSecureTcp: , ExternalTcp:
10.80.10.11:11002, ExternalSecureTcp: , InternalHttp:
10.80.10.11:11003, ExternalHttp:
10.80.10.11:11004].
[PID:21182:010 2014.01.14 11:00:56.949 DEBUG ElectionsService   ] ELECTIONS: (V=37) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21182:010 2014.01.14 11:00:56.949 DEBUG ElectionsService   ] ELECTIONS: (V=37) MAJORITY OF VIEWCHANGE.
[PID:21182:010 2014.01.14 11:00:56.949 DEBUG ElectionsService   ] ELECTIONS: (V=39) SHIFT TO PREPARE PHASE.
[PID:21182:010 2014.01.14 11:00:56.949 DEBUG ElectionsService   ] ELECTIONS: (V=39) PREPARE_OK FROM [
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}](L=803,W=1757,C=1757,E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}).
[PID:21182:010 2014.01.14 11:00:56.960 DEBUG ElectionsService   ] ELECTIONS: (V=39) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:56.960 DEBUG ElectionsService   ] ELECTIONS: (V=40) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:56.960 DEBUG ElectionsService   ] ELECTIONS: (V=40) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:57.460 INFO  ReplicaService    ] Subscribing at LogPosition: 1757 (0x6DD) to MASTER [
10.80.10.11:11001, {46577878-07ac-4f88-9a42-8889a62e649e}] as replica with SubscriptionId: {1c2dacb0-e1bd-4587-acb9-619affe40bb2}, ConnectionId: {04cf5cf3-0933-422d-ae32-79cef06334db}, LocalEndPoint: [], Epochs:
E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}
E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}
E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}
E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}...
.
[PID:21182:061 2014.01.14 11:00:57.946 INFO  TcpConnection    ] ES TcpConnection closed [11:00:57.946: N10.80.10.11:11001, L, {04cf5cf3-0933-422d-ae32-79cef06334db}]:
Received bytes: 0, Sent bytes: 0
Send calls: 0, callbacks: 0
Receive calls: 0, callbacks: 0
Close reason: [Success] Connection establishment timeout.
[PID:21182:061 2014.01.14 11:00:57.946 INFO Â TcpConnectionManager] Connection 'master-normal' [
10.80.10.11:11001, {04cf5cf3-0933-422d-ae32-79cef06334db}] closed: Success.
[PID:21182:010 2014.01.14 11:00:57.952 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:11003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:57.952 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:57.960 DEBUG ElectionsService   ] ELECTIONS: (V=40) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:57.960 DEBUG ElectionsService   ] ELECTIONS: (V=41) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:57.960 DEBUG ElectionsService   ] ELECTIONS: (V=41) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:57.967 DEBUG ElectionsService   ] ELECTIONS: (V=41) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21182:010 2014.01.14 11:00:57.967 DEBUG ElectionsService   ] ELECTIONS: (V=41) MAJORITY OF VIEWCHANGE.
[PID:21182:010 2014.01.14 11:00:58.448 TRACE TcpConnectionManager] Closing connection 'master-normal' [
10.80.10.11:11001, L, {04cf5cf3-0933-422d-ae32-79cef06334db}] cleanly. Reason: Reconnecting from old master [
10.80.10.11:11001] to new master: [
10.80.10.11:11001].
[PID:21182:061 2014.01.14 11:00:58.454 INFO Â TcpConnectionManager] Connection 'master-normal' ({d1cec8f0-21db-494d-903b-f074cdb7906f}) to [
10.80.10.11:11001] established.
[PID:21182:010 2014.01.14 11:00:58.461 INFO  ReplicaService    ] Subscribing at LogPosition: 1757 (0x6DD) to MASTER [
10.80.10.11:11001, {46577878-07ac-4f88-9a42-8889a62e649e}] as replica with SubscriptionId: {fbd71414-8b30-499b-a854-9293c4bb1b6d}, ConnectionId: {d1cec8f0-21db-494d-903b-f074cdb7906f}, LocalEndPoint: [
10.80.10.11:58653], Epochs:
E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}
E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}
E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}
E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}...
.
[PID:21182:010 2014.01.14 11:00:58.737 TRACE GossipServiceBase  ] Looks like master [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}] is DEAD (Gossip send failed), though we wait for TCP to decide.
[PID:21182:061 2014.01.14 11:00:58.737 INFO  TcpConnection    ] ES TcpConnection closed [11:00:58.737: N10.80.10.11:11001, L10.80.10.11:58653, {d1cec8f0-21db-494d-903b-f074cdb7906f}]:
Received bytes: 0, Sent bytes: 185
Send calls: 1, callbacks: 1
Receive calls: 1, callbacks: 1
Close reason: [ConnectionReset] Socket receive error
[PID:21182:061 2014.01.14 11:00:58.737 INFO Â TcpConnectionManager] Connection 'master-normal' [
10.80.10.11:11001, {d1cec8f0-21db-494d-903b-f074cdb7906f}] closed: ConnectionReset.
[PID:21182:010 2014.01.14 11:00:58.737 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:11001] is DEAD (TCP connection lost).
[PID:21182:010 2014.01.14 11:00:58.738 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (TCP connection lost to [
10.80.10.11:11001])
Old:
New:
--------------------------------------------------------------------------------
[PID:21182:010 2014.01.14 11:00:58.738 DEBUG ClusterVNodeControll] There is NO MASTER or MASTER is DEAD according to GOSSIP. Starting new elections. MASTER: [InstanceId: {46577878-07ac-4f88-9a42-8889a62e649e}, InternalTcp:
10.80.10.11:11001, InternalSecureTcp: , ExternalTcp:
10.80.10.11:11002, ExternalSecureTcp: , InternalHttp:
10.80.10.11:11003, ExternalHttp:
10.80.10.11:11004].
[PID:21182:010 2014.01.14 11:00:58.963 DEBUG ElectionsService   ] ELECTIONS: (V=41) TIMED OUT! (S=ElectingLeader, M=).
[PID:21182:010 2014.01.14 11:00:58.963 DEBUG ElectionsService   ] ELECTIONS: (V=42) SHIFT TO LEADER ELECTION.
[PID:21182:010 2014.01.14 11:00:58.963 DEBUG ElectionsService   ] ELECTIONS: (V=42) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21182:010 2014.01.14 11:00:58.968 DEBUG ElectionsService   ] ELECTIONS: (V=42) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21182:010 2014.01.14 11:00:58.968 DEBUG ElectionsService   ] ELECTIONS: (V=42) MAJORITY OF VIEWCHANGE.
[PID:21182:010 2014.01.14 11:00:58.968 DEBUG ElectionsService   ] ELECTIONS: (V=42) PREPARE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21182:010 2014.01.14 11:00:58.968 DEBUG ElectionsService   ] ELECTIONS: (V=42) SHIFT TO REG_NONLEADER.
[PID:21182:010 2014.01.14 11:00:58.973 DEBUG ElectionsService   ] ELECTIONS: (V=42) PROPOSAL FROM [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}] M=[
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=803,W=1972,C=1972,E4@1757:{8668e607-7c93-4b0c-b7a6-3102ae249983}). ME=[
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}](L=803,W=1757,C=1757,E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}).
[PID:21182:010 2014.01.14 11:00:58.973 DEBUG ElectionsService   ] ELECTIONS: (V=42) ACCEPT FROM [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}] M=[
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}]).
[PID:21182:010 2014.01.14 11:00:58.973 DEBUG ElectionsService   ] ELECTIONS: (V=42) ACCEPT FROM [
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}] M=[
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}]).
[PID:21182:010 2014.01.14 11:00:58.973 INFO  ElectionsService   ] ELECTIONS: (V=42) DONE. ELECTED MASTER = [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=803,W=1972,C=1972,E4@1757:{8668e607-7c93-4b0c-b7a6-3102ae249983}). ME=[
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}](L=803,W=1757,C=1757,E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}).
[PID:21182:010 2014.01.14 11:00:58.973 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] PRE-REPLICA STATE, WAITING FOR CHASER TO CATCH UP... MASTER IS [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}]
[PID:21182:010 2014.01.14 11:00:58.974 TRACE TcpConnectionManager] Closing connection 'master-normal' [
10.80.10.11:11001, L10.80.10.11:58653, {d1cec8f0-21db-494d-903b-f074cdb7906f}] cleanly. Reason: Reconnecting from old master [
10.80.10.11:11001] to new master: [
10.80.10.11:13001].
[PID:21182:010 2014.01.14 11:00:58.974 INFO  ReplicaService    ] Subscribing at LogPosition: 1757 (0x6DD) to MASTER [
10.80.10.11:13001, {40cf708a-9a28-4ea4-941b-20a053f34a89}] as replica with SubscriptionId: {a138758e-f684-4950-9148-4fcd5df2faa8}, ConnectionId: {0c168a36-c547-4eb3-9eab-40b7acc3b7bb}, LocalEndPoint: [
10.80.10.11:26102], Epochs:
E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}
E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}
E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}
E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}...
.
[PID:21182:061 2014.01.14 11:00:58.974 INFO Â TcpConnectionManager] Connection 'master-normal' ({0c168a36-c547-4eb3-9eab-40b7acc3b7bb}) to [
10.80.10.11:13001] established.
[PID:21182:010 2014.01.14 11:00:59.121 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] IS CATCHING UP!!! BANZAI!!! MASTER IS [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}]
[PID:21182:007 2014.01.14 11:00:59.121 INFO Â ClusterStorageWriter] === SUBSCRIBED to [
10.80.10.11:13001,{40cf708a-9a28-4ea4-941b-20a053f34a89}] at 1757 (0x6DD). SubscriptionId: {a138758e-f684-4950-9148-4fcd5df2faa8}.
[PID:21182:010 2014.01.14 11:00:59.133 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] CLONE ASSIGNMENT RECEIVED FROM [
10.80.10.11:13001,n/a,{40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21182:010 2014.01.14 11:00:59.133 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:12003] IS CLONE!!! SPARTA!!! MASTER IS [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}]
[PID:21182:015 2014.01.14 11:00:59.142 DEBUG EpochManager     ] === Update Last Epoch E4@1757:{8668e607-7c93-4b0c-b7a6-3102ae249983} (previous epoch at 1542).
[PID:21182:015 2014.01.14 11:00:59.144 DEBUG EpochManager     ] === Update Last Epoch E5@1972:{98953efe-7a6e-4601-98b6-de6af46649b3} (previous epoch at 1757).
[PID:21182:010 2014.01.14 11:00:59.304 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:13003])
Old:
New:
--------------------------------------------------------------------------------
# cat /srv/eventsore/db-cluster3-logs/2014-01-14/10.80.10.11-13004-cluster-node.logÂ
[PID:21286:001 2014.01.14 11:00:25.020 INFO Â ProgramBase`1 Â Â Â ]Â
ES VERSION: Â Â Â Â Â Â Â no-werror (master/5433fdc82895c181e0325a5730d36424de8eb28f, Fri, 10 Jan 2014 13:48:40 +0000)
OS: Â Â Â Â Â Â Â Â Â Â Â Unknown (Unix 2.6.32.431)
RUNTIME: Â Â Â Â Â Â Â Â Â 3.2.5 (tarball Thu Dec 12 12:56:24 MSK 2013) (64-bit)
GC: Â Â Â Â Â Â Â Â Â Â Â 2 GENERATIONS
LOGS: Â Â Â Â Â Â Â Â Â Â /srv/eventsore/db-cluster3-logs
SHOW HELP: Â Â Â Â Â Â Â Â False (<DEFAULT>)
SHOW VERSION: Â Â Â Â Â Â False (<DEFAULT>)
LOGS DIR: Â Â Â Â Â Â Â Â /srv/eventsore/db-cluster3-logs (--logsdir from command line)
CONFIGS: Â Â Â Â Â Â Â Â Â <empty> (<DEFAULT>)
DEFINES: Â Â Â Â Â Â Â Â Â <empty> (<DEFAULT>)
INTERNAL IP: Â Â Â Â Â Â Â 10.80.10.11 (--internal-ip from command line)
EXTERNAL IP: Â Â Â Â Â Â Â 10.80.10.11 (--external-ip from command line)
INTERNAL HTTP PORT: Â Â Â 13003 (--internal-http-port from command line)
EXTERNAL HTTP PORT: Â Â Â 13004 (--external-http-port from command line)
INTERNAL TCP PORT: Â Â Â Â 13001 (--internal-tcp-port from command line)
INTERNAL SECURE TCP PORT: 0 (<DEFAULT>)
EXTERNAL TCP PORT: Â Â Â Â 13002 (--external-tcp-port from command line)
EXTERNAL SECURE TCP PORT: 0 (<DEFAULT>)
FORCE: Â Â Â Â Â Â Â Â Â Â False (<DEFAULT>)
CLUSTER SIZE: Â Â Â Â Â Â 3 (--cluster-size from command line)
MIN FLUSH DELAY MS: Â Â Â 2 (<DEFAULT>)
NODE PRIORITY: Â Â Â Â Â Â 0 (<DEFAULT>)
COMMIT COUNT: Â Â Â Â Â Â 2 (<DEFAULT>)
PREPARE COUNT: Â Â Â Â Â Â 2 (<DEFAULT>)
DISCOVER VIA DNS: Â Â Â Â False (--use-dns-discovery from command line)
CLUSTER DNS: Â Â Â Â Â Â Â fake.dns (<DEFAULT>)
CLUSTER GOSSIP PORT: Â Â Â 30777 (<DEFAULT>)
STATS PERIOD SEC: Â Â Â Â 300 (--stats-period-sec from command line)
CACHED CHUNKS: Â Â Â Â Â Â -1 (<DEFAULT>)
CHUNKS CACHE SIZE: Â Â Â Â 536871424 (<DEFAULT>)
DB PATH: Â Â Â Â Â Â Â Â Â /srv/eventsore/db-cluster3 (--db from command line)
IN MEM DB: Â Â Â Â Â Â Â Â False (<DEFAULT>)
SKIP DB VERIFY: Â Â Â Â Â False (<DEFAULT>)
RUN PROJECTIONS: Â Â Â Â Â All (--run-projections from command line)
PROJECTION THREADS: Â Â Â 3 (<DEFAULT>)
WORKER THREADS: Â Â Â Â Â 5 (<DEFAULT>)
HTTP PREFIXES: Â Â Â Â Â Â <empty> (<DEFAULT>)
ENABLE TRUSTED AUTH: Â Â Â True (--enable-trusted-auth from command line)
CERTIFICATE STORE: Â Â Â Â <empty> (<DEFAULT>)
CERTIFICATE NAME: Â Â Â Â <empty> (<DEFAULT>)
CERTIFICATE FILE: Â Â Â Â <empty> (<DEFAULT>)
CERTIFICATE PASSWORD: Â Â <empty> (<DEFAULT>)
USE INTERNAL SSL: Â Â Â Â False (<DEFAULT>)
SSL TARGET HOST: Â Â Â Â Â n/a (<DEFAULT>)
SSL VALIDATE SERVER: Â Â Â True (<DEFAULT>)
AUTHENTICATION TYPE: Â Â Â internal (<DEFAULT>)
AUTHENTICATION CONFIG FILE: <empty> (<DEFAULT>)
PREPARE TIMEOUT MS: Â Â Â 2000 (<DEFAULT>)
COMMIT TIMEOUT MS: Â Â Â Â 2000 (<DEFAULT>)
DISABLE SCAVENGE MERGING: False (<DEFAULT>)
[PID:21286:001 2014.01.14 11:00:25.100 INFO Â ProgramBase`1 Â Â Â ] Quorum size set to 2
[PID:21286:001 2014.01.14 11:00:25.115 INFO Â ProgramBase`1 Â Â Â ] Can't find plugins path: /opt/eventstore/eventstore-mono-20140114.1110/plugins
[PID:21286:001 2014.01.14 11:00:25.197 INFO Â ProgramBase`1 Â Â Â ]Â
INSTANCE ID: Â Â Â Â Â Â Â 40cf708a-9a28-4ea4-941b-20a053f34a89
DATABASE: Â Â Â Â Â Â Â Â /srv/eventsore/db-cluster3
WRITER CHECKPOINT: Â Â Â Â 0 (0x0)
CHASER CHECKPOINT: Â Â Â Â 0 (0x0)
EPOCH CHECKPOINT: Â Â Â Â -1 (0xFFFFFFFFFFFFFFFF)
TRUNCATE CHECKPOINT: Â Â Â -1 (0xFFFFFFFFFFFFFFFF)
[PID:21286:001 2014.01.14 11:00:25.472 TRACE MessageHierarchy   ] MessageHierarchy initialization took 00:00:00.2144775.
[PID:21286:001 2014.01.14 11:00:25.625 TRACE TFChunk       ] CACHED TFChunk #0-0 (chunk-000000.000000) in 00:00:00.0042778.
[PID:21286:001 2014.01.14 11:00:25.861 INFO  MiniWeb       ] Starting MiniWeb for /web/es/js/projections ==> /opt/eventstore/current/singlenode-web/js/projections
[PID:21286:001 2014.01.14 11:00:25.863 INFO  MiniWeb       ] Starting MiniWeb for /web/es/js/projections/v8/Prelude ==> /opt/eventstore/current/Prelude
[PID:21286:001 2014.01.14 11:00:25.863 INFO  MiniWeb       ] Starting MiniWeb for /web/es/js/projections/resources ==> /opt/eventstore/current/web-resources/js
[PID:21286:001 2014.01.14 11:00:25.865 TRACE MiniWeb       ] Binding MiniWeb to /web/es/js/projections/{*remaining_path}
[PID:21286:001 2014.01.14 11:00:25.865 TRACE MiniWeb       ] Binding MiniWeb to /web/es/js/projections/v8/Prelude/{*remaining_path}
[PID:21286:001 2014.01.14 11:00:25.866 TRACE MiniWeb       ] Binding MiniWeb to /web/es/js/projections/resources/{*remaining_path}
[PID:21286:001 2014.01.14 11:00:25.868 TRACE MiniWeb       ] Binding MiniWeb to /web/es/js/projections/{*remaining_path}
[PID:21286:001 2014.01.14 11:00:25.868 TRACE MiniWeb       ] Binding MiniWeb to /web/es/js/projections/v8/Prelude/{*remaining_path}
[PID:21286:001 2014.01.14 11:00:25.868 TRACE MiniWeb       ] Binding MiniWeb to /web/es/js/projections/resources/{*remaining_path}
[PID:21286:001 2014.01.14 11:00:25.874 INFO  MiniWeb       ] Starting MiniWeb for /web ==> /opt/eventstore/current/clusternode-web
[PID:21286:001 2014.01.14 11:00:25.874 INFO  MiniWeb       ] Starting MiniWeb for /web/es ==> /opt/eventstore/current/es-common-web
[PID:21286:001 2014.01.14 11:00:25.874 TRACE MiniWeb       ] Binding MiniWeb to /web/{*remaining_path}
[PID:21286:001 2014.01.14 11:00:25.875 TRACE MiniWeb       ] Binding MiniWeb to /web/es/{*remaining_path}
[PID:21286:001 2014.01.14 11:00:25.875 INFO  MiniWeb       ] Starting MiniWeb for /web ==> /opt/eventstore/current/clusternode-web
[PID:21286:001 2014.01.14 11:00:25.877 INFO  MiniWeb       ] Starting MiniWeb for /web/es ==> /opt/eventstore/current/es-common-web
[PID:21286:001 2014.01.14 11:00:25.877 TRACE MiniWeb       ] Binding MiniWeb to /web/{*remaining_path}
[PID:21286:001 2014.01.14 11:00:25.877 TRACE MiniWeb       ] Binding MiniWeb to /web/es/{*remaining_path}
[PID:21286:001 2014.01.14 11:00:25.877 INFO  MiniWeb       ] Starting MiniWeb for /web/users ==> /opt/eventstore/current/Users/web
[PID:21286:001 2014.01.14 11:00:25.878 TRACE MiniWeb       ] Binding MiniWeb to /web/users/{*remaining_path}
[PID:21286:001 2014.01.14 11:00:25.878 INFO  MiniWeb       ] Starting MiniWeb for /web/users ==> /opt/eventstore/current/Users/web
[PID:21286:001 2014.01.14 11:00:25.878 TRACE MiniWeb       ] Binding MiniWeb to /web/users/{*remaining_path}
[PID:21286:010 2014.01.14 11:00:25.930 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] SYSTEM INIT...
[PID:21286:010 2014.01.14 11:00:25.980 INFO  TcpServerListener  ] Starting Normal TCP listening on TCP endpoint:
10.80.10.11:13002.
[PID:21286:015 2014.01.14 11:00:26.023 INFO  IndexCommitter    ] TableIndex initialization...
[PID:21286:015 2014.01.14 11:00:26.053 INFO  IndexCommitter    ] ReadIndex building...
[PID:21286:015 2014.01.14 11:00:26.056 DEBUG IndexCommitter    ] ReadIndex rebuilding done: total processed 0 records, time elapsed: 00:00:00.0023630.
[PID:21286:010 2014.01.14 11:00:26.072 TRACE InMemoryBus     ] SLOW BUS MSG [MainBus]: SystemInit - 62ms. Handler: TcpService.
[PID:21286:010 2014.01.14 11:00:26.072 INFO  TcpServerListener  ] Starting Normal TCP listening on TCP endpoint:
10.80.10.11:13001.
[PID:21286:010 2014.01.14 11:00:26.115 INFO  HttpAsyncServer   ] HTTP server is up and listening on [
http://10.80.10.11:13004/]
[PID:21286:010 2014.01.14 11:00:26.117 INFO  HttpAsyncServer   ] HTTP server is up and listening on [
http://10.80.10.11:13003/]
[PID:21286:010 2014.01.14 11:00:26.157 TRACE QueuedHandlerAutoRes] SLOW QUEUE MSG [MainQueue]: SystemInit - 241ms. Q: 0/7.
[PID:21286:010 2014.01.14 11:00:26.157 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] Service 'StorageReader' initialized.
[PID:21286:010 2014.01.14 11:00:26.157 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] Service 'StorageWriter' initialized.
[PID:21286:010 2014.01.14 11:00:26.157 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] Service 'StorageChaser' initialized.
[PID:21286:010 2014.01.14 11:00:26.223 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:26.227 TRACE InMemoryBus     ] SLOW BUS MSG [MainBus]: GotGossipSeedSources - 67ms. Handler: NodeGossipService.
[PID:21286:010 2014.01.14 11:00:26.227 TRACE QueuedHandlerAutoRes] SLOW QUEUE MSG [MainQueue]: GotGossipSeedSources - 67ms. Q: 1/3.
[PID:21286:010 2014.01.14 11:00:26.227 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] SYSTEM START...
[PID:21286:010 2014.01.14 11:00:26.229 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] IS UNKNOWN!!! WHOA!!!
[PID:21286:010 2014.01.14 11:00:26.315 DEBUG ElectionsService   ] ELECTIONS: STARTING ELECTIONS.
[PID:21286:010 2014.01.14 11:00:26.316 DEBUG ElectionsService   ] ELECTIONS: (V=0) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:26.320 DEBUG ElectionsService   ] ELECTIONS: (V=0) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:26.325 TRACE InMemoryBus     ] SLOW BUS MSG [MainBus]: StartElections - 87ms. Handler: ElectionsService.
[PID:21286:010 2014.01.14 11:00:26.325 TRACE QueuedHandlerAutoRes] SLOW QUEUE MSG [MainQueue]: StartElections - 87ms. Q: 0/2.
[PID:21286:006 2014.01.14 11:00:26.532 TRACE InMemoryBus     ] SLOW BUS MSG [Worker #1 Bus]: SendOverHttp - 299ms. Handler: HttpSendService.
[PID:21286:006 2014.01.14 11:00:26.575 TRACE QueuedHandlerThreadP] SLOW QUEUE MSG [Worker #1]: SendOverHttp - 300ms. Q: 0/0.
[PID:21286:010 2014.01.14 11:00:27.065 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:12003] is DEAD (Gossip send failed).
[PID:21286:010 2014.01.14 11:00:27.067 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip send failed to [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:27.075 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:11003] is DEAD (Gossip send failed).
[PID:21286:010 2014.01.14 11:00:27.075 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip send failed to [
10.80.10.11:11003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:27.327 DEBUG ElectionsService   ] ELECTIONS: (V=0) TIMED OUT! (S=ElectingLeader, M=).
[PID:21286:010 2014.01.14 11:00:27.328 DEBUG ElectionsService   ] ELECTIONS: (V=1) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:27.328 DEBUG ElectionsService   ] ELECTIONS: (V=1) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:28.328 DEBUG ElectionsService   ] ELECTIONS: (V=1) TIMED OUT! (S=ElectingLeader, M=).
[PID:21286:010 2014.01.14 11:00:28.328 DEBUG ElectionsService   ] ELECTIONS: (V=2) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:28.328 DEBUG ElectionsService   ] ELECTIONS: (V=2) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:29.330 DEBUG ElectionsService   ] ELECTIONS: (V=2) TIMED OUT! (S=ElectingLeader, M=).
[PID:21286:010 2014.01.14 11:00:29.330 DEBUG ElectionsService   ] ELECTIONS: (V=3) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:29.330 DEBUG ElectionsService   ] ELECTIONS: (V=3) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:29.809 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:30.331 DEBUG ElectionsService   ] ELECTIONS: (V=3) TIMED OUT! (S=ElectingLeader, M=).
[PID:21286:010 2014.01.14 11:00:30.331 DEBUG ElectionsService   ] ELECTIONS: (V=4) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:30.331 DEBUG ElectionsService   ] ELECTIONS: (V=4) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:30.909 DEBUG ElectionsService   ] ELECTIONS: (IV=15) VIEWCHANGEPROOF FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}]. JUMPING TO LEADER STATE.
[PID:21286:010 2014.01.14 11:00:30.909 DEBUG ElectionsService   ] ELECTIONS: (V=15) SHIFT TO PREPARE PHASE.
[PID:21286:010 2014.01.14 11:00:30.911 DEBUG ElectionsService   ] ELECTIONS: (V=15) PREPARE_OK FROM [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=-1,W=0,C=0,E-1@-1:{00000000-0000-0000-0000-000000000000}).
[PID:21286:010 2014.01.14 11:00:30.937 DEBUG ElectionsService   ] ELECTIONS: (V=15) PREPARE_OK FROM [
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}](L=803,W=1115,C=1115,E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}).
[PID:21286:010 2014.01.14 11:00:30.937 DEBUG ElectionsService   ] ELECTIONS: (V=15) SHIFT TO REG_LEADER.
[PID:21286:010 2014.01.14 11:00:30.953 DEBUG ElectionsService   ] ELECTIONS: (V=15) SENDING PROPOSAL CANDIDATE: [
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}](L=803,W=1115,C=1115,E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}), ME: [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=-1,W=0,C=0,E-1@-1:{00000000-0000-0000-0000-000000000000}).
[PID:21286:010 2014.01.14 11:00:30.955 DEBUG ElectionsService   ] ELECTIONS: (V=15) ACCEPT FROM [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}] M=[
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}]).
[PID:21286:010 2014.01.14 11:00:31.915 DEBUG ElectionsService   ] ELECTIONS: (V=15) TIMED OUT! (S=Leader, M=).
[PID:21286:010 2014.01.14 11:00:31.915 DEBUG ElectionsService   ] ELECTIONS: (V=16) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:31.916 DEBUG ElectionsService   ] ELECTIONS: (V=16) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:32.059 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:11003] is DEAD (Gossip send failed).
[PID:21286:010 2014.01.14 11:00:32.059 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip send failed to [
10.80.10.11:11003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:32.917 DEBUG ElectionsService   ] ELECTIONS: (V=16) TIMED OUT! (S=ElectingLeader, M=).
[PID:21286:010 2014.01.14 11:00:32.917 DEBUG ElectionsService   ] ELECTIONS: (V=17) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:32.917 DEBUG ElectionsService   ] ELECTIONS: (V=17) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:33.065 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:12003] is DEAD (Gossip send failed).
[PID:21286:010 2014.01.14 11:00:33.065 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip send failed to [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:33.073 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:11003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:33.245 DEBUG ElectionsService   ] ELECTIONS: (V=16) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21286:010 2014.01.14 11:00:33.245 DEBUG ElectionsService   ] ELECTIONS: (V=16) MAJORITY OF VIEWCHANGE.
[PID:21286:010 2014.01.14 11:00:33.918 DEBUG ElectionsService   ] ELECTIONS: (V=17) TIMED OUT! (S=ElectingLeader, M=).
[PID:21286:010 2014.01.14 11:00:33.918 DEBUG ElectionsService   ] ELECTIONS: (V=18) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:33.919 DEBUG ElectionsService   ] ELECTIONS: (V=18) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:33.923 DEBUG ElectionsService   ] ELECTIONS: (V=18) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21286:010 2014.01.14 11:00:33.923 DEBUG ElectionsService   ] ELECTIONS: (V=18) MAJORITY OF VIEWCHANGE.
[PID:21286:010 2014.01.14 11:00:33.923 DEBUG ElectionsService   ] ELECTIONS: (V=18) SHIFT TO PREPARE PHASE.
[PID:21286:010 2014.01.14 11:00:33.923 DEBUG ElectionsService   ] ELECTIONS: (V=18) PREPARE_OK FROM [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=-1,W=0,C=0,E-1@-1:{00000000-0000-0000-0000-000000000000}).
[PID:21286:010 2014.01.14 11:00:33.927 DEBUG ElectionsService   ] ELECTIONS: (V=18) PREPARE_OK FROM [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1115,C=1115,E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}).
[PID:21286:010 2014.01.14 11:00:33.927 DEBUG ElectionsService   ] ELECTIONS: (V=18) SHIFT TO REG_LEADER.
[PID:21286:010 2014.01.14 11:00:33.928 DEBUG ElectionsService   ] ELECTIONS: (V=18) SENDING PROPOSAL CANDIDATE: [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1115,C=1115,E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}), ME: [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=-1,W=0,C=0,E-1@-1:{00000000-0000-0000-0000-000000000000}).
[PID:21286:010 2014.01.14 11:00:33.928 DEBUG ElectionsService   ] ELECTIONS: (V=18) ACCEPT FROM [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]).
[PID:21286:010 2014.01.14 11:00:33.945 DEBUG ElectionsService   ] ELECTIONS: (V=18) ACCEPT FROM [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]).
[PID:21286:010 2014.01.14 11:00:33.945 INFO  ElectionsService   ] ELECTIONS: (V=18) DONE. ELECTED MASTER = [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1115,C=1115,E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}). ME=[
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=-1,W=0,C=0,E-1@-1:{00000000-0000-0000-0000-000000000000}).
[PID:21286:010 2014.01.14 11:00:33.947 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] PRE-REPLICA STATE, WAITING FOR CHASER TO CATCH UP... MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21286:010 2014.01.14 11:00:34.022 INFO  ReplicaService    ] Subscribing at LogPosition: 0 (0x0) to MASTER [
10.80.10.11:11001, {46577878-07ac-4f88-9a42-8889a62e649e}] as replica with SubscriptionId: {16525da7-0533-4bdc-b46c-24e639a186fc}, ConnectionId: {044e2966-504c-40a9-ba90-7a9ab0547c42}, LocalEndPoint: [], Epochs:
...
.
[PID:21286:029 2014.01.14 11:00:34.100 INFO Â TcpConnectionManager] Connection 'master-normal' ({044e2966-504c-40a9-ba90-7a9ab0547c42}) to [
10.80.10.11:11001] established.
[PID:21286:010 2014.01.14 11:00:34.192 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] IS CATCHING UP!!! BANZAI!!! MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21286:010 2014.01.14 11:00:34.226 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] CLONE ASSIGNMENT RECEIVED FROM [
10.80.10.11:11001,n/a,{46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21286:010 2014.01.14 11:00:34.226 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] IS CLONE!!! SPARTA!!! MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21286:010 2014.01.14 11:00:34.229 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] SLAVE ASSIGNMENT RECEIVED FROM [
10.80.10.11:11001,n/a,{46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21286:010 2014.01.14 11:00:34.229 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] IS SLAVE!!! SPARTA!!! MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21286:007 2014.01.14 11:00:34.255 INFO Â ClusterStorageWriter] === SUBSCRIBED to [
10.80.10.11:11001,{46577878-07ac-4f88-9a42-8889a62e649e}] at 0 (0x0). SubscriptionId: {16525da7-0533-4bdc-b46c-24e639a186fc}.
[PID:21286:015 2014.01.14 11:00:34.336 DEBUG EpochManager     ] === Update Last Epoch E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691} (previous epoch at -1).
[PID:21286:010 2014.01.14 11:00:34.363 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:11003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:015 2014.01.14 11:00:34.371 DEBUG EpochManager     ] === Update Last Epoch E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09} (previous epoch at 0).
[PID:21286:010 2014.01.14 11:00:35.918 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:36.082 DEBUG ElectionsService   ] ELECTIONS: (V=20) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21286:010 2014.01.14 11:00:36.082 DEBUG ElectionsService   ] ELECTIONS: (V=20) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:36.082 DEBUG ElectionsService   ] ELECTIONS: (V=20) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:36.082 DEBUG ElectionsService   ] ELECTIONS: (V=20) MAJORITY OF VIEWCHANGE.
[PID:21286:010 2014.01.14 11:00:37.084 DEBUG ElectionsService   ] ELECTIONS: (V=20) TIMED OUT! (S=ElectingLeader, M=).
[PID:21286:010 2014.01.14 11:00:37.084 DEBUG ElectionsService   ] ELECTIONS: (V=21) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:37.084 DEBUG ElectionsService   ] ELECTIONS: (V=21) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:008 2014.01.14 11:00:37.206 TRACE TcpConnectionManager] Closing connection 'master-normal' [
10.80.10.11:11001, L10.80.10.11:58563, {044e2966-504c-40a9-ba90-7a9ab0547c42}] cleanly. Reason: HEARTBEAT TIMEOUT at msgNum 5
[PID:21286:008 2014.01.14 11:00:37.248 INFO  TcpConnection    ] ES TcpConnection closed [11:00:37.210: N10.80.10.11:11001, L10.80.10.11:58563, {044e2966-504c-40a9-ba90-7a9ab0547c42}]:
Received bytes: 1834, Sent bytes: 613
Send calls: 10, callbacks: 9
Receive calls: 7, callbacks: 6
Close reason: [Success] HEARTBEAT TIMEOUT at msgNum 5
[PID:21286:008 2014.01.14 11:00:37.250 INFO Â TcpConnectionManager] Connection 'master-normal' [
10.80.10.11:11001, {044e2966-504c-40a9-ba90-7a9ab0547c42}] closed: Success.
[PID:21286:010 2014.01.14 11:00:37.253 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:11001] is DEAD (TCP connection lost).
[PID:21286:010 2014.01.14 11:00:37.253 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (TCP connection lost to [
10.80.10.11:11001])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:37.254 DEBUG ClusterVNodeControll] There is NO MASTER or MASTER is DEAD according to GOSSIP. Starting new elections. MASTER: [InstanceId: {46577878-07ac-4f88-9a42-8889a62e649e}, InternalTcp:
10.80.10.11:11001, InternalSecureTcp: , ExternalTcp:
10.80.10.11:11002, ExternalSecureTcp: , InternalHttp:
10.80.10.11:11003, ExternalHttp:
10.80.10.11:11004].
[PID:21286:010 2014.01.14 11:00:37.754 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] PRE-REPLICA STATE, WAITING FOR CHASER TO CATCH UP... MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21286:010 2014.01.14 11:00:37.754 TRACE TcpConnectionManager] Closing connection 'master-normal' [
10.80.10.11:11001, L10.80.10.11:58563, {044e2966-504c-40a9-ba90-7a9ab0547c42}] cleanly. Reason: Reconnecting from old master [
10.80.10.11:11001] to new master: [
10.80.10.11:11001].
[PID:21286:010 2014.01.14 11:00:37.756 DEBUG ClusterVNodeControll] There is NO MASTER or MASTER is DEAD according to GOSSIP. Starting new elections. MASTER: [InstanceId: {46577878-07ac-4f88-9a42-8889a62e649e}, InternalTcp:
10.80.10.11:11001, InternalSecureTcp: , ExternalTcp:
10.80.10.11:11002, ExternalSecureTcp: , InternalHttp:
10.80.10.11:11003, ExternalHttp:
10.80.10.11:11004].
[PID:21286:010 2014.01.14 11:00:37.757 INFO  ReplicaService    ] Subscribing at LogPosition: 1327 (0x52F) to MASTER [
10.80.10.11:11001, {46577878-07ac-4f88-9a42-8889a62e649e}] as replica with SubscriptionId: {5cb33487-749b-4dfe-b6e3-9a0adbe4a384}, ConnectionId: {b44e2f5a-903c-455c-a735-4af151d8f629}, LocalEndPoint: [], Epochs:
E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}
E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}...
.
[PID:21286:010 2014.01.14 11:00:38.081 DEBUG ElectionsService   ] ELECTIONS: (V=21) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21286:010 2014.01.14 11:00:38.081 DEBUG ElectionsService   ] ELECTIONS: (V=21) MAJORITY OF VIEWCHANGE.
[PID:21286:028 2014.01.14 11:00:38.086 INFO Â TcpConnectionManager] Connection 'master-normal' ({b44e2f5a-903c-455c-a735-4af151d8f629}) to [
10.80.10.11:11001] established.
[PID:21286:010 2014.01.14 11:00:38.091 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (TCP connection established to [
10.80.10.11:11001])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:38.091 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:38.095 DEBUG ElectionsService   ] ELECTIONS: (V=21) TIMED OUT! (S=ElectingLeader, M=).
[PID:21286:010 2014.01.14 11:00:38.095 DEBUG ElectionsService   ] ELECTIONS: (V=22) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:38.096 DEBUG ElectionsService   ] ELECTIONS: (V=22) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:38.099 DEBUG ElectionsService   ] ELECTIONS: (V=22) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21286:010 2014.01.14 11:00:38.099 DEBUG ElectionsService   ] ELECTIONS: (V=22) MAJORITY OF VIEWCHANGE.
[PID:21286:010 2014.01.14 11:00:38.253 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] IS CATCHING UP!!! BANZAI!!! MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21286:007 2014.01.14 11:00:38.253 INFO Â ClusterStorageWriter] === SUBSCRIBED to [
10.80.10.11:11001,{46577878-07ac-4f88-9a42-8889a62e649e}] at 1327 (0x52F). SubscriptionId: {5cb33487-749b-4dfe-b6e3-9a0adbe4a384}.
[PID:21286:010 2014.01.14 11:00:38.257 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] CLONE ASSIGNMENT RECEIVED FROM [
10.80.10.11:11001,n/a,{46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21286:010 2014.01.14 11:00:38.257 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] IS CLONE!!! SPARTA!!! MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21286:010 2014.01.14 11:00:38.257 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] SLAVE ASSIGNMENT RECEIVED FROM [
10.80.10.11:11001,n/a,{46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21286:010 2014.01.14 11:00:38.258 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] IS SLAVE!!! SPARTA!!! MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21286:010 2014.01.14 11:00:38.272 DEBUG ElectionsService   ] ELECTIONS: (V=21) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21286:010 2014.01.14 11:00:38.274 DEBUG ElectionsService   ] ELECTIONS: (V=22) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21286:010 2014.01.14 11:00:38.997 DEBUG ElectionsService   ] ELECTIONS: (IV=21) VIEWCHANGEPROOF FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}]. JUMPING TO LEADER STATE.
[PID:21286:010 2014.01.14 11:00:38.997 DEBUG ElectionsService   ] ELECTIONS: (V=21) SHIFT TO PREPARE PHASE.
[PID:21286:010 2014.01.14 11:00:38.998 DEBUG ElectionsService   ] ELECTIONS: (V=21) PREPARE_OK FROM [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=803,W=1327,C=1327,E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}).
[PID:21286:010 2014.01.14 11:00:39.255 DEBUG ElectionsService   ] ELECTIONS: (V=23) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21286:010 2014.01.14 11:00:39.255 DEBUG ElectionsService   ] ELECTIONS: (V=23) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:39.255 DEBUG ElectionsService   ] ELECTIONS: (V=23) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:39.256 DEBUG ElectionsService   ] ELECTIONS: (V=23) MAJORITY OF VIEWCHANGE.
[PID:21286:010 2014.01.14 11:00:40.077 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:12003] is DEAD (Gossip send failed).
[PID:21286:010 2014.01.14 11:00:40.077 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip send failed to [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:40.257 DEBUG ElectionsService   ] ELECTIONS: (V=23) TIMED OUT! (S=ElectingLeader, M=).
[PID:21286:010 2014.01.14 11:00:40.257 DEBUG ElectionsService   ] ELECTIONS: (V=24) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:40.257 DEBUG ElectionsService   ] ELECTIONS: (V=24) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:41.258 DEBUG ElectionsService   ] ELECTIONS: (V=24) TIMED OUT! (S=ElectingLeader, M=).
[PID:21286:010 2014.01.14 11:00:41.258 DEBUG ElectionsService   ] ELECTIONS: (V=25) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:41.258 DEBUG ElectionsService   ] ELECTIONS: (V=25) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:41.929 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:41.932 DEBUG ElectionsService   ] ELECTIONS: (V=24) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21286:010 2014.01.14 11:00:41.932 DEBUG ElectionsService   ] ELECTIONS: (V=24) MAJORITY OF VIEWCHANGE.
[PID:21286:010 2014.01.14 11:00:41.936 DEBUG ElectionsService   ] ELECTIONS: (V=25) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21286:010 2014.01.14 11:00:41.937 DEBUG ElectionsService   ] ELECTIONS: (V=25) PREPARE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21286:010 2014.01.14 11:00:41.937 DEBUG ElectionsService   ] ELECTIONS: (V=25) SHIFT TO REG_NONLEADER.
[PID:21286:010 2014.01.14 11:00:41.968 DEBUG ElectionsService   ] ELECTIONS: (V=25) PROPOSAL FROM [
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1327,C=1327,E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}). ME=[
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=803,W=1327,C=1327,E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}).
[PID:21286:010 2014.01.14 11:00:41.968 DEBUG ElectionsService   ] ELECTIONS: (V=25) ACCEPT FROM [
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]).
[PID:21286:010 2014.01.14 11:00:41.968 DEBUG ElectionsService   ] ELECTIONS: (V=25) ACCEPT FROM [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]).
[PID:21286:010 2014.01.14 11:00:41.968 INFO  ElectionsService   ] ELECTIONS: (V=25) DONE. ELECTED MASTER = [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1327,C=1327,E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}). ME=[
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=803,W=1327,C=1327,E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}).
[PID:21286:010 2014.01.14 11:00:42.110 DEBUG ElectionsService   ] ELECTIONS: (V=25) PREPARE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21286:010 2014.01.14 11:00:42.602 DEBUG ElectionsService   ] ELECTIONS: (V=25) ACCEPT FROM [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]).
[PID:21286:015 2014.01.14 11:00:42.607 DEBUG EpochManager     ] === Update Last Epoch E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843} (previous epoch at 1115).
[PID:21286:010 2014.01.14 11:00:43.104 DEBUG ElectionsService   ] ELECTIONS: (V=26) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21286:010 2014.01.14 11:00:43.104 DEBUG ElectionsService   ] ELECTIONS: (V=26) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:43.105 DEBUG ElectionsService   ] ELECTIONS: (V=26) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:43.105 DEBUG ElectionsService   ] ELECTIONS: (V=26) MAJORITY OF VIEWCHANGE.
[PID:21286:010 2014.01.14 11:00:43.105 TRACE GossipServiceBase  ] Looks like master [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}] is DEAD (Gossip send failed), though we wait for TCP to decide.
[PID:21286:010 2014.01.14 11:00:43.291 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:039 2014.01.14 11:00:43.894 INFO  TcpConnection    ] ES TcpConnection closed [11:00:43.894: N10.80.10.11:11001, L10.80.10.11:58574, {b44e2f5a-903c-455c-a735-4af151d8f629}]:
Received bytes: 752, Sent bytes: 605
Send calls: 9, callbacks: 9
Receive calls: 11, callbacks: 11
Close reason: [Success] Socket closed
[PID:21286:039 2014.01.14 11:00:43.894 INFO Â TcpConnectionManager] Connection 'master-normal' [
10.80.10.11:11001, {b44e2f5a-903c-455c-a735-4af151d8f629}] closed: Success.
[PID:21286:010 2014.01.14 11:00:43.894 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:11001] is DEAD (TCP connection lost).
[PID:21286:010 2014.01.14 11:00:43.895 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (TCP connection lost to [
10.80.10.11:11001])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:43.895 DEBUG ClusterVNodeControll] There is NO MASTER or MASTER is DEAD according to GOSSIP. Starting new elections. MASTER: [InstanceId: {46577878-07ac-4f88-9a42-8889a62e649e}, InternalTcp:
10.80.10.11:11001, InternalSecureTcp: , ExternalTcp:
10.80.10.11:11002, ExternalSecureTcp: , InternalHttp:
10.80.10.11:11003, ExternalHttp:
10.80.10.11:11004].
[PID:21286:010 2014.01.14 11:00:44.106 DEBUG ElectionsService   ] ELECTIONS: (V=26) TIMED OUT! (S=ElectingLeader, M=).
[PID:21286:010 2014.01.14 11:00:44.106 DEBUG ElectionsService   ] ELECTIONS: (V=27) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:44.106 DEBUG ElectionsService   ] ELECTIONS: (V=27) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:44.395 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] PRE-REPLICA STATE, WAITING FOR CHASER TO CATCH UP... MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21286:010 2014.01.14 11:00:44.395 TRACE TcpConnectionManager] Closing connection 'master-normal' [
10.80.10.11:11001, L10.80.10.11:58574, {b44e2f5a-903c-455c-a735-4af151d8f629}] cleanly. Reason: Reconnecting from old master [
10.80.10.11:11001] to new master: [
10.80.10.11:11001].
[PID:21286:010 2014.01.14 11:00:44.396 DEBUG ClusterVNodeControll] There is NO MASTER or MASTER is DEAD according to GOSSIP. Starting new elections. MASTER: [InstanceId: {46577878-07ac-4f88-9a42-8889a62e649e}, InternalTcp:
10.80.10.11:11001, InternalSecureTcp: , ExternalTcp:
10.80.10.11:11002, ExternalSecureTcp: , InternalHttp:
10.80.10.11:11003, ExternalHttp:
10.80.10.11:11004].
[PID:21286:010 2014.01.14 11:00:44.396 INFO  ReplicaService    ] Subscribing at LogPosition: 1542 (0x606) to MASTER [
10.80.10.11:11001, {46577878-07ac-4f88-9a42-8889a62e649e}] as replica with SubscriptionId: {a852f1c1-e057-41ad-ba50-41870d273838}, ConnectionId: {e0cd63ff-3715-45da-ab72-b3d448ea9363}, LocalEndPoint: [], Epochs:
E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}
E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}
E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}...
.
[PID:21286:038 2014.01.14 11:00:44.396 INFO Â TcpConnectionManager] Connection 'master-normal' ({e0cd63ff-3715-45da-ab72-b3d448ea9363}) to [
10.80.10.11:11001] established.
[PID:21286:010 2014.01.14 11:00:44.397 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (TCP connection established to [
10.80.10.11:11001])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:45.107 DEBUG ElectionsService   ] ELECTIONS: (V=27) TIMED OUT! (S=ElectingLeader, M=).
[PID:21286:010 2014.01.14 11:00:45.107 DEBUG ElectionsService   ] ELECTIONS: (V=28) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:45.107 DEBUG ElectionsService   ] ELECTIONS: (V=28) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:45.397 INFO  ReplicaService    ] Subscribing at LogPosition: 1542 (0x606) to MASTER [
10.80.10.11:11001, {46577878-07ac-4f88-9a42-8889a62e649e}] as replica with SubscriptionId: {d9429626-89cd-48a2-afd3-e6f190f92bdd}, ConnectionId: {e0cd63ff-3715-45da-ab72-b3d448ea9363}, LocalEndPoint: [
10.80.10.11:58604], Epochs:
E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}
E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}
E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}...
.
[PID:21286:008 2014.01.14 11:00:46.098 TRACE TcpConnectionManager] Closing connection 'master-normal' [
10.80.10.11:11001, L10.80.10.11:58604, {e0cd63ff-3715-45da-ab72-b3d448ea9363}] cleanly. Reason: HEARTBEAT TIMEOUT at msgNum 0
[PID:21286:008 2014.01.14 11:00:46.098 INFO  TcpConnection    ] ES TcpConnection closed [11:00:46.098: N10.80.10.11:11001, L10.80.10.11:58604, {e0cd63ff-3715-45da-ab72-b3d448ea9363}]:
Received bytes: 0, Sent bytes: 182
Send calls: 3, callbacks: 2
Receive calls: 1, callbacks: 0
Close reason: [Success] HEARTBEAT TIMEOUT at msgNum 0
[PID:21286:008 2014.01.14 11:00:46.098 INFO Â TcpConnectionManager] Connection 'master-normal' [
10.80.10.11:11001, {e0cd63ff-3715-45da-ab72-b3d448ea9363}] closed: Success.
[PID:21286:010 2014.01.14 11:00:46.099 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:11001] is DEAD (TCP connection lost).
[PID:21286:010 2014.01.14 11:00:46.100 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (TCP connection lost to [
10.80.10.11:11001])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:46.100 DEBUG ClusterVNodeControll] There is NO MASTER or MASTER is DEAD according to GOSSIP. Starting new elections. MASTER: [InstanceId: {46577878-07ac-4f88-9a42-8889a62e649e}, InternalTcp:
10.80.10.11:11001, InternalSecureTcp: , ExternalTcp:
10.80.10.11:11002, ExternalSecureTcp: , InternalHttp:
10.80.10.11:11003, ExternalHttp:
10.80.10.11:11004].
[PID:21286:010 2014.01.14 11:00:46.105 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:12003] is DEAD (Gossip send failed).
[PID:21286:010 2014.01.14 11:00:46.105 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip send failed to [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:46.105 DEBUG ClusterVNodeControll] There is NO MASTER or MASTER is DEAD according to GOSSIP. Starting new elections. MASTER: [InstanceId: {46577878-07ac-4f88-9a42-8889a62e649e}, InternalTcp:
10.80.10.11:11001, InternalSecureTcp: , ExternalTcp:
10.80.10.11:11002, ExternalSecureTcp: , InternalHttp:
10.80.10.11:11003, ExternalHttp:
10.80.10.11:11004].
[PID:21286:010 2014.01.14 11:00:46.108 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:11003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:46.108 DEBUG ElectionsService   ] ELECTIONS: (V=28) TIMED OUT! (S=ElectingLeader, M=).
[PID:21286:010 2014.01.14 11:00:46.108 DEBUG ElectionsService   ] ELECTIONS: (V=29) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:46.109 DEBUG ElectionsService   ] ELECTIONS: (V=29) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:46.116 DEBUG ElectionsService   ] ELECTIONS: (V=29) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21286:010 2014.01.14 11:00:46.116 DEBUG ElectionsService   ] ELECTIONS: (V=29) MAJORITY OF VIEWCHANGE.
[PID:21286:010 2014.01.14 11:00:46.122 DEBUG ElectionsService   ] ELECTIONS: (V=29) PREPARE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21286:010 2014.01.14 11:00:46.122 DEBUG ElectionsService   ] ELECTIONS: (V=29) SHIFT TO REG_NONLEADER.
[PID:21286:010 2014.01.14 11:00:46.139 DEBUG ElectionsService   ] ELECTIONS: (V=29) PROPOSAL FROM [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1542,C=1542,E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}). ME=[
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=803,W=1542,C=1542,E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}).
[PID:21286:010 2014.01.14 11:00:46.139 DEBUG ElectionsService   ] ELECTIONS: (V=29) ACCEPT FROM [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]).
[PID:21286:010 2014.01.14 11:00:46.139 DEBUG ElectionsService   ] ELECTIONS: (V=29) ACCEPT FROM [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]).
[PID:21286:010 2014.01.14 11:00:46.139 INFO  ElectionsService   ] ELECTIONS: (V=29) DONE. ELECTED MASTER = [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1542,C=1542,E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}). ME=[
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=803,W=1542,C=1542,E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}).
[PID:21286:010 2014.01.14 11:00:46.398 INFO  ReplicaService    ] Subscribing at LogPosition: 1542 (0x606) to MASTER [
10.80.10.11:11001, {46577878-07ac-4f88-9a42-8889a62e649e}] as replica with SubscriptionId: {c6be4e80-a7bd-465d-b7b3-ae464315e13a}, ConnectionId: {e0cd63ff-3715-45da-ab72-b3d448ea9363}, LocalEndPoint: [
10.80.10.11:58604], Epochs:
E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}
E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}
E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}...
.
[PID:21286:010 2014.01.14 11:00:46.601 TRACE TcpConnectionManager] Closing connection 'master-normal' [
10.80.10.11:11001, L10.80.10.11:58604, {e0cd63ff-3715-45da-ab72-b3d448ea9363}] cleanly. Reason: Reconnecting from old master [
10.80.10.11:11001] to new master: [
10.80.10.11:11001].
[PID:21286:038 2014.01.14 11:00:46.601 INFO Â TcpConnectionManager] Connection 'master-normal' ({114f288f-362d-4212-8fc3-e502cc2c4ca5}) to [
10.80.10.11:11001] established.
[PID:21286:010 2014.01.14 11:00:46.958 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:11003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:47.400 INFO  ReplicaService    ] Subscribing at LogPosition: 1542 (0x606) to MASTER [
10.80.10.11:11001, {46577878-07ac-4f88-9a42-8889a62e649e}] as replica with SubscriptionId: {06602b5f-6aae-498f-9dc6-c268d0c1f6b0}, ConnectionId: {114f288f-362d-4212-8fc3-e502cc2c4ca5}, LocalEndPoint: [
10.80.10.11:58612], Epochs:
E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}
E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}
E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}...
.
[PID:21286:010 2014.01.14 11:00:47.402 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] IS CATCHING UP!!! BANZAI!!! MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21286:007 2014.01.14 11:00:47.402 INFO Â ClusterStorageWriter] === SUBSCRIBED to [
10.80.10.11:11001,{46577878-07ac-4f88-9a42-8889a62e649e}] at 1542 (0x606). SubscriptionId: {06602b5f-6aae-498f-9dc6-c268d0c1f6b0}.
[PID:21286:010 2014.01.14 11:00:47.404 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] CLONE ASSIGNMENT RECEIVED FROM [
10.80.10.11:11001,n/a,{46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21286:010 2014.01.14 11:00:47.404 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] IS CLONE!!! SPARTA!!! MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21286:015 2014.01.14 11:00:47.408 DEBUG EpochManager     ] === Update Last Epoch E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc} (previous epoch at 1327).
[PID:21286:010 2014.01.14 11:00:47.931 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:47.936 DEBUG ElectionsService   ] ELECTIONS: (V=30) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21286:010 2014.01.14 11:00:47.936 DEBUG ElectionsService   ] ELECTIONS: (V=30) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:47.936 DEBUG ElectionsService   ] ELECTIONS: (V=30) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:47.936 DEBUG ElectionsService   ] ELECTIONS: (V=30) MAJORITY OF VIEWCHANGE.
[PID:21286:010 2014.01.14 11:00:47.937 DEBUG ElectionsService   ] ELECTIONS: (V=30) SHIFT TO PREPARE PHASE.
[PID:21286:010 2014.01.14 11:00:47.937 DEBUG ElectionsService   ] ELECTIONS: (V=30) PREPARE_OK FROM [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=803,W=1757,C=1757,E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}).
[PID:21286:010 2014.01.14 11:00:47.938 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:48.937 DEBUG ElectionsService   ] ELECTIONS: (V=30) TIMED OUT! (S=ElectingLeader, M=).
[PID:21286:010 2014.01.14 11:00:48.937 DEBUG ElectionsService   ] ELECTIONS: (V=31) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:48.938 DEBUG ElectionsService   ] ELECTIONS: (V=31) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:49.611 TRACE GossipServiceBase  ] Looks like master [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}] is DEAD (Gossip send failed), though we wait for TCP to decide.
[PID:21286:010 2014.01.14 11:00:49.939 DEBUG ElectionsService   ] ELECTIONS: (V=31) TIMED OUT! (S=ElectingLeader, M=).
[PID:21286:010 2014.01.14 11:00:49.939 DEBUG ElectionsService   ] ELECTIONS: (V=32) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:49.939 DEBUG ElectionsService   ] ELECTIONS: (V=32) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:50.111 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] SLAVE ASSIGNMENT RECEIVED FROM [
10.80.10.11:11001,n/a,{46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21286:010 2014.01.14 11:00:50.111 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] IS SLAVE!!! SPARTA!!! MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21286:010 2014.01.14 11:00:50.112 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:50.112 DEBUG ElectionsService   ] ELECTIONS: (V=32) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21286:010 2014.01.14 11:00:50.112 DEBUG ElectionsService   ] ELECTIONS: (V=32) MAJORITY OF VIEWCHANGE.
[PID:21286:010 2014.01.14 11:00:50.112 DEBUG ElectionsService   ] ELECTIONS: (V=31) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21286:010 2014.01.14 11:00:50.942 DEBUG ElectionsService   ] ELECTIONS: (V=32) TIMED OUT! (S=ElectingLeader, M=).
[PID:21286:010 2014.01.14 11:00:50.942 DEBUG ElectionsService   ] ELECTIONS: (V=33) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:50.942 DEBUG ElectionsService   ] ELECTIONS: (V=33) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:51.942 DEBUG ElectionsService   ] ELECTIONS: (V=33) TIMED OUT! (S=ElectingLeader, M=).
[PID:21286:010 2014.01.14 11:00:51.942 DEBUG ElectionsService   ] ELECTIONS: (V=34) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:51.942 DEBUG ElectionsService   ] ELECTIONS: (V=34) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:52.114 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:12003] is DEAD (Gossip send failed).
[PID:21286:010 2014.01.14 11:00:52.114 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip send failed to [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:52.616 DEBUG ElectionsService   ] ELECTIONS: (V=34) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21286:010 2014.01.14 11:00:52.616 DEBUG ElectionsService   ] ELECTIONS: (V=34) MAJORITY OF VIEWCHANGE.
[PID:21286:010 2014.01.14 11:00:52.616 DEBUG ElectionsService   ] ELECTIONS: (V=34) SHIFT TO PREPARE PHASE.
[PID:21286:010 2014.01.14 11:00:52.617 DEBUG ElectionsService   ] ELECTIONS: (V=34) PREPARE_OK FROM [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=803,W=1757,C=1757,E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}).
[PID:21286:010 2014.01.14 11:00:52.943 DEBUG ElectionsService   ] ELECTIONS: (V=34) TIMED OUT! (S=ElectingLeader, M=).
[PID:21286:010 2014.01.14 11:00:52.943 DEBUG ElectionsService   ] ELECTIONS: (V=35) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:52.943 DEBUG ElectionsService   ] ELECTIONS: (V=35) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:53.329 DEBUG ElectionsService   ] ELECTIONS: (V=35) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21286:010 2014.01.14 11:00:53.329 DEBUG ElectionsService   ] ELECTIONS: (V=35) MAJORITY OF VIEWCHANGE.
[PID:21286:010 2014.01.14 11:00:53.338 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:53.338 DEBUG ElectionsService   ] ELECTIONS: (V=36) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21286:010 2014.01.14 11:00:53.338 DEBUG ElectionsService   ] ELECTIONS: (V=36) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:53.339 DEBUG ElectionsService   ] ELECTIONS: (V=36) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:53.339 DEBUG ElectionsService   ] ELECTIONS: (V=36) MAJORITY OF VIEWCHANGE.
[PID:21286:010 2014.01.14 11:00:53.339 DEBUG ElectionsService   ] ELECTIONS: (V=36) SHIFT TO PREPARE PHASE.
[PID:21286:010 2014.01.14 11:00:53.339 DEBUG ElectionsService   ] ELECTIONS: (V=36) PREPARE_OK FROM [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=803,W=1757,C=1757,E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}).
[PID:21286:010 2014.01.14 11:00:53.830 TRACE GossipServiceBase  ] Looks like master [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}] is DEAD (Gossip send failed), though we wait for TCP to decide.
[PID:21286:010 2014.01.14 11:00:54.340 DEBUG ElectionsService   ] ELECTIONS: (V=36) TIMED OUT! (S=ElectingLeader, M=).
[PID:21286:010 2014.01.14 11:00:54.340 DEBUG ElectionsService   ] ELECTIONS: (V=37) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:54.340 DEBUG ElectionsService   ] ELECTIONS: (V=37) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:55.341 DEBUG ElectionsService   ] ELECTIONS: (V=37) TIMED OUT! (S=ElectingLeader, M=).
[PID:21286:010 2014.01.14 11:00:55.342 DEBUG ElectionsService   ] ELECTIONS: (V=38) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:55.342 DEBUG ElectionsService   ] ELECTIONS: (V=38) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:008 2014.01.14 11:00:56.212 TRACE TcpConnectionManager] Closing connection 'master-normal' [
10.80.10.11:11001, L10.80.10.11:58612, {114f288f-362d-4212-8fc3-e502cc2c4ca5}] cleanly. Reason: HEARTBEAT TIMEOUT at msgNum 12
[PID:21286:008 2014.01.14 11:00:56.212 INFO  TcpConnection    ] ES TcpConnection closed [11:00:56.212: N10.80.10.11:11001, L10.80.10.11:58612, {114f288f-362d-4212-8fc3-e502cc2c4ca5}]:
Received bytes: 796, Sent bytes: 696
Send calls: 12, callbacks: 12
Receive calls: 13, callbacks: 12
Close reason: [Success] HEARTBEAT TIMEOUT at msgNum 12
[PID:21286:008 2014.01.14 11:00:56.213 INFO Â TcpConnectionManager] Connection 'master-normal' [
10.80.10.11:11001, {114f288f-362d-4212-8fc3-e502cc2c4ca5}] closed: Success.
[PID:21286:010 2014.01.14 11:00:56.213 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:11001] is DEAD (TCP connection lost).
[PID:21286:010 2014.01.14 11:00:56.214 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (TCP connection lost to [
10.80.10.11:11001])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:56.214 DEBUG ClusterVNodeControll] There is NO MASTER or MASTER is DEAD according to GOSSIP. Starting new elections. MASTER: [InstanceId: {46577878-07ac-4f88-9a42-8889a62e649e}, InternalTcp:
10.80.10.11:11001, InternalSecureTcp: , ExternalTcp:
10.80.10.11:11002, ExternalSecureTcp: , InternalHttp:
10.80.10.11:11003, ExternalHttp:
10.80.10.11:11004].
[PID:21286:010 2014.01.14 11:00:56.343 DEBUG ElectionsService   ] ELECTIONS: (V=38) TIMED OUT! (S=ElectingLeader, M=).
[PID:21286:010 2014.01.14 11:00:56.343 DEBUG ElectionsService   ] ELECTIONS: (V=39) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:56.343 DEBUG ElectionsService   ] ELECTIONS: (V=39) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:56.715 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] PRE-REPLICA STATE, WAITING FOR CHASER TO CATCH UP... MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21286:010 2014.01.14 11:00:56.715 TRACE TcpConnectionManager] Closing connection 'master-normal' [
10.80.10.11:11001, L10.80.10.11:58612, {114f288f-362d-4212-8fc3-e502cc2c4ca5}] cleanly. Reason: Reconnecting from old master [
10.80.10.11:11001] to new master: [
10.80.10.11:11001].
[PID:21286:010 2014.01.14 11:00:56.716 DEBUG ClusterVNodeControll] There is NO MASTER or MASTER is DEAD according to GOSSIP. Starting new elections. MASTER: [InstanceId: {46577878-07ac-4f88-9a42-8889a62e649e}, InternalTcp:
10.80.10.11:11001, InternalSecureTcp: , ExternalTcp:
10.80.10.11:11002, ExternalSecureTcp: , InternalHttp:
10.80.10.11:11003, ExternalHttp:
10.80.10.11:11004].
[PID:21286:010 2014.01.14 11:00:56.717 INFO  ReplicaService    ] Subscribing at LogPosition: 1757 (0x6DD) to MASTER [
10.80.10.11:11001, {46577878-07ac-4f88-9a42-8889a62e649e}] as replica with SubscriptionId: {c740f553-910c-4c06-af77-067a6c6861c9}, ConnectionId: {0db78248-b1b3-4ecb-85ab-031d7295611f}, LocalEndPoint: [], Epochs:
E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}
E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}
E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}
E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}...
.
[PID:21286:010 2014.01.14 11:00:57.128 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:11003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:056 2014.01.14 11:00:57.133 INFO Â TcpConnectionManager] Connection 'master-normal' ({0db78248-b1b3-4ecb-85ab-031d7295611f}) to [
10.80.10.11:11001] established.
[PID:21286:010 2014.01.14 11:00:57.135 DEBUG ElectionsService   ] ELECTIONS: (V=38) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21286:010 2014.01.14 11:00:57.135 DEBUG ElectionsService   ] ELECTIONS: (V=38) MAJORITY OF VIEWCHANGE.
[PID:21286:010 2014.01.14 11:00:57.138 DEBUG ElectionsService   ] ELECTIONS: (V=40) VIEWCHANGE FROM [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21286:010 2014.01.14 11:00:57.138 DEBUG ElectionsService   ] ELECTIONS: (V=40) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:57.138 DEBUG ElectionsService   ] ELECTIONS: (V=40) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:57.139 DEBUG ElectionsService   ] ELECTIONS: (V=40) MAJORITY OF VIEWCHANGE.
[PID:21286:010 2014.01.14 11:00:57.139 DEBUG ElectionsService   ] ELECTIONS: (V=40) SHIFT TO PREPARE PHASE.
[PID:21286:010 2014.01.14 11:00:57.139 DEBUG ElectionsService   ] ELECTIONS: (V=40) PREPARE_OK FROM [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=803,W=1757,C=1757,E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}).
[PID:21286:007 2014.01.14 11:00:57.139 INFO Â ClusterStorageWriter] === SUBSCRIBED to [
10.80.10.11:11001,{46577878-07ac-4f88-9a42-8889a62e649e}] at 1757 (0x6DD). SubscriptionId: {c740f553-910c-4c06-af77-067a6c6861c9}.
[PID:21286:010 2014.01.14 11:00:57.140 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] IS CATCHING UP!!! BANZAI!!! MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21286:010 2014.01.14 11:00:57.140 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] CLONE ASSIGNMENT RECEIVED FROM [
10.80.10.11:11001,n/a,{46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21286:010 2014.01.14 11:00:57.140 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] IS CLONE!!! SPARTA!!! MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21286:010 2014.01.14 11:00:57.141 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] SLAVE ASSIGNMENT RECEIVED FROM [
10.80.10.11:11001,n/a,{46577878-07ac-4f88-9a42-8889a62e649e}].
[PID:21286:010 2014.01.14 11:00:57.141 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] IS SLAVE!!! SPARTA!!! MASTER IS [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]
[PID:21286:010 2014.01.14 11:00:57.348 DEBUG ElectionsService   ] ELECTIONS: (V=40) PREPARE_OK FROM [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1757,C=1757,E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}).
[PID:21286:010 2014.01.14 11:00:57.348 DEBUG ElectionsService   ] ELECTIONS: (V=40) SHIFT TO REG_LEADER.
[PID:21286:010 2014.01.14 11:00:57.349 DEBUG ElectionsService   ] ELECTIONS: (V=40) SENDING PROPOSAL CANDIDATE: [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1757,C=1757,E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}), ME: [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=803,W=1757,C=1757,E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}).
[PID:21286:010 2014.01.14 11:00:57.349 DEBUG ElectionsService   ] ELECTIONS: (V=40) ACCEPT FROM [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]).
[PID:21286:010 2014.01.14 11:00:57.354 DEBUG ElectionsService   ] ELECTIONS: (V=40) ACCEPT FROM [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}] M=[
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}]).
[PID:21286:010 2014.01.14 11:00:57.354 INFO  ElectionsService   ] ELECTIONS: (V=40) DONE. ELECTED MASTER = [
10.80.10.11:11003,{46577878-07ac-4f88-9a42-8889a62e649e}](L=803,W=1757,C=1757,E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}). ME=[
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=803,W=1757,C=1757,E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}).
[PID:21286:015 2014.01.14 11:00:57.358 DEBUG EpochManager     ] === Update Last Epoch E4@1757:{8668e607-7c93-4b0c-b7a6-3102ae249983} (previous epoch at 1542).
[PID:21286:010 2014.01.14 11:00:57.957 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:57.963 DEBUG ElectionsService   ] ELECTIONS: (V=41) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21286:010 2014.01.14 11:00:57.963 DEBUG ElectionsService   ] ELECTIONS: (V=41) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:57.963 DEBUG ElectionsService   ] ELECTIONS: (V=41) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:57.963 DEBUG ElectionsService   ] ELECTIONS: (V=41) MAJORITY OF VIEWCHANGE.
[PID:21286:010 2014.01.14 11:00:58.737 TRACE GossipServiceBase  ] Looks like master [
10.80.10.11:11003, {46577878-07ac-4f88-9a42-8889a62e649e}] is DEAD (Gossip send failed), though we wait for TCP to decide.
[PID:21286:056 2014.01.14 11:00:58.739 INFO  TcpConnection    ] ES TcpConnection closed [11:00:58.739: N10.80.10.11:11001, L10.80.10.11:58645, {0db78248-b1b3-4ecb-85ab-031d7295611f}]:
Received bytes: 664, Sent bytes: 567
Send calls: 4, callbacks: 4
Receive calls: 7, callbacks: 7
Close reason: [Success] Socket closed
[PID:21286:056 2014.01.14 11:00:58.739 INFO Â TcpConnectionManager] Connection 'master-normal' [
10.80.10.11:11001, {0db78248-b1b3-4ecb-85ab-031d7295611f}] closed: Success.
[PID:21286:010 2014.01.14 11:00:58.739 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:11001] is DEAD (TCP connection lost).
[PID:21286:010 2014.01.14 11:00:58.740 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (TCP connection lost to [
10.80.10.11:11001])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:010 2014.01.14 11:00:58.740 DEBUG ClusterVNodeControll] There is NO MASTER or MASTER is DEAD according to GOSSIP. Starting new elections. MASTER: [InstanceId: {46577878-07ac-4f88-9a42-8889a62e649e}, InternalTcp:
10.80.10.11:11001, InternalSecureTcp: , ExternalTcp:
10.80.10.11:11002, ExternalSecureTcp: , InternalHttp:
10.80.10.11:11003, ExternalHttp:
10.80.10.11:11004].
[PID:21286:010 2014.01.14 11:00:58.964 DEBUG ElectionsService   ] ELECTIONS: (V=41) TIMED OUT! (S=ElectingLeader, M=).
[PID:21286:010 2014.01.14 11:00:58.964 DEBUG ElectionsService   ] ELECTIONS: (V=42) SHIFT TO LEADER ELECTION.
[PID:21286:010 2014.01.14 11:00:58.964 DEBUG ElectionsService   ] ELECTIONS: (V=42) VIEWCHANGE FROM [
10.80.10.11:13003, {40cf708a-9a28-4ea4-941b-20a053f34a89}].
[PID:21286:010 2014.01.14 11:00:58.965 DEBUG ElectionsService   ] ELECTIONS: (V=42) VIEWCHANGE FROM [
10.80.10.11:12003, {382eac31-36d3-43ac-a3d6-74f363b8fb15}].
[PID:21286:010 2014.01.14 11:00:58.965 DEBUG ElectionsService   ] ELECTIONS: (V=42) MAJORITY OF VIEWCHANGE.
[PID:21286:010 2014.01.14 11:00:58.965 DEBUG ElectionsService   ] ELECTIONS: (V=42) SHIFT TO PREPARE PHASE.
[PID:21286:010 2014.01.14 11:00:58.966 DEBUG ElectionsService   ] ELECTIONS: (V=42) PREPARE_OK FROM [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=803,W=1972,C=1972,E4@1757:{8668e607-7c93-4b0c-b7a6-3102ae249983}).
[PID:21286:010 2014.01.14 11:00:58.970 DEBUG ElectionsService   ] ELECTIONS: (V=42) PREPARE_OK FROM [
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}](L=803,W=1757,C=1757,E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}).
[PID:21286:010 2014.01.14 11:00:58.970 DEBUG ElectionsService   ] ELECTIONS: (V=42) SHIFT TO REG_LEADER.
[PID:21286:010 2014.01.14 11:00:58.971 DEBUG ElectionsService   ] ELECTIONS: (V=42) SENDING PROPOSAL CANDIDATE: [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=803,W=1972,C=1972,E4@1757:{8668e607-7c93-4b0c-b7a6-3102ae249983}), ME: [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=803,W=1972,C=1972,E4@1757:{8668e607-7c93-4b0c-b7a6-3102ae249983}).
[PID:21286:010 2014.01.14 11:00:58.971 DEBUG ElectionsService   ] ELECTIONS: (V=42) ACCEPT FROM [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}] M=[
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}]).
[PID:21286:010 2014.01.14 11:00:58.977 DEBUG ElectionsService   ] ELECTIONS: (V=42) ACCEPT FROM [
10.80.10.11:12003,{382eac31-36d3-43ac-a3d6-74f363b8fb15}] M=[
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}]).
[PID:21286:010 2014.01.14 11:00:58.977 INFO  ElectionsService   ] ELECTIONS: (V=42) DONE. ELECTED MASTER = [
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=803,W=1972,C=1972,E4@1757:{8668e607-7c93-4b0c-b7a6-3102ae249983}). ME=[
10.80.10.11:13003,{40cf708a-9a28-4ea4-941b-20a053f34a89}](L=803,W=1972,C=1972,E4@1757:{8668e607-7c93-4b0c-b7a6-3102ae249983}).
[PID:21286:010 2014.01.14 11:00:58.978 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] PRE-MASTER STATE, WAITING FOR CHASER TO CATCH UP...
[PID:21286:010 2014.01.14 11:00:58.979 TRACE TcpConnectionManager] Closing connection 'master-normal' [
10.80.10.11:11001, L10.80.10.11:58645, {0db78248-b1b3-4ecb-85ab-031d7295611f}] cleanly. Reason: Node state changed to PreMaster. Closing replication connection.
[PID:21286:010 2014.01.14 11:00:58.985 INFO Â ClusterVNodeControll] ========== [
10.80.10.11:13003] IS MASTER!!! SPARTA!!!
[PID:21286:007 2014.01.14 11:00:58.992 DEBUG EpochManager     ] === Writing E5@1972:{98953efe-7a6e-4601-98b6-de6af46649b3} (previous epoch at 1757).
[PID:21286:007 2014.01.14 11:00:58.999 DEBUG EpochManager     ] === Update Last Epoch E5@1972:{98953efe-7a6e-4601-98b6-de6af46649b3} (previous epoch at 1757).
[PID:21286:057 2014.01.14 11:00:59.038 INFO  TcpService      ] Internal TCP connection accepted: [Normal,
10.80.10.11:26102, L10.80.10.11:13001, {e6a78080-b272-4511-a71c-a80a9c4a539a}].
[PID:21286:010 2014.01.14 11:00:59.113 INFO Â MasterReplicationSer] SUBSCRIBE REQUEST from [
10.80.10.11:12001,C:{e6a78080-b272-4511-a71c-a80a9c4a539a},S:{a138758e-f684-4950-9148-4fcd5df2faa8},1757(0x6DD),E3@1542:{6921d027-822a-4be8-8657-40bf15e20bfc}, E2@1327:{efb61c78-0eb4-4c8e-8f50-6f50943ad843}, E1@1115:{dff5204a-2442-4a37-a344-1df54a8bad09}, E0@0:{1959b903-081c-4ce8-9b2e-ad977b6c6691}]...
[PID:21286:010 2014.01.14 11:00:59.118 INFO Â MasterReplicationSer] Subscribed replica [
10.80.10.11:12001,S:a138758e-f684-4950-9148-4fcd5df2faa8] for data send at 1757 (0x6DD).
[PID:21286:010 2014.01.14 11:00:59.126 TRACE InMemoryBus     ] SLOW BUS MSG [MainBus]: ReplicaSubscriptionRequest - 62ms. Handler: MasterReplicationService.
[PID:21286:010 2014.01.14 11:00:59.126 TRACE QueuedHandlerAutoRes] SLOW QUEUE MSG [MainQueue]: ReplicaSubscriptionRequest - 63ms. Q: 0/4.
[PID:21286:011 2014.01.14 11:00:59.179 INFO  ProjectionManager  ] Projection manager is initializing from the empty $projections-$all stream
[PID:21286:011 2014.01.14 11:00:59.180 TRACE InMemoryBus     ] SLOW BUS MSG [manager input bus]: ReadStreamEventsBackwardCompleted - 103ms. Handler: ProjectionManager.
[PID:21286:011 2014.01.14 11:00:59.180 TRACE QueuedHandlerAutoRes] SLOW QUEUE MSG [Projections Master]: ReadStreamEventsBackwardCompleted - 103ms. Q: 0/3.
[PID:21286:010 2014.01.14 11:00:59.301 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (gossip received from [
10.80.10.11:12003])
Old:
New:
--------------------------------------------------------------------------------
[PID:21286:056 2014.01.14 11:00:59.838 INFO  TcpConnection    ] ES TcpConnection closed [11:00:59.838: N10.80.10.11:26102, L10.80.10.11:13001, {e6a78080-b272-4511-a71c-a80a9c4a539a}]:
Received bytes: 425, Sent bytes: 1130
Send calls: 7, callbacks: 7
Receive calls: 4, callbacks: 4
Close reason: [Success] Socket closed
[PID:21286:056 2014.01.14 11:00:59.838 INFO Â TcpConnectionManager] Connection 'internal-normal' [
10.80.10.11:26102, {e6a78080-b272-4511-a71c-a80a9c4a539a}] closed: Success.
[PID:21286:010 2014.01.14 11:00:59.841 TRACE GossipServiceBase  ] Looks like node [
10.80.10.11:12001] is DEAD (TCP connection lost).
[PID:21286:010 2014.01.14 11:00:59.842 TRACE GossipServiceBase  ] CLUSTER HAS CHANGED (TCP connection lost to [
10.80.10.11:12001])
Old:
New:
--------------------------------------------------------------------------------
Please help me to solve this problem.
Thank you.