This was discovered due to testing session expiration per a prior Zookeeper users thread. Upon deeper investigation it seems that the second client is unable to connect to Zookeeper because it is supplying the wrong password. This results in the connection being dropped and the client getting a EXPIRED_SESSION_STATE, when its not actually expired, its a bad password.

I've changed the subject here to ensure this gets more attention for the bug it likely is.

I dropped additional debug statements into the C API to echo the password out, and the password it gets is not what Python sees. With one password the C binding got back, the Python API had *no password at all*, or it has less than 16 bytes, which is clearly a bug as the password is always 16 bytes.

I tweaked the C layer to output this after connection:
                    LOG_INFO(("Password is: %02x", zh->client_id.passwd));

Granted, I should probably use a better print modifier, I'm a C newb unfortunately. This is what I see in my logs during the problem:

ZooKeeper: INFO: check_events@1747: session establishment complete on server [127.0.0.1:20000], sessionId=0x139507b99fe00c6, negotiated timeout=10000
ZooKeeper: INFO: check_events@1748: Password is: 2502978
kazoo.testing: DEBUG: Password is:

Note, yes, there should be a password from the kazoo.testing line, its where I'm spitting out the hex password in Python. Problem is, there *is no password* available from Python. The Zookeeper server generates 16 random bytes for the password, and when it gets to Python... there's nothing.

This doesn't happen every time, which has me thinking that there is something in the C binding that is resulting in the mistranslation of the password when it contains certain characters getting truncated. I've noticed that the amount of characters in the Python one when the test fails is between 0-15 characters in length. Not the 16 it should be.

At this point, I don't know exactly where the bytes are being dropped. Digging through 2 layers is also very discouraging. Having a pure Python API to talk to Zookeeper has suddenly become much more attractive.

Cheers,
Ben

On Aug 22, 2012, at 4:38 PM, Ben Bangert <[EMAIL PROTECTED]> wrote:

> I tweaked the C layer to output this after connection:
>                    LOG_INFO(("Password is: %02x", zh->client_id.passwd));
>
> Granted, I should probably use a better print modifier, I'm a C newb unfortunately. This is what I see in my logs during the problem:
>
> ZooKeeper: INFO: check_events@1747: session establishment complete on server [127.0.0.1:20000], sessionId=0x139507b99fe00c6, negotiated timeout=10000
> ZooKeeper: INFO: check_events@1748: Password is: 2502978
> kazoo.testing: DEBUG: Password is:

For a possibly more helpful message, I changed it to:
LOG_INFO(("Password is: %#llx", zh->client_id.passwd));

Here's a failure with that:
ZooKeeper: INFO: check_events@1749: Password is: 0x101883698
kazoo.testing: DEBUG: Password is: c46b53ec5b9290, length: 7

Here we can see that the C layer got a password (not sure on C encoding if thats 16 bytes or not), and the Python one was 7 characters (prolly 6 chars, it seems to count one extra). So something is quite wrong here, and of course supplying the wrong password gets a session expired issue.

If someone that knows C better can translate that password back to the raw bytes, perhaps it'd be a good test case somewhere to see that the bytes aren't mucked up someone on the way to Python.

Cheers,
Ben

Hi Ben -

Possibly you're running in to https://issues.apache.org/jira/browse/ZOOKEEPER-1398, which is to do with zkpython prematurely truncating a password due to it containing a null byte. Unfortunately that's not yet resolved, but it's worth checking to see if your problem is the same.

Henry
Sent from my iPad

On Aug 23, 2012, at 1:58 AM, Ben Bangert <[EMAIL PROTECTED]> wrote:

> On Aug 22, 2012, at 4:38 PM, Ben Bangert <[EMAIL PROTECTED]> wrote:
>
>> I tweaked the C layer to output this after connection:
>>                   LOG_INFO(("Password is: %02x", zh->client_id.passwd));
>>
>> Granted, I should probably use a better print modifier, I'm a C newb unfortunately. This is what I see in my logs during the problem:
>>
>> ZooKeeper: INFO: check_events@1747: session establishment complete on server [127.0.0.1:20000], sessionId=0x139507b99fe00c6, negotiated timeout=10000
>> ZooKeeper: INFO: check_events@1748: Password is: 2502978
>> kazoo.testing: DEBUG: Password is:
>
> For a possibly more helpful message, I changed it to:
> LOG_INFO(("Password is: %#llx", zh->client_id.passwd));
>
> Here's a failure with that:
> ZooKeeper: INFO: check_events@1749: Password is: 0x101883698
> kazoo.testing: DEBUG: Password is: c46b53ec5b9290, length: 7
>
> Here we can see that the C layer got a password (not sure on C encoding if thats 16 bytes or not), and the Python one was 7 characters (prolly 6 chars, it seems to count one extra). So something is quite wrong here, and of course supplying the wrong password gets a session expired issue.
>
> If someone that knows C better can translate that password back to the raw bytes, perhaps it'd be a good test case somewhere to see that the bytes aren't mucked up someone on the way to Python.
>
> Cheers,
> Ben

On Thu, Aug 23, 2012 at 12:58 PM, Henry Robinson <[EMAIL PROTECTED]> wrote:
> Possibly you're running in to https://issues.apache.org/jira/browse/ZOOKEEPER-1398, which is to do with zkpython prematurely truncating a password due to it containing a null byte. Unfortunately that's not yet resolved, but it's worth checking to see if your problem is the same.

That's indeed been the problem.

We've applied the patch to our own statically compiled zkpython
binding and released it at
http://pypi.python.org/pypi/zc-zookeeper-static/3.4.3-5.

Hanno