source: main/waeup.kofa/trunk/src/waeup/kofa/utils/logger.py @ 11156

Last change on this file since 11156 was 9988, checked in by uli, 12 years ago

Use WatchedFileHandler? instead of DatedRotatingFileHandler? for logging.

  • Property svn:keywords set to Id
File size: 13.7 KB
Line 
1## $Id: logger.py 9988 2013-02-24 13:42:04Z uli $
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.kofa.utils.logging` is a mix-in class
22:class:`waeup.kofa.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.kofa.${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.kofa.utils.logger import Logger
49
50  class MyComponent(object, Logger):
51      # Yes that's a complete working class
52      logger_name = 'waeup.kofa.${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.kofa.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 logging.handlers import WatchedFileHandler
79from string import Template
80from ulif.loghandlers import DatedRotatingFileHandler
81from zope import schema
82from zope.component import queryUtility
83from zope.interface import Interface, Attribute, implements
84from waeup.kofa.interfaces import (
85    IDataCenter, IDataCenterStorageMovedEvent, ILoggerCollector)
86from waeup.kofa.utils.helpers import get_current_principal
87
88#: Default logfile size (5 KB, not relevant for DatedRotatingFileHandlers)
89MAX_BYTES = 5 * 1024 ** 2
90
91#: Default num of backup files (-1 = indefinite)
92BACKUP_COUNT = -1
93
94#: Default logging level (`logging.INFO')
95LEVEL = logging.INFO
96
97class ILogger(Interface):
98    logger_name = schema.TextLine(
99        title = u'A Python logger name')
100    logger_filename = schema.TextLine(
101        title = u'A filename for the log file to use (basename)')
102    logger = Attribute("Get a Python logger instance already set up")
103    def logger_setup(logger):
104        """Setup a logger.
105
106        `logger` is an instance of :class:`logging.Logger`.
107        """
108
109    def logger_get_logfile_path():
110        """Get path to logfile used.
111
112        Return `None` if the file path cannot be computed.
113        """
114
115    def logger_get_logdir():
116        """Get the directory of the logfile.
117
118        Return `None` if the directory path cannot be computed.
119        """
120
121class ContextFilter(logging.Filter):
122    """
123    This is a filter which injects contextual information into the log.
124
125    """
126
127    def filter(self, record):
128        user = get_current_principal()
129        record.user = getattr(user, 'id', 'system')
130        return True
131
132class Logger(object):
133    """Mixin-class that for logging support.
134
135    Classes that (also) inherit from this class provide support for
136    logging with waeup sites.
137
138    By default a `logger` attribute is provided which returns a
139    regular Python logger. This logger has already registered a file
140    rotating log handler that writes log messages to a file `main.log`
141    in datacenters ``log/`` directory. This is the main log file also
142    used by other components. Therefore you can pick another filename
143    by setting the `logger_filename` attribute.
144
145    All methods and attributes of this mix-in start with ``logger_``
146    in order not to interfere with already existing names of a class.
147
148    Method names do not follow the usual Zope habit (CamelCase) but
149    PEP8 convention (lower_case_with_underscores).
150    """
151
152    #: The filename to use when logging.
153    logger_filename = 'main.log'
154
155    #: The Python logger name used when
156    #: logging. ``'waeup.kofa.${sitename}'`` by default. You can use the
157    #: ``${sitename}`` placeholder in that string, which will be
158    #: replaced by the actual used site name.
159    logger_name = 'waeup.kofa.${sitename}'
160
161    #: The format to use when logging.
162    logger_format_str = '%(asctime)s - %(levelname)s - %(user)s - %(message)s'
163
164    implements(ILogger)
165
166    @property
167    def logger(self):
168        """Get a logger instance.
169
170        Returns a standard logger object as provided by :mod:`logging`
171        module from the standard library.
172
173        Other components can use this logger to perform log entries
174        into the logfile of this component.
175
176        The logger is initialized the first time it is called.
177
178        The logger is only available when used inside a site.
179
180        .. note:: The logger default level is
181                  :data:`logging.WARN`. Use
182                  :meth:`logging.Logger.setLevel` to set a different level.
183        """
184        site = grok.getSite()
185        sitename = getattr(site, '__name__', None)
186        loggername = Template(self.logger_name).substitute(
187            dict(sitename='%s' % sitename))
188        logger = logging.getLogger(loggername)
189        if site is None or sitename is None:
190            # Site not added to ZODB yet. Log to commandline
191            return logger
192        if len(logger.handlers) != 1:
193            handlers = [x for x in logger.handlers]
194            for handler in handlers:
195                handler.flush()
196                handler.close()
197                logger.removeHandler(handler)
198            logger = self.logger_setup(logger)
199        if logger is None:
200            # It might happen, that we have no logger now.
201            logger = logging.getLogger(loggername)
202        return logger
203
204    def logger_setup(self, logger):
205        """Setup logger.
206
207        The logfile will be stored in the datacenter logs/ dir.
208        """
209        filename = self.logger_get_logfile_path()
210        if filename is None:
211            return
212        collector = queryUtility(ILoggerCollector)
213        if collector is not None:
214            site = grok.getSite()
215            collector.registerLogger(site, self)
216
217        # Create a rotating file handler logger.
218        handler = WatchedFileHandler(
219            filename, encoding='utf-8')
220        #handler = DatedRotatingFileHandler(
221        #    filename, when='MON', backupCount=BACKUP_COUNT)
222        handler.setLevel(LEVEL)
223        formatter = logging.Formatter(self.logger_format_str)
224        handler.setFormatter(formatter)
225
226        # Don't send log msgs to ancestors. This stops displaying
227        # logmessages on the commandline.
228        logger.propagate = False
229        logger.addHandler(handler)
230        logger.setLevel(LEVEL)
231
232        flt = ContextFilter()
233        logger.addFilter(flt)
234        return logger
235
236    def logger_get_logfile_path(self):
237        """Get the path to the logfile used.
238
239        Returns the path to a file in local sites datacenter ``log/``
240        directory (dependent on :meth:`logger_get_logdir`) and with
241        :attr:`logger_filename` as basename.
242
243        Override this method if you want a complete different
244        computation of the logfile path. If you only want a different
245        logfile name, set :attr:`logger_filename`. If you only want a
246        different path to the logfile override
247        :meth:`logger_get_logdir` instead.
248
249        Returns ``None`` if no logdir can be fetched.
250
251        .. note:: creates the logfile dir if it does not exist.
252
253        """
254        logdir = self.logger_get_logdir()
255        if logdir is None:
256            return None
257        return os.path.join(logdir, self.logger_filename)
258
259    def logger_get_logdir(self):
260        """Get log dir where logfile should be put.
261
262        Returns the path to the logfile directory. If no site is set,
263        ``None`` is returned. The same applies, if the site has no
264        datacenter.
265
266        If the dir dies not exist already it will be created. Only the
267        last part of the directory path will be created.
268        """
269        site = grok.getSite()
270        if site is None:
271            return None
272        datacenter = site.get('datacenter', None)
273        if datacenter is None:
274            return None
275        logdir = os.path.join(datacenter.storage, 'logs')
276        if not os.path.exists(logdir):
277            os.mkdir(logdir)
278        return logdir
279
280    def logger_logfile_changed(self):
281        """React on logfile location change.
282
283        If the logfile changed, we can set a different logfile. While
284        changing the logfile is a rather critical operation you might
285        not do often in production use, we have to cope with that
286        especially in tests.
287
288        What this method does by default (unless you override it):
289
290        - It fetches the current logger and
291
292          - Removes flushes, closes, and removes all handlers
293
294          - Sets up new handler(s).
295
296        All this, of course, requires to be 'in a site'.
297
298        Use this method to handle moves of datacenters, for instance
299        by writing an appropriate event handler.
300        """
301        logger = self.logger
302        self.logger_shutdown()
303        self.logger_setup(logger)
304        return
305
306    def logger_shutdown(self):
307        """Remove all specific logger setup.
308        """
309        logger = self.logger
310        handlers = [x for x in logger.handlers]
311        for handler in handlers:
312            handler.flush()
313            handler.close()
314            logger.removeHandler(handler)
315        collector = queryUtility(ILoggerCollector)
316        if collector is not None:
317            collector.unregisterLogger(grok.getSite(), self)
318        return
319
320
321class LoggerCollector(dict, grok.GlobalUtility):
322    """A global utility providing `ILoggerCollector`.
323
324    A logging collector collects logging components. This helps to
325    inform them when a logfile location changes.
326
327    Logging components are registered per site they belong to.
328    """
329
330    implements(ILoggerCollector)
331
332    def getLoggers(self, site):
333        name = getattr(site, '__name__', None)
334        if name is None:
335            return []
336        if name not in self.keys():
337            return []
338        return self[name]
339
340    def registerLogger(self, site, logging_component):
341        name = getattr(site, '__name__', None)
342        if name is None:
343            return
344        if not name in self.keys():
345            # new component
346            self[name] = []
347        if logging_component in self[name]:
348            # already registered
349            return
350        self[name].append(logging_component)
351        return
352
353    def unregisterLogger(self, site, logging_component):
354        name = getattr(site, '__name__', None)
355        if name is None or name not in self.keys():
356            return
357        if logging_component not in self[name]:
358            return
359        self[name].remove(logging_component)
360        return
361
362@grok.subscribe(IDataCenter, IDataCenterStorageMovedEvent)
363def handle_datacenter_storage_moved(obj, event):
364    """Event handler, in case datacenter storage moves.
365
366    By default all our logfiles (yes, we produce a whole bunch of it)
367    are located in a ``log/`` dir of a local datacenter, the
368    datacenter 'storage'. If this path changes because the datacenter
369    is moved an appropriate event is triggered and we can react.
370
371    Via the global ILoggerCollector utility, a small piece that allows
372    self-registering of logging components, we can lookup components
373    whose logfile path has to be set up anew.
374
375    Each component we call has to provide ILogger or, more specific,
376    the :meth:`logger_logfile_changed` method of this interface.
377    """
378    site = grok.getSite()
379    if site is None:
380        return
381    collector = queryUtility(ILoggerCollector)
382    loggers = collector.getLoggers(site)
383    for logger in loggers:
384        if hasattr(logger, 'logger_logfile_changed'):
385            logger.logger_logfile_changed()
386    return
387
388from waeup.kofa.interfaces import IUniversity
389@grok.subscribe(IUniversity, grok.IObjectRemovedEvent)
390def handle_site_removed(obj, event):
391    collector = queryUtility(ILoggerCollector)
392    name = getattr(obj, '__name__', None)
393    if name is None:
394        return
395    if name not in collector.keys():
396        return
397    del collector[name]
398    return
Note: See TracBrowser for help on using the repository browser.