source: main/waeup.sirp/trunk/src/waeup/sirp/utils/logger.py @ 11102

Last change on this file since 11102 was 7651, checked in by Henrik Bettermann, 13 years ago

Add principal name in log messages.

  • Property svn:keywords set to Id
File size: 13.5 KB
Line 
1## $Id: logger.py 7651 2012-02-15 08:25:58Z henrik $
2##
3## Copyright (C) 2011 Uli Fouquet & Henrik Bettermann
4## This program is free software; you can redistribute it and/or modify
5## it under the terms of the GNU General Public License as published by
6## the Free Software Foundation; either version 2 of the License, or
7## (at your option) any later version.
8##
9## This program is distributed in the hope that it will be useful,
10## but WITHOUT ANY WARRANTY; without even the implied warranty of
11## MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
12## GNU General Public License for more details.
13##
14## You should have received a copy of the GNU General Public License
15## along with this program; if not, write to the Free Software
16## Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA
17##
18"""
19Convenience stuff for logging.
20
21Main component of :mod:`waeup.sirp.utils.logging` is a mix-in class
22:class:`waeup.sirp.utils.logging.Logger`. Classes derived (also) from
23that mix-in provide a `logger` attribute that returns a regular Python
24logger logging to a rotating log file stored in the datacenter storage
25path.
26
27Deriving components (classes) should set their own `logger_name` and
28`logger_filename` attribute.
29
30The `logger_name` tells under which name the logger should be
31registered Python-wise. This is usually a dotted name string like
32``waeup.sirp.${sitename}.mycomponent`` which should be unique. If you
33pick a name already used by another component, trouble is ahead. The
34``${sitename}`` chunk of the name can be set literally like this. The
35logger machinery will turn it into some real site name at time of
36logging.
37
38The `logger_filename` attribute tells how the logfile should be
39named. This should be some base filename like
40``mycomponent.log``. Please note, that some logfile names are already
41used: ``main.log``, ``applications.log``, and ``datacenter.log``.
42
43The `Logger` mix-in also cares for updating the logging handlers when
44a datacenter location moves. That means you do not have to write your
45own event handlers for the purpose. Just derive from `Logger`, set
46your `logger_name` and `logger_filename` attribute and off you go::
47
48  from waeup.sirp.utils.logger import Logger
49
50  class MyComponent(object, Logger):
51      # Yes that's a complete working class
52      logger_name = 'waeup.sirp.${sitename}.mycomponent
53      logger_filename = 'mycomponent.log'
54
55      def do_something(self):
56           # demomstrate how to use logging from methods
57           self.logger.info('About to do something')
58           try:
59               # Do something here
60           except IOError:
61               self.logger.warn('Something went wrong')
62               return
63           self.logger.info('I did it')
64
65As you can see from that example, methods of the class can log
66messages simply by calling `self.logger`.
67
68The datacenter and its storage are created automatically when you
69create a :class:`waeup.sirp.app.University`. This also means that
70logging with the `Logger` mix-in will work only inside so-called sites
71(`University` instances put into ZODB are such `sites`).
72
73Other components in this module help to make everything work.
74"""
75import os
76import grok
77import logging
78from string import Template
79from zope import schema
80from zope.component import queryUtility
81from zope.interface import Interface, Attribute, implements
82from waeup.sirp.interfaces import (
83    IDataCenter, IDataCenterStorageMovedEvent, ILoggerCollector)
84from waeup.sirp.utils.helpers import get_current_principal
85
86#: Default logfile size (5 KB)
87MAX_BYTES = 5 * 1024 ** 2
88
89#: Default num of backup files (5)
90BACKUP_COUNT = 5
91
92#: Default logging level (`logging.INFO')
93LEVEL = logging.INFO
94
95class ILogger(Interface):
96    logger_name = schema.TextLine(
97        title = u'A Python logger name')
98    logger_filename = schema.TextLine(
99        title = u'A filename for the log file to use (basename)')
100    logger = Attribute("Get a Python logger instance already set up")
101    def logger_setup(logger):
102        """Setup a logger.
103
104        `logger` is an instance of :class:`logging.Logger`.
105        """
106
107    def logger_get_logfile_path():
108        """Get path to logfile used.
109
110        Return `None` if the file path cannot be computed.
111        """
112
113    def logger_get_logdir():
114        """Get the directory of the logfile.
115
116        Return `None` if the directory path cannot be computed.
117        """
118
119class ContextFilter(logging.Filter):
120    """
121    This is a filter which injects contextual information into the log.
122
123    """
124
125    def filter(self, record):
126        user = get_current_principal()
127        record.user = getattr(user, 'id', 'system')
128        return True
129
130class Logger(object):
131    """Mixin-class that for logging support.
132
133    Classes that (also) inherit from this class provide support for
134    logging with waeup sites.
135
136    By default a `logger` attribute is provided which returns a
137    regular Python logger. This logger has already registered a file
138    rotating log handler that writes log messages to a file `main.log`
139    in datacenters ``log/`` directory. This is the main log file also
140    used by other components. Therefore you can pick another filename
141    by setting the `logger_filename` attribute.
142
143    All methods and attributes of this mix-in start with ``logger_``
144    in order not to interfere with already existing names of a class.
145
146    Method names do not follow the usual Zope habit (CamelCase) but
147    PEP8 convention (lower_case_with_underscores).
148    """
149
150    #: The filename to use when logging.
151    logger_filename = 'main.log'
152
153    #: The Python logger name used when
154    #: logging. ``'waeup.sirp.${sitename}'`` by default. You can use the
155    #: ``${sitename}`` placeholder in that string, which will be
156    #: replaced by the actual used site name.
157    logger_name = 'waeup.sirp.${sitename}'
158    implements(ILogger)
159
160    @property
161    def logger(self):
162        """Get a logger instance.
163
164        Returns a standard logger object as provided by :mod:`logging`
165        module from the standard library.
166
167        Other components can use this logger to perform log entries
168        into the logfile of this component.
169
170        The logger is initialized the first time it is called.
171
172        The logger is only available when used inside a site.
173
174        .. note:: The logger default level is
175                  :data:`logging.WARN`. Use
176                  :meth:`logging.Logger.setLevel` to set a different level.
177        """
178        site = grok.getSite()
179        sitename = getattr(site, '__name__', None)
180        loggername = Template(self.logger_name).substitute(
181            dict(sitename='%s' % sitename))
182        logger = logging.getLogger(loggername)
183        flt = ContextFilter()
184        logger.addFilter(flt)
185        if site is None or sitename is None:
186            # Site not added to ZODB yet. Log to commandline
187            return logger
188        if len(logger.handlers) != 1:
189            handlers = [x for x in logger.handlers]
190            for handler in handlers:
191                handler.flush()
192                handler.close()
193                logger.removeHandler(handler)
194            logger = self.logger_setup(logger)
195        if logger is None:
196            # It might happen, that we have no logger now.
197            logger = logging.getLogger(loggername)
198        return logger
199
200    def logger_setup(self, logger):
201        """Setup logger.
202
203        The logfile will be stored in the datacenter logs/ dir.
204        """
205        filename = self.logger_get_logfile_path()
206        if filename is None:
207            return
208        collector = queryUtility(ILoggerCollector)
209        if collector is not None:
210            site = grok.getSite()
211            collector.registerLogger(site, self)
212
213        # Create a rotating file handler logger.
214        handler = logging.handlers.RotatingFileHandler(
215            filename, maxBytes=MAX_BYTES, backupCount=BACKUP_COUNT)
216        handler.setLevel(LEVEL)
217        formatter = logging.Formatter(
218            '%(asctime)s - %(levelname)s - %(user)s - %(message)s')
219        handler.setFormatter(formatter)
220
221        # Don't send log msgs to ancestors. This stops displaying
222        # logmessages on the commandline.
223        logger.propagate = False
224        logger.addHandler(handler)
225        logger.setLevel(LEVEL)
226        return logger
227
228    def logger_get_logfile_path(self):
229        """Get the path to the logfile used.
230
231        Returns the path to a file in local sites datacenter ``log/``
232        directory (dependent on :meth:`logger_get_logdir`) and with
233        :attr:`logger_filename` as basename.
234
235        Override this method if you want a complete different
236        computation of the logfile path. If you only want a different
237        logfile name, set :attr:`logger_filename`. If you only want a
238        different path to the logfile override
239        :meth:`logger_get_logdir` instead.
240
241        Returns ``None`` if no logdir can be fetched.
242
243        .. note:: creates the logfile dir if it does not exist.
244
245        """
246        logdir = self.logger_get_logdir()
247        if logdir is None:
248            return None
249        return os.path.join(logdir, self.logger_filename)
250
251    def logger_get_logdir(self):
252        """Get log dir where logfile should be put.
253
254        Returns the path to the logfile directory. If no site is set,
255        ``None`` is returned. The same applies, if the site has no
256        datacenter.
257
258        If the dir dies not exist already it will be created. Only the
259        last part of the directory path will be created.
260        """
261        site = grok.getSite()
262        if site is None:
263            return None
264        datacenter = site.get('datacenter', None)
265        if datacenter is None:
266            return None
267        logdir = os.path.join(datacenter.storage, 'logs')
268        if not os.path.exists(logdir):
269            os.mkdir(logdir)
270        return logdir
271
272    def logger_logfile_changed(self):
273        """React on logfile location change.
274
275        If the logfile changed, we can set a different logfile. While
276        changing the logfile is a rather critical operation you might
277        not do often in production use, we have to cope with that
278        especially in tests.
279
280        What this method does by default (unless you override it):
281
282        - It fetches the current logger and
283
284          - Removes flushes, closes, and removes all handlers
285
286          - Sets up new handler(s).
287
288        All this, of course, requires to be 'in a site'.
289
290        Use this method to handle moves of datacenters, for instance
291        by writing an appropriate event handler.
292        """
293        logger = self.logger
294        self.logger_shutdown()
295        self.logger_setup(logger)
296        return
297
298    def logger_shutdown(self):
299        """Remove all specific logger setup.
300        """
301        logger = self.logger
302        handlers = [x for x in logger.handlers]
303        for handler in handlers:
304            handler.flush()
305            handler.close()
306            logger.removeHandler(handler)
307        collector = queryUtility(ILoggerCollector)
308        if collector is not None:
309            collector.unregisterLogger(grok.getSite(), self)
310        return
311
312
313class LoggerCollector(dict, grok.GlobalUtility):
314    """A global utility providing `ILoggerCollector`.
315
316    A logging collector collects logging components. This helps to
317    inform them when a logfile location changes.
318
319    Logging components are registered per site they belong to.
320    """
321
322    implements(ILoggerCollector)
323
324    def getLoggers(self, site):
325        name = getattr(site, '__name__', None)
326        if name is None:
327            return []
328        if name not in self.keys():
329            return []
330        return self[name]
331
332    def registerLogger(self, site, logging_component):
333        name = getattr(site, '__name__', None)
334        if name is None:
335            return
336        if not name in self.keys():
337            # new component
338            self[name] = []
339        if logging_component in self[name]:
340            # already registered
341            return
342        self[name].append(logging_component)
343        return
344
345    def unregisterLogger(self, site, logging_component):
346        name = getattr(site, '__name__', None)
347        if name is None or name not in self.keys():
348            return
349        if logging_component not in self[name]:
350            return
351        self[name].remove(logging_component)
352        return
353
354@grok.subscribe(IDataCenter, IDataCenterStorageMovedEvent)
355def handle_datacenter_storage_moved(obj, event):
356    """Event handler, in case datacenter storage moves.
357
358    By default all our logfiles (yes, we produce a whole bunch of it)
359    are located in a ``log/`` dir of a local datacenter, the
360    datacenter 'storage'. If this path changes because the datacenter
361    is moved an appropriate event is triggered and we can react.
362
363    Via the global ILoggerCollector utility, a small piece that allows
364    self-registering of logging components, we can lookup components
365    whose logfile path has to be set up anew.
366
367    Each component we call has to provide ILogger or, more specific,
368    the :meth:`logger_logfile_changed` method of this interface.
369    """
370    site = grok.getSite()
371    if site is None:
372        return
373    collector = queryUtility(ILoggerCollector)
374    loggers = collector.getLoggers(site)
375    for logger in loggers:
376        if hasattr(logger, 'logger_logfile_changed'):
377            logger.logger_logfile_changed()
378    return
379
380from waeup.sirp.interfaces import IUniversity
381@grok.subscribe(IUniversity, grok.IObjectRemovedEvent)
382def handle_site_removed(obj, event):
383    collector = queryUtility(ILoggerCollector)
384    name = getattr(obj, '__name__', None)
385    if name is None:
386        return
387    if name not in collector.keys():
388        return
389    del collector[name]
390    return
Note: See TracBrowser for help on using the repository browser.