log.py 13 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368
  1. from logging import *
  2. import time, sys
  3. import socket
  4. import datetime
  5. import logging
  6. import logging.handlers
  7. from BTL.reactor_magic import reactor
  8. from BTL.defer import Deferred
  9. from BTL.btl_string import printable
  10. from BTL import twisted_logger
  11. # convenience re-export so that they can be used without import logging.
  12. DEBUG = DEBUG
  13. INFO = INFO
  14. WARNING = WARNING
  15. ERROR = ERROR
  16. CRITICAL = CRITICAL
  17. getLogger = getLogger
  18. # Not used at the moment but can be changed later
  19. SYSLOG_HOST = 'localhost'
  20. SYSLOG_PORT = 514
  21. class BTLFormatter(logging.Formatter):
  22. def __init__(self, *a, **k):
  23. self.use_localtime = False
  24. if k.has_key('use_localtime'):
  25. self.use_localtime = k['use_localtime']
  26. del k['use_localtime']
  27. logging.Formatter.__init__(self, *a, **k)
  28. def formatTime(self, record, datefmt=None):
  29. ct = self.converter(record.created)
  30. try:
  31. if self.use_localtime:
  32. dt = datetime.datetime.fromtimestamp(record.created)
  33. else:
  34. dt = datetime.datetime.utcfromtimestamp(record.created)
  35. if datefmt:
  36. s = dt.strftime(datefmt)
  37. else:
  38. s = dt.isoformat()
  39. except:
  40. s = "Interpretter Shutdown"
  41. return s
  42. class RateLimitedLogger:
  43. """Logger that tosses log entries whenever the logged
  44. entries per second exceeds the specified rate limit by
  45. max_burst log entries."""
  46. def __init__(self, logger, rate_limit, max_burst, log_all_level = CRITICAL ):
  47. """@param logger: logging.Logger object that this class wraps.
  48. @param rate_limit: maximum number of log entries per second.
  49. @param max_burst: maximum number of log entries that can be printed
  50. in a burst. max_burst is the sigma in a (sigma,rho) token bucket.
  51. @param log_all_level: log all entries with level >= log_all_level.
  52. Such entries are still counted against the rate limit.
  53. """
  54. self.logger = logger
  55. self.rate_limit = rate_limit
  56. self.max_burst = max_burst
  57. self.logged_discard = False # logged that we are dropping entries?
  58. self.tokens = self.max_burst
  59. self.log_all_above_level = log_all_level
  60. reactor.callLater(1,self._increment_tokens)
  61. reactor.callLater(5,self._log_clear)
  62. def _increment_tokens(self):
  63. self.tokens += self.rate_limit
  64. if self.tokens >= self.max_burst:
  65. self.tokens = self.max_burst
  66. reactor.callLater(1, self._increment_tokens)
  67. def _log_clear(self):
  68. self.logged_discard = False
  69. def setLevel(self, level):
  70. return self.logger.setLevel(level)
  71. def _discarded(self, level):
  72. self.tokens -= 1
  73. if self.tokens < 0:
  74. self.tokens = 0
  75. if level >= self.log_all_above_level:
  76. return False
  77. elif not self.logged_discard:
  78. self.logger.error( "Discarding '%s' logger entries because they are arriving "
  79. "too fast. Will not log this error again for 5 "
  80. "seconds." % self.logger.name )
  81. self.logged_discard = True
  82. return True # true = discarded
  83. return False # false = not discarded
  84. def debug(self, msg, *args, **kwargs):
  85. if not self._discarded(level = DEBUG):
  86. self.logger.debug(msg,*args, **kwargs)
  87. def info(self, msg, *args, **kwargs):
  88. if not self._discarded(level = INFO):
  89. self.logger.info(msg, *args, **kwargs)
  90. def warning(self, msg, *args, **kwargs):
  91. if not self._discarded(level = WARNING):
  92. self.logger.warning(msg, *args, **kwargs)
  93. def error(self, msg, *args, **kwargs):
  94. if not self._discarded(level = ERROR):
  95. self.logger.error(msg, *args, **kwargs)
  96. def exception(self, msg, *args):
  97. if not self._discarded(level = EXCEPTION):
  98. self.logger.exception(msg, *args)
  99. def critical(self, msg, *args, **kwargs):
  100. if not self._discarded(level = CRITICAL):
  101. self.logger.critical(msg, *args, **kwargs)
  102. def log(self, level, msg, *args, **kwargs):
  103. if not self._discarded():
  104. self.logger.log(level, msg, *args, **kwargs)
  105. def findCaller(self):
  106. return self.logger.findCaller()
  107. def makeRecord(self, name, level, fn, lno, msg, args, exc_info):
  108. self.logger.makeRecord(name, level, fn, lno, msg, args, exc_info)
  109. def addHandler(self, hdlr):
  110. self.logger.addHandler(hdlr)
  111. def removeHandler(self, hdlr):
  112. self.logger.removeHandler(hdlr)
  113. def callHandlers(self, record):
  114. self.logger.callHandlers(record)
  115. def getEffectiveLevel(self):
  116. return self.logger.getEffectiveLevel()
  117. class StdioPretender:
  118. """Pretends to be stdout or stderr."""
  119. # modified from twisted.python.log.StdioOnnaStick
  120. closed = 0
  121. softspace = 0
  122. mode = 'wb'
  123. name = '<stdio (log)>'
  124. def __init__(self, capture_name, level ):
  125. self.level = level
  126. self.logger = logging.getLogger( capture_name )
  127. self.buf = ''
  128. def close(self):
  129. pass
  130. def flush(self):
  131. pass
  132. def fileno(self):
  133. return -1
  134. def read(self):
  135. raise IOError("can't read from the log!")
  136. readline = read
  137. readlines = read
  138. seek = read
  139. tell = read
  140. def write(self, data):
  141. d = (self.buf + data).split('\n')
  142. self.buf = d[-1]
  143. messages = d[0:-1]
  144. for message in messages:
  145. self.logger.log( self.level, message )
  146. def writelines(self, lines):
  147. for line in lines:
  148. self.logger.log( self.level, message )
  149. class SysLogHandler(logging.handlers.SysLogHandler):
  150. # This is a hack to get around log entry size limits imposed by syslog.
  151. def __init__(self, address=('localhost', logging.handlers.SYSLOG_UDP_PORT),
  152. facility=logging.handlers.SysLogHandler.LOG_USER,
  153. max_msg_len = 4096, fragment_len = 900, make_printable = True ):
  154. """@param max_msg_len: maximum message length before truncation.
  155. @param fragment_len: when message length exceeds 900 it is truncated
  156. and broken into multiple consecutive log entries.
  157. @param make_printable: runs each message through
  158. BTL.btl_string.printable in emit. For example,
  159. this is useful if the messages are being sent
  160. through a UNIX socket to syslogd and the
  161. message might contain non-ascii characters.
  162. """
  163. logging.handlers.SysLogHandler.__init__( self, address, facility )
  164. self.max_msg_len = max_msg_len
  165. self.fragment_len = fragment_len
  166. self.make_printable = make_printable
  167. def emit(self, record):
  168. """Differs from the override emit in that it
  169. fragments the message to allow for much longer
  170. syslog messages."""
  171. msg = self.format(record)
  172. if self.make_printable:
  173. msg = printable(msg)
  174. msg = msg[:self.max_msg_len]
  175. i = 0
  176. while msg:
  177. remaining = msg[self.fragment_len:]
  178. if i > 0:
  179. msg = "(cont.) " + msg[:self.fragment_len]
  180. else:
  181. msg = msg[:self.fragment_len]
  182. msg = self.log_format_string % (self.encodePriority(self.facility,
  183. string.lower(record.levelname)),msg)
  184. try:
  185. if self.unixsocket:
  186. try:
  187. self.socket.send(msg)
  188. except socket.error:
  189. self._connect_unixsocket(self.address)
  190. self.socket.send(msg)
  191. else:
  192. self.socket.sendto(msg, self.address)
  193. except (KeyboardInterrupt, SystemExit):
  194. raise
  195. except:
  196. self.handleError(record)
  197. msg = remaining
  198. i += 1
  199. def injectLogger(use_syslog = True, log_file = None, verbose = False,
  200. capture_output = True,
  201. twisted_error_log_level = ERROR,
  202. twisted_info_log_level = INFO,
  203. capture_stderr_log_level = ERROR,
  204. capture_stdout_log_level = INFO,
  205. capture_stderr_name = 'stderr',
  206. capture_stdout_name = 'stdout',
  207. log_level = DEBUG,
  208. log_twisted = True,
  209. use_localtime = False ):
  210. """
  211. Installs logging.
  212. @param use_syslog: log to syslog. use_syslog, log_file, and verbose are not
  213. mutually exclusive.
  214. @param log_file: log to a file.
  215. @param verbose: output logs to stdout. Setting verbose and capture_output
  216. to this function does NOT result in an infinite loop.
  217. @param capture_output: redirects stdout and stderr to the logger. Be careful. This can
  218. create infinite loops with loggers that
  219. output to stdout or stderr.
  220. @param twisted_error_log_level: log level for errors reported
  221. by twisted.
  222. @param twisted_info_log_level: log level for non-errors reported by twisted.
  223. If capture_output is set then this is also the log
  224. level for anything output to stdout or stderr.
  225. @param log_level: only log events that have level >= passed level
  226. are logged. This is achieved by setting the log level in
  227. each of the installed handlers.
  228. @param capture_stderr_log_level: log level for output captured from stdout.
  229. @param capture_stdout_log_level: log level for output captured from stderr.
  230. @param capture_stderr_name: log name used for stderr. 'name'
  231. refers to the name arg passed to logging.getLogger(name).
  232. @param capture_stdout_name: log name used for stdout. Analogous to capture_stderr_name.
  233. """
  234. logger = logging.getLogger('')
  235. logger.setLevel(DEBUG) # we use log handler levels to control output level.
  236. formatter = BTLFormatter("%(asctime)s - %(name)s - %(process)d - "
  237. "%(levelname)s - %(message)s", use_localtime=use_localtime)
  238. if log_file is not None:
  239. lf_handler = logging.handlers.RotatingFileHandler(filename=log_file,
  240. mode='a',
  241. maxBytes=2**27,
  242. backupCount=10)
  243. lf_handler.setFormatter(formatter)
  244. lf_handler.setLevel(log_level)
  245. logger.addHandler(lf_handler)
  246. if use_syslog:
  247. sl_handler = SysLogHandler('/dev/log',
  248. facility=SysLogHandler.LOG_LOCAL0)
  249. #address = (SYSLOG_HOST, SYSLOG_PORT))
  250. # namespace - pid - level - message
  251. sl_handler.setFormatter(BTLFormatter("%(name)s - %(process)d - "
  252. "%(levelname)s - %(message)s"))
  253. sl_handler.setLevel(log_level)
  254. logger.addHandler(sl_handler)
  255. if verbose:
  256. # StreamHandler does not capture stdout, it directs output from
  257. # loggers to stdout.
  258. so_handler = logging.StreamHandler(sys.stdout)
  259. so_handler.setFormatter(formatter)
  260. so_handler.setLevel(log_level)
  261. logger.addHandler(so_handler)
  262. if capture_output:
  263. sys.stdout = StdioPretender( capture_stdout_name, capture_stdout_log_level )
  264. sys.stderr = StdioPretender( capture_stderr_name, capture_stderr_log_level )
  265. if log_twisted:
  266. twisted_logger.start(error_log_level = twisted_error_log_level,
  267. info_log_level = twisted_info_log_level)
  268. if __name__ == '__main__':
  269. from BTL.greenlet_yielddefer import coroutine, like_yield
  270. @coroutine
  271. def test_rate_limited_logger():
  272. injectLogger(verbose = True)
  273. log = RateLimitedLogger(logging.getLogger("myapp"), 1,1)
  274. log.info( "should be printed." )
  275. log.info( "should not be printed" ) # but should log "discard" message.
  276. log.info( "also should not be printed" ) # should not logging of discard message.
  277. df = Deferred()
  278. reactor.callLater(3, df.callback, True)
  279. like_yield(df)
  280. log.info( "should also be printed" )
  281. reactor.stop()
  282. def test_injectLogger():
  283. injectLogger(log_file = "your.log", use_syslog=False, verbose=True)
  284. logger = logging.getLogger("myapp")
  285. logger.warning("You are awesome")
  286. print 'stdout!'
  287. print >>sys.stderr, 'stderr!'
  288. from twisted.internet import reactor
  289. from twisted.python import failure
  290. def foo():
  291. reactor.stop()
  292. zuul = dana
  293. reactor.callLater(0, foo)
  294. def test_injectLogger2():
  295. injectLogger(log_file = "your.log", verbose=False, capture_output=True)
  296. print "hello world"
  297. def foo():
  298. reactor.stop()
  299. zuul = dana
  300. reactor.callLater(0, foo)
  301. #test_injectLogger()
  302. test_injectLogger2()
  303. #reactor.callLater(0, test_rate_limited_logger)
  304. reactor.run()