- The RemoteUserAuthenticationPolicy , ``AuthTktAuthenticationPol…

…icy``,

  and ``SessionAuthenticationPolicy`` constructors now accept an additional
  keyword argument named ``debug``.  By default, this keyword argument is
  ``False``.  When it is ``True``, debug information will be sent to the
  Pyramid debug logger (usually on stderr) when the ``authenticated_userid``
  or ``effective_principals`` method is called on any of these policies.  The
  output produced can be useful when trying to diagnose
  authentication-related problems.

CHANGES.txt

@@ -89,6 +89,15 @@ Features
   Previously, trying to generate a URL to an asset using an absolute file
   path would raise a ValueError.
 
+- The ``RemoteUserAuthenticationPolicy ``, ``AuthTktAuthenticationPolicy``,
+  and ``SessionAuthenticationPolicy`` constructors now accept an additional
+  keyword argument named ``debug``.  By default, this keyword argument is
+  ``False``.  When it is ``True``, debug information will be sent to the
+  Pyramid debug logger (usually on stderr) when the ``authenticated_userid``
+  or ``effective_principals`` method is called on any of these policies.  The
+  output produced can be useful when trying to diagnose
+  authentication-related problems.
+
 Internal
 --------
 

TODO.txt

@@ -14,12 +14,11 @@ Should-Have
 Nice-to-Have
 ------------
 
