| 123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368 |
- from logging import *
- import time, sys
- import socket
- import datetime
- import logging
- import logging.handlers
- from BTL.reactor_magic import reactor
- from BTL.defer import Deferred
- from BTL.btl_string import printable
- from BTL import twisted_logger
- # convenience re-export so that they can be used without import logging.
- DEBUG = DEBUG
- INFO = INFO
- WARNING = WARNING
- ERROR = ERROR
- CRITICAL = CRITICAL
- getLogger = getLogger
- # Not used at the moment but can be changed later
- SYSLOG_HOST = 'localhost'
- SYSLOG_PORT = 514
- class BTLFormatter(logging.Formatter):
- def __init__(self, *a, **k):
- self.use_localtime = False
- if k.has_key('use_localtime'):
- self.use_localtime = k['use_localtime']
- del k['use_localtime']
- logging.Formatter.__init__(self, *a, **k)
- def formatTime(self, record, datefmt=None):
- ct = self.converter(record.created)
- try:
- if self.use_localtime:
- dt = datetime.datetime.fromtimestamp(record.created)
- else:
- dt = datetime.datetime.utcfromtimestamp(record.created)
- if datefmt:
- s = dt.strftime(datefmt)
- else:
- s = dt.isoformat()
- except:
- s = "Interpretter Shutdown"
- return s
- class RateLimitedLogger:
- """Logger that tosses log entries whenever the logged
- entries per second exceeds the specified rate limit by
- max_burst log entries."""
- def __init__(self, logger, rate_limit, max_burst, log_all_level = CRITICAL ):
- """@param logger: logging.Logger object that this class wraps.
- @param rate_limit: maximum number of log entries per second.
- @param max_burst: maximum number of log entries that can be printed
- in a burst. max_burst is the sigma in a (sigma,rho) token bucket.
- @param log_all_level: log all entries with level >= log_all_level.
- Such entries are still counted against the rate limit.
- """
- self.logger = logger
- self.rate_limit = rate_limit
- self.max_burst = max_burst
- self.logged_discard = False # logged that we are dropping entries?
- self.tokens = self.max_burst
- self.log_all_above_level = log_all_level
- reactor.callLater(1,self._increment_tokens)
- reactor.callLater(5,self._log_clear)
- def _increment_tokens(self):
- self.tokens += self.rate_limit
- if self.tokens >= self.max_burst:
- self.tokens = self.max_burst
- reactor.callLater(1, self._increment_tokens)
- def _log_clear(self):
- self.logged_discard = False
- def setLevel(self, level):
- return self.logger.setLevel(level)
- def _discarded(self, level):
- self.tokens -= 1
- if self.tokens < 0:
- self.tokens = 0
- if level >= self.log_all_above_level:
- return False
- elif not self.logged_discard:
- self.logger.error( "Discarding '%s' logger entries because they are arriving "
- "too fast. Will not log this error again for 5 "
- "seconds." % self.logger.name )
- self.logged_discard = True
- return True # true = discarded
- return False # false = not discarded
- def debug(self, msg, *args, **kwargs):
- if not self._discarded(level = DEBUG):
- self.logger.debug(msg,*args, **kwargs)
- def info(self, msg, *args, **kwargs):
- if not self._discarded(level = INFO):
- self.logger.info(msg, *args, **kwargs)
- def warning(self, msg, *args, **kwargs):
- if not self._discarded(level = WARNING):
- self.logger.warning(msg, *args, **kwargs)
- def error(self, msg, *args, **kwargs):
- if not self._discarded(level = ERROR):
- self.logger.error(msg, *args, **kwargs)
- def exception(self, msg, *args):
- if not self._discarded(level = EXCEPTION):
- self.logger.exception(msg, *args)
- def critical(self, msg, *args, **kwargs):
- if not self._discarded(level = CRITICAL):
- self.logger.critical(msg, *args, **kwargs)
- def log(self, level, msg, *args, **kwargs):
- if not self._discarded():
- self.logger.log(level, msg, *args, **kwargs)
- def findCaller(self):
- return self.logger.findCaller()
- def makeRecord(self, name, level, fn, lno, msg, args, exc_info):
- self.logger.makeRecord(name, level, fn, lno, msg, args, exc_info)
- def addHandler(self, hdlr):
- self.logger.addHandler(hdlr)
- def removeHandler(self, hdlr):
- self.logger.removeHandler(hdlr)
- def callHandlers(self, record):
- self.logger.callHandlers(record)
- def getEffectiveLevel(self):
- return self.logger.getEffectiveLevel()
- class StdioPretender:
- """Pretends to be stdout or stderr."""
- # modified from twisted.python.log.StdioOnnaStick
- closed = 0
- softspace = 0
- mode = 'wb'
- name = '<stdio (log)>'
- def __init__(self, capture_name, level ):
- self.level = level
- self.logger = logging.getLogger( capture_name )
- self.buf = ''
- def close(self):
- pass
- def flush(self):
- pass
- def fileno(self):
- return -1
- def read(self):
- raise IOError("can't read from the log!")
- readline = read
- readlines = read
- seek = read
- tell = read
- def write(self, data):
- d = (self.buf + data).split('\n')
- self.buf = d[-1]
- messages = d[0:-1]
- for message in messages:
- self.logger.log( self.level, message )
- def writelines(self, lines):
- for line in lines:
- self.logger.log( self.level, message )
- class SysLogHandler(logging.handlers.SysLogHandler):
- # This is a hack to get around log entry size limits imposed by syslog.
- def __init__(self, address=('localhost', logging.handlers.SYSLOG_UDP_PORT),
- facility=logging.handlers.SysLogHandler.LOG_USER,
- max_msg_len = 4096, fragment_len = 900, make_printable = True ):
- """@param max_msg_len: maximum message length before truncation.
- @param fragment_len: when message length exceeds 900 it is truncated
- and broken into multiple consecutive log entries.
- @param make_printable: runs each message through
- BTL.btl_string.printable in emit. For example,
- this is useful if the messages are being sent
- through a UNIX socket to syslogd and the
- message might contain non-ascii characters.
- """
- logging.handlers.SysLogHandler.__init__( self, address, facility )
- self.max_msg_len = max_msg_len
- self.fragment_len = fragment_len
- self.make_printable = make_printable
- def emit(self, record):
- """Differs from the override emit in that it
- fragments the message to allow for much longer
- syslog messages."""
- msg = self.format(record)
- if self.make_printable:
- msg = printable(msg)
- msg = msg[:self.max_msg_len]
- i = 0
- while msg:
- remaining = msg[self.fragment_len:]
- if i > 0:
- msg = "(cont.) " + msg[:self.fragment_len]
- else:
- msg = msg[:self.fragment_len]
- msg = self.log_format_string % (self.encodePriority(self.facility,
- string.lower(record.levelname)),msg)
- try:
- if self.unixsocket:
- try:
- self.socket.send(msg)
- except socket.error:
- self._connect_unixsocket(self.address)
- self.socket.send(msg)
- else:
- self.socket.sendto(msg, self.address)
- except (KeyboardInterrupt, SystemExit):
- raise
- except:
- self.handleError(record)
- msg = remaining
- i += 1
- def injectLogger(use_syslog = True, log_file = None, verbose = False,
- capture_output = True,
- twisted_error_log_level = ERROR,
- twisted_info_log_level = INFO,
- capture_stderr_log_level = ERROR,
- capture_stdout_log_level = INFO,
- capture_stderr_name = 'stderr',
- capture_stdout_name = 'stdout',
- log_level = DEBUG,
- log_twisted = True,
- use_localtime = False ):
- """
- Installs logging.
- @param use_syslog: log to syslog. use_syslog, log_file, and verbose are not
- mutually exclusive.
- @param log_file: log to a file.
- @param verbose: output logs to stdout. Setting verbose and capture_output
- to this function does NOT result in an infinite loop.
- @param capture_output: redirects stdout and stderr to the logger. Be careful. This can
- create infinite loops with loggers that
- output to stdout or stderr.
- @param twisted_error_log_level: log level for errors reported
- by twisted.
- @param twisted_info_log_level: log level for non-errors reported by twisted.
- If capture_output is set then this is also the log
- level for anything output to stdout or stderr.
- @param log_level: only log events that have level >= passed level
- are logged. This is achieved by setting the log level in
- each of the installed handlers.
- @param capture_stderr_log_level: log level for output captured from stdout.
- @param capture_stdout_log_level: log level for output captured from stderr.
- @param capture_stderr_name: log name used for stderr. 'name'
- refers to the name arg passed to logging.getLogger(name).
- @param capture_stdout_name: log name used for stdout. Analogous to capture_stderr_name.
- """
- logger = logging.getLogger('')
- logger.setLevel(DEBUG) # we use log handler levels to control output level.
- formatter = BTLFormatter("%(asctime)s - %(name)s - %(process)d - "
- "%(levelname)s - %(message)s", use_localtime=use_localtime)
- if log_file is not None:
- lf_handler = logging.handlers.RotatingFileHandler(filename=log_file,
- mode='a',
- maxBytes=2**27,
- backupCount=10)
- lf_handler.setFormatter(formatter)
- lf_handler.setLevel(log_level)
- logger.addHandler(lf_handler)
- if use_syslog:
- sl_handler = SysLogHandler('/dev/log',
- facility=SysLogHandler.LOG_LOCAL0)
- #address = (SYSLOG_HOST, SYSLOG_PORT))
- # namespace - pid - level - message
- sl_handler.setFormatter(BTLFormatter("%(name)s - %(process)d - "
- "%(levelname)s - %(message)s"))
- sl_handler.setLevel(log_level)
- logger.addHandler(sl_handler)
- if verbose:
- # StreamHandler does not capture stdout, it directs output from
- # loggers to stdout.
- so_handler = logging.StreamHandler(sys.stdout)
- so_handler.setFormatter(formatter)
- so_handler.setLevel(log_level)
- logger.addHandler(so_handler)
- if capture_output:
- sys.stdout = StdioPretender( capture_stdout_name, capture_stdout_log_level )
- sys.stderr = StdioPretender( capture_stderr_name, capture_stderr_log_level )
- if log_twisted:
- twisted_logger.start(error_log_level = twisted_error_log_level,
- info_log_level = twisted_info_log_level)
- if __name__ == '__main__':
- from BTL.greenlet_yielddefer import coroutine, like_yield
- @coroutine
- def test_rate_limited_logger():
- injectLogger(verbose = True)
- log = RateLimitedLogger(logging.getLogger("myapp"), 1,1)
- log.info( "should be printed." )
- log.info( "should not be printed" ) # but should log "discard" message.
- log.info( "also should not be printed" ) # should not logging of discard message.
- df = Deferred()
- reactor.callLater(3, df.callback, True)
- like_yield(df)
- log.info( "should also be printed" )
- reactor.stop()
- def test_injectLogger():
- injectLogger(log_file = "your.log", use_syslog=False, verbose=True)
- logger = logging.getLogger("myapp")
- logger.warning("You are awesome")
- print 'stdout!'
- print >>sys.stderr, 'stderr!'
- from twisted.internet import reactor
- from twisted.python import failure
- def foo():
- reactor.stop()
- zuul = dana
- reactor.callLater(0, foo)
- def test_injectLogger2():
- injectLogger(log_file = "your.log", verbose=False, capture_output=True)
- print "hello world"
- def foo():
- reactor.stop()
- zuul = dana
- reactor.callLater(0, foo)
- #test_injectLogger()
- test_injectLogger2()
- #reactor.callLater(0, test_rate_limited_logger)
- reactor.run()
|