Permalink
Browse files

handle logging exceptions when stack missing

  • Loading branch information...
1 parent 28efad5 commit 0bab3a9d415297802b02f9b1fbebc801107b5edf @newbrough newbrough committed Sep 25, 2012
Showing with 266 additions and 13 deletions.
  1. +1 −1 setup.py
  2. +24 −1 src/ooi/logging/configure.py
  3. +63 −11 src/ooi/logging/format.py
  4. +53 −0 src/ooi/testing.py
  5. +35 −0 src/ooi/timer.py
  6. +74 −0 test/ooi/test_merge.py
  7. +16 −0 test/ooi/test_testing.py
View
@@ -1,7 +1,7 @@
from distutils.core import setup
setup(name='utilities',
- version='2012.9.13.15',
+ version='2012.9.25',
author='Jonathan Newbrough',
author_email='jonathan.newbrough@gyregroup.com',
url='https://github.com/newbrough/utilities',
@@ -29,9 +29,20 @@ def oh_please_make_it_stop():
class _LoggingConfiguration(object):
+ debug = False
current_config = {}
+ def set_debug(self, value=True):
+ """print all calls to public methods"""
+ self.debug = value
+
def add_configuration(self, configuration):
+ if self.debug:
+ print 'DEBUG LOGGING: add_configuration: %r\nStack trace:' % configuration
+ self._print_caller()
+
+ if not configuration:
+ return # no config = no-op
if isinstance(configuration, dict):
self._add_dictionary(self.current_config, configuration)
logging.config.dictConfig(self.current_config)
@@ -52,10 +63,16 @@ def replace_configuration(self, configuration):
self.add_configuration(configuration)
def set_level(self, scope, level):
+ if self.debug:
+ print 'DEBUG LOGGING: set_level: %s: %s\nStack trace:' % (scope,level)
+ self._print_caller()
config = { 'loggers': { scope: {'level':level }}}
self.add_configuration(config)
def set_all_levels(self, level):
+ if self.debug:
+ print 'DEBUG LOGGING: set_all_levels: %s\nStack trace:' % level
+ self._print_caller()
changes = {}
for scope in self.current_config['loggers'].keys():
changes[changes] = {'level':level}
@@ -94,5 +111,11 @@ def add_filter(self, filter):
ooi.logging.log._add_filter(filter)
def set_logging_fields(self, thread_local_fields, constant_fields):
+ """WARNING: calling multiple times is currently additive -- will not replace fields"""
filter = logger.AddFields(thread_local_fields, constant_fields)
- self.add_filter(filter)
+ self.add_filter(filter)
+
+ def _print_caller(self):
+ """ display stack when enabled """
+ import traceback
+ print '\n'.join(['%s:%d %s'%(f,l,c) for f,l,m,c in traceback.extract_stack()])
View
@@ -4,6 +4,7 @@
import ooi.exception
import sys
+
class StackFormatter(logging.Formatter):
""" logging formatter that:
- displays exception stack traces one line per frame, with aligned columns
@@ -38,16 +39,20 @@ def set_filename_width(self, width):
self._format_string = '%%%ds:%%-7d%%s'%width #ie- "%40s:%-7d%s" --> .../path/to/filename.py:123 line.of_code()
def formatException(self, record):
- type,ex,tb = sys.exc_info()
- # use special exception logging only for IonExceptions with more than one saved stack
- if isinstance(ex, ooi.exception.ApplicationException):
- stacks = ex.get_stacks()
- else:
- stacks = [ ('exception: '+str(ex), traceback.extract_tb(tb) if tb else None) ]
- lines = []
- for label,stack in stacks:
- lines += self.format_stack(label, stack)
- return '\n'.join(lines)
+ try:
+ type,ex,tb = sys.exc_info()
+ # use special exception logging only for IonExceptions with more than one saved stack
+ if isinstance(ex, ooi.exception.ApplicationException):
+ stacks = ex.get_stacks()
+ else:
+ stacks = [ ('exception: '+str(ex), traceback.extract_tb(tb) if tb else None) ]
+ lines = []
+ for label,stack in stacks:
+ lines += self.format_stack(label, stack)
+ return '\n'.join(lines)
+ except Exception,e:
+ print 'WARNING: StackFormatter could not dislay stack: %s (submitting to default formatter)' % e
+ return super(logging.Formatter,self).formatException(self,record)
def format_stack(self, label, stack):
first_stack = label=='__init__' # skip initial label -- start output with first stack frame
@@ -70,6 +75,7 @@ def filter_frames(self, first_stack, stack):
"""
return stack
+
class RawRecordFormatter(logging.Formatter):
""" non-readable formatter that encodes all record fields to store for later processing.
to re-read the file later, define a function "handle_raw" and exec the log entries.
@@ -78,4 +84,50 @@ def format(self, record):
if record.exc_info and not record.exc_text:
record.exc_text = self.formatException(record.exc_info)
record.exc_info = None
- return 'handle_record_dict(' + repr(record.__dict__) + ')\n'
+ return 'handle_record_dict(' + repr(record.__dict__) + ')\n'
+
+
+class FieldFormatter(logging.Formatter):
+ """ display special values added by AddField filter.
+ useful for debugging extra fields added via the threadlocal mechanism
+ without having to use graylog to see them.
+
+ create with logging.yml:
+
+ formatter:
+ (): ooi.logging.format.FieldFormatter
+ fields: threadID,userName,conversationID
+
+ and set these fields in code:
+
+ from ooi.logging import config
+ config.set_logging_fields( {'call':'conversationID'}, {'userName':'bob'} )
+
+ and set the thread-local parts
+
+ import threading
+ x = threading.local()
+ x.call = 'abc'
+
+ from ooi.logging import log
+ log.warning('pop goes the weasel')
+
+ should produce this output:
+
+ <date,time,level,etc> threadID?? userName=bob conversationID=abc: pop goes the weasel
+ """
+
+ def __init__(self, fields,*a,**b):
+ super(logging.Formatter,self).__init__(*a,**b)
+ self.fields = ','.split(fields)
+
+ def format(self, record):
+ line = ''
+ for field in self.fields:
+ if hasattr(record,field):
+ line += '%s: %s '%(field,getattr(record,field))
+ else:
+ line += '%s?? '%field
+ line += ': ' + record.message
+ record.message = line
+ return super(logging.Formatter,self).format(record)
View
@@ -0,0 +1,53 @@
+"""
+testing utilities
+"""
+
+import unittest
+import os
+import os.path
+
+class ImportTest(unittest.TestCase):
+ """
+ unit test that attempts to import every python file beneath the base directory given.
+ fail if any can not be imported
+ """
+ def __init__(self, source_directory, base_package,*a,**b):
+ """
+ @param source_directory: should be something in the PYTHONPATH
+ @param base_package: top-level package to start recursive search in (or list of them)
+ @param a, b: pass-through from unittest.main() to TestCase.__init__()
+ """
+ super(ImportTest,self).__init__(*a,**b)
+ self.source_directory = source_directory
+ self.base_package = base_package
+
+ def test_can_import(self):
+ failures = []
+
+ packages = self.base_package if isinstance(self.base_package,list) else [ self.base_package ]
+ for pkg in packages:
+ pkg_dir = pkg.replace('.','/')
+ self._import_below(pkg_dir, pkg, failures)
+ if failures:
+ self.fail(msg='failed to import these modules:\n' + '\n'.join(failures))
+
+ def _import_below(self, dir, mod, failures):
+ subdir = os.path.join(self.source_directory, dir)
+ for entry in os.listdir(subdir):
+ path = os.path.join(subdir, entry)
+ # each python script (except init), try to import
+ if os.path.isfile(path) and entry.endswith('.py') and entry!='__init__.py':
+ try:
+ submod = mod + '.' + entry[:-3]
+ __import__(submod)
+ except Exception,e:
+ failures.append(submod + '\t' + str(e))
+ # each new subpackage import and recurse
+ elif os.path.isdir(path) and os.path.isfile(os.path.join(path,'__init__.py')) and entry!='test':
+ submod = mod + '.' + entry
+ try:
+ __import__(submod)
+ except Exception,e:
+ failures.append(submod + '\t' + str(e))
+ continue
+ self._import_below(os.path.join(dir,entry), submod, failures)
View
@@ -0,0 +1,35 @@
+"""
+record time taken for code to peform several steps
+"""
+
+import time
+import logging
+
+class Timer(object):
+ def __init__(self, name, milliseconds=True):
+ self.log = logging.getLogger('timing.'+name)
+ self.times = []
+ self.next_step("")
+ self.multiplier = 1000 if milliseconds else 1
+
+ def next_step(self, *lbl):
+ label = lbl[1] if lbl else None
+ self.times.append((label, time.time()))
+
+ def last_step(self, *lbl):
+ self.next_step(*lbl)
+ self._log()
+
+ def _log(self):
+ if self.log.isEnabledFor(logging.DEBUG):
+ previous_step = self.times[0][1]
+ message = 'elapsed %f:' % self.multiplier*(self.times[:-1][1]-previous_step)
+ for tuple in self.times[1:]:
+ message += ' '
+ if tuple[0]:
+ message += tuple[0]+'='
+ this_step = tuple[1]
+ delta = self.multiplier*(this_step-previous_step)
+ message += '%f' % delta
+ previous_step = this_step
+ self.log.debug(message)
View
@@ -0,0 +1,74 @@
+
+import ooi.testing
+from ooi.exception import ApplicationException
+from unittest.case import TestCase
+import unittest
+
+class TargetException(ApplicationException):
+ def __init__(self):
+ super(TargetException,self).__init__()
+ self.drop_chained_init_frame()
+
+class TestException(TestCase, ooi.testing.ImportTest):
+ def __init__(self):
+ TestCase.__init__(self, methodName='runTest')
+ ooi.testing.ImportTest.__ini__(self, os.path.join(os.path.dirname(os.path.dirname(os.path.dirname(__name__))),'src'), 'ooi')
+
+ def willRaiseGeneric(self):
+ return 1/0
+ def willRaiseTarget(self):
+ raise TargetException()
+ def willRaiseCaused(self):
+ try:
+ self.willRaiseGeneric()
+ except Exception,e:
+ raise TargetException()
+ def willRaiseCausedIndirect(self):
+ try:
+ self.willRaiseGeneric()
+ except Exception,e:
+ self.willRaiseTarget()
+
+ def testTargetOnly(self):
+ #""" make sure ApplicationException captures stack when thrown """
+ caught = None
+ try:
+ self.willRaiseTarget()
+ except Exception,e:
+ caught = e
+
+ self.assertTrue(isinstance(caught, TargetException), msg="exception is %s"%caught.__class__.__name__)
+ self.assertTrue(caught.get_stack())
+ self.assertEqual(caught.get_stack()[-1][2], "willRaiseTarget", msg=caught.get_stack()[-1][2])
+
+ def testCause(self):
+ caught = None
+ try:
+ self.willRaiseCaused()
+ except Exception,e:
+ caught = e
+
+ self.assertTrue(isinstance(caught, TargetException))
+
+ self.assertTrue(caught.get_cause())
+ self.assertTrue(caught.get_cause_stack())
+ self.assertEqual(caught.get_stack()[-1][2], "willRaiseCaused", msg='raised at '+repr(caught.get_stack()))
+ self.assertEqual(caught.get_cause_stack()[-1][2], "willRaiseGeneric", msg='caused by '+repr(caught.get_cause_stack()))
+
+ def testIndirect(self):
+ caught = None
+ try:
+ self.willRaiseCausedIndirect()
+ except Exception,e:
+ caught = e
+
+ self.assertTrue(isinstance(caught, TargetException))
+
+ self.assertTrue(caught.get_cause())
+ self.assertTrue(caught.get_cause_stack())
+ self.assertEqual(caught.get_stack()[-1][2], "willRaiseTarget", msg='raised at '+repr(caught.get_stack()))
+ self.assertEqual(caught.get_cause_stack()[-1][2], "willRaiseGeneric", msg='caused by '+repr(caught.get_cause_stack()))
+
+
+if __name__ == '__main__':
+ unittest.main()
View
@@ -0,0 +1,16 @@
+
+import os
+from unittest import TestCase,main
+import ooi.testing
+import __main__
+
+class TestOOIImports(ooi.testing.ImportTest):
+ def __init__(self,*a,**b):
+ # for utilities project only, want to search in BASE/src
+ # but this test is in BASE/test/ooi
+ # so have to go up two levels, then down to src
+ target_dir = os.path.join(os.path.dirname(os.path.dirname(os.path.dirname(__file__))),'src')
+ super(TestOOIImports,self).__init__(target_dir, 'ooi', *a, **b)
+
+if __name__ == '__main__':
+ main()

0 comments on commit 0bab3a9

Please sign in to comment.