Become a Logging Expert in 30 Minutes by Gavin M. Roy

Become a Logging Expert in 30 Minutes by Gavin M. Roy

The logging module is one of the more complex areas of the Python standard library. In this talk you will learn how to leverage loggers, formatters, handlers and filters. In addition you will learn how to use dictConfig and other formats to manage logging settings for your applications.

Afcfefa1f067d10bd021de0cc2e5e806?s=128

PyCon 2013

March 17, 2013
Tweet

Transcript

  1. Become a Logging Expert in 30 Minutes Gavin M. Roy

    @crad
  2. We’re Hiring! • Senior Architects • API Engineering Team •

    Android • iOS • Web Front-End • DevOps Engineers • Network Engineers
  3. https://github.com/gmr/pycon2013-logging

  4. Why should you use logging?

  5. Common Pattern? try:        if  debug:    

               print'Executing  query:  %s'  %  query        self.cursor.execute(query)                                           except  psycopg2.OperationalError,  e:        sys.stderr.write('PostgreSQL  Error:  %s'  %  e[0])        sys.exit(1)                                 except  psycopg2.IntegrityError,  e:        sys.stderr.write('PostgreSQL  Error:  %r'  %  e[0])        return  False                         except  Exception,  e:        sys.stderr.write('Unhandled  Exception:  %r'  %  e[0])        sys.exit(1)
  6. Consistent Output Method try:        logger.DEBUG('Executing  query:  %s',

     query)        cursor.execute(query)                                           except  psycopg2.OperationalError  as  error:        logger.CRITICAL('PostgreSQL  Exception:  %s',  error)        sys.exit(1)                                 except  psycopg2.IntegrityError  as  error:        logger.ERROR('PostgreSQL  Data  Error:  %s',  error)        return  False                         except  Exception  as  exception:        logger.CRITICAL('Unhandled  Exception:  %s',  exception)        sys.exit(1)
  7. Avoid NIH

  8. Configurable Destinations Files Rotating Files Logging Email In-Memory Buffer Syslog

    Console HTTP Web Service Socket TCP, UDP Windows NT Event Log Watched Files
  9. Configurable Formatting • Standard string- formatting options • Many attributes

    available • Per destination conditional formatting
  10. Filterable Content

  11. Easy to use API for: • Debugging your application •

    Providing runtime state information • Triggering alerts upon specific conditions • Sharing application data and information with external services
  12. Logging Levels DEBUG INFO WARNING ERROR CRITICAL

  13. namespaces

  14. Using for writing Packages • Common, well-documented methods and tools

    for configuration • Users can control the level of information they want/need • Reduces the amount of code • Ensure your package is more Pythonic and plays well with others
  15. The Logging Lexicon

  16. Log Records • Used to build the logged messages, route

    them and filter them • Hold all attributes about the message
  17. Loggers • The logger is the first actor to decide

    if a message should be distributed to assigned handlers • Point of entry for all logged messages • Provides destination for namespaced logged messages
  18. The Object to Use •debug(msg,  *args,  **kwargs) •info(msg,  *args,  **kwargs)

    •warning(msg,  *args,  **kwargs) •error(msg,  *args,  **kwargs) •exception(msg,  *args)* * Logs at ERROR level and should be called only by exception handlers
  19. Root Logger

  20. propagate = True?

  21. foo.bar.baz when Propagate is True: apply to everything under foo

  22. Double Logging?

  23. incremental = True?

  24. Dangerous Behavior If loggers are already configured, incremental=True will not

    change pre-existing configuration for formatters or filters
  25. Handlers • Deliver messages to their destination • Also filterable

    by level and filter • Can have multiple per application • Assigned to loggers • Can have multiple per logger as well • Assigned a formatter and any filters
  26. Formatters • Use for destination specific formatting • One formatter

    can be assigned to multiple handlers • Responsible for merging internal values • Uses Python %-style mapping keys to LogRecord attributes
  27. Example Formats %(levelname)s %(asctime)s %(module)s.%(funcName)s() (%(lineno)d): %(message)s INFO  2013-­‐03-­‐16  17:01:34

     web.log_request()  (1462):  200  GET  /  (::1)  0.41ms INFO  2013-­‐03-­‐16  17:01:34  web.log_request()  (1462):  200  GET  /  (::1)  0.33ms INFO  2013-­‐03-­‐16  17:02:02  web.log_request()  (1462):  200  GET  /  (127.0.0.1)  0.39ms INFO  2013-­‐03-­‐16  17:02:03  web.log_request()  (1462):  200  GET  /  (127.0.0.1)  0.27ms %(levelname)s <PID %(process)d:%(processName)s> %(name)s.%(funcName)s(): %(message)s <PID  69849:MainProcess>  root.log_request():  200  GET  /  (127.0.0.1)  0.53ms <PID  69849:MainProcess>  root.log_request():  200  GET  /  (127.0.0.1)  0.37ms <PID  69849:MainProcess>  root.log_request():  200  GET  /  (127.0.0.1)  0.27ms <PID  69849:MainProcess>  root.log_request():  200  GET  /  (127.0.0.1)  0.42ms
  28. Log Adapters • Build custom adapters to inject additional information

    not available to formatters by default • Add context, simplify logger calls • Same signature as a Logger, passed a logger on construction • Use like a Logger
  29. Filters • Applied to Loggers • Base class filters on

    namespace • Example limiting logging to only items in the foo.bar.baz namespace:  filter  =  logging.Filter('content')  logger.addFilter(filter) • Can be extended for your own purposes
  30. Configuration Options • 4 configuration options: • Manually in code

    • Very limiting, code change to alter configuration • Dictionary based configuration (2.7+) • File based configuration • Socket listener configuration*
  31. DictConfig • Allows for configuration to be passed in using

    a dict format • Great for structured config data, such as configuration stored in JSON or YAML • Can be very verbose
  32. DictConfig Example {'version': 1, 'disable_existing_loggers': True, 'incremental': False, 'filters': [],

    'formatters': {'syslog': {'format': '%(levelname)s <PID %(process)d> ' '%(name)s.%(funcName)s(): %(message)s'}, 'verbose': {'datefmt': '%Y-%m-%d %H:%M:%S', 'format': '%(levelname) -10s %(asctime)s ' '%(processName) -35s %(name) -35s ' '%(funcName) -30s: %(message)s'}}, 'handlers': {'console': {'class': 'logging.StreamHandler', 'debug_only': False, 'formatter': 'verbose'}, 'syslog': {'address': '/var/run/syslog', 'class': 'logging.handlers.SysLogHandler', 'facility': 'daemon', 'formatter': 'syslog'}}, 'loggers': {'django': {'handlers': ['console', 'syslog'], 'level': 'ERROR', 'propagate': False}, 'psycopg2': {'handlers': ['console', 'syslog'], 'level': 'INFO', 'propagate': True}}}
  33. DictConfig YAML Example Logging: formatters: brief: format: "%(levelname)s <PID %(process)d:%(processName)s>

    %(name)s.% (funcName)s(): %(message)s" filters: [] handlers: console: class: logging.StreamHandler formatter: brief syslog: class: logging.handlers.SysLogHandler facility: daemon address: /dev/log formatter: brief loggers: django: propagate: true level: WARNING handlers: [console, syslog] psycopg2: propagate: false level: ERROR handlers: [console, syslog] disable_existing_loggers: true incremental: false version: 1
  34. Using a YAML config import logging.config import yaml config =

    yaml.load(open('config.yaml', 'r')) logging.config.dictConfig(config)
  35. FileConfig • ConfigParser formatted configuration files • Can’t use SafeConfigParser

    due to auto-string interpolation • Somewhat more verbose than a YAML format
  36. FileConfig Example [loggers] keys  =  myapp   [logger_myapp] level  =

     INFO handlers  =  syslog propagate  =  1 qualname  =  myapp   [handlers] keys  =  syslog   [handler_syslog] class  =  handlers.SysLogHandler formatter  =  brief args  =  ('/dev/log',  handlers.SysLogHandler.LOG_LOCAL6)   [formatters] keys  =  brief   [formatter_brief] format  =  <PID  %(process)d:%(processName)s>  %(name)s.%(funcName)s():  %(message)s
  37. Logging Config Listener #!/usr/bin/env  python   import  logging   import

     logging.config   import  time     logging.basicConfig(level=logging.INFO)     #  Listen  on  default  port  of  9030,  is  a  thread   listener  =  logging.config.listen()   listener.start()     logger  =  logging.getLogger('listener')     start_time  =  time.time()   while  True:          logger.info('Time  since  start:  %.2f',  time.time()  -­‐  start_time)          try:                  time.sleep(1)          except  KeyboardInterrupt:                  logging.config.stopListening()                  break  
  38. Send to Listener #!/usr/bin/env  python   import  logging.config   import

     socket   import  struct     HOST  =  'localhost'   PORT  =  logging.config.DEFAULT_LOGGING_CONFIG_PORT    #  9030       def  send_conf(config_text):          s  =  socket.socket(socket.AF_INET,  socket.SOCK_STREAM)          s.connect((HOST,  PORT))          s.send(struct.pack('>L',  len(config_text)))          s.send(config_text)          s.close()     with  open('logging.conf',  'r')  as  handle:          send_conf(handle.read())  
  39. logger.cfg [loggers]   keys  =  root,  listener   [logger_listener]  

    level  =  INFO handlers  =  console propagate  =  1 qualname  =  listener   [logger_root]   level  =  WARNING handlers  =  console,  syslog propagate  =  1   [handlers]   keys  =  console,  syslog   [handler_console]   class  =  StreamHandler formatter  =  brief args  =  () stream  =  (ext://sys.stdout)   [handler_syslog] class  =  handlers.SysLogHandler formatter  =  brief args  =  ('/dev/log',  handlers.SysLogHandler.LOG_LOCAL6)   [formatters] keys  =  brief   [formatter_brief] format  =  <PID  %(process)d:%(processName)s>  %(name)s.%(funcName)s():  %(message)s
  40. Output Before  calling  send-­‐config-­‐to-­‐listener.py INFO:listener:Time  since  start:  0.00 INFO:listener:Time  since

     start:  1.00 INFO:listener:Time  since  start:  2.00 After  calling  send-­‐config-­‐to-­‐listener.py <PID  18289:MainProcess>  listener.<module>():  Time  since  start:  3.00 <PID  18289:MainProcess>  listener.<module>():  Time  since  start:  3.00 <PID  18289:MainProcess>  listener.<module>():  Time  since  start:  4.00 <PID  18289:MainProcess>  listener.<module>():  Time  since  start:  4.00
  41. stdlib Handlers • StreamHandler • FileHandler • SyslogHandler • WatchedFileHandler

    • RotatingFileHandler • TimedRotatingFileHandler • NTEventLogHandler • SocketHandler (TCP) • DatagramHandler (UDP) • SMTPHandler • MemoryHandler • HTTPHandler • NullHandler
  42. Using SMTPHandler #!/usr/bin/env  python   import  logging   from  logging

     import  handlers   import  socket   import  traceback     HOST  =  'localhost'   FROM  =  '"APPLICATION  ALERT"  <python@your-­‐domain>'   TO  =  'you@your-­‐domain'   SUBJECT  =  'New  Critical  Event  From  [APPLICATION]'     logging.basicConfig(level=logging.INFO)     handler  =  handlers.SMTPHandler(HOST,  FROM,  TO,  SUBJECT)   email_logger  =  logging.getLogger('smtp.example')   email_logger.addHandler(handler)   email_logger.setLevel  =  logging.CRITICAL     logging.info('Root  logger  output')   try:          email_logger.critical('Critical  Event  Notification\n\nTraceback:\n  %s',                                                      ''.join(traceback.format_stack()))   except  socket.error  as  error:          logging.critical('Could  not  send  email  via  SMTPHandler:  %r',  error)  
  43. None
  44. Using HTTPHandler #!/usr/bin/env  python   import  logging   from  logging

     import  handlers   import  socket   import  traceback     HOST  =  'localhost'   PORT  =  8888     logging.basicConfig(level=logging.INFO)     handler  =  handlers.HTTPHandler('%s:%s'  %  (HOST,  PORT),  '/')   http_logger  =  logging.getLogger('http.example')   http_logger.addHandler(handler)   http_logger.setLevel  =  logging.CRITICAL     logging.info('Root  logger  output')   try:          http_logger.critical('Critical  Event  Notification\n\nTraceback:\n  %s',                                                    ''.join(traceback.format_stack()))   except  socket.error  as  error:          logging.critical('Could  not  deliver  message  via  HTTPHandler:  %r',  error)  
  45. HTTPHandler Request Data {'args':  '(\'    File  "http_handler-­‐example.py",  line  21,

     in  <module>\\n        '                  '\\\'\\\'.join(traceback.format_stack()))\\n\',)',    'created':  '1363542183.32',    'exc_info':  'None',    'exc_text':  'None',    'filename':  'http_handler-­‐example.py',    'funcName':  '<module>',    'levelname':  'CRITICAL',    'levelno':  '50',    'lineno':  '21',    'module':  'http_handler-­‐example',    'msecs':  '316.456079483',    'msg':  'Critical  Event  Notification\n\nTraceback:\n  %s',    'name':  'http.example',    'pathname':  'http_handler-­‐example.py',    'process':  '13948',    'processName':  'MainProcess',    'relativeCreated':  '12.0251178741',    'thread':  '140735278571904',    'threadName':  'MainThread'}
  46. Example Custom Handler Proof of concept application: • Handler with

    a rotating log buffer • Tornado web application to view log entries
  47. class  BufferedLogHandler(handlers.BufferingHandler):          def  emit(self,  record):  

                   self.buffer.append(self.format(record))                  while  len(''.join(self.buffer))  >=  self.capacity:                          self.buffer.remove(0)   Custom Logging Handler
  48. class WebRequestHandler(web.RequestHandler): def get(self): handler = self.application.log_handler self.write({'entries': handler.buffer}) if

    self.get_argument('flush', False): handler.flush() Tornado Request Handler
  49. if  __name__  == '__main__':            logging.basicConfig(level=logging.INFO)

             routes  =  [(r'.*',  WebRequestHandler)])          application  =  web.Application(routes)        application.listen(8888)          application.log_handler  =  BufferedLogHandler(MAX)            root_logger  =  logging.getLogger()        root_logger.addHandler(application.log_handler)            ioloop.IOLoop.instance().start()   Setup & Start Application
  50. AMQPHandler?

  51. Logging Performance •Fibonacci Sequence •cProfile •Python 2.7.2 •Python 3.3.0 •Default

    Handler
  52. Baseline Profile def fib(n): a, b = 0, 1 while

    a < n: a, b = b, a+b fib(1000000) 2.7 3.3
  53. import logging 2.7 import logging def fib(n): a, b =

    0, 1 while a < n: a, b = b, a+b fib(1000000)
  54. import logging 3.3 I don’t know if cProfile is that

    much better or if things are that much more complex
  55. level=INFO, debug 2.7 import logging logger = logging.getLogger(__name__) logging.basicConfig(level=logging.INFO) def

    fib(n): a, b = 0, 1 while a < n: logger.debug(‘Value: %i’, a) a, b = b, a+b fib(1000000)
  56. level=INFO, debug 3.3

  57. level=DEBUG, debug 2.7 import logging logger = logging.getLogger(__name__) logging.basicConfig(level=logging.DEBUG) def

    fib(n): a, b = 0, 1 while a < n: logger.debug(‘Value: %i’, a) a, b = b, a+b fib(1000000)
  58. level=DEBUG, debug 3.3

  59. Logging Performance 0 ms 0.375 ms 0.75 ms 1.125 ms

    1.5 ms import level=INFO level=DEBUG 2.7 3.3 * Chart data at end of deck on slide #62
  60. Fibonacci Slowdown 2.7 3.3 import 0.78x 0.99x level=INFO 6.19x 9.48x

    level=DEBUG 195.26x 312.31x
  61. What to do?

  62. Use Debug* #  *  But  check  if  your  app  is

     in  debug  mode  first if  debug:        LOGGER.debug('Has  stairs  in  their  house:  %r',                                  is_protected)
  63. Moderation in all things

  64. https://github.com/gmr/pycon2013-logging Questions? Follow me on Twitter: @crad

  65. Logging Profiling Times Baseline Baseline import logging import logging level=INFO

    level=INFO level=DEBUG level=DEBUG 2.7 3.3 2.7 3.3 2.7 3.3 2.7 3.3 0.00001407 0.00000405 0.00000501 0.00000310 0.00003815 0.00003910 0.00117683 0.00132799 0.00000501 0.00000501 0.00000501 0.00000405 0.00004697 0.00006413 0.00112104 0.00135493 0.00000620 0.00000405 0.00000596 0.00000501 0.00003695 0.00003791 0.00110388 0.00130010 0.00000501 0.00000501 0.00000501 0.00000405 0.00003791 0.00003815 0.00111318 0.00131106 0.00000596 0.00000405 0.00000405 0.00000381 0.00003910 0.00003886 0.00192213 0.00132895 0.00000501 0.00000405 0.00000501 0.00000501 0.00003695 0.00003695 0.00119281 0.00132513 0.00000501 0.00000405 0.00000501 0.00000405 0.00003815 0.00003600 0.00111604 0.00132608 0.00000596 0.00000405 0.00000501 0.00000405 0.00003695 0.00003695 0.00113606 0.00129580 0.00000501 0.00000405 0.00000501 0.00000501 0.00003910 0.00003791 0.00112295 0.00132108 0.00000501 0.00000405 0.00000405 0.00000405 0.00003600 0.00003600 0.00116682 0.00135112 0.00000623 0.00000424 0.00000491 0.00000422 0.00003862 0.00004020 0.00121717 0.00132422
  66. Photo Credits • Slide #12 "Back on the Log Train"

    Claire L. Evans http://www.flickr.com/photos/ 10097505@N00/1492818224/ • Slide #44 "I'm a lumberjack and I'm ok..." Neil Kremer http://www.flickr.com/photos/ neilarmstrong2/