Details
-
Type:
Bug
-
Status: Closed
-
Priority:
Major
-
Resolution: Fixed
-
Affects Version/s: 3.3.1, 3.4.0
-
Component/s: contrib-bindings
-
Labels:None
-
Environment:
Mac OS X 10.6.4, included Python 2.6.1
-
Hadoop Flags:Reviewed
Description
Calling zookeeper.create() seems, under certain circumstances, to be corrupting a subsequent call to Python's logging module.
Specifically, if the node does not exist (but its parent does), I end up with a traceback like this when I try to make the logging call:
Traceback (most recent call last):
File "zktest.py", line 21, in <module>
logger.error("Boom?")
File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/logging/__init__.py", line 1046, in error
if self.isEnabledFor(ERROR):
File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/logging/__init__.py", line 1206, in isEnabledFor
return level >= self.getEffectiveLevel()
File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/logging/__init__.py", line 1194, in getEffectiveLevel
while logger:
TypeError: an integer is required
But if the node already exists, or the parent does not exist, I get the appropriate NodeExists or NoNode exceptions.
I'll be attaching a test script that can be used to reproduce this behavior.
Activity
- All
- Comments
- Work Log
- History
- Activity
- Transitions
I've found the actual problem.
The direct cause was that I forgot to include the 'perms' element in the ACL. My bad.
Contributing to the difficulty in figuring out what the heck was going on was the fact that check_is_acl() in src/contrib/zkpython/src/zookeeper.c incorrectly checks for the existence of the required elements:
entry = PyDict_GetItemString( element, "perms" );
if (entry == Py_None) {
return 0;
}
Per the Python C API docs (http://docs.python.org/c-api/dict.html#PyDict_GetItemString), PyDict_GetItemString returns NULL, not Py_None, if the item doesn't exist.
There are probably some other checks that should really be done in check_is_acl(), but just changing Py_None to NULL in each if (entry == ... check resulted in the correct behavior – a useful exception: Caught exception: InvalidACLException('invalid acl',)
Nicholas -
Good catch, thanks! Do you think you will be able to submit a patch fixing the args checking in check_is_acl()?
Thanks,
Henry
Sorry, been swamped. I'll have time to get a proper patch posted over the weekend.
So, I was going to do a more comprehensive error checking patch, but after a brief journey through the source for zookeeper's C bindings, the Java API docs, and a bit of the java server code, the exact rules for what does constitute a valid ACL are completely unclear to me, so for now I'm limiting this to what I feel sure is at least "more correct" than what we already have.
Note that while there's no new test included in this patch, acl.py:ACLTest.test_invalid_acl2() should have been catching this issue, but a rogue comma prevented it from running correctly. This patch removes the rogue comma. Without the Py_None -> NULL change, the fixed test fails (well, actually, segfaults, at least on OS X), and with the change, it passes.
Hmm. Here's the patch. JIRA's "submit patch" interface confused me. :/
+1 overall. Here are the results of testing the latest attachment
http://issues.apache.org/jira/secure/attachment/12459558/ZOOKEEPER-921.patch
against trunk revision 1034003.
+1 @author. The patch does not contain any @author tags.
+1 tests included. The patch appears to include 3 new or modified tests.
+1 javadoc. The javadoc tool did not generate any warning messages.
+1 javac. The applied patch does not increase the total number of javac compiler warnings.
+1 findbugs. The patch does not introduce any new Findbugs warnings.
+1 release audit. The applied patch does not increase the total number of release audit warnings.
+1 core tests. The patch passed core unit tests.
+1 contrib tests. The patch passed contrib unit tests.
Test results: https://hudson.apache.org/hudson/job/PreCommit-ZOOKEEPER-Build/27//testReport/
Findbugs warnings: https://hudson.apache.org/hudson/job/PreCommit-ZOOKEEPER-Build/27//artifact/trunk/build/test/findbugs/newPatchFindbugsWarnings.html
Console output: https://hudson.apache.org/hudson/job/PreCommit-ZOOKEEPER-Build/27//console
This message is automatically generated.
henry, can you please review this patch? Also, can you please recommend if this should go into 3.3.3 or not?
+1
Nice work, particularly nice catch on the test not running bug. I'll commit this shortly.
I just committed this to trunk and 3.3. Thanks Nicholas!
Integrated in ZooKeeper-trunk #1051 (See https://hudson.apache.org/hudson/job/ZooKeeper-trunk/1051/)
ZOOKEEPER-921. zkPython incorrectly checks for existence of required ACL elements (Nicholas Knight via henryr)
Script showing issue. This has been tested with a ZooKeeper 3.3.1 instance, with both the bindings in the 3.3.1 source tree, and those from an svn checkout of trunk (from within the last few hours). Results were identical with both bindings.
If '/SomeDir' exists, but '/SomeDir/last_modified' does not, this is the erroneous output from the script:
2010-11-08 16:53:04,916:2623(0x7fff71077c20):ZOO_INFO@log_env@660: Client environment:zookeeper.version=zookeeper C client 3.4.0 2010-11-08 16:53:04,916:2623(0x7fff71077c20):ZOO_INFO@log_env@664: Client environment:host.name=Nicholas-Knights-MacBook-Pro.local 2010-11-08 16:53:04,916:2623(0x7fff71077c20):ZOO_INFO@log_env@671: Client environment:os.name=Darwin 2010-11-08 16:53:04,916:2623(0x7fff71077c20):ZOO_INFO@log_env@672: Client environment:os.arch=10.4.0 2010-11-08 16:53:04,916:2623(0x7fff71077c20):ZOO_INFO@log_env@673: Client environment:os.version=Darwin Kernel Version 10.4.0: Fri Apr 23 18:28:53 PDT 2010; root:xnu-1504.7.4~1/RELEASE_I386 2010-11-08 16:53:04,916:2623(0x7fff71077c20):ZOO_INFO@log_env@681: Client environment:user.name=nknight 2010-11-08 16:53:04,917:2623(0x7fff71077c20):ZOO_INFO@log_env@689: Client environment:user.home=/Users/nknight 2010-11-08 16:53:04,917:2623(0x7fff71077c20):ZOO_INFO@log_env@701: Client environment:user.dir=/Users/nknight 2010-11-08 16:53:04,917:2623(0x7fff71077c20):ZOO_INFO@zookeeper_init@729: Initiating client connection, host=127.0.0.1:2181 sessionTimeout=10000 watcher=0x0 sessionId=0 sessionPasswd=<null> context=0x0 flags=0 2010-11-08 16:53:04,917:2623(0x100602000):ZOO_INFO@check_events@1587: initiated connection to server [127.0.0.1:2181] 2010-11-08 16:53:04,919:2623(0x100602000):ZOO_INFO@check_events@1634: session establishment complete on server [127.0.0.1:2181], sessionId=0x12c2a04fa7501ab, negotiated timeout=10000 Traceback (most recent call last): File "zktest.py", line 21, in <module> logger.debug("Boom?") File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/logging/__init__.py", line 1008, in debug if self.isEnabledFor(DEBUG): File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/logging/__init__.py", line 1206, in isEnabledFor return level >= self.getEffectiveLevel() File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/logging/__init__.py", line 1194, in getEffectiveLevel while logger: TypeError: an integer is requiredIf the node already exists (as is the case if you run the script a second time), you get expected results:
2010-11-08 16:55:55,555:2630(0x7fff71077c20):ZOO_INFO@log_env@660: Client environment:zookeeper.version=zookeeper C client 3.4.0 2010-11-08 16:55:55,555:2630(0x7fff71077c20):ZOO_INFO@log_env@664: Client environment:host.name=Nicholas-Knights-MacBook-Pro.local 2010-11-08 16:55:55,555:2630(0x7fff71077c20):ZOO_INFO@log_env@671: Client environment:os.name=Darwin 2010-11-08 16:55:55,555:2630(0x7fff71077c20):ZOO_INFO@log_env@672: Client environment:os.arch=10.4.0 2010-11-08 16:55:55,555:2630(0x7fff71077c20):ZOO_INFO@log_env@673: Client environment:os.version=Darwin Kernel Version 10.4.0: Fri Apr 23 18:28:53 PDT 2010; root:xnu-1504.7.4~1/RELEASE_I386 2010-11-08 16:55:55,555:2630(0x7fff71077c20):ZOO_INFO@log_env@681: Client environment:user.name=nknight 2010-11-08 16:55:55,556:2630(0x7fff71077c20):ZOO_INFO@log_env@689: Client environment:user.home=/Users/nknight 2010-11-08 16:55:55,556:2630(0x7fff71077c20):ZOO_INFO@log_env@701: Client environment:user.dir=/Users/nknight 2010-11-08 16:55:55,556:2630(0x7fff71077c20):ZOO_INFO@zookeeper_init@729: Initiating client connection, host=127.0.0.1:2181 sessionTimeout=10000 watcher=0x0 sessionId=0 sessionPasswd=<null> context=0x0 flags=0 2010-11-08 16:55:55,557:2630(0x100602000):ZOO_INFO@check_events@1587: initiated connection to server [127.0.0.1:2181] 2010-11-08 16:55:55,558:2630(0x100602000):ZOO_INFO@check_events@1634: session establishment complete on server [127.0.0.1:2181], sessionId=0x12c2a04fa7501ac, negotiated timeout=10000 Caught exception: NodeExistsException('node exists',) DEBUG:Boom:Boom?If /SomeDir doesn't exist, you also get expected results:
2010-11-08 16:56:59,198:2634(0x7fff71077c20):ZOO_INFO@log_env@660: Client environment:zookeeper.version=zookeeper C client 3.4.0 2010-11-08 16:56:59,198:2634(0x7fff71077c20):ZOO_INFO@log_env@664: Client environment:host.name=Nicholas-Knights-MacBook-Pro.local 2010-11-08 16:56:59,198:2634(0x7fff71077c20):ZOO_INFO@log_env@671: Client environment:os.name=Darwin 2010-11-08 16:56:59,198:2634(0x7fff71077c20):ZOO_INFO@log_env@672: Client environment:os.arch=10.4.0 2010-11-08 16:56:59,198:2634(0x7fff71077c20):ZOO_INFO@log_env@673: Client environment:os.version=Darwin Kernel Version 10.4.0: Fri Apr 23 18:28:53 PDT 2010; root:xnu-1504.7.4~1/RELEASE_I386 2010-11-08 16:56:59,198:2634(0x7fff71077c20):ZOO_INFO@log_env@681: Client environment:user.name=nknight 2010-11-08 16:56:59,199:2634(0x7fff71077c20):ZOO_INFO@log_env@689: Client environment:user.home=/Users/nknight 2010-11-08 16:56:59,199:2634(0x7fff71077c20):ZOO_INFO@log_env@701: Client environment:user.dir=/Users/nknight 2010-11-08 16:56:59,199:2634(0x7fff71077c20):ZOO_INFO@zookeeper_init@729: Initiating client connection, host=127.0.0.1:2181 sessionTimeout=10000 watcher=0x0 sessionId=0 sessionPasswd=<null> context=0x0 flags=0 2010-11-08 16:56:59,200:2634(0x100602000):ZOO_INFO@check_events@1587: initiated connection to server [127.0.0.1:2181] 2010-11-08 16:56:59,202:2634(0x100602000):ZOO_INFO@check_events@1634: session establishment complete on server [127.0.0.1:2181], sessionId=0x12c2a04fa7501ad, negotiated timeout=10000 Caught exception: NoNodeException('no node',) DEBUG:Boom:Boom?