ZooKeeper
  1. ZooKeeper
  2. ZOOKEEPER-921

zkPython incorrectly checks for existence of required ACL elements

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 3.3.1, 3.4.0
    • Fix Version/s: 3.3.3, 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.

      1. zktest.py
        0.4 kB
        Nicholas Knight
      2. ZOOKEEPER-921.patch
        1 kB
        Nicholas Knight

        Activity

        Hide
        Hudson added a comment -

        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)

        Show
        Hudson added a comment - 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)
        Hide
        Henry Robinson added a comment -

        I just committed this to trunk and 3.3. Thanks Nicholas!

        Show
        Henry Robinson added a comment - I just committed this to trunk and 3.3. Thanks Nicholas!
        Hide
        Henry Robinson added a comment -

        +1

        Nice work, particularly nice catch on the test not running bug. I'll commit this shortly.

        Show
        Henry Robinson added a comment - +1 Nice work, particularly nice catch on the test not running bug. I'll commit this shortly.
        Hide
        Mahadev konar added a comment -

        henry, can you please review this patch? Also, can you please recommend if this should go into 3.3.3 or not?

        Show
        Mahadev konar added a comment - henry, can you please review this patch? Also, can you please recommend if this should go into 3.3.3 or not?
        Hide
        Hadoop QA added a comment -

        +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.

        Show
        Hadoop QA added a comment - +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.
        Hide
        Nicholas Knight added a comment -

        Hmm. Here's the patch. JIRA's "submit patch" interface confused me. :/

        Show
        Nicholas Knight added a comment - Hmm. Here's the patch. JIRA's "submit patch" interface confused me. :/
        Hide
        Nicholas Knight added a comment -

        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.

        Show
        Nicholas Knight added a comment - 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.
        Hide
        Nicholas Knight added a comment -

        Sorry, been swamped. I'll have time to get a proper patch posted over the weekend.

        Show
        Nicholas Knight added a comment - Sorry, been swamped. I'll have time to get a proper patch posted over the weekend.
        Hide
        Henry Robinson added a comment -

        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

        Show
        Henry Robinson added a comment - 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
        Hide
        Nicholas Knight added a comment -

        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:

        zookeeper.c
            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',)

        Show
        Nicholas Knight added a comment - 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: zookeeper.c 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',)
        Hide
        Nicholas Knight added a comment -

        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 required
        

        If 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?
        
        Show
        Nicholas Knight added a comment - 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 required If 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?

          People

          • Assignee:
            Nicholas Knight
            Reporter:
            Nicholas Knight
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development