Thanks for the nice write-up Maurits.
And yes, I would say that the code's willingness to treat a ':' character as the definitive indicator that a cookie is 'ours' is ill-advised, to say the least. cheers, - David On Thu, Aug 12, 2010 at 10:32, Maurits van Rees <[email protected]> wrote: > 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 > _______________________________________________ Product-Developers mailing list [email protected] http://lists.plone.org/mailman/listinfo/product-developers
