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

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.

PyCon 2013

March 17, 2013
Tweet

More Decks by PyCon 2013

Other Decks in Programming

Transcript

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

    View full-size slide

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

    View full-size slide

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

    View full-size slide

  4. Why should you use logging?

    View full-size 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 full-size 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 full-size slide

  7. 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 full-size slide

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

    View full-size slide

  9. Filterable Content

    View full-size slide

  10. 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 full-size slide

  11. Logging Levels
    DEBUG
    INFO
    WARNING
    ERROR
    CRITICAL

    View full-size slide

  12. 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 full-size slide

  13. The Logging Lexicon

    View full-size slide

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

    View full-size slide

  15. 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 full-size slide

  16. 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 full-size slide

  17. propagate = True?

    View full-size slide

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

    View full-size slide

  19. Double Logging?

    View full-size slide

  20. incremental = True?

    View full-size slide

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

    View full-size slide

  22. 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 full-size slide

  23. 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 full-size slide

  24. 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 full-size slide

  25. 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 full-size slide

  26. 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 full-size slide

  27. 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 full-size slide

  28. 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 full-size slide

  29. 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 full-size slide

  30. 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 full-size slide

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

    View full-size slide

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

    View full-size slide

  33. 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 full-size slide

  34. 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 full-size slide

  35. 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 full-size slide

  36. 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 full-size slide

  37. 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 full-size slide

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

    View full-size slide

  39. 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 full-size slide

  40. 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 full-size slide

  41. 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 full-size slide

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

    View full-size slide

  43. 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 full-size slide

  44. 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 full-size slide

  45. 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 full-size slide

  46. AMQPHandler?

    View full-size slide

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

    View full-size slide

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

    View full-size slide

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

    View full-size slide

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

    View full-size slide

  51. 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 full-size slide

  52. level=INFO, debug 3.3

    View full-size slide

  53. 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 full-size slide

  54. level=DEBUG, debug 3.3

    View full-size slide

  55. 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 full-size slide

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

    View full-size slide

  57. 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 full-size slide

  58. Moderation in all things

    View full-size slide

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

    View full-size slide

  60. 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 full-size slide

  61. 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 full-size slide