[
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)
