Docs

   - An "Environment and Configuration" chapter was added to the narrative 
     portion of the documentation.

  Features

   - Ensure bfg doesn't generate warnings when running under Python
     2.6.

   - The environment variable ``BFG_RELOAD_TEMPLATES`` is now available
     (serves the same purpose as ``reload_templates`` in the config file).

   - A new configuration file option ``debug_authorization`` was added.
     This turns on printing of security authorization debug statements
     to ``sys.stderr``.  The ``BFG_DEBUG_AUTHORIZATION`` environment
     variable was also added; this performs the same duty.

  Bug Fixes

   - The environment variable ``BFG_SECURITY_DEBUG`` did not always work.
     It has been renamed to ``BFG_DEBUG_AUTHORIZATION`` and fixed.

  Deprecations

   - A deprecation warning is now issued when old API names from the
     ``repoze.bfg.templates`` module are imported.

  Backwards incompatibilities

   - The ``BFG_SECURITY_DEBUG`` environment variable was renamed to
     ``BFG_DEBUG_AUTHORIZATION``.

7 files changed, 132 insertions, 59 deletions

diff --git a/repoze/bfg/interfaces.py b/repoze/bfg/interfaces.py
index ffa61a11e..bbff9bca7 100644
--- a/repoze/bfg/interfaces.py
+++ b/repoze/bfg/interfaces.py
@@ -113,3 +113,6 @@ class ILocation(Interface):
 
     __name__ = Attribute("The name within the parent")
 
+class ILogger(Interface):
+    """ Interface representing a PEP 282 logger """
+
diff --git a/repoze/bfg/log.py b/repoze/bfg/log.py
new file mode 100644
index 000000000..ac2145a47
--- /dev/null
+++ b/repoze/bfg/log.py
@@ -0,0 +1,16 @@
+import logging
+
+def make_stream_logger(name, stream, levelname='DEBUG',
+                       fmt='%(asctime)s %(message)s'):
+    """ Return an object which implements
+    ``repoze.bfg.interfaces.ILogger`` (ie. a Python PEP 282 logger
+    instance) with the name ``name`` using the stream (or open
+    filehandle) ``stream``, logging at ``levelname`` log level or
+    above with format ``fmt``. """
+    handler = logging.StreamHandler(stream)
+    formatter = logging.Formatter(fmt)
+    handler.setFormatter(formatter)
+    logger = logging.Logger(name)
+    logger.addHandler(handler)
+    logger.setLevel(getattr(logging, levelname))
+    return logger
diff --git a/repoze/bfg/registry.py b/repoze/bfg/registry.py
index 9baa0452a..836d2ad6a 100644
--- a/repoze/bfg/registry.py
+++ b/repoze/bfg/registry.py
@@ -1,3 +1,5 @@
+import os
+import sys
 import threading
 
 import zope.component
@@ -11,7 +13,9 @@ from zope.component import getSiteManager as original_getSiteManager
 from zope.interface import implements
 
 from repoze.bfg.interfaces import ISettings
+from repoze.bfg.interfaces import ILogger
 from repoze.bfg.zcml import zcml_configure
+from repoze.bfg.log import make_stream_logger
 
 class ThreadLocalRegistryManager(threading.local):
     registry = getGlobalSiteManager()
@@ -54,6 +58,10 @@ def makeRegistry(filename, package, options=None, lock=threading.Lock()):
             options = {}
         settings = Settings(options)
         registry.registerUtility(settings, ISettings)
+        if options.get('debug_authorization'):
+            auth_logger = make_stream_logger('repoze.bfg.authdebug',sys.stderr)
+            registry.registerUtility(auth_logger, ILogger,
+                                     'repoze.bfg.authdebug')
         original_getSiteManager.sethook(getSiteManager)
         zope.component.getGlobalSiteManager = registry_manager.get
         zcml_configure(filename, package=package)
@@ -82,9 +90,18 @@ def asbool(s):
     s = str(s).strip()
     return s.lower() in ('t', 'true', 'y', 'yes', 'on', '1')
 
