You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@hbase.apache.org by Reinis Vicups <hb...@orbit-x.de> on 2014/09/10 09:01:55 UTC
Re: HBaseTestingUtility: Issue with unclosed sessions after minicluster
is shutdown
For those of you who will bump into this issue, here is what looks like
the solution:
https://issues.apache.org/jira/browse/ZOOKEEPER-1904
It is a zookeeper issue solved in zookeeper 3.4.7 and 3.5.0
cheers
reinis
On 17.07.2014 12:30, Reinis Vicups wrote:
> Hi Mikhail,
>
> thank you for your reply.
>
> I absolutely close all the connections e.g. like this:
>
> var localHBase: HBaseTestingUtility = new HBaseTestingUtility()
> val admin: HBaseAdmin = localHBase.getHBaseAdmin
> try {
> admin.createNamespace(NamespaceDescriptor.create(testClient).build())
> } catch {
> case e: NamespaceExistException => traitLog.info("Namespace {}
> already exist, no need to create", testClient)
> } finally {
> admin.close()
> }
>
> The tests per se are quite primitive (at least the stuff in my code)
> and I thoroughly checked, double-checked and quadruple-checked that
> everything I open, I close (in the manner shown in the code fragment
> above).
>
> My question to the community is about HBaseTestingUtility and if it is
> possible that utility might leave some (1-2 per spinned-of
> HBaseTestingUtility) internal(?) zombie-threads or some sort utility
> sessions running after I issue HBaseTestingUtility#shutdownMiniCluster()?
>
> One additional thing I have realized is - I am writing into HBase
> using mapreduce like this:
>
> HBaseConfiguration.addHbaseResources(getConf)
> ...
> job.setMapOutputKeyClass(classOf[ImmutableBytesWritable])
> job.setMapOutputValueClass(classOf[Put])
> ...
> TableMapReduceUtil.initTableReducerJob(tableName, null, job, null,
> null, null, null, false)
>
> There I have way less control on interaction with HBase - could it be
> that HBaseTestingUtility in combination with mapreduce-based HBase
> operations cause this issue.
>
> I am not sure if I mentioned this - ALL the code works perfectly on
> the production system, the issue occurs only during integration testing!
>
> For sure I do not expect that you, guys, find the solution for me, I
> am happy on just any hint whatsoever on what direction I could look
> next into even if its highly speculative.
>
> kind regards
> reinis
>
>
> On 17.07.2014 11:01, Mikhail Antonov wrote:
>> Hi Reinis,
>>
>> sorry, may be missing some context here, you're saying - "Why is Watcher
>> ignoring Disconnected from ZooKeeper?". Normally there's a quorum of
>> zookeeper nodes in the cluster, and when client (having
>> ZooKeeperWatcher)
>> receives this event from zookeeper, it assumes that this zookeeper node
>> failed and it needs to connect to another node. I.e. the fact the or
>> several zookeeper servers appear to have shut down generally doesn't
>> (shouldn't) suggest clients to stop reconnecting.
>>
>> Do you explicitly close client's connections (like HBaseAdmin) when you
>> don't need them anymore?
>>
>> -Mikhail
>>
>>
>> 2014-07-17 1:31 GMT-07:00 Reinis Vicups <hb...@orbit-x.de>:
>>
>>> I am humbly bumping this, since after a week of searching and trying
>>> I am
>>> still unsuccessful in fixing this.
>>>
>>> Thank you guys for your patience
>>> reinis
>>>
>>> On 13.07.2014 14:52, Reinis Vicups wrote:
>>>
>>>> Thank you, Esteban, for your response!
>>>>
>>>> This issue occurs on all my systems (my local windows machine that
>>>> is not
>>>> virtualized, build server - non-virtualized linux, test cluster -
>>>> virtualized linux).
>>>>
>>>> After further investigation and increasing of log level I see log
>>>> bellow.
>>>> It appears as if zookeeper ClientCnxn (or whoever controls it,
>>>> HBase-Client?) does not get (or believe) that server shut down and
>>>> keeps on
>>>> attempting to reconnect. Unfortunately I am a typical consumer and
>>>> do not
>>>> understand the HBase/Zookeeper/Hadoop architecture/choreography :(
>>>> What I
>>>> found interesting is this log message:
>>>>
>>>> 14/07/13 11:27:57 DEBUG zookeeper.ZooKeeperWatcher:
>>>> hconnection-0x1a97512e-0x1472f0ca7df0002, quorum=localhost:49713,
>>>> baseZNode=/afc60aef-1620-435e-847a-71cc4192bb22 Received Disconnected
>>>> from ZooKeeper, ignoring
>>>>
>>>> Why is Watcher ignoring Disconnected from ZooKeeper?
>>>>
>>>> Well, generally I would be very interested to find out how to force
>>>> client just to shutdown.
>>>>
>>>> I have tried already all this:
>>>> localConfig.set(HConstants.ZOOKEEPER_ZNODE_PARENT, "/".concat(new
>>>> RandomStringGeneratorImpl().getRandString)) // give each znode
>>>> different
>>>> name to avoid overlapping
>>>> localConfig.set("zookeeper.recovery.retry", "0") // no recovery
>>>> localConfig.set("zookeeper.session.timeout", "10000") // short
>>>> timeouts
>>>> localConfig.set("hbase.rpc.timeout", "10000") // no idea if
>>>> this is
>>>> relevant
>>>> localConfig.set("hbase.client.retries.number", "1") // could
>>>> not set
>>>> it to 0 since then client wouldn't manage to connect at all
>>>> localConfig.set("hbase.client.pause", "1000") // no idea if
>>>> this is
>>>> relevant
>>>>
>>>> Besides that I tried to:
>>>> - run tests in forked and then in non-forked mode
>>>> - set -Djava.net.preferIPv4Stack=true because in some forum it was
>>>> mentioned as possible reason for connection issues
>>>>
>>>> All in all my integration test consists of 11 somewhat larger
>>>> integration
>>>> test suites (multiple test methods) and I observe that at the end I
>>>> have
>>>> some 11-14 such stale client sessions attempting to re-connect
>>>> endlessly.
>>>>
>>>> I thank you guys in advance and hope someone has energy to help me out
>>>> with this tough sh*t
>>>> reinis
>>>>
>>>>
>>>> LOG
>>>> ----------------------------------------------------
>>>> 14/07/13 11:27:47 INFO zookeeper.ClientCnxn: Opening socket
>>>> connection to
>>>> server 0:0:0:0:0:0:0:1/0:0:0:0:0:0:0:1:49713. Will not attempt to
>>>> authenticate using SASL (unknown error)
>>>> 14/07/13 11:27:47 INFO server.NIOServerCnxnFactory: Accepted socket
>>>> connection from /0:0:0:0:0:0:0:1:50061
>>>> 14/07/13 11:27:47 INFO zookeeper.ClientCnxn: Socket connection
>>>> established to 0:0:0:0:0:0:0:1/0:0:0:0:0:0:0:1:49713, initiating
>>>> session
>>>> 14/07/13 11:27:47 DEBUG zookeeper.ClientCnxn: Session establishment
>>>> request sent on 0:0:0:0:0:0:0:1/0:0:0:0:0:0:0:1:49713
>>>> 14/07/13 11:27:47 DEBUG server.ZooKeeperServer: Session establishment
>>>> request from client /0:0:0:0:0:0:0:1:50061 client's lastZxid is 0x0
>>>> 14/07/13 11:27:47 INFO server.ZooKeeperServer: Client attempting to
>>>> establish new session at /0:0:0:0:0:0:0:1:50061
>>>> 14/07/13 11:27:47 TRACE server.SessionTrackerImpl:
>>>> SessionTrackerImpl ---
>>>> Adding session 0x1472f0ca7df0002 10000
>>>> 14/07/13 11:27:47 TRACE server.PrepRequestProcessor:
>>>> :Psessionid:0x1472f0ca7df0002 type:createSession cxid:0x0
>>>> zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
>>>> 14/07/13 11:27:47 TRACE server.SessionTrackerImpl:
>>>> SessionTrackerImpl ---
>>>> Existing session 0x1472f0ca7df0002 10000
>>>> ...
>>>> 14/07/13 11:27:47 DEBUG server.FinalRequestProcessor: Processing
>>>> request:: sessionid:0x1472f0ca7df0002 type:createSession cxid:0x0
>>>> zxid:0xe
>>>> txntype:-10 reqpath:n/a
>>>> 14/07/13 11:27:47 TRACE server.FinalRequestProcessor:
>>>> :Esessionid:0x1472f0ca7df0002 type:createSession cxid:0x0 zxid:0xe
>>>> txntype:-10 reqpath:n/a
>>>> 14/07/13 11:27:47 TRACE server.SessionTrackerImpl:
>>>> SessionTrackerImpl ---
>>>> Existing session 0x1472f0ca7df0002 10000
>>>> 14/07/13 11:27:47 DEBUG server.FinalRequestProcessor:
>>>> sessionid:0x1472f0ca7df0002 type:createSession cxid:0x0 zxid:0xe
>>>> txntype:-10 reqpath:n/a
>>>> ...
>>>> 14/07/13 11:27:47 INFO server.ZooKeeperServer: Established session
>>>> 0x1472f0ca7df0002 with negotiated timeout 10000 for client
>>>> /0:0:0:0:0:0:0:1:50061
>>>> 14/07/13 11:27:47 TRACE zookeeper.ClientCnxnSocket:
>>>> readConnectResult 37
>>>> 0x[0,0,...
>>>> 14/07/13 11:27:47 INFO zookeeper.ClientCnxn: Session establishment
>>>> complete on server 0:0:0:0:0:0:0:1/0:0:0:0:0:0:0:1:49713, sessionid =
>>>> 0x1472f0ca7df0002, negotiated timeout = 10000
>>>> 14/07/13 11:27:47 DEBUG zookeeper.ZooKeeperWatcher:
>>>> hconnection-0x1a97512e, quorum=localhost:49713,
>>>> baseZNode=/afc60aef-1620-435e-847a-71cc4192bb22 Received ZooKeeper
>>>> Event, type=None, state=SyncConnected, path=null
>>>> 14/07/13 11:27:47 TRACE server.PrepRequestProcessor:
>>>> :Psessionid:0x1472f0ca7df0002 type:exists cxid:0x1
>>>> zxid:0xfffffffffffffffe
>>>> txntype:unknown reqpath:/afc60aef-1620-435e-847a-71cc4192bb22/hbaseid
>>>> ...
>>>> 14/07/13 11:27:47 DEBUG server.FinalRequestProcessor: Processing
>>>> request:: sessionid:0x1472f0ca7df0002 type:exists cxid:0x1
>>>> zxid:0xfffffffffffffffe txntype:unknown reqpath:/afc60aef-1620-435e-
>>>> 847a-71cc4192bb22/hbaseid
>>>> 14/07/13 11:27:47 TRACE server.FinalRequestProcessor:
>>>> :Esessionid:0x1472f0ca7df0002 type:exists cxid:0x1
>>>> zxid:0xfffffffffffffffe
>>>> txntype:unknown reqpath:/afc60aef-1620-435e-847a-71cc4192bb22/hbaseid
>>>> 14/07/13 11:27:47 DEBUG zookeeper.ZooKeeperWatcher:
>>>> hconnection-0x1a97512e-0x1472f0ca7df0002 connected
>>>> 14/07/13 11:27:47 DEBUG server.FinalRequestProcessor:
>>>> sessionid:0x1472f0ca7df0002 type:exists cxid:0x1
>>>> zxid:0xfffffffffffffffe
>>>> txntype:unknown reqpath:/afc60aef-1620-435e-847a-71cc4192bb22/hbaseid
>>>> 14/07/13 11:27:47 DEBUG zookeeper.ClientCnxn: Reading reply
>>>> sessionid:0x1472f0ca7df0002, packet:: clientPath:null serverPath:null
>>>> finished:false header:: 1,3 replyHeader:: 1,14,0 request::
>>>> '/afc60aef-1620-435e-847a-71cc4192bb22/hbaseid,F response::
>>>> s{13,13,1405243667232,1405243667232,0,0,0,0,67,0,13}
>>>> 14/07/13 11:27:47 TRACE server.PrepRequestProcessor:
>>>> :Psessionid:0x1472f0ca7df0002 type:getData cxid:0x2
>>>> zxid:0xfffffffffffffffe
>>>> txntype:unknown reqpath:/afc60aef-1620-435e-847a-71cc4192bb22/hbaseid
>>>> 14/07/13 11:27:47 DEBUG server.FinalRequestProcessor: Processing
>>>> request:: sessionid:0x1472f0ca7df0002 type:getData cxid:0x2
>>>> zxid:0xfffffffffffffffe txntype:unknown reqpath:/afc60aef-1620-435e-
>>>> 847a-71cc4192bb22/hbaseid
>>>> 14/07/13 11:27:47 TRACE server.FinalRequestProcessor:
>>>> :Esessionid:0x1472f0ca7df0002 type:getData cxid:0x2
>>>> zxid:0xfffffffffffffffe
>>>> txntype:unknown reqpath:/afc60aef-1620-435e-847a-71cc4192bb22/hbaseid
>>>> 14/07/13 11:27:47 DEBUG server.FinalRequestProcessor:
>>>> sessionid:0x1472f0ca7df0002 type:getData cxid:0x2
>>>> zxid:0xfffffffffffffffe
>>>> txntype:unknown reqpath:/afc60aef-1620-435e-847a-71cc4192bb22/hbaseid
>>>> 14/07/13 11:27:47 DEBUG zookeeper.ClientCnxn: Reading reply
>>>> sessionid:0x1472f0ca7df0002, packet:: clientPath:null serverPath:null
>>>> finished:false header:: 2,4 replyHeader:: 2,14,0 request::
>>>> '/afc60aef-1620-435e-847a-71cc4192bb22/hbaseid,F response:: #
>>>> ffffffff000146d61737465723a34393939323d6c467c3affffff86fffff
>>>> fc9ffffff8250425546a2435396136323662622d393330312d343763332d
>>>> 616462622d626466366436323365646639,s{13,13,1405243667232,1405243667232,0,0,0,0,67,0,13}
>>>>
>>>>
>>>> 14/07/13 11:27:47 TRACE zookeeper.ZKUtil:
>>>> hconnection-0x1a97512e-0x1472f0ca7df0002,
>>>> quorum=localhost:49713,
>>>> baseZNode=/afc60aef-1620-435e-847a-71cc4192bb22
>>>> Retrieved 42 byte(s) of data from znode
>>>> /afc60aef-1620-435e-847a-71cc4192bb22/hbaseid;
>>>> data=PBUF\x0A$59a626bb-9301-47c3-a...
>>>> ...
>>>> # Number of transactions are being processed normaly, the final
>>>> transaction is cxid:0x18
>>>> 14/07/13 11:27:51 TRACE server.PrepRequestProcessor:
>>>> :Psessionid:0x1472f0ca7df0002 type:getData cxid:0x18
>>>> zxid:0xfffffffffffffffe txntype:unknown reqpath:/afc60aef-1620-435e-
>>>> 847a-71cc4192bb22/meta-region-server
>>>> 14/07/13 11:27:51 DEBUG server.FinalRequestProcessor: Processing
>>>> request:: sessionid:0x1472f0ca7df0002 type:getData cxid:0x18
>>>> zxid:0xfffffffffffffffe txntype:unknown reqpath:/afc60aef-1620-435e-
>>>> 847a-71cc4192bb22/meta-region-server
>>>> 14/07/13 11:27:51 TRACE server.FinalRequestProcessor:
>>>> :Esessionid:0x1472f0ca7df0002 type:getData cxid:0x18
>>>> zxid:0xfffffffffffffffe txntype:unknown reqpath:/afc60aef-1620-435e-
>>>> 847a-71cc4192bb22/meta-region-server
>>>> 14/07/13 11:27:51 DEBUG server.FinalRequestProcessor:
>>>> sessionid:0x1472f0ca7df0002 type:getData cxid:0x18
>>>> zxid:0xfffffffffffffffe
>>>> txntype:unknown reqpath:/afc60aef-1620-435e-
>>>> 847a-71cc4192bb22/meta-region-server
>>>> 14/07/13 11:27:51 DEBUG zookeeper.ClientCnxn: Reading reply
>>>> sessionid:0x1472f0ca7df0002, packet:: clientPath:null serverPath:null
>>>> finished:false header:: 24,4 replyHeader:: 24,70,0 request::
>>>> '/afc60aef-1620-435e-847a-71cc4192bb22/meta-region-server,F
>>>> response:: #
>>>> ffffffff0001a726567696f6e7365727665723a353030323072ffffff9cf
>>>> fffffebffffffc62dffffffb8ffffffc14050425546a20a13616972666f7
>>>> 26365312e667269747a2e626f7810ffffffe4ffffff86318ffffffc8ffff
>>>> ffd6ffffffb2fffffff8fffffff228100,s{38,38,1405243668798,1405243668798,0,0,0,0,71,0,38}
>>>>
>>>>
>>>> 14/07/13 11:27:51 TRACE zookeeper.ZKUtil:
>>>> hconnection-0x1a97512e-0x1472f0ca7df0002,
>>>> quorum=localhost:49713,
>>>> baseZNode=/afc60aef-1620-435e-847a-71cc4192bb22
>>>> Retrieved 40 byte(s) of data from znode /afc60aef-1620-435e-847a-
>>>> 71cc4192bb22/meta-region-server; data=airforce1.fritz.box,
>>>> 50020,1405243665224
>>>> ...
>>>> # Pings ok too!
>>>> 14/07/13 11:27:54 DEBUG server.FinalRequestProcessor: Processing
>>>> request:: sessionid:0x1472f0ca7df0002 type:ping
>>>> cxid:0xfffffffffffffffe
>>>> zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
>>>> 14/07/13 11:27:54 DEBUG server.FinalRequestProcessor:
>>>> sessionid:0x1472f0ca7df0002 type:ping cxid:0xfffffffffffffffe
>>>> zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
>>>> 14/07/13 11:27:54 DEBUG zookeeper.ClientCnxn: Got ping response for
>>>> sessionid: 0x1472f0ca7df0002 after 6ms
>>>> ...
>>>> 14/07/13 11:27:57 DEBUG server.FinalRequestProcessor: Processing
>>>> request:: sessionid:0x1472f0ca7df0002 type:ping
>>>> cxid:0xfffffffffffffffe
>>>> zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
>>>> 14/07/13 11:27:57 DEBUG server.FinalRequestProcessor:
>>>> sessionid:0x1472f0ca7df0002 type:ping cxid:0xfffffffffffffffe
>>>> zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
>>>> 14/07/13 11:27:57 TRACE server.PrepRequestProcessor:
>>>> :Psessionid:0x1472f0ca7df0001 type:getChildren cxid:0x38
>>>> zxid:0xfffffffffffffffe txntype:unknown reqpath:/afc60aef-1620-435e-
>>>> 847a-71cc4192bb22/replication/rs/airforce1.fritz.box,50020,1405243665224
>>>>
>>>> 14/07/13 11:27:57 DEBUG zookeeper.ClientCnxn: Got ping response for
>>>> sessionid: 0x1472f0ca7df0002 after 2ms
>>>> ...
>>>> # Shutdown is starting!
>>>> 14/07/13 11:27:57 INFO server.NIOServerCnxn: Closed socket
>>>> connection for
>>>> client /0:0:0:0:0:0:0:1:50061 which had sessionid 0x1472f0ca7df0002
>>>> 14/07/13 11:27:57 INFO zookeeper.ClientCnxn: Unable to read additional
>>>> data from server sessionid 0x1472f0ca7df0002, likely server has closed
>>>> socket, closing socket connection and attempting reconnect
>>>> 14/07/13 11:27:57 INFO server.NIOServerCnxnFactory: NIOServerCnxn
>>>> factory
>>>> exited run method
>>>> 14/07/13 11:27:57 INFO server.ZooKeeperServer: shutting down
>>>> 14/07/13 11:27:57 INFO server.SessionTrackerImpl: Shutting down
>>>> 14/07/13 11:27:57 TRACE server.SessionTrackerImpl: Shutdown
>>>> SessionTrackerImpl!
>>>> 14/07/13 11:27:57 INFO server.PrepRequestProcessor: Shutting down
>>>> 14/07/13 11:27:57 INFO server.SyncRequestProcessor: Shutting down
>>>> 14/07/13 11:27:57 TRACE server.PrepRequestProcessor: :Psessionid:0x0
>>>> type:notification cxid:0x0 zxid:0xfffffffffffffffe txntype:unknown
>>>> reqpath:n/a
>>>> 14/07/13 11:27:57 INFO server.PrepRequestProcessor:
>>>> PrepRequestProcessor
>>>> exited loop!
>>>> 14/07/13 11:27:57 INFO server.SyncRequestProcessor:
>>>> SyncRequestProcessor
>>>> exited!
>>>> 14/07/13 11:27:57 INFO server.FinalRequestProcessor: shutdown of
>>>> request
>>>> processor complete
>>>> 14/07/13 11:27:57 TRACE zookeeper.ClientCnxnSocketNIO: Doing client
>>>> selector close
>>>> 14/07/13 11:27:57 TRACE zookeeper.ClientCnxnSocketNIO: Closed client
>>>> selector
>>>> 14/07/13 11:27:57 TRACE zookeeper.ClientCnxn: SendThread exitedloop.
>>>> ...
>>>> 14/07/13 11:27:57 DEBUG zookeeper.ZooKeeperWatcher:
>>>> hconnection-0x1a97512e-0x1472f0ca7df0002, quorum=localhost:49713,
>>>> baseZNode=/afc60aef-1620-435e-847a-71cc4192bb22 Received ZooKeeper
>>>> Event, type=None, state=Disconnected, path=null
>>>> 14/07/13 11:27:57 DEBUG zookeeper.ZooKeeperWatcher:
>>>> hconnection-0x56db0aff-0x1472f0ca7df0007, quorum=localhost:49713,
>>>> baseZNode=/afc60aef-1620-435e-847a-71cc4192bb22 Received ZooKeeper
>>>> Event, type=None, state=Disconnected, path=null
>>>>
>>>> # Is it interesting, how ZooKeeperWatcher says 'ignoring' in the log
>>>> message bellow?
>>>> 14/07/13 11:27:57 DEBUG zookeeper.ZooKeeperWatcher:
>>>> hconnection-0x1a97512e-0x1472f0ca7df0002, quorum=localhost:49713,
>>>> baseZNode=/afc60aef-1620-435e-847a-71cc4192bb22 Received Disconnected
>>>> from ZooKeeper, ignoring
>>>> 14/07/13 11:27:57 DEBUG zookeeper.ZooKeeperWatcher:
>>>> hconnection-0x56db0aff-0x1472f0ca7df0007, quorum=localhost:49713,
>>>> baseZNode=/afc60aef-1620-435e-847a-71cc4192bb22 Received Disconnected
>>>> from ZooKeeper, ignoring
>>>> ...
>>>> # from now on this session appears to be stale and attempts to
>>>> re-connect
>>>> until JVM is shutdown!
>>>> 14/07/13 11:27:59 WARN zookeeper.ClientCnxn: Session 0x1472f0ca7df0002
>>>> for server null, unexpected error, closing socket connection and
>>>> attempting
>>>> reconnect
>>>> java.net.ConnectException: Connection refused: no further information
>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>> SocketChannelImpl.java:692)
>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>> ClientCnxnSocketNIO.java:350)
>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>> ClientCnxn.java:1075)
>>>> 14/07/13 11:27:59 DEBUG zookeeper.ClientCnxnSocketNIO: Ignoring
>>>> exception
>>>> during shutdown input
>>>> java.nio.channels.ClosedChannelException
>>>> at sun.nio.ch.SocketChannelImpl.shutdownInput(
>>>> SocketChannelImpl.java:755)
>>>> at sun.nio.ch.SocketAdaptor.shutdownInput(SocketAdaptor.java:421)
>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.cleanup(
>>>> ClientCnxnSocketNIO.java:189)
>>>> at org.apache.zookeeper.ClientCnxn$SendThread.cleanup(
>>>> ClientCnxn.java:1164)
>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>> ClientCnxn.java:1104)
>>>> ...
>>>> 14/07/13 11:28:02 WARN zookeeper.ClientCnxn: Session 0x1472f0ca7df0002
>>>> for server null, unexpected error, closing socket connection and
>>>> attempting
>>>> reconnect
>>>> java.net.ConnectException: Connection refused: no further information
>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>> SocketChannelImpl.java:692)
>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>> ClientCnxnSocketNIO.java:350)
>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>> ClientCnxn.java:1075)
>>>> 14/07/13 11:28:02 DEBUG zookeeper.ClientCnxnSocketNIO: Ignoring
>>>> exception
>>>> during shutdown input
>>>> java.nio.channels.ClosedChannelException
>>>> at sun.nio.ch.SocketChannelImpl.shutdownInput(
>>>> SocketChannelImpl.java:755)
>>>> at sun.nio.ch.SocketAdaptor.shutdownInput(SocketAdaptor.java:421)
>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.cleanup(
>>>> ClientCnxnSocketNIO.java:189)
>>>> at org.apache.zookeeper.ClientCnxn$SendThread.cleanup(
>>>> ClientCnxn.java:1164)
>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>> ClientCnxn.java:1104)
>>>> 14/07/13 11:28:02 DEBUG zookeeper.ClientCnxnSocketNIO: Ignoring
>>>> exception
>>>> during shutdown output
>>>> java.nio.channels.ClosedChannelException
>>>> at sun.nio.ch.SocketChannelImpl.shutdownOutput(
>>>> SocketChannelImpl.java:772)
>>>> at
>>>> sun.nio.ch.SocketAdaptor.shutdownOutput(SocketAdaptor.java:429)
>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.cleanup(
>>>> ClientCnxnSocketNIO.java:196)
>>>> at org.apache.zookeeper.ClientCnxn$SendThread.cleanup(
>>>> ClientCnxn.java:1164)
>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>> ClientCnxn.java:1104)
>>>>
>>>>
>>>> On 13.07.2014 06:34, Esteban Gutierrez wrote:
>>>>
>>>>> Hello Renis,
>>>>>
>>>>> Is this happening every time the test runs? I've seen this
>>>>> happening few
>>>>> times when the test is running with a very small heap or the test is
>>>>> running on VMs and the Java VM or the local file system are
>>>>> unstable due
>>>>> load on the virtualized environment. Have you looked into
>>>>> increasing the
>>>>> heap or the the load of the environment where you are running this
>>>>> test?
>>>>>
>>>>> cheers,
>>>>> esteban.
>>>>>
>>>>> --
>>>>> Cloudera, Inc.
>>>>>
>>>>> On Fri, Jul 11, 2014 at 3:40 AM, Reinis Vicups <hb...@orbit-x.de>
>>>>> wrote:
>>>>>
>>>>> Hi,
>>>>>> I have built a test-harness that I am using to test integration
>>>>>> with the
>>>>>> help of HBaseTestingUtility. The code bellow although allows me
>>>>>> to run
>>>>>> tests, it has one very annoying side effect - some of the sessions
>>>>>> woun't
>>>>>> get closed after I shutdown the minicluster, thus causing lag and
>>>>>> delayed
>>>>>> test execution.
>>>>>>
>>>>>> I would be very grateful to anyone who could give me tip on how
>>>>>> to fix
>>>>>> this.
>>>>>>
>>>>>> merci
>>>>>>
>>>>>> reinis
>>>>>>
>>>>>> Test Suite Code:
>>>>>> ------------------------------------------------------------
>>>>>> ----------------------------------
>>>>>>
>>>>>> abstract trait LocalHBaseSuite extends BeforeAndAfterAll {
>>>>>>
>>>>>> this: Suite =>
>>>>>> @transient lazy val traitLog: Logger =
>>>>>> LoggerFactory.getLogger(this.
>>>>>> getClass.getName)
>>>>>>
>>>>>> var localHBase: HBaseTestingUtility = null
>>>>>> var localFileSystem: FileSystem = null
>>>>>>
>>>>>> override def beforeAll = {
>>>>>> traitLog.warn("{} before beforeAll", this.getClass.getName)
>>>>>> //<-
>>>>>> see
>>>>>> in log
>>>>>>
>>>>>> // load snappy.dll found in hadoop bin directory
>>>>>> val hadoopHomePath = file.Paths.get(ClassLoader.
>>>>>> getSystemResource("hadoop").toURI)
>>>>>> addJavaLibraryPath(file.Paths.get(hadoopHomePath.toAbsolutePath.toString,
>>>>>>
>>>>>>
>>>>>> "bin").toString)
>>>>>> System.loadLibrary("snappy")
>>>>>> System.setProperty("hadoop.home.dir",
>>>>>> hadoopHomePath.toAbsolutePath.
>>>>>> toString)
>>>>>>
>>>>>> localHBase = new HBaseTestingUtility()
>>>>>>
>>>>>> val localConfig = localHBase.getConfiguration
>>>>>> localConfig.set("mapreduce.framework.name", "local")
>>>>>> localConfig.set("dfs.permissions.enabled", "false")
>>>>>> localConfig.set("fs.file.impl.disable.cache", "true")
>>>>>>
>>>>>> localHBase.startMiniCluster()
>>>>>> localFileSystem = localHBase.getTestFileSystem
>>>>>>
>>>>>> traitLog.warn("{} after beforeAll", this.getClass.getName)
>>>>>> //<-
>>>>>> see in
>>>>>> log
>>>>>> }
>>>>>>
>>>>>> override def afterAll = {
>>>>>> traitLog.warn("{} before afterAll", this.getClass.getName)
>>>>>> //<-
>>>>>> see in
>>>>>> log
>>>>>> localHBase.shutdownMiniCluster()
>>>>>> traitLog.warn("{} after afterAll", this.getClass.getName)
>>>>>> //<- see
>>>>>> in
>>>>>> log
>>>>>> localHBase = null
>>>>>> }
>>>>>>
>>>>>> /**
>>>>>> * Adds the given path to the java.library.path system property
>>>>>> */
>>>>>> private def addJavaLibraryPath(libraryPath: String): Unit = {
>>>>>> val usrPathsField: Field = classOf[ClassLoader].
>>>>>> getDeclaredField("usr_paths")
>>>>>> usrPathsField.setAccessible(true)
>>>>>> val newPaths =
>>>>>> usrPathsField.get(null).asInstanceOf[Array[String]]
>>>>>> :+
>>>>>> libraryPath
>>>>>> usrPathsField.set(null, newPaths.asInstanceOf[Array[String]])
>>>>>> }
>>>>>> }
>>>>>>
>>>>>>
>>>>>> Resulting Log-File:
>>>>>> -------------------------------------------
>>>>>>
>>>>>> [info] Loading project definition from D:\git\myproj\project
>>>>>> [info] Set current project to myproj (in build file:/D:/git/myproj/)
>>>>>> [success] Total time: 1 s, completed 11.07.2014 11:00:53
>>>>>> [info] Compiling 1 Scala source to D:\git\myproj\etl\target\
>>>>>> scala-2.10\test-classes...
>>>>>> [info] ScalaTest
>>>>>> [info] Run completed in 42 milliseconds.
>>>>>> [info] Total number of tests run: 0
>>>>>> [info] Suites: completed 0, aborted 0
>>>>>> [info] Tests: succeeded 0, failed 0, canceled 0, ignored 0,
>>>>>> pending 0
>>>>>> [info] No tests were executed.
>>>>>> [info] Passed: Total 0, Failed 0, Errors 0, Passed 0
>>>>>> [info] No tests to run for myproj-Root/it:test
>>>>>> [info] ScalaTest
>>>>>> [info] Run completed in 25 milliseconds.
>>>>>> [info] Total number of tests run: 0
>>>>>> [info] Suites: completed 0, aborted 0
>>>>>> [info] Tests: succeeded 0, failed 0, canceled 0, ignored 0,
>>>>>> pending 0
>>>>>> [info] No tests were executed.
>>>>>> [info] Passed: Total 0, Failed 0, Errors 0, Passed 0
>>>>>> [info] No tests to run for myproj-API/it:test
>>>>>> [info] VectorizeTicketSolutionLogMRJobTest:
>>>>>> 14/07/11 11:01:01 WARN
>>>>>> solutionlog.VectorizeTicketSolutionLogMRJobTest:
>>>>>> com.myproj.quantify.ticket.solutionlog.VectorizeTicketSolutionLogMRJobTest
>>>>>>
>>>>>>
>>>>>> before beforeAll
>>>>>> Formatting using clusterid: testClusterID
>>>>>> 14/07/11 11:01:03 WARN impl.MetricsConfig: Cannot locate
>>>>>> configuration:
>>>>>> tried hadoop-metrics2-namenode.properties,hadoop-metrics2.properties
>>>>>> 14/07/11 11:01:04 WARN server.AuthenticationFilter:
>>>>>> 'signature.secret'
>>>>>> configuration not set, using a random value as secret
>>>>>> 14/07/11 11:01:06 WARN hbase.ZNodeClearer: Environment variable
>>>>>> HBASE_ZNODE_FILE not set; znodes will not be cleared on crash by
>>>>>> start
>>>>>> scripts (Longer MTTR!)
>>>>>> 14/07/11 11:01:08 WARN hbase.ZNodeClearer: Environment variable
>>>>>> HBASE_ZNODE_FILE not set; znodes will not be cleared on crash by
>>>>>> start
>>>>>> scripts (Longer MTTR!)
>>>>>> 14/07/11 11:01:09 WARN zookeeper.RecoverableZooKeeper: Node
>>>>>> /hbase/meta-region-server already deleted, retry=false
>>>>>> 14/07/11 11:01:10 WARN
>>>>>> solutionlog.VectorizeTicketSolutionLogMRJobTest:
>>>>>> com.myproj.quantify.ticket.solutionlog.VectorizeTicketSolutionLogMRJobTest
>>>>>>
>>>>>>
>>>>>> after beforeAll
>>>>>> 14/07/11 11:01:10 WARN hbase.HBaseCommonTestingUtility: close()
>>>>>> called
>>>>>> on
>>>>>> HBaseAdmin instance returned from
>>>>>> HBaseTestingUtility.getHBaseAdmin()
>>>>>> 14/07/11 11:01:12 WARN mapreduce.JobSubmitter: No job jar file
>>>>>> set. User
>>>>>> classes may not be found. See Job or Job#setJar(String).
>>>>>> 14/07/11 11:01:12 WARN conf.Configuration: file:/D:/git/myproj/etl/
>>>>>> target/test-data/1e71ff51-76c5-45e9-8d44-1249dbff3055/
>>>>>> hadoop/mapreduce-jobtracker-staging-root-dir/
>>>>>> user467204862/.staging/job_local467204862_0001/job.xml:an
>>>>>> attempt to override final parameter: mapreduce.job.end-
>>>>>> notification.max.retry.interval; Ignoring.
>>>>>> 14/07/11 11:01:12 WARN conf.Configuration: file:/D:/git/myproj/etl/
>>>>>> target/test-data/1e71ff51-76c5-45e9-8d44-1249dbff3055/
>>>>>> hadoop/mapreduce-jobtracker-staging-root-dir/
>>>>>> user467204862/.staging/job_local467204862_0001/job.xml:an
>>>>>> attempt to override final parameter: mapreduce.job.end-
>>>>>> notification.max.attempts;
>>>>>> Ignoring.
>>>>>> 14/07/11 11:01:12 WARN conf.Configuration: file:/D:/git/myproj/etl/
>>>>>> target/test-data/1e71ff51-76c5-45e9-8d44-1249dbff3055/
>>>>>> hadoop_tmp/mapred/local/localRunner/user/job_local467204862_0001/job_local467204862_0001.xml:an
>>>>>>
>>>>>>
>>>>>> attempt to override final parameter: mapreduce.job.end-
>>>>>> notification.max.retry.interval; Ignoring.
>>>>>> 14/07/11 11:01:12 WARN conf.Configuration: file:/D:/git/myproj/etl/
>>>>>> target/test-data/1e71ff51-76c5-45e9-8d44-1249dbff3055/
>>>>>> hadoop_tmp/mapred/local/localRunner/user/job_local467204862_0001/job_local467204862_0001.xml:an
>>>>>>
>>>>>>
>>>>>> attempt to override final parameter: mapreduce.job.end-
>>>>>> notification.max.attempts;
>>>>>> Ignoring.
>>>>>> [info] - should validate that VectorizeTicketSolutionLogMRJob
>>>>>> generates
>>>>>> correct HBase table
>>>>>> 14/07/11 11:01:13 WARN
>>>>>> solutionlog.VectorizeTicketSolutionLogMRJobTest:
>>>>>> com.myproj.quantify.ticket.solutionlog.VectorizeTicketSolutionLogMRJobTest
>>>>>>
>>>>>>
>>>>>> after table close
>>>>>> 14/07/11 11:01:13 WARN
>>>>>> solutionlog.VectorizeTicketSolutionLogMRJobTest:
>>>>>> com.myproj.quantify.ticket.solutionlog.VectorizeTicketSolutionLogMRJobTest
>>>>>>
>>>>>>
>>>>>> before afterAll
>>>>>> 14/07/11 11:01:13 WARN server.NIOServerCnxn: caught end of stream
>>>>>> exception
>>>>>> EndOfStreamException: Unable to read additional data from client
>>>>>> sessionid
>>>>>> 0x14724a78b320003, likely client has closed socket
>>>>>> at org.apache.zookeeper.server.NIOServerCnxn.doIO(
>>>>>> NIOServerCnxn.java:220)
>>>>>> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(
>>>>>> NIOServerCnxnFactory.java:208)
>>>>>> at java.lang.Thread.run(Thread.java:722)
>>>>>> 14/07/11 11:01:18 WARN server.NIOServerCnxn: caught end of stream
>>>>>> exception
>>>>>> EndOfStreamException: Unable to read additional data from client
>>>>>> sessionid
>>>>>> 0x14724a78b320004, likely client has closed socket
>>>>>> at org.apache.zookeeper.server.NIOServerCnxn.doIO(
>>>>>> NIOServerCnxn.java:220)
>>>>>> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(
>>>>>> NIOServerCnxnFactory.java:208)
>>>>>> at java.lang.Thread.run(Thread.java:722)
>>>>>> 14/07/11 11:01:18 ERROR client.HConnectionManager: Connection not
>>>>>> found
>>>>>> in
>>>>>> the list, can't delete it (connection key=HConnectionKey{properties=
>>>>>> {hbase.rpc.timeout=60000,
>>>>>> hbase.zookeeper.property.clientPort=63640, hbase.client.pause=100,
>>>>>> zookeeper.znode.parent=/hbase, hbase.client.retries.number=350,
>>>>>> hbase.zookeeper.quorum=localhost}, username='user'}). May be the key
>>>>>> was
>>>>>> modified?
>>>>>> java.lang.Exception
>>>>>> at org.apache.hadoop.hbase.client.HConnectionManager.
>>>>>> deleteConnection(
>>>>>> HConnectionManager.java:466)
>>>>>> at org.apache.hadoop.hbase.client.HConnectionManager.
>>>>>> deleteConnection(
>>>>>> HConnectionManager.java:402)
>>>>>> at org.apache.hadoop.hbase.replication.master.
>>>>>> ReplicationLogCleaner.stop(ReplicationLogCleaner.java:142)
>>>>>> at org.apache.hadoop.hbase.master.cleaner.CleanerChore.
>>>>>> cleanup(CleanerChore.java:276)
>>>>>> at org.apache.hadoop.hbase.Chore.run(Chore.java:94)
>>>>>> at java.lang.Thread.run(Thread.java:722)
>>>>>> 14/07/11 11:01:19 WARN datanode.DirectoryScanner: DirectoryScanner:
>>>>>> shutdown has been called
>>>>>> 14/07/11 11:01:19 WARN datanode.DataNode: BPOfferService for
>>>>>> Block pool
>>>>>> BP-466654724-192.168.178.20-1405069263037 (Datanode Uuid
>>>>>> cc3e8ece-62e2-4877-92fe-8fdec4d1179f) service to /127.0.0.1:61391
>>>>>> interrupted
>>>>>> 14/07/11 11:01:19 WARN datanode.DataNode: Ending block pool
>>>>>> service for:
>>>>>> Block pool BP-466654724-192.168.178.20-1405069263037 (Datanode Uuid
>>>>>> cc3e8ece-62e2-4877-92fe-8fdec4d1179f) service to /127.0.0.1:61391
>>>>>> 14/07/11 11:01:19 WARN blockmanagement.DecommissionManager: Monitor
>>>>>> interrupted: java.lang.InterruptedException: sleep interrupted
>>>>>> 14/07/11 11:01:19 WARN
>>>>>> solutionlog.VectorizeTicketSolutionLogMRJobTest:
>>>>>> com.myproj.quantify.ticket.solutionlog.VectorizeTicketSolutionLogMRJobTest
>>>>>>
>>>>>>
>>>>>> after afterAll
>>>>>> 14/07/11 11:01:19 WARN similarity.TicketTextSimilarityPreference
>>>>>> MRJobTest:
>>>>>> com.myproj.similarity.TicketTextSimilarityPreferenceMRJobTest before
>>>>>> beforeAll
>>>>>> [info] TicketTextSimilarityPreferenceMRJobTest:
>>>>>> 14/07/11 11:01:19 WARN hbase.HBaseCommonTestingUtility:
>>>>>> hadoop.tmp.dir
>>>>>> property value differs in configuration and system:
>>>>>> Configuration=/tmp/hadoop-user while System=D:/git/myproj/etl/
>>>>>> target/test-data/1e71ff51-76c5-45e9-8d44-1249dbff3055/hadoop_tmp
>>>>>> Erasing
>>>>>> configuration value by system value.
>>>>>> Formatting using clusterid: testClusterID
>>>>>> 14/07/11 11:01:19 WARN zookeeper.ClientCnxn: Session
>>>>>> 0x14724a78b320002
>>>>>> for
>>>>>> server null, unexpected error, closing socket connection and
>>>>>> attempting
>>>>>> reconnect
>>>>>> java.net.ConnectException: Connection refused: no further
>>>>>> information
>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>> SocketChannelImpl.java:692)
>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>> ClientCnxn.java:1075)
>>>>>> 14/07/11 11:01:20 WARN server.AuthenticationFilter:
>>>>>> 'signature.secret'
>>>>>> configuration not set, using a random value as secret
>>>>>> 14/07/11 11:01:20 WARN zookeeper.ClientCnxn: Session
>>>>>> 0x14724a78b320007
>>>>>> for
>>>>>> server null, unexpected error, closing socket connection and
>>>>>> attempting
>>>>>> reconnect
>>>>>> java.net.ConnectException: Connection refused: no further
>>>>>> information
>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>> SocketChannelImpl.java:692)
>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>> ClientCnxn.java:1075)
>>>>>> 14/07/11 11:01:21 WARN hbase.ZNodeClearer: Environment variable
>>>>>> HBASE_ZNODE_FILE not set; znodes will not be cleared on crash by
>>>>>> start
>>>>>> scripts (Longer MTTR!)
>>>>>> 14/07/11 11:01:22 WARN zookeeper.ClientCnxn: Session
>>>>>> 0x14724a78b320002
>>>>>> for
>>>>>> server null, unexpected error, closing socket connection and
>>>>>> attempting
>>>>>> reconnect
>>>>>> java.net.ConnectException: Connection refused: no further
>>>>>> information
>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>> SocketChannelImpl.java:692)
>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>> ClientCnxn.java:1075)
>>>>>> 14/07/11 11:01:22 WARN zookeeper.ClientCnxn: Session
>>>>>> 0x14724a78b320007
>>>>>> for
>>>>>> server null, unexpected error, closing socket connection and
>>>>>> attempting
>>>>>> reconnect
>>>>>> java.net.ConnectException: Connection refused: no further
>>>>>> information
>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>> SocketChannelImpl.java:692)
>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>> ClientCnxn.java:1075)
>>>>>> 14/07/11 11:01:23 WARN regionserver.HRegionServer: reportForDuty
>>>>>> failed;
>>>>>> sleeping and then retrying.
>>>>>> 14/07/11 11:01:23 WARN zookeeper.ClientCnxn: Session
>>>>>> 0x14724a78b320002
>>>>>> for
>>>>>> server null, unexpected error, closing socket connection and
>>>>>> attempting
>>>>>> reconnect
>>>>>> java.net.ConnectException: Connection refused: no further
>>>>>> information
>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>> SocketChannelImpl.java:692)
>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>> ClientCnxn.java:1075)
>>>>>> 14/07/11 11:01:24 WARN zookeeper.ClientCnxn: Session
>>>>>> 0x14724a78b320007
>>>>>> for
>>>>>> server null, unexpected error, closing socket connection and
>>>>>> attempting
>>>>>> reconnect
>>>>>> java.net.ConnectException: Connection refused: no further
>>>>>> information
>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>> SocketChannelImpl.java:692)
>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>> ClientCnxn.java:1075)
>>>>>> 14/07/11 11:01:26 WARN hbase.ZNodeClearer: Environment variable
>>>>>> HBASE_ZNODE_FILE not set; znodes will not be cleared on crash by
>>>>>> start
>>>>>> scripts (Longer MTTR!)
>>>>>> 14/07/11 11:01:26 WARN zookeeper.ClientCnxn: Session
>>>>>> 0x14724a78b320002
>>>>>> for
>>>>>> server null, unexpected error, closing socket connection and
>>>>>> attempting
>>>>>> reconnect
>>>>>> java.net.ConnectException: Connection refused: no further
>>>>>> information
>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>> SocketChannelImpl.java:692)
>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>> ClientCnxn.java:1075)
>>>>>> 14/07/11 11:01:27 WARN zookeeper.ClientCnxn: Session
>>>>>> 0x14724a78b320007
>>>>>> for
>>>>>> server null, unexpected error, closing socket connection and
>>>>>> attempting
>>>>>> reconnect
>>>>>> java.net.ConnectException: Connection refused: no further
>>>>>> information
>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>> SocketChannelImpl.java:692)
>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>> ClientCnxn.java:1075)
>>>>>> 14/07/11 11:01:27 WARN zookeeper.RecoverableZooKeeper: Node
>>>>>> /hbase/meta-region-server already deleted, retry=false
>>>>>> 14/07/11 11:01:28 WARN zookeeper.ClientCnxn: Session
>>>>>> 0x14724a78b320002
>>>>>> for
>>>>>> server null, unexpected error, closing socket connection and
>>>>>> attempting
>>>>>> reconnect
>>>>>> java.net.ConnectException: Connection refused: no further
>>>>>> information
>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>> SocketChannelImpl.java:692)
>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>> ClientCnxn.java:1075)
>>>>>> 14/07/11 11:01:28 WARN zookeeper.ClientCnxn: Session
>>>>>> 0x14724a78b320007
>>>>>> for
>>>>>> server null, unexpected error, closing socket connection and
>>>>>> attempting
>>>>>> reconnect
>>>>>> java.net.ConnectException: Connection refused: no further
>>>>>> information
>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>> SocketChannelImpl.java:692)
>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>> ClientCnxn.java:1075)
>>>>>> 14/07/11 11:01:28 WARN similarity.TicketTextSimilarityPreference
>>>>>> MRJobTest:
>>>>>> com.myproj.similarity.TicketTextSimilarityPreferenceMRJobTest after
>>>>>> beforeAll
>>>>>> 14/07/11 11:01:28 WARN hbase.HBaseCommonTestingUtility: close()
>>>>>> called
>>>>>> on
>>>>>> HBaseAdmin instance returned from
>>>>>> HBaseTestingUtility.getHBaseAdmin()
>>>>>> 14/07/11 11:01:30 WARN mapreduce.JobSubmitter: No job jar file
>>>>>> set. User
>>>>>> classes may not be found. See Job or Job#setJar(String).
>>>>>> 14/07/11 11:01:30 WARN conf.Configuration: file:/D:/git/myproj/etl/
>>>>>> target/test-data/c85b7f3b-4e4b-40b4-a434-a45cecc9cba8/
>>>>>> hadoop/mapreduce-jobtracker-staging-root-dir/user1872843153/.staging/job_
>>>>>>
>>>>>>
>>>>>> local1872843153_0002/job.xml:an attempt to override final parameter:
>>>>>> mapreduce.job.end-notification.max.retry.interval; Ignoring.
>>>>>> 14/07/11 11:01:30 WARN conf.Configuration: file:/D:/git/myproj/etl/
>>>>>> target/test-data/c85b7f3b-4e4b-40b4-a434-a45cecc9cba8/
>>>>>> hadoop/mapreduce-jobtracker-staging-root-dir/user1872843153/.staging/job_
>>>>>>
>>>>>>
>>>>>> local1872843153_0002/job.xml:an attempt to override final parameter:
>>>>>> mapreduce.job.end-notification.max.attempts; Ignoring.
>>>>>> 14/07/11 11:01:30 WARN conf.Configuration: file:/D:/git/myproj/etl/
>>>>>> target/test-data/c85b7f3b-4e4b-40b4-a434-a45cecc9cba8/
>>>>>> mapred_local/localRunner/user/job_local1872843153_0002/job_local1872843153_0002.xml:an
>>>>>>
>>>>>>
>>>>>> attempt to override final parameter: mapreduce.job.end-
>>>>>> notification.max.retry.interval; Ignoring.
>>>>>> 14/07/11 11:01:30 WARN conf.Configuration: file:/D:/git/myproj/etl/
>>>>>> target/test-data/c85b7f3b-4e4b-40b4-a434-a45cecc9cba8/
>>>>>> mapred_local/localRunner/user/job_local1872843153_0002/job_local1872843153_0002.xml:an
>>>>>>
>>>>>>
>>>>>> attempt to override final parameter: mapreduce.job.end-
>>>>>> notification.max.attempts;
>>>>>> Ignoring.
>>>>>> 14/07/11 11:01:31 WARN zookeeper.ClientCnxn: Session
>>>>>> 0x14724a78b320002
>>>>>> for
>>>>>> server null, unexpected error, closing socket connection and
>>>>>> attempting
>>>>>> reconnect
>>>>>> java.net.ConnectException: Connection refused: no further
>>>>>> information
>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>> SocketChannelImpl.java:692)
>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>> ClientCnxn.java:1075)
>>>>>> 14/07/11 11:01:31 WARN zookeeper.ClientCnxn: Session
>>>>>> 0x14724a78b320007
>>>>>> for
>>>>>> server null, unexpected error, closing socket connection and
>>>>>> attempting
>>>>>> reconnect
>>>>>> java.net.ConnectException: Connection refused: no further
>>>>>> information
>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>> SocketChannelImpl.java:692)
>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>> ClientCnxn.java:1075)
>>>>>> 14/07/11 11:01:32 WARN zookeeper.ClientCnxn: Session
>>>>>> 0x14724a78b320007
>>>>>> for
>>>>>> server null, unexpected error, closing socket connection and
>>>>>> attempting
>>>>>> reconnect
>>>>>> java.net.ConnectException: Connection refused: no further
>>>>>> information
>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>> SocketChannelImpl.java:692)
>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>> ClientCnxn.java:1075)
>>>>>> 14/07/11 11:01:33 WARN zookeeper.ClientCnxn: Session
>>>>>> 0x14724a78b320002
>>>>>> for
>>>>>> server null, unexpected error, closing socket connection and
>>>>>> attempting
>>>>>> reconnect
>>>>>> java.net.ConnectException: Connection refused: no further
>>>>>> information
>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>> SocketChannelImpl.java:692)
>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>> ClientCnxn.java:1075)
>>>>>> [info] - should run ticket text similarity preference mr job
>>>>>> [info] - should generate preference table that is compatible with
>>>>>> HBasedDataModel
>>>>>> 14/07/11 11:01:33 WARN similarity.TicketTextSimilarityPreference
>>>>>> MRJobTest:
>>>>>> com.myproj.similarity.TicketTextSimilarityPreferenceMRJobTest after
>>>>>> table
>>>>>> close
>>>>>> 14/07/11 11:01:33 WARN similarity.TicketTextSimilarityPreference
>>>>>> MRJobTest:
>>>>>> com.myproj.similarity.TicketTextSimilarityPreferenceMRJobTest before
>>>>>> afterAll
>>>>>> 14/07/11 11:01:35 WARN zookeeper.ClientCnxn: Session
>>>>>> 0x14724a78b320007
>>>>>> for
>>>>>> server null, unexpected error, closing socket connection and
>>>>>> attempting
>>>>>> reconnect
>>>>>> java.net.ConnectException: Connection refused: no further
>>>>>> information
>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>> SocketChannelImpl.java:692)
>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>> ClientCnxn.java:1075)
>>>>>> 14/07/11 11:01:36 WARN zookeeper.ClientCnxn: Session
>>>>>> 0x14724a78b320002
>>>>>> for
>>>>>> server null, unexpected error, closing socket connection and
>>>>>> attempting
>>>>>> reconnect
>>>>>> java.net.ConnectException: Connection refused: no further
>>>>>> information
>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>> SocketChannelImpl.java:692)
>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>> ClientCnxn.java:1075)
>>>>>> 14/07/11 11:01:36 ERROR client.HConnectionManager: Connection not
>>>>>> found
>>>>>> in
>>>>>> the list, can't delete it (connection key=HConnectionKey{properties=
>>>>>> {hbase.rpc.timeout=60000,
>>>>>> hbase.zookeeper.property.clientPort=65078, hbase.client.pause=100,
>>>>>> zookeeper.znode.parent=/hbase, hbase.client.retries.number=350,
>>>>>> hbase.zookeeper.quorum=localhost}, username='user'}). May be the key
>>>>>> was
>>>>>> modified?
>>>>>> java.lang.Exception
>>>>>> at org.apache.hadoop.hbase.client.HConnectionManager.
>>>>>> deleteConnection(
>>>>>> HConnectionManager.java:466)
>>>>>> at org.apache.hadoop.hbase.client.HConnectionManager.
>>>>>> deleteConnection(
>>>>>> HConnectionManager.java:402)
>>>>>> at org.apache.hadoop.hbase.replication.master.
>>>>>> ReplicationLogCleaner.stop(ReplicationLogCleaner.java:142)
>>>>>> at org.apache.hadoop.hbase.master.cleaner.CleanerChore.
>>>>>> cleanup(CleanerChore.java:276)
>>>>>> at org.apache.hadoop.hbase.Chore.run(Chore.java:94)
>>>>>> at java.lang.Thread.run(Thread.java:722)
>>>>>> 14/07/11 11:01:37 WARN zookeeper.ClientCnxn: Session
>>>>>> 0x14724a78b320007
>>>>>> for
>>>>>> server null, unexpected error, closing socket connection and
>>>>>> attempting
>>>>>> reconnect
>>>>>> java.net.ConnectException: Connection refused: no further
>>>>>> information
>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>> SocketChannelImpl.java:692)
>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>> ClientCnxn.java:1075)
>>>>>> 14/07/11 11:01:37 WARN zookeeper.ClientCnxn: Session
>>>>>> 0x14724a78b320002
>>>>>> for
>>>>>> server null, unexpected error, closing socket connection and
>>>>>> attempting
>>>>>> reconnect
>>>>>> java.net.ConnectException: Connection refused: no further
>>>>>> information
>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>> SocketChannelImpl.java:692)
>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>> ClientCnxn.java:1075)
>>>>>> 14/07/11 11:01:37 WARN datanode.DirectoryScanner: DirectoryScanner:
>>>>>> shutdown has been called
>>>>>> 14/07/11 11:01:37 WARN datanode.DataNode: BPOfferService for
>>>>>> Block pool
>>>>>> BP-912909389-192.168.178.20-1405069279778 (Datanode Uuid
>>>>>> c6c45632-3e50-4575-8b65-92d7479a48ba) service to /127.0.0.1:61553
>>>>>> interrupted
>>>>>> 14/07/11 11:01:37 WARN datanode.DataNode: Ending block pool
>>>>>> service for:
>>>>>> Block pool BP-912909389-192.168.178.20-1405069279778 (Datanode Uuid
>>>>>> c6c45632-3e50-4575-8b65-92d7479a48ba) service to /127.0.0.1:61553
>>>>>> 14/07/11 11:01:37 WARN blockmanagement.DecommissionManager: Monitor
>>>>>> interrupted: java.lang.InterruptedException: sleep interrupted
>>>>>> 14/07/11 11:01:37 WARN similarity.TicketTextSimilarityPreference
>>>>>> MRJobTest:
>>>>>> com.myproj.similarity.TicketTextSimilarityPreferenceMRJobTest after
>>>>>> afterAll
>>>>>> [info] TicketMasterDataCategoryGroupingMRJobTest:
>>>>>> 14/07/11 11:01:37 WARN masterdata.TicketMasterDataCategoryGroupi
>>>>>> ngMRJobTest:
>>>>>> com.myproj.quantify.ticket.masterdata.TicketMasterDataCategoryGroupingMRJobTest
>>>>>>
>>>>>>
>>>>>> before beforeAll
>>>>>> 14/07/11 11:01:37 WARN hbase.HBaseCommonTestingUtility:
>>>>>> hadoop.tmp.dir
>>>>>> property value differs in configuration and system:
>>>>>> Configuration=/tmp/hadoop-user while System=D:/git/myproj/etl/
>>>>>> target/test-data/c85b7f3b-4e4b-40b4-a434-a45cecc9cba8/hadoop_tmp
>>>>>> Erasing
>>>>>> configuration value by system value.
>>>>>> Formatting using clusterid: testClusterID
>>>>>> 14/07/11 11:01:38 WARN server.AuthenticationFilter:
>>>>>> 'signature.secret'
>>>>>> configuration not set, using a random value as secret
>>>>>> 14/07/11 11:01:38 WARN zookeeper.ClientCnxn: Session
>>>>>> 0x14724a7c5790007
>>>>>> for
>>>>>> server null, unexpected error, closing socket connection and
>>>>>> attempting
>>>>>> reconnect
>>>>>> java.net.ConnectException: Connection refused: no further
>>>>>> information
>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>> SocketChannelImpl.java:692)
>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>> ClientCnxn.java:1075)
>>>>>> 14/07/11 11:01:38 WARN zookeeper.ClientCnxn: Session
>>>>>> 0x14724a7c5790002
>>>>>> for
>>>>>> server null, unexpected error, closing socket connection and
>>>>>> attempting
>>>>>> reconnect
>>>>>> java.net.ConnectException: Connection refused: no further
>>>>>> information
>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>> SocketChannelImpl.java:692)
>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>> ClientCnxn.java:1075)
>>>>>> 14/07/11 11:01:39 WARN hbase.ZNodeClearer: Environment variable
>>>>>> HBASE_ZNODE_FILE not set; znodes will not be cleared on crash by
>>>>>> start
>>>>>> scripts (Longer MTTR!)
>>>>>> 14/07/11 11:01:39 WARN zookeeper.ClientCnxn: Session
>>>>>> 0x14724a78b320002
>>>>>> for
>>>>>> server null, unexpected error, closing socket connection and
>>>>>> attempting
>>>>>> reconnect
>>>>>> java.net.ConnectException: Connection refused: no further
>>>>>> information
>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>> SocketChannelImpl.java:692)
>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>> ClientCnxn.java:1075)
>>>>>>
>>>>>> # ... This goes on and on and on ...
>>>>>>
>>>>>> [info] ScalaTest
>>>>>> [info] Run completed in 5 minutes, 23 seconds.
>>>>>> [info] Total number of tests run: 22
>>>>>> [info] Suites: completed 10, aborted 0
>>>>>> [info] Tests: succeeded 22, failed 0, canceled 0, ignored 0,
>>>>>> pending 0
>>>>>> [info] All tests passed.
>>>>>> [info] Passed: Total 26, Failed 0, Errors 0, Passed 24, Skipped 2
>>>>>> [success] Total time: 331 s, completed 11.07.2014 11:06:24
>>>>>>
Re: HBaseTestingUtility: Issue with unclosed sessions after
minicluster is shutdown
Posted by Esteban Gutierrez <es...@cloudera.com>.
Thanks for the update Renis,
however from a cursory read from the committed code in ZooKeeper doesn't
seems that code path is used by HBase at all, have you tried the 3.5
release? does that solve the issue? If upgrading ZK to another release
fixed the issue perhaps the problem in a different part of the ZK code.
cheers,
esteban.
--
Cloudera, Inc.
On Wed, Sep 10, 2014 at 12:01 AM, Reinis Vicups <hb...@orbit-x.de> wrote:
> For those of you who will bump into this issue, here is what looks like
> the solution:
>
> https://issues.apache.org/jira/browse/ZOOKEEPER-1904
>
> It is a zookeeper issue solved in zookeeper 3.4.7 and 3.5.0
>
> cheers
> reinis
>
>
> On 17.07.2014 12:30, Reinis Vicups wrote:
>
>> Hi Mikhail,
>>
>> thank you for your reply.
>>
>> I absolutely close all the connections e.g. like this:
>>
>> var localHBase: HBaseTestingUtility = new HBaseTestingUtility()
>> val admin: HBaseAdmin = localHBase.getHBaseAdmin
>> try {
>> admin.createNamespace(NamespaceDescriptor.create(testClient).build())
>> } catch {
>> case e: NamespaceExistException => traitLog.info("Namespace {}
>> already exist, no need to create", testClient)
>> } finally {
>> admin.close()
>> }
>>
>> The tests per se are quite primitive (at least the stuff in my code) and
>> I thoroughly checked, double-checked and quadruple-checked that everything
>> I open, I close (in the manner shown in the code fragment above).
>>
>> My question to the community is about HBaseTestingUtility and if it is
>> possible that utility might leave some (1-2 per spinned-of
>> HBaseTestingUtility) internal(?) zombie-threads or some sort utility
>> sessions running after I issue HBaseTestingUtility#shutdownMiniCluster()?
>>
>> One additional thing I have realized is - I am writing into HBase using
>> mapreduce like this:
>>
>> HBaseConfiguration.addHbaseResources(getConf)
>> ...
>> job.setMapOutputKeyClass(classOf[ImmutableBytesWritable])
>> job.setMapOutputValueClass(classOf[Put])
>> ...
>> TableMapReduceUtil.initTableReducerJob(tableName, null, job, null,
>> null, null, null, false)
>>
>> There I have way less control on interaction with HBase - could it be
>> that HBaseTestingUtility in combination with mapreduce-based HBase
>> operations cause this issue.
>>
>> I am not sure if I mentioned this - ALL the code works perfectly on the
>> production system, the issue occurs only during integration testing!
>>
>> For sure I do not expect that you, guys, find the solution for me, I am
>> happy on just any hint whatsoever on what direction I could look next into
>> even if its highly speculative.
>>
>> kind regards
>> reinis
>>
>>
>> On 17.07.2014 11:01, Mikhail Antonov wrote:
>>
>>> Hi Reinis,
>>>
>>> sorry, may be missing some context here, you're saying - "Why is Watcher
>>> ignoring Disconnected from ZooKeeper?". Normally there's a quorum of
>>> zookeeper nodes in the cluster, and when client (having ZooKeeperWatcher)
>>> receives this event from zookeeper, it assumes that this zookeeper node
>>> failed and it needs to connect to another node. I.e. the fact the or
>>> several zookeeper servers appear to have shut down generally doesn't
>>> (shouldn't) suggest clients to stop reconnecting.
>>>
>>> Do you explicitly close client's connections (like HBaseAdmin) when you
>>> don't need them anymore?
>>>
>>> -Mikhail
>>>
>>>
>>> 2014-07-17 1:31 GMT-07:00 Reinis Vicups <hb...@orbit-x.de>:
>>>
>>> I am humbly bumping this, since after a week of searching and trying I
>>>> am
>>>> still unsuccessful in fixing this.
>>>>
>>>> Thank you guys for your patience
>>>> reinis
>>>>
>>>> On 13.07.2014 14:52, Reinis Vicups wrote:
>>>>
>>>> Thank you, Esteban, for your response!
>>>>>
>>>>> This issue occurs on all my systems (my local windows machine that is
>>>>> not
>>>>> virtualized, build server - non-virtualized linux, test cluster -
>>>>> virtualized linux).
>>>>>
>>>>> After further investigation and increasing of log level I see log
>>>>> bellow.
>>>>> It appears as if zookeeper ClientCnxn (or whoever controls it,
>>>>> HBase-Client?) does not get (or believe) that server shut down and
>>>>> keeps on
>>>>> attempting to reconnect. Unfortunately I am a typical consumer and do
>>>>> not
>>>>> understand the HBase/Zookeeper/Hadoop architecture/choreography :(
>>>>> What I
>>>>> found interesting is this log message:
>>>>>
>>>>> 14/07/13 11:27:57 DEBUG zookeeper.ZooKeeperWatcher:
>>>>> hconnection-0x1a97512e-0x1472f0ca7df0002, quorum=localhost:49713,
>>>>> baseZNode=/afc60aef-1620-435e-847a-71cc4192bb22 Received Disconnected
>>>>> from ZooKeeper, ignoring
>>>>>
>>>>> Why is Watcher ignoring Disconnected from ZooKeeper?
>>>>>
>>>>> Well, generally I would be very interested to find out how to force
>>>>> client just to shutdown.
>>>>>
>>>>> I have tried already all this:
>>>>> localConfig.set(HConstants.ZOOKEEPER_ZNODE_PARENT, "/".concat(new
>>>>> RandomStringGeneratorImpl().getRandString)) // give each znode
>>>>> different
>>>>> name to avoid overlapping
>>>>> localConfig.set("zookeeper.recovery.retry", "0") // no recovery
>>>>> localConfig.set("zookeeper.session.timeout", "10000") // short
>>>>> timeouts
>>>>> localConfig.set("hbase.rpc.timeout", "10000") // no idea if this
>>>>> is
>>>>> relevant
>>>>> localConfig.set("hbase.client.retries.number", "1") // could not
>>>>> set
>>>>> it to 0 since then client wouldn't manage to connect at all
>>>>> localConfig.set("hbase.client.pause", "1000") // no idea if this
>>>>> is
>>>>> relevant
>>>>>
>>>>> Besides that I tried to:
>>>>> - run tests in forked and then in non-forked mode
>>>>> - set -Djava.net.preferIPv4Stack=true because in some forum it was
>>>>> mentioned as possible reason for connection issues
>>>>>
>>>>> All in all my integration test consists of 11 somewhat larger
>>>>> integration
>>>>> test suites (multiple test methods) and I observe that at the end I
>>>>> have
>>>>> some 11-14 such stale client sessions attempting to re-connect
>>>>> endlessly.
>>>>>
>>>>> I thank you guys in advance and hope someone has energy to help me out
>>>>> with this tough sh*t
>>>>> reinis
>>>>>
>>>>>
>>>>> LOG
>>>>> ----------------------------------------------------
>>>>> 14/07/13 11:27:47 INFO zookeeper.ClientCnxn: Opening socket connection
>>>>> to
>>>>> server 0:0:0:0:0:0:0:1/0:0:0:0:0:0:0:1:49713. Will not attempt to
>>>>> authenticate using SASL (unknown error)
>>>>> 14/07/13 11:27:47 INFO server.NIOServerCnxnFactory: Accepted socket
>>>>> connection from /0:0:0:0:0:0:0:1:50061
>>>>> 14/07/13 11:27:47 INFO zookeeper.ClientCnxn: Socket connection
>>>>> established to 0:0:0:0:0:0:0:1/0:0:0:0:0:0:0:1:49713, initiating
>>>>> session
>>>>> 14/07/13 11:27:47 DEBUG zookeeper.ClientCnxn: Session establishment
>>>>> request sent on 0:0:0:0:0:0:0:1/0:0:0:0:0:0:0:1:49713
>>>>> 14/07/13 11:27:47 DEBUG server.ZooKeeperServer: Session establishment
>>>>> request from client /0:0:0:0:0:0:0:1:50061 client's lastZxid is 0x0
>>>>> 14/07/13 11:27:47 INFO server.ZooKeeperServer: Client attempting to
>>>>> establish new session at /0:0:0:0:0:0:0:1:50061
>>>>> 14/07/13 11:27:47 TRACE server.SessionTrackerImpl: SessionTrackerImpl
>>>>> ---
>>>>> Adding session 0x1472f0ca7df0002 10000
>>>>> 14/07/13 11:27:47 TRACE server.PrepRequestProcessor:
>>>>> :Psessionid:0x1472f0ca7df0002 type:createSession cxid:0x0
>>>>> zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
>>>>> 14/07/13 11:27:47 TRACE server.SessionTrackerImpl: SessionTrackerImpl
>>>>> ---
>>>>> Existing session 0x1472f0ca7df0002 10000
>>>>> ...
>>>>> 14/07/13 11:27:47 DEBUG server.FinalRequestProcessor: Processing
>>>>> request:: sessionid:0x1472f0ca7df0002 type:createSession cxid:0x0
>>>>> zxid:0xe
>>>>> txntype:-10 reqpath:n/a
>>>>> 14/07/13 11:27:47 TRACE server.FinalRequestProcessor:
>>>>> :Esessionid:0x1472f0ca7df0002 type:createSession cxid:0x0 zxid:0xe
>>>>> txntype:-10 reqpath:n/a
>>>>> 14/07/13 11:27:47 TRACE server.SessionTrackerImpl: SessionTrackerImpl
>>>>> ---
>>>>> Existing session 0x1472f0ca7df0002 10000
>>>>> 14/07/13 11:27:47 DEBUG server.FinalRequestProcessor:
>>>>> sessionid:0x1472f0ca7df0002 type:createSession cxid:0x0 zxid:0xe
>>>>> txntype:-10 reqpath:n/a
>>>>> ...
>>>>> 14/07/13 11:27:47 INFO server.ZooKeeperServer: Established session
>>>>> 0x1472f0ca7df0002 with negotiated timeout 10000 for client
>>>>> /0:0:0:0:0:0:0:1:50061
>>>>> 14/07/13 11:27:47 TRACE zookeeper.ClientCnxnSocket: readConnectResult
>>>>> 37
>>>>> 0x[0,0,...
>>>>> 14/07/13 11:27:47 INFO zookeeper.ClientCnxn: Session establishment
>>>>> complete on server 0:0:0:0:0:0:0:1/0:0:0:0:0:0:0:1:49713, sessionid =
>>>>> 0x1472f0ca7df0002, negotiated timeout = 10000
>>>>> 14/07/13 11:27:47 DEBUG zookeeper.ZooKeeperWatcher:
>>>>> hconnection-0x1a97512e, quorum=localhost:49713,
>>>>> baseZNode=/afc60aef-1620-435e-847a-71cc4192bb22 Received ZooKeeper
>>>>> Event, type=None, state=SyncConnected, path=null
>>>>> 14/07/13 11:27:47 TRACE server.PrepRequestProcessor:
>>>>> :Psessionid:0x1472f0ca7df0002 type:exists cxid:0x1
>>>>> zxid:0xfffffffffffffffe
>>>>> txntype:unknown reqpath:/afc60aef-1620-435e-847a-71cc4192bb22/hbaseid
>>>>> ...
>>>>> 14/07/13 11:27:47 DEBUG server.FinalRequestProcessor: Processing
>>>>> request:: sessionid:0x1472f0ca7df0002 type:exists cxid:0x1
>>>>> zxid:0xfffffffffffffffe txntype:unknown reqpath:/afc60aef-1620-435e-
>>>>> 847a-71cc4192bb22/hbaseid
>>>>> 14/07/13 11:27:47 TRACE server.FinalRequestProcessor:
>>>>> :Esessionid:0x1472f0ca7df0002 type:exists cxid:0x1
>>>>> zxid:0xfffffffffffffffe
>>>>> txntype:unknown reqpath:/afc60aef-1620-435e-847a-71cc4192bb22/hbaseid
>>>>> 14/07/13 11:27:47 DEBUG zookeeper.ZooKeeperWatcher:
>>>>> hconnection-0x1a97512e-0x1472f0ca7df0002 connected
>>>>> 14/07/13 11:27:47 DEBUG server.FinalRequestProcessor:
>>>>> sessionid:0x1472f0ca7df0002 type:exists cxid:0x1
>>>>> zxid:0xfffffffffffffffe
>>>>> txntype:unknown reqpath:/afc60aef-1620-435e-847a-71cc4192bb22/hbaseid
>>>>> 14/07/13 11:27:47 DEBUG zookeeper.ClientCnxn: Reading reply
>>>>> sessionid:0x1472f0ca7df0002, packet:: clientPath:null serverPath:null
>>>>> finished:false header:: 1,3 replyHeader:: 1,14,0 request::
>>>>> '/afc60aef-1620-435e-847a-71cc4192bb22/hbaseid,F response::
>>>>> s{13,13,1405243667232,1405243667232,0,0,0,0,67,0,13}
>>>>> 14/07/13 11:27:47 TRACE server.PrepRequestProcessor:
>>>>> :Psessionid:0x1472f0ca7df0002 type:getData cxid:0x2
>>>>> zxid:0xfffffffffffffffe
>>>>> txntype:unknown reqpath:/afc60aef-1620-435e-847a-71cc4192bb22/hbaseid
>>>>> 14/07/13 11:27:47 DEBUG server.FinalRequestProcessor: Processing
>>>>> request:: sessionid:0x1472f0ca7df0002 type:getData cxid:0x2
>>>>> zxid:0xfffffffffffffffe txntype:unknown reqpath:/afc60aef-1620-435e-
>>>>> 847a-71cc4192bb22/hbaseid
>>>>> 14/07/13 11:27:47 TRACE server.FinalRequestProcessor:
>>>>> :Esessionid:0x1472f0ca7df0002 type:getData cxid:0x2
>>>>> zxid:0xfffffffffffffffe
>>>>> txntype:unknown reqpath:/afc60aef-1620-435e-847a-71cc4192bb22/hbaseid
>>>>> 14/07/13 11:27:47 DEBUG server.FinalRequestProcessor:
>>>>> sessionid:0x1472f0ca7df0002 type:getData cxid:0x2
>>>>> zxid:0xfffffffffffffffe
>>>>> txntype:unknown reqpath:/afc60aef-1620-435e-847a-71cc4192bb22/hbaseid
>>>>> 14/07/13 11:27:47 DEBUG zookeeper.ClientCnxn: Reading reply
>>>>> sessionid:0x1472f0ca7df0002, packet:: clientPath:null serverPath:null
>>>>> finished:false header:: 2,4 replyHeader:: 2,14,0 request::
>>>>> '/afc60aef-1620-435e-847a-71cc4192bb22/hbaseid,F response:: #
>>>>> ffffffff000146d61737465723a34393939323d6c467c3affffff86fffff
>>>>> fc9ffffff8250425546a2435396136323662622d393330312d343763332d
>>>>> 616462622d626466366436323365646639,s{13,13,1405243667232,1405243667232,0,0,0,0,67,0,13}
>>>>>
>>>>>
>>>>> 14/07/13 11:27:47 TRACE zookeeper.ZKUtil: hconnection-0x1a97512e-
>>>>> 0x1472f0ca7df0002,
>>>>> quorum=localhost:49713, baseZNode=/afc60aef-1620-435e-
>>>>> 847a-71cc4192bb22
>>>>> Retrieved 42 byte(s) of data from znode /afc60aef-1620-435e-847a-
>>>>> 71cc4192bb22/hbaseid;
>>>>> data=PBUF\x0A$59a626bb-9301-47c3-a...
>>>>> ...
>>>>> # Number of transactions are being processed normaly, the final
>>>>> transaction is cxid:0x18
>>>>> 14/07/13 11:27:51 TRACE server.PrepRequestProcessor:
>>>>> :Psessionid:0x1472f0ca7df0002 type:getData cxid:0x18
>>>>> zxid:0xfffffffffffffffe txntype:unknown reqpath:/afc60aef-1620-435e-
>>>>> 847a-71cc4192bb22/meta-region-server
>>>>> 14/07/13 11:27:51 DEBUG server.FinalRequestProcessor: Processing
>>>>> request:: sessionid:0x1472f0ca7df0002 type:getData cxid:0x18
>>>>> zxid:0xfffffffffffffffe txntype:unknown reqpath:/afc60aef-1620-435e-
>>>>> 847a-71cc4192bb22/meta-region-server
>>>>> 14/07/13 11:27:51 TRACE server.FinalRequestProcessor:
>>>>> :Esessionid:0x1472f0ca7df0002 type:getData cxid:0x18
>>>>> zxid:0xfffffffffffffffe txntype:unknown reqpath:/afc60aef-1620-435e-
>>>>> 847a-71cc4192bb22/meta-region-server
>>>>> 14/07/13 11:27:51 DEBUG server.FinalRequestProcessor:
>>>>> sessionid:0x1472f0ca7df0002 type:getData cxid:0x18
>>>>> zxid:0xfffffffffffffffe
>>>>> txntype:unknown reqpath:/afc60aef-1620-435e-
>>>>> 847a-71cc4192bb22/meta-region-server
>>>>> 14/07/13 11:27:51 DEBUG zookeeper.ClientCnxn: Reading reply
>>>>> sessionid:0x1472f0ca7df0002, packet:: clientPath:null serverPath:null
>>>>> finished:false header:: 24,4 replyHeader:: 24,70,0 request::
>>>>> '/afc60aef-1620-435e-847a-71cc4192bb22/meta-region-server,F
>>>>> response:: #
>>>>> ffffffff0001a726567696f6e7365727665723a353030323072ffffff9cf
>>>>> fffffebffffffc62dffffffb8ffffffc14050425546a20a13616972666f7
>>>>> 26365312e667269747a2e626f7810ffffffe4ffffff86318ffffffc8ffff
>>>>> ffd6ffffffb2fffffff8fffffff228100,s{38,38,1405243668798,1405243668798,0,0,0,0,71,0,38}
>>>>>
>>>>>
>>>>> 14/07/13 11:27:51 TRACE zookeeper.ZKUtil: hconnection-0x1a97512e-
>>>>> 0x1472f0ca7df0002,
>>>>> quorum=localhost:49713, baseZNode=/afc60aef-1620-435e-
>>>>> 847a-71cc4192bb22
>>>>> Retrieved 40 byte(s) of data from znode /afc60aef-1620-435e-847a-
>>>>> 71cc4192bb22/meta-region-server; data=airforce1.fritz.box,
>>>>> 50020,1405243665224
>>>>> ...
>>>>> # Pings ok too!
>>>>> 14/07/13 11:27:54 DEBUG server.FinalRequestProcessor: Processing
>>>>> request:: sessionid:0x1472f0ca7df0002 type:ping cxid:0xfffffffffffffffe
>>>>> zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
>>>>> 14/07/13 11:27:54 DEBUG server.FinalRequestProcessor:
>>>>> sessionid:0x1472f0ca7df0002 type:ping cxid:0xfffffffffffffffe
>>>>> zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
>>>>> 14/07/13 11:27:54 DEBUG zookeeper.ClientCnxn: Got ping response for
>>>>> sessionid: 0x1472f0ca7df0002 after 6ms
>>>>> ...
>>>>> 14/07/13 11:27:57 DEBUG server.FinalRequestProcessor: Processing
>>>>> request:: sessionid:0x1472f0ca7df0002 type:ping cxid:0xfffffffffffffffe
>>>>> zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
>>>>> 14/07/13 11:27:57 DEBUG server.FinalRequestProcessor:
>>>>> sessionid:0x1472f0ca7df0002 type:ping cxid:0xfffffffffffffffe
>>>>> zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a
>>>>> 14/07/13 11:27:57 TRACE server.PrepRequestProcessor:
>>>>> :Psessionid:0x1472f0ca7df0001 type:getChildren cxid:0x38
>>>>> zxid:0xfffffffffffffffe txntype:unknown reqpath:/afc60aef-1620-435e-
>>>>> 847a-71cc4192bb22/replication/rs/airforce1.fritz.box,50020,1405243665224
>>>>>
>>>>> 14/07/13 11:27:57 DEBUG zookeeper.ClientCnxn: Got ping response for
>>>>> sessionid: 0x1472f0ca7df0002 after 2ms
>>>>> ...
>>>>> # Shutdown is starting!
>>>>> 14/07/13 11:27:57 INFO server.NIOServerCnxn: Closed socket connection
>>>>> for
>>>>> client /0:0:0:0:0:0:0:1:50061 which had sessionid 0x1472f0ca7df0002
>>>>> 14/07/13 11:27:57 INFO zookeeper.ClientCnxn: Unable to read additional
>>>>> data from server sessionid 0x1472f0ca7df0002, likely server has closed
>>>>> socket, closing socket connection and attempting reconnect
>>>>> 14/07/13 11:27:57 INFO server.NIOServerCnxnFactory: NIOServerCnxn
>>>>> factory
>>>>> exited run method
>>>>> 14/07/13 11:27:57 INFO server.ZooKeeperServer: shutting down
>>>>> 14/07/13 11:27:57 INFO server.SessionTrackerImpl: Shutting down
>>>>> 14/07/13 11:27:57 TRACE server.SessionTrackerImpl: Shutdown
>>>>> SessionTrackerImpl!
>>>>> 14/07/13 11:27:57 INFO server.PrepRequestProcessor: Shutting down
>>>>> 14/07/13 11:27:57 INFO server.SyncRequestProcessor: Shutting down
>>>>> 14/07/13 11:27:57 TRACE server.PrepRequestProcessor: :Psessionid:0x0
>>>>> type:notification cxid:0x0 zxid:0xfffffffffffffffe txntype:unknown
>>>>> reqpath:n/a
>>>>> 14/07/13 11:27:57 INFO server.PrepRequestProcessor:
>>>>> PrepRequestProcessor
>>>>> exited loop!
>>>>> 14/07/13 11:27:57 INFO server.SyncRequestProcessor:
>>>>> SyncRequestProcessor
>>>>> exited!
>>>>> 14/07/13 11:27:57 INFO server.FinalRequestProcessor: shutdown of
>>>>> request
>>>>> processor complete
>>>>> 14/07/13 11:27:57 TRACE zookeeper.ClientCnxnSocketNIO: Doing client
>>>>> selector close
>>>>> 14/07/13 11:27:57 TRACE zookeeper.ClientCnxnSocketNIO: Closed client
>>>>> selector
>>>>> 14/07/13 11:27:57 TRACE zookeeper.ClientCnxn: SendThread exitedloop.
>>>>> ...
>>>>> 14/07/13 11:27:57 DEBUG zookeeper.ZooKeeperWatcher:
>>>>> hconnection-0x1a97512e-0x1472f0ca7df0002, quorum=localhost:49713,
>>>>> baseZNode=/afc60aef-1620-435e-847a-71cc4192bb22 Received ZooKeeper
>>>>> Event, type=None, state=Disconnected, path=null
>>>>> 14/07/13 11:27:57 DEBUG zookeeper.ZooKeeperWatcher:
>>>>> hconnection-0x56db0aff-0x1472f0ca7df0007, quorum=localhost:49713,
>>>>> baseZNode=/afc60aef-1620-435e-847a-71cc4192bb22 Received ZooKeeper
>>>>> Event, type=None, state=Disconnected, path=null
>>>>>
>>>>> # Is it interesting, how ZooKeeperWatcher says 'ignoring' in the log
>>>>> message bellow?
>>>>> 14/07/13 11:27:57 DEBUG zookeeper.ZooKeeperWatcher:
>>>>> hconnection-0x1a97512e-0x1472f0ca7df0002, quorum=localhost:49713,
>>>>> baseZNode=/afc60aef-1620-435e-847a-71cc4192bb22 Received Disconnected
>>>>> from ZooKeeper, ignoring
>>>>> 14/07/13 11:27:57 DEBUG zookeeper.ZooKeeperWatcher:
>>>>> hconnection-0x56db0aff-0x1472f0ca7df0007, quorum=localhost:49713,
>>>>> baseZNode=/afc60aef-1620-435e-847a-71cc4192bb22 Received Disconnected
>>>>> from ZooKeeper, ignoring
>>>>> ...
>>>>> # from now on this session appears to be stale and attempts to
>>>>> re-connect
>>>>> until JVM is shutdown!
>>>>> 14/07/13 11:27:59 WARN zookeeper.ClientCnxn: Session 0x1472f0ca7df0002
>>>>> for server null, unexpected error, closing socket connection and
>>>>> attempting
>>>>> reconnect
>>>>> java.net.ConnectException: Connection refused: no further information
>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>> SocketChannelImpl.java:692)
>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>> ClientCnxnSocketNIO.java:350)
>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>> ClientCnxn.java:1075)
>>>>> 14/07/13 11:27:59 DEBUG zookeeper.ClientCnxnSocketNIO: Ignoring
>>>>> exception
>>>>> during shutdown input
>>>>> java.nio.channels.ClosedChannelException
>>>>> at sun.nio.ch.SocketChannelImpl.shutdownInput(
>>>>> SocketChannelImpl.java:755)
>>>>> at sun.nio.ch.SocketAdaptor.shutdownInput(SocketAdaptor.java:421)
>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.cleanup(
>>>>> ClientCnxnSocketNIO.java:189)
>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.cleanup(
>>>>> ClientCnxn.java:1164)
>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>> ClientCnxn.java:1104)
>>>>> ...
>>>>> 14/07/13 11:28:02 WARN zookeeper.ClientCnxn: Session 0x1472f0ca7df0002
>>>>> for server null, unexpected error, closing socket connection and
>>>>> attempting
>>>>> reconnect
>>>>> java.net.ConnectException: Connection refused: no further information
>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>> SocketChannelImpl.java:692)
>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>> ClientCnxnSocketNIO.java:350)
>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>> ClientCnxn.java:1075)
>>>>> 14/07/13 11:28:02 DEBUG zookeeper.ClientCnxnSocketNIO: Ignoring
>>>>> exception
>>>>> during shutdown input
>>>>> java.nio.channels.ClosedChannelException
>>>>> at sun.nio.ch.SocketChannelImpl.shutdownInput(
>>>>> SocketChannelImpl.java:755)
>>>>> at sun.nio.ch.SocketAdaptor.shutdownInput(SocketAdaptor.java:421)
>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.cleanup(
>>>>> ClientCnxnSocketNIO.java:189)
>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.cleanup(
>>>>> ClientCnxn.java:1164)
>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>> ClientCnxn.java:1104)
>>>>> 14/07/13 11:28:02 DEBUG zookeeper.ClientCnxnSocketNIO: Ignoring
>>>>> exception
>>>>> during shutdown output
>>>>> java.nio.channels.ClosedChannelException
>>>>> at sun.nio.ch.SocketChannelImpl.shutdownOutput(
>>>>> SocketChannelImpl.java:772)
>>>>> at sun.nio.ch.SocketAdaptor.shutdownOutput(SocketAdaptor.
>>>>> java:429)
>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.cleanup(
>>>>> ClientCnxnSocketNIO.java:196)
>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.cleanup(
>>>>> ClientCnxn.java:1164)
>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>> ClientCnxn.java:1104)
>>>>>
>>>>>
>>>>> On 13.07.2014 06:34, Esteban Gutierrez wrote:
>>>>>
>>>>> Hello Renis,
>>>>>>
>>>>>> Is this happening every time the test runs? I've seen this happening
>>>>>> few
>>>>>> times when the test is running with a very small heap or the test is
>>>>>> running on VMs and the Java VM or the local file system are unstable
>>>>>> due
>>>>>> load on the virtualized environment. Have you looked into increasing
>>>>>> the
>>>>>> heap or the the load of the environment where you are running this
>>>>>> test?
>>>>>>
>>>>>> cheers,
>>>>>> esteban.
>>>>>>
>>>>>> --
>>>>>> Cloudera, Inc.
>>>>>>
>>>>>> On Fri, Jul 11, 2014 at 3:40 AM, Reinis Vicups <hb...@orbit-x.de>
>>>>>> wrote:
>>>>>>
>>>>>> Hi,
>>>>>>
>>>>>>> I have built a test-harness that I am using to test integration with
>>>>>>> the
>>>>>>> help of HBaseTestingUtility. The code bellow although allows me to
>>>>>>> run
>>>>>>> tests, it has one very annoying side effect - some of the sessions
>>>>>>> woun't
>>>>>>> get closed after I shutdown the minicluster, thus causing lag and
>>>>>>> delayed
>>>>>>> test execution.
>>>>>>>
>>>>>>> I would be very grateful to anyone who could give me tip on how to
>>>>>>> fix
>>>>>>> this.
>>>>>>>
>>>>>>> merci
>>>>>>>
>>>>>>> reinis
>>>>>>>
>>>>>>> Test Suite Code:
>>>>>>> ------------------------------------------------------------
>>>>>>> ----------------------------------
>>>>>>>
>>>>>>> abstract trait LocalHBaseSuite extends BeforeAndAfterAll {
>>>>>>>
>>>>>>> this: Suite =>
>>>>>>> @transient lazy val traitLog: Logger =
>>>>>>> LoggerFactory.getLogger(this.
>>>>>>> getClass.getName)
>>>>>>>
>>>>>>> var localHBase: HBaseTestingUtility = null
>>>>>>> var localFileSystem: FileSystem = null
>>>>>>>
>>>>>>> override def beforeAll = {
>>>>>>> traitLog.warn("{} before beforeAll", this.getClass.getName)
>>>>>>> //<-
>>>>>>> see
>>>>>>> in log
>>>>>>>
>>>>>>> // load snappy.dll found in hadoop bin directory
>>>>>>> val hadoopHomePath = file.Paths.get(ClassLoader.
>>>>>>> getSystemResource("hadoop").toURI)
>>>>>>> addJavaLibraryPath(file.Paths.get(hadoopHomePath.toAbsolutePath.toString,
>>>>>>>
>>>>>>>
>>>>>>> "bin").toString)
>>>>>>> System.loadLibrary("snappy")
>>>>>>> System.setProperty("hadoop.home.dir",
>>>>>>> hadoopHomePath.toAbsolutePath.
>>>>>>> toString)
>>>>>>>
>>>>>>> localHBase = new HBaseTestingUtility()
>>>>>>>
>>>>>>> val localConfig = localHBase.getConfiguration
>>>>>>> localConfig.set("mapreduce.framework.name", "local")
>>>>>>> localConfig.set("dfs.permissions.enabled", "false")
>>>>>>> localConfig.set("fs.file.impl.disable.cache", "true")
>>>>>>>
>>>>>>> localHBase.startMiniCluster()
>>>>>>> localFileSystem = localHBase.getTestFileSystem
>>>>>>>
>>>>>>> traitLog.warn("{} after beforeAll", this.getClass.getName) //<-
>>>>>>> see in
>>>>>>> log
>>>>>>> }
>>>>>>>
>>>>>>> override def afterAll = {
>>>>>>> traitLog.warn("{} before afterAll", this.getClass.getName) //<-
>>>>>>> see in
>>>>>>> log
>>>>>>> localHBase.shutdownMiniCluster()
>>>>>>> traitLog.warn("{} after afterAll", this.getClass.getName) //<-
>>>>>>> see
>>>>>>> in
>>>>>>> log
>>>>>>> localHBase = null
>>>>>>> }
>>>>>>>
>>>>>>> /**
>>>>>>> * Adds the given path to the java.library.path system property
>>>>>>> */
>>>>>>> private def addJavaLibraryPath(libraryPath: String): Unit = {
>>>>>>> val usrPathsField: Field = classOf[ClassLoader].
>>>>>>> getDeclaredField("usr_paths")
>>>>>>> usrPathsField.setAccessible(true)
>>>>>>> val newPaths = usrPathsField.get(null).
>>>>>>> asInstanceOf[Array[String]]
>>>>>>> :+
>>>>>>> libraryPath
>>>>>>> usrPathsField.set(null, newPaths.asInstanceOf[Array[String]])
>>>>>>> }
>>>>>>> }
>>>>>>>
>>>>>>>
>>>>>>> Resulting Log-File:
>>>>>>> -------------------------------------------
>>>>>>>
>>>>>>> [info] Loading project definition from D:\git\myproj\project
>>>>>>> [info] Set current project to myproj (in build file:/D:/git/myproj/)
>>>>>>> [success] Total time: 1 s, completed 11.07.2014 11:00:53
>>>>>>> [info] Compiling 1 Scala source to D:\git\myproj\etl\target\
>>>>>>> scala-2.10\test-classes...
>>>>>>> [info] ScalaTest
>>>>>>> [info] Run completed in 42 milliseconds.
>>>>>>> [info] Total number of tests run: 0
>>>>>>> [info] Suites: completed 0, aborted 0
>>>>>>> [info] Tests: succeeded 0, failed 0, canceled 0, ignored 0, pending 0
>>>>>>> [info] No tests were executed.
>>>>>>> [info] Passed: Total 0, Failed 0, Errors 0, Passed 0
>>>>>>> [info] No tests to run for myproj-Root/it:test
>>>>>>> [info] ScalaTest
>>>>>>> [info] Run completed in 25 milliseconds.
>>>>>>> [info] Total number of tests run: 0
>>>>>>> [info] Suites: completed 0, aborted 0
>>>>>>> [info] Tests: succeeded 0, failed 0, canceled 0, ignored 0, pending 0
>>>>>>> [info] No tests were executed.
>>>>>>> [info] Passed: Total 0, Failed 0, Errors 0, Passed 0
>>>>>>> [info] No tests to run for myproj-API/it:test
>>>>>>> [info] VectorizeTicketSolutionLogMRJobTest:
>>>>>>> 14/07/11 11:01:01 WARN solutionlog.VectorizeTicketSolutionLogMRJo
>>>>>>> bTest:
>>>>>>> com.myproj.quantify.ticket.solutionlog.
>>>>>>> VectorizeTicketSolutionLogMRJobTest
>>>>>>>
>>>>>>> before beforeAll
>>>>>>> Formatting using clusterid: testClusterID
>>>>>>> 14/07/11 11:01:03 WARN impl.MetricsConfig: Cannot locate
>>>>>>> configuration:
>>>>>>> tried hadoop-metrics2-namenode.properties,hadoop-metrics2.properties
>>>>>>> 14/07/11 11:01:04 WARN server.AuthenticationFilter:
>>>>>>> 'signature.secret'
>>>>>>> configuration not set, using a random value as secret
>>>>>>> 14/07/11 11:01:06 WARN hbase.ZNodeClearer: Environment variable
>>>>>>> HBASE_ZNODE_FILE not set; znodes will not be cleared on crash by
>>>>>>> start
>>>>>>> scripts (Longer MTTR!)
>>>>>>> 14/07/11 11:01:08 WARN hbase.ZNodeClearer: Environment variable
>>>>>>> HBASE_ZNODE_FILE not set; znodes will not be cleared on crash by
>>>>>>> start
>>>>>>> scripts (Longer MTTR!)
>>>>>>> 14/07/11 11:01:09 WARN zookeeper.RecoverableZooKeeper: Node
>>>>>>> /hbase/meta-region-server already deleted, retry=false
>>>>>>> 14/07/11 11:01:10 WARN solutionlog.VectorizeTicketSolutionLogMRJo
>>>>>>> bTest:
>>>>>>> com.myproj.quantify.ticket.solutionlog.
>>>>>>> VectorizeTicketSolutionLogMRJobTest
>>>>>>>
>>>>>>> after beforeAll
>>>>>>> 14/07/11 11:01:10 WARN hbase.HBaseCommonTestingUtility: close()
>>>>>>> called
>>>>>>> on
>>>>>>> HBaseAdmin instance returned from HBaseTestingUtility.
>>>>>>> getHBaseAdmin()
>>>>>>> 14/07/11 11:01:12 WARN mapreduce.JobSubmitter: No job jar file set.
>>>>>>> User
>>>>>>> classes may not be found. See Job or Job#setJar(String).
>>>>>>> 14/07/11 11:01:12 WARN conf.Configuration: file:/D:/git/myproj/etl/
>>>>>>> target/test-data/1e71ff51-76c5-45e9-8d44-1249dbff3055/
>>>>>>> hadoop/mapreduce-jobtracker-staging-root-dir/
>>>>>>> user467204862/.staging/job_local467204862_0001/job.xml:an
>>>>>>> attempt to override final parameter: mapreduce.job.end-
>>>>>>> notification.max.retry.interval; Ignoring.
>>>>>>> 14/07/11 11:01:12 WARN conf.Configuration: file:/D:/git/myproj/etl/
>>>>>>> target/test-data/1e71ff51-76c5-45e9-8d44-1249dbff3055/
>>>>>>> hadoop/mapreduce-jobtracker-staging-root-dir/
>>>>>>> user467204862/.staging/job_local467204862_0001/job.xml:an
>>>>>>> attempt to override final parameter: mapreduce.job.end-
>>>>>>> notification.max.attempts;
>>>>>>> Ignoring.
>>>>>>> 14/07/11 11:01:12 WARN conf.Configuration: file:/D:/git/myproj/etl/
>>>>>>> target/test-data/1e71ff51-76c5-45e9-8d44-1249dbff3055/
>>>>>>> hadoop_tmp/mapred/local/localRunner/user/job_
>>>>>>> local467204862_0001/job_local467204862_0001.xml:an
>>>>>>>
>>>>>>> attempt to override final parameter: mapreduce.job.end-
>>>>>>> notification.max.retry.interval; Ignoring.
>>>>>>> 14/07/11 11:01:12 WARN conf.Configuration: file:/D:/git/myproj/etl/
>>>>>>> target/test-data/1e71ff51-76c5-45e9-8d44-1249dbff3055/
>>>>>>> hadoop_tmp/mapred/local/localRunner/user/job_
>>>>>>> local467204862_0001/job_local467204862_0001.xml:an
>>>>>>>
>>>>>>> attempt to override final parameter: mapreduce.job.end-
>>>>>>> notification.max.attempts;
>>>>>>> Ignoring.
>>>>>>> [info] - should validate that VectorizeTicketSolutionLogMRJob
>>>>>>> generates
>>>>>>> correct HBase table
>>>>>>> 14/07/11 11:01:13 WARN solutionlog.VectorizeTicketSolutionLogMRJo
>>>>>>> bTest:
>>>>>>> com.myproj.quantify.ticket.solutionlog.
>>>>>>> VectorizeTicketSolutionLogMRJobTest
>>>>>>>
>>>>>>> after table close
>>>>>>> 14/07/11 11:01:13 WARN solutionlog.VectorizeTicketSolutionLogMRJo
>>>>>>> bTest:
>>>>>>> com.myproj.quantify.ticket.solutionlog.
>>>>>>> VectorizeTicketSolutionLogMRJobTest
>>>>>>>
>>>>>>> before afterAll
>>>>>>> 14/07/11 11:01:13 WARN server.NIOServerCnxn: caught end of stream
>>>>>>> exception
>>>>>>> EndOfStreamException: Unable to read additional data from client
>>>>>>> sessionid
>>>>>>> 0x14724a78b320003, likely client has closed socket
>>>>>>> at org.apache.zookeeper.server.NIOServerCnxn.doIO(
>>>>>>> NIOServerCnxn.java:220)
>>>>>>> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(
>>>>>>> NIOServerCnxnFactory.java:208)
>>>>>>> at java.lang.Thread.run(Thread.java:722)
>>>>>>> 14/07/11 11:01:18 WARN server.NIOServerCnxn: caught end of stream
>>>>>>> exception
>>>>>>> EndOfStreamException: Unable to read additional data from client
>>>>>>> sessionid
>>>>>>> 0x14724a78b320004, likely client has closed socket
>>>>>>> at org.apache.zookeeper.server.NIOServerCnxn.doIO(
>>>>>>> NIOServerCnxn.java:220)
>>>>>>> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(
>>>>>>> NIOServerCnxnFactory.java:208)
>>>>>>> at java.lang.Thread.run(Thread.java:722)
>>>>>>> 14/07/11 11:01:18 ERROR client.HConnectionManager: Connection not
>>>>>>> found
>>>>>>> in
>>>>>>> the list, can't delete it (connection key=HConnectionKey{properties=
>>>>>>> {hbase.rpc.timeout=60000,
>>>>>>> hbase.zookeeper.property.clientPort=63640, hbase.client.pause=100,
>>>>>>> zookeeper.znode.parent=/hbase, hbase.client.retries.number=350,
>>>>>>> hbase.zookeeper.quorum=localhost}, username='user'}). May be the key
>>>>>>> was
>>>>>>> modified?
>>>>>>> java.lang.Exception
>>>>>>> at org.apache.hadoop.hbase.client.HConnectionManager.
>>>>>>> deleteConnection(
>>>>>>> HConnectionManager.java:466)
>>>>>>> at org.apache.hadoop.hbase.client.HConnectionManager.
>>>>>>> deleteConnection(
>>>>>>> HConnectionManager.java:402)
>>>>>>> at org.apache.hadoop.hbase.replication.master.
>>>>>>> ReplicationLogCleaner.stop(ReplicationLogCleaner.java:142)
>>>>>>> at org.apache.hadoop.hbase.master.cleaner.CleanerChore.
>>>>>>> cleanup(CleanerChore.java:276)
>>>>>>> at org.apache.hadoop.hbase.Chore.run(Chore.java:94)
>>>>>>> at java.lang.Thread.run(Thread.java:722)
>>>>>>> 14/07/11 11:01:19 WARN datanode.DirectoryScanner: DirectoryScanner:
>>>>>>> shutdown has been called
>>>>>>> 14/07/11 11:01:19 WARN datanode.DataNode: BPOfferService for Block
>>>>>>> pool
>>>>>>> BP-466654724-192.168.178.20-1405069263037 (Datanode Uuid
>>>>>>> cc3e8ece-62e2-4877-92fe-8fdec4d1179f) service to /127.0.0.1:61391
>>>>>>> interrupted
>>>>>>> 14/07/11 11:01:19 WARN datanode.DataNode: Ending block pool service
>>>>>>> for:
>>>>>>> Block pool BP-466654724-192.168.178.20-1405069263037 (Datanode Uuid
>>>>>>> cc3e8ece-62e2-4877-92fe-8fdec4d1179f) service to /127.0.0.1:61391
>>>>>>> 14/07/11 11:01:19 WARN blockmanagement.DecommissionManager: Monitor
>>>>>>> interrupted: java.lang.InterruptedException: sleep interrupted
>>>>>>> 14/07/11 11:01:19 WARN solutionlog.VectorizeTicketSolutionLogMRJo
>>>>>>> bTest:
>>>>>>> com.myproj.quantify.ticket.solutionlog.
>>>>>>> VectorizeTicketSolutionLogMRJobTest
>>>>>>>
>>>>>>> after afterAll
>>>>>>> 14/07/11 11:01:19 WARN similarity.TicketTextSimilarityPreference
>>>>>>> MRJobTest:
>>>>>>> com.myproj.similarity.TicketTextSimilarityPreferenceMRJobTest before
>>>>>>> beforeAll
>>>>>>> [info] TicketTextSimilarityPreferenceMRJobTest:
>>>>>>> 14/07/11 11:01:19 WARN hbase.HBaseCommonTestingUtility:
>>>>>>> hadoop.tmp.dir
>>>>>>> property value differs in configuration and system:
>>>>>>> Configuration=/tmp/hadoop-user while System=D:/git/myproj/etl/
>>>>>>> target/test-data/1e71ff51-76c5-45e9-8d44-1249dbff3055/hadoop_tmp
>>>>>>> Erasing
>>>>>>> configuration value by system value.
>>>>>>> Formatting using clusterid: testClusterID
>>>>>>> 14/07/11 11:01:19 WARN zookeeper.ClientCnxn: Session
>>>>>>> 0x14724a78b320002
>>>>>>> for
>>>>>>> server null, unexpected error, closing socket connection and
>>>>>>> attempting
>>>>>>> reconnect
>>>>>>> java.net.ConnectException: Connection refused: no further information
>>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>>> SocketChannelImpl.java:692)
>>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>>> ClientCnxn.java:1075)
>>>>>>> 14/07/11 11:01:20 WARN server.AuthenticationFilter:
>>>>>>> 'signature.secret'
>>>>>>> configuration not set, using a random value as secret
>>>>>>> 14/07/11 11:01:20 WARN zookeeper.ClientCnxn: Session
>>>>>>> 0x14724a78b320007
>>>>>>> for
>>>>>>> server null, unexpected error, closing socket connection and
>>>>>>> attempting
>>>>>>> reconnect
>>>>>>> java.net.ConnectException: Connection refused: no further information
>>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>>> SocketChannelImpl.java:692)
>>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>>> ClientCnxn.java:1075)
>>>>>>> 14/07/11 11:01:21 WARN hbase.ZNodeClearer: Environment variable
>>>>>>> HBASE_ZNODE_FILE not set; znodes will not be cleared on crash by
>>>>>>> start
>>>>>>> scripts (Longer MTTR!)
>>>>>>> 14/07/11 11:01:22 WARN zookeeper.ClientCnxn: Session
>>>>>>> 0x14724a78b320002
>>>>>>> for
>>>>>>> server null, unexpected error, closing socket connection and
>>>>>>> attempting
>>>>>>> reconnect
>>>>>>> java.net.ConnectException: Connection refused: no further information
>>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>>> SocketChannelImpl.java:692)
>>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>>> ClientCnxn.java:1075)
>>>>>>> 14/07/11 11:01:22 WARN zookeeper.ClientCnxn: Session
>>>>>>> 0x14724a78b320007
>>>>>>> for
>>>>>>> server null, unexpected error, closing socket connection and
>>>>>>> attempting
>>>>>>> reconnect
>>>>>>> java.net.ConnectException: Connection refused: no further information
>>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>>> SocketChannelImpl.java:692)
>>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>>> ClientCnxn.java:1075)
>>>>>>> 14/07/11 11:01:23 WARN regionserver.HRegionServer: reportForDuty
>>>>>>> failed;
>>>>>>> sleeping and then retrying.
>>>>>>> 14/07/11 11:01:23 WARN zookeeper.ClientCnxn: Session
>>>>>>> 0x14724a78b320002
>>>>>>> for
>>>>>>> server null, unexpected error, closing socket connection and
>>>>>>> attempting
>>>>>>> reconnect
>>>>>>> java.net.ConnectException: Connection refused: no further information
>>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>>> SocketChannelImpl.java:692)
>>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>>> ClientCnxn.java:1075)
>>>>>>> 14/07/11 11:01:24 WARN zookeeper.ClientCnxn: Session
>>>>>>> 0x14724a78b320007
>>>>>>> for
>>>>>>> server null, unexpected error, closing socket connection and
>>>>>>> attempting
>>>>>>> reconnect
>>>>>>> java.net.ConnectException: Connection refused: no further information
>>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>>> SocketChannelImpl.java:692)
>>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>>> ClientCnxn.java:1075)
>>>>>>> 14/07/11 11:01:26 WARN hbase.ZNodeClearer: Environment variable
>>>>>>> HBASE_ZNODE_FILE not set; znodes will not be cleared on crash by
>>>>>>> start
>>>>>>> scripts (Longer MTTR!)
>>>>>>> 14/07/11 11:01:26 WARN zookeeper.ClientCnxn: Session
>>>>>>> 0x14724a78b320002
>>>>>>> for
>>>>>>> server null, unexpected error, closing socket connection and
>>>>>>> attempting
>>>>>>> reconnect
>>>>>>> java.net.ConnectException: Connection refused: no further information
>>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>>> SocketChannelImpl.java:692)
>>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>>> ClientCnxn.java:1075)
>>>>>>> 14/07/11 11:01:27 WARN zookeeper.ClientCnxn: Session
>>>>>>> 0x14724a78b320007
>>>>>>> for
>>>>>>> server null, unexpected error, closing socket connection and
>>>>>>> attempting
>>>>>>> reconnect
>>>>>>> java.net.ConnectException: Connection refused: no further information
>>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>>> SocketChannelImpl.java:692)
>>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>>> ClientCnxn.java:1075)
>>>>>>> 14/07/11 11:01:27 WARN zookeeper.RecoverableZooKeeper: Node
>>>>>>> /hbase/meta-region-server already deleted, retry=false
>>>>>>> 14/07/11 11:01:28 WARN zookeeper.ClientCnxn: Session
>>>>>>> 0x14724a78b320002
>>>>>>> for
>>>>>>> server null, unexpected error, closing socket connection and
>>>>>>> attempting
>>>>>>> reconnect
>>>>>>> java.net.ConnectException: Connection refused: no further information
>>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>>> SocketChannelImpl.java:692)
>>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>>> ClientCnxn.java:1075)
>>>>>>> 14/07/11 11:01:28 WARN zookeeper.ClientCnxn: Session
>>>>>>> 0x14724a78b320007
>>>>>>> for
>>>>>>> server null, unexpected error, closing socket connection and
>>>>>>> attempting
>>>>>>> reconnect
>>>>>>> java.net.ConnectException: Connection refused: no further information
>>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>>> SocketChannelImpl.java:692)
>>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>>> ClientCnxn.java:1075)
>>>>>>> 14/07/11 11:01:28 WARN similarity.TicketTextSimilarityPreference
>>>>>>> MRJobTest:
>>>>>>> com.myproj.similarity.TicketTextSimilarityPreferenceMRJobTest after
>>>>>>> beforeAll
>>>>>>> 14/07/11 11:01:28 WARN hbase.HBaseCommonTestingUtility: close()
>>>>>>> called
>>>>>>> on
>>>>>>> HBaseAdmin instance returned from HBaseTestingUtility.
>>>>>>> getHBaseAdmin()
>>>>>>> 14/07/11 11:01:30 WARN mapreduce.JobSubmitter: No job jar file set.
>>>>>>> User
>>>>>>> classes may not be found. See Job or Job#setJar(String).
>>>>>>> 14/07/11 11:01:30 WARN conf.Configuration: file:/D:/git/myproj/etl/
>>>>>>> target/test-data/c85b7f3b-4e4b-40b4-a434-a45cecc9cba8/
>>>>>>> hadoop/mapreduce-jobtracker-staging-root-dir/user1872843153/.staging/job_
>>>>>>>
>>>>>>>
>>>>>>> local1872843153_0002/job.xml:an attempt to override final parameter:
>>>>>>> mapreduce.job.end-notification.max.retry.interval; Ignoring.
>>>>>>> 14/07/11 11:01:30 WARN conf.Configuration: file:/D:/git/myproj/etl/
>>>>>>> target/test-data/c85b7f3b-4e4b-40b4-a434-a45cecc9cba8/
>>>>>>> hadoop/mapreduce-jobtracker-staging-root-dir/user1872843153/.staging/job_
>>>>>>>
>>>>>>>
>>>>>>> local1872843153_0002/job.xml:an attempt to override final parameter:
>>>>>>> mapreduce.job.end-notification.max.attempts; Ignoring.
>>>>>>> 14/07/11 11:01:30 WARN conf.Configuration: file:/D:/git/myproj/etl/
>>>>>>> target/test-data/c85b7f3b-4e4b-40b4-a434-a45cecc9cba8/
>>>>>>> mapred_local/localRunner/user/job_local1872843153_0002/job_local1872843153_0002.xml:an
>>>>>>>
>>>>>>>
>>>>>>> attempt to override final parameter: mapreduce.job.end-
>>>>>>> notification.max.retry.interval; Ignoring.
>>>>>>> 14/07/11 11:01:30 WARN conf.Configuration: file:/D:/git/myproj/etl/
>>>>>>> target/test-data/c85b7f3b-4e4b-40b4-a434-a45cecc9cba8/
>>>>>>> mapred_local/localRunner/user/job_local1872843153_0002/job_local1872843153_0002.xml:an
>>>>>>>
>>>>>>>
>>>>>>> attempt to override final parameter: mapreduce.job.end-
>>>>>>> notification.max.attempts;
>>>>>>> Ignoring.
>>>>>>> 14/07/11 11:01:31 WARN zookeeper.ClientCnxn: Session
>>>>>>> 0x14724a78b320002
>>>>>>> for
>>>>>>> server null, unexpected error, closing socket connection and
>>>>>>> attempting
>>>>>>> reconnect
>>>>>>> java.net.ConnectException: Connection refused: no further information
>>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>>> SocketChannelImpl.java:692)
>>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>>> ClientCnxn.java:1075)
>>>>>>> 14/07/11 11:01:31 WARN zookeeper.ClientCnxn: Session
>>>>>>> 0x14724a78b320007
>>>>>>> for
>>>>>>> server null, unexpected error, closing socket connection and
>>>>>>> attempting
>>>>>>> reconnect
>>>>>>> java.net.ConnectException: Connection refused: no further information
>>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>>> SocketChannelImpl.java:692)
>>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>>> ClientCnxn.java:1075)
>>>>>>> 14/07/11 11:01:32 WARN zookeeper.ClientCnxn: Session
>>>>>>> 0x14724a78b320007
>>>>>>> for
>>>>>>> server null, unexpected error, closing socket connection and
>>>>>>> attempting
>>>>>>> reconnect
>>>>>>> java.net.ConnectException: Connection refused: no further information
>>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>>> SocketChannelImpl.java:692)
>>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>>> ClientCnxn.java:1075)
>>>>>>> 14/07/11 11:01:33 WARN zookeeper.ClientCnxn: Session
>>>>>>> 0x14724a78b320002
>>>>>>> for
>>>>>>> server null, unexpected error, closing socket connection and
>>>>>>> attempting
>>>>>>> reconnect
>>>>>>> java.net.ConnectException: Connection refused: no further information
>>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>>> SocketChannelImpl.java:692)
>>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>>> ClientCnxn.java:1075)
>>>>>>> [info] - should run ticket text similarity preference mr job
>>>>>>> [info] - should generate preference table that is compatible with
>>>>>>> HBasedDataModel
>>>>>>> 14/07/11 11:01:33 WARN similarity.TicketTextSimilarityPreference
>>>>>>> MRJobTest:
>>>>>>> com.myproj.similarity.TicketTextSimilarityPreferenceMRJobTest after
>>>>>>> table
>>>>>>> close
>>>>>>> 14/07/11 11:01:33 WARN similarity.TicketTextSimilarityPreference
>>>>>>> MRJobTest:
>>>>>>> com.myproj.similarity.TicketTextSimilarityPreferenceMRJobTest before
>>>>>>> afterAll
>>>>>>> 14/07/11 11:01:35 WARN zookeeper.ClientCnxn: Session
>>>>>>> 0x14724a78b320007
>>>>>>> for
>>>>>>> server null, unexpected error, closing socket connection and
>>>>>>> attempting
>>>>>>> reconnect
>>>>>>> java.net.ConnectException: Connection refused: no further information
>>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>>> SocketChannelImpl.java:692)
>>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>>> ClientCnxn.java:1075)
>>>>>>> 14/07/11 11:01:36 WARN zookeeper.ClientCnxn: Session
>>>>>>> 0x14724a78b320002
>>>>>>> for
>>>>>>> server null, unexpected error, closing socket connection and
>>>>>>> attempting
>>>>>>> reconnect
>>>>>>> java.net.ConnectException: Connection refused: no further information
>>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>>> SocketChannelImpl.java:692)
>>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>>> ClientCnxn.java:1075)
>>>>>>> 14/07/11 11:01:36 ERROR client.HConnectionManager: Connection not
>>>>>>> found
>>>>>>> in
>>>>>>> the list, can't delete it (connection key=HConnectionKey{properties=
>>>>>>> {hbase.rpc.timeout=60000,
>>>>>>> hbase.zookeeper.property.clientPort=65078, hbase.client.pause=100,
>>>>>>> zookeeper.znode.parent=/hbase, hbase.client.retries.number=350,
>>>>>>> hbase.zookeeper.quorum=localhost}, username='user'}). May be the key
>>>>>>> was
>>>>>>> modified?
>>>>>>> java.lang.Exception
>>>>>>> at org.apache.hadoop.hbase.client.HConnectionManager.
>>>>>>> deleteConnection(
>>>>>>> HConnectionManager.java:466)
>>>>>>> at org.apache.hadoop.hbase.client.HConnectionManager.
>>>>>>> deleteConnection(
>>>>>>> HConnectionManager.java:402)
>>>>>>> at org.apache.hadoop.hbase.replication.master.
>>>>>>> ReplicationLogCleaner.stop(ReplicationLogCleaner.java:142)
>>>>>>> at org.apache.hadoop.hbase.master.cleaner.CleanerChore.
>>>>>>> cleanup(CleanerChore.java:276)
>>>>>>> at org.apache.hadoop.hbase.Chore.run(Chore.java:94)
>>>>>>> at java.lang.Thread.run(Thread.java:722)
>>>>>>> 14/07/11 11:01:37 WARN zookeeper.ClientCnxn: Session
>>>>>>> 0x14724a78b320007
>>>>>>> for
>>>>>>> server null, unexpected error, closing socket connection and
>>>>>>> attempting
>>>>>>> reconnect
>>>>>>> java.net.ConnectException: Connection refused: no further information
>>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>>> SocketChannelImpl.java:692)
>>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>>> ClientCnxn.java:1075)
>>>>>>> 14/07/11 11:01:37 WARN zookeeper.ClientCnxn: Session
>>>>>>> 0x14724a78b320002
>>>>>>> for
>>>>>>> server null, unexpected error, closing socket connection and
>>>>>>> attempting
>>>>>>> reconnect
>>>>>>> java.net.ConnectException: Connection refused: no further information
>>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>>> SocketChannelImpl.java:692)
>>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>>> ClientCnxn.java:1075)
>>>>>>> 14/07/11 11:01:37 WARN datanode.DirectoryScanner: DirectoryScanner:
>>>>>>> shutdown has been called
>>>>>>> 14/07/11 11:01:37 WARN datanode.DataNode: BPOfferService for Block
>>>>>>> pool
>>>>>>> BP-912909389-192.168.178.20-1405069279778 (Datanode Uuid
>>>>>>> c6c45632-3e50-4575-8b65-92d7479a48ba) service to /127.0.0.1:61553
>>>>>>> interrupted
>>>>>>> 14/07/11 11:01:37 WARN datanode.DataNode: Ending block pool service
>>>>>>> for:
>>>>>>> Block pool BP-912909389-192.168.178.20-1405069279778 (Datanode Uuid
>>>>>>> c6c45632-3e50-4575-8b65-92d7479a48ba) service to /127.0.0.1:61553
>>>>>>> 14/07/11 11:01:37 WARN blockmanagement.DecommissionManager: Monitor
>>>>>>> interrupted: java.lang.InterruptedException: sleep interrupted
>>>>>>> 14/07/11 11:01:37 WARN similarity.TicketTextSimilarityPreference
>>>>>>> MRJobTest:
>>>>>>> com.myproj.similarity.TicketTextSimilarityPreferenceMRJobTest after
>>>>>>> afterAll
>>>>>>> [info] TicketMasterDataCategoryGroupingMRJobTest:
>>>>>>> 14/07/11 11:01:37 WARN masterdata.TicketMasterDataCategoryGroupi
>>>>>>> ngMRJobTest:
>>>>>>> com.myproj.quantify.ticket.masterdata.TicketMasterDataCategoryGroupingMRJobTest
>>>>>>>
>>>>>>>
>>>>>>> before beforeAll
>>>>>>> 14/07/11 11:01:37 WARN hbase.HBaseCommonTestingUtility:
>>>>>>> hadoop.tmp.dir
>>>>>>> property value differs in configuration and system:
>>>>>>> Configuration=/tmp/hadoop-user while System=D:/git/myproj/etl/
>>>>>>> target/test-data/c85b7f3b-4e4b-40b4-a434-a45cecc9cba8/hadoop_tmp
>>>>>>> Erasing
>>>>>>> configuration value by system value.
>>>>>>> Formatting using clusterid: testClusterID
>>>>>>> 14/07/11 11:01:38 WARN server.AuthenticationFilter:
>>>>>>> 'signature.secret'
>>>>>>> configuration not set, using a random value as secret
>>>>>>> 14/07/11 11:01:38 WARN zookeeper.ClientCnxn: Session
>>>>>>> 0x14724a7c5790007
>>>>>>> for
>>>>>>> server null, unexpected error, closing socket connection and
>>>>>>> attempting
>>>>>>> reconnect
>>>>>>> java.net.ConnectException: Connection refused: no further information
>>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>>> SocketChannelImpl.java:692)
>>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>>> ClientCnxn.java:1075)
>>>>>>> 14/07/11 11:01:38 WARN zookeeper.ClientCnxn: Session
>>>>>>> 0x14724a7c5790002
>>>>>>> for
>>>>>>> server null, unexpected error, closing socket connection and
>>>>>>> attempting
>>>>>>> reconnect
>>>>>>> java.net.ConnectException: Connection refused: no further information
>>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>>> SocketChannelImpl.java:692)
>>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>>> ClientCnxn.java:1075)
>>>>>>> 14/07/11 11:01:39 WARN hbase.ZNodeClearer: Environment variable
>>>>>>> HBASE_ZNODE_FILE not set; znodes will not be cleared on crash by
>>>>>>> start
>>>>>>> scripts (Longer MTTR!)
>>>>>>> 14/07/11 11:01:39 WARN zookeeper.ClientCnxn: Session
>>>>>>> 0x14724a78b320002
>>>>>>> for
>>>>>>> server null, unexpected error, closing socket connection and
>>>>>>> attempting
>>>>>>> reconnect
>>>>>>> java.net.ConnectException: Connection refused: no further information
>>>>>>> at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
>>>>>>> at sun.nio.ch.SocketChannelImpl.finishConnect(
>>>>>>> SocketChannelImpl.java:692)
>>>>>>> at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(
>>>>>>> ClientCnxnSocketNIO.java:350)
>>>>>>> at org.apache.zookeeper.ClientCnxn$SendThread.run(
>>>>>>> ClientCnxn.java:1075)
>>>>>>>
>>>>>>> # ... This goes on and on and on ...
>>>>>>>
>>>>>>> [info] ScalaTest
>>>>>>> [info] Run completed in 5 minutes, 23 seconds.
>>>>>>> [info] Total number of tests run: 22
>>>>>>> [info] Suites: completed 10, aborted 0
>>>>>>> [info] Tests: succeeded 22, failed 0, canceled 0, ignored 0, pending
>>>>>>> 0
>>>>>>> [info] All tests passed.
>>>>>>> [info] Passed: Total 26, Failed 0, Errors 0, Passed 24, Skipped 2
>>>>>>> [success] Total time: 331 s, completed 11.07.2014 11:06:24
>>>>>>>
>>>>>>>
>