[
https://issues.apache.org/jira/browse/ZOOKEEPER-2028?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Qiang Tian updated ZOOKEEPER-2028:
----------------------------------
Description:
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
{quote}
[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
{quote}
2. last lines in zk server log:
{quote}
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
{quote}
3. last lines in TEST-Zookeeper_simpleSystem-mt.txt:
{quote}
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=localhost
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
{quote}
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...?
was:
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
{quote}
[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
{quote}
2. last lines in zk server log:
{quote}
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
{quote}
3. last lines in TEST-Zookeeper_simpleSystem-mt.txt:
{quote}
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
{quote}
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...?
> cppunit testcase testAuth consistently fails in zookeeper 3.4.6
> ---------------------------------------------------------------
>
> Key: ZOOKEEPER-2028
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-2028
> Project: ZooKeeper
> Issue Type: Bug
> Components: tests
> Affects Versions: 3.4.6
> Environment: linux
> Reporter: Qiang Tian
> Priority: Minor
>
> 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
> {quote}
> [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
> {quote}
> 2. last lines in zk server log:
> {quote}
> 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
> {quote}
> 3. last lines in TEST-Zookeeper_simpleSystem-mt.txt:
> {quote}
> 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=localhost
> 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
> {quote}
> 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...?
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
