Hi all,
Note: when I came at the end of this mail, I understood what was going
on so I could do a fix and conclude that it was really no big deal. But
for those interested in weird behaviour, please read on. ;-)
Using Plone 3.3.5. I am working on a PAS plugin, so I had enabled the
debug level for logging ('event-log-level = debug' in [instance]). I
started seeing these messages in the log:
2010-08-12 15:36:14 DEBUG PluggableAuthService ExtractionPlugin
credentials_cookie_auth error
Traceback (most recent call last):
File
"/Users/mauritsvanrees/shared-eggs/Products.PluggableAuthService-1.6.3-py2.4.egg/Products/PluggableAuthService/PluggableAuthService.py",
line 559, in _extractUserIds
credentials = extractor.extractCredentials( request )
File
"/Users/mauritsvanrees/shared-eggs/Products.PluggableAuthService-1.6.3-py2.4.egg/Products/PluggableAuthService/plugins/CookieAuthHelper.py",
line 128, in extractCredentials
creds['login'] = login.decode('hex')
File
"/Users/mauritsvanrees/buildout/python/parts/opt/lib/python2.4/encodings/hex_codec.py",
line 42, in hex_decode
output = binascii.a2b_hex(input)
TypeError: Non-hexadecimal digit found
This was with the user 'foo' logged in. With user 'bar' everything was
fine. Removing the user and recreating it with that same id 'foo' did
not help. Nothing seemed to be going wrong; I remained logged in and
did not notice anything out of the ordinary.
It turns out I had to go to acl_users/session and create a new secret
and then the log stopped complaining.
So the problem was in the signing secret. With Undo I went back to the
previous secret and started a bin/instance debug:
>>> app.test.acl_users.session.source.getSigningSecret()
'&\xbcE\xbe\x08\x84\xe9\xe4\x0b\xf0\x07D\xad\\\xbd\t\xe9\x1f\x0f\xab`\x16\x86-\x01k(\xe2\xb2\xfa/S\x81GK\xf2V~g\x1bg{\xd8h\xe9\x04\r\x8fjJfb\xf9\xf3\x05k\xb1\x1a\xc5[r!\xe9\xd1'
>>> app.test.acl_users.session.source.signUserid('foo')
'\x1e/\xdeKG\x10:\x80[\xc6\xfa\xab\xf5\x91\xe5\xec\xde\xf2+\xca'
>>> app.test.acl_users.session.source.signUserid('bar')
'\xad\xa5B\xa9\x97)\xa1\x1e\x8a\xd2\x06\xf3j[\xd9m\x11\xd1%,'
Note that with signUserid('foo') you get a colon (:) in the string and I
guess that is what causes the problem.
I could reproduce it in the plonenext 3.3. buildout with bin/instance debug:
>>> from zope.annotation import IAnnotations
>>> anno = IAnnotations(app.test.acl_users.session)
>>> old_secrets = anno['plone.session.plugins.hash.secrets']
>>> new_secret =
'&\xbcE\xbe\x08\x84\xe9\xe4\x0b\xf0\x07D\xad\\\xbd\t\xe9\x1f\x0f\xab`\x16\x86-\x01k(\xe2\xb2\xfa/S\x81GK\xf2V~g\x1bg{\xd8h\xe9\x04\r\x8fjJfb\xf9\xf3\x05k\xb1\x1a\xc5[r!\xe9\xd1'
>>> anno['plone.session.plugins.hash.secrets'] = [new_secret]
>>> app.test.acl_users.session.source.signUserid('foo')
'\x1e/\xdeKG\x10:\x80[\xc6\xfa\xab\xf5\x91\xe5\xec\xde\xf2+\xca'
>>> import transaction
>>> transaction.commit()
If I then restarted the instance (with the debug log level) and created
a user foo, I would get that same error in the logs.
I guess my question is: should we care? Nothing seems to be really
going wrong, but it feels like some code is making assumptions that are
not true.
Okay, I am beginning to grasp what is going on here. It helps to
talk/write to myself. ;-) The code that throws the error is this part
from the extractCredentials method in
Products/PluggableAuthService/plugins/CookieAuthHelper.py:
==================================================================
cookie_val = decodestring(unquote(cookie))
try:
login, password = cookie_val.split(':')
except ValueError:
# Cookie is in a different format, so it is not ours
return creds
# The next line goes wrong:
creds['login'] = login.decode('hex')
creds['password'] = password.decode('hex')
==================================================================
What happens is that CookieAuthHelper tries to parse a cookie that is
set by plone.session. Usually this would raise a ValueError, which gets
excepted and it returns creds, which at that point is an empty
dictionary. In our case by coincidence the cookie contains a colon,
which means the ValueError is not raised. Execution goes further under
the wrong assumption that the cookie is from CookieAuthHelper.
What should help is to wrap the decode('hex') calls in an except
TypeError and return an empty dictionary. Yes, I can confirm that
works. I'll commit that.
Note that if I have seen this correctly, then it should not really
matter in practice, except that there will be no error in the log when
you the log level is debug. It might prevent some unlucky guy from
going on a wild goose chase... ;-)
--
Maurits van Rees
Programmer, Zest Software
_______________________________________________
Product-Developers mailing list
[email protected]
http://lists.plone.org/mailman/listinfo/product-developers
