From dev-return-75034-archive-asf-public=cust-asf.ponee.io@zookeeper.apache.org Thu Oct 25 16:39:21 2018 Return-Path: X-Original-To: archive-asf-public@cust-asf.ponee.io Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by mx-eu-01.ponee.io (Postfix) with SMTP id 176A4180670 for ; Thu, 25 Oct 2018 16:39:17 +0200 (CEST) Received: (qmail 54376 invoked by uid 500); 25 Oct 2018 14:39:17 -0000 Mailing-List: contact dev-help@zookeeper.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@zookeeper.apache.org Delivered-To: mailing list dev@zookeeper.apache.org Received: (qmail 54363 invoked by uid 99); 25 Oct 2018 14:39:17 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd4-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Thu, 25 Oct 2018 14:39:17 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd4-us-west.apache.org (ASF Mail Server at spamd4-us-west.apache.org) with ESMTP id 79EC9C1BBE for ; Thu, 25 Oct 2018 14:39:16 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd4-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: -109.501 X-Spam-Level: X-Spam-Status: No, score=-109.501 tagged_above=-999 required=6.31 tests=[ENV_AND_HDR_SPF_MATCH=-0.5, KAM_ASCII_DIVIDERS=0.8, RCVD_IN_DNSWL_MED=-2.3, SPF_PASS=-0.001, USER_IN_DEF_SPF_WL=-7.5, USER_IN_WHITELIST=-100] autolearn=disabled Received: from mx1-lw-us.apache.org ([10.40.0.8]) by localhost (spamd4-us-west.apache.org [10.40.0.11]) (amavisd-new, port 10024) with ESMTP id hTzW6ausFaYq for ; Thu, 25 Oct 2018 14:39:02 +0000 (UTC) Received: from mailrelay1-us-west.apache.org (mailrelay1-us-west.apache.org [209.188.14.139]) by mx1-lw-us.apache.org (ASF Mail Server at mx1-lw-us.apache.org) with ESMTP id 9BEE35F4ED for ; Thu, 25 Oct 2018 14:39:01 +0000 (UTC) Received: from jira-lw-us.apache.org (unknown [207.244.88.139]) by mailrelay1-us-west.apache.org (ASF Mail Server at mailrelay1-us-west.apache.org) with ESMTP id F06B3E25AA for ; Thu, 25 Oct 2018 14:39:00 +0000 (UTC) Received: from jira-lw-us.apache.org (localhost [127.0.0.1]) by jira-lw-us.apache.org (ASF Mail Server at jira-lw-us.apache.org) with ESMTP id 7079C2669C for ; Thu, 25 Oct 2018 14:39:00 +0000 (UTC) Date: Thu, 25 Oct 2018 14:39:00 +0000 (UTC) From: "Andor Molnar (JIRA)" To: dev@zookeeper.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Resolved] (ZOOKEEPER-2485) Flaky Test: org.apache.zookeeper.test.FourLetterWordsTest.testFourLetterWords MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: quoted-printable X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/ZOOKEEPER-2485?page=3Dcom.atla= ssian.jira.plugin.system.issuetabpanels:all-tabpanel ] Andor Molnar resolved ZOOKEEPER-2485. ------------------------------------- Resolution: Cannot Reproduce > Flaky Test: org.apache.zookeeper.test.FourLetterWordsTest.testFourLetterW= ords > -------------------------------------------------------------------------= ---- > > Key: ZOOKEEPER-2485 > URL: https://issues.apache.org/jira/browse/ZOOKEEPER-2485 > Project: ZooKeeper > Issue Type: Sub-task > Components: tests > Affects Versions: 3.4.8 > Reporter: Michael Han > Assignee: Andor Molnar > Priority: Major > Labels: flaky, flaky-test > Fix For: 3.6.0, 3.5.5 > > > From https://builds.apache.org/job/ZooKeeper_branch34_jdk7/1156/ > {noformat} > Error Message > test timed out after 30000 milliseconds > Stacktrace > java.lang.Exception: test timed out after 30000 milliseconds > =09at java.io.FileOutputStream.writeBytes(Native Method) > =09at java.io.FileOutputStream.write(FileOutputStream.java:345) > =09at java.io.BufferedOutputStream.write(BufferedOutputStream.java:122) > =09at java.io.PrintStream.write(PrintStream.java:480) > =09at java.io.PrintStream.write(PrintStream.java:480) > =09at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221) > =09at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291) > =09at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:295) > =09at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141) > =09at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229) > =09at org.apache.log4j.helpers.QuietWriter.flush(QuietWriter.java:59) > =09at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:324) > =09at org.apache.log4j.WriterAppender.append(WriterAppender.java:162) > =09at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:25= 1) > =09at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppende= rs(AppenderAttachableImpl.java:66) > =09at org.apache.log4j.Category.callAppenders(Category.java:206) > =09at org.apache.log4j.Category.forcedLog(Category.java:391) > =09at org.apache.log4j.Category.log(Category.java:856) > =09at org.slf4j.impl.Log4jLoggerAdapter.info(Log4jLoggerAdapter.java:305) > =09at org.apache.zookeeper.test.FourLetterWordsTest.verify(FourLetterWord= sTest.java:121) > =09at org.apache.zookeeper.test.FourLetterWordsTest.testFourLetterWords(F= ourLetterWordsTest.java:52) > =09at org.apache.zookeeper.JUnit4ZKTestRunner$LoggedInvokeMethod.evaluate= (JUnit4ZKTestRunner.java:55) > Standard Output > 2016-07-21 08:05:43,150 [myid:] - INFO [main:PortAssignment@32] - assign= ing port 11221 > 2016-07-21 08:05:43,156 [myid:] - INFO [main:ZKTestCase$1@50] - STARTING= testDisconnectedAddAuth > 2016-07-21 08:05:43,157 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@53] - RUNNING TEST METHOD testDisconnectedAddAuth > 2016-07-21 08:05:43,178 [myid:] - INFO [main:Environment@100] - Server e= nvironment:zookeeper.version=3D3.4.9-SNAPSHOT-1753645, built on 07/21/2016 = 07:46 GMT > 2016-07-21 08:05:43,178 [myid:] - INFO [main:Environment@100] - Server e= nvironment:host.name=3Dasf907.gq1.ygridcore.net > 2016-07-21 08:05:43,178 [myid:] - INFO [main:Environment@100] - Server e= nvironment:java.version=3D1.7.0_80 > 2016-07-21 08:05:43,178 [myid:] - INFO [main:Environment@100] - Server e= nvironment:java.vendor=3DOracle Corporation > 2016-07-21 08:05:43,178 [myid:] - INFO [main:Environment@100] - Server e= nvironment:java.home=3D/home/jenkins/jenkins-slave/tools/hudson.model.JDK/l= atest1.7/jre > 2016-07-21 08:05:43,179 [myid:] - INFO [main:Environment@100] - Server e= nvironment:java.class.path=3D/home/jenkins/jenkins-slave/workspace/ZooKeepe= r_branch34_jdk7/branch-3.4/build/test/classes:/home/jenkins/jenkins-slave/w= orkspace/ZooKeeper_branch34_jdk7/branch-3.4/build/test/lib/antlr-2.7.6.jar:= /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/bu= ild/test/lib/checkstyle-5.0.jar:/home/jenkins/jenkins-slave/workspace/ZooKe= eper_branch34_jdk7/branch-3.4/build/test/lib/commons-beanutils-core-1.7.0.j= ar:/home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4= /build/test/lib/commons-cli-1.0.jar:/home/jenkins/jenkins-slave/workspace/Z= ooKeeper_branch34_jdk7/branch-3.4/build/test/lib/commons-collections-3.2.2.= jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.= 4/build/test/lib/commons-lang-1.0.jar:/home/jenkins/jenkins-slave/workspace= /ZooKeeper_branch34_jdk7/branch-3.4/build/test/lib/commons-logging-1.0.3.ja= r:/home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/= build/test/lib/google-collections-0.9.jar:/home/jenkins/jenkins-slave/works= pace/ZooKeeper_branch34_jdk7/branch-3.4/build/test/lib/junit-4.8.1.jar:/hom= e/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/build/= test/lib/mockito-all-1.8.2.jar:/home/jenkins/jenkins-slave/workspace/ZooKee= per_branch34_jdk7/branch-3.4/build/classes:/home/jenkins/jenkins-slave/work= space/ZooKeeper_branch34_jdk7/branch-3.4/src/java/lib/ivy-2.4.0.jar:/home/j= enkins/tools/ant/latest/lib/ant.jar:/home/jenkins/jenkins-slave/workspace/Z= ooKeeper_branch34_jdk7/branch-3.4/build/lib/jline-0.9.94.jar:/home/jenkins/= jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/build/lib/log4j-= 1.2.16.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/br= anch-3.4/build/lib/netty-3.10.5.Final.jar:/home/jenkins/jenkins-slave/works= pace/ZooKeeper_branch34_jdk7/branch-3.4/build/lib/slf4j-api-1.6.1.jar:/home= /jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/build/l= ib/slf4j-log4j12-1.6.1.jar:/home/jenkins/tools/ant/apache-ant-1.9.4/lib/ant= -launcher.jar:/home/jenkins/tools/ant/latest/lib/ant-junit.jar:/home/jenkin= s/tools/ant/latest/lib/ant-junit4.jar > 2016-07-21 08:05:43,179 [myid:] - INFO [main:Environment@100] - Server e= nvironment:java.library.path=3D/usr/java/packages/lib/amd64:/usr/lib64:/lib= 64:/lib:/usr/lib > 2016-07-21 08:05:43,179 [myid:] - INFO [main:Environment@100] - Server e= nvironment:java.io.tmpdir=3D/tmp > 2016-07-21 08:05:43,179 [myid:] - INFO [main:Environment@100] - Server e= nvironment:java.compiler=3D > 2016-07-21 08:05:43,179 [myid:] - INFO [main:Environment@100] - Server e= nvironment:os.name=3DLinux > 2016-07-21 08:05:43,180 [myid:] - INFO [main:Environment@100] - Server e= nvironment:os.arch=3Damd64 > 2016-07-21 08:05:43,180 [myid:] - INFO [main:Environment@100] - Server e= nvironment:os.version=3D3.13.0-36-lowlatency > 2016-07-21 08:05:43,180 [myid:] - INFO [main:Environment@100] - Server e= nvironment:user.name=3Djenkins > 2016-07-21 08:05:43,182 [myid:] - INFO [main:Environment@100] - Server e= nvironment:user.home=3D/home/jenkins > 2016-07-21 08:05:43,182 [myid:] - INFO [main:Environment@100] - Server e= nvironment:user.dir=3D/home/jenkins/jenkins-slave/workspace/ZooKeeper_branc= h34_jdk7/branch-3.4 > 2016-07-21 08:05:43,199 [myid:] - INFO [main:ZooKeeperServer@170] - Crea= ted server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 6000= 0 datadir /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/bra= nch-3.4/build/test/tmp/test4168931007806197633.junit.dir/version-2 snapdir = /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/bu= ild/test/tmp/test4168931007806197633.junit.dir/version-2 > 2016-07-21 08:05:43,295 [myid:] - INFO [main:NettyServerCnxnFactory@365]= - binding to port 0.0.0.0/0.0.0.0:11221 > 2016-07-21 08:05:43,387 [myid:] - INFO [main:ACLTest@62] - starting up t= he zookeeper server .. waiting > 2016-07-21 08:05:43,388 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11221 > 2016-07-21 08:05:43,420 [myid:] - INFO [New I/O worker #1:NettyServerCnx= n@632] - Processing stat command from /127.0.0.1:35232 > 2016-07-21 08:05:43,422 [myid:] - INFO [New I/O worker #1:NettyServerCnx= n$StatCommand@469] - Stat command output > 2016-07-21 08:05:43,431 [myid:] - INFO [main:Environment@100] - Client e= nvironment:zookeeper.version=3D3.4.9-SNAPSHOT-1753645, built on 07/21/2016 = 07:46 GMT > 2016-07-21 08:05:43,431 [myid:] - INFO [main:Environment@100] - Client e= nvironment:host.name=3Dasf907.gq1.ygridcore.net > 2016-07-21 08:05:43,431 [myid:] - INFO [main:Environment@100] - Client e= nvironment:java.version=3D1.7.0_80 > 2016-07-21 08:05:43,431 [myid:] - INFO [main:Environment@100] - Client e= nvironment:java.vendor=3DOracle Corporation > 2016-07-21 08:05:43,431 [myid:] - INFO [main:Environment@100] - Client e= nvironment:java.home=3D/home/jenkins/jenkins-slave/tools/hudson.model.JDK/l= atest1.7/jre > 2016-07-21 08:05:43,431 [myid:] - INFO [main:Environment@100] - Client e= nvironment:java.class.path=3D/home/jenkins/jenkins-slave/workspace/ZooKeepe= r_branch34_jdk7/branch-3.4/build/test/classes:/home/jenkins/jenkins-slave/w= orkspace/ZooKeeper_branch34_jdk7/branch-3.4/build/test/lib/antlr-2.7.6.jar:= /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/bu= ild/test/lib/checkstyle-5.0.jar:/home/jenkins/jenkins-slave/workspace/ZooKe= eper_branch34_jdk7/branch-3.4/build/test/lib/commons-beanutils-core-1.7.0.j= ar:/home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4= /build/test/lib/commons-cli-1.0.jar:/home/jenkins/jenkins-slave/workspace/Z= ooKeeper_branch34_jdk7/branch-3.4/build/test/lib/commons-collections-3.2.2.= jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.= 4/build/test/lib/commons-lang-1.0.jar:/home/jenkins/jenkins-slave/workspace= /ZooKeeper_branch34_jdk7/branch-3.4/build/test/lib/commons-logging-1.0.3.ja= r:/home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/= build/test/lib/google-collections-0.9.jar:/home/jenkins/jenkins-slave/works= pace/ZooKeeper_branch34_jdk7/branch-3.4/build/test/lib/junit-4.8.1.jar:/hom= e/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/build/= test/lib/mockito-all-1.8.2.jar:/home/jenkins/jenkins-slave/workspace/ZooKee= per_branch34_jdk7/branch-3.4/build/classes:/home/jenkins/jenkins-slave/work= space/ZooKeeper_branch34_jdk7/branch-3.4/src/java/lib/ivy-2.4.0.jar:/home/j= enkins/tools/ant/latest/lib/ant.jar:/home/jenkins/jenkins-slave/workspace/Z= ooKeeper_branch34_jdk7/branch-3.4/build/lib/jline-0.9.94.jar:/home/jenkins/= jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/build/lib/log4j-= 1.2.16.jar:/home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/br= anch-3.4/build/lib/netty-3.10.5.Final.jar:/home/jenkins/jenkins-slave/works= pace/ZooKeeper_branch34_jdk7/branch-3.4/build/lib/slf4j-api-1.6.1.jar:/home= /jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/build/l= ib/slf4j-log4j12-1.6.1.jar:/home/jenkins/tools/ant/apache-ant-1.9.4/lib/ant= -launcher.jar:/home/jenkins/tools/ant/latest/lib/ant-junit.jar:/home/jenkin= s/tools/ant/latest/lib/ant-junit4.jar > 2016-07-21 08:05:43,432 [myid:] - INFO [main:Environment@100] - Client e= nvironment:java.library.path=3D/usr/java/packages/lib/amd64:/usr/lib64:/lib= 64:/lib:/usr/lib > 2016-07-21 08:05:43,432 [myid:] - INFO [main:Environment@100] - Client e= nvironment:java.io.tmpdir=3D/tmp > 2016-07-21 08:05:43,432 [myid:] - INFO [main:Environment@100] - Client e= nvironment:java.compiler=3D > 2016-07-21 08:05:43,432 [myid:] - INFO [main:Environment@100] - Client e= nvironment:os.name=3DLinux > 2016-07-21 08:05:43,432 [myid:] - INFO [main:Environment@100] - Client e= nvironment:os.arch=3Damd64 > 2016-07-21 08:05:43,433 [myid:] - INFO [main:Environment@100] - Client e= nvironment:os.version=3D3.13.0-36-lowlatency > 2016-07-21 08:05:43,433 [myid:] - INFO [main:Environment@100] - Client e= nvironment:user.name=3Djenkins > 2016-07-21 08:05:43,433 [myid:] - INFO [main:Environment@100] - Client e= nvironment:user.home=3D/home/jenkins > 2016-07-21 08:05:43,433 [myid:] - INFO [main:Environment@100] - Client e= nvironment:user.dir=3D/home/jenkins/jenkins-slave/workspace/ZooKeeper_branc= h34_jdk7/branch-3.4 > 2016-07-21 08:05:43,434 [myid:] - INFO [main:ZooKeeper@438] - Initiating= client connection, connectString=3D127.0.0.1:11221 sessionTimeout=3D30000 = watcher=3Dorg.apache.zookeeper.test.ACLTest@14f8e8b > 2016-07-21 08:05:43,450 [myid:] - INFO [main-SendThread(127.0.0.1:11221)= :ClientCnxn$SendThread@1032] - Opening socket connection to server 127.0.0.= 1/127.0.0.1:11221. Will not attempt to authenticate using SASL (unknown err= or) > 2016-07-21 08:05:43,450 [myid:] - INFO [main-SendThread(127.0.0.1:11221)= :ClientCnxn$SendThread@876] - Socket connection established to 127.0.0.1/12= 7.0.0.1:11221, initiating session > 2016-07-21 08:05:43,454 [myid:] - INFO [New I/O worker #2:ZooKeeperServe= r@900] - Client attempting to establish new session at /127.0.0.1:35233 > 2016-07-21 08:05:43,458 [myid:] - INFO [SyncThread:0:FileTxnLog@203] - C= reating new log file: log.1 > 2016-07-21 08:05:43,468 [myid:] - INFO [SyncThread:0:ZooKeeperServer@645= ] - Established session 0x1560c7d251c0000 with negotiated timeout 30000 for= client /127.0.0.1:35233 > 2016-07-21 08:05:43,471 [myid:] - INFO [main-SendThread(127.0.0.1:11221)= :ClientCnxn$SendThread@1299] - Session establishment complete on server 127= .0.0.1/127.0.0.1:11221, sessionid =3D 0x1560c7d251c0000, negotiated timeout= =3D 30000 > 2016-07-21 08:05:43,474 [myid:] - INFO [main-EventThread:ACLTest@175] - = Event:SyncConnected None null > 2016-07-21 08:05:43,475 [myid:] - INFO [New I/O worker #2:ZooKeeperServe= r@924] - got auth packet /127.0.0.1:35233 > 2016-07-21 08:05:43,475 [myid:] - WARN [main-EventThread:ACLTest@182] - = startsignal null > 2016-07-21 08:05:43,478 [myid:] - INFO [New I/O worker #2:ZooKeeperServe= r@958] - auth success /127.0.0.1:35233 > 2016-07-21 08:05:43,479 [myid:] - INFO [New I/O worker #2:ZooKeeperServe= r@924] - got auth packet /127.0.0.1:35233 > 2016-07-21 08:05:43,479 [myid:] - INFO [New I/O worker #2:ZooKeeperServe= r@958] - auth success /127.0.0.1:35233 > 2016-07-21 08:05:43,485 [myid:] - INFO [ProcessThread(sid:0 cport:11221)= ::PrepRequestProcessor@487] - Processed session termination for sessionid: = 0x1560c7d251c0000 > 2016-07-21 08:05:43,488 [myid:] - WARN [New I/O worker #2:NettyServerCnx= nFactory$CnxnChannelHandler@111] - Exception caught [id: 0xbe54f7b5, /127.0= .0.1:35233 :> /127.0.0.1:11221] EXCEPTION: java.nio.channels.ClosedChannelE= xception > java.nio.channels.ClosedChannelException > =09at sun.nio.ch.SocketChannelImpl.ensureWriteOpen(SocketChannelImpl.java= :270) > =09at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:479) > =09at org.jboss.netty.channel.socket.nio.SocketSendBufferPool$UnpooledSen= dBuffer.transferTo(SocketSendBufferPool.java:203) > =09at org.jboss.netty.channel.socket.nio.AbstractNioWorker.write0(Abstrac= tNioWorker.java:201) > =09at org.jboss.netty.channel.socket.nio.AbstractNioWorker.writeFromTaskL= oop(AbstractNioWorker.java:151) > =09at org.jboss.netty.channel.socket.nio.AbstractNioChannel$WriteTask.run= (AbstractNioChannel.java:315) > =09at org.jboss.netty.channel.socket.nio.AbstractNioSelector.processTaskQ= ueue(AbstractNioSelector.java:391) > =09at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(Abstract= NioSelector.java:315) > =09at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNi= oWorker.java:89) > =09at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178= ) > =09at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunna= ble.java:108) > =09at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockPro= ofWorker.java:42) > =09at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecuto= r.java:1145) > =09at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecut= or.java:615) > =09at java.lang.Thread.run(Thread.java:745) > 2016-07-21 08:05:43,587 [myid:] - INFO [main:ZooKeeper@684] - Session: 0= x1560c7d251c0000 closed > 2016-07-21 08:05:43,588 [myid:] - INFO [main-EventThread:ClientCnxn$Even= tThread@519] - EventThread shut down for session: 0x1560c7d251c0000 > 2016-07-21 08:05:43,588 [myid:] - INFO [main:NettyServerCnxnFactory@342]= - shutdown called 0.0.0.0/0.0.0.0:11221 > 2016-07-21 08:05:43,607 [myid:] - INFO [main:ZooKeeperServer@469] - shut= ting down > 2016-07-21 08:05:43,607 [myid:] - INFO [main:SessionTrackerImpl@225] - S= hutting down > 2016-07-21 08:05:43,607 [myid:] - INFO [main:PrepRequestProcessor@765] -= Shutting down > 2016-07-21 08:05:43,608 [myid:] - INFO [main:SyncRequestProcessor@209] -= Shutting down > 2016-07-21 08:05:43,608 [myid:] - INFO [ProcessThread(sid:0 cport:11221)= ::PrepRequestProcessor@143] - PrepRequestProcessor exited loop! > 2016-07-21 08:05:43,608 [myid:] - INFO [SyncThread:0:SyncRequestProcesso= r@187] - SyncRequestProcessor exited! > 2016-07-21 08:05:43,608 [myid:] - INFO [main:FinalRequestProcessor@402] = - shutdown of request processor complete > 2016-07-21 08:05:43,609 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11221 > 2016-07-21 08:05:43,610 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@58] - Memory used 124233 > 2016-07-21 08:05:43,611 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@63] - Number of threads 5 > 2016-07-21 08:05:43,611 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@78] - FINISHED TEST METHOD testDisconnectedAddAuth > 2016-07-21 08:05:43,611 [myid:] - INFO [main:ZKTestCase$1@60] - SUCCEEDE= D testDisconnectedAddAuth > 2016-07-21 08:05:43,611 [myid:] - INFO [main:ZKTestCase$1@55] - FINISHED= testDisconnectedAddAuth > 2016-07-21 08:05:43,613 [myid:] - INFO [main:ZKTestCase$1@50] - STARTING= testAcls > 2016-07-21 08:05:43,613 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@53] - RUNNING TEST METHOD testAcls > 2016-07-21 08:05:43,614 [myid:] - INFO [main:ZooKeeperServer@170] - Crea= ted server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 6000= 0 datadir /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/bra= nch-3.4/build/test/tmp/test2000752507502946075.junit.dir/version-2 snapdir = /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/bu= ild/test/tmp/test2000752507502946075.junit.dir/version-2 > 2016-07-21 08:05:43,635 [myid:] - INFO [main:NettyServerCnxnFactory@365]= - binding to port 0.0.0.0/0.0.0.0:11221 > 2016-07-21 08:05:43,639 [myid:] - INFO [main:ACLTest@98] - starting up t= he zookeeper server .. waiting > 2016-07-21 08:05:43,639 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11221 > 2016-07-21 08:05:43,640 [myid:] - INFO [New I/O worker #34:NettyServerCn= xn@632] - Processing stat command from /127.0.0.1:35236 > 2016-07-21 08:05:43,641 [myid:] - INFO [New I/O worker #34:NettyServerCn= xn$StatCommand@469] - Stat command output > 2016-07-21 08:05:43,641 [myid:] - INFO [main:ZooKeeper@438] - Initiating= client connection, connectString=3D127.0.0.1:11221 sessionTimeout=3D30000 = watcher=3Dorg.apache.zookeeper.test.ACLTest@114f6322 > 2016-07-21 08:05:43,642 [myid:] - INFO [main:ACLTest@102] - starting cre= ating acls > 2016-07-21 08:05:43,642 [myid:] - INFO [main-SendThread(127.0.0.1:11221)= :ClientCnxn$SendThread@1032] - Opening socket connection to server 127.0.0.= 1/127.0.0.1:11221. Will not attempt to authenticate using SASL (unknown err= or) > 2016-07-21 08:05:43,643 [myid:] - INFO [main-SendThread(127.0.0.1:11221)= :ClientCnxn$SendThread@876] - Socket connection established to 127.0.0.1/12= 7.0.0.1:11221, initiating session > 2016-07-21 08:05:43,644 [myid:] - INFO [New I/O worker #35:ZooKeeperServ= er@900] - Client attempting to establish new session at /127.0.0.1:35237 > 2016-07-21 08:05:43,644 [myid:] - INFO [SyncThread:0:FileTxnLog@203] - C= reating new log file: log.1 > 2016-07-21 08:05:43,648 [myid:] - INFO [SyncThread:0:ZooKeeperServer@645= ] - Established session 0x1560c7d26540000 with negotiated timeout 30000 for= client /127.0.0.1:35237 > 2016-07-21 08:05:43,648 [myid:] - INFO [main-SendThread(127.0.0.1:11221)= :ClientCnxn$SendThread@1299] - Session establishment complete on server 127= .0.0.1/127.0.0.1:11221, sessionid =3D 0x1560c7d26540000, negotiated timeout= =3D 30000 > 2016-07-21 08:05:43,648 [myid:] - INFO [main-EventThread:ACLTest@175] - = Event:SyncConnected None null > 2016-07-21 08:05:43,648 [myid:] - WARN [main-EventThread:ACLTest@182] - = startsignal null > 2016-07-21 08:05:43,954 [myid:] - INFO [main:NettyServerCnxnFactory@342]= - shutdown called 0.0.0.0/0.0.0.0:11221 > 2016-07-21 08:05:43,955 [myid:] - INFO [main-SendThread(127.0.0.1:11221)= :ClientCnxn$SendThread@1158] - Unable to read additional data from server s= essionid 0x1560c7d26540000, likely server has closed socket, closing socket= connection and attempting reconnect > 2016-07-21 08:05:43,961 [myid:] - INFO [main:ZooKeeperServer@469] - shut= ting down > 2016-07-21 08:05:43,961 [myid:] - INFO [main:SessionTrackerImpl@225] - S= hutting down > 2016-07-21 08:05:43,961 [myid:] - INFO [main:PrepRequestProcessor@765] -= Shutting down > 2016-07-21 08:05:43,962 [myid:] - INFO [main:SyncRequestProcessor@209] -= Shutting down > 2016-07-21 08:05:43,962 [myid:] - INFO [ProcessThread(sid:0 cport:11221)= ::PrepRequestProcessor@143] - PrepRequestProcessor exited loop! > 2016-07-21 08:05:43,962 [myid:] - INFO [SyncThread:0:SyncRequestProcesso= r@187] - SyncRequestProcessor exited! > 2016-07-21 08:05:43,963 [myid:] - INFO [main:FinalRequestProcessor@402] = - shutdown of request processor complete > 2016-07-21 08:05:43,963 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11221 > 2016-07-21 08:05:43,964 [myid:] - INFO [main:ZooKeeperServer@170] - Crea= ted server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 6000= 0 datadir /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/bra= nch-3.4/build/test/tmp/test2000752507502946075.junit.dir/version-2 snapdir = /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/bu= ild/test/tmp/test2000752507502946075.junit.dir/version-2 > 2016-07-21 08:05:43,972 [myid:] - INFO [main:NettyServerCnxnFactory@365]= - binding to port 0.0.0.0/0.0.0.0:11221 > 2016-07-21 08:05:44,002 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11221 > 2016-07-21 08:05:44,004 [myid:] - INFO [New I/O worker #67:NettyServerCn= xn@632] - Processing stat command from /127.0.0.1:35240 > 2016-07-21 08:05:44,004 [myid:] - INFO [New I/O worker #67:NettyServerCn= xn$StatCommand@469] - Stat command output > 2016-07-21 08:05:44,055 [myid:] - INFO [main-EventThread:ACLTest@175] - = Event:Disconnected None null > 2016-07-21 08:05:45,000 [myid:] - INFO [SessionTracker:SessionTrackerImp= l@162] - SessionTrackerImpl exited loop! > 2016-07-21 08:05:45,000 [myid:] - INFO [SessionTracker:SessionTrackerImp= l@162] - SessionTrackerImpl exited loop! > 2016-07-21 08:05:45,784 [myid:] - INFO [main-SendThread(127.0.0.1:11221)= :ClientCnxn$SendThread@1032] - Opening socket connection to server 127.0.0.= 1/127.0.0.1:11221. Will not attempt to authenticate using SASL (unknown err= or) > 2016-07-21 08:05:45,784 [myid:] - INFO [main-SendThread(127.0.0.1:11221)= :ClientCnxn$SendThread@876] - Socket connection established to 127.0.0.1/12= 7.0.0.1:11221, initiating session > 2016-07-21 08:05:45,785 [myid:] - INFO [New I/O worker #68:ZooKeeperServ= er@893] - Client attempting to renew session 0x1560c7d26540000 at /127.0.0.= 1:35246 > 2016-07-21 08:05:45,786 [myid:] - INFO [New I/O worker #68:ZooKeeperServ= er@645] - Established session 0x1560c7d26540000 with negotiated timeout 300= 00 for client /127.0.0.1:35246 > 2016-07-21 08:05:45,786 [myid:] - INFO [main-SendThread(127.0.0.1:11221)= :ClientCnxn$SendThread@1299] - Session establishment complete on server 127= .0.0.1/127.0.0.1:11221, sessionid =3D 0x1560c7d26540000, negotiated timeout= =3D 30000 > 2016-07-21 08:05:45,786 [myid:] - INFO [main-EventThread:ACLTest@175] - = Event:SyncConnected None null > 2016-07-21 08:05:45,786 [myid:] - INFO [main-EventThread:ACLTest@179] - = startsignal.countDown() > 2016-07-21 08:05:45,788 [myid:] - INFO [SyncThread:0:FileTxnLog@203] - C= reating new log file: log.ca > 2016-07-21 08:05:45,795 [myid:] - INFO [ProcessThread(sid:0 cport:11221)= ::PrepRequestProcessor@487] - Processed session termination for sessionid: = 0x1560c7d26540000 > 2016-07-21 08:05:45,795 [myid:] - WARN [New I/O worker #68:NettyServerCn= xnFactory$CnxnChannelHandler@111] - Exception caught [id: 0x0ae869d5, /127.= 0.0.1:35246 :> /127.0.0.1:11221] EXCEPTION: java.nio.channels.ClosedChannel= Exception > java.nio.channels.ClosedChannelException > =09at sun.nio.ch.SocketChannelImpl.ensureWriteOpen(SocketChannelImpl.java= :270) > =09at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:479) > =09at org.jboss.netty.channel.socket.nio.SocketSendBufferPool$UnpooledSen= dBuffer.transferTo(SocketSendBufferPool.java:203) > =09at org.jboss.netty.channel.socket.nio.AbstractNioWorker.write0(Abstrac= tNioWorker.java:201) > =09at org.jboss.netty.channel.socket.nio.AbstractNioWorker.writeFromTaskL= oop(AbstractNioWorker.java:151) > =09at org.jboss.netty.channel.socket.nio.AbstractNioChannel$WriteTask.run= (AbstractNioChannel.java:315) > =09at org.jboss.netty.channel.socket.nio.AbstractNioSelector.processTaskQ= ueue(AbstractNioSelector.java:391) > =09at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(Abstract= NioSelector.java:315) > =09at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNi= oWorker.java:89) > =09at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178= ) > =09at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunna= ble.java:108) > =09at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockPro= ofWorker.java:42) > =09at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecuto= r.java:1145) > =09at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecut= or.java:615) > =09at java.lang.Thread.run(Thread.java:745) > 2016-07-21 08:05:45,896 [myid:] - INFO [main:ZooKeeper@684] - Session: 0= x1560c7d26540000 closed > 2016-07-21 08:05:45,896 [myid:] - INFO [main:NettyServerCnxnFactory@342]= - shutdown called 0.0.0.0/0.0.0.0:11221 > 2016-07-21 08:05:45,896 [myid:] - INFO [main-EventThread:ClientCnxn$Even= tThread@519] - EventThread shut down for session: 0x1560c7d26540000 > 2016-07-21 08:05:45,901 [myid:] - INFO [main:ZooKeeperServer@469] - shut= ting down > 2016-07-21 08:05:45,901 [myid:] - INFO [main:SessionTrackerImpl@225] - S= hutting down > 2016-07-21 08:05:45,901 [myid:] - INFO [main:PrepRequestProcessor@765] -= Shutting down > 2016-07-21 08:05:45,902 [myid:] - INFO [ProcessThread(sid:0 cport:11221)= ::PrepRequestProcessor@143] - PrepRequestProcessor exited loop! > 2016-07-21 08:05:45,902 [myid:] - INFO [main:SyncRequestProcessor@209] -= Shutting down > 2016-07-21 08:05:45,902 [myid:] - INFO [SyncThread:0:SyncRequestProcesso= r@187] - SyncRequestProcessor exited! > 2016-07-21 08:05:45,902 [myid:] - INFO [main:FinalRequestProcessor@402] = - shutdown of request processor complete > 2016-07-21 08:05:45,903 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11221 > 2016-07-21 08:05:45,904 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@58] - Memory used 81805 > 2016-07-21 08:05:45,904 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@63] - Number of threads 7 > 2016-07-21 08:05:45,904 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@78] - FINISHED TEST METHOD testAcls > 2016-07-21 08:05:45,904 [myid:] - INFO [main:ZKTestCase$1@60] - SUCCEEDE= D testAcls > 2016-07-21 08:05:45,905 [myid:] - INFO [main:ZKTestCase$1@55] - FINISHED= testAcls > 2016-07-21 08:05:45,914 [myid:] - INFO [main:PortAssignment@32] - assign= ing port 11222 > 2016-07-21 08:05:45,915 [myid:] - INFO [main:ZKTestCase$1@50] - STARTING= testAsyncCreate > 2016-07-21 08:05:45,916 [myid:] - INFO [main:ClientBase@425] - Initial f= dcount is: 33 > 2016-07-21 08:05:46,035 [myid:] - INFO [main:ClientBase@443] - STARTING = server > 2016-07-21 08:05:46,035 [myid:] - INFO [main:ClientBase@364] - CREATING = server instance 127.0.0.1:11222 > 2016-07-21 08:05:46,042 [myid:] - INFO [main:ClientBase@339] - STARTING = server instance 127.0.0.1:11222 > 2016-07-21 08:05:46,043 [myid:] - INFO [main:ZooKeeperServer@170] - Crea= ted server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 6000= 0 datadir /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/bra= nch-3.4/build/test/tmp/test4160740823067989579.junit.dir/version-2 snapdir = /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/bu= ild/test/tmp/test4160740823067989579.junit.dir/version-2 > 2016-07-21 08:05:46,043 [myid:] - INFO [main:NettyServerCnxnFactory@365]= - binding to port 0.0.0.0/0.0.0.0:11222 > 2016-07-21 08:05:46,046 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11222 > 2016-07-21 08:05:46,047 [myid:] - INFO [New I/O worker #100:NettyServerC= nxn@632] - Processing stat command from /127.0.0.1:49831 > 2016-07-21 08:05:46,047 [myid:] - INFO [New I/O worker #100:NettyServerC= nxn$StatCommand@469] - Stat command output > 2016-07-21 08:05:46,048 [myid:] - INFO [main:JMXEnv@229] - ensureParent:= [InMemoryDataTree, StandaloneServer_port] > 2016-07-21 08:05:46,053 [myid:] - INFO [main:JMXEnv@246] - expect:InMemo= ryDataTree > 2016-07-21 08:05:46,053 [myid:] - INFO [main:JMXEnv@250] - found:InMemor= yDataTree org.apache.ZooKeeperService:name0=3DStandaloneServer_port11222,na= me1=3DInMemoryDataTree > 2016-07-21 08:05:46,054 [myid:] - INFO [main:JMXEnv@246] - expect:Standa= loneServer_port > 2016-07-21 08:05:46,054 [myid:] - INFO [main:JMXEnv@250] - found:Standal= oneServer_port org.apache.ZooKeeperService:name0=3DStandaloneServer_port112= 22 > 2016-07-21 08:05:46,054 [myid:] - INFO [main:ClientBase@439] - Client te= st setup finished > 2016-07-21 08:05:46,054 [myid:] - INFO [main:AsyncOpsTest@47] - Creating= client testAsyncCreate > 2016-07-21 08:05:46,055 [myid:] - INFO [main:ZooKeeper@438] - Initiating= client connection, connectString=3D127.0.0.1:11222 sessionTimeout=3D30000 = watcher=3Dorg.apache.zookeeper.test.ClientBase$CountdownWatcher@42701c57 > 2016-07-21 08:05:46,056 [myid:] - INFO [main-SendThread(127.0.0.1:11222)= :ClientCnxn$SendThread@1032] - Opening socket connection to server 127.0.0.= 1/127.0.0.1:11222. Will not attempt to authenticate using SASL (unknown err= or) > 2016-07-21 08:05:46,056 [myid:] - INFO [main-SendThread(127.0.0.1:11222)= :ClientCnxn$SendThread@876] - Socket connection established to 127.0.0.1/12= 7.0.0.1:11222, initiating session > 2016-07-21 08:05:46,057 [myid:] - INFO [New I/O worker #101:ZooKeeperSer= ver@900] - Client attempting to establish new session at /127.0.0.1:49832 > 2016-07-21 08:05:46,057 [myid:] - INFO [SyncThread:0:FileTxnLog@203] - C= reating new log file: log.1 > 2016-07-21 08:05:46,060 [myid:] - INFO [SyncThread:0:ZooKeeperServer@645= ] - Established session 0x1560c7d2fbb0000 with negotiated timeout 30000 for= client /127.0.0.1:49832 > 2016-07-21 08:05:46,060 [myid:] - INFO [main-SendThread(127.0.0.1:11222)= :ClientCnxn$SendThread@1299] - Session establishment complete on server 127= .0.0.1/127.0.0.1:11222, sessionid =3D 0x1560c7d2fbb0000, negotiated timeout= =3D 30000 > 2016-07-21 08:05:46,062 [myid:] - INFO [main:JMXEnv@117] - expect:0x1560= c7d2fbb0000 > 2016-07-21 08:05:46,062 [myid:] - INFO [main:JMXEnv@120] - found:0x1560c= 7d2fbb0000 org.apache.ZooKeeperService:name0=3DStandaloneServer_port11222,n= ame1=3DConnections,name2=3D127.0.0.1,name3=3D0x1560c7d2fbb0000 > 2016-07-21 08:05:46,063 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@53] - RUNNING TEST METHOD testAsyncCreate > 2016-07-21 08:05:46,063 [myid:] - INFO [New I/O worker #101:ZooKeeperSer= ver@924] - got auth packet /127.0.0.1:49832 > 2016-07-21 08:05:46,063 [myid:] - INFO [New I/O worker #101:ZooKeeperSer= ver@958] - auth success /127.0.0.1:49832 > 2016-07-21 08:05:46,069 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@58] - Memory used 40629 > 2016-07-21 08:05:46,069 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@63] - Number of threads 51 > 2016-07-21 08:05:46,069 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@78] - FINISHED TEST METHOD testAsyncCreate > 2016-07-21 08:05:46,070 [myid:] - INFO [ProcessThread(sid:0 cport:11222)= ::PrepRequestProcessor@487] - Processed session termination for sessionid: = 0x1560c7d2fbb0000 > 2016-07-21 08:05:46,070 [myid:] - WARN [New I/O worker #101:NettyServerC= nxnFactory$CnxnChannelHandler@111] - Exception caught [id: 0xe25524be, /127= .0.0.1:49832 :> /127.0.0.1:11222] EXCEPTION: java.nio.channels.ClosedChanne= lException > java.nio.channels.ClosedChannelException > =09at sun.nio.ch.SocketChannelImpl.ensureWriteOpen(SocketChannelImpl.java= :270) > =09at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:479) > =09at org.jboss.netty.channel.socket.nio.SocketSendBufferPool$UnpooledSen= dBuffer.transferTo(SocketSendBufferPool.java:203) > =09at org.jboss.netty.channel.socket.nio.AbstractNioWorker.write0(Abstrac= tNioWorker.java:201) > =09at org.jboss.netty.channel.socket.nio.AbstractNioWorker.writeFromTaskL= oop(AbstractNioWorker.java:151) > =09at org.jboss.netty.channel.socket.nio.AbstractNioChannel$WriteTask.run= (AbstractNioChannel.java:315) > =09at org.jboss.netty.channel.socket.nio.AbstractNioSelector.processTaskQ= ueue(AbstractNioSelector.java:391) > =09at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(Abstract= NioSelector.java:315) > =09at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNi= oWorker.java:89) > =09at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178= ) > =09at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunna= ble.java:108) > =09at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockPro= ofWorker.java:42) > =09at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecuto= r.java:1145) > =09at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecut= or.java:615) > =09at java.lang.Thread.run(Thread.java:745) > 2016-07-21 08:05:46,171 [myid:] - INFO [main:ZooKeeper@684] - Session: 0= x1560c7d2fbb0000 closed > 2016-07-21 08:05:46,171 [myid:] - INFO [main:ClientBase@520] - tearDown = starting > 2016-07-21 08:05:46,171 [myid:] - INFO [main-EventThread:ClientCnxn$Even= tThread@519] - EventThread shut down for session: 0x1560c7d2fbb0000 > 2016-07-21 08:05:46,171 [myid:] - INFO [main:ClientBase@490] - STOPPING = server > 2016-07-21 08:05:46,172 [myid:] - INFO [main:NettyServerCnxnFactory@342]= - shutdown called 0.0.0.0/0.0.0.0:11222 > 2016-07-21 08:05:46,183 [myid:] - INFO [main:ZooKeeperServer@469] - shut= ting down > 2016-07-21 08:05:46,183 [myid:] - INFO [main:SessionTrackerImpl@225] - S= hutting down > 2016-07-21 08:05:46,183 [myid:] - INFO [main:PrepRequestProcessor@765] -= Shutting down > 2016-07-21 08:05:46,184 [myid:] - INFO [main:SyncRequestProcessor@209] -= Shutting down > 2016-07-21 08:05:46,184 [myid:] - INFO [ProcessThread(sid:0 cport:11222)= ::PrepRequestProcessor@143] - PrepRequestProcessor exited loop! > 2016-07-21 08:05:46,184 [myid:] - INFO [SyncThread:0:SyncRequestProcesso= r@187] - SyncRequestProcessor exited! > 2016-07-21 08:05:46,185 [myid:] - INFO [main:FinalRequestProcessor@402] = - shutdown of request processor complete > 2016-07-21 08:05:46,185 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11222 > 2016-07-21 08:05:46,186 [myid:] - INFO [main:JMXEnv@146] - ensureOnly:[] > 2016-07-21 08:05:46,189 [myid:] - INFO [main:ClientBase@545] - fdcount a= fter test is: 34 at start it was 33 > 2016-07-21 08:05:46,190 [myid:] - INFO [main:ClientBase@547] - sleeping = for 20 secs > 2016-07-21 08:05:46,190 [myid:] - INFO [main:AsyncOpsTest@60] - Test cli= ents shutting down > 2016-07-21 08:05:46,191 [myid:] - INFO [main:ZKTestCase$1@60] - SUCCEEDE= D testAsyncCreate > 2016-07-21 08:05:46,191 [myid:] - INFO [main:ZKTestCase$1@55] - FINISHED= testAsyncCreate > 2016-07-21 08:05:46,192 [myid:] - INFO [main:PortAssignment@32] - assign= ing port 11223 > 2016-07-21 08:05:46,193 [myid:] - INFO [main:ZKTestCase$1@50] - STARTING= testAsyncCreateThree > 2016-07-21 08:05:46,193 [myid:] - INFO [main:ClientBase@425] - Initial f= dcount is: 34 > 2016-07-21 08:05:46,204 [myid:] - INFO [main:ClientBase@443] - STARTING = server > 2016-07-21 08:05:46,204 [myid:] - INFO [main:ClientBase@364] - CREATING = server instance 127.0.0.1:11223 > 2016-07-21 08:05:46,212 [myid:] - INFO [main:ClientBase@339] - STARTING = server instance 127.0.0.1:11223 > 2016-07-21 08:05:46,212 [myid:] - INFO [main:ZooKeeperServer@170] - Crea= ted server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 6000= 0 datadir /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/bra= nch-3.4/build/test/tmp/test8798982101480729726.junit.dir/version-2 snapdir = /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/bu= ild/test/tmp/test8798982101480729726.junit.dir/version-2 > 2016-07-21 08:05:46,212 [myid:] - INFO [main:NettyServerCnxnFactory@365]= - binding to port 0.0.0.0/0.0.0.0:11223 > 2016-07-21 08:05:46,214 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11223 > 2016-07-21 08:05:46,215 [myid:] - INFO [New I/O worker #133:NettyServerC= nxn@632] - Processing stat command from /127.0.0.1:38741 > 2016-07-21 08:05:46,215 [myid:] - INFO [New I/O worker #133:NettyServerC= nxn$StatCommand@469] - Stat command output > 2016-07-21 08:05:46,216 [myid:] - INFO [main:JMXEnv@229] - ensureParent:= [InMemoryDataTree, StandaloneServer_port] > 2016-07-21 08:05:46,218 [myid:] - INFO [main:JMXEnv@246] - expect:InMemo= ryDataTree > 2016-07-21 08:05:46,218 [myid:] - INFO [main:JMXEnv@250] - found:InMemor= yDataTree org.apache.ZooKeeperService:name0=3DStandaloneServer_port11223,na= me1=3DInMemoryDataTree > 2016-07-21 08:05:46,218 [myid:] - INFO [main:JMXEnv@246] - expect:Standa= loneServer_port > 2016-07-21 08:05:46,218 [myid:] - INFO [main:JMXEnv@250] - found:Standal= oneServer_port org.apache.ZooKeeperService:name0=3DStandaloneServer_port112= 23 > 2016-07-21 08:05:46,218 [myid:] - INFO [main:ClientBase@439] - Client te= st setup finished > 2016-07-21 08:05:46,219 [myid:] - INFO [main:AsyncOpsTest@47] - Creating= client testAsyncCreateThree > 2016-07-21 08:05:46,219 [myid:] - INFO [main:ZooKeeper@438] - Initiating= client connection, connectString=3D127.0.0.1:11223 sessionTimeout=3D30000 = watcher=3Dorg.apache.zookeeper.test.ClientBase$CountdownWatcher@41327667 > 2016-07-21 08:05:46,220 [myid:] - INFO [main-SendThread(127.0.0.1:11223)= :ClientCnxn$SendThread@1032] - Opening socket connection to server 127.0.0.= 1/127.0.0.1:11223. Will not attempt to authenticate using SASL (unknown err= or) > 2016-07-21 08:05:46,220 [myid:] - INFO [main-SendThread(127.0.0.1:11223)= :ClientCnxn$SendThread@876] - Socket connection established to 127.0.0.1/12= 7.0.0.1:11223, initiating session > 2016-07-21 08:05:46,221 [myid:] - INFO [New I/O worker #134:ZooKeeperSer= ver@900] - Client attempting to establish new session at /127.0.0.1:38742 > 2016-07-21 08:05:46,221 [myid:] - INFO [SyncThread:0:FileTxnLog@203] - C= reating new log file: log.1 > 2016-07-21 08:05:46,223 [myid:] - INFO [SyncThread:0:ZooKeeperServer@645= ] - Established session 0x1560c7d30650000 with negotiated timeout 30000 for= client /127.0.0.1:38742 > 2016-07-21 08:05:46,224 [myid:] - INFO [main-SendThread(127.0.0.1:11223)= :ClientCnxn$SendThread@1299] - Session establishment complete on server 127= .0.0.1/127.0.0.1:11223, sessionid =3D 0x1560c7d30650000, negotiated timeout= =3D 30000 > 2016-07-21 08:05:46,226 [myid:] - INFO [main:JMXEnv@117] - expect:0x1560= c7d30650000 > 2016-07-21 08:05:46,226 [myid:] - INFO [main:JMXEnv@120] - found:0x1560c= 7d30650000 org.apache.ZooKeeperService:name0=3DStandaloneServer_port11223,n= ame1=3DConnections,name2=3D127.0.0.1,name3=3D0x1560c7d30650000 > 2016-07-21 08:05:46,226 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@53] - RUNNING TEST METHOD testAsyncCreateThree > 2016-07-21 08:05:46,227 [myid:] - INFO [New I/O worker #134:ZooKeeperSer= ver@924] - got auth packet /127.0.0.1:38742 > 2016-07-21 08:05:46,227 [myid:] - INFO [New I/O worker #134:ZooKeeperSer= ver@958] - auth success /127.0.0.1:38742 > 2016-07-21 08:05:46,230 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@58] - Memory used 77876 > 2016-07-21 08:05:46,230 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@63] - Number of threads 52 > 2016-07-21 08:05:46,230 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@78] - FINISHED TEST METHOD testAsyncCreateThree > 2016-07-21 08:05:46,231 [myid:] - INFO [ProcessThread(sid:0 cport:11223)= ::PrepRequestProcessor@487] - Processed session termination for sessionid: = 0x1560c7d30650000 > 2016-07-21 08:05:46,232 [myid:] - WARN [New I/O worker #134:NettyServerC= nxnFactory$CnxnChannelHandler@111] - Exception caught [id: 0x84929b58, /127= .0.0.1:38742 :> /127.0.0.1:11223] EXCEPTION: java.nio.channels.ClosedChanne= lException > java.nio.channels.ClosedChannelException > =09at sun.nio.ch.SocketChannelImpl.ensureWriteOpen(SocketChannelImpl.java= :270) > =09at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:479) > =09at org.jboss.netty.channel.socket.nio.SocketSendBufferPool$UnpooledSen= dBuffer.transferTo(SocketSendBufferPool.java:203) > =09at org.jboss.netty.channel.socket.nio.AbstractNioWorker.write0(Abstrac= tNioWorker.java:201) > =09at org.jboss.netty.channel.socket.nio.AbstractNioWorker.writeFromTaskL= oop(AbstractNioWorker.java:151) > =09at org.jboss.netty.channel.socket.nio.AbstractNioChannel$WriteTask.run= (AbstractNioChannel.java:315) > =09at org.jboss.netty.channel.socket.nio.AbstractNioSelector.processTaskQ= ueue(AbstractNioSelector.java:391) > =09at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(Abstract= NioSelector.java:315) > =09at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNi= oWorker.java:89) > =09at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178= ) > =09at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunna= ble.java:108) > =09at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockPro= ofWorker.java:42) > =09at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecuto= r.java:1145) > =09at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecut= or.java:615) > =09at java.lang.Thread.run(Thread.java:745) > 2016-07-21 08:05:46,332 [myid:] - INFO [main:ZooKeeper@684] - Session: 0= x1560c7d30650000 closed > 2016-07-21 08:05:46,333 [myid:] - INFO [main:ClientBase@520] - tearDown = starting > 2016-07-21 08:05:46,333 [myid:] - INFO [main:ClientBase@490] - STOPPING = server > 2016-07-21 08:05:46,332 [myid:] - INFO [main-EventThread:ClientCnxn$Even= tThread@519] - EventThread shut down for session: 0x1560c7d30650000 > 2016-07-21 08:05:46,333 [myid:] - INFO [main:NettyServerCnxnFactory@342]= - shutdown called 0.0.0.0/0.0.0.0:11223 > 2016-07-21 08:05:46,340 [myid:] - INFO [main:ZooKeeperServer@469] - shut= ting down > 2016-07-21 08:05:46,341 [myid:] - INFO [main:SessionTrackerImpl@225] - S= hutting down > 2016-07-21 08:05:46,341 [myid:] - INFO [main:PrepRequestProcessor@765] -= Shutting down > 2016-07-21 08:05:46,341 [myid:] - INFO [main:SyncRequestProcessor@209] -= Shutting down > 2016-07-21 08:05:46,341 [myid:] - INFO [ProcessThread(sid:0 cport:11223)= ::PrepRequestProcessor@143] - PrepRequestProcessor exited loop! > 2016-07-21 08:05:46,342 [myid:] - INFO [SyncThread:0:SyncRequestProcesso= r@187] - SyncRequestProcessor exited! > 2016-07-21 08:05:46,342 [myid:] - INFO [main:FinalRequestProcessor@402] = - shutdown of request processor complete > 2016-07-21 08:05:46,343 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11223 > 2016-07-21 08:05:46,343 [myid:] - INFO [main:JMXEnv@146] - ensureOnly:[] > 2016-07-21 08:05:46,346 [myid:] - INFO [main:ClientBase@545] - fdcount a= fter test is: 34 at start it was 34 > 2016-07-21 08:05:46,346 [myid:] - INFO [main:AsyncOpsTest@60] - Test cli= ents shutting down > 2016-07-21 08:05:46,347 [myid:] - INFO [main:ZKTestCase$1@60] - SUCCEEDE= D testAsyncCreateThree > 2016-07-21 08:05:46,347 [myid:] - INFO [main:ZKTestCase$1@55] - FINISHED= testAsyncCreateThree > 2016-07-21 08:05:46,347 [myid:] - INFO [main:PortAssignment@32] - assign= ing port 11224 > 2016-07-21 08:05:46,348 [myid:] - INFO [main:ZKTestCase$1@50] - STARTING= testAsyncCreateFailure_NodeExists > 2016-07-21 08:05:46,348 [myid:] - INFO [main:ClientBase@425] - Initial f= dcount is: 34 > 2016-07-21 08:05:46,355 [myid:] - INFO [main:ClientBase@443] - STARTING = server > 2016-07-21 08:05:46,355 [myid:] - INFO [main:ClientBase@364] - CREATING = server instance 127.0.0.1:11224 > 2016-07-21 08:05:46,362 [myid:] - INFO [main:ClientBase@339] - STARTING = server instance 127.0.0.1:11224 > 2016-07-21 08:05:46,363 [myid:] - INFO [main:ZooKeeperServer@170] - Crea= ted server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 6000= 0 datadir /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/bra= nch-3.4/build/test/tmp/test937004609623311539.junit.dir/version-2 snapdir /= home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/bui= ld/test/tmp/test937004609623311539.junit.dir/version-2 > 2016-07-21 08:05:46,363 [myid:] - INFO [main:NettyServerCnxnFactory@365]= - binding to port 0.0.0.0/0.0.0.0:11224 > 2016-07-21 08:05:46,364 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11224 > 2016-07-21 08:05:46,365 [myid:] - INFO [New I/O worker #166:NettyServerC= nxn@632] - Processing stat command from /127.0.0.1:54116 > 2016-07-21 08:05:46,366 [myid:] - INFO [New I/O worker #166:NettyServerC= nxn$StatCommand@469] - Stat command output > 2016-07-21 08:05:46,366 [myid:] - INFO [main:JMXEnv@229] - ensureParent:= [InMemoryDataTree, StandaloneServer_port] > 2016-07-21 08:05:46,368 [myid:] - INFO [main:JMXEnv@246] - expect:InMemo= ryDataTree > 2016-07-21 08:05:46,368 [myid:] - INFO [main:JMXEnv@250] - found:InMemor= yDataTree org.apache.ZooKeeperService:name0=3DStandaloneServer_port11224,na= me1=3DInMemoryDataTree > 2016-07-21 08:05:46,368 [myid:] - INFO [main:JMXEnv@246] - expect:Standa= loneServer_port > 2016-07-21 08:05:46,369 [myid:] - INFO [main:JMXEnv@250] - found:Standal= oneServer_port org.apache.ZooKeeperService:name0=3DStandaloneServer_port112= 24 > 2016-07-21 08:05:46,369 [myid:] - INFO [main:ClientBase@439] - Client te= st setup finished > 2016-07-21 08:05:46,369 [myid:] - INFO [main:AsyncOpsTest@47] - Creating= client testAsyncCreateFailure_NodeExists > 2016-07-21 08:05:46,369 [myid:] - INFO [main:ZooKeeper@438] - Initiating= client connection, connectString=3D127.0.0.1:11224 sessionTimeout=3D30000 = watcher=3Dorg.apache.zookeeper.test.ClientBase$CountdownWatcher@78f394a2 > 2016-07-21 08:05:46,370 [myid:] - INFO [main-SendThread(127.0.0.1:11224)= :ClientCnxn$SendThread@1032] - Opening socket connection to server 127.0.0.= 1/127.0.0.1:11224. Will not attempt to authenticate using SASL (unknown err= or) > 2016-07-21 08:05:46,371 [myid:] - INFO [main-SendThread(127.0.0.1:11224)= :ClientCnxn$SendThread@876] - Socket connection established to 127.0.0.1/12= 7.0.0.1:11224, initiating session > 2016-07-21 08:05:46,371 [myid:] - INFO [New I/O worker #167:ZooKeeperSer= ver@900] - Client attempting to establish new session at /127.0.0.1:54117 > 2016-07-21 08:05:46,372 [myid:] - INFO [SyncThread:0:FileTxnLog@203] - C= reating new log file: log.1 > 2016-07-21 08:05:46,374 [myid:] - INFO [SyncThread:0:ZooKeeperServer@645= ] - Established session 0x1560c7d30fb0000 with negotiated timeout 30000 for= client /127.0.0.1:54117 > 2016-07-21 08:05:46,374 [myid:] - INFO [main-SendThread(127.0.0.1:11224)= :ClientCnxn$SendThread@1299] - Session establishment complete on server 127= .0.0.1/127.0.0.1:11224, sessionid =3D 0x1560c7d30fb0000, negotiated timeout= =3D 30000 > 2016-07-21 08:05:46,376 [myid:] - INFO [main:JMXEnv@117] - expect:0x1560= c7d30fb0000 > 2016-07-21 08:05:46,377 [myid:] - INFO [main:JMXEnv@120] - found:0x1560c= 7d30fb0000 org.apache.ZooKeeperService:name0=3DStandaloneServer_port11224,n= ame1=3DConnections,name2=3D127.0.0.1,name3=3D0x1560c7d30fb0000 > 2016-07-21 08:05:46,377 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@53] - RUNNING TEST METHOD testAsyncCreateFailure_NodeExists > 2016-07-21 08:05:46,377 [myid:] - INFO [New I/O worker #167:ZooKeeperSer= ver@924] - got auth packet /127.0.0.1:54117 > 2016-07-21 08:05:46,378 [myid:] - INFO [New I/O worker #167:ZooKeeperSer= ver@958] - auth success /127.0.0.1:54117 > 2016-07-21 08:05:46,382 [myid:] - INFO [ProcessThread(sid:0 cport:11224)= ::PrepRequestProcessor@649] - Got user-level KeeperException when processin= g sessionid:0x1560c7d30fb0000 type:create cxid:0x2 zxid:0x3 txntype:-1 reqp= ath:n/a Error Path:/foo Error:KeeperErrorCode =3D NodeExists for /foo > 2016-07-21 08:05:46,382 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@58] - Memory used 115887 > 2016-07-21 08:05:46,383 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@63] - Number of threads 53 > 2016-07-21 08:05:46,383 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@78] - FINISHED TEST METHOD testAsyncCreateFailure_NodeExists > 2016-07-21 08:05:46,384 [myid:] - INFO [ProcessThread(sid:0 cport:11224)= ::PrepRequestProcessor@487] - Processed session termination for sessionid: = 0x1560c7d30fb0000 > 2016-07-21 08:05:46,385 [myid:] - WARN [New I/O worker #167:NettyServerC= nxnFactory$CnxnChannelHandler@111] - Exception caught [id: 0x08491bfc, /127= .0.0.1:54117 :> /127.0.0.1:11224] EXCEPTION: java.nio.channels.ClosedChanne= lException > java.nio.channels.ClosedChannelException > =09at sun.nio.ch.SocketChannelImpl.ensureWriteOpen(SocketChannelImpl.java= :270) > =09at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:479) > =09at org.jboss.netty.channel.socket.nio.SocketSendBufferPool$UnpooledSen= dBuffer.transferTo(SocketSendBufferPool.java:203) > =09at org.jboss.netty.channel.socket.nio.AbstractNioWorker.write0(Abstrac= tNioWorker.java:201) > =09at org.jboss.netty.channel.socket.nio.AbstractNioWorker.writeFromTaskL= oop(AbstractNioWorker.java:151) > =09at org.jboss.netty.channel.socket.nio.AbstractNioChannel$WriteTask.run= (AbstractNioChannel.java:315) > =09at org.jboss.netty.channel.socket.nio.AbstractNioSelector.processTaskQ= ueue(AbstractNioSelector.java:391) > =09at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(Abstract= NioSelector.java:315) > =09at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNi= oWorker.java:89) > =09at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178= ) > =09at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunna= ble.java:108) > =09at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockPro= ofWorker.java:42) > =09at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecuto= r.java:1145) > =09at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecut= or.java:615) > =09at java.lang.Thread.run(Thread.java:745) > 2016-07-21 08:05:46,485 [myid:] - INFO [main:ZooKeeper@684] - Session: 0= x1560c7d30fb0000 closed > 2016-07-21 08:05:46,485 [myid:] - INFO [main:ClientBase@520] - tearDown = starting > 2016-07-21 08:05:46,485 [myid:] - INFO [main:ClientBase@490] - STOPPING = server > 2016-07-21 08:05:46,486 [myid:] - INFO [main:NettyServerCnxnFactory@342]= - shutdown called 0.0.0.0/0.0.0.0:11224 > 2016-07-21 08:05:46,485 [myid:] - INFO [main-EventThread:ClientCnxn$Even= tThread@519] - EventThread shut down for session: 0x1560c7d30fb0000 > 2016-07-21 08:05:46,495 [myid:] - INFO [main:ZooKeeperServer@469] - shut= ting down > 2016-07-21 08:05:46,495 [myid:] - INFO [main:SessionTrackerImpl@225] - S= hutting down > 2016-07-21 08:05:46,495 [myid:] - INFO [main:PrepRequestProcessor@765] -= Shutting down > 2016-07-21 08:05:46,496 [myid:] - INFO [main:SyncRequestProcessor@209] -= Shutting down > 2016-07-21 08:05:46,496 [myid:] - INFO [ProcessThread(sid:0 cport:11224)= ::PrepRequestProcessor@143] - PrepRequestProcessor exited loop! > 2016-07-21 08:05:46,496 [myid:] - INFO [SyncThread:0:SyncRequestProcesso= r@187] - SyncRequestProcessor exited! > 2016-07-21 08:05:46,496 [myid:] - INFO [main:FinalRequestProcessor@402] = - shutdown of request processor complete > 2016-07-21 08:05:46,498 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11224 > 2016-07-21 08:05:46,499 [myid:] - INFO [main:JMXEnv@146] - ensureOnly:[] > 2016-07-21 08:05:46,502 [myid:] - INFO [main:ClientBase@545] - fdcount a= fter test is: 34 at start it was 34 > 2016-07-21 08:05:46,502 [myid:] - INFO [main:AsyncOpsTest@60] - Test cli= ents shutting down > 2016-07-21 08:05:46,502 [myid:] - INFO [main:ZKTestCase$1@60] - SUCCEEDE= D testAsyncCreateFailure_NodeExists > 2016-07-21 08:05:46,502 [myid:] - INFO [main:ZKTestCase$1@55] - FINISHED= testAsyncCreateFailure_NodeExists > 2016-07-21 08:05:46,503 [myid:] - INFO [main:PortAssignment@32] - assign= ing port 11225 > 2016-07-21 08:05:46,503 [myid:] - INFO [main:ZKTestCase$1@50] - STARTING= testAsyncCreateFailure_NoNode > 2016-07-21 08:05:46,504 [myid:] - INFO [main:ClientBase@425] - Initial f= dcount is: 34 > 2016-07-21 08:05:46,514 [myid:] - INFO [main:ClientBase@443] - STARTING = server > 2016-07-21 08:05:46,514 [myid:] - INFO [main:ClientBase@364] - CREATING = server instance 127.0.0.1:11225 > 2016-07-21 08:05:46,525 [myid:] - INFO [main:ClientBase@339] - STARTING = server instance 127.0.0.1:11225 > 2016-07-21 08:05:46,525 [myid:] - INFO [main:ZooKeeperServer@170] - Crea= ted server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 6000= 0 datadir /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/bra= nch-3.4/build/test/tmp/test5380464042991622148.junit.dir/version-2 snapdir = /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/bu= ild/test/tmp/test5380464042991622148.junit.dir/version-2 > 2016-07-21 08:05:46,525 [myid:] - INFO [main:NettyServerCnxnFactory@365]= - bindin > ...[truncated 880056 chars]... > ocessor exited loop! > 2016-07-21 08:08:01,738 [myid:] - INFO [SyncThread:0:SyncRequestProcesso= r@187] - SyncRequestProcessor exited! > 2016-07-21 08:08:01,739 [myid:] - INFO [main:FinalRequestProcessor@402] = - shutdown of request processor complete > 2016-07-21 08:08:01,740 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11289 > 2016-07-21 08:08:01,740 [myid:] - INFO [main:JMXEnv@146] - ensureOnly:[] > 2016-07-21 08:08:02,332 [myid:] - INFO [main:ClientBase@443] - STARTING = server > 2016-07-21 08:08:02,332 [myid:] - INFO [main:ClientBase@364] - CREATING = server instance 127.0.0.1:11289 > 2016-07-21 08:08:02,340 [myid:] - INFO [main:ClientBase@339] - STARTING = server instance 127.0.0.1:11289 > 2016-07-21 08:08:02,341 [myid:] - INFO [main:ZooKeeperServer@170] - Crea= ted server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 6000= 0 datadir /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/bra= nch-3.4/build/test/tmp/test4028127123136724556.junit.dir/version-2 snapdir = /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/bu= ild/test/tmp/test4028127123136724556.junit.dir/version-2 > 2016-07-21 08:08:02,341 [myid:] - INFO [main:NettyServerCnxnFactory@365]= - binding to port 0.0.0.0/0.0.0.0:11289 > 2016-07-21 08:08:02,344 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11289 > 2016-07-21 08:08:02,345 [myid:] - INFO [New I/O worker #2707:NettyServer= Cnxn@632] - Processing stat command from /127.0.0.1:36112 > 2016-07-21 08:08:02,345 [myid:] - INFO [New I/O worker #2707:NettyServer= Cnxn$StatCommand@469] - Stat command output > 2016-07-21 08:08:02,345 [myid:] - INFO [main:JMXEnv@229] - ensureParent:= [InMemoryDataTree, StandaloneServer_port] > 2016-07-21 08:08:02,346 [myid:] - INFO [main:JMXEnv@246] - expect:InMemo= ryDataTree > 2016-07-21 08:08:02,347 [myid:] - INFO [main:JMXEnv@250] - found:InMemor= yDataTree org.apache.ZooKeeperService:name0=3DStandaloneServer_port11289,na= me1=3DInMemoryDataTree > 2016-07-21 08:08:02,347 [myid:] - INFO [main:JMXEnv@246] - expect:Standa= loneServer_port > 2016-07-21 08:08:02,347 [myid:] - INFO [main:JMXEnv@250] - found:Standal= oneServer_port org.apache.ZooKeeperService:name0=3DStandaloneServer_port112= 89 > 2016-07-21 08:08:03,000 [myid:] - INFO [SessionTracker:SessionTrackerImp= l@162] - SessionTrackerImpl exited loop! > 2016-07-21 08:08:03,274 [myid:] - INFO [main-SendThread(127.0.0.1:11289)= :ClientCnxn$SendThread@1032] - Opening socket connection to server 127.0.0.= 1/127.0.0.1:11289. Will not attempt to authenticate using SASL (unknown err= or) > 2016-07-21 08:08:03,274 [myid:] - INFO [main-SendThread(127.0.0.1:11289)= :ClientCnxn$SendThread@876] - Socket connection established to 127.0.0.1/12= 7.0.0.1:11289, initiating session > 2016-07-21 08:08:03,275 [myid:] - INFO [New I/O worker #2708:ZooKeeperSe= rver@893] - Client attempting to renew session 0x1560c7f3a630000 at /127.0.= 0.1:36116 > 2016-07-21 08:08:03,276 [myid:] - INFO [New I/O worker #2708:ZooKeeperSe= rver@645] - Established session 0x1560c7f3a630000 with negotiated timeout 6= 000 for client /127.0.0.1:36116 > 2016-07-21 08:08:03,276 [myid:] - INFO [main-SendThread(127.0.0.1:11289)= :ClientCnxn$SendThread@1299] - Session establishment complete on server 127= .0.0.1/127.0.0.1:11289, sessionid =3D 0x1560c7f3a630000, negotiated timeout= =3D 6000 > 2016-07-21 08:08:03,281 [myid:] - INFO [SyncThread:0:FileTxnLog@203] - C= reating new log file: log.6 > 2016-07-21 08:08:03,283 [myid:] - INFO [main:ClientBase@490] - STOPPING = server > 2016-07-21 08:08:03,283 [myid:] - INFO [main:NettyServerCnxnFactory@342]= - shutdown called 0.0.0.0/0.0.0.0:11289 > 2016-07-21 08:08:03,284 [myid:] - INFO [main-SendThread(127.0.0.1:11289)= :ClientCnxn$SendThread@1158] - Unable to read additional data from server s= essionid 0x1560c7f3a630000, likely server has closed socket, closing socket= connection and attempting reconnect > 2016-07-21 08:08:03,293 [myid:] - INFO [main:ZooKeeperServer@469] - shut= ting down > 2016-07-21 08:08:03,295 [myid:] - INFO [main:SessionTrackerImpl@225] - S= hutting down > 2016-07-21 08:08:03,296 [myid:] - INFO [main:PrepRequestProcessor@765] -= Shutting down > 2016-07-21 08:08:03,296 [myid:] - INFO [main:SyncRequestProcessor@209] -= Shutting down > 2016-07-21 08:08:03,296 [myid:] - INFO [ProcessThread(sid:0 cport:11289)= ::PrepRequestProcessor@143] - PrepRequestProcessor exited loop! > 2016-07-21 08:08:03,296 [myid:] - INFO [SyncThread:0:SyncRequestProcesso= r@187] - SyncRequestProcessor exited! > 2016-07-21 08:08:03,297 [myid:] - INFO [main:FinalRequestProcessor@402] = - shutdown of request processor complete > 2016-07-21 08:08:03,298 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11289 > 2016-07-21 08:08:03,298 [myid:] - INFO [main:JMXEnv@146] - ensureOnly:[] > 2016-07-21 08:08:03,384 [myid:] - INFO [main:ClientBase@443] - STARTING = server > 2016-07-21 08:08:03,385 [myid:] - INFO [main:ClientBase@364] - CREATING = server instance 127.0.0.1:11289 > 2016-07-21 08:08:03,392 [myid:] - INFO [main:ClientBase@339] - STARTING = server instance 127.0.0.1:11289 > 2016-07-21 08:08:03,392 [myid:] - INFO [main:ZooKeeperServer@170] - Crea= ted server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 6000= 0 datadir /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/bra= nch-3.4/build/test/tmp/test4028127123136724556.junit.dir/version-2 snapdir = /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/bu= ild/test/tmp/test4028127123136724556.junit.dir/version-2 > 2016-07-21 08:08:03,392 [myid:] - INFO [main:NettyServerCnxnFactory@365]= - binding to port 0.0.0.0/0.0.0.0:11289 > 2016-07-21 08:08:03,395 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11289 > 2016-07-21 08:08:03,396 [myid:] - INFO [New I/O worker #2740:NettyServer= Cnxn@632] - Processing stat command from /127.0.0.1:36118 > 2016-07-21 08:08:03,396 [myid:] - INFO [New I/O worker #2740:NettyServer= Cnxn$StatCommand@469] - Stat command output > 2016-07-21 08:08:03,397 [myid:] - INFO [main:JMXEnv@229] - ensureParent:= [InMemoryDataTree, StandaloneServer_port] > 2016-07-21 08:08:03,398 [myid:] - INFO [main:JMXEnv@246] - expect:InMemo= ryDataTree > 2016-07-21 08:08:03,398 [myid:] - INFO [main:JMXEnv@250] - found:InMemor= yDataTree org.apache.ZooKeeperService:name0=3DStandaloneServer_port11289,na= me1=3DInMemoryDataTree > 2016-07-21 08:08:03,399 [myid:] - INFO [main:JMXEnv@246] - expect:Standa= loneServer_port > 2016-07-21 08:08:03,399 [myid:] - INFO [main:JMXEnv@250] - found:Standal= oneServer_port org.apache.ZooKeeperService:name0=3DStandaloneServer_port112= 89 > 2016-07-21 08:08:04,956 [myid:] - INFO [main-SendThread(127.0.0.1:11289)= :ClientCnxn$SendThread@1032] - Opening socket connection to server 127.0.0.= 1/127.0.0.1:11289. Will not attempt to authenticate using SASL (unknown err= or) > 2016-07-21 08:08:04,956 [myid:] - INFO [main-SendThread(127.0.0.1:11289)= :ClientCnxn$SendThread@876] - Socket connection established to 127.0.0.1/12= 7.0.0.1:11289, initiating session > 2016-07-21 08:08:04,957 [myid:] - INFO [New I/O worker #2741:ZooKeeperSe= rver@893] - Client attempting to renew session 0x1560c7f3a630000 at /127.0.= 0.1:36123 > 2016-07-21 08:08:04,958 [myid:] - INFO [New I/O worker #2741:ZooKeeperSe= rver@645] - Established session 0x1560c7f3a630000 with negotiated timeout 6= 000 for client /127.0.0.1:36123 > 2016-07-21 08:08:04,958 [myid:] - INFO [main-SendThread(127.0.0.1:11289)= :ClientCnxn$SendThread@1299] - Session establishment complete on server 127= .0.0.1/127.0.0.1:11289, sessionid =3D 0x1560c7f3a630000, negotiated timeout= =3D 6000 > 2016-07-21 08:08:04,959 [myid:] - INFO [SyncThread:0:FileTxnLog@203] - C= reating new log file: log.7 > 2016-07-21 08:08:05,963 [myid:] - INFO [ProcessThread(sid:0 cport:11289)= ::PrepRequestProcessor@487] - Processed session termination for sessionid: = 0x1560c7f3a630000 > 2016-07-21 08:08:05,964 [myid:] - INFO [main:ZooKeeper@684] - Session: 0= x1560c7f3a630000 closed > 2016-07-21 08:08:05,964 [myid:] - INFO [main-EventThread:ClientCnxn$Even= tThread@519] - EventThread shut down for session: 0x1560c7f3a630000 > 2016-07-21 08:08:05,965 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@58] - Memory used 71640 > 2016-07-21 08:08:05,965 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@63] - Number of threads 65 > 2016-07-21 08:08:05,965 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@78] - FINISHED TEST METHOD testWatcherAutoResetWithLocal > 2016-07-21 08:08:05,965 [myid:] - INFO [main:ClientBase@520] - tearDown = starting > 2016-07-21 08:08:05,965 [myid:] - INFO [main:ClientBase@490] - STOPPING = server > 2016-07-21 08:08:05,965 [myid:] - INFO [main:NettyServerCnxnFactory@342]= - shutdown called 0.0.0.0/0.0.0.0:11289 > 2016-07-21 08:08:05,972 [myid:] - INFO [main:ZooKeeperServer@469] - shut= ting down > 2016-07-21 08:08:05,975 [myid:] - INFO [main:SessionTrackerImpl@225] - S= hutting down > 2016-07-21 08:08:05,975 [myid:] - INFO [main:PrepRequestProcessor@765] -= Shutting down > 2016-07-21 08:08:05,975 [myid:] - INFO [main:SyncRequestProcessor@209] -= Shutting down > 2016-07-21 08:08:05,975 [myid:] - INFO [ProcessThread(sid:0 cport:11289)= ::PrepRequestProcessor@143] - PrepRequestProcessor exited loop! > 2016-07-21 08:08:05,975 [myid:] - INFO [SyncThread:0:SyncRequestProcesso= r@187] - SyncRequestProcessor exited! > 2016-07-21 08:08:05,976 [myid:] - INFO [main:FinalRequestProcessor@402] = - shutdown of request processor complete > 2016-07-21 08:08:05,977 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11289 > 2016-07-21 08:08:05,978 [myid:] - INFO [main:JMXEnv@146] - ensureOnly:[] > 2016-07-21 08:08:05,981 [myid:] - INFO [main:ClientBase@545] - fdcount a= fter test is: 45 at start it was 41 > 2016-07-21 08:08:05,981 [myid:] - INFO [main:ClientBase@547] - sleeping = for 20 secs > 2016-07-21 08:08:05,981 [myid:] - INFO [main:ZKTestCase$1@60] - SUCCEEDE= D testWatcherAutoResetWithLocal > 2016-07-21 08:08:05,982 [myid:] - INFO [main:ZKTestCase$1@55] - FINISHED= testWatcherAutoResetWithLocal > 2016-07-21 08:08:05,983 [myid:] - INFO [main:PortAssignment@32] - assign= ing port 11290 > 2016-07-21 08:08:05,983 [myid:] - INFO [main:ZKTestCase$1@50] - STARTING= testWatcherAutoResetDisabledWithGlobal > 2016-07-21 08:08:05,983 [myid:] - INFO [main:ClientBase@425] - Initial f= dcount is: 45 > 2016-07-21 08:08:05,991 [myid:] - INFO [main:ClientBase@443] - STARTING = server > 2016-07-21 08:08:05,992 [myid:] - INFO [main:ClientBase@364] - CREATING = server instance 127.0.0.1:11290 > 2016-07-21 08:08:06,000 [myid:] - INFO [SessionTracker:SessionTrackerImp= l@162] - SessionTrackerImpl exited loop! > 2016-07-21 08:08:06,000 [myid:] - INFO [SessionTracker:SessionTrackerImp= l@162] - SessionTrackerImpl exited loop! > 2016-07-21 08:08:06,002 [myid:] - INFO [main:ClientBase@339] - STARTING = server instance 127.0.0.1:11290 > 2016-07-21 08:08:06,002 [myid:] - INFO [main:ZooKeeperServer@170] - Crea= ted server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 6000= 0 datadir /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/bra= nch-3.4/build/test/tmp/test6527239161822360616.junit.dir/version-2 snapdir = /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/bu= ild/test/tmp/test6527239161822360616.junit.dir/version-2 > 2016-07-21 08:08:06,002 [myid:] - INFO [main:NettyServerCnxnFactory@365]= - binding to port 0.0.0.0/0.0.0.0:11290 > 2016-07-21 08:08:06,004 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11290 > 2016-07-21 08:08:06,005 [myid:] - INFO [New I/O worker #2773:NettyServer= Cnxn@632] - Processing stat command from /127.0.0.1:59460 > 2016-07-21 08:08:06,005 [myid:] - INFO [New I/O worker #2773:NettyServer= Cnxn$StatCommand@469] - Stat command output > 2016-07-21 08:08:06,006 [myid:] - INFO [main:JMXEnv@229] - ensureParent:= [InMemoryDataTree, StandaloneServer_port] > 2016-07-21 08:08:06,007 [myid:] - INFO [main:JMXEnv@246] - expect:InMemo= ryDataTree > 2016-07-21 08:08:06,007 [myid:] - INFO [main:JMXEnv@250] - found:InMemor= yDataTree org.apache.ZooKeeperService:name0=3DStandaloneServer_port11290,na= me1=3DInMemoryDataTree > 2016-07-21 08:08:06,007 [myid:] - INFO [main:JMXEnv@246] - expect:Standa= loneServer_port > 2016-07-21 08:08:06,007 [myid:] - INFO [main:JMXEnv@250] - found:Standal= oneServer_port org.apache.ZooKeeperService:name0=3DStandaloneServer_port112= 90 > 2016-07-21 08:08:06,007 [myid:] - INFO [main:ClientBase@439] - Client te= st setup finished > 2016-07-21 08:08:06,008 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@53] - RUNNING TEST METHOD testWatcherAutoResetDisabledWithGlobal > 2016-07-21 08:08:06,008 [myid:] - INFO [main:ZooKeeper@438] - Initiating= client connection, connectString=3D127.0.0.1:11290 sessionTimeout=3D5000 w= atcher=3Dorg.apache.zookeeper.test.WatcherTest$MyWatcher@63979eb4 > 2016-07-21 08:08:06,009 [myid:] - INFO [main-SendThread(127.0.0.1:11290)= :ClientCnxn$SendThread@1032] - Opening socket connection to server 127.0.0.= 1/127.0.0.1:11290. Will not attempt to authenticate using SASL (unknown err= or) > 2016-07-21 08:08:06,009 [myid:] - INFO [main-SendThread(127.0.0.1:11290)= :ClientCnxn$SendThread@876] - Socket connection established to 127.0.0.1/12= 7.0.0.1:11290, initiating session > 2016-07-21 08:08:06,010 [myid:] - INFO [New I/O worker #2774:ZooKeeperSe= rver@900] - Client attempting to establish new session at /127.0.0.1:59461 > 2016-07-21 08:08:06,010 [myid:] - INFO [SyncThread:0:FileTxnLog@203] - C= reating new log file: log.1 > 2016-07-21 08:08:06,012 [myid:] - INFO [SyncThread:0:ZooKeeperServer@645= ] - Established session 0x1560c7f52730000 with negotiated timeout 6000 for = client /127.0.0.1:59461 > 2016-07-21 08:08:06,012 [myid:] - INFO [main-SendThread(127.0.0.1:11290)= :ClientCnxn$SendThread@1299] - Session establishment complete on server 127= .0.0.1/127.0.0.1:11290, sessionid =3D 0x1560c7f52730000, negotiated timeout= =3D 6000 > 2016-07-21 08:08:06,013 [myid:] - INFO [main:JMXEnv@117] - expect:0x1560= c7f52730000 > 2016-07-21 08:08:06,013 [myid:] - INFO [main:JMXEnv@120] - found:0x1560c= 7f52730000 org.apache.ZooKeeperService:name0=3DStandaloneServer_port11290,n= ame1=3DConnections,name2=3D127.0.0.1,name3=3D0x1560c7f52730000 > 2016-07-21 08:08:06,018 [myid:] - INFO [main:ClientBase@490] - STOPPING = server > 2016-07-21 08:08:06,019 [myid:] - INFO [main:NettyServerCnxnFactory@342]= - shutdown called 0.0.0.0/0.0.0.0:11290 > 2016-07-21 08:08:06,019 [myid:] - INFO [main-SendThread(127.0.0.1:11290)= :ClientCnxn$SendThread@1158] - Unable to read additional data from server s= essionid 0x1560c7f52730000, likely server has closed socket, closing socket= connection and attempting reconnect > 2016-07-21 08:08:06,023 [myid:] - INFO [main:ZooKeeperServer@469] - shut= ting down > 2016-07-21 08:08:06,023 [myid:] - INFO [main:SessionTrackerImpl@225] - S= hutting down > 2016-07-21 08:08:06,024 [myid:] - INFO [main:PrepRequestProcessor@765] -= Shutting down > 2016-07-21 08:08:06,024 [myid:] - INFO [main:SyncRequestProcessor@209] -= Shutting down > 2016-07-21 08:08:06,024 [myid:] - INFO [ProcessThread(sid:0 cport:11290)= ::PrepRequestProcessor@143] - PrepRequestProcessor exited loop! > 2016-07-21 08:08:06,024 [myid:] - INFO [SyncThread:0:SyncRequestProcesso= r@187] - SyncRequestProcessor exited! > 2016-07-21 08:08:06,026 [myid:] - INFO [main:FinalRequestProcessor@402] = - shutdown of request processor complete > 2016-07-21 08:08:06,027 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11290 > 2016-07-21 08:08:06,027 [myid:] - INFO [main:JMXEnv@146] - ensureOnly:[] > 2016-07-21 08:08:06,119 [myid:] - INFO [main:ClientBase@443] - STARTING = server > 2016-07-21 08:08:06,120 [myid:] - INFO [main:ClientBase@364] - CREATING = server instance 127.0.0.1:11290 > 2016-07-21 08:08:06,126 [myid:] - INFO [main:ClientBase@339] - STARTING = server instance 127.0.0.1:11290 > 2016-07-21 08:08:06,127 [myid:] - INFO [main:ZooKeeperServer@170] - Crea= ted server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 6000= 0 datadir /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/bra= nch-3.4/build/test/tmp/test6527239161822360616.junit.dir/version-2 snapdir = /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/bu= ild/test/tmp/test6527239161822360616.junit.dir/version-2 > 2016-07-21 08:08:06,127 [myid:] - INFO [main:NettyServerCnxnFactory@365]= - binding to port 0.0.0.0/0.0.0.0:11290 > 2016-07-21 08:08:06,129 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11290 > 2016-07-21 08:08:06,130 [myid:] - INFO [New I/O worker #2806:NettyServer= Cnxn@632] - Processing stat command from /127.0.0.1:59463 > 2016-07-21 08:08:06,130 [myid:] - INFO [New I/O worker #2806:NettyServer= Cnxn$StatCommand@469] - Stat command output > 2016-07-21 08:08:06,131 [myid:] - INFO [main:JMXEnv@229] - ensureParent:= [InMemoryDataTree, StandaloneServer_port] > 2016-07-21 08:08:06,132 [myid:] - INFO [main:JMXEnv@246] - expect:InMemo= ryDataTree > 2016-07-21 08:08:06,132 [myid:] - INFO [main:JMXEnv@250] - found:InMemor= yDataTree org.apache.ZooKeeperService:name0=3DStandaloneServer_port11290,na= me1=3DInMemoryDataTree > 2016-07-21 08:08:06,132 [myid:] - INFO [main:JMXEnv@246] - expect:Standa= loneServer_port > 2016-07-21 08:08:06,132 [myid:] - INFO [main:JMXEnv@250] - found:Standal= oneServer_port org.apache.ZooKeeperService:name0=3DStandaloneServer_port112= 90 > 2016-07-21 08:08:07,861 [myid:] - INFO [main-SendThread(127.0.0.1:11290)= :ClientCnxn$SendThread@1032] - Opening socket connection to server 127.0.0.= 1/127.0.0.1:11290. Will not attempt to authenticate using SASL (unknown err= or) > 2016-07-21 08:08:07,861 [myid:] - INFO [main-SendThread(127.0.0.1:11290)= :ClientCnxn$SendThread@876] - Socket connection established to 127.0.0.1/12= 7.0.0.1:11290, initiating session > 2016-07-21 08:08:07,862 [myid:] - INFO [New I/O worker #2807:ZooKeeperSe= rver@893] - Client attempting to renew session 0x1560c7f52730000 at /127.0.= 0.1:59469 > 2016-07-21 08:08:07,862 [myid:] - INFO [New I/O worker #2807:ZooKeeperSe= rver@645] - Established session 0x1560c7f52730000 with negotiated timeout 6= 000 for client /127.0.0.1:59469 > 2016-07-21 08:08:07,862 [myid:] - INFO [main-SendThread(127.0.0.1:11290)= :ClientCnxn$SendThread@1299] - Session establishment complete on server 127= .0.0.1/127.0.0.1:11290, sessionid =3D 0x1560c7f52730000, negotiated timeout= =3D 6000 > 2016-07-21 08:08:07,864 [myid:] - INFO [SyncThread:0:FileTxnLog@203] - C= reating new log file: log.4 > 2016-07-21 08:08:07,868 [myid:] - INFO [main:ClientBase@490] - STOPPING = server > 2016-07-21 08:08:07,868 [myid:] - INFO [main:NettyServerCnxnFactory@342]= - shutdown called 0.0.0.0/0.0.0.0:11290 > 2016-07-21 08:08:07,869 [myid:] - INFO [main-SendThread(127.0.0.1:11290)= :ClientCnxn$SendThread@1158] - Unable to read additional data from server s= essionid 0x1560c7f52730000, likely server has closed socket, closing socket= connection and attempting reconnect > 2016-07-21 08:08:07,872 [myid:] - INFO [main:ZooKeeperServer@469] - shut= ting down > 2016-07-21 08:08:07,872 [myid:] - INFO [main:SessionTrackerImpl@225] - S= hutting down > 2016-07-21 08:08:07,872 [myid:] - INFO [main:PrepRequestProcessor@765] -= Shutting down > 2016-07-21 08:08:07,873 [myid:] - INFO [main:SyncRequestProcessor@209] -= Shutting down > 2016-07-21 08:08:07,873 [myid:] - INFO [ProcessThread(sid:0 cport:11290)= ::PrepRequestProcessor@143] - PrepRequestProcessor exited loop! > 2016-07-21 08:08:07,873 [myid:] - INFO [SyncThread:0:SyncRequestProcesso= r@187] - SyncRequestProcessor exited! > 2016-07-21 08:08:07,874 [myid:] - INFO [main:FinalRequestProcessor@402] = - shutdown of request processor complete > 2016-07-21 08:08:07,874 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11290 > 2016-07-21 08:08:07,875 [myid:] - INFO [main:JMXEnv@146] - ensureOnly:[] > 2016-07-21 08:08:07,969 [myid:] - INFO [main:ClientBase@443] - STARTING = server > 2016-07-21 08:08:07,970 [myid:] - INFO [main:ClientBase@364] - CREATING = server instance 127.0.0.1:11290 > 2016-07-21 08:08:07,978 [myid:] - INFO [main:ClientBase@339] - STARTING = server instance 127.0.0.1:11290 > 2016-07-21 08:08:07,978 [myid:] - INFO [main:ZooKeeperServer@170] - Crea= ted server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 6000= 0 datadir /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/bra= nch-3.4/build/test/tmp/test6527239161822360616.junit.dir/version-2 snapdir = /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/bu= ild/test/tmp/test6527239161822360616.junit.dir/version-2 > 2016-07-21 08:08:07,978 [myid:] - INFO [main:NettyServerCnxnFactory@365]= - binding to port 0.0.0.0/0.0.0.0:11290 > 2016-07-21 08:08:07,981 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11290 > 2016-07-21 08:08:07,982 [myid:] - INFO [New I/O worker #2839:NettyServer= Cnxn@632] - Processing stat command from /127.0.0.1:59471 > 2016-07-21 08:08:07,982 [myid:] - INFO [New I/O worker #2839:NettyServer= Cnxn$StatCommand@469] - Stat command output > 2016-07-21 08:08:07,983 [myid:] - INFO [main:JMXEnv@229] - ensureParent:= [InMemoryDataTree, StandaloneServer_port] > 2016-07-21 08:08:07,984 [myid:] - INFO [main:JMXEnv@246] - expect:InMemo= ryDataTree > 2016-07-21 08:08:07,985 [myid:] - INFO [main:JMXEnv@250] - found:InMemor= yDataTree org.apache.ZooKeeperService:name0=3DStandaloneServer_port11290,na= me1=3DInMemoryDataTree > 2016-07-21 08:08:07,985 [myid:] - INFO [main:JMXEnv@246] - expect:Standa= loneServer_port > 2016-07-21 08:08:07,985 [myid:] - INFO [main:JMXEnv@250] - found:Standal= oneServer_port org.apache.ZooKeeperService:name0=3DStandaloneServer_port112= 90 > 2016-07-21 08:08:09,000 [myid:] - INFO [SessionTracker:SessionTrackerImp= l@162] - SessionTrackerImpl exited loop! > 2016-07-21 08:08:09,000 [myid:] - INFO [SessionTracker:SessionTrackerImp= l@162] - SessionTrackerImpl exited loop! > 2016-07-21 08:08:09,515 [myid:] - INFO [main-SendThread(127.0.0.1:11290)= :ClientCnxn$SendThread@1032] - Opening socket connection to server 127.0.0.= 1/127.0.0.1:11290. Will not attempt to authenticate using SASL (unknown err= or) > 2016-07-21 08:08:09,515 [myid:] - INFO [main-SendThread(127.0.0.1:11290)= :ClientCnxn$SendThread@876] - Socket connection established to 127.0.0.1/12= 7.0.0.1:11290, initiating session > 2016-07-21 08:08:09,516 [myid:] - INFO [New I/O worker #2840:ZooKeeperSe= rver@893] - Client attempting to renew session 0x1560c7f52730000 at /127.0.= 0.1:59477 > 2016-07-21 08:08:09,517 [myid:] - INFO [New I/O worker #2840:ZooKeeperSe= rver@645] - Established session 0x1560c7f52730000 with negotiated timeout 6= 000 for client /127.0.0.1:59477 > 2016-07-21 08:08:09,517 [myid:] - INFO [main-SendThread(127.0.0.1:11290)= :ClientCnxn$SendThread@1299] - Session establishment complete on server 127= .0.0.1/127.0.0.1:11290, sessionid =3D 0x1560c7f52730000, negotiated timeout= =3D 6000 > 2016-07-21 08:08:09,521 [myid:] - INFO [SyncThread:0:FileTxnLog@203] - C= reating new log file: log.6 > 2016-07-21 08:08:09,523 [myid:] - INFO [main:ClientBase@490] - STOPPING = server > 2016-07-21 08:08:09,523 [myid:] - INFO [main:NettyServerCnxnFactory@342]= - shutdown called 0.0.0.0/0.0.0.0:11290 > 2016-07-21 08:08:09,524 [myid:] - INFO [main-SendThread(127.0.0.1:11290)= :ClientCnxn$SendThread@1158] - Unable to read additional data from server s= essionid 0x1560c7f52730000, likely server has closed socket, closing socket= connection and attempting reconnect > 2016-07-21 08:08:09,530 [myid:] - INFO [main:ZooKeeperServer@469] - shut= ting down > 2016-07-21 08:08:09,530 [myid:] - INFO [main:SessionTrackerImpl@225] - S= hutting down > 2016-07-21 08:08:09,530 [myid:] - INFO [main:PrepRequestProcessor@765] -= Shutting down > 2016-07-21 08:08:09,530 [myid:] - INFO [main:SyncRequestProcessor@209] -= Shutting down > 2016-07-21 08:08:09,531 [myid:] - INFO [ProcessThread(sid:0 cport:11290)= ::PrepRequestProcessor@143] - PrepRequestProcessor exited loop! > 2016-07-21 08:08:09,531 [myid:] - INFO [SyncThread:0:SyncRequestProcesso= r@187] - SyncRequestProcessor exited! > 2016-07-21 08:08:09,532 [myid:] - INFO [main:FinalRequestProcessor@402] = - shutdown of request processor complete > 2016-07-21 08:08:09,533 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11290 > 2016-07-21 08:08:09,534 [myid:] - INFO [main:JMXEnv@146] - ensureOnly:[] > 2016-07-21 08:08:09,625 [myid:] - INFO [main:ClientBase@443] - STARTING = server > 2016-07-21 08:08:09,625 [myid:] - INFO [main:ClientBase@364] - CREATING = server instance 127.0.0.1:11290 > 2016-07-21 08:08:09,631 [myid:] - INFO [main:ClientBase@339] - STARTING = server instance 127.0.0.1:11290 > 2016-07-21 08:08:09,632 [myid:] - INFO [main:ZooKeeperServer@170] - Crea= ted server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 6000= 0 datadir /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/bra= nch-3.4/build/test/tmp/test6527239161822360616.junit.dir/version-2 snapdir = /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/bu= ild/test/tmp/test6527239161822360616.junit.dir/version-2 > 2016-07-21 08:08:09,632 [myid:] - INFO [main:NettyServerCnxnFactory@365]= - binding to port 0.0.0.0/0.0.0.0:11290 > 2016-07-21 08:08:09,635 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11290 > 2016-07-21 08:08:09,636 [myid:] - INFO [New I/O worker #2872:NettyServer= Cnxn@632] - Processing stat command from /127.0.0.1:59479 > 2016-07-21 08:08:09,636 [myid:] - INFO [New I/O worker #2872:NettyServer= Cnxn$StatCommand@469] - Stat command output > 2016-07-21 08:08:09,637 [myid:] - INFO [main:JMXEnv@229] - ensureParent:= [InMemoryDataTree, StandaloneServer_port] > 2016-07-21 08:08:09,638 [myid:] - INFO [main:JMXEnv@246] - expect:InMemo= ryDataTree > 2016-07-21 08:08:09,638 [myid:] - INFO [main:JMXEnv@250] - found:InMemor= yDataTree org.apache.ZooKeeperService:name0=3DStandaloneServer_port11290,na= me1=3DInMemoryDataTree > 2016-07-21 08:08:09,638 [myid:] - INFO [main:JMXEnv@246] - expect:Standa= loneServer_port > 2016-07-21 08:08:09,638 [myid:] - INFO [main:JMXEnv@250] - found:Standal= oneServer_port org.apache.ZooKeeperService:name0=3DStandaloneServer_port112= 90 > 2016-07-21 08:08:11,158 [myid:] - INFO [main-SendThread(127.0.0.1:11290)= :ClientCnxn$SendThread@1032] - Opening socket connection to server 127.0.0.= 1/127.0.0.1:11290. Will not attempt to authenticate using SASL (unknown err= or) > 2016-07-21 08:08:11,159 [myid:] - INFO [main-SendThread(127.0.0.1:11290)= :ClientCnxn$SendThread@876] - Socket connection established to 127.0.0.1/12= 7.0.0.1:11290, initiating session > 2016-07-21 08:08:11,160 [myid:] - INFO [New I/O worker #2873:ZooKeeperSe= rver@893] - Client attempting to renew session 0x1560c7f52730000 at /127.0.= 0.1:59485 > 2016-07-21 08:08:11,161 [myid:] - INFO [New I/O worker #2873:ZooKeeperSe= rver@645] - Established session 0x1560c7f52730000 with negotiated timeout 6= 000 for client /127.0.0.1:59485 > 2016-07-21 08:08:11,162 [myid:] - INFO [main-SendThread(127.0.0.1:11290)= :ClientCnxn$SendThread@1299] - Session establishment complete on server 127= .0.0.1/127.0.0.1:11290, sessionid =3D 0x1560c7f52730000, negotiated timeout= =3D 6000 > 2016-07-21 08:08:11,163 [myid:] - INFO [SyncThread:0:FileTxnLog@203] - C= reating new log file: log.7 > 2016-07-21 08:08:12,000 [myid:] - INFO [SessionTracker:SessionTrackerImp= l@162] - SessionTrackerImpl exited loop! > 2016-07-21 08:08:12,166 [myid:] - INFO [ProcessThread(sid:0 cport:11290)= ::PrepRequestProcessor@487] - Processed session termination for sessionid: = 0x1560c7f52730000 > 2016-07-21 08:08:12,167 [myid:] - INFO [main:ZooKeeper@684] - Session: 0= x1560c7f52730000 closed > 2016-07-21 08:08:12,167 [myid:] - INFO [main-EventThread:ClientCnxn$Even= tThread@519] - EventThread shut down for session: 0x1560c7f52730000 > 2016-07-21 08:08:12,168 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@58] - Memory used 93132 > 2016-07-21 08:08:12,168 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@63] - Number of threads 64 > 2016-07-21 08:08:12,168 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@78] - FINISHED TEST METHOD testWatcherAutoResetDisabledWithGloba= l > 2016-07-21 08:08:12,168 [myid:] - INFO [main:ClientBase@520] - tearDown = starting > 2016-07-21 08:08:12,168 [myid:] - INFO [main:ClientBase@490] - STOPPING = server > 2016-07-21 08:08:12,169 [myid:] - INFO [main:NettyServerCnxnFactory@342]= - shutdown called 0.0.0.0/0.0.0.0:11290 > 2016-07-21 08:08:12,175 [myid:] - INFO [main:ZooKeeperServer@469] - shut= ting down > 2016-07-21 08:08:12,176 [myid:] - INFO [main:SessionTrackerImpl@225] - S= hutting down > 2016-07-21 08:08:12,177 [myid:] - INFO [main:PrepRequestProcessor@765] -= Shutting down > 2016-07-21 08:08:12,177 [myid:] - INFO [main:SyncRequestProcessor@209] -= Shutting down > 2016-07-21 08:08:12,177 [myid:] - INFO [ProcessThread(sid:0 cport:11290)= ::PrepRequestProcessor@143] - PrepRequestProcessor exited loop! > 2016-07-21 08:08:12,177 [myid:] - INFO [SyncThread:0:SyncRequestProcesso= r@187] - SyncRequestProcessor exited! > 2016-07-21 08:08:12,178 [myid:] - INFO [main:FinalRequestProcessor@402] = - shutdown of request processor complete > 2016-07-21 08:08:12,179 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11290 > 2016-07-21 08:08:12,179 [myid:] - INFO [main:JMXEnv@146] - ensureOnly:[] > 2016-07-21 08:08:12,181 [myid:] - INFO [main:ClientBase@545] - fdcount a= fter test is: 45 at start it was 45 > 2016-07-21 08:08:12,182 [myid:] - INFO [main:ZKTestCase$1@60] - SUCCEEDE= D testWatcherAutoResetDisabledWithGlobal > 2016-07-21 08:08:12,182 [myid:] - INFO [main:ZKTestCase$1@55] - FINISHED= testWatcherAutoResetDisabledWithGlobal > 2016-07-21 08:08:12,182 [myid:] - INFO [main:PortAssignment@32] - assign= ing port 11291 > 2016-07-21 08:08:12,182 [myid:] - INFO [main:ZKTestCase$1@50] - STARTING= testWatcherAutoResetDisabledWithLocal > 2016-07-21 08:08:12,183 [myid:] - INFO [main:ClientBase@425] - Initial f= dcount is: 45 > 2016-07-21 08:08:12,191 [myid:] - INFO [main:ClientBase@443] - STARTING = server > 2016-07-21 08:08:12,191 [myid:] - INFO [main:ClientBase@364] - CREATING = server instance 127.0.0.1:11291 > 2016-07-21 08:08:12,197 [myid:] - INFO [main:ClientBase@339] - STARTING = server instance 127.0.0.1:11291 > 2016-07-21 08:08:12,197 [myid:] - INFO [main:ZooKeeperServer@170] - Crea= ted server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 6000= 0 datadir /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/bra= nch-3.4/build/test/tmp/test5697721892495919568.junit.dir/version-2 snapdir = /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/bu= ild/test/tmp/test5697721892495919568.junit.dir/version-2 > 2016-07-21 08:08:12,198 [myid:] - INFO [main:NettyServerCnxnFactory@365]= - binding to port 0.0.0.0/0.0.0.0:11291 > 2016-07-21 08:08:12,199 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11291 > 2016-07-21 08:08:12,200 [myid:] - INFO [New I/O worker #2905:NettyServer= Cnxn@632] - Processing stat command from /127.0.0.1:51830 > 2016-07-21 08:08:12,200 [myid:] - INFO [New I/O worker #2905:NettyServer= Cnxn$StatCommand@469] - Stat command output > 2016-07-21 08:08:12,200 [myid:] - INFO [main:JMXEnv@229] - ensureParent:= [InMemoryDataTree, StandaloneServer_port] > 2016-07-21 08:08:12,202 [myid:] - INFO [main:JMXEnv@246] - expect:InMemo= ryDataTree > 2016-07-21 08:08:12,202 [myid:] - INFO [main:JMXEnv@250] - found:InMemor= yDataTree org.apache.ZooKeeperService:name0=3DStandaloneServer_port11291,na= me1=3DInMemoryDataTree > 2016-07-21 08:08:12,202 [myid:] - INFO [main:JMXEnv@246] - expect:Standa= loneServer_port > 2016-07-21 08:08:12,202 [myid:] - INFO [main:JMXEnv@250] - found:Standal= oneServer_port org.apache.ZooKeeperService:name0=3DStandaloneServer_port112= 91 > 2016-07-21 08:08:12,202 [myid:] - INFO [main:ClientBase@439] - Client te= st setup finished > 2016-07-21 08:08:12,202 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@53] - RUNNING TEST METHOD testWatcherAutoResetDisabledWithLocal > 2016-07-21 08:08:12,202 [myid:] - INFO [main:ZooKeeper@438] - Initiating= client connection, connectString=3D127.0.0.1:11291 sessionTimeout=3D5000 w= atcher=3Dorg.apache.zookeeper.test.WatcherTest$MyWatcher@b901239 > 2016-07-21 08:08:12,203 [myid:] - INFO [main-SendThread(127.0.0.1:11291)= :ClientCnxn$SendThread@1032] - Opening socket connection to server 127.0.0.= 1/127.0.0.1:11291. Will not attempt to authenticate using SASL (unknown err= or) > 2016-07-21 08:08:12,203 [myid:] - INFO [main-SendThread(127.0.0.1:11291)= :ClientCnxn$SendThread@876] - Socket connection established to 127.0.0.1/12= 7.0.0.1:11291, initiating session > 2016-07-21 08:08:12,204 [myid:] - INFO [New I/O worker #2906:ZooKeeperSe= rver@900] - Client attempting to establish new session at /127.0.0.1:51831 > 2016-07-21 08:08:12,205 [myid:] - INFO [SyncThread:0:FileTxnLog@203] - C= reating new log file: log.1 > 2016-07-21 08:08:12,206 [myid:] - INFO [SyncThread:0:ZooKeeperServer@645= ] - Established session 0x1560c7f6aa60000 with negotiated timeout 6000 for = client /127.0.0.1:51831 > 2016-07-21 08:08:12,207 [myid:] - INFO [main-SendThread(127.0.0.1:11291)= :ClientCnxn$SendThread@1299] - Session establishment complete on server 127= .0.0.1/127.0.0.1:11291, sessionid =3D 0x1560c7f6aa60000, negotiated timeout= =3D 6000 > 2016-07-21 08:08:12,208 [myid:] - INFO [main:JMXEnv@117] - expect:0x1560= c7f6aa60000 > 2016-07-21 08:08:12,209 [myid:] - INFO [main:JMXEnv@120] - found:0x1560c= 7f6aa60000 org.apache.ZooKeeperService:name0=3DStandaloneServer_port11291,n= ame1=3DConnections,name2=3D127.0.0.1,name3=3D0x1560c7f6aa60000 > 2016-07-21 08:08:12,214 [myid:] - INFO [main:ClientBase@490] - STOPPING = server > 2016-07-21 08:08:12,214 [myid:] - INFO [main:NettyServerCnxnFactory@342]= - shutdown called 0.0.0.0/0.0.0.0:11291 > 2016-07-21 08:08:12,214 [myid:] - INFO [main-SendThread(127.0.0.1:11291)= :ClientCnxn$SendThread@1158] - Unable to read additional data from server s= essionid 0x1560c7f6aa60000, likely server has closed socket, closing socket= connection and attempting reconnect > 2016-07-21 08:08:12,219 [myid:] - INFO [main:ZooKeeperServer@469] - shut= ting down > 2016-07-21 08:08:12,219 [myid:] - INFO [main:SessionTrackerImpl@225] - S= hutting down > 2016-07-21 08:08:12,219 [myid:] - INFO [main:PrepRequestProcessor@765] -= Shutting down > 2016-07-21 08:08:12,220 [myid:] - INFO [main:SyncRequestProcessor@209] -= Shutting down > 2016-07-21 08:08:12,220 [myid:] - INFO [ProcessThread(sid:0 cport:11291)= ::PrepRequestProcessor@143] - PrepRequestProcessor exited loop! > 2016-07-21 08:08:12,220 [myid:] - INFO [SyncThread:0:SyncRequestProcesso= r@187] - SyncRequestProcessor exited! > 2016-07-21 08:08:12,221 [myid:] - INFO [main:FinalRequestProcessor@402] = - shutdown of request processor complete > 2016-07-21 08:08:12,222 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11291 > 2016-07-21 08:08:12,223 [myid:] - INFO [main:JMXEnv@146] - ensureOnly:[] > 2016-07-21 08:08:12,315 [myid:] - INFO [main:ClientBase@443] - STARTING = server > 2016-07-21 08:08:12,315 [myid:] - INFO [main:ClientBase@364] - CREATING = server instance 127.0.0.1:11291 > 2016-07-21 08:08:12,321 [myid:] - INFO [main:ClientBase@339] - STARTING = server instance 127.0.0.1:11291 > 2016-07-21 08:08:12,321 [myid:] - INFO [main:ZooKeeperServer@170] - Crea= ted server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 6000= 0 datadir /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/bra= nch-3.4/build/test/tmp/test5697721892495919568.junit.dir/version-2 snapdir = /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/bu= ild/test/tmp/test5697721892495919568.junit.dir/version-2 > 2016-07-21 08:08:12,321 [myid:] - INFO [main:NettyServerCnxnFactory@365]= - binding to port 0.0.0.0/0.0.0.0:11291 > 2016-07-21 08:08:12,324 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11291 > 2016-07-21 08:08:12,325 [myid:] - INFO [New I/O worker #2938:NettyServer= Cnxn@632] - Processing stat command from /127.0.0.1:51833 > 2016-07-21 08:08:12,325 [myid:] - INFO [New I/O worker #2938:NettyServer= Cnxn$StatCommand@469] - Stat command output > 2016-07-21 08:08:12,326 [myid:] - INFO [main:JMXEnv@229] - ensureParent:= [InMemoryDataTree, StandaloneServer_port] > 2016-07-21 08:08:12,327 [myid:] - INFO [main:JMXEnv@246] - expect:InMemo= ryDataTree > 2016-07-21 08:08:12,327 [myid:] - INFO [main:JMXEnv@250] - found:InMemor= yDataTree org.apache.ZooKeeperService:name0=3DStandaloneServer_port11291,na= me1=3DInMemoryDataTree > 2016-07-21 08:08:12,327 [myid:] - INFO [main:JMXEnv@246] - expect:Standa= loneServer_port > 2016-07-21 08:08:12,327 [myid:] - INFO [main:JMXEnv@250] - found:Standal= oneServer_port org.apache.ZooKeeperService:name0=3DStandaloneServer_port112= 91 > 2016-07-21 08:08:13,518 [myid:] - INFO [main-SendThread(127.0.0.1:11291)= :ClientCnxn$SendThread@1032] - Opening socket connection to server 127.0.0.= 1/127.0.0.1:11291. Will not attempt to authenticate using SASL (unknown err= or) > 2016-07-21 08:08:13,518 [myid:] - INFO [main-SendThread(127.0.0.1:11291)= :ClientCnxn$SendThread@876] - Socket connection established to 127.0.0.1/12= 7.0.0.1:11291, initiating session > 2016-07-21 08:08:13,519 [myid:] - INFO [New I/O worker #2939:ZooKeeperSe= rver@893] - Client attempting to renew session 0x1560c7f6aa60000 at /127.0.= 0.1:51839 > 2016-07-21 08:08:13,520 [myid:] - INFO [New I/O worker #2939:ZooKeeperSe= rver@645] - Established session 0x1560c7f6aa60000 with negotiated timeout 6= 000 for client /127.0.0.1:51839 > 2016-07-21 08:08:13,520 [myid:] - INFO [main-SendThread(127.0.0.1:11291)= :ClientCnxn$SendThread@1299] - Session establishment complete on server 127= .0.0.1/127.0.0.1:11291, sessionid =3D 0x1560c7f6aa60000, negotiated timeout= =3D 6000 > 2016-07-21 08:08:13,521 [myid:] - INFO [SyncThread:0:FileTxnLog@203] - C= reating new log file: log.4 > 2016-07-21 08:08:13,523 [myid:] - INFO [main:ClientBase@490] - STOPPING = server > 2016-07-21 08:08:13,524 [myid:] - INFO [main:NettyServerCnxnFactory@342]= - shutdown called 0.0.0.0/0.0.0.0:11291 > 2016-07-21 08:08:13,525 [myid:] - INFO [main-SendThread(127.0.0.1:11291)= :ClientCnxn$SendThread@1158] - Unable to read additional data from server s= essionid 0x1560c7f6aa60000, likely server has closed socket, closing socket= connection and attempting reconnect > 2016-07-21 08:08:13,531 [myid:] - INFO [main:ZooKeeperServer@469] - shut= ting down > 2016-07-21 08:08:13,531 [myid:] - INFO [main:SessionTrackerImpl@225] - S= hutting down > 2016-07-21 08:08:13,531 [myid:] - INFO [main:PrepRequestProcessor@765] -= Shutting down > 2016-07-21 08:08:13,531 [myid:] - INFO [main:SyncRequestProcessor@209] -= Shutting down > 2016-07-21 08:08:13,531 [myid:] - INFO [ProcessThread(sid:0 cport:11291)= ::PrepRequestProcessor@143] - PrepRequestProcessor exited loop! > 2016-07-21 08:08:13,531 [myid:] - INFO [SyncThread:0:SyncRequestProcesso= r@187] - SyncRequestProcessor exited! > 2016-07-21 08:08:13,532 [myid:] - INFO [main:FinalRequestProcessor@402] = - shutdown of request processor complete > 2016-07-21 08:08:13,533 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11291 > 2016-07-21 08:08:13,533 [myid:] - INFO [main:JMXEnv@146] - ensureOnly:[] > 2016-07-21 08:08:13,625 [myid:] - INFO [main:ClientBase@443] - STARTING = server > 2016-07-21 08:08:13,625 [myid:] - INFO [main:ClientBase@364] - CREATING = server instance 127.0.0.1:11291 > 2016-07-21 08:08:13,633 [myid:] - INFO [main:ClientBase@339] - STARTING = server instance 127.0.0.1:11291 > 2016-07-21 08:08:13,634 [myid:] - INFO [main:ZooKeeperServer@170] - Crea= ted server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 6000= 0 datadir /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/bra= nch-3.4/build/test/tmp/test5697721892495919568.junit.dir/version-2 snapdir = /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/bu= ild/test/tmp/test5697721892495919568.junit.dir/version-2 > 2016-07-21 08:08:13,634 [myid:] - INFO [main:NettyServerCnxnFactory@365]= - binding to port 0.0.0.0/0.0.0.0:11291 > 2016-07-21 08:08:13,636 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11291 > 2016-07-21 08:08:13,637 [myid:] - INFO [New I/O worker #2971:NettyServer= Cnxn@632] - Processing stat command from /127.0.0.1:51841 > 2016-07-21 08:08:13,637 [myid:] - INFO [New I/O worker #2971:NettyServer= Cnxn$StatCommand@469] - Stat command output > 2016-07-21 08:08:13,637 [myid:] - INFO [main:JMXEnv@229] - ensureParent:= [InMemoryDataTree, StandaloneServer_port] > 2016-07-21 08:08:13,639 [myid:] - INFO [main:JMXEnv@246] - expect:InMemo= ryDataTree > 2016-07-21 08:08:13,639 [myid:] - INFO [main:JMXEnv@250] - found:InMemor= yDataTree org.apache.ZooKeeperService:name0=3DStandaloneServer_port11291,na= me1=3DInMemoryDataTree > 2016-07-21 08:08:13,639 [myid:] - INFO [main:JMXEnv@246] - expect:Standa= loneServer_port > 2016-07-21 08:08:13,639 [myid:] - INFO [main:JMXEnv@250] - found:Standal= oneServer_port org.apache.ZooKeeperService:name0=3DStandaloneServer_port112= 91 > 2016-07-21 08:08:14,760 [myid:] - INFO [main-SendThread(127.0.0.1:11291)= :ClientCnxn$SendThread@1032] - Opening socket connection to server 127.0.0.= 1/127.0.0.1:11291. Will not attempt to authenticate using SASL (unknown err= or) > 2016-07-21 08:08:14,761 [myid:] - INFO [main-SendThread(127.0.0.1:11291)= :ClientCnxn$SendThread@876] - Socket connection established to 127.0.0.1/12= 7.0.0.1:11291, initiating session > 2016-07-21 08:08:14,762 [myid:] - INFO [New I/O worker #2972:ZooKeeperSe= rver@893] - Client attempting to renew session 0x1560c7f6aa60000 at /127.0.= 0.1:51846 > 2016-07-21 08:08:14,763 [myid:] - INFO [New I/O worker #2972:ZooKeeperSe= rver@645] - Established session 0x1560c7f6aa60000 with negotiated timeout 6= 000 for client /127.0.0.1:51846 > 2016-07-21 08:08:14,763 [myid:] - INFO [main-SendThread(127.0.0.1:11291)= :ClientCnxn$SendThread@1299] - Session establishment complete on server 127= .0.0.1/127.0.0.1:11291, sessionid =3D 0x1560c7f6aa60000, negotiated timeout= =3D 6000 > 2016-07-21 08:08:14,768 [myid:] - INFO [SyncThread:0:FileTxnLog@203] - C= reating new log file: log.6 > 2016-07-21 08:08:14,770 [myid:] - INFO [main:ClientBase@490] - STOPPING = server > 2016-07-21 08:08:14,771 [myid:] - INFO [main:NettyServerCnxnFactory@342]= - shutdown called 0.0.0.0/0.0.0.0:11291 > 2016-07-21 08:08:14,771 [myid:] - INFO [main-SendThread(127.0.0.1:11291)= :ClientCnxn$SendThread@1158] - Unable to read additional data from server s= essionid 0x1560c7f6aa60000, likely server has closed socket, closing socket= connection and attempting reconnect > 2016-07-21 08:08:14,777 [myid:] - INFO [main:ZooKeeperServer@469] - shut= ting down > 2016-07-21 08:08:14,777 [myid:] - INFO [main:SessionTrackerImpl@225] - S= hutting down > 2016-07-21 08:08:14,778 [myid:] - INFO [main:PrepRequestProcessor@765] -= Shutting down > 2016-07-21 08:08:14,779 [myid:] - INFO [main:SyncRequestProcessor@209] -= Shutting down > 2016-07-21 08:08:14,779 [myid:] - INFO [ProcessThread(sid:0 cport:11291)= ::PrepRequestProcessor@143] - PrepRequestProcessor exited loop! > 2016-07-21 08:08:14,779 [myid:] - INFO [SyncThread:0:SyncRequestProcesso= r@187] - SyncRequestProcessor exited! > 2016-07-21 08:08:14,780 [myid:] - INFO [main:FinalRequestProcessor@402] = - shutdown of request processor complete > 2016-07-21 08:08:14,782 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11291 > 2016-07-21 08:08:14,782 [myid:] - INFO [main:JMXEnv@146] - ensureOnly:[] > 2016-07-21 08:08:14,871 [myid:] - INFO [main:ClientBase@443] - STARTING = server > 2016-07-21 08:08:14,872 [myid:] - INFO [main:ClientBase@364] - CREATING = server instance 127.0.0.1:11291 > 2016-07-21 08:08:14,880 [myid:] - INFO [main:ClientBase@339] - STARTING = server instance 127.0.0.1:11291 > 2016-07-21 08:08:14,881 [myid:] - INFO [main:ZooKeeperServer@170] - Crea= ted server with tickTime 3000 minSessionTimeout 6000 maxSessionTimeout 6000= 0 datadir /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/bra= nch-3.4/build/test/tmp/test5697721892495919568.junit.dir/version-2 snapdir = /home/jenkins/jenkins-slave/workspace/ZooKeeper_branch34_jdk7/branch-3.4/bu= ild/test/tmp/test5697721892495919568.junit.dir/version-2 > 2016-07-21 08:08:14,881 [myid:] - INFO [main:NettyServerCnxnFactory@365]= - binding to port 0.0.0.0/0.0.0.0:11291 > 2016-07-21 08:08:14,884 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11291 > 2016-07-21 08:08:14,885 [myid:] - INFO [New I/O worker #3004:NettyServer= Cnxn@632] - Processing stat command from /127.0.0.1:51849 > 2016-07-21 08:08:14,886 [myid:] - INFO [New I/O worker #3004:NettyServer= Cnxn$StatCommand@469] - Stat command output > 2016-07-21 08:08:14,886 [myid:] - INFO [main:JMXEnv@229] - ensureParent:= [InMemoryDataTree, StandaloneServer_port] > 2016-07-21 08:08:14,887 [myid:] - INFO [main:JMXEnv@246] - expect:InMemo= ryDataTree > 2016-07-21 08:08:14,887 [myid:] - INFO [main:JMXEnv@250] - found:InMemor= yDataTree org.apache.ZooKeeperService:name0=3DStandaloneServer_port11291,na= me1=3DInMemoryDataTree > 2016-07-21 08:08:14,887 [myid:] - INFO [main:JMXEnv@246] - expect:Standa= loneServer_port > 2016-07-21 08:08:14,888 [myid:] - INFO [main:JMXEnv@250] - found:Standal= oneServer_port org.apache.ZooKeeperService:name0=3DStandaloneServer_port112= 91 > 2016-07-21 08:08:15,000 [myid:] - INFO [SessionTracker:SessionTrackerImp= l@162] - SessionTrackerImpl exited loop! > 2016-07-21 08:08:15,001 [myid:] - INFO [SessionTracker:SessionTrackerImp= l@162] - SessionTrackerImpl exited loop! > 2016-07-21 08:08:15,001 [myid:] - INFO [SessionTracker:SessionTrackerImp= l@162] - SessionTrackerImpl exited loop! > 2016-07-21 08:08:15,001 [myid:] - INFO [SessionTracker:SessionTrackerImp= l@162] - SessionTrackerImpl exited loop! > 2016-07-21 08:08:16,075 [myid:] - INFO [main-SendThread(127.0.0.1:11291)= :ClientCnxn$SendThread@1032] - Opening socket connection to server 127.0.0.= 1/127.0.0.1:11291. Will not attempt to authenticate using SASL (unknown err= or) > 2016-07-21 08:08:16,075 [myid:] - INFO [main-SendThread(127.0.0.1:11291)= :ClientCnxn$SendThread@876] - Socket connection established to 127.0.0.1/12= 7.0.0.1:11291, initiating session > 2016-07-21 08:08:16,076 [myid:] - INFO [New I/O worker #3005:ZooKeeperSe= rver@893] - Client attempting to renew session 0x1560c7f6aa60000 at /127.0.= 0.1:51852 > 2016-07-21 08:08:16,077 [myid:] - INFO [New I/O worker #3005:ZooKeeperSe= rver@645] - Established session 0x1560c7f6aa60000 with negotiated timeout 6= 000 for client /127.0.0.1:51852 > 2016-07-21 08:08:16,077 [myid:] - INFO [main-SendThread(127.0.0.1:11291)= :ClientCnxn$SendThread@1299] - Session establishment complete on server 127= .0.0.1/127.0.0.1:11291, sessionid =3D 0x1560c7f6aa60000, negotiated timeout= =3D 6000 > 2016-07-21 08:08:16,078 [myid:] - INFO [SyncThread:0:FileTxnLog@203] - C= reating new log file: log.7 > 2016-07-21 08:08:17,082 [myid:] - INFO [ProcessThread(sid:0 cport:11291)= ::PrepRequestProcessor@487] - Processed session termination for sessionid: = 0x1560c7f6aa60000 > 2016-07-21 08:08:17,083 [myid:] - WARN [New I/O worker #3005:NettyServer= CnxnFactory$CnxnChannelHandler@111] - Exception caught [id: 0x3265227a, /12= 7.0.0.1:51852 :> /127.0.0.1:11291] EXCEPTION: java.nio.channels.ClosedChann= elException > java.nio.channels.ClosedChannelException > =09at sun.nio.ch.SocketChannelImpl.ensureWriteOpen(SocketChannelImpl.java= :270) > =09at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:479) > =09at org.jboss.netty.channel.socket.nio.SocketSendBufferPool$UnpooledSen= dBuffer.transferTo(SocketSendBufferPool.java:203) > =09at org.jboss.netty.channel.socket.nio.AbstractNioWorker.write0(Abstrac= tNioWorker.java:201) > =09at org.jboss.netty.channel.socket.nio.AbstractNioWorker.writeFromTaskL= oop(AbstractNioWorker.java:151) > =09at org.jboss.netty.channel.socket.nio.AbstractNioChannel$WriteTask.run= (AbstractNioChannel.java:315) > =09at org.jboss.netty.channel.socket.nio.AbstractNioSelector.processTaskQ= ueue(AbstractNioSelector.java:391) > =09at org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(Abstract= NioSelector.java:315) > =09at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNi= oWorker.java:89) > =09at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:178= ) > =09at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunna= ble.java:108) > =09at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockPro= ofWorker.java:42) > =09at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecuto= r.java:1145) > =09at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecut= or.java:615) > =09at java.lang.Thread.run(Thread.java:745) > 2016-07-21 08:08:17,184 [myid:] - INFO [main:ZooKeeper@684] - Session: 0= x1560c7f6aa60000 closed > 2016-07-21 08:08:17,184 [myid:] - INFO [main-EventThread:ClientCnxn$Even= tThread@519] - EventThread shut down for session: 0x1560c7f6aa60000 > 2016-07-21 08:08:17,184 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@58] - Memory used 115316 > 2016-07-21 08:08:17,184 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@63] - Number of threads 63 > 2016-07-21 08:08:17,184 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedIn= vokeMethod@78] - FINISHED TEST METHOD testWatcherAutoResetDisabledWithLocal > 2016-07-21 08:08:17,184 [myid:] - INFO [main:ClientBase@520] - tearDown = starting > 2016-07-21 08:08:17,184 [myid:] - INFO [main:ClientBase@490] - STOPPING = server > 2016-07-21 08:08:17,185 [myid:] - INFO [main:NettyServerCnxnFactory@342]= - shutdown called 0.0.0.0/0.0.0.0:11291 > 2016-07-21 08:08:17,190 [myid:] - INFO [main:ZooKeeperServer@469] - shut= ting down > 2016-07-21 08:08:17,191 [myid:] - INFO [main:SessionTrackerImpl@225] - S= hutting down > 2016-07-21 08:08:17,191 [myid:] - INFO [main:PrepRequestProcessor@765] -= Shutting down > 2016-07-21 08:08:17,191 [myid:] - INFO [main:SyncRequestProcessor@209] -= Shutting down > 2016-07-21 08:08:17,191 [myid:] - INFO [ProcessThread(sid:0 cport:11291)= ::PrepRequestProcessor@143] - PrepRequestProcessor exited loop! > 2016-07-21 08:08:17,191 [myid:] - INFO [SyncThread:0:SyncRequestProcesso= r@187] - SyncRequestProcessor exited! > 2016-07-21 08:08:17,192 [myid:] - INFO [main:FinalRequestProcessor@402] = - shutdown of request processor complete > 2016-07-21 08:08:17,192 [myid:] - INFO [main:FourLetterWordMain@62] - co= nnecting to 127.0.0.1 11291 > 2016-07-21 08:08:17,193 [myid:] - INFO [main:JMXEnv@146] - ensureOnly:[] > 2016-07-21 08:08:17,195 [myid:] - INFO [main:ClientBase@545] - fdcount a= fter test is: 41 at start it was 45 > 2016-07-21 08:08:17,195 [myid:] - INFO [main:ZKTestCase$1@60] - SUCCEEDE= D testWatcherAutoResetDisabledWithLocal > 2016-07-21 08:08:17,195 [myid:] - INFO [main:ZKTestCase$1@55] - FINISHED= testWatcherAutoResetDisabledWithLocal > {noformat} -- This message was sent by Atlassian JIRA (v7.6.3#76005)