-def get_options(kw):
+def get_options(kw, environ=os.environ):
+    # environ is passed in for unit tests
+    eget = environ.get
+    config_debug_auth = kw.get('debug_authorization', '')
+    effective_debug_auth = asbool(eget('BFG_DEBUG_AUTHORIZATION',
+                                       config_debug_auth))
+    config_reload_templates = kw.get('reload_templates')
+    effective_reload_templates = asbool(eget('BFG_RELOAD_TEMPLATES',
+                                        config_reload_templates))
     return {
-        'reload_templates':asbool(kw.get('reload_templates')),
+        'debug_authorization': effective_debug_auth,
+        'reload_templates':effective_reload_templates,
         }
 
 from zope.testing.cleanup import addCleanUp
diff --git a/repoze/bfg/security.py b/repoze/bfg/security.py
index ee54c7971..dd2f94ab8 100644
--- a/repoze/bfg/security.py
+++ b/repoze/bfg/security.py
@@ -1,4 +1,3 @@
-import logging
 import os
 import sys
 
@@ -11,6 +10,7 @@ from repoze.bfg.interfaces import ISecurityPolicy
 from repoze.bfg.interfaces import IViewPermission
 from repoze.bfg.interfaces import IViewPermissionFactory
 from repoze.bfg.interfaces import NoAuthorizationInformation
+from repoze.bfg.interfaces import ILogger
 
 Everyone = 'system.Everyone'
 Authenticated = 'system.Authenticated'
@@ -68,7 +68,7 @@ def principals_allowed_by_permission(context, permission):
 
 class ACLAuthorizer(object):
 
-    def __init__(self, context, logger=None):
+    def __init__(self, context, logger):
         self.context = context
         self.logger = logger
 
@@ -101,16 +101,16 @@ class ACLSecurityPolicy(object):
     implements(ISecurityPolicy)
     authorizer_factory = ACLAuthorizer
     
-    def __init__(self, logger, get_principals):
-        self.logger = logger
+    def __init__(self, get_principals):
         self.get_principals = get_principals
 
     def permits(self, context, request, permission):
         """ Return ``Allowed`` if the policy permits access,
         ``Denied`` if not."""
+        logger = queryUtility(ILogger, name='repoze.bfg.authdebug')
         principals = self.effective_principals(request)
         for location in lineage(context):
-            authorizer = self.authorizer_factory(location, self.logger)
+            authorizer = self.authorizer_factory(location, logger)
             try:
                 return authorizer.permits(permission, *principals)
             except NoAuthorizationInformation:
@@ -148,29 +148,13 @@ class ACLSecurityPolicy(object):
                 return sorted(allowed.keys())
         return []
 
-DEBUG_LOG_KEY = 'BFG_SECURITY_DEBUG'
-
-def debug_logger(logger):
-    if logger is None:
-        do_debug_log = os.environ.get(DEBUG_LOG_KEY, '')
-        if str(do_debug_log).lower() in ('1', 'y', 'true', 't', 'on'):
-            handler = logging.StreamHandler(sys.stdout)
-            fmt = '%(asctime)s %(message)s'
-            formatter = logging.Formatter(fmt)
-            handler.setFormatter(formatter)
-            logger = logging.Logger('repoze.bfg.security')
-            logger.addHandler(handler)
-            logger.setLevel(logging.DEBUG)
-            return logger
-    return logger
-
 def get_remoteuser(request):
     user_id = request.environ.get('REMOTE_USER')
     if user_id:
         return [user_id]
     return []
 
-def RemoteUserACLSecurityPolicy(logger=None):
+def RemoteUserACLSecurityPolicy():
     """ A security policy which:
 
     - examines the request.environ for the REMOTE_USER variable and
@@ -188,8 +172,7 @@ def RemoteUserACLSecurityPolicy(logger=None):
       grant or deny access.
 
     """
-    logger = debug_logger(logger)
-    return ACLSecurityPolicy(logger, get_remoteuser)
+    return ACLSecurityPolicy(get_remoteuser)
 
 def get_who_principals(request):
     identity = request.environ.get('repoze.who.identity')
@@ -199,7 +182,7 @@ def get_who_principals(request):
     principals.extend(identity.get('groups', []))
     return principals
 
-def RepozeWhoIdentityACLSecurityPolicy(logger=None):
+def RepozeWhoIdentityACLSecurityPolicy():
     """ A security policy which:
 
     - examines the request.environ for the ``repoze.who.identity``
@@ -219,8 +202,7 @@ def RepozeWhoIdentityACLSecurityPolicy(logger=None):
       grant or deny access.
 
     """
