hbase-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Reinis Vicups <hb...@orbit-x.de>
Subject Re: HBaseTestingUtility: Issue with unclosed sessions after minicluster is shutdown
Date Thu, 17 Jul 2014 10:30:41 GMT
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 <hbase@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 <hbase@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
>>>>>

Mime
View raw message