Ok.
I analysed some logs from time when problem last occurred.
brokensession.txt - logs concerning session which had a problem
leader.txt - logs concerning leader election (i grepped for Leader in
zookeeper.log)
Some observations below
- Network glitch which resulted in problem occurred at about 22:08.
- From what I see since 17:48 node2 was the leader and it did not
change later yesterday.
- Client was connected to node2 since 17:50
- At around 22:09 client tried to connect to every node (1,2,3).
Connections to node1 and node3 were closed
with exception "Exception causing close of session 0x22767e1c9630000
due to java.io.IOException: Read error".
Connection to node2 stood alive.
- All subsequent operations were refused with ZSESSIONMOVED error.
Error visible both on client and on server side.
Some more clarifications concerning questions from different posts:
1. Saying we have huge packet drop I mean we have huge packet drop for
a local network. We are still investigating source of it. From time to
time we observe that machines loose contact with others for few
seconds.
2. We do not use any fancy network tricks. All machines are in single
vlan and use permanently assigned IP addresses.
Let me know if anything more can help.
PS. Should I already create JIRA issue for this or is not concrete enough?
Regards, Łukasz
On Tue, Mar 16, 2010 at 20:39, Patrick Hunt <ph...@apache.org> wrote:
> Yea, that's great. (no complaints on my end, just wasn't sure what you
> meant, wanted to make sure I was clear.).
>
> Can you identify some sort of pattern? We're discussing on our end, but this
> is the first time we've heard of such an issue (outside 3.2.0 bug) and we're
> looking for a direction to hunt... anything you could add would help.
>
> Is it possible for you to upgrade your client/server to 3.2.2 and report the
> next failure, including any server/client logs if they are available? You
> should create a JIRA for this in order to track the details as they emerge.
> (incl attaching the logs, etc...)
>
> Patrick
>
> Łukasz Osipiuk wrote:
>>
>> On Tue, Mar 16, 2010 at 20:05, Patrick Hunt <ph...@apache.org> wrote:
>>>
>>> We'll probably need the ZK server/client logs to hunt this down. Can you
>>> tell if the MOVED happens in some particular scenario, say you are
>>> connected
>>> to a follower and move to a leader, or perhaps you are connected to
>>> server
>>> A, get disconnected and reconnected to server A? .... is there some
>>> pattern
>>> that could help us understand what's causing this?
>>>
>>>> Session gets broken after zookeeper library reconnects to cluster,
>>>> although most of reconnection leave session if working state.
>>>
>>> I'm not sure I follow this ^^^, could you restate it? (I get the first
>>> about
>>> about the session is broken after reconnect, what's the second part
>>> saying?)
>>
>> Sorry for my English.
>>
>> I meant that it only happens from time to time. We get reconnects
>> quite often due to large packet loss in our network, but most of the
>> time they do not break the session.
>>
>> Is it clear now?
>>
>> Regards, Łukasz Osipiuk
>>
>>> Regards,
>>>
>>> Patrick
>>>
>>> Łukasz Osipiuk wrote:
>>>>
>>>> On Tue, Mar 16, 2010 at 19:22, Patrick Hunt <ph...@apache.org> wrote:
>>>>>
>>>>> Łukasz Osipiuk wrote:
>>>>>>
>>>>>> On Tue, Mar 16, 2010 at 17:18, Patrick Hunt <ph...@apache.org> wrote:
>>>>>>>
>>>>>>> Can you verify that you are using 3.2.2 on all servers? You can do
>>>>>>> this
>>>>>>> by
>>>>>>> running the "stat" command against each of your servers and look at
>>>>>>> the
>>>>>>> very
>>>>>>> top of the output (we include the version of zk server there).
>>>>>>> http://bit.ly/dglVld
>>>>>>
>>>>>> Thanks for hint.
>>>>>>
>>>>>> We had 3.2.2 jars installed on all server - I checked it previously
>>>>>> but apparently our script which restarts instance
>>>>>> after installing .deb does not work very well and node2 and node3 were
>>>>>> running version 3.2.1.
>>>>>> Could using 3.2.1 be source of the problem?
>>>>>>
>>>>> I heard this story where customer service for dell asks customers to
>>>>> replug
>>>>> in the mouse because it might be "a dusty connection". Invariably when
>>>>> ppl
>>>>> look at the back of the box they find that the mouse is not actually
>>>>> plugged
>>>>> in. Brilliant ideas from CS perspective. ;-)
>>>>>
>>>>> I think that issue was fixed in 3.2.1, so I don't think that's an issue
>>>>> (version).
>>>>
>>>> Damn :(
>>>>
>>>>>>> Are you using synchronous or async operations in your client?
>>>>>>
>>>>>> We are only using async operations.
>>>>>
>>>>> Ok. good info.
>>>>>
>>>>>>> I see snippets from the server logs, but I don't see anything from
>>>>>>> you
>>>>>>> client logs. It would really help if you could zip up all the logs
>>>>>>> (server
>>>>>>> and client) and provide them.
>>>>>>
>>>>>> We do not really have much logging on application side :(. Failed
>>>>>> operations are logged with error code (ZSESSIONEXPIRED in our case).
>>>>>> We also log session state changes but we noticed only changes between
>>>>>> 1
>>>>>> and 3.
>>>>>> Unfortunately we do not have logs coming directly from zookeeper
>>>>>> library as it logs to stderr/stdout and we do not store any of them at
>>>>>> the moment.
>>>>>>
>>>>> I see, in this case I think that the log messages theyselves are the
>>>>> problem, ie we are warning about this, but it's not a real problem. We
>>>>> warn
>>>>> on things that we don't like but can handle, we error if we
>>>>> don'tlike/can'thandle.
>>>>>
>>>>> MOVED basically means that a client initiated a request on one server,
>>>>> then
>>>>> moved to another server before the request could be processed.
>>>>>
>>>>> In your case you are using async requests, that can actually make this
>>>>> problem show up more (more "in flight" requests vs sync operation).
>>>>>
>>>>> So if you are not seeing MOVED on the client then this is fine. If you
>>>>> see
>>>>> them in the server log it means what I said above.
>>>>>
>>>>> That make sense, or am I missing something?
>>>>
>>>> It seems I was what I wrote was not clear. We are noticing errors on
>>>> client side. Any operation after
>>>> session gets into broken state fails with ZSESSIONMOVE error code (I
>>>> wrote ZSESSIONEXPIRED by mistake in previous post).
>>>> We get ZSESSIONMOVE from callback on rc parameter.
>>>>
>>>> Session gets broken after zookeeper library reconnects to cluster,
>>>> although most of reconnection leave session if working state.
>>>>
>>>> Regards, Łukasz
>>>>
>>>>
>>>>> Patrick
>>>>>
>>>>>
>>>>>
>>>>>> Regards, Łukasz
>>>>>>
>>>>>>> Patrick
>>>>>>>
>>>>>>> Łukasz Osipiuk wrote:
>>>>>>>>
>>>>>>>> not really - it happens occasionally - every few days :(
>>>>>>>> I believe it is somewhat connected with our network environment
>>>>>>>> which
>>>>>>>> suffers from some packet loss which leads to
>>>>>>>> connection timeouts.
>>>>>>>>
>>>>>>>> I can switch on some more logging if you can lead me which
>>>>>>>> categories
>>>>>>>> are worth to enable DEBUG for them.
>>>>>>>>
>>>>>>>> Regards, Łukasz Osipiuk
>>>>>>>>
>>>>>>>> On Tue, Mar 16, 2010 at 16:35, Benjamin Reed <br...@yahoo-inc.com>
>>>>>>>> wrote:
>>>>>>>>>
>>>>>>>>> weird, this does sound like a bug. do you have a reliable way of
>>>>>>>>> reproducing
>>>>>>>>> the problem?
>>>>>>>>>
>>>>>>>>> thanx
>>>>>>>>> ben
>>>>>>>>>
>>>>>>>>> On 03/16/2010 08:27 AM, Łukasz Osipiuk wrote:
>>>>>>>>>>
>>>>>>>>>> nope.
>>>>>>>>>>
>>>>>>>>>> I always pass 0 as clientid.
>>>>>>>>>>
>>>>>>>>>> Łukasz
>>>>>>>>>>
>>>>>>>>>> On Tue, Mar 16, 2010 at 16:20, Benjamin Reed<br...@yahoo-inc.com>
>>>>>>>>>> wrote:
>>>>>>>>>>
>>>>>>>>>>> do you ever use zookeeper_init() with the clientid field set to
>>>>>>>>>>> something
>>>>>>>>>>> other than null?
>>>>>>>>>>>
>>>>>>>>>>> ben
>>>>>>>>>>>
>>>>>>>>>>> On 03/16/2010 07:43 AM, Łukasz Osipiuk wrote:
>>>>>>>>>>>
>>>>>>>>>>>> Hi everyone!
>>>>>>>>>>>>
>>>>>>>>>>>> I am writing to this group because recently we are getting some
>>>>>>>>>>>> strange errors with our production zookeeper setup.
>>>>>>>>>>>>
>>>>>>>>>>>> From time to time we are observing that our client application
>>>>>>>>>>>> (C++
>>>>>>>>>>>> based) disconnects from zookeeper (session state is changed to
>>>>>>>>>>>> 1)
>>>>>>>>>>>> and
>>>>>>>>>>>> reconnects (state changed to 3).
>>>>>>>>>>>> This itself is not a problem - usually application continues to
>>>>>>>>>>>> run
>>>>>>>>>>>> without problems after reconnect.
>>>>>>>>>>>> But from time to time after above happens all subsequent
>>>>>>>>>>>> operations
>>>>>>>>>>>> start to return ZSESSIONMOVED error. To make it work again we
>>>>>>>>>>>> have
>>>>>>>>>>>> to
>>>>>>>>>>>> restart application (which creates new zookeeper session).
>>>>>>>>>>>>
>>>>>>>>>>>> I noticed that in 3.2.0 introduced a bug
>>>>>>>>>>>> http://issues.apache.org/jira/browse/ZOOKEEPER-449 but we are
>>>>>>>>>>>> using
>>>>>>>>>>>> zookeeper v. 3.2.2.
>>>>>>>>>>>> I just noticed that app at compile time used 3.2.0 library but
>>>>>>>>>>>> patches
>>>>>>>>>>>> fixing bug 449 did not touch C client lib so I believe that our
>>>>>>>>>>>> problems are not
>>>>>>>>>>>> related with that.
>>>>>>>>>>>>
>>>>>>>>>>>> In zookeeper logs at moment which initiated the problem with
>>>>>>>>>>>> client
>>>>>>>>>>>> application I have
>>>>>>>>>>>>
>>>>>>>>>>>> node1:
>>>>>>>>>>>> 2010-03-16 14:21:43,510 - INFO
>>>>>>>>>>>> [NIOServerCxn.Factory:2181:nioserverc...@607] - Connected to
>>>>>>>>>>>> /10.1.112.61:37197 lastZxid 42992576502
>>>>>>>>>>>> 2010-03-16 14:21:43,510 - INFO
>>>>>>>>>>>> [NIOServerCxn.Factory:2181:nioserverc...@636] - Renewing session
>>>>>>>>>>>> 0x324dcc1ba580085
>>>>>>>>>>>> 2010-03-16 14:21:49,443 - INFO
>>>>>>>>>>>> [QuorumPeer:/0:0:0:0:0:0:0:0:2181:nioserverc...@992] - Finished
>>>>>>>>>>>> init
>>>>>>>>>>>> of 0x324dcc1ba580085 valid:true
>>>>>>>>>>>> 2010-03-16 14:21:49,443 - WARN
>>>>>>>>>>>> [NIOServerCxn.Factory:2181:nioserverc...@518] - Exception
>>>>>>>>>>>> causing
>>>>>>>>>>>> close of session 0x324dcc1ba580085 due to java.io.IOException:
>>>>>>>>>>>> Read
>>>>>>>>>>>> error
>>>>>>>>>>>> 2010-03-16 14:21:49,444 - INFO
>>>>>>>>>>>> [NIOServerCxn.Factory:2181:nioserverc...@857] - closing
>>>>>>>>>>>> session:0x324dcc1ba580085 NIOServerCnxn:
>>>>>>>>>>>> java.nio.channels.SocketChannel[connected
>>>>>>>>>>>> local=/10.1.112.62:2181
>>>>>>>>>>>> remote=/10.1.112.61:37197]
>>>>>>>>>>>>
>>>>>>>>>>>> node2:
>>>>>>>>>>>> 2010-03-16 14:21:40,580 - WARN
>>>>>>>>>>>> [NIOServerCxn.Factory:2181:nioserverc...@494] - Exception
>>>>>>>>>>>> causing
>>>>>>>>>>>> close of session 0x324dcc1ba580085 due to java.io.IOException:
>>>>>>>>>>>> Read
>>>>>>>>>>>> error
>>>>>>>>>>>> 2010-03-16 14:21:40,581 - INFO
>>>>>>>>>>>> [NIOServerCxn.Factory:2181:nioserverc...@833] - closing
>>>>>>>>>>>> session:0x324dcc1ba580085 NIOServerCnxn:
>>>>>>>>>>>> java.nio.channels.SocketChannel[connected
>>>>>>>>>>>> local=/10.1.112.63:2181
>>>>>>>>>>>> remote=/10.1.112.61:60693]
>>>>>>>>>>>> 2010-03-16 14:21:46,839 - INFO
>>>>>>>>>>>> [NIOServerCxn.Factory:2181:nioserverc...@583] - Connected to
>>>>>>>>>>>> /10.1.112.61:48336 lastZxid 42992576502
>>>>>>>>>>>> 2010-03-16 14:21:46,839 - INFO
>>>>>>>>>>>> [NIOServerCxn.Factory:2181:nioserverc...@612] - Renewing session
>>>>>>>>>>>> 0x324dcc1ba580085
>>>>>>>>>>>> 2010-03-16 14:21:49,439 - INFO
>>>>>>>>>>>> [QuorumPeer:/0:0:0:0:0:0:0:0:2181:nioserverc...@964] - Finished
>>>>>>>>>>>> init
>>>>>>>>>>>> of 0x324dcc1ba580085 valid:true
>>>>>>>>>>>>
>>>>>>>>>>>> node3:
>>>>>>>>>>>> 2010-03-16 02:14:48,961 - WARN
>>>>>>>>>>>> [NIOServerCxn.Factory:2181:nioserverc...@494] - Exception
>>>>>>>>>>>> causing
>>>>>>>>>>>> close of session 0x324dcc1ba580085 due to java.io.IOException:
>>>>>>>>>>>> Read
>>>>>>>>>>>> error
>>>>>>>>>>>> 2010-03-16 02:14:48,962 - INFO
>>>>>>>>>>>> [NIOServerCxn.Factory:2181:nioserverc...@833] - closing
>>>>>>>>>>>> session:0x324dcc1ba580085 NIOServerCnxn:
>>>>>>>>>>>> java.nio.channels.SocketChannel[connected
>>>>>>>>>>>> local=/10.1.112.64:2181
>>>>>>>>>>>> remote=/10.1.112.61:57309]
>>>>>>>>>>>>
>>>>>>>>>>>> and then lots of entries like this
>>>>>>>>>>>> 2010-03-16 02:14:54,696 - WARN
>>>>>>>>>>>> [ProcessThread:-1:preprequestproces...@402] - Got exception when
>>>>>>>>>>>> processing sessionid:0x324dcc1ba580085 type:create
>>>>>>>>>>>> cxid:0x4b9e9e49
>>>>>>>>>>>> zxid:0xfffffffffffffffe txntype:unknown
>>>>>>>>>>>> /locks/9871253/lock-8589943989-
>>>>>>>>>>>> org.apache.zookeeper.KeeperException$SessionMovedException:
>>>>>>>>>>>> KeeperErrorCode = Session moved
>>>>>>>>>>>> at
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> org.apache.zookeeper.server.SessionTrackerImpl.checkSession(SessionTrackerImpl.java:231)
>>>>>>>>>>>> at
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> org.apache.zookeeper.server.PrepRequestProcessor.pRequest(PrepRequestProcessor.java:211)
>>>>>>>>>>>> at
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> org.apache.zookeeper.server.PrepRequestProcessor.run(PrepRequestProcessor.java:114)
>>>>>>>>>>>> 2010-03-16 14:22:06,428 - WARN
>>>>>>>>>>>> [ProcessThread:-1:preprequestproces...@402] - Got exception when
>>>>>>>>>>>> processing sessionid:0x324dcc1ba580085 type:create
>>>>>>>>>>>> cxid:0x4b9f6603
>>>>>>>>>>>> zxid:0xfffffffffffffffe txntype:unknown
>>>>>>>>>>>> /locks/1665960/lock-8589961006-
>>>>>>>>>>>> org.apache.zookeeper.KeeperException$SessionMovedException:
>>>>>>>>>>>> KeeperErrorCode = Session moved
>>>>>>>>>>>> at
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> org.apache.zookeeper.server.SessionTrackerImpl.checkSession(SessionTrackerImpl.java:231)
>>>>>>>>>>>> at
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> org.apache.zookeeper.server.PrepRequestProcessor.pRequest(PrepRequestProcessor.java:211)
>>>>>>>>>>>> at
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> org.apache.zookeeper.server.PrepRequestProcessor.run(PrepRequestProcessor.java:114)
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> To workaround disconnections I am going to increase session
>>>>>>>>>>>> timeout
>>>>>>>>>>>> from 5 to 15 seconds but event if it helps at all it is just a
>>>>>>>>>>>> workaround.
>>>>>>>>>>>>
>>>>>>>>>>>> Do you have an idea where is the source of my problem.
>>>>>>>>>>>>
>>>>>>>>>>>> Regards, Łukasz Osipiuk
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>
>>>>
>>>>
>>
>>
>>
>
--
--
Łukasz Osipiuk
mailto:luk...@osipiuk.net
node1:
egrep '22767e1c9630000|10.1.112.60' zookeeper.log.2010-03-16
2010-03-16 22:08:56,714 - INFO [NIOServerCxn.Factory:2181:nioserverc...@607] -
Connected to /10.1.112.60:43791 lastZxid 51539665953
2010-03-16 22:08:56,715 - INFO [NIOServerCxn.Factory:2181:nioserverc...@636] -
Renewing session 0x22767e1c9630000
2010-03-16 22:09:00,164 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:nioserverc...@992] - Finished init of
0x22767e1c9630000 valid:true
2010-03-16 22:09:00,164 - WARN [NIOServerCxn.Factory:2181:nioserverc...@518] -
Exception causing close of session 0x22767e1c9630000 due to
java.io.IOException: Read error
2010-03-16 22:09:00,166 - INFO [NIOServerCxn.Factory:2181:nioserverc...@857] -
closing session:0x22767e1c9630000 NIOServerCnxn:
java.nio.channels.SocketChannel[connected local=/10.1.112.62:2181
remote=/10.1.112.60:43791]
node2:
egrep '22767e1c9630000|10.1.112.60' zookeeper.log.2010-03-16
2010-03-16 17:50:20,112 - INFO [NIOServerCxn.Factory:2181:nioserverc...@607] -
Connected to /10.1.112.60:56602 lastZxid 42992642482
2010-03-16 17:50:20,119 - INFO [NIOServerCxn.Factory:2181:nioserverc...@857] -
closing session:0x224ea5675b4007e NIOServerCnxn:
java.nio.channels.SocketChannel[connected local=/10.1.112.63:2181 remote=
/10.1.112.60:56602]
2010-03-16 17:50:24,674 - INFO [NIOServerCxn.Factory:2181:nioserverc...@607] -
Connected to /10.1.112.60:56642 lastZxid 0
2010-03-16 17:50:24,674 - INFO [NIOServerCxn.Factory:2181:nioserverc...@639] -
Creating new session 0x22767e1c9630000
2010-03-16 17:50:25,290 - INFO [CommitProcessor:0:nioserverc...@992] -
Finished init of 0x22767e1c9630000 valid:true
2010-03-16 22:08:53,900 - WARN [ProcessThread:-1:preprequestproces...@402] -
Got exception when processing sessionid:0x22767e1c9630000 type:create
cxid:0x4ba04d67 zxid:0xfffffffffffffffe txntype:unknow
n /ggmboxlocks/9650430/lock-4294980145-
2010-03-16 22:08:58,431 - WARN [NIOServerCxn.Factory:2181:nioserverc...@518] -
Exception causing close of session 0x22767e1c9630000 due to
java.io.IOException: Read error
2010-03-16 22:08:58,432 - INFO [NIOServerCxn.Factory:2181:nioserverc...@857] -
closing session:0x22767e1c9630000 NIOServerCnxn:
java.nio.channels.SocketChannel[connected local=/10.1.112.63:2181 remote=
/10.1.112.60:56642]
2010-03-16 22:09:00,156 - INFO [NIOServerCxn.Factory:2181:nioserverc...@607] -
Connected to /10.1.112.60:50057 lastZxid 51539665953
2010-03-16 22:09:00,157 - INFO [NIOServerCxn.Factory:2181:nioserverc...@992] -
Finished init of 0x22767e1c9630000 valid:true
2010-03-16 22:09:00,157 - INFO [NIOServerCxn.Factory:2181:nioserverc...@636] -
Renewing session 0x22767e1c9630000
2010-03-16 22:09:00,182 - WARN [ProcessThread:-1:preprequestproces...@402] -
Got exception when processing sessionid:0x22767e1c9630000 type:delete
cxid:0x4ba04d6d zxid:0xfffffffffffffffe txntype:unknow
n /ggmboxlocks/1268054/lock-4294980146-0000000282
2010-03-16 22:09:01,535 - WARN [ProcessThread:-1:preprequestproces...@402] -
Got exception when processing sessionid:0x22767e1c9630000 type:create
cxid:0x4ba04d6e zxid:0xfffffffffffffffe txntype:unknow
n /ggmboxlocks/16314/lock-4294980147-
2010-03-16 22:09:01,562 - WARN [ProcessThread:-1:preprequestproces...@402] -
Got exception when processing sessionid:0x22767e1c9630000 type:getChildren
cxid:0x4ba04d6f zxid:0xfffffffffffffffe txntype:u
more exception follows.........
node3:
egrep '22767e1c9630000|10.1.112.60' zookeeper.log.2010-03-16
2010-03-16 22:08:52,502 - INFO [NIOServerCxn.Factory:2181:nioserverc...@607] -
Connected to /10.1.112.60:33716 lastZxid 51539665953
2010-03-16 22:08:52,502 - INFO [NIOServerCxn.Factory:2181:nioserverc...@636] -
Renewing session 0x22767e1c9630000
2010-03-16 22:08:53,379 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:nioserverc...@992] - Finished init of
0x22767e1c9630000 valid:true
2010-03-16 22:08:56,713 - WARN [NIOServerCxn.Factory:2181:nioserverc...@518] -
Exception causing close of session 0x22767e1c9630000 due to
java.io.IOException: Read error
2010-03-16 22:08:56,715 - INFO [NIOServerCxn.Factory:2181:nioserverc...@857] -
closing session:0x22767e1c9630000 NIOServerCnxn:
java.nio.channels.SocketChannel[connected local=/10.1.112.64:2181
remote=/10.1.112.60:33716]
client:
Mar 16 22:08:52 ggmail-c1-mbox-1 ggmail_mbox[7976]: DEBUG: ZooKeeper:
ZooKeeper::execWatch() executing watch
Mar 16 22:08:52 ggmail-c1-mbox-1 ggmail_mbox[7976]: INFO: ZooKeeper:
ZooKeeper::watcherFunHandleSessionEvent() state change to 1
Mar 16 22:08:52 ggmail-c1-mbox-1 ggmail_mbox[7976]: ERROR: ZooKeeper:
ZooKeeper::create() path='/ggmboxlocks/1268054/lock-4294980146-'; callback
error='operation timeout'
Mar 16 22:08:52 ggmail-c1-mbox-1 ggmail_mbox[7976]: ERROR: ZooKeeper:
ZooKeeper::create() path='/ggmboxlocks/9650430/lock-4294980145-'; callback
error='operation timeout'
Mar 16 22:08:53 ggmail-c1-mbox-1 ggmail_mbox[7976]: DEBUG: ZooKeeper:
ZooKeeper::execWatch() executing watch
Mar 16 22:08:53 ggmail-c1-mbox-1 ggmail_mbox[7976]: INFO: ZooKeeper:
ZooKeeper::watcherFunHandleSessionEvent() state change to 3
Mar 16 22:08:53 ggmail-c1-mbox-1 ggmail_mbox[7976]: INFO: ZooKeeper:
ZooKeeper::fireAllWatchFunctions() calling all watches
Mar 16 22:08:56 ggmail-c1-mbox-1 ggmail_mbox[7976]: DEBUG: ZooKeeper:
ZooKeeper::execWatch() executing watch
Mar 16 22:08:56 ggmail-c1-mbox-1 ggmail_mbox[7976]: INFO: ZooKeeper:
ZooKeeper::watcherFunHandleSessionEvent() state change to 1
Mar 16 22:08:56 ggmail-c1-mbox-1 ggmail_mbox[7976]: ERROR: ZooKeeper:
ZooKeeper::getChildren() path='/ggmboxlocks/9650430'; callback error='operation
timeout'
Mar 16 22:08:56 ggmail-c1-mbox-1 ggmail_mbox[7976]: ERROR: ZooKeeper:
ZooKeeper::getChildren() path='/ggmboxlocks/1268054'; callback error='operation
timeout'
Mar 16 22:08:56 ggmail-c1-mbox-1 ggmail_mbox[7976]: ERROR: Locker:
Locker::lock() not connected to zookeeper
Mar 16 22:08:57 ggmail-c1-mbox-1 ggmail_mbox[7976]: ERROR: Locker:
Locker::lock() not connected to zookeeper
Mar 16 22:08:57 ggmail-c1-mbox-1 ggmail_mbox[7976]: ERROR: Locker:
Locker::lock() not connected to zookeeper
Mar 16 22:09:00 ggmail-c1-mbox-1 ggmail_mbox[7976]: ERROR: ZooKeeper:
ZooKeeper::getChildren() path='/ggmboxlocks/9650430'; callback error='operation
timeout'
Mar 16 22:09:00 ggmail-c1-mbox-1 ggmail_mbox[7976]: DEBUG: ZooKeeper:
ZooKeeper::execWatch() executing watch
Mar 16 22:09:00 ggmail-c1-mbox-1 ggmail_mbox[7976]: INFO: ZooKeeper:
ZooKeeper::watcherFunHandleSessionEvent() state change to 3
Mar 16 22:09:00 ggmail-c1-mbox-1 ggmail_mbox[7976]: INFO: ZooKeeper:
ZooKeeper::fireAllWatchFunctions() calling all watches
Mar 16 22:09:00 ggmail-c1-mbox-1 ggmail_mbox[7976]: ERROR: ZooKeeper:
ZooKeeper::erase() path='/ggmboxlocks/1268054/lock-4294980146-0000000282';
callback error='session moved to another server, so opera
tion is ignored'
Mar 16 22:09:01 ggmail-c1-mbox-1 ggmail_mbox[7976]: ERROR: ZooKeeper:
ZooKeeper::create() path='/ggmboxlocks/16314/lock-4294980147-'; callback
error='session moved to another server, so operation is ign
ored'
Mar 16 22:09:01 ggmail-c1-mbox-1 ggmail_mbox[7976]: ERROR: ZooKeeper:
ZooKeeper::getChildren() path='/ggmboxlocks/16314'; callback error='session
moved to another server, so operation is ignored'
Mar 16 22:09:01 ggmail-c1-mbox-1 ggmail_mbox[7976]: ERROR: ZooKeeper:
ZooKeeper::getChildren() path='/ggmboxlocks/16314'; callback error='session
moved to another server, so operation is ignored'
Mar 16 22:09:04 ggmail-c1-mbox-1 ggmail_mbox[7976]: ERROR: ZooKeeper:
ZooKeeper::create() path='/ggmboxlocks/16428/lock-4294980148-'; callback
error='session moved to another server, so operation is ign
ored'
Mar 16 22:09:04 ggmail-c1-mbox-1 ggmail_mbox[7976]: ERROR: ZooKeeper:
ZooKeeper::getChildren() path='/ggmboxlocks/16428'; callback error='session
moved to another server, so operation is ignored'
Mar 16 22:09:04 ggmail-c1-mbox-1 ggmail_mbox[7976]: ERROR: ZooKeeper:
ZooKeeper::getChildren() path='/ggmboxlocks/16428'; callback error='session
moved to another server, so operation is ignored'
Mar 16 22:09:10 ggmail-c1-mbox-1 ggmail_mbox[7976]: ERROR: ZooKeeper:
ZooKeeper::create() path='/ggmboxlocks/4943819/lock-4294980149-'; callback
error='session moved to another server, so operation is i
gnored'
Mar 16 22:09:10 ggmail-c1-mbox-1 ggmail_mbox[7976]: ERROR: ZooKeeper:
ZooKeeper::getChildren() path='/ggmboxlocks/4943819'; callback error='session
moved to another server, so operation is ignored'
Mar 16 22:09:10 ggmail-c1-mbox-1 ggmail_mbox[7976]: ERROR: ZooKeeper:
ZooKeeper::create() path='/ggmboxlocks/10479580/lock-4294980150-'; callback
error='session moved to another server, so operation is
ignored'
Mar 16 22:09:10 ggmail-c1-mbox-1 ggmail_mbox[7976]: ERROR: ZooKeeper:
ZooKeeper::getChildren() path='/ggmboxlocks/10479580'; callback error='session
moved to another server, so operation is ignored'
Mar 16 22:09:11 ggmail-c1-mbox-1 ggmail_mbox[7976]: ERROR: ZooKeeper:
ZooKeeper::getChildren() path='/ggmboxlocks/4943819'; callback error='session
moved to another server, so operation is ignored'
Mar 16 22:09:11 ggmail-c1-mbox-1 ggmail_mbox[7976]: ERROR: ZooKeeper:
ZooKeeper::getChildren() path='/ggmboxlocks/10479580'; callback error='session
moved to another server, so operation is ignored'
Mar 16 22:09:13 ggmail-c1-mbox-1 ggmail_mbox[7976]: ERROR: ZooKeeper:
ZooKeeper::create() path='/ggmboxlocks/20648971/lock-4294980151-'; callback
error='session moved to another server, so operation is
node1:
2010-03-16 17:47:12,200 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:47:12,205 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:47:52,665 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
at
org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:252)
2010-03-16 17:48:38,590 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@579] - New election:
42992642482
2010-03-16 17:48:38,591 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 2,
42992642482, 5, 1, LOOKING, LOOKING, 2
2010-03-16 17:48:38,591 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@637] - Updating proposal
2010-03-16 17:48:38,591 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:48:38,591 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 1,
42992642482, 5, 1, LOOKING, LOOKING, 1
2010-03-16 17:48:38,591 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:48:38,591 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 2,
42992642482, 5, 1, LOOKING, LOOKING, 1
2010-03-16 17:48:38,592 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:48:38,798 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@673] - About to leave
instance:2, 42992642482, 1, FOLLOWING
at
org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:156)
2010-03-16 17:48:43,305 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:48:43,311 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:48:43,517 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:48:43,525 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:48:43,935 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:48:44,754 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:48:46,363 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:48:46,379 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
at
org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:218)
2010-03-16 17:49:17,526 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@579] - New election:
42992642482
2010-03-16 17:49:17,526 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 1,
42992642482, 6, 1, LOOKING, LOOKING, 1
2010-03-16 17:49:17,527 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:49:17,631 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@706] - Notification: 2,
42992642482, 5, 1, LOOKING, FOLLOWING, 3
2010-03-16 17:49:17,839 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@612] - Notification time
out: 400
2010-03-16 17:49:17,840 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 1,
42992642482, 6, 1, LOOKING, LOOKING, 1
2010-03-16 17:49:17,841 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:49:18,044 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 2,
42992642482, 5, 1, LOOKING, LOOKING, 2
2010-03-16 17:49:18,044 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@633] - n.epoch <
logicalclock
2010-03-16 17:49:18,044 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 2,
47244640260, 6, 1, LOOKING, LOOKING, 2
2010-03-16 17:49:18,044 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@637] - Updating proposal
2010-03-16 17:49:18,044 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:49:18,045 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 2,
47244640260, 6, 1, LOOKING, LOOKING, 1
2010-03-16 17:49:18,045 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:49:18,527 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@673] - About to leave
instance:2, 47244640260, 1, FOLLOWING
2010-03-16 17:49:57,101 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:49:57,101 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:49:57,101 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:49:57,102 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
at
org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:285)
2010-03-16 17:50:38,295 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@579] - New election:
42992642482
2010-03-16 17:50:38,302 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 1,
42992642482, 1, 1, LOOKING, LOOKING, 1
2010-03-16 17:50:38,305 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:50:38,306 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@706] - Notification: 2,
47244640260, 7, 1, LOOKING, LEADING, 2
2010-03-16 17:50:38,307 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 2,
47244640260, 7, 1, LOOKING, LOOKING, 3
2010-03-16 17:50:38,532 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:50:38,533 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@706] - Notification: 2,
47244640260, 7, 1, LOOKING, FOLLOWING, 3
node2:
2010-03-16 17:47:12,196 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@579] - New election:
42992642151
2010-03-16 17:47:12,212 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 2,
42992642151, 1, 2, LOOKING, LOOKING, 2
2010-03-16 17:47:12,212 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:47:12,213 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@706] - Notification: 3,
38654726926, 4, 2, LOOKING, LEADING, 3
2010-03-16 17:47:12,213 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@706] - Notification: 3,
38654726926, 4, 2, LOOKING, LEADING, 3
2010-03-16 17:47:12,215 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@706] - Notification: 3,
38654726926, 4, 2, LOOKING, FOLLOWING, 1
at
org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:252)
2010-03-16 17:47:52,667 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@579] - New election:
42992642179
2010-03-16 17:47:52,668 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 2,
42992642179, 5, 2, LOOKING, LOOKING, 2
2010-03-16 17:47:52,668 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:47:52,669 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@706] - Notification: 3,
38654726926, 4, 2, LOOKING, FOLLOWING, 1
2010-03-16 17:47:52,669 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@706] - Notification: 3,
38654726926, 4, 2, LOOKING, LEADING, 3
at
org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:252)
2010-03-16 17:48:38,545 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@579] - New election:
42992642482
2010-03-16 17:48:38,546 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 2,
42992642482, 5, 2, LOOKING, LOOKING, 2
2010-03-16 17:48:38,546 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:48:38,597 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 2,
42992642482, 5, 2, LOOKING, LOOKING, 1
2010-03-16 17:48:38,597 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:48:38,799 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@673] - About to leave
instance:2, 42992642482, 2, LEADING
2010-03-16 17:48:38,802 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:lea...@54] -
TCP NoDelay set to: true
2010-03-16 17:48:44,201 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:48:44,201 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:48:44,201 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:48:49,466 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:48:49,466 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:48:50,362 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:48:50,363 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:48:52,589 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:48:52,973 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:48:54,003 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:49:17,243 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:lea...@371] -
Shutdown called
java.lang.Exception: shutdown Leader! reason: Waiting for a quorum of
followers, only synced with: 2:
at org.apache.zookeeper.server.quorum.Leader.shutdown(Leader.java:371)
at org.apache.zookeeper.server.quorum.Leader.lead(Leader.java:297)
2010-03-16 17:49:17,598 - INFO [Thread-18:leader$followercnxaccep...@227] -
exception while shutting down acceptor: java.net.SocketException: Socket closed
2010-03-16 17:49:18,045 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@579] - New election:
47244640260
2010-03-16 17:49:18,046 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 2,
47244640260, 6, 2, LOOKING, LOOKING, 2
2010-03-16 17:49:18,046 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:49:18,051 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 1,
42992642482, 6, 2, LOOKING, LOOKING, 1
2010-03-16 17:49:18,051 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:49:18,051 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 1,
42992642482, 6, 2, LOOKING, LOOKING, 1
2010-03-16 17:49:18,051 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:49:18,051 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 2,
47244640260, 6, 2, LOOKING, LOOKING, 1
2010-03-16 17:49:18,052 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:49:18,299 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@673] - About to leave
instance:2, 47244640260, 2, LEADING
2010-03-16 17:49:18,359 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:49:18,359 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:49:55,424 - INFO [QuorumPeer:/0:0:0:0:0:0:0:0:2181:lea...@371] -
Shutdown called
java.lang.Exception: shutdown Leader! reason: Waiting for a quorum of
followers, only synced with: 2:
at org.apache.zookeeper.server.quorum.Leader.shutdown(Leader.java:371)
at org.apache.zookeeper.server.quorum.Leader.lead(Leader.java:297)
2010-03-16 17:49:56,060 - WARN [FollowerHandler-/10.1.112.62:41616:lea...@452]
- Commiting zxid 0xc00000000 from 0.0.0.0/0.0.0.0:2888 not first!
2010-03-16 17:49:56,100 - WARN [FollowerHandler-/10.1.112.62:41616:lea...@454]
- First is 0
2010-03-16 17:49:56,137 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@579] - New election:
47244640260
2010-03-16 17:49:56,138 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 2,
47244640260, 7, 2, LOOKING, LOOKING, 2
2010-03-16 17:49:56,139 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:49:56,098 - INFO [Thread-32:leader$followercnxaccep...@227] -
exception while shutting down acceptor: java.net.SocketException: Socket closed
2010-03-16 17:49:56,285 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 3,
42992642482, 7, 2, LOOKING, LOOKING, 3
2010-03-16 17:49:56,285 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:49:56,286 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 2,
47244640260, 7, 2, LOOKING, LOOKING, 3
2010-03-16 17:49:56,286 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:49:56,487 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@673] - About to leave
instance:2, 47244640260, 2, LEADING
2010-03-16 17:49:56,703 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:50:16,805 - WARN [FollowerHandler-/10.1.112.64:59053:lea...@452]
- Commiting zxid 0xc00000000 from /10.1.112.63:2888 not first!
2010-03-16 17:50:16,805 - WARN [FollowerHandler-/10.1.112.64:59053:lea...@454]
- First is 0
2010-03-16 17:50:38,309 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:50:38,536 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
node3:
2010-03-16 17:47:12,205 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:47:52,666 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:48:43,301 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@579] - New election:
42992642482
2010-03-16 17:48:43,314 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 3,
42992642482, 1, 3, LOOKING, LOOKING, 3
2010-03-16 17:48:43,315 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:48:43,315 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@706] - Notification: 2,
42992642482, 5, 3, LOOKING, FOLLOWING, 1
2010-03-16 17:48:43,518 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@612] - Notification time
out: 400
2010-03-16 17:48:43,529 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 3,
42992642482, 1, 3, LOOKING, LOOKING, 3
2010-03-16 17:48:43,529 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:48:43,529 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@706] - Notification: 2,
42992642482, 5, 3, LOOKING, FOLLOWING, 1
2010-03-16 17:48:43,530 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@706] - Notification: 2,
42992642482, 5, 3, LOOKING, FOLLOWING, 1
2010-03-16 17:48:43,935 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@612] - Notification time
out: 800
2010-03-16 17:48:43,936 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 3,
42992642482, 1, 3, LOOKING, LOOKING, 3
2010-03-16 17:48:43,937 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:48:43,943 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@706] - Notification: 2,
42992642482, 5, 3, LOOKING, FOLLOWING, 1
2010-03-16 17:48:44,752 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@612] - Notification time
out: 1600
2010-03-16 17:48:44,756 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 3,
42992642482, 1, 3, LOOKING, LOOKING, 3
2010-03-16 17:48:44,756 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:48:46,362 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@612] - Notification time
out: 3200
2010-03-16 17:48:46,364 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 3,
42992642482, 1, 3, LOOKING, LOOKING, 3
2010-03-16 17:48:46,364 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:48:46,367 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@706] - Notification: 2,
42992642482, 5, 3, LOOKING, FOLLOWING, 1
2010-03-16 17:48:46,379 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@706] - Notification: 2,
42992642482, 5, 3, LOOKING, FOLLOWING, 1
2010-03-16 17:48:49,463 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@706] - Notification: 2,
42992642482, 5, 3, LOOKING, LEADING, 2
2010-03-16 17:49:17,631 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
at
org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:218)
2010-03-16 17:49:18,319 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@579] - New election:
42992642482
2010-03-16 17:49:18,320 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 2,
47244640260, 6, 3, LOOKING, LOOKING, 2
2010-03-16 17:49:18,320 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@637] - Updating proposal
2010-03-16 17:49:18,320 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:49:18,321 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 2,
47244640260, 6, 3, LOOKING, LOOKING, 1
2010-03-16 17:49:18,321 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:49:18,600 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@673] - About to leave
instance:2, 47244640260, 3, FOLLOWING
at
org.apache.zookeeper.server.quorum.Follower.followLeader(Follower.java:218)
2010-03-16 17:49:56,281 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@579] - New election:
42992642482
2010-03-16 17:49:56,282 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 2,
47244640260, 7, 3, LOOKING, LOOKING, 2
2010-03-16 17:49:56,282 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@637] - Updating proposal
2010-03-16 17:49:56,283 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:49:56,283 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 3,
42992642482, 7, 3, LOOKING, LOOKING, 3
2010-03-16 17:49:56,283 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:49:56,283 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@618] - Notification: 2,
47244640260, 7, 3, LOOKING, LOOKING, 3
2010-03-16 17:49:56,284 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@642] - Adding vote
2010-03-16 17:49:56,489 - INFO
[QuorumPeer:/0:0:0:0:0:0:0:0:2181:fastleaderelect...@673] - About to leave
instance:2, 47244640260, 3, FOLLOWING
2010-03-16 17:50:38,308 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
2010-03-16 17:50:38,534 - INFO [WorkerReceiver
Thread:fastleaderelection$messenger$workerrecei...@254] - Sending new
notification.
