You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@zookeeper.apache.org by "Qiang Tian (JIRA)" <ji...@apache.org> on 2014/09/18 09:13:33 UTC
[jira] [Commented] (ZOOKEEPER-2028) TestClient#testAuth aborts
because ASSERT throws execption again in destructor when there is active
execption already
[ https://issues.apache.org/jira/browse/ZOOKEEPER-2028?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14138628#comment-14138628 ]
Qiang Tian commented on ZOOKEEPER-2028:
---------------------------------------
analysis:
{quote}
[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}
above error is caused by below test unit:
src/c/tests/TestClient.cc:
void testAuth() {
// auth as pat, create /tauth1, close session
rc = zoo_add_auth(zk, "digest", "pat:passwd", 10, voidCompletion,
(void*)ZOK);
static void voidCompletion(int rc, const void *data) {
int tmp = (int) (long) data;
CPPUNIT_ASSERT_EQUAL(tmp, rc); // <----this line
count++;
}
but it is not expected behavior - there is no source code line provided and the program aborted.
with more debug, we hit below code path(frame #1 is my debug code):
{quote}
#0 0x000000398b8acb8d in nanosleep () from /lib64/libc.so.6
#1 0x000000398b8aca00 in sleep () from /lib64/libc.so.6
#2 0x000000000042fd1b in Zookeeper_simpleSystem::voidCompletion (rc=-116, data=<value optimized out>)
at /home/tianq/zookeeper/src/c/tests/TestClient.cc:440
#3 0x00000000004566f1 in free_completions (zh=0x22582c0, callCompletion=1, reason=-116)
at /home/tianq/zookeeper/src/c/src/zookeeper.c:1200
#4 0x000000000045aa4c in zookeeper_close (zh=0x22582c0)
at /home/tianq/zookeeper/src/c/src/zookeeper.c:2496
#5 0x000000000040d7ef in watchCtx::~watchCtx (this=0x7fff9b93cc90, __in_chrg=<value optimized out>)
at /home/tianq/zookeeper/src/c/tests/TestClientRetry.cc:115
#6 0x000000000043916a in Zookeeper_simpleSystem::testAuth (this=<value optimized out>)
at /home/tianq/zookeeper/src/c/tests/TestClient.cc:649
#7 0x000000334ee24d3a in CppUnit::TestCaseMethodFunctor::operator()() const ()
from /usr/lib64/libcppunit-1.12.so.1
#8 0x000000334ee1a064 in CppUnit::DefaultProtector::protect(CppUnit::Functor const&, CppUnit::ProtectorContext const&) () from /usr/lib64/libcppunit-1.12.so.1
#9 0x000000334ee21647 in CppUnit::ProtectorChain::protect(CppUnit::Functor const&, CppUnit::ProtectorContext const&) () from /usr/lib64/libcppunit-1.12.so.1
#10 0x000000334ee2a854 in CppUnit::TestResult::protect(CppUnit::Functor const&, CppUnit::Test*, std::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) ()
from /usr/lib64/libcppunit-1.12.so.1
#11 0x000000334ee24a18 in CppUnit::TestCase::run(CppUnit::TestResult*) ()
from /usr/lib64/libcppunit-1.12.so.1:
{quote}
Regarding callback voidCompletion, there are 2 possible code paths:
a)zookeeper_process. this is the expected call in this test. "Processing AUTH_XID" will be logged after the processing, if debug is on.
b)zookeeper_close->process_completions. when we close connection.
in this case we hit the 2nd code path, when we leave testAuth and destruct watchCtx object.
however, that is not the first failure. the real problem is actually this line:
{code}
// auth as pat, create /tauth1, close session
rc = zoo_add_auth(zk, "digest", "pat:passwd", 10, voidCompletion,
(void*)ZOK);
CPPUNIT_ASSERT_EQUAL((int) ZOK, rc);
waitForVoidCompletion(3); //wait for 3 seconds, then decrement count anyway.
CPPUNIT_ASSERT(count == 0); //<--- the count is -1, the assert fails and throw exception, cppunit try/catch triggered object destructor, which triggers zookeeper_close code path and the callback.
{code}
the related code of cppunit:
{code}
#define CPPUNIT_ASSERT(condition) \
( CPPUNIT_NS::Asserter::failIf( !(condition), \
CPPUNIT_NS::Message( "assertion failed", \
"Expression: " #condition), \
CPPUNIT_SOURCELINE() ) )
void
Asserter::failIf( bool shouldFail,
const Message &message,
const SourceLine &sourceLine )
{
if ( shouldFail )
fail( message, sourceLine );
}
void
Asserter::fail( const Message &message,
const SourceLine &sourceLine )
{
throw Exception( message, sourceLine );
}
//exception should be caught here
bool
DefaultProtector::protect( const Functor &functor,
const ProtectorContext &context )
{
try
{
return functor(); //call the Testcase function
}
catch ( Exception &failure )
{
reportFailure( context, failure );
}
catch ( std::exception &e )
{
std::string shortDescription( "uncaught exception of type " );
#if CPPUNIT_USE_TYPEINFO_NAME
shortDescription += TypeInfoHelper::getClassName( typeid(e) );
#else
shortDescription += "std::exception (or derived).";
#endif
Message message( shortDescription, e.what() );
reportError( context, message );
}
catch ( ... )
{
reportError( context,
Message( "uncaught exception of unknown type") );
}
return false;
}
{code}
in short it is a typical problem of rule 8, "Effective C++"
> TestClient#testAuth aborts because ASSERT throws execption again in destructor when there is active execption already
> ---------------------------------------------------------------------------------------------------------------------
>
> 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
> Assignee: 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)