#!/usr/bin/env python
#
# trace.py - debugging functions
#
# Author: Paul McCarthy <pauldmccarthy@gmail.com>
#
"""This module provides some useful logging/debugging functions.
.. warning:: This module is not intended for general use - it is solely for
development/debugging purposes. Do not use it unless you know
know what you are doing.
.. warning:: When this module is imported, it monkey patches the
:class:`.CallQueue` class in a devious and dangerous manner to
allow for more informative debug statements. Therefore it's a
bad idea to even import this module, unless you really know what
you are doing.
.. warning:: Just don't import this module, ok?
The functions provided by this module are as follows:
.. autosummary::
trace
setcause
propchange
"""
import logging
import inspect
import os.path as op
log = logging.getLogger(__name__)
# If trace debugging is enabled, we're going to
# do some funky stuff to the props callqueue
# object, so we can get some extra information
# in the propchange function.
if log.getEffectiveLevel() == logging.DEBUG:
log.debug('Monkey-patching fsleyes_props.properties_value.queue instance')
import fsleyes_props as props
import queue
# The problem that I am addressing here is the
# fact that, when a property value listener is
# called, the cause of the call (i.e. the point
# at which the property value was changed) does
# not necessarily exist in the stack. This is
# because when a PV instance passes all of its
# listeners to the CallQueue (CQ) to call, the
# CQ will queue them immediately, but will not
# necessarily call them - they are only called
# if the CQ is not already processing the
# listeners from another PV change.
# A single CallQueue instance is shared
# by all PropertyValue instances to queue/
# call property value listeners.
theQ = props.properties_value.PropertyValue.queue
def tracePop(*args, **kwargs):
# When the CallQueue calls its _pop
# method, it will call the returned
# function. For debugging purposes,
# we'll pop the associated cause
# (enqueued in the tracePush function
# below), so the propchange function
# can print it out.
#
# This will throw Queue.EmptyError if
# the _causes queue is empty, but
# that is what the real _pop method
# does anyway.
try: theQ._currentCause = theQ._causes.get_nowait()
except: theQ._currentCause = None
return theQ._realPop(*args, **kwargs)
def tracePush(*args, **kwargs):
pushed = theQ._realPush(*args, **kwargs)
# If the real _push method returns False,
# it means that the function was not enqueued
if not pushed:
return False
frames = inspect.stack()[1:]
# We search for the first frame in the stack
# which is not in the props package - this
# will be the point of the PV change which
# caused this listener to be enqueued
triggerFrame = None
for frame in frames:
if 'fsleyes_props' not in frame[1]:
triggerFrame = frame
break
# This should never happen,
# but in case it does, we
# put a dummy value into
# the causes queue, so it
# is the same length as the
# reall call queue
if triggerFrame is None:
theQ._causes.put_nowait(None)
# Store the cause of the listener
# push on the causes queue
else:
cause = [triggerFrame[1],
triggerFrame[2],
triggerFrame[3]]
if triggerFrame[4] is not None:
cause.append(triggerFrame[4][triggerFrame[5]])
else:
cause.append('<input>')
theQ._causes.put_nowait(cause)
return True
# Patch the CallQueue instance with
# our push/pop implementations
theQ._causes = queue.Queue()
theQ._realPush = theQ._CallQueue__push
theQ._realPop = theQ._CallQueue__pop
theQ._CallQueue__push = tracePush
theQ._CallQueue__pop = tracePop
[docs]
def trace(desc):
"""Outputs a log message containing the given description and the current
stack trace.
"""
if log.getEffectiveLevel() != logging.DEBUG:
return
stack = inspect.stack()[1:]
lines = '{}\n'.format(desc)
for i, frame in enumerate(stack):
srcMod = frame[1]
srcLineNo = frame[2]
if frame[4] is not None: srcLine = frame[4][frame[5]]
else: srcLine = '<native>'
lines = lines + '{}{}:{}: {}\n'.format(
' ' * (i + 1),
srcMod, srcLineNo,
srcLine.strip())
log.debug(lines)
return lines
[docs]
def propchange(*args):
"""Intended to be called from a :class:`.PropertyValue` listener
function.
If this function is called due to a change, attempts to determine the line
of code which triggered the change. Prints some informative log messages.
:arg args: The arguments that were passed to the listener function.
"""
if log.getEffectiveLevel() != logging.DEBUG:
return
import fsleyes_props as props
theQ = props.properties_value.PropertyValue.queue
stack = inspect.stack()
listenerFile = stack[1][1]
listenerLine = stack[1][2]
listenerFunc = stack[1][3]
triggerFile = None
if len(args) != 4:
triggerFile = stack[2][1]
triggerLine = stack[2][2]
triggerFunc = stack[2][3]
triggerSrc = stack[2][4][stack[2][5]]
else:
triggerFile = theQ._currentCause[0]
triggerLine = theQ._currentCause[1]
triggerFunc = theQ._currentCause[2]
triggerSrc = theQ._currentCause[3]
if triggerFile is None:
log.debug('Listener {} ({}:{}) was called '
'due to an unknown process'.format(
listenerFunc,
op.basename(listenerFile),
listenerLine))
else:
if len(args) != 4:
reason = 'manually called from'
else:
value, valid, ctx, name = args
reason = 'called due to a value change of {}.{} ({}) at'.format(
type(ctx).__name__,
name,
value)
log.debug('Listener {} ({}:{}) was {} '
'{} ({}:{}:{})'.format(
listenerFunc,
op.basename(listenerFile),
listenerLine,
reason,
triggerFunc,
op.basename(triggerFile),
triggerLine,
triggerSrc.strip()))
[docs]
def setcause(desc):
"""I can't quite remember the difference betwen this function and the
:func:`propchange` function.
"""
if log.getEffectiveLevel() != logging.DEBUG:
return
stack = inspect.stack()[1:]
causeFrame = None
ultCauseFrame = None
for i, frame in enumerate(stack):
if 'fsleyes_props' not in frame[1]:
causeFrame = frame
break
if causeFrame is not None:
for i, frame in reversed(list(enumerate(stack))):
if 'fsleyes_props' in frame[1]:
ultCauseFrame = stack[i + 1]
break
if causeFrame is None:
log.debug('{}: Unknown cause'.format(desc))
else:
causeFile = causeFrame[1]
causeLine = causeFrame[2]
causeFunc = causeFrame[3]
causeSrc = causeFrame[4][causeFrame[5]]
line = '{}: Caused by {} ({}:{}:{})'.format(
desc,
causeFunc,
op.basename(causeFile),
causeLine,
causeSrc.strip())
if ultCauseFrame is not None:
causeFile = ultCauseFrame[1]
causeLine = ultCauseFrame[2]
causeFunc = ultCauseFrame[3]
causeSrc = ultCauseFrame[4][ultCauseFrame[5]]
line = '{} (ultimately caused by {} ({}:{}:{})'.format(
line,
causeFunc,
op.basename(causeFile),
causeLine,
causeSrc.strip())
log.debug(line)