Upgrade to Pro — share decks privately, control downloads, hide ads and more …

Become a Logging Expert in 30 Minutes

Become a Logging Expert in 30 Minutes

If used correctly, the logging module is a great tool for gathering information about the runtime state of your application. For example, when an application is under development or experiencing problems, the DEBUG level is extremely useful if leveraged, but normally can be information overload. In this talk I will demonstrate how an application can provide multiple levels of instrumentation with logging and deliver the data via different channels such as syslog, automatically rotating log files or over other protocols such as AMQP.

Gavin M. Roy

March 17, 2013
Tweet

More Decks by Gavin M. Roy

Other Decks in Programming

Transcript

  1. We’re Hiring! • Senior Architects • API Engineering Team •

    Android • iOS • Web Front-End • DevOps Engineers • Network Engineers
  2. 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)
  3. 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)
  4. Configurable Destinations Files Rotating Files Logging Email In-Memory Buffer Syslog

    Console HTTP Web Service Socket TCP, UDP Windows NT Event Log Watched Files
  5. 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
  6. 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
  7. Log Records • Used to build the logged messages, route

    them and filter them • Hold all attributes about the message
  8. 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
  9. 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
  10. Dangerous Behavior If loggers are already configured, incremental=True will not

    change pre-existing configuration for formatters or filters
  11. 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
  12. 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
  13. 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
  14. 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
  15. 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
  16. 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*
  17. 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
  18. 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}}}
  19. 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
  20. Using a YAML config import logging.config import yaml config =

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

    due to auto-string interpolation • Somewhat more verbose than a YAML format
  22. 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
  23. 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  
  24. 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())  
  25. 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
  26. 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
  27. stdlib Handlers • StreamHandler • FileHandler • SyslogHandler • WatchedFileHandler

    • RotatingFileHandler • TimedRotatingFileHandler • NTEventLogHandler • SocketHandler (TCP) • DatagramHandler (UDP) • SMTPHandler • MemoryHandler • HTTPHandler • NullHandler
  28. 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)  
  29. 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)  
  30. 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'}
  31. Example Custom Handler Proof of concept application: • Handler with

    a rotating log buffer • Tornado web application to view log entries
  32. 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
  33. 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
  34. Baseline Profile def fib(n): a, b = 0, 1 while

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

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

    much better or if things are that much more complex
  37. 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)
  38. 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)
  39. 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
  40. Use Debug* #  *  But  check  if  your  app  is

     in  debug  mode  first if  debug:        LOGGER.debug('Has  stairs  in  their  house:  %r',                                  is_protected)
  41. 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
  42. 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/