You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@activemq.apache.org by Roman Khmelichek <ro...@gmail.com> on 2014/10/20 21:36:04 UTC
ActiveMQ Master Slave with ZooKeeper Session Expiration
Hi,
We are using ActiveMQ 5.10.0 with the replicated LevelDB store, with leader
election handled by ZooKeeper.
We have encountered an issue where the ZooKeeper session expired on all of
our 3 AMQ instances.
However, no leader election took place to elect a master after a new
session was established, so even though all AMQ nodes were up and running,
none of them were listening for messages on port 61616.
Has anyone else encountered this issue? Is this a bug? I have not attempted
to replicate this yet.
I pasted the relevant logs below. Notably, after 2014-10-18 09:04:47,585,
no leader election took place; we restarted the activemq process
at 2014-10-18 15:13:14,541
Thanks,
-Roman
2014-10-18 09:04:31,904 | WARN | [/activemq/leveldb-stores/00000000084]
[ZooKeeperTreeTracker@51987ed7] [Thread[main-EventThread,5,main]] Error in
treeWatcher (ignored) | org.linkedin.zookeeper.tracker.ZooKeeperTreeTracker
| main-EventThread
org.apache.zookeeper.KeeperException$SessionExpiredException:
KeeperErrorCode = Session expired for /activemq/leveldb-stores/00000000084
at
org.apache.zookeeper.KeeperException.create(KeeperException.java:127)[zookeeper-3.4.5.jar:3.4.5-1392090]
at
org.apache.zookeeper.KeeperException.create(KeeperException.java:51)[zookeeper-3.4.5.jar:3.4.5-1392090]
at
org.apache.zookeeper.ZooKeeper.getData(ZooKeeper.java:1151)[zookeeper-3.4.5.jar:3.4.5-1392090]
at
org.linkedin.zookeeper.client.ZooKeeperImpl.getData(ZooKeeperImpl.java:191)[org.linkedin.zookeeper-impl-1.4.0.jar:]
at
org.linkedin.zookeeper.client.AbstractZooKeeper.getData(AbstractZooKeeper.java:213)[org.linkedin.zookeeper-impl-1.4.0.jar:]
at
org.linkedin.zookeeper.client.AbstractZKClient.getZKByteData(AbstractZKClient.java:213)[org.linkedin.zookeeper-impl-1.4.0.jar:]
at
org.linkedin.zookeeper.tracker.ZKByteArrayDataReader.readData(ZKByteArrayDataReader.java:37)[org.linkedin.zookeeper-impl-1.4.0.jar:]
at
org.linkedin.zookeeper.tracker.ZooKeeperTreeTracker.trackNode(ZooKeeperTreeTracker.java:280)[org.linkedin.zookeeper-impl-1.4.0.jar:]
at
org.linkedin.zookeeper.tracker.ZooKeeperTreeTracker.handleNodeDeleted(ZooKeeperTreeTracker.java:359)[org.linkedin.zookeeper-impl-1.4.0.jar:]
at
org.linkedin.zookeeper.tracker.ZooKeeperTreeTracker.access$500(ZooKeeperTreeTracker.java:50)[org.linkedin.zookeeper-impl-1.4.0.jar:]
at
org.linkedin.zookeeper.tracker.ZooKeeperTreeTracker$TreeWatcher.process(ZooKeeperTreeTracker.java:94)[org.linkedin.zookeeper-impl-1.4.0.jar:]
at
org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)[zookeeper-3.4.5.jar:3.4.5-1392090]
at
org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)[zookeeper-3.4.5.jar:3.4.5-1392090]
2014-10-18 09:04:31,905 | WARN | unprocessed event state: AuthFailed |
org.apache.activemq.leveldb.replicated.groups.ZKClient | main-EventThread
2014-10-18 09:04:31,905 | WARN | Expiration detected: trying to restart...
| org.apache.activemq.leveldb.replicated.groups.ZKClient | main-EventThread
2014-10-18 09:04:31,906 | INFO | Initiating client connection,
connectString=cargo308:2181,cargo309:2181,cargo310:2181 sessionTimeout=2000
watcher=org.apache.activemq.leveldb.replicated.groups.ZKClient@512edb17 |
org.apache.zookeeper.ZooKeeper | main-EventThread
2014-10-18 09:04:31,909 | INFO | EventThread shut down |
org.apache.zookeeper.ClientCnxn | main-EventThread
2014-10-18 09:04:31,911 | WARN | SASL configuration failed:
javax.security.auth.login.LoginException: No JAAS configuration section
named 'Client' was found in specified JAAS configuration file:
'/home/apps/activemq/conf/login.config'. Will continue connection to
Zookeeper server without SASL authentication, if Zookeeper server allows
it. | org.apache.zookeeper.ClientCnxn | main-SendThread(cargo309:2181)
2014-10-18 09:04:31,911 | INFO | Opening socket connection to server
cargo309/10.3.30.59:2181 | org.apache.zookeeper.ClientCnxn |
main-SendThread(cargo309:2181)
2014-10-18 09:04:31,911 | WARN | unprocessed event state: AuthFailed |
org.apache.activemq.leveldb.replicated.groups.ZKClient | main-EventThread
2014-10-18 09:04:31,912 | INFO | Socket connection established to cargo309/
10.3.30.59:2181, initiating session | org.apache.zookeeper.ClientCnxn |
main-SendThread(cargo309:2181)
2014-10-18 09:04:31,927 | INFO | Session establishment complete on server
cargo309/10.3.30.59:2181, sessionid = 0x24893c5d5e6022f, negotiated timeout
= 4000 | org.apache.zookeeper.ClientCnxn | main-SendThread(cargo309:2181)
2014-10-18 09:04:37,283 | INFO | Client session timed out, have not heard
from server in 2668ms for sessionid 0x24893c5d5e6022f, closing socket
connection and attempting reconnect | org.apache.zookeeper.ClientCnxn |
main-SendThread(cargo309:2181)
2014-10-18 09:04:38,124 | WARN | SASL configuration failed:
javax.security.auth.login.LoginException: No JAAS configuration section
named 'Client' was found in specified JAAS configuration file:
'/home/apps/activemq/conf/login.config'. Will continue connection to
Zookeeper server without SASL authentication, if Zookeeper server allows
it. | org.apache.zookeeper.ClientCnxn | main-SendThread(cargo310:2181)
2014-10-18 09:04:38,124 | INFO | Opening socket connection to server
cargo310/10.3.30.60:2181 | org.apache.zookeeper.ClientCnxn |
main-SendThread(cargo310:2181)
2014-10-18 09:04:38,124 | WARN | unprocessed event state: AuthFailed |
org.apache.activemq.leveldb.replicated.groups.ZKClient | main-EventThread
2014-10-18 09:04:38,127 | INFO | Socket connection established to cargo310/
10.3.30.60:2181, initiating session | org.apache.zookeeper.ClientCnxn |
main-SendThread(cargo310:2181)
2014-10-18 09:04:39,462 | INFO | Client session timed out, have not heard
from server in 1335ms for sessionid 0x24893c5d5e6022f, closing socket
connection and attempting reconnect | org.apache.zookeeper.ClientCnxn |
main-SendThread(cargo310:2181)
2014-10-18 09:04:39,775 | WARN | SASL configuration failed:
javax.security.auth.login.LoginException: No JAAS configuration section
named 'Client' was found in specified JAAS configuration file:
'/home/apps/activemq/conf/login.config'. Will continue connection to
Zookeeper server without SASL authentication, if Zookeeper server allows
it. | org.apache.zookeeper.ClientCnxn | main-SendThread(cargo308:2181)
2014-10-18 09:04:39,775 | INFO | Opening socket connection to server
cargo308/10.3.30.58:2181 | org.apache.zookeeper.ClientCnxn |
main-SendThread(cargo308:2181)
2014-10-18 09:04:39,775 | WARN | unprocessed event state: AuthFailed |
org.apache.activemq.leveldb.replicated.groups.ZKClient | main-EventThread
2014-10-18 09:04:39,776 | INFO | Socket connection established to cargo308/
10.3.30.58:2181, initiating session | org.apache.zookeeper.ClientCnxn |
main-SendThread(cargo308:2181)
2014-10-18 09:04:41,111 | INFO | Client session timed out, have not heard
from server in 1335ms for sessionid 0x24893c5d5e6022f, closing socket
connection and attempting reconnect | org.apache.zookeeper.ClientCnxn |
main-SendThread(cargo308:2181)
2014-10-18 09:04:43,070 | WARN | SASL configuration failed:
javax.security.auth.login.LoginException: No JAAS configuration section
named 'Client' was found in specified JAAS configuration file:
'/home/apps/activemq/conf/login.config'. Will continue connection to
Zookeeper server without SASL authentication, if Zookeeper server allows
it. | org.apache.zookeeper.ClientCnxn | main-SendThread(cargo309:2181)
2014-10-18 09:04:43,070 | INFO | Opening socket connection to server
cargo309/10.3.30.59:2181 | org.apache.zookeeper.ClientCnxn |
main-SendThread(cargo309:2181)
2014-10-18 09:04:43,070 | WARN | unprocessed event state: AuthFailed |
org.apache.activemq.leveldb.replicated.groups.ZKClient | main-EventThread
2014-10-18 09:04:44,405 | INFO | Client session timed out, have not heard
from server in 3193ms for sessionid 0x24893c5d5e6022f, closing socket
connection and attempting reconnect | org.apache.zookeeper.ClientCnxn |
main-SendThread(cargo309:2181)
2014-10-18 09:04:44,698 | WARN | SASL configuration failed:
javax.security.auth.login.LoginException: No JAAS configuration section
named 'Client' was found in specified JAAS configuration file:
'/home/apps/activemq/conf/login.config'. Will continue connection to
Zookeeper server without SASL authentication, if Zookeeper server allows
it. | org.apache.zookeeper.ClientCnxn | main-SendThread(cargo310:2181)
2014-10-18 09:04:44,699 | INFO | Opening socket connection to server
cargo310/10.3.30.60:2181 | org.apache.zookeeper.ClientCnxn |
main-SendThread(cargo310:2181)
2014-10-18 09:04:44,699 | WARN | unprocessed event state: AuthFailed |
org.apache.activemq.leveldb.replicated.groups.ZKClient | main-EventThread
2014-10-18 09:04:44,699 | INFO | Socket connection established to cargo310/
10.3.30.60:2181, initiating session | org.apache.zookeeper.ClientCnxn |
main-SendThread(cargo310:2181)
2014-10-18 09:04:44,701 | INFO | Unable to read additional data from
server sessionid 0x24893c5d5e6022f, likely server has closed socket,
closing socket connection and attempting reconnect |
org.apache.zookeeper.ClientCnxn | main-SendThread(cargo310:2181)
2014-10-18 09:04:44,979 | WARN | SASL configuration failed:
javax.security.auth.login.LoginException: No JAAS configuration section
named 'Client' was found in specified JAAS configuration file:
'/home/apps/activemq/conf/login.config'. Will continue connection to
Zookeeper server without SASL authentication, if Zookeeper server allows
it. | org.apache.zookeeper.ClientCnxn | main-SendThread(cargo308:2181)
2014-10-18 09:04:44,979 | INFO | Opening socket connection to server
cargo308/10.3.30.58:2181 | org.apache.zookeeper.ClientCnxn |
main-SendThread(cargo308:2181)
2014-10-18 09:04:44,979 | WARN | unprocessed event state: AuthFailed |
org.apache.activemq.leveldb.replicated.groups.ZKClient | main-EventThread
2014-10-18 09:04:44,980 | INFO | Socket connection established to cargo308/
10.3.30.58:2181, initiating session | org.apache.zookeeper.ClientCnxn |
main-SendThread(cargo308:2181)
2014-10-18 09:04:44,981 | INFO | Unable to read additional data from
server sessionid 0x24893c5d5e6022f, likely server has closed socket,
closing socket connection and attempting reconnect |
org.apache.zookeeper.ClientCnxn | main-SendThread(cargo308:2181)
2014-10-18 09:04:47,076 | WARN | SASL configuration failed:
javax.security.auth.login.LoginException: No JAAS configuration section
named 'Client' was found in specified JAAS configuration file:
'/home/apps/activemq/conf/login.config'. Will continue connection to
Zookeeper server without SASL authentication, if Zookeeper server allows
it. | org.apache.zookeeper.ClientCnxn | main-SendThread(cargo309:2181)
2014-10-18 09:04:47,076 | INFO | Opening socket connection to server
cargo309/10.3.30.59:2181 | org.apache.zookeeper.ClientCnxn |
main-SendThread(cargo309:2181)
2014-10-18 09:04:47,076 | WARN | unprocessed event state: AuthFailed |
org.apache.activemq.leveldb.replicated.groups.ZKClient | main-EventThread
2014-10-18 09:04:47,077 | INFO | Socket connection established to cargo309/
10.3.30.59:2181, initiating session | org.apache.zookeeper.ClientCnxn |
main-SendThread(cargo309:2181)
2014-10-18 09:04:47,079 | INFO | Unable to read additional data from
server sessionid 0x24893c5d5e6022f, likely server has closed socket,
closing socket connection and attempting reconnect |
org.apache.zookeeper.ClientCnxn | main-SendThread(cargo309:2181)
2014-10-18 09:04:47,582 | WARN | SASL configuration failed:
javax.security.auth.login.LoginException: No JAAS configuration section
named 'Client' was found in specified JAAS configuration file:
'/home/apps/activemq/conf/login.config'. Will continue connection to
Zookeeper server without SASL authentication, if Zookeeper server allows
it. | org.apache.zookeeper.ClientCnxn | main-SendThread(cargo310:2181)
2014-10-18 09:04:47,582 | INFO | Opening socket connection to server
cargo310/10.3.30.60:2181 | org.apache.zookeeper.ClientCnxn |
main-SendThread(cargo310:2181)
2014-10-18 09:04:47,582 | WARN | unprocessed event state: AuthFailed |
org.apache.activemq.leveldb.replicated.groups.ZKClient | main-EventThread
2014-10-18 09:04:47,583 | INFO | Socket connection established to cargo310/
10.3.30.60:2181, initiating session | org.apache.zookeeper.ClientCnxn |
main-SendThread(cargo310:2181)
2014-10-18 09:04:47,585 | INFO | Session establishment complete on server
cargo310/10.3.30.60:2181, sessionid = 0x24893c5d5e6022f, negotiated timeout
= 4000 | org.apache.zookeeper.ClientCnxn | main-SendThread(cargo310:2181)
2014-10-18 15:13:14,541 | INFO | Refreshing
org.apache.activemq.xbean.XBeanBrokerFactory$1@476d7e38: startup date [Sat
Oct 18 15:13:14 EDT 2014]; root of context hierarchy |
org.apache.activemq.xbean.XBeanBrokerFactory$1 | main
Re: ActiveMQ Master Slave with ZooKeeper Session Expiration
Posted by khandelwalanuj <kh...@gmail.com>.
Just to be clear:
Zookeeper side : Session Timeout is 2 * tick_time.
"zkSessionTmeout" : ActiveMQ configuration for session timeout
So if I specify both tick_time and zkSessionTimeout different which will be
respected. Is it minimum of both the values ?
Thanks,
Anuj
--
View this message in context: http://activemq.2283324.n4.nabble.com/ActiveMQ-Master-Slave-with-ZooKeeper-Session-Expiration-tp4686562p4688333.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.
Re: ActiveMQ Master Slave with ZooKeeper Session Expiration
Posted by khandelwalanuj <kh...@gmail.com>.
Hi Torsh,
I also saw this issue once. What values did you specify for tickTime and
zkSessionTmeout ?
Thanks,
Anuj
--
View this message in context: http://activemq.2283324.n4.nabble.com/ActiveMQ-Master-Slave-with-ZooKeeper-Session-Expiration-tp4686562p4688318.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.
Re: ActiveMQ Master Slave with ZooKeeper Session Expiration
Posted by James Black <be...@yahoo.co.uk>.
Hi,
I had the same issue with 2 ActiveMq 5.10 nodes and 3 ZooKeeper nodes.
At first everything worked well but after long running stress tests we had
the same situation were the master would step down and no node would become
the new master. This would break our application and we were glad not to be
using this in production.
After this we moved to using RabbitMq and have had no problems with that
solution.
Thanks,
Justin
--
View this message in context: http://activemq.2283324.n4.nabble.com/ActiveMQ-Master-Slave-with-ZooKeeper-Session-Expiration-tp4686562p4687808.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.
Re: ActiveMQ Master Slave with ZooKeeper Session Expiration
Posted by uromahn <ul...@ulrichromahn.net>.
I have experimented with ActiveMQ's replicated LevelDB store for quite some
time now and finally came to the conclusion that it is very "flaky" and
"brittle" at best.
I believe it is not ready for production yet and everybody who considers
using it in a hot production environment should probably think twice (or
trice).
For example, I have a running active/passive cluster with three instances
(one active, two passive) connecting to three Zookeeper nodes. I ran several
tests against this cluster and then left it sitting over night. The next
morning I came back I saw the following exceptions in the log files
*without* any activity!
On the active node:
2014-10-22 22:31:05,027 | WARN | Unexpected session error:
java.io.IOException: Connection reset by peer |
org.apache.activemq.leveldb.replicated.MasterLevelDBStore |
hawtdispatch-DEFAULT-2
2014-10-22 22:31:05,028 | INFO | Slave has disconnected:
d8175d91-6602-4abf-bdfc-2ab07c40997e |
org.apache.activemq.leveldb.replicated.MasterLevelDBStore |
hawtdispatch-DEFAULT-2
On node #2 (passive):
2014-10-22 22:31:04,796 | INFO | Client session timed out, have not heard
from server in 29584ms for sessionid 0x24937f0a2a70001, closing socket
connection and attempting reconnect | org.apache.zookeeper.ClientCnxn |
main-SendThread(uromahn-zk2:2181)
2014-10-22 22:31:05,098 | INFO | Slave stopped |
org.apache.activemq.leveldb.replicated.MasterElector | ActiveMQ
BrokerService[brokergrp1] Task-3
2014-10-22 22:31:05,494 | INFO | Opening socket connection to server
uromahn-zk3/10.XX.YY.ZZ:2181. Will not attempt to authenticate using SASL
(unknown error) | org.apache.zookeeper.ClientCnxn |
main-SendThread(uromahn-zk3:2181)
2014-10-22 22:31:05,524 | INFO | Socket connection established to
uromahn-zk3/10.XX.YY.ZZ:2181, initiating session |
org.apache.zookeeper.ClientCnxn | main-SendThread(uromahn-zk3:2181)
2014-10-22 22:31:05,564 | WARN | Expiration detected: trying to restart...
| org.apache.activemq.leveldb.replicated.groups.ZKClient | main-EventThread
2014-10-22 22:31:05,564 | INFO | Initiating client connection,
connectString=uromahn-zk1:2181,uromahn-zk2:2181,uromahn-zk3:2181
sessionTimeout=2000
watcher=org.apache.activemq.leveldb.replicated.groups.ZKClient@3c53cec2 |
org.apache.zookeeper.ZooKeeper | main-EventThread
2014-10-22 22:31:05,566 | INFO | Unable to reconnect to ZooKeeper service,
session 0x24937f0a2a70001 has expired, closing socket connection |
org.apache.zookeeper.ClientCnxn | main-SendThread(uromahn-zk3:2181)
2014-10-22 22:31:05,572 | INFO | Opening socket connection to server
uromahn-zk1/10.XX.AA.BB:2181. Will not attempt to authenticate using SASL
(unknown error) | org.apache.zookeeper.ClientCnxn |
main-SendThread(uromahn-zk1:2181)
2014-10-22 22:31:05,579 | INFO | EventThread shut down |
org.apache.zookeeper.ClientCnxn | main-EventThread
2014-10-22 22:31:05,597 | INFO | Socket connection established to
uromahn-zk1/10.XX.AA.BB:2181, initiating session |
org.apache.zookeeper.ClientCnxn | main-SendThread(uromahn-zk1:2181)
2014-10-22 22:31:05,625 | INFO | Session establishment complete on server
uromahn-zk1/10.XX.AA.BB:2181, sessionid = 0x14937f0a2840000, negotiated
timeout = 4000 | org.apache.zookeeper.ClientCnxn |
main-SendThread(uromahn-zk1:2181)
2014-10-22 22:31:05,745 | WARN | listeners are taking too long to process
the events |
org.apache.activemq.leveldb.replicated.groups.ChangeListenerSupport |
ZooKeeper state change dispatcher thread
On node #3 (passive):
no entry int he log file for that time.
And these are the log entries in my corresponding Zookeeper nodes:
Node #1:
2014-10-22 22:31:05,604 [myid:1] - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] -
Accepted socket connection from /10.XX.YY.ZZ:38788
2014-10-22 22:31:05,606 [myid:1] - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@868] - Client
attempting to establish new session at /10.XX.YY.ZZ:38788
2014-10-22 22:31:05,612 [myid:1] - INFO
[CommitProcessor:1:ZooKeeperServer@617] - Established session
0x14937f0a2840000 with negotiated timeout 4000 for client /10.XX.YY.ZZ:38788
Node #2:
2014-10-22 22:30:40,000 [myid:2] - INFO
[SessionTracker:ZooKeeperServer@347] - Expiring session 0x24937f0a2a70001,
timeout of 4000ms exceeded
2014-10-22 22:30:40,002 [myid:2] - INFO [ProcessThread(sid:2
cport:-1)::PrepRequestProcessor@494] - Processed session termination for
sessionid: 0x24937f0a2a70001
2014-10-22 22:30:40,009 [myid:2] - INFO
[CommitProcessor:2:NIOServerCnxn@1007] - Closed socket connection for client
/10.XX.YY.ZZ:52422 which had sessionid 0x24937f0a2a70001
2014-10-22 22:31:05,639 [myid:2] - INFO [ProcessThread(sid:2
cport:-1)::PrepRequestProcessor@645] - Got user-level KeeperException when
processing sessionid:0x14937f0a2840000 type:setData cxid:0x1
zxid:0x100000014 txntype:-1 reqpath:n/a Error
Path:/activemq-grp1/leveldb-stores/00000000001 Error:KeeperErrorCode =
NoNode for /activemq-grp1/leveldb-stores/00000000001
Node #3:
2014-10-22 22:30:39,972 [myid:3] - WARN
[QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:Follower@118] - Got zxid
0x100000012 expected 0x1
2014-10-22 22:31:05,494 [myid:3] - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxnFactory@197] -
Accepted socket connection from /10.XX.YY.ZZ:60802
2014-10-22 22:31:05,497 [myid:3] - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:ZooKeeperServer@861] - Client
attempting to renew session 0x24937f0a2a70001 at /10.XX.YY.ZZ:60802
2014-10-22 22:31:05,497 [myid:3] - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:Learner@108] - Revalidating
client: 0x24937f0a2a70001
2014-10-22 22:31:05,516 [myid:3] - INFO
[QuorumPeer[myid=3]/0:0:0:0:0:0:0:0:2181:ZooKeeperServer@610] - Invalid
session 0x24937f0a2a70001 for client /10.XX.YY.ZZ:60802, probably expired
2014-10-22 22:31:05,519 [myid:3] - INFO
[NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1007] - Closed
socket connection for client /10.XX.YY.ZZ:60802 which had sessionid
0x24937f0a2a70001
One should note and emphasize again: during the time I see those messages in
the log there was absolutely no activity on the broker and the Zookeeper
nodes (those are exclusively for my brokers)!
This simply doesn't give me the confidence of a robust solution - sorry
guys!
--
View this message in context: http://activemq.2283324.n4.nabble.com/ActiveMQ-Master-Slave-with-ZooKeeper-Session-Expiration-tp4686562p4686658.html
Sent from the ActiveMQ - User mailing list archive at Nabble.com.