-    logger = debug_logger(logger)
-    return ACLSecurityPolicy(logger, get_who_principals)
+    return ACLSecurityPolicy(get_who_principals)
 
 class PermitsResult:
     def __init__(self, ace, acl, permission, principals, context):
diff --git a/repoze/bfg/tests/test_log.py b/repoze/bfg/tests/test_log.py
new file mode 100644
index 000000000..4cc8d12a0
--- /dev/null
+++ b/repoze/bfg/tests/test_log.py
@@ -0,0 +1,16 @@
+import unittest
+
+class TestFunctions(unittest.TestCase):
+    def test_make_stream_logger(self):
+        from repoze.bfg.log import make_stream_logger
+        import logging
+        import sys
+        logger = make_stream_logger('foo', sys.stderr, levelname='DEBUG',
+                                    fmt='%(message)s')
+        self.assertEqual(logger.name, 'foo')
+        self.assertEqual(logger.handlers[0].stream, sys.stderr)
+        self.assertEqual(logger.handlers[0].formatter._fmt, '%(message)s')
+        self.assertEqual(logger.level, logging.DEBUG)
+        
+        
+
diff --git a/repoze/bfg/tests/test_registry.py b/repoze/bfg/tests/test_registry.py
index efc99b41a..d2e6b4caf 100644
--- a/repoze/bfg/tests/test_registry.py
+++ b/repoze/bfg/tests/test_registry.py
@@ -23,7 +23,8 @@ class TestMakeRegistry(unittest.TestCase, PlacelessSetup):
             old = repoze.bfg.registry.setRegistryManager(dummyregmgr)
             registry = makeRegistry('configure.zcml',
                                     fixtureapp,
-                                    options={'reload_templates':True},
+                                    options={'reload_templates':True,
+                                             'debug_authorization':True},
                                     lock=dummylock)
             from zope.component.registry import Components
             self.failUnless(isinstance(registry, Components))
@@ -32,8 +33,12 @@ class TestMakeRegistry(unittest.TestCase, PlacelessSetup):
             self.assertEqual(dummyregmgr.registry, registry)
             from zope.component import getUtility
             from repoze.bfg.interfaces import ISettings
+            from repoze.bfg.interfaces import ILogger
             settings = getUtility(ISettings)
+            logger = getUtility(ILogger, name='repoze.bfg.authdebug')
+            self.assertEqual(logger.name, 'repoze.bfg.authdebug')
             self.assertEqual(settings.reload_templates, True)
+            self.assertEqual(settings.debug_authorization, True)
         finally:
             repoze.bfg.registry.setRegistryManager(old)
 
@@ -52,6 +57,27 @@ class TestGetOptions(unittest.TestCase):
         self.assertEqual(result['reload_templates'], True)
         result = get_options({'reload_templates':'1'})
         self.assertEqual(result['reload_templates'], True)
+        result = get_options({}, {'BFG_RELOAD_TEMPLATES':'1'})
+        self.assertEqual(result['reload_templates'], True)
+        result = get_options({'reload_templates':'false'},
+                             {'BFG_RELOAD_TEMPLATES':'1'})
+        self.assertEqual(result['reload_templates'], True)
+
+    def test_debug_authorization(self):
+        get_options = self._getFUT()
+        result = get_options({})
+        self.assertEqual(result['debug_authorization'], False)
+        result = get_options({'debug_authorization':'false'})
+        self.assertEqual(result['debug_authorization'], False)
+        result = get_options({'debug_authorization':'t'})
+        self.assertEqual(result['debug_authorization'], True)
+        result = get_options({'debug_authorization':'1'})
+        self.assertEqual(result['debug_authorization'], True)
+        result = get_options({}, {'BFG_DEBUG_AUTHORIZATION':'1'})
+        self.assertEqual(result['debug_authorization'], True)
+        result = get_options({'debug_authorization':'false'},
+                             {'BFG_DEBUG_AUTHORIZATION':'1'})
+        self.assertEqual(result['debug_authorization'], True)
 
 class TestThreadLocalRegistryManager(unittest.TestCase, PlacelessSetup):
     def setUp(self):