+- _fix_registry should dictify the registry being fixed.
+
 - Make "localizer" a property of request (instead of requiring
   "get_localizer(request)"?
 
-- Debugging setting for detecting why authenticated_userid(request) might
-  return None.
-
 - Deprecate pyramid.security.view_execution_permitted (it only works for
   traversal).
 

pyramid/authentication.py

@@ -10,6 +10,7 @@
 from zope.interface import implements
 
 from pyramid.interfaces import IAuthenticationPolicy
+from pyramid.interfaces import IDebugLogger
 
 from pyramid.request import add_global_response_headers
 from pyramid.security import Authenticated
@@ -20,30 +21,91 @@
 
 class CallbackAuthenticationPolicy(object):
     """ Abstract class """
+
+    debug = False
+    callback = None
+
+    def _log(self, msg, methodname, request):
+        logger = request.registry.queryUtility(IDebugLogger)
+        if logger:
+            cls = self.__class__
+            classname = cls.__module__ + '.' + cls.__name__
+            methodname = classname + '.' + methodname
+            logger.debug(methodname + ': ' + msg)
+
     def authenticated_userid(self, request):
+        debug = self.debug
         userid = self.unauthenticated_userid(request)
         if userid is None:
+            debug and self._log(
+                'call to unauthenticated_userid returned None; returning None',
+                'authenticated_userid',
+                request)
             return None
         if self.callback is None:
+            debug and self._log(
+                'there was no groupfinder callback; returning %r' % (userid,),
+                'authenticated_userid',
+                request)
             return userid
-        if self.callback(userid, request) is not None: # is not None!
+        callback_ok = self.callback(userid, request)
+        if callback_ok is not None: # is not None!
+            debug and self._log(
+                'groupfinder callback returned %r; returning %r' % (
+                    callback_ok, userid),
+                'authenticated_userid',
+                request
+                )
             return userid
+        debug and self._log(
+            'groupfinder callback returned None; returning None',
+            'authenticated_userid',
+            request
+            )
 
     def effective_principals(self, request):
+        debug = self.debug
         effective_principals = [Everyone]
         userid = self.unauthenticated_userid(request)
         if userid is None:
+            debug and self._log(
+                'authenticated_userid returned %r; returning %r' % (
+                    userid, effective_principals),
+                'effective_principals',
+                request
+                )
             return effective_principals
         if self.callback is None:
+            debug and self._log(
+                'groupfinder callback is None, so groups is []',
+                'effective_principals',
+                request)
             groups = []
         else:
             groups = self.callback(userid, request)
+            debug and self._log(
+                'groupfinder callback returned %r as groups' % (groups,),
+                'effective_principals',
+                request)
         if groups is None: # is None!
+            debug and self._log(
+                'returning effective principals: %r' % (
+                    effective_principals,),
+                'effective_principals',
+                request
+                )
             return effective_principals
+
         effective_principals.append(Authenticated)
         effective_principals.append(userid)
         effective_principals.extend(groups)
 
+        debug and self._log(
+            'returning effective principals: %r' % (
+                effective_principals,),
+            'effective_principals',
+            request
+             )
         return effective_principals
 
 
@@ -154,14 +216,22 @@ class RemoteUserAuthenticationPolicy(CallbackAuthenticationPolicy):
         user does exist.  If ``callback`` is None, the userid will be assumed
         to exist with no group principals.
 
+    ``debug``
+
+        Default: ``False``.  If ``debug`` is ``True``, log messages to the
+        Pyramid debug logger about the results of various authentication
+        steps.  The output from debugging is useful for reporting to maillist
+        or IRC channels when asking for support.
+
     Objects of this class implement the interface described by
     :class:`pyramid.interfaces.IAuthenticationPolicy`.
     """
     implements(IAuthenticationPolicy)
 
-    def __init__(self, environ_key='REMOTE_USER', callback=None):
+    def __init__(self, environ_key='REMOTE_USER', callback=None, debug=False):
         self.environ_key = environ_key
         self.callback = callback
+        self.debug = debug
 
     def unauthenticated_userid(self, request):
         return request.environ.get(self.environ_key)
@@ -264,6 +334,13 @@ class AuthTktAuthenticationPolicy(CallbackAuthenticationPolicy):
        wildcard domain.
        Optional.
 
+    ``debug``
+
+        Default: ``False``.  If ``debug`` is ``True``, log messages to the
+        Pyramid debug logger about the results of various authentication
+        steps.  The output from debugging is useful for reporting to maillist
+        or IRC channels when asking for support.
+
     Objects of this class implement the interface described by
     :class:`pyramid.interfaces.IAuthenticationPolicy`.
     """
@@ -280,6 +357,7 @@ def __init__(self,
                  path="/",
                  http_only=False,
                  wild_domain=True,
+                 debug=False,
                  ):
         self.cookie = AuthTktCookieHelper(
             secret,
@@ -294,6 +372,7 @@ def __init__(self,
             wild_domain=wild_domain,
             )
         self.callback = callback
+        self.debug = debug
 
     def unauthenticated_userid(self, request):
         result = self.cookie.identify(request)
@@ -545,13 +624,22 @@ class SessionAuthenticationPolicy(CallbackAuthenticationPolicy):
        exist or a sequence of principal identifiers (possibly empty) if
        the user does exist.  If ``callback`` is ``None``, the userid
        will be assumed to exist with no principals.  Optional.
+
+    ``debug``
+
+        Default: ``False``.  If ``debug`` is ``True``, log messages to the
+        Pyramid debug logger about the results of various authentication
+        steps.  The output from debugging is useful for reporting to maillist
+        or IRC channels when asking for support.
+       
     """
     implements(IAuthenticationPolicy)
 
-    def __init__(self, prefix='auth.', callback=None):
+    def __init__(self, prefix='auth.', callback=None, debug=False):
         self.callback = callback
         self.prefix = prefix or ''
         self.userid_key = prefix + 'userid'
+        self.debug = debug
 
     def remember(self, request, principal, **kw):
         """ Store a principal in the session."""

pyramid/tests/test_authentication.py

@@ -1,4 +1,144 @@
 import unittest
+from pyramid import testing
+
+class TestCallbackAuthenticationPolicyDebugging(unittest.TestCase):
+    def setUp(self):
+        from pyramid.interfaces import IDebugLogger
+        self.config = testing.setUp()
+        self.config.registry.registerUtility(self, IDebugLogger)
+        self.messages = []
+
+    def tearDown(self):
+        del self.config
+
+    def debug(self, msg):
+        self.messages.append(msg)
+
+    def _makeOne(self, userid=None, callback=None):
+        from pyramid.authentication import CallbackAuthenticationPolicy
+        class MyAuthenticationPolicy(CallbackAuthenticationPolicy):
+            def unauthenticated_userid(self, request):
+                return userid
+        policy = MyAuthenticationPolicy()
+        policy.debug = True
+        policy.callback = callback
+        return policy
+
+    def test_authenticated_userid_no_unauthenticated_userid(self):
+        request = DummyRequest(registry=self.config.registry)
+        policy = self._makeOne()
+        self.assertEqual(policy.authenticated_userid(request), None)
+        self.assertEqual(len(self.messages), 1)
+        self.assertEqual(
+            self.messages[0],
+            'pyramid.tests.test_authentication.MyAuthenticationPolicy.'
+            'authenticated_userid: call to unauthenticated_userid returned '
+            'None; returning None')
+
+    def test_authenticated_userid_no_callback(self):
+        request = DummyRequest(registry=self.config.registry)
+        policy = self._makeOne(userid='fred')
+        self.assertEqual(policy.authenticated_userid(request), 'fred')
+        self.assertEqual(len(self.messages), 1)
+        self.assertEqual(
+            self.messages[0],
+             "pyramid.tests.test_authentication.MyAuthenticationPolicy."
+            "authenticated_userid: there was no groupfinder callback; "
+            "returning 'fred'")
+
+    def test_authenticated_userid_with_callback_fail(self):
+        request = DummyRequest(registry=self.config.registry)
+        def callback(userid, request):
+            return None
+        policy = self._makeOne(userid='fred', callback=callback)
+        self.assertEqual(policy.authenticated_userid(request), None)
+        self.assertEqual(len(self.messages), 1)
+        self.assertEqual(
+            self.messages[0],
+            'pyramid.tests.test_authentication.MyAuthenticationPolicy.'
+            'authenticated_userid: groupfinder callback returned None; '
+            'returning None')
+
+    def test_authenticated_userid_with_callback_success(self):
+        request = DummyRequest(registry=self.config.registry)
+        def callback(userid, request):
+            return []
+        policy = self._makeOne(userid='fred', callback=callback)
+        self.assertEqual(policy.authenticated_userid(request), 'fred')
+        self.assertEqual(len(self.messages), 1)
+        self.assertEqual(
+            self.messages[0],
+            "pyramid.tests.test_authentication.MyAuthenticationPolicy."
+            "authenticated_userid: groupfinder callback returned []; "
+            "returning 'fred'")
+
+    def test_effective_principals_no_unauthenticated_userid(self):
+        request = DummyRequest(registry=self.config.registry)
+        policy = self._makeOne()
+        self.assertEqual(policy.effective_principals(request),
+                         ['system.Everyone'])
+        self.assertEqual(len(self.messages), 1)
+        self.assertEqual(
+            self.messages[0],
+            "pyramid.tests.test_authentication.MyAuthenticationPolicy."
+            "effective_principals: authenticated_userid returned None; "
+            "returning ['system.Everyone']")
+
+    def test_effective_principals_no_callback(self):
+        request = DummyRequest(registry=self.config.registry)
+        policy = self._makeOne(userid='fred')
+        self.assertEqual(
+            policy.effective_principals(request),
+            ['system.Everyone', 'system.Authenticated', 'fred'])
+        self.assertEqual(len(self.messages), 2)
+        self.assertEqual(
+            self.messages[0],
+            'pyramid.tests.test_authentication.MyAuthenticationPolicy.'
+            'effective_principals: groupfinder callback is None, so groups '
+            'is []')
+        self.assertEqual(
+            self.messages[1],
+            "pyramid.tests.test_authentication.MyAuthenticationPolicy."
+            "effective_principals: returning effective principals: "
+            "['system.Everyone', 'system.Authenticated', 'fred']")
+
+    def test_effective_principals_with_callback_fail(self):
+        request = DummyRequest(registry=self.config.registry)
+        def callback(userid, request):
+            return None
+        policy = self._makeOne(userid='fred', callback=callback)
+        self.assertEqual(
+            policy.effective_principals(request), ['system.Everyone'])
+        self.assertEqual(len(self.messages), 2)
+        self.assertEqual(
+            self.messages[0],
+            'pyramid.tests.test_authentication.MyAuthenticationPolicy.'
+            'effective_principals: groupfinder callback returned None as '
+            'groups')
+        self.assertEqual(
+            self.messages[1],
+            "pyramid.tests.test_authentication.MyAuthenticationPolicy."
+            "effective_principals: returning effective principals: "
+            "['system.Everyone']")
+
+    def test_effective_principals_with_callback_success(self):
+        request = DummyRequest(registry=self.config.registry)
+        def callback(userid, request):
+            return []
+        policy = self._makeOne(userid='fred', callback=callback)
+        self.assertEqual(
+            policy.effective_principals(request),
+            ['system.Everyone', 'system.Authenticated', 'fred'])
+        self.assertEqual(len(self.messages), 2)
+        self.assertEqual(
+            self.messages[0],
+            'pyramid.tests.test_authentication.MyAuthenticationPolicy.'
+            'effective_principals: groupfinder callback returned [] as groups')
+        self.assertEqual(
+            self.messages[1],
+            "pyramid.tests.test_authentication.MyAuthenticationPolicy."
+            "effective_principals: returning effective principals: "
+            "['system.Everyone', 'system.Authenticated', 'fred']")
 
 class TestRepozeWho1AuthenticationPolicy(unittest.TestCase):
     def _getTargetClass(self):
@@ -848,9 +988,10 @@ class DummyContext:
     pass
 
 class DummyRequest:
-    def __init__(self, environ=None, session=None):
+    def __init__(self, environ=None, session=None, registry=None):
         self.environ = environ or {}
         self.session = session or {}
+        self.registry = registry
         self.callbacks = []
 
     def add_response_callback(self, callback):