source: branches/numpy/anuga/utilities/log.py

Last change on this file was 7140, checked in by rwilson, 14 years ago

Slight change to logging to shorten common usage code.

  • Property svn:executable set to *
File size: 9.5 KB
Line 
1#!/usr/bin/env python
2
3'''
4A simple logging module that logs to the console and a logfile, and has a
5configurable threshold loglevel for each of console and logfile output.
6
7Use it this way:
8    import anuga.utilities.log as log
9
10    # configure my logging
11    log.console_logging_level = log.INFO
12    log.log_logging_level = log.DEBUG
13    log.log_filename('./my.log')
14
15    # log away!
16    log.debug('A message at DEBUG level')
17    log.info('Another message, INFO level')
18
19This class uses the 'borg' pattern - there is never more than one instance
20of log data.  See the URL for the basic idea used here: modules *are*
21singletons!
22
23<http://www.suttoncourtenay.org.uk/duncan/accu/pythonpatterns.html>
24
25Until the first call to log() the user is free to play with the module data
26to configure the logging.
27
28Note that this module uses some features of the logging package that were
29introduced in python2.5.  If running on earlier versions, the following
30features are disabled:
31    . Calling module name + line number
32'''
33
34import os
35import sys
36import traceback
37import logging
38
39DefaultConsoleLogLevel = logging.CRITICAL
40DefaultFileLogLevel = logging.INFO
41
42
43################################################################################
44# Module variables - only one copy of these, ever.
45#
46# The console logging level is set to a high level, like CRITICAL.  The logfile
47# logging is set lower, between DEBUG and CRITICAL.  The idea is to log least to
48# the console, but ensure that everything that goes to the console *will* also
49# appear in the log file.  There is code to ensure log <= console levels.
50#
51# If console logging level is set to CRITICAL+1 then nothing will print on the
52# console.
53################################################################################
54
55# flag variable to determine if logging set up or not
56_setup = False
57
58# logging level for the console
59console_logging_level = DefaultConsoleLogLevel
60
61# logging level for the logfile
62log_logging_level = DefaultFileLogLevel
63
64# The default name of the file to log to.
65log_filename = os.path.join('.', 'anuga.log')
66
67# set module variables so users don't have to do 'import logging'.
68CRITICAL = logging.CRITICAL
69ERROR = logging.ERROR
70WARNING = logging.WARNING
71INFO = logging.INFO
72DEBUG = logging.DEBUG
73NOTSET = logging.NOTSET
74
75# set _new_python to True if python version 2.5 or later
76_new_python = (sys.version_info >= 0x02050000)      # 2.5.x.x
77
78
79################################################################################
80# Module code.
81################################################################################
82
83def log(msg, level=None):
84    '''Log a message at a particular loglevel.
85
86    msg:    The message string to log.
87    level:  The logging level to log with (defaults to console level).
88
89    The first call to this method (by anybody) initializes logging and
90    then logs the message.  Subsequent calls just log the message.
91    '''
92
93    global _setup, log_logging_level
94
95    # have we been setup?
96    if not _setup:
97        # sanity check the logging levels, require console >= file
98        if log_logging_level > console_logging_level:
99            log_logging_level = console_logging_level
100
101        # setup the file logging system
102        if _new_python:
103            fmt = '%(asctime)s %(levelname)-8s %(mname)25s:%(lnum)-4d|%(message)s'
104        else:
105            fmt = '%(asctime)s %(levelname)-8s|%(message)s'
106        logging.basicConfig(level=log_logging_level, format=fmt,
107                            filename=log_filename, filemode='w')
108
109        # define a console handler which writes to sys.stdout
110        console = logging.StreamHandler(sys.stdout)
111        console.setLevel(console_logging_level)
112        formatter = logging.Formatter('%(message)s')
113        console.setFormatter(formatter)
114        logging.getLogger('').addHandler(console)
115
116        # catch exceptions
117        sys.excepthook = log_exception_hook
118
119        # tell the world how we are set up
120        start_msg = ("Logfile is '%s' with logging level of %s, "
121                     "console logging level is %s"
122                     % (log_filename,
123                        logging.getLevelName(log_logging_level),
124                        logging.getLevelName(console_logging_level)))
125        if _new_python:
126            logging.log(logging.CRITICAL, start_msg,
127                        extra={'mname': __name__, 'lnum': 0})
128        else:
129            logging.log(logging.CRITICAL, start_msg)
130
131        # mark module as *setup*
132        _setup = True
133
134    # if logging level not supplied, assume console level
135    if level is None:
136        level = console_logging_level
137
138    # get caller information - look back for first module != <this module name>
139    frames = traceback.extract_stack()
140    frames.reverse()
141    try:
142        (_, mod_name) = __name__.rsplit('.', 1)
143    except ValueError:
144        mod_name = __name__
145    for (fpath, lnum, mname, _) in frames:
146        (fname, _) = os.path.basename(fpath).rsplit('.', 1)
147        if fname != mod_name:
148            break
149
150    # why are we here? ... Oh yes! Log the message!
151    if _new_python:
152        logging.log(level, msg, extra={'mname': fname, 'lnum': lnum})
153    else:
154        logging.log(level, msg)
155
156
157def log_exception_hook(type, value, tb):
158    '''Hook function to process uncaught exceptions.
159
160    type:   Type of exception.
161    value:  The exception data.
162    tb:     Traceback object.
163
164    This has the same interface as sys.excepthook().
165    '''
166
167    msg = '\n' + ''.join(traceback.format_exception(type, value, tb))
168    critical(msg)
169
170   
171################################################################################
172# Shortcut routines to make for simpler user code.
173################################################################################
174
175def debug(msg=''):
176    '''Shortcut for log(DEBUG, msg).'''
177
178    log(msg, logging.DEBUG)
179
180
181def info(msg=''):
182    '''Shortcut for log(INFO, msg).'''
183
184    log(msg, logging.INFO)
185
186
187def warning(msg=''):
188    '''Shortcut for log(WARNING, msg).'''
189
190    log(msg, logging.WARNING)
191
192
193def error(msg=''):
194    '''Shortcut for log(ERROR, msg).'''
195
196    log(msg, logging.ERROR)
197
198
199def critical(msg=''):
200    '''Shortcut for log(CRITICAL, msg).'''
201
202    log(msg, logging.CRITICAL)
203
204
205def resource_usage(level=logging.INFO):
206    '''Log memory usage at given log level.'''
207
208    _scale = {'KB': 1024, 'MB': 1024*1024, 'GB': 1024*1024*1024,
209              'kB': 1024, 'mB': 1024*1024, 'gB': 1024*1024*1024}
210
211    if sys.platform != 'win32':
212        _proc_status = '/proc/%d/status' % os.getpid()
213       
214        def _VmB(VmKey):
215            '''Get number of virtual bytes used.'''
216
217            # get pseudo file /proc/<pid>/status
218            try:
219                t = open(_proc_status)
220                v = t.read()
221                t.close()
222            except IOError:
223                return 0.0
224
225            # get VmKey line, eg: 'VmRSS: 999 kB\n ...
226            i = v.index(VmKey)
227            v = v[i:].split(None, 3)
228            if len(v) < 3:
229                return 0.0
230
231            # convert Vm value to bytes
232            return float(v[1]) * _scale[v[2]]
233
234        def memory(since=0.0):
235            '''Get virtual memory usage in bytes.'''
236
237            return _VmB('VmSize:') - since
238
239        def resident(since=0.0):
240            '''Get resident memory usage in bytes.'''
241
242            return _VmB('VmRSS:') - since
243
244        def stacksize(since=0.0):
245            '''Get stack size in bytes.'''
246
247            return _VmB('VmStk:') - since
248
249        msg = ('Resource usage: memory=%.1fMB resident=%.1fMB stacksize=%.1fMB'
250               % (memory()/_scale['MB'], resident()/_scale['MB'],
251                  stacksize()/_scale['MB']))
252        log(msg, level)
253    else:
254        # Windows code from: http://code.activestate.com/recipes/511491/
255        try:
256            import ctypes
257            import _winreg
258        except:
259            log(level, 'Windows resource usage not available')
260            return
261
262        kernel32 = ctypes.windll.kernel32
263        c_ulong = ctypes.c_ulong
264        c_ulonglong = ctypes.c_ulonglong
265        class MEMORYSTATUSEX(ctypes.Structure):
266            _fields_ = [('dwLength', c_ulong),
267                        ('dwMemoryLoad', c_ulong),
268                        ('ullTotalPhys', c_ulonglong),
269                        ('ullAvailPhys', c_ulonglong),
270                        ('ullTotalPageFile', c_ulonglong),
271                        ('ullAvailPageFile', c_ulonglong),
272                        ('ullTotalVirtual', c_ulonglong),
273                        ('ullAvailVirtual', c_ulonglong),
274                        ('ullAvailExtendedVirtual', c_ulonglong)
275                       ]
276
277        memoryStatusEx = MEMORYSTATUSEX()
278        memoryStatusEx.dwLength = ctypes.sizeof(MEMORYSTATUSEX)
279        kernel32.GlobalMemoryStatusEx(ctypes.byref(memoryStatusEx))
280
281        msg = ('Resource usage: total memory=%.1fMB free memory=%.1fMB'
282               % (memoryStatusEx.ullTotalPhys/_scale['MB'],
283                  memoryStatusEx.ullAvailPhys/_scale['MB']))
284        log(msg, level)
285
286
287################################################################################
288
289if __name__ == '__main__':
290    critical('#' * 80)
291    warning('Test of logging...')
292    log('CRITICAL+1', CRITICAL+1)
293    log('CRITICAL', CRITICAL)
294    log('CRITICAL-1', CRITICAL-1)
295    log('CRITICAL-2', CRITICAL-2)
296    log('default - CRITICAL?')
297
298    def test_it(num=100):
299        if num > 0:
300            test_it(num-1)
301        else:
302            resource_usage()
303
304    import numpy as num
305   
306    a = num.zeros((1000,1000), num.float)
307
308    info('sys.version_info=%s, _new_python=%s'
309         % (str(sys.version_info), str(_new_python)))
310    test_it()
Note: See TracBrowser for help on using the repository browser.