Back to index

moin  1.9.0~rc2
replaylog.py
Go to the documentation of this file.
00001 #!/usr/bin/env python
00002 #
00003 # Copyright (C) 2007 Lemur Consulting Ltd
00004 #
00005 # This program is free software; you can redistribute it and/or modify
00006 # it under the terms of the GNU General Public License as published by
00007 # the Free Software Foundation; either version 2 of the License, or
00008 # (at your option) any later version.
00009 #
00010 # This program is distributed in the hope that it will be useful,
00011 # but WITHOUT ANY WARRANTY; without even the implied warranty of
00012 # MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
00013 # GNU General Public License for more details.
00014 # 
00015 # You should have received a copy of the GNU General Public License along
00016 # with this program; if not, write to the Free Software Foundation, Inc.,
00017 # 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
00018 r"""replaylog.py: Log all xapian calls to a file, so that they can be replayed.
00019 
00020 """
00021 __docformat__ = "restructuredtext en"
00022 
00023 import datetime
00024 import sys
00025 import thread
00026 import threading
00027 import time
00028 import traceback
00029 import types
00030 import weakref
00031 import xapian
00032 
00033 from pprint import pprint
00034 
00035 # The logger in use.
00036 _replay_log = None
00037 
00038 # True if a replay log has ever been in use since import time.
00039 _had_replay_log = False
00040 
00041 class NotifyingDeleteObject(object):
00042     """An wrapping for an object which calls a callback when its deleted.
00043 
00044     Note that the callback will be called from a __del__ method, so shouldn't
00045     raise any exceptions, and probably shouldn't make new references to the
00046     object supplied to it.
00047 
00048     """
00049     def __init__(self, obj, callback):
00050         self.obj = obj
00051         self.callback = callback
00052 
00053     def __del__(self):
00054         self.callback(self.obj)
00055 
00056 class ReplayLog(object):
00057     """Log of xapian calls, to be replayed.
00058 
00059     """
00060 
00061     def __init__(self, logpath):
00062         """Create a new replay log.
00063 
00064         """
00065         # Mutex used to protect all access to _fd
00066         self._fd_mutex = threading.Lock()
00067         self._fd = file(logpath, 'wb')
00068 
00069         # Mutex used to protect all access to members other than _fd
00070         self._mutex = threading.Lock()
00071         self._next_call = 1
00072 
00073         self._next_thread = 0
00074         self._thread_ids = {}
00075 
00076         self._objs = weakref.WeakKeyDictionary()
00077         self._next_num = 1
00078 
00079         self._xapian_classes = {}
00080         self._xapian_functions = {}
00081         self._xapian_methods = {}
00082         for name in dir(xapian):
00083             item = getattr(xapian, name)
00084             has_members = False
00085             for membername in dir(item):
00086                 member = getattr(item, membername)
00087                 if isinstance(member, types.MethodType):
00088                     self._xapian_methods[member.im_func] = (name, membername)
00089                     has_members = True
00090             if has_members:
00091                 self._xapian_classes[item] = name
00092             if isinstance(item, types.BuiltinFunctionType):
00093                 self._xapian_functions[item] = name
00094 
00095     def _get_obj_num(self, obj, maybe_new):
00096         """Get the number associated with an object.
00097 
00098         If maybe_new is False, a value of 0 will be supplied if the object
00099         hasn't already been seen.  Otherwise, a new (and previously unused)
00100         value will be allocated to the object.
00101 
00102         The mutex should be held when this is called.
00103 
00104         """
00105         try:
00106             num = self._objs[obj]
00107             return num.obj
00108         except KeyError:
00109             pass
00110 
00111         if not maybe_new:
00112             return 0
00113 
00114         self._objs[obj] = NotifyingDeleteObject(self._next_num, self._obj_gone)
00115         self._next_num += 1
00116         return self._next_num - 1
00117 
00118     def _is_xap_obj(self, obj):
00119         """Return True iff an object is an instance of a xapian object.
00120 
00121         (Also returns true if the object is an instance of a subclass of a
00122         xapian object.)
00123 
00124         The mutex should be held when this is called.
00125 
00126         """
00127         # Check for xapian classes.
00128         classname = self._xapian_classes.get(type(obj), None)
00129         if classname is not None:
00130             return True
00131         # Check for subclasses of xapian classes.
00132         for classobj, classname in self._xapian_classes.iteritems():
00133             if isinstance(obj, classobj):
00134                 return True
00135         # Not a xapian class or subclass.
00136         return False
00137 
00138     def _get_xap_name(self, obj, maybe_new=False):
00139         """Get the name of a xapian class or method.
00140 
00141         The mutex should be held when this is called.
00142 
00143         """
00144         # Check if it's a xapian class, or subclass.
00145         if isinstance(obj, types.TypeType):
00146             classname = self._xapian_classes.get(obj, None)
00147             if classname is not None:
00148                 return classname
00149 
00150             for classobj, classname in self._xapian_classes.iteritems():
00151                 if issubclass(obj, classobj):
00152                     return "subclassof_%s" % (classname, )
00153 
00154             return None
00155 
00156         # Check if it's a xapian function.
00157         if isinstance(obj, types.BuiltinFunctionType):
00158             funcname = self._xapian_functions.get(obj, None)
00159             if funcname is not None:
00160                 return funcname
00161 
00162         # Check if it's a proxied object.
00163         if isinstance(obj, LoggedProxy):
00164             classname = self._xapian_classes.get(obj.__class__, None)
00165             if classname is not None:
00166                 objnum = self._get_obj_num(obj, maybe_new=maybe_new)
00167                 return "%s#%d" % (classname, objnum)
00168 
00169         # Check if it's a proxied method.
00170         if isinstance(obj, LoggedProxyMethod):
00171             classname, methodname = self._xapian_methods[obj.real.im_func]
00172             objnum = self._get_obj_num(obj.proxyobj, maybe_new=maybe_new)
00173             return "%s#%d.%s" % (classname, objnum, methodname)
00174 
00175         # Check if it's a subclass of a xapian class.  Note: this will only
00176         # pick up subclasses, because the original classes are filtered out
00177         # higher up.
00178         for classobj, classname in self._xapian_classes.iteritems():
00179             if isinstance(obj, classobj):
00180                 objnum = self._get_obj_num(obj, maybe_new=maybe_new)
00181                 return "subclassof_%s#%d" % (classname, objnum)
00182 
00183         return None
00184 
00185     def _log(self, msg):
00186         self._fd_mutex.acquire()
00187         try:
00188 #            msg = '%s,%s' % (
00189 #                datetime.datetime.fromtimestamp(time.time()).isoformat(),
00190 #                msg,
00191 #            )
00192             self._fd.write(msg)
00193             self._fd.flush()
00194         finally:
00195             self._fd_mutex.release()
00196 
00197     def _repr_arg(self, arg):
00198         """Return a representation of an argument.
00199 
00200         The mutex should be held when this is called.
00201 
00202         """
00203 
00204         xapargname = self._get_xap_name(arg)
00205         if xapargname is not None:
00206             return xapargname
00207 
00208         if isinstance(arg, basestring):
00209             if isinstance(arg, unicode):
00210                 arg = arg.encode('utf-8')
00211             return 'str(%d,%s)' % (len(arg), arg)
00212 
00213         if isinstance(arg, long):
00214             try:
00215                 arg = int(arg)
00216             except OverFlowError:
00217                 pass
00218 
00219         if isinstance(arg, long):
00220             return 'long(%d)' % arg
00221 
00222         if isinstance(arg, int):
00223             return 'int(%d)' % arg
00224 
00225         if isinstance(arg, float):
00226             return 'float(%f)' % arg
00227 
00228         if arg is None:
00229             return 'None'
00230 
00231         if hasattr(arg, '__iter__'):
00232             seq = []
00233             for item in arg:
00234                 seq.append(self._repr_arg(item))
00235             return 'list(%s)' % ','.join(seq)
00236 
00237         return 'UNKNOWN:' + str(arg)
00238 
00239     def _repr_args(self, args):
00240         """Return a representation of a list of arguments.
00241 
00242         The mutex should be held when this is called.
00243 
00244         """
00245         logargs = []
00246         for arg in args:
00247             logargs.append(self._repr_arg(arg))
00248         return ','.join(logargs)
00249 
00250     def _get_call_id(self):
00251         """Get an ID string for a call.
00252 
00253         The mutex should be held when this is called.
00254 
00255         """
00256         call_num = self._next_call
00257         self._next_call += 1
00258 
00259         thread_id = thread.get_ident()
00260         try:
00261             thread_num = self._thread_ids[thread_id]
00262         except KeyError:
00263             thread_num = self._next_thread
00264             self._thread_ids[thread_id] = thread_num
00265             self._next_thread += 1
00266 
00267         if thread_num is 0:
00268             return "%s" % call_num
00269         return "%dT%d" % (call_num, thread_num)
00270 
00271     def log_call(self, call, *args):
00272         """Add a log message about a call.
00273 
00274         Returns a number for the call, so it can be tied to a particular
00275         result.
00276 
00277         """
00278         self._mutex.acquire()
00279         try:
00280             logargs = self._repr_args(args)
00281             xapobjname = self._get_xap_name(call)
00282             call_id = self._get_call_id()
00283         finally:
00284             self._mutex.release()
00285 
00286         if xapobjname is not None:
00287             self._log("CALL%s:%s(%s)\n" % (call_id, xapobjname, logargs))
00288         else:
00289             self._log("CALL%s:UNKNOWN:%r(%s)\n" % (call_id, call, logargs))
00290         return call_id
00291 
00292     def log_except(self, (etype, value, tb), call_id):
00293         """Log an exception which has occurred.
00294 
00295         """
00296         # No access to an members, so no need to acquire mutex.
00297         exc = traceback.format_exception_only(etype, value)
00298         self._log("EXCEPT%s:%s\n" % (call_id, ''.join(exc).strip()))
00299 
00300     def log_retval(self, ret, call_id):
00301         """Log a return value.
00302 
00303         """
00304         if ret is None:
00305             self._log("RET%s:None\n" % call_id)
00306             return
00307 
00308         self._mutex.acquire()
00309         try:
00310             # If it's a xapian object, return a proxy for it.
00311             if self._is_xap_obj(ret):
00312                 ret = LoggedProxy(ret)
00313                 xapobjname = self._get_xap_name(ret, maybe_new=True)
00314             msg = "RET%s:%s\n" % (call_id, self._repr_arg(ret))
00315         finally:
00316             self._mutex.release()
00317 
00318         # Not a xapian object - just return it.
00319         self._log(msg)
00320         return ret
00321 
00322     def _obj_gone(self, num):
00323         """Log that an object has been deleted.
00324 
00325         """
00326         self._log('DEL:#%d\n' % num)
00327 
00328 class LoggedProxy(object):
00329     """A proxy for a xapian object, which logs all calls made on the object.
00330 
00331     """
00332     def __init__(self, obj):
00333         self.__obj = obj
00334 
00335     def __getattribute__(self, name):
00336         obj = object.__getattribute__(self, '_LoggedProxy__obj')
00337         if name == '__obj':
00338             return obj
00339         real = getattr(obj, name)
00340         if not isinstance(real, types.MethodType):
00341             return real
00342         return LoggedProxyMethod(real, self)
00343 
00344     def __iter__(self):
00345         obj = object.__getattribute__(self, '_LoggedProxy__obj')
00346         return obj.__iter__()
00347 
00348     def __len__(self):
00349         obj = object.__getattribute__(self, '_LoggedProxy__obj')
00350         return obj.__len__()
00351 
00352     def __repr__(self):
00353         obj = object.__getattribute__(self, '_LoggedProxy__obj')
00354         return '<LoggedProxy of %s >' % obj.__repr__()
00355 
00356     def __str__(self):
00357         obj = object.__getattribute__(self, '_LoggedProxy__obj')
00358         return obj.__str__()
00359 
00360 class LoggedProxyMethod(object):
00361     """A proxy for a xapian method, which logs all calls made on the method.
00362 
00363     """
00364     def __init__(self, real, proxyobj):
00365         """Make a proxy for the method.
00366 
00367         """
00368         self.real = real
00369         self.proxyobj = proxyobj
00370 
00371     def __call__(self, *args):
00372         """Call the proxied method, logging the call.
00373 
00374         """
00375         return log(self, *args)
00376 
00377 def set_replay_path(logpath):
00378     """Set the path for the replay log.
00379 
00380     """
00381     global _replay_log
00382     global _had_replay_log
00383     if logpath is None:
00384         _replay_log = None
00385     else:
00386         _had_replay_log = True
00387         _replay_log = ReplayLog(logpath)
00388 
00389 def _unproxy_call_and_args(call, args):
00390     """Convert a call and list of arguments to unproxied form.
00391 
00392     """
00393     if isinstance(call, LoggedProxyMethod):
00394         realcall = call.real
00395     else:
00396         realcall = call
00397 
00398     realargs = []
00399     for arg in args:
00400         if isinstance(arg, LoggedProxy):
00401             arg = arg.__obj
00402         realargs.append(arg)
00403 
00404     return realcall, realargs
00405 
00406 def log(call, *args):
00407     """Make a call to xapian, and log it.
00408 
00409     """
00410     # If we've never had a replay log in force, no need to unproxy objects.
00411     global _had_replay_log
00412     if not _had_replay_log:
00413         return call(*args)
00414 
00415     # Get unproxied versions of the call and arguments.
00416     realcall, realargs = _unproxy_call_and_args(call, args)
00417 
00418     # If we have no replay log currently, just do the call.
00419     global _replay_log
00420     replay_log = _replay_log
00421     if replay_log is None:
00422         return realcall(*realargs)
00423 
00424     # We have a replay log: do a logged version of the call.
00425     call_id = replay_log.log_call(call, *args)
00426     try:
00427         ret = realcall(*realargs)
00428     except:
00429         replay_log.log_except(sys.exc_info(), call_id)
00430         raise
00431     return replay_log.log_retval(ret, call_id)
00432 
00433 #set_replay_path('replay.log')