BUG: prospective fix for demotion filter ignoring handler log level

[ZLLentz]

Description

Apply log level redundantly in demotion filter

Motivation and Context

The expected effect of demotion filter is to drop the log level, but the log level is checked before the filter is run, so if the log record would have been dropped by the log level then we need to apply it retroactively.

The behavior of modifying the record on the way through is still needed for the cases where we have e.g. a demotion filter on a logger with log level not set that needs to propagate debug-level messages to a root logger that has leveled handlers

How Has This Been Tested?

Added tests that fail before my patch and pass afterwards

Where Has This Been Documented?

WIP

[klauer]

It may be worth caching the result of that check (but then again, that'd be premature optimization which I would normally say not to do...)

[ZLLentz]

I'm not immediately sure how to implement caching here, since the same filter can be applied to multiple loggers and multiple handlers.

[ZLLentz]

Five more seconds of thinking: mapping from logger name to cached object that has a log level?

[klauer]

You're right - caching makes much less sense than I thought it did on the initial read-through!

[ZLLentz]

Ok I'm finally getting back to this. I will open it for review and check that it actually works when run through a hutch-python build.

[ZLLentz]

Ok this has the intended effect in hutch-python sessions: the DEBUG messages do not come through to the console (unless we change the log level of the console to DEBUG).

In [1]: from ophyd import Signal

In [2]: sig = Signal(name='sig')

In [3]: def bad(**kwargs):
   ...:     1/0
   ...:

In [4]: sig.subscribe(bad)
Out[4]: 0

In [5]: sig.put(1)

In [6]: logs.debug_mode(debug=True)

In [7]: sig.put(2)
DEBUG    inner sig Subscription value callback exception (Signal(name='sig', value=2, timestamp=1643416238.7144418))
Traceback (most recent call last):
  File "/cds/home/z/zlentz/miniconda3/envs/dev/lib/python3.9/site-packages/ophyd/ophydobj.py", line 462, in inner
    cb(*args, **kwargs)
  File "<ipython-input-3-3a9d191e6347>", line 2, in bad
    1/0
ZeroDivisionError: division by zero

[klauer]

I think this looks good code-wise. How's it look from hutch-python? Looking good from hutch-python as well!

My only remaining fear is the unbounded log record .cache set, which admittedly isn't new to this PR. Need something like a bounded LRU set, which isn't as easy as it should be with the standard lib...

[ZLLentz]

Right, that's a good point. There's definitely a problem here, but only in cases where only_duplicates=True. It's possible for this cache to increase in an unbounded manner if the user is dynamically generating differing log messages and piping them through this filter. Imagine the extreme case where we maliciously do logger.debug(uuid.uuid4()) in a loop...