diff --git a/repoze/bfg/tests/test_security.py b/repoze/bfg/tests/test_security.py
index 98750c728..4a1511c50 100644
--- a/repoze/bfg/tests/test_security.py
+++ b/repoze/bfg/tests/test_security.py
@@ -219,6 +219,12 @@ class TestACLSecurityPolicy(unittest.TestCase, PlacelessSetup):
         klass = self._getTargetClass()
         return klass(*arg, **kw)
 
+    def _registerLogger(self, logger):
+        import zope.component
+        gsm = zope.component.getGlobalSiteManager()
+        from repoze.bfg.interfaces import ILogger
+        gsm.registerUtility(logger, ILogger, name='repoze.bfg.authdebug')
+
     def setUp(self):
         PlacelessSetup.setUp(self)
 
@@ -233,14 +239,12 @@ class TestACLSecurityPolicy(unittest.TestCase, PlacelessSetup):
     def test_instance_implements_ISecurityPolicy(self):
         from zope.interface.verify import verifyObject
         from repoze.bfg.interfaces import ISecurityPolicy
-        logger = DummyLogger()
-        verifyObject(ISecurityPolicy, self._makeOne(logger, lambda *arg: None))
+        verifyObject(ISecurityPolicy, self._makeOne(lambda *arg: None))
 
     def test_permits_no_principals_no_acl_info_on_context(self):
         context = DummyContext()
         request = DummyRequest({})
-        logger = DummyLogger()
-        policy = self._makeOne(logger, lambda *arg: None)
+        policy = self._makeOne(lambda *arg: None)
         authorizer_factory = make_authorizer_factory(None)
         policy.authorizer_factory = authorizer_factory
         result = policy.permits(context, request, 'view')
@@ -254,8 +258,7 @@ class TestACLSecurityPolicy(unittest.TestCase, PlacelessSetup):
         context = DummyContext()
         context.__acl__ = []
         request = DummyRequest({})
-        logger = DummyLogger()
-        policy = self._makeOne(logger, lambda *arg: None)
+        policy = self._makeOne(lambda *arg: None)
         authorizer_factory = make_authorizer_factory(None)
         policy.authorizer_factory = authorizer_factory
         result = policy.permits(context, request, 'view')
@@ -274,8 +277,7 @@ class TestACLSecurityPolicy(unittest.TestCase, PlacelessSetup):
         context2.__parent__ = context
         context.__acl__ = []
         request = DummyRequest({})
-        logger = DummyLogger()
-        policy = self._makeOne(logger, lambda *arg: None)
+        policy = self._makeOne(lambda *arg: None)
         authorizer_factory = make_authorizer_factory(None)
         policy.authorizer_factory = authorizer_factory
         result = policy.permits(context, request, 'view')
@@ -293,8 +295,7 @@ class TestACLSecurityPolicy(unittest.TestCase, PlacelessSetup):
         context2.__name__ = 'context2'
         context2.__parent__ = context
         request = DummyRequest({})
-        logger = DummyLogger()
-        policy = self._makeOne(logger, lambda *arg: None)
+        policy = self._makeOne(lambda *arg: None)
         authorizer_factory = make_authorizer_factory(context)
         policy.authorizer_factory = authorizer_factory
         result = policy.permits(context, request, 'view')
@@ -303,15 +304,34 @@ class TestACLSecurityPolicy(unittest.TestCase, PlacelessSetup):
         self.assertEqual(authorizer_factory.principals, (Everyone,))
         self.assertEqual(authorizer_factory.permission, 'view')
         self.assertEqual(authorizer_factory.context, context)
-    
+
+    def test_permits_with_logger(self):
+        logger = DummyLogger()
+        self._registerLogger(logger)
+        context = DummyContext()
+        request = DummyRequest({})
+        policy = self._makeOne(lambda *arg: None)
+        authorizer_factory = make_authorizer_factory(context)
+        policy.authorizer_factory = authorizer_factory
+        policy.permits(context, request, 'view')
+        self.assertEqual(authorizer_factory.logger, logger)
+
+    def test_permits_no_logger(self):
+        context = DummyContext()
+        request = DummyRequest({})
+        policy = self._makeOne(lambda *arg: None)
+        authorizer_factory = make_authorizer_factory(context)
+        policy.authorizer_factory = authorizer_factory
+        policy.permits(context, request, 'view')
+        self.assertEqual(authorizer_factory.logger, None)
+
     def test_principals_allowed_by_permission_direct(self):
         from repoze.bfg.security import Allow
         context = DummyContext()
         acl = [ (Allow, 'chrism', ('read', 'write')),
                 (Allow, 'other', ('read',)) ]
         context.__acl__ = acl
