Please see https://issues.apache.org/jira/browse/ZOOKEEPER-2028 can you please review the patch? thanks.
On Fri, Sep 5, 2014 at 3:16 PM, Qiang Tian <[email protected]> wrote: > Hi Guys, > the testcase consistently fails if debug is turned on(set > zoo_set_debug_level(ZOO_LOG_LEVEL_DEBUG) in TestDriver.cc); if debug is > OFF, it fails for the first time, subsequent runs succeed. > > can someone help take a look? > thanks! > > below is related info: > > 1. screen output > [exec] Zookeeper_simpleSystem::testPing : elapsed 17200 : OK > [exec] Zookeeper_simpleSystem::testAcl : elapsed 1014 : OK > [exec] Zookeeper_simpleSystem::testChroot : elapsed 3041 : OK > [exec] terminate called after throwing an instance of > 'CppUnit::Exception' > [exec] what(): equality assertion failed > [exec] - Expected: 0 > [exec] - Actual : -116 > [exec] > [exec] make: *** [run-check] Aborted (core dumped) > [exec] Zookeeper_simpleSystem::testAuth > > 2. last lines in zk server log: > 2014-09-04 21:13:57,711 [myid:] - INFO [NIOServerCxn.Factory: > 0.0.0.0/0.0.0.0:22181:ZooKeeperServer@868] - Client attempting to > establish new session at /127.0.0.1:34992 > 2014-09-04 21:13:57,714 [myid:] - INFO [SyncThread:0:ZooKeeperServer@617] > - Established session 0x14844044d96000a with negotiated timeout 10000 for > client /127.0.0.1:34992 > 2014-09-04 21:14:01,039 [myid:] - INFO [NIOServerCxn.Factory: > 0.0.0.0/0.0.0.0:22181:ZooKeeperServer@892] - got auth packet / > 127.0.0.1:34992 > 2014-09-04 21:14:01,747 [myid:] - INFO [NIOServerCxn.Factory: > 0.0.0.0/0.0.0.0:22181:ZooKeeperServer@926] - auth success /127.0.0.1:34992 > 2014-09-04 21:14:01,912 [myid:] - WARN [NIOServerCxn.Factory: > 0.0.0.0/0.0.0.0:22181:NIOServerCnxn@362] - Exception causing close of > session 0x14844044d96000a due to java.io.IOException: Connection reset by > peer > 2014-09-04 21:14:01,914 [myid:] - INFO [NIOServerCxn.Factory: > 0.0.0.0/0.0.0.0:22181:NIOServerCnxn@1007] - Closed socket connection for > client /127.0.0.1:34992 which had sessionid 0x14844044d96000a > 2014-09-04 21:14:12,000 [myid:] - INFO [SessionTracker:ZooKeeperServer@347] > - Expiring session 0x14844044d96000a, timeout of 10000ms exceeded > 2014-09-04 21:14:12,001 [myid:] - INFO [ProcessThread(sid:0 > cport:-1)::PrepRequestProcessor@494] - Processed session termination for > sessionid: 0x14844044d96000a > > 3. last lines in TEST-Zookeeper_simpleSystem-mt.txt: > 2014-09-04 21:13:57,703:383481(0x7f8866c4b720):ZOO_INFO@log_env@712: > Client environment:zookeeper.version=zookeeper C client 3.4.6 > 2014-09-04 21:13:57,703:383481(0x7f8866c4b720):ZOO_INFO@log_env@716: > Client environment:host.name=bdvm099.svl.ibm.com > 2014-09-04 21:13:57,703:383481(0x7f8866c4b720):ZOO_INFO@log_env@723: > Client environment:os.name=Linux > 2014-09-04 21:13:57,703:383481(0x7f8866c4b720):ZOO_INFO@log_env@724: > Client environment:os.arch=2.6.32-358.el6.x86_64 > 2014-09-04 21:13:57,703:383481(0x7f8866c4b720):ZOO_INFO@log_env@725: > Client environment:os.version=#1 SMP Tue Jan 29 11:47:41 EST 2013 > 2014-09-04 21:13:57,703:383481(0x7f8866c4b720):ZOO_INFO@log_env@733: > Client environment:user.name=tianq > 2014-09-04 21:13:57,703:383481(0x7f8866c4b720):ZOO_INFO@log_env@741: > Client environment:user.home=/home/tianq > 2014-09-04 21:13:57,703:383481(0x7f8866c4b720):ZOO_INFO@log_env@753: > Client environment:user.dir=/home/tianq/zookeeper/build/test/test-cppunit > 2014-09-04 21:13:57,703:383481(0x7f8866c4b720):ZOO_INFO@zookeeper_init@786: > Initiating client connection, host=127.0.0.1:22181 sessionTimeout=10000 > watcher=0x42e590 sessionId=0 sessionPasswd=<null> context=0x7fff695ea9a0 > flags=0 > 2014-09-04 21:13:57,703:383481(0x7f8866c4b720):ZOO_DEBUG@start_threads@221: > starting threads... > 2014-09-04 21:13:57,704:383481(0x7f8857fff700):ZOO_DEBUG@do_io@367: > started IO thread > 2014-09-04 21:13:57,704:383481(0x7f8857fff700):ZOO_INFO@check_events@1705: > initiated connection to server [127.0.0.1:22181] > 2014-09-04 21:13:57,704:383481(0x7f88667f9700):ZOO_DEBUG@do_completion@459: > started completion thread > 2014-09-04 21:13:57,714:383481(0x7f8857fff700):ZOO_INFO@check_events@1752: > session establishment complete on server [127.0.0.1:22181], > sessionId=0x14844044d96000a, negotiated timeout=10000 > 2014-09-04 21:13:57,714:383481(0x7f8857fff700):ZOO_DEBUG@check_events@1758: > Calling a watcher for a ZOO_SESSION_EVENT and the state=ZOO_CONNECTED_STATE > 2014-09-04 > 21:13:57,714:383481(0x7f88667f9700):ZOO_DEBUG@process_completions@2113: > Calling a watcher for node [], type = -1 event=ZOO_SESSION_EVENT > 2014-09-04 > 21:13:58,704:383481(0x7f8866c4b720):ZOO_DEBUG@send_last_auth_info@1353: > Sending auth info request to 127.0.0.1:22181 > > > If I understand correctly, it fails because assert expected 0, but looking > at the testcase log, "Sending auth info request to .." appears for the > first time, so it should correspond to the first zoo_add_auth call in > testAuth. but its expected value is ZBADARGUMENTS... > > > > >
