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

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

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

Why should you use logging?

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)

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)

Avoid NIH

Configurable Destinations Files Rotating Files Logging Email In-Memory Buffer Syslog Console HTTP Web Service Socket TCP, UDP Windows NT Event Log Watched Files

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

Filterable Content

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

Logging Levels DEBUG INFO WARNING ERROR CRITICAL

namespaces

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

The Logging Lexicon

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

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

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

Root Logger

propagate = True?

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

Double Logging?

incremental = True?

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

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

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

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

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

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

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*

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

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}}}

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

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

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

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

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  

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

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

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

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

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)  

No content

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)  

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'}

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

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

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

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

AMQPHandler?

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

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

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

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

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)

level=INFO, debug 3.3

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)

level=DEBUG, debug 3.3

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

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

What to do?

Use Debug* #  *  But  check  if  your  app  is  in  debug  mode  first if  debug:        LOGGER.debug('Has  stairs  in  their  house:  %r',                                  is_protected)

Moderation in all things

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

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

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/