-        logger = DummyLogger()
-        policy = self._makeOne(logger, lambda *arg: None)
+        policy = self._makeOne(lambda *arg: None)
         result = policy.principals_allowed_by_permission(context, 'read')
         self.assertEqual(result, ['chrism', 'other'])
 
@@ -326,14 +346,12 @@ class TestACLSecurityPolicy(unittest.TestCase, PlacelessSetup):
         inter = DummyContext()
         inter.__name__ = None
         inter.__parent__ = context
-        logger = DummyLogger()
-        policy = self._makeOne(logger, lambda *arg: None)
+        policy = self._makeOne(lambda *arg: None)
         result = policy.principals_allowed_by_permission(inter, 'read')
         self.assertEqual(result, ['chrism', 'other'])
 
     def test_principals_allowed_by_permission_no_acls(self):
-        logger = DummyLogger()
-        policy = self._makeOne(logger, lambda *arg: None)
+        policy = self._makeOne(lambda *arg: None)
         result = policy.principals_allowed_by_permission(None, 'read')
         self.assertEqual(result, [])
 
@@ -355,22 +373,19 @@ class TestRemoteUserACLSecurityPolicy(unittest.TestCase, PlacelessSetup):
     def test_instance_implements_ISecurityPolicy(self):
         from zope.interface.verify import verifyObject
         from repoze.bfg.interfaces import ISecurityPolicy
-        logger = DummyLogger()
-        verifyObject(ISecurityPolicy, self._makeOne(logger))
+        verifyObject(ISecurityPolicy, self._makeOne())
 
     def test_authenticated_userid(self):
         context = DummyContext()
         request = DummyRequest({'REMOTE_USER':'fred'})
-        logger = DummyLogger()
-        policy = self._makeOne(logger)
+        policy = self._makeOne()
         result = policy.authenticated_userid(request)
         self.assertEqual(result, 'fred')
 
     def test_effective_principals(self):
         context = DummyContext()
         request = DummyRequest({'REMOTE_USER':'fred'})
-        logger = DummyLogger()
-        policy = self._makeOne(logger)
+        policy = self._makeOne()
         result = policy.effective_principals(request)
         from repoze.bfg.security import Everyone
         from repoze.bfg.security import Authenticated
@@ -395,15 +410,13 @@ class TestRepozeWhoIdentityACLSecurityPolicy(unittest.TestCase, PlacelessSetup):
     def test_instance_implements_ISecurityPolicy(self):
         from zope.interface.verify import verifyObject
         from repoze.bfg.interfaces import ISecurityPolicy
-        logger = DummyLogger()
-        verifyObject(ISecurityPolicy, self._makeOne(logger))
+        verifyObject(ISecurityPolicy, self._makeOne())
 
     def test_authenticated_userid(self):
         context = DummyContext()
         identity = {'repoze.who.identity':{'repoze.who.userid':'fred'}}
         request = DummyRequest(identity)
-        logger = DummyLogger()
-        policy = self._makeOne(logger)
+        policy = self._makeOne()
         result = policy.authenticated_userid(request)
         self.assertEqual(result, 'fred')
 
@@ -411,8 +424,7 @@ class TestRepozeWhoIdentityACLSecurityPolicy(unittest.TestCase, PlacelessSetup):
         context = DummyContext()
         identity = {'repoze.who.identity':{'repoze.who.userid':'fred'}}
         request = DummyRequest(identity)
-        logger = DummyLogger()
-        policy = self._makeOne(logger)
+        policy = self._makeOne()
         result = policy.effective_principals(request)
         from repoze.bfg.security import Everyone
         from repoze.bfg.security import Authenticated
@@ -557,6 +569,7 @@ class make_authorizer_factory:
                 authorizer.permission = permission
                 authorizer.principals = principals
                 authorizer.context = context
+                authorizer.logger = logger
                 result = authorizer.expected_context == context
                 if not result and authorizer.intermediates_raise:
                     from repoze.bfg.interfaces import NoAuthorizationInformation