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.

Transcript

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

   View Slide

2. We’re Hiring!
   • Senior Architects
   • API Engineering Team
   • Android
   • iOS
   • Web Front-End
   • DevOps Engineers
   • Network Engineers
   

   View Slide

3. https://github.com/gmr/pycon2013-logging
   

   View Slide

4. Why should you use logging?
   

   View Slide

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)
   

   View Slide

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)
   

   View Slide

7. Avoid NIH
   

   View Slide

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
   

   View Slide

9. Configurable Formatting
   • Standard string-
   formatting options
   • Many attributes
   available
   • Per destination
   conditional formatting
   

   View Slide

10. Filterable Content
    

    View Slide

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
    

    View Slide

12. Logging Levels
    DEBUG
    INFO
    WARNING
    ERROR
    CRITICAL
    

    View Slide

13. namespaces
    

    View Slide

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
    

    View Slide

15. The Logging Lexicon
    

    View Slide

16. Log Records
    • Used to build the logged messages,
    route them and filter them
    • Hold all attributes about the message
    

    View Slide

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
    

    View Slide

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
    

    View Slide

19. Root Logger
    

    View Slide

20. propagate = True?
    

    View Slide

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

    View Slide

22. Double Logging?
    

    View Slide

23. incremental = True?
    

    View Slide

24. Dangerous
    Behavior
    If loggers are already
    configured, incremental=True
    will not change pre-existing
    configuration for formatters
    or filters
    

    View Slide

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
    

    View Slide

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
    

    View Slide

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 %(name)s.%(funcName)s(): %(message)s
     root.log_request():  200  GET  /  (127.0.0.1)  0.53ms
     root.log_request():  200  GET  /  (127.0.0.1)  0.37ms
     root.log_request():  200  GET  /  (127.0.0.1)  0.27ms
     root.log_request():  200  GET  /  (127.0.0.1)  0.42ms
    

    View Slide

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
    

    View Slide

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
    

    View Slide

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*
    

    View Slide

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
    

    View Slide

32. DictConfig Example
    {'version': 1,
    'disable_existing_loggers': True,
    'incremental': False,
    'filters': [],
    'formatters': {'syslog': {'format': '%(levelname)s '
    '%(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}}}
    

    View Slide

33. DictConfig YAML Example
    Logging:
    formatters:
    brief:
    format: "%(levelname)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
    

    View Slide

34. Using a YAML config
    import logging.config
    import yaml
    config = yaml.load(open('config.yaml', 'r'))
    logging.config.dictConfig(config)
    

    View Slide

35. FileConfig
    • ConfigParser formatted configuration
    files
    • Can’t use SafeConfigParser due to
    auto-string interpolation
    • Somewhat more verbose than a YAML
    format
    

    View Slide

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  =    %(name)s.%(funcName)s():  %(message)s
    

    View Slide

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  
    

    View Slide

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())  
    

    View Slide

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  =    %(name)s.%(funcName)s():  %(message)s
    

    View Slide

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
     listener.():  Time  since  start:  3.00
     listener.():  Time  since  start:  3.00
     listener.():  Time  since  start:  4.00
     listener.():  Time  since  start:  4.00
    

    View Slide

41. stdlib Handlers
    • StreamHandler
    • FileHandler
    • SyslogHandler
    • WatchedFileHandler
    • RotatingFileHandler
    • TimedRotatingFileHandler
    • NTEventLogHandler
    • SocketHandler (TCP)
    • DatagramHandler (UDP)
    • SMTPHandler
    • MemoryHandler
    • HTTPHandler
    • NullHandler
    

    View Slide

42. Using SMTPHandler
    #!/usr/bin/env  python  
    import  logging  
    from  logging  import  handlers  
    import  socket  
    import  traceback  
     
    HOST  =  'localhost'  
    FROM  =  '"APPLICATION  ALERT"  '  
    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)  
    

    View Slide

43. View Slide

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)  
    

    View Slide

45. HTTPHandler Request Data
    {'args':  '(\'    File  "http_handler-­‐example.py",  line  21,  in  \\n        '
                     '\\\'\\\'.join(traceback.format_stack()))\\n\',)',  
     'created':  '1363542183.32',  
     'exc_info':  'None',  
     'exc_text':  'None',  
     'filename':  'http_handler-­‐example.py',  
     'funcName':  '',  
     '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'}
    

    View Slide

46. Example Custom Handler
    Proof of concept application:
    • Handler with a rotating log buffer
    • Tornado web application to view log
    entries
    

    View Slide

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
    

    View Slide

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
    

    View Slide

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
    

    View Slide

50. AMQPHandler?
    

    View Slide

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

    View Slide

52. Baseline Profile
    def fib(n):
    a, b = 0, 1
    while a < n:
    a, b = b, a+b
    fib(1000000)
    2.7 3.3
    

    View Slide

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

    View Slide

54. import logging 3.3
    I don’t know if cProfile is
    that much better or if
    things are that much
    more complex
    

    View Slide

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)
    

    View Slide

56. level=INFO, debug 3.3
    

    View Slide

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)
    

    View Slide

58. level=DEBUG, debug 3.3
    

    View Slide

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
    

    View Slide

60. Fibonacci Slowdown
    2.7 3.3
    import 0.78x 0.99x
    level=INFO 6.19x 9.48x
    level=DEBUG 195.26x 312.31x
    

    View Slide

61. What to do?
    

    View Slide

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)
    

    View Slide

63. Moderation in all things
    

    View Slide

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

    View Slide

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
    

    View Slide

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/
    

    View Slide