Ignore:
Timestamp:
6 Aug 2011, 11:11:41 (13 years ago)
Author:
uli
Message:

Implement a new logging technique and use it.
Details are explained in waeup.sirp.utils.logger.

Location:
main/waeup.sirp/trunk/src/waeup/sirp
Files:
7 edited

Legend:

Unmodified
Added
Removed

  • main/waeup.sirp/trunk/src/waeup/sirp/app.py

    r6522 r6578  
    11import grok
    2 import logging
    3 import os
    42from hurry.file.interfaces import IFileRetrieval
    53from zope.authentication.interfaces import IAuthentication
    … …  
    119from waeup.sirp.imagestorage import ImageStorageFileRetrieval, ImageStorage
    1210from waeup.sirp.interfaces import (
    13     IUniversity, IDataCenter, IWAeUPSIRPPluggable,
    14     IDataCenterStorageMovedEvent, IObjectUpgradeEvent, )
     11    IUniversity, IWAeUPSIRPPluggable, IObjectUpgradeEvent, )
    1512from waeup.sirp.users import UserContainer
     13from waeup.sirp.utils.logger import Logger
    1614from waeup.sirp.utils.helpers import attrs_to_fields
    1715
    18 class University(grok.Application, grok.Container):
     16class University(grok.Application, grok.Container, Logger):
    1917    """A university.
    2018    """
    … …  
    2927    grok.local_utility(
    3028        ImageStorageFileRetrieval, provides = IFileRetrieval)
    31 
    32     @property
    33     def logger(self):
    34         """The application logger.
    35 
    36         Returns a standard logger object as provided by :mod:`logging`
    37         module from the standard library.
    38 
    39         Other components can use this logger to perform log entries
    40         into the 'main' logfile.
    41 
    42         The logger is initialized the first time, it is called.
    43         """
    44         sitename = self.__name__
    45         loggername = 'waeup.sirp.%s' % sitename
    46         logger = logging.getLogger(loggername)
    47         if not logger.handlers:
    48             logger = self._setupLogger(logger)
    49         return logger
    5029
    5130    def __init__(self, name=None, skin=None, title=None,
    … …  
    9574        self.logger.info('Plugin update finished.')
    9675        return
    97 
    98     def _setupLogger(self, logger):
    99         """Setup general application logger.
    100 
    101         The logfile will be stored in the datacenter logs/ dir.
    102         """
    103         logdir = os.path.join(self['datacenter'].storage, 'logs')
    104         if not os.path.exists(logdir):
    105             os.mkdir(logdir)
    106         filename = os.path.join(logdir, 'main.log')
    107 
    108         # Create a rotating file handler logger for application.
    109         handler = logging.handlers.RotatingFileHandler(
    110             filename, maxBytes=5*1024**1, backupCount=7)
    111         formatter = logging.Formatter(
    112             '%(asctime)s - %(levelname)s - %(message)s')
    113         handler.setFormatter(formatter)
    114 
    115         # Don't send log msgs to ancestors. This stops displaying
    116         # logmessages on the commandline.
    117         logger.propagate = False
    118         logger.addHandler(handler)
    119         return logger
    12076attrs_to_fields(University)
    121 
    122 @grok.subscribe(IDataCenter, IDataCenterStorageMovedEvent)
    123 def handle_storage_move(obj, event):
    124     """Event handler, in case datacenter storage moves.
    125 
    126     We initialize the application log again, then.
    127     """
    128     app = grok.getSite()
    129     if app is None:
    130         return
    131     if obj is not app['datacenter']:
    132         return
    133     logger = app.logger
    134     logger.warn('Log Dir moved. Closing.')
    135     handlers = logger.handlers
    136     for handler in handlers:
    137         logger.removeHandler(handler)
    138     app._setupLogger(logger)
    139     logger.warn('Log file moved. Opening.')
    14077
    14178class ObjectUpgradeEvent(ObjectEvent):
    … …  
    14380    """
    14481    grok.implements(IObjectUpgradeEvent)
     82
     83@grok.subscribe(University, grok.IObjectAddedEvent)
     84def handle_university_add(app, event):
     85    app.logger.info('University `%s` added.' % getattr(app, '__name__', None))
     86    return

  • main/waeup.sirp/trunk/src/waeup/sirp/applicants/root.py

    r6500 r6578  
    2727from hurry.query.interfaces import IQuery
    2828from zope.component import getUtility
    29 from waeup.sirp.interfaces import IWAeUPSIRPPluggable, ISiteLoggers
     29from waeup.sirp.interfaces import IWAeUPSIRPPluggable
    3030from waeup.sirp.applicants.interfaces import IApplicantsRoot
    3131from waeup.sirp.utils.helpers import get_current_principal
     32from waeup.sirp.utils.logger import Logger
    3233
    33 class ApplicantsRoot(grok.Container):
     34class ApplicantsRoot(grok.Container, Logger):
    3435    """The root of applicants-related components. It contains only
    3536    containers for applicants.
    … …  
    3940    local_roles = ['waeup.ApplicationsOfficer']
    4041
    41     @property
    42     def logger(self):
    43         """Get a logger for applicants.
    44         """
    45         loggers = getUtility(ISiteLoggers).getLoggers()
    46         if 'waeup.sirp.%s.applicants' not in loggers.keys():
    47             loggers.register('waeup.sirp.%s.applicants')
    48         return loggers.getLogger('waeup.sirp.%s.applicants')
     42    logger_name = 'waeup.sirp.${sitename}.applicants'
     43    logger_filename = 'applicants.log'
    4944
    5045    def logger_info(self, target, ob_class, comment=None):

  • main/waeup.sirp/trunk/src/waeup/sirp/applicants/tests/test_root.py

    r6443 r6578  
    2828import unittest
    2929from StringIO import StringIO
    30 from zope.app.testing.functional import FunctionalTestCase
    31 from zope.component.hooks import setSite, clearSite
     30from zope.component.hooks import setSite
    3231from zope.interface.verify import verifyClass, verifyObject
    33 from zope.site import LocalSiteManager
    3432from waeup.sirp.app import University
    3533from waeup.sirp.applicants import (
    … …  
    4038    ApplicantsRoot, ApplicantsPlugin,
    4139    )
    42 from waeup.sirp.testing import FunctionalLayer
     40from waeup.sirp.testing import (
     41    FunctionalLayer, FunctionalTestCase, get_all_loggers, remove_new_loggers,
     42    remove_logger)
    4343
    4444
    … …  
    5454    def setUp(self):
    5555        super(ApplicantsRootTestCase, self).setUp()
    56 
     56        remove_logger('waeup.sirp.app.applicants')
     57        self.old_loggers = get_all_loggers()
    5758        # Setup a sample site for each test
     59
     60        # Prepopulate the ZODB...
    5861        app = University()
    59         self.dc_root = tempfile.mkdtemp()
    60         app['datacenter'].setStoragePath(self.dc_root)
    61 
    62         # Prepopulate the ZODB...
    6362        self.getRootFolder()['app'] = app
    6463        self.app = self.getRootFolder()['app']
    6564        setSite(self.app)
     65
     66        self.dc_root = tempfile.mkdtemp()
     67        app['datacenter'].setStoragePath(self.dc_root)
     68
    6669        return
    6770
    6871    def tearDown(self):
    6972        super(ApplicantsRootTestCase, self).tearDown()
     73        remove_new_loggers(self.old_loggers)
    7074        shutil.rmtree(self.dc_root)
    7175        return

  • main/waeup.sirp/trunk/src/waeup/sirp/datacenter.py

    r6286 r6578  
    1313                                   IDataCenterStorageMovedEvent)
    1414from waeup.sirp.utils.helpers import copyFileSystemTree
    15 
    16 class DataCenter(grok.Container):
     15from waeup.sirp.utils.logger import Logger
     16
     17class DataCenter(grok.Container, Logger):
    1718    """A data center contains CSV files.
    1819    """
    … …  
    2021    storage = os.path.join(os.path.dirname(__file__), 'files')
    2122
    22     @property
    23     def logger(self):
    24         """Get a logger for datacenter actions.
    25         """
    26         # We need a different logger for every site...
    27         site = grok.getSite()
    28         sitename = getattr(site, '__name__', 'app')
    29         loggername = 'waeup.sirp.%s.datacenter' % sitename
    30         logger = logging.getLogger(loggername)
    31         if not logger.handlers:
    32             logger = self._setupLogger(logger)
    33         return logger
     23    logger_name = 'waeup.sirp.${sitename}.datacenter'
     24    logger_filename = 'datacenter.log'
    3425
    3526    def __init__(self, *args, **kw):
    … …  
    6253        """Create standard subdirs.
    6354        """
    64         for name in ['finished', 'unfinished']:
     55        for name in ['finished', 'unfinished', 'logs']:
    6556            path = os.path.join(self.storage, name)
    6657            if os.path.exists(path):
    … …  
    116107        self._createSubDirs()
    117108        # Adjust logger...
    118         logger = self.logger
    119         handlers = logger.handlers
    120         for handler in handlers:
    121             logger.removeHandler(handler)
    122         self._setupLogger(logger)
     109        #logger = self.logger
     110        #handlers = logger.handlers
     111        #for handler in handlers:
     112        #    logger.removeHandler(handler)
     113        #self._setupLogger(logger)
    123114        grok.notify(DataCenterStorageMovedEvent(self))
    124115        return not_copied

  • main/waeup.sirp/trunk/src/waeup/sirp/testing.py

    r6577 r6578  
    3636                   if key not in old_loggers]
    3737    for key in new_loggers:
     38        logger = logging.getLogger(key)
     39        for handler in logger.handlers:
     40            handler.close()
     41        del logger
    3842        del logging.root.manager.loggerDict[key]
    3943    return
     44
     45def remove_logger(name):
     46    """Remove logger with name `name`.
     47
     48    Use is safe. If the logger does not exist nothing happens.
     49    """
     50    if name in logging.root.manager.loggerDict.keys():
     51        del logging.root.manager.loggerDict[name]
     52    return
     53
    4054
    4155def setUpZope(test=None):
    … …  
    265279    """
    266280
     281    def setUp(self):
     282        super(FunctionalTestCase, self).setUp()
     283        self.functional_old_loggers = get_all_loggers()
     284        return
     285
     286    def tearDown(self):
     287        super(FunctionalTestCase, self).tearDown()
     288        remove_new_loggers(self.functional_old_loggers)
     289        return
     290
    267291    def assertMatches(self, want, got, checker=checker,
    268292                      optionflags=optionflags):

  • main/waeup.sirp/trunk/src/waeup/sirp/utils/logger.py

    r6481 r6578  
    2222"""
    2323Convenience stuff for logging.
     24
     25Main component of :mod:`waeup.sirp.utils.logging` is a mix-in class
     26:class:`waeup.sirp.utils.logging.Logger`. Classes derived (also) from
     27that mix-in provide a `logger` attribute that returns a regular Python
     28logger logging to a rotating log file stored in the datacenter storage
     29path.
     30
     31Deriving components (classes) should set their own `logger_name` and
     32`logger_filename` attribute.
     33
     34The `logger_name` tells under which name the logger should be
     35registered Python-wise. This is usually a dotted name string like
     36``waeup.sirp.${sitename}.mycomponent`` which should be unique. If you
     37pick a name already used by another component, trouble is ahead. The
     38``${sitename}`` chunk of the name can be set literally like this. The
     39logger machinery will turn it into some real site name at time of
     40logging.
     41
     42The `logger_filename` attribute tells how the logfile should be
     43named. This should be some base filename like
     44``mycomponent.log``. Please note, that some logfile names are already
     45used: ``main.log``, ``applications.log``, and ``datacenter.log``.
     46
     47The `Logger` mix-in also cares for updating the logging handlers when
     48a datacenter location moves. That means you do not have to write your
     49own event handlers for the purpose. Just derive from `Logger`, set
     50your `logger_name` and `logger_filename` attribute and off you go::
     51
     52  from waeup.sirp.utils.logger import Logger
     53
     54  class MyComponent(object, Logger):
     55      # Yes that's a complete working class
     56      logger_name = 'waeup.sirp.${sitename}.mycomponent
     57      logger_filename = 'mycomponent.log'
     58
     59      def do_something(self):
     60           # demomstrate how to use logging from methods
     61           self.logger.info('About to do something')
     62           try:
     63               # Do something here
     64           except IOError:
     65               self.logger.warn('Something went wrong')
     66               return
     67           self.logger.info('I did it')
     68
     69As you can see from that example, methods of the class can log
     70messages simply by calling `self.logger`.
     71
     72The datacenter and its storage are created automatically when you
     73create a :class:`waeup.sirp.app.University`. This also means that
     74logging with the `Logger` mix-in will work only inside so-called sites
     75(`University` instances put into ZODB are such `sites`).
     76
     77Other components in this module help to make everything work.
    2478"""
    2579import os
    2680import grok
    2781import logging
    28 from zope.interface import Interface, Attribute
    29 from waeup.sirp.interfaces import ISiteLoggers, ILogger
    30 
    31 class SiteLoggers(object):
    32 
    33     grok.implements(ISiteLoggers)
    34 
    35     @property
    36     def loggers(self):
    37         return self._loggers.values()
    38 
    39     def __init__(self):
    40         self._loggers = dict()
    41 
    42     def getLogger(self, filename):
    43         waeup_logger = self._loggers.get(filename, None)
    44         return waeup_logger.logger
    45 
    46     def register(self, loggername, filename=None, site=None, **kw):
    47         if loggername in self._loggers.keys():
    48             raise KeyError('Logger "%s" exists already.' % loggername)
    49         self._loggers[loggername] = WAeUPLogger(
    50             loggername, filename=filename, site=site, **kw)
    51         return
    52 
    53     def unregister(self, name):
    54         if name in self._loggers.keys():
    55             del self._loggers[name]
    56         return
    57 
    58     def keys(self):
    59         return self._loggers.keys()
    60 
    61 class WAeUPLogger(object):
    62 
    63     grok.implements(ILogger)
    64 
    65     _logger = None
    66 
    67     def __init__(self, name, filename=None, site=None, **options):
    68         self.name = name
    69         self.filename = filename
    70         if filename is None:
    71             if '.' in name:
    72                 name = name.rsplit('.', 1)[1]
    73             self.filename = "%s.log" % name
    74         self.site = site
    75         self.max_bytes = options.get('maxBytes', 5 * 1024 ** 2)
    76         self.backup_count = options.get('backupCount', 5)
    77         self.options = options
    78         return
     82from string import Template
     83from zope import schema
     84from zope.component import queryUtility
     85from zope.interface import Interface, Attribute, implements
     86from waeup.sirp.interfaces import IDataCenter, IDataCenterStorageMovedEvent
     87
     88#: Default logfile size
     89MAX_BYTES = 5 * 1024 ** 2
     90
     91#: Default num of backup files
     92BACKUP_COUNT = 5
     93
     94class ILogger(Interface):
     95    logger_name = schema.TextLine(
     96        title = u'A Python logger name')
     97    logger_filename = schema.TextLine(
     98        title = u'A filename for the log file to use (basename)')
     99    logger = Attribute("Get a Python logger instance already set up")
     100    def logger_setup(logger):
     101        """Setup a logger.
     102
     103        `logger` is an instance of :class:`logging.Logger`.
     104        """
     105
     106    def logger_get_logfile_path():
     107        """Get path to logfile used.
     108
     109        Return `None` if the file path cannot be computed.
     110        """
     111
     112    def logger_get_logdir():
     113        """Get the directory of the logfile.
     114
     115        Return `None` if the directory path cannot be computed.
     116        """
     117
     118class Logger(object):
     119    """Mixin-class that for logging support.
     120
     121    Classes that (also) inherit from this class provide support for
     122    logging with waeup sites.
     123
     124    By default a `logger` attribute is provided which returns a
     125    regular Python logger. This logger has already registered a file
     126    rotating log handler that writes log messages to a file `main.log`
     127    in datacenters ``log/`` directory. This is the main log file also
     128    used by other components. Therefore you can pick another filename
     129    by setting the `logger_filename` attribute.
     130
     131    All methods and attributes of this mix-in start with ``logger_``
     132    in order not to interfere with already existing names of a class.
     133
     134    Method names do not follow the usual Zope habit (CamelCase) but
     135    PEP8 convention (lower_case_with_underscores).
     136    """
     137
     138    #: The filename to use when logging.
     139    logger_filename = 'main.log'
     140
     141    #: The Python logger name used when
     142    #: logging. ``'waeup.sirp.${sitename}'`` by default. You can use the
     143    #: ``${sitename}`` placeholder in that string, which will be
     144    #: replaced by the actual used site name.
     145    logger_name = 'waeup.sirp.${sitename}'
     146    implements(ILogger)
    79147
    80148    @property
    81149    def logger(self):
    82         if self._needSetup():
    83             self._setup()
    84         return logging.getLogger(self._loggername)
    85 
    86     def setup(self):
    87         return self._setup()
    88 
    89     def update(self, **options):
    90         self._logger = None # unset to be set up again on next access.
    91         # XXX: set options
    92         pass
    93 
    94     def _needSetup(self):
    95         if self._logger is None:
    96             return True
    97         if not '__app' in self._logger.name:
    98             return False
    99         if getattr(self.site, '__name__', None) is not None:
    100             return True
    101         return False
    102 
    103     def _removeHandlers(self):
    104         handlers = self._logger.handlers
     150        """Get a logger instance.
     151
     152        Returns a standard logger object as provided by :mod:`logging`
     153        module from the standard library.
     154
     155        Other components can use this logger to perform log entries
     156        into the logfile of this component.
     157
     158        The logger is initialized the first time it is called.
     159
     160        The logger is only available when used inside a site.
     161
     162        .. note:: The logger default level is
     163                  :data:`logging.WARN`. Use
     164                  :meth:`logging.Logger.setLevel` to set a different level.
     165        """
     166        site = grok.getSite()
     167        sitename = '%s' % getattr(site, '__name__', None)
     168        loggername = Template(self.logger_name).substitute(
     169            dict(sitename=sitename))
     170        logger = logging.getLogger(loggername)
     171        if site is None:
     172            return logger
     173        if len(logger.handlers) != 1:
     174            handlers = [x for x in logger.handlers]
     175            for handler in handlers:
     176                handler.flush()
     177                handler.close()
     178                logger.removeHandler(handler)
     179            logger = self.logger_setup(logger)
     180        return logger
     181
     182    def logger_setup(self, logger):
     183        """Setup logger.
     184
     185        The logfile will be stored in the datacenter logs/ dir.
     186        """
     187        filename = self.logger_get_logfile_path()
     188        if filename is None:
     189            return
     190        collector = queryUtility(ILoggerCollector)
     191        if collector is not None:
     192            site = grok.getSite()
     193            collector.registerLogger(site, self)
     194
     195        # Create a rotating file handler logger.
     196        handler = logging.handlers.RotatingFileHandler(
     197            filename, maxBytes=MAX_BYTES, backupCount=BACKUP_COUNT)
     198        formatter = logging.Formatter(
     199            '%(asctime)s - %(levelname)s - %(message)s')
     200        handler.setFormatter(formatter)
     201
     202        # Don't send log msgs to ancestors. This stops displaying
     203        # logmessages on the commandline.
     204        logger.propagate = False
     205        logger.addHandler(handler)
     206        return logger
     207
     208    def logger_get_logfile_path(self):
     209        """Get the path to the logfile used.
     210
     211        Returns the path to a file in local sites datacenter ``log/``
     212        directory (dependent on :meth:`logger_get_logdir`) and with
     213        :attr:`logger_filename` as basename.
     214
     215        Override this method if you want a complete different
     216        computation of the logfile path. If you only want a different
     217        logfile name, set :attr:`logger_filename`. If you only want a
     218        different path to the logfile override
     219        :meth:`logger_get_logdir` instead.
     220
     221        Returns ``None`` if no logdir can be fetched.
     222
     223        .. note:: creates the logfile dir if it does not exist.
     224
     225        """
     226        logdir = self.logger_get_logdir()
     227        if logdir is None:
     228            return None
     229        return os.path.join(logdir, self.logger_filename)
     230
     231    def logger_get_logdir(self):
     232        """Get log dir where logfile should be put.
     233
     234        Returns the path to the logfile directory. If no site is set,
     235        ``None`` is returned. The same applies, if the site has no
     236        datacenter.
     237
     238        If the dir dies not exist already it will be created. Only the
     239        last part of the directory path will be created.
     240        """
     241        site = grok.getSite()
     242        if site is None:
     243            return None
     244        datacenter = site.get('datacenter', None)
     245        if datacenter is None:
     246            return None
     247        logdir = os.path.join(datacenter.storage, 'logs')
     248        if not os.path.exists(logdir):
     249            os.mkdir(logdir)
     250        return logdir
     251
     252    def logger_logfile_changed(self):
     253        """React on logfile location change.
     254
     255        If the logfile changed, we can set a different logfile. While
     256        changing the logfile is a rather critical operation you might
     257        not do often in production use, we have to cope with that
     258        especially in tests.
     259
     260        What this method does by default (unless you override it):
     261
     262        - It fetches the current logger and
     263
     264          - Removes flushes, closes, and removes all handlers
     265
     266          - Sets up new handler(s).
     267
     268        All this, of course, requires to be 'in a site'.
     269
     270        Use this method to handle moves of datacenters, for instance
     271        by writing an appropriate event handler.
     272        """
     273        logger = self.logger
     274        self.logger_shutdown()
     275        self.logger_setup(logger)
     276        return
     277
     278    def logger_shutdown(self):
     279        """Remove all specific logger setup.
     280        """
     281        logger = self.logger
     282        handlers = [x for x in logger.handlers]
    105283        for handler in handlers:
    106             self._logger.removeHandler(handler)
    107 
    108     def _setup(self):
    109         if self.site is None:
    110             self.site = grok.getSite()
    111         self._loggername = self.name
    112         if not '.' in self._loggername:
    113             self._loggername = 'waeup.sirp.%s.%s' % ('%s', self._loggername)
    114         if '%s' in self._loggername:
    115             site_name = getattr(self.site, '__name__', '__app')
    116             if site_name is None:
    117                 site_name = '__app'
    118             self._loggername = self._loggername % (site_name,)
    119         self._logger = logging.getLogger(self._loggername)
    120         return self._update()
    121 
    122     def _update(self):
    123         self._removeHandlers() # Remove any old handlers
    124         self._logdir = os.path.join(self.site['datacenter'].storage, 'logs')
    125         if not os.path.exists(self._logdir):
    126             os.mkdir(self._logdir)
    127         filename = os.path.join(self._logdir, self.filename)
    128 
    129         # Create a rotating file handler logger for datacenter.
    130         default_handler = logging.handlers.RotatingFileHandler(
    131             filename, maxBytes=self.max_bytes, backupCount=self.backup_count)
    132         self.handler = self.options.get('handler', default_handler)
    133 
    134         default_formatter = logging.Formatter(
    135             '%(asctime)s - %(levelname)s - %(message)s')
    136         formatter = self.options.get('formatter', default_formatter)
    137         self.handler.setFormatter(formatter)
    138 
    139         self._logger.addHandler(self.handler)
    140         self._logger.propagate = self.options.get('propagate', False)
    141         self._logger.setLevel(self.options.get('level', logging.DEBUG))
    142         return self._logger
    143 
    144 #: A place where we store seen loggers.
    145 SiteLoggersRepository = dict()
    146 
    147 class SiteLoggersFinder(object):
    148     grok.provides(ISiteLoggers)
    149 
    150     def getLoggers(self, site=None):
    151         if site is None:
    152             site = grok.getSite()
    153         if site not in SiteLoggersRepository.keys():
    154             SiteLoggersRepository[site] = SiteLoggers()
    155         return SiteLoggersRepository[site]
    156 
    157 grok.global_utility(SiteLoggersFinder, provides=ISiteLoggers)
     284            handler.flush()
     285            handler.close()
     286            logger.removeHandler(handler)
     287        collector = queryUtility(ILoggerCollector)
     288        if collector is not None:
     289            collector.unregisterLogger(grok.getSite(), self)
     290        return
     291
     292
     293class ILoggerCollector(Interface):
     294
     295    def getLoggers(site):
     296        """Return all loggers registered for `site`.
     297        """
     298
     299    def registerLogger(site, logging_component):
     300        """Register a logging component residing in `site`.
     301        """
     302
     303    def unregisterLogger(site, logging_component):
     304        """Unregister a logger.
     305        """
     306
     307class LoggerCollector(dict, grok.GlobalUtility):
     308    """A global utility providing `ILoggerCollector`.
     309
     310    A logging collector collects logging components. This helps to
     311    inform them when a logfile location changes.
     312
     313    Logging components are registered per site they belong to.
     314    """
     315
     316    implements(ILoggerCollector)
     317
     318    def getLoggers(self, site):
     319        name = getattr(site, '__name__', None)
     320        if name is None:
     321            return []
     322        if name not in self.keys():
     323            return []
     324        return self[name]
     325
     326    def registerLogger(self, site, logging_component):
     327        name = getattr(site, '__name__', None)
     328        if name is None:
     329            return
     330        if not name in self.keys():
     331            # new component
     332            self[name] = []
     333        if logging_component in self[name]:
     334            # already registered
     335            return
     336        self[name].append(logging_component)
     337        return
     338
     339    def unregisterLogger(self, site, logging_component):
     340        name = getattr(site, '__name__', None)
     341        if name is None or name not in self.keys():
     342            return
     343        if logging_component not in self[name]:
     344            return
     345        self[name].remove(logging_component)
     346        return
     347
     348@grok.subscribe(IDataCenter, IDataCenterStorageMovedEvent)
     349def handle_datacenter_storage_move(obj, event):
     350    """Event handler, in case datacenter storage moves.
     351
     352    By default all our logfiles (yes, we produce a whole bunch of it)
     353    are located in a ``log/`` dir of a local datacenter, the
     354    datacenter 'storage'. If this path changes because the datacenter
     355    is moved an appropriate event is triggered and we can react.
     356
     357    Via the global ILoggerCollector utility, a small piece that allows
     358    self-registering of logging components, we can lookup components
     359    whose logfile path has to be set up anew.
     360
     361    Each component we call has to provide ILogger or, more specific,
     362    the :meth:`logger_logfile_changed` method of this interface.
     363    """
     364    site = grok.getSite()
     365    if site is None:
     366        return
     367    collector = queryUtility(ILoggerCollector)
     368    loggers = collector.getLoggers(site)
     369    for logger in loggers:
     370        if hasattr(logger, 'logger_logfile_changed'):
     371            logger.logger_logfile_changed()
     372    return

  • main/waeup.sirp/trunk/src/waeup/sirp/utils/tests/test_logger.py

    r6481 r6578  
    1 ##
    2 ## test_logger.py
    3 ## Login : <uli@pu.smp.net>
    4 ## Started on  Mon Jun 13 14:40:04 2011 Uli Fouquet
    5 ## $Id$
    6 ##
    7 ## Copyright (C) 2011 Uli Fouquet
    8 ## This program is free software; you can redistribute it and/or modify
    9 ## it under the terms of the GNU General Public License as published by
    10 ## the Free Software Foundation; either version 2 of the License, or
    11 ## (at your option) any later version.
    12 ##
    13 ## This program is distributed in the hope that it will be useful,
    14 ## but WITHOUT ANY WARRANTY; without even the implied warranty of
    15 ## MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
    16 ## GNU General Public License for more details.
    17 ##
    18 ## You should have received a copy of the GNU General Public License
    19 ## along with this program; if not, write to the Free Software
    20 ## Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA
    21 ##
     1# Tests for waeup.sirp.utils.logger
    222import logging
    233import os
    24 import re
    254import shutil
    265import tempfile
    27 from zope.app.testing.functional import FunctionalTestCase
    286from zope.component import queryUtility
    297from zope.component.hooks import setSite, clearSite
    308from zope.interface.verify import verifyClass, verifyObject
    319from waeup.sirp.app import University
    32 from waeup.sirp.interfaces import ISiteLoggers, ILogger
    33 from waeup.sirp.testing import FunctionalLayer, doctestsuite_for_module
     10from waeup.sirp.testing import (
     11    FunctionalLayer, FunctionalTestCase, get_all_loggers,
     12    remove_new_loggers, remove_logger)
     13
    3414from waeup.sirp.utils.logger import (
    35     SiteLoggers, WAeUPLogger, SiteLoggersRepository)
    36 
    37 class SiteLoggersTests(FunctionalTestCase):
     15    Logger, MAX_BYTES, BACKUP_COUNT, ILoggerCollector, LoggerCollector,
     16    ILogger)
     17
     18class FakeComponent(object):
     19    # A component that can use the Logger mixin-class
     20    def do_something(self):
     21        self.logger.info('msg from do_something')
     22
     23class LoggingComponent(FakeComponent, Logger):
     24    # A component that supports logging by mixing in Logger
     25    logger_name = 'sample.${sitename}'
     26    logger_filename = 'sample.log'
     27
     28class LoggersTests(FunctionalTestCase):
    3829
    3930    layer = FunctionalLayer
    4031
    4132    def setUp(self):
    42         super(SiteLoggersTests, self).setUp()
     33        super(LoggersTests, self).setUp()
     34        self.old_loggers = get_all_loggers()
     35        # Setup a sample site for each test
     36        app = University()
     37        self.dc_root = tempfile.mkdtemp()
     38        self.dc_root2 = None
     39        app['datacenter'].setStoragePath(self.dc_root)
     40
     41        # Prepopulate the ZODB...
     42        self.getRootFolder()['app'] = app
     43        self.app = self.getRootFolder()['app']
     44        self.workdir = tempfile.mkdtemp()
     45        return
     46
     47    def tearDown(self):
     48        super(LoggersTests, self).tearDown()
     49        remove_new_loggers(self.old_loggers)
     50        shutil.rmtree(self.workdir)
     51        shutil.rmtree(self.dc_root)
     52        clearSite()
     53        return
     54
     55    def clear_logger(self, logger):
     56        del_list = [x for x in logger.handlers]
     57        for handler in del_list:
     58            logger.removeHandler(handler)
     59        return
     60
     61    def test_iface(self):
     62        setSite(self.app)
     63        logger = LoggingComponent()
     64        verifyClass(ILogger, Logger)
     65        verifyObject(ILogger, logger)
     66        return
     67
     68    def test_logger_prop_no_site(self):
     69        # If not in a site, we will get a logger without handlers
     70        logger = Logger().logger
     71        self.assertTrue(isinstance(logger, logging.Logger))
     72        self.assertEqual(len(logger.handlers), 0)
     73        return
     74
     75    def test_site_no_site_name(self):
     76        # If a site has not name we will get a logger anyway
     77        setSite(self.app)
     78        del self.app.__name__
     79        logger = Logger().logger
     80        self.assertTrue(logger is not None)
     81        return
     82
     83    def test_get_logdir(self):
     84        # We can get a logdir
     85        setSite(self.app)
     86        logger = Logger()
     87        logdir = logger.logger_get_logdir()
     88        expected_logdir = os.path.join(
     89            self.app['datacenter'].storage, 'logs')
     90        self.assertEqual(logdir, expected_logdir)
     91        return
     92
     93    def test_get_logdir_no_site(self):
     94        # We cannot get a logdir without a site
     95        logger = Logger()
     96        logdir = logger.logger_get_logdir()
     97        self.assertTrue(logdir is None)
     98        return
     99
     100    def test_get_logdir_no_datacenter(self):
     101        # Having a site, is not enough. We also need a datacenter in it.
     102        setSite(self.app)
     103        del self.app['datacenter']
     104        logger = Logger()
     105        logdir = logger.logger_get_logdir()
     106        self.assertTrue(logdir is None)
     107        return
     108
     109    def test_get_logdir_create_dir(self):
     110        # If the logdirectory does not exist, we will create it
     111        setSite(self.app)
     112        logger = Logger()
     113        expected_logdir = os.path.join(
     114            self.app['datacenter'].storage, 'logs')
     115        if os.path.exists(expected_logdir):
     116            shutil.rmtree(expected_logdir)
     117        logdir = logger.logger_get_logdir()
     118        exists_after = os.path.exists(expected_logdir)
     119        self.assertEqual(logdir, expected_logdir)
     120        self.assertTrue(exists_after is True)
     121        return
     122
     123    def test_get_logfile(self):
     124        # We can get a logfile
     125        setSite(self.app)
     126        logger = Logger()
     127        expected_filepath = os.path.join(
     128            self.app['datacenter'].storage, 'logs', 'main.log')
     129        path = logger.logger_get_logfile_path()
     130        self.assertEqual(expected_filepath, path)
     131        return
     132
     133    def test_get_logfile_no_dir(self):
     134        # We cannot get a logfilepath if there is no dir for it
     135        setSite(self.app)
     136        logger = Logger()
     137        del self.app['datacenter']
     138        path = logger.logger_get_logfile_path()
     139        self.assertTrue(path is None)
     140        return
     141
     142    def test_setup(self):
     143        # We can setup a logger.
     144        mylogger = logging.getLogger('test.sample')
     145        setSite(self.app)
     146        logger = Logger()
     147        result = logger.logger_setup(mylogger)
     148        self.assertEqual(len(result.handlers), 1)
     149        handler = result.handlers[0]
     150        self.assertEqual(handler.maxBytes, MAX_BYTES)
     151        self.assertEqual(handler.backupCount, BACKUP_COUNT)
     152        self.assertTrue(result.propagate is False)
     153        return
     154
     155    def test_setup_no_site(self):
     156        # Without a site we get no logger from setup
     157        mylogger = logging.getLogger('test.sample')
     158        logger = Logger()
     159        result = logger.logger_setup(mylogger)
     160        self.assertTrue(result is None)
     161        return
     162
     163    def test_logfile_change(self):
     164        # When the logfile location changes, logger_logfile_changed can react
     165        setSite(self.app)
     166        logger = Logger()
     167        logger.logger.warn('Warning 1')  # Log something to old logfile
     168        filename1 = logger.logger.handlers[0].baseFilename
     169        content1 = open(filename1, 'r').read()
     170        # Now move the logfile
     171        self.dc_root2 = tempfile.mkdtemp()
     172        self.app['datacenter'].setStoragePath(self.dc_root2)
     173        logger.logger_logfile_changed()
     174        logger.logger.warn('Warning 2')  # Log something to new logfile
     175        filename2 = logger.logger.handlers[0].baseFilename
     176        content2 = open(filename2, 'r').read()
     177        self.assertTrue('Warning 1' in content1)
     178        self.assertTrue('Warning 2' in content2)
     179        self.assertTrue('Warning 1' not in content2)
     180        self.assertTrue('Warning 2' not in content1)
     181        self.assertTrue(filename1 != filename2)
     182        return
     183
     184
     185class LoggersFunctionalTests(FunctionalTestCase):
     186    # Check loggers with real components using them
     187
     188    layer = FunctionalLayer
     189
     190    def setUp(self):
     191        super(LoggersFunctionalTests, self).setUp()
    43192
    44193        # Setup a sample site for each test
    … …  
    50199        self.getRootFolder()['app'] = app
    51200        self.app = self.getRootFolder()['app']
    52 
    53201        self.workdir = tempfile.mkdtemp()
    54         SiteLoggersRepository.clear()
     202
     203        self.app['mycomponent'] = LoggingComponent()
     204        self.component = self.app['mycomponent']
     205        setSite(self.app)
     206        self.old_loggers = get_all_loggers()
    55207        return
    56208
    57209    def tearDown(self):
    58         super(SiteLoggersTests, self).tearDown()
     210        super(LoggersFunctionalTests, self).tearDown()
     211        remove_new_loggers(self.old_loggers)
    59212        shutil.rmtree(self.workdir)
    60213        shutil.rmtree(self.dc_root)
    … …  
    62215        return
    63216
    64     def test_iface(self):
    65         loggers = SiteLoggers()
    66         verifyClass(ISiteLoggers, SiteLoggers)
    67         verifyObject(ISiteLoggers, loggers)
    68         return
    69 
    70     def test_loggers(self):
    71         loggers = SiteLoggers()
    72         loggers.register('sample1')
    73         loggers.register('sample2')
    74         result = loggers.loggers
    75         assert len(result) == 2
    76 
    77     def test_register(self):
    78         loggers = SiteLoggers()
    79         loggers.register('sample')
    80         assert 'sample' in loggers._loggers.keys()
    81 
    82     def test_register_duplicate(self):
    83         loggers = SiteLoggers()
    84         loggers.register('sample')
    85         self.assertRaises(
    86             KeyError,
    87             loggers.register, 'sample')
    88 
    89     def test_unregister(self):
    90         loggers = SiteLoggers()
    91         loggers.register('sample')
    92         loggers.unregister('sample')
    93         self.assertEqual(loggers._loggers, {})
    94 
    95     def test_utility_no_site(self):
    96         # make sure we get loggers even if no site is defined/set
    97         util = queryUtility(ISiteLoggers)
    98         loggers = util.getLoggers()
    99         assert util is not None
    100         assert loggers is not None
    101         assert None in SiteLoggersRepository.keys()
    102 
    103     def test_utility(self):
    104         # make sute we get loggers for a certain site
    105         setSite(self.app)
    106         util = queryUtility(ISiteLoggers)
    107         loggers = util.getLoggers()
    108         assert util is not None
    109         assert loggers is not None
    110         assert self.app in SiteLoggersRepository.keys()
    111 
    112     def test_utility_multiple(self):
    113         # make sure we get the same loggers for same site
    114         setSite(self.app)
    115         self.assertEqual(SiteLoggersRepository.keys(), [])
    116         util = queryUtility(ISiteLoggers)
    117         loggers1 = util.getLoggers()
    118         loggers2 = util.getLoggers()
    119         assert loggers1 is loggers2
    120 
    121     def test_utility_given_site(self):
    122         # make sure a passed site is respected
    123         util = queryUtility(ISiteLoggers)
    124         loggers = util.getLoggers(site=self.app)
    125         assert loggers is not None
    126         assert self.app in SiteLoggersRepository.keys()
    127 
    128 class LoggerTests(FunctionalTestCase):
     217    def test_component_can_get_logger(self):
     218        # Components can get a logger
     219        logger = self.component.logger
     220        self.assertTrue(logger is not None)
     221        self.assertEqual(len(logger.handlers), 1)
     222        self.assertEqual(logger.name, 'sample.app')
     223        return
     224
     225    def test_component_handler_setup(self):
     226        # handlers of components are setup
     227        handler = self.component.logger.handlers[0]
     228        self.assertTrue(isinstance(
     229                handler, logging.handlers.RotatingFileHandler))
     230        self.assertEqual(handler.maxBytes, MAX_BYTES)
     231        self.assertEqual(handler.backupCount, BACKUP_COUNT)
     232        self.assertTrue(handler.baseFilename.endswith('logs/sample.log'))
     233        return
     234
     235    def test_component_can_log(self):
     236        # a method of some 'loggerized' instance can log like this.
     237        self.component.logger.setLevel(logging.INFO)
     238        self.component.do_something()
     239        handler = logging.getLogger('sample.app').handlers[0]
     240        logfile = handler.baseFilename
     241        content = open(logfile, 'rb').read()
     242        self.assertTrue(content.endswith(' - INFO - msg from do_something\n'))
     243        return
     244
     245class LoggerCollectorTests(FunctionalTestCase):
    129246
    130247    layer = FunctionalLayer
    131248
    132249    def setUp(self):
    133         super(LoggerTests, self).setUp()
    134 
     250        super(LoggerCollectorTests, self).setUp()
     251        self.old_loggers = get_all_loggers()
    135252        # Setup a sample site for each test
    136253        app = University()
    … …  
    141258        self.getRootFolder()['app'] = app
    142259        self.app = self.getRootFolder()['app']
    143 
    144260        self.workdir = tempfile.mkdtemp()
     261
     262        self.app['mycomponent'] = LoggingComponent()
     263        self.component = self.app['mycomponent']
     264        setSite(self.app)
     265
     266        self.component = LoggingComponent()
     267
     268
    145269        return
    146270
    147271    def tearDown(self):
    148         super(LoggerTests, self).tearDown()
     272        super(LoggerCollectorTests, self).tearDown()
     273        remove_new_loggers(self.old_loggers)
    149274        shutil.rmtree(self.workdir)
    150275        shutil.rmtree(self.dc_root)
    … …  
    152277        return
    153278
    154     def test_iface(self):
    155         setSite(self.app)
    156         logger = WAeUPLogger('sample')
    157         verifyClass(ILogger, WAeUPLogger)
    158         verifyObject(ILogger, logger)
    159         return
    160 
    161     def test_logger_attr(self):
    162         setSite(self.app)
    163         logger = WAeUPLogger('sample')
    164         raw_logger = logger.logger
    165         assert isinstance(raw_logger, logging.Logger)
    166 
    167     def test_site_name(self):
    168         setSite(self.app)
    169         logger = WAeUPLogger('waeup.sirp.%s.sample', site=self.app)
    170         self.assertEqual(logger.logger.name, 'waeup.sirp.app.sample')
    171 
    172     def test_site_no_name(self):
    173         # While a site has no name, we get __app as placeholder
    174         setSite(self.app)
    175         self.app.__name__ = None
    176         logger = WAeUPLogger('waeup.sirp.%s.sample', site=self.app)
    177         self.assertEqual(logger.logger.name, 'waeup.sirp.__app.sample')
    178 
    179     def test_site_changing_name(self):
    180         # Changing the sitename (from None to a value) will be reflected
    181         setSite(self.app)
    182         self.app.__name__ = None
    183         logger = WAeUPLogger('waeup.sirp.%s.sample', site=self.app)
    184         self.assertEqual(logger.logger.name, 'waeup.sirp.__app.sample')
    185         self.app.__name__ = 'myapp'
    186         self.assertEqual(logger.logger.name, 'waeup.sirp.myapp.sample')
    187         assert len(logger.logger.handlers) > 0
    188 
    189     def test_loggername_expansion(self):
    190         setSite(self.app)
    191         logger = WAeUPLogger('sample', site=self.app)
    192         logger.logger # Trigger setup
    193         self.assertEqual(logger._loggername, 'waeup.sirp.app.sample')
    194 
    195     def test_filename(self):
    196         setSite(self.app)
    197         logger = WAeUPLogger('sample')
    198         logger.logger # Trigger setup
    199         self.assertEqual(logger.filename, 'sample.log')
    200 
    201     def test_filename_from_dotted_name(self):
    202         setSite(self.app)
    203         logger = WAeUPLogger('waeup.sirp.%s.sample')
    204         logger.logger # Trigger setup
    205         logfile = os.path.join(self.dc_root, 'logs', 'sample.log')
    206         self.assertEqual(logger.filename, 'sample.log')
    207         assert os.path.isfile(logfile)
    208 
    209     def test_option_filename(self):
    210         setSite(self.app)
    211         logger = WAeUPLogger('sample', filename='my.log')
    212         logger.logger # Trigger setup
    213         logfile = os.path.join(self.dc_root, 'logs', 'my.log')
    214         self.assertEqual(logger.filename, 'my.log')
    215         assert os.path.isfile(logfile)
    216 
    217     def test_option_propagate(self):
    218         logger = WAeUPLogger('sample', site=self.app)
    219         assert logger.logger.propagate is False  # default
    220         logger = WAeUPLogger('sample', site=self.app, propagate=True)
    221         assert logger.logger.propagate is True
    222         logger = WAeUPLogger('sample', site=self.app, propagate=False)
    223         assert logger.logger.propagate is False
    224 
    225     def test_logging(self):
    226         logger = WAeUPLogger('sample', site=self.app)
    227         logger.logger.info('Hi there!')
    228         logfile = os.path.join(self.dc_root, 'logs', 'sample.log')
    229         assert os.path.isfile(logfile)
    230         contents = open(logfile, 'rb').read()
    231         self.assertTrue(re.match(
    232                 '^....-..-.. ..:..:..,... - INFO - Hi there!\n$', contents))
     279    def test_ifaces(self):
     280        collector = LoggerCollector()
     281        verifyClass(ILoggerCollector, LoggerCollector)
     282        verifyObject(ILoggerCollector, collector)
     283        return
     284
     285    def test_get_utility(self):
     286        # We can get a logger collector via utility lookup
     287        util1 = queryUtility(ILoggerCollector, default=None)
     288        util2 = queryUtility(ILoggerCollector, default=None)
     289        self.assertTrue(util1 is util2)
     290        self.assertTrue(isinstance(util1, LoggerCollector))
     291        return
     292
     293    def test_get_loggers(self):
     294        # We can get loggers from a logger collector
     295        collector = LoggerCollector()
     296        result0 = collector.getLoggers(None)
     297        result1 = collector.getLoggers('not-a-site')
     298        result2 = collector.getLoggers(self.app)
     299        collector.registerLogger(self.app, self.component)
     300        result3 = collector.getLoggers(self.app)
     301        self.assertEqual(result0, [])
     302        self.assertEqual(result1, [])
     303        self.assertEqual(result2, [])
     304        self.assertEqual(result3, [self.component])
     305        self.assertTrue(result3[0] is self.component)
     306        return
     307
     308    def test_register_logger(self):
     309        # We can register loggers by name
     310        collector = LoggerCollector()
     311        collector.registerLogger(None, self.component) # Should have no effect
     312        collector.registerLogger(object(), self.component) # Same here
     313        collector.registerLogger(self.app, self.component)
     314        self.assertEqual(['app'], collector.keys())
     315        return
     316
     317    def test_register_logger_double(self):
     318        # Registering the same component twice gives one entry, not two
     319        collector = LoggerCollector()
     320        collector.registerLogger(self.app, self.component)
     321        collector.registerLogger(self.app, self.component)
     322        self.assertEqual(len(collector['app']), 1)
     323        return
     324
     325    def test_unregister_logger(self):
     326        # We can also unregister loggers
     327        collector = LoggerCollector()
     328        collector.registerLogger(self.app, self.component)
     329        collector.unregisterLogger(self.app, self.component)
     330        result = collector.getLoggers(self.app)
     331        self.assertEqual(result, [])
     332        return
     333
     334    def test_unregister_logger_invalid(self):
     335        # We can cope with unregistration of non-existing entries.
     336        collector = LoggerCollector()
     337        collector.registerLogger(self.app, self.component)
     338        collector.unregisterLogger(None, self.component)
     339        collector.unregisterLogger(self.app, 'nonsense')
     340        self.assertEqual(len(collector), 1)
     341        return
     342
     343class LogfileChangeTests(FunctionalTestCase):
     344
     345    layer = FunctionalLayer
     346
     347    def setUp(self):
     348        super(LogfileChangeTests, self).setUp()
     349        remove_logger('waeup.sirp.app') # In case it lingers around
     350        self.old_loggers = get_all_loggers()
     351        # Setup a sample site for each test
     352        app = University()
     353        self.dc_root = tempfile.mkdtemp()
     354        self.dc_root_new = None
     355        app['datacenter'].setStoragePath(self.dc_root)
     356
     357        # Prepopulate the ZODB...
     358        self.getRootFolder()['app'] = app
     359        self.app = self.getRootFolder()['app']
     360        self.workdir = tempfile.mkdtemp()
     361
     362        self.app['mycomponent'] = LoggingComponent()
     363        self.component = self.app['mycomponent']
     364        setSite(self.app)
     365
     366        self.component = LoggingComponent()
     367        return
     368
     369    def tearDown(self):
     370        super(LogfileChangeTests, self).tearDown()
     371        remove_new_loggers(self.old_loggers)
     372        shutil.rmtree(self.workdir)
     373        shutil.rmtree(self.dc_root)
     374        if self.dc_root_new is not None:
     375            shutil.rmtree(self.dc_root_new)
     376        clearSite()
     377        return
     378
     379    def test_storage_move(self):
     380        # When a datacenter storage (its path) changes, we have to
     381        # move the logfiles as well.
     382        #return
     383        filename1 = self.component.logger.handlers[0].baseFilename
     384        self.dc_root_new = tempfile.mkdtemp()
     385        self.app['datacenter'].setStoragePath(self.dc_root_new)
     386        filename2 = self.component.logger.handlers[0].baseFilename
     387        self.assertTrue(filename1 != filename2)
     388        self.assertTrue(filename2.startswith(self.dc_root_new))
     389        return
Note: See TracChangeset for help on using the changeset viewer.