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.

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