mahmoud/lithoxyl

Application instrumentation and logging, with a geological bent.

lithoxyl's Issues

Test lithoxyl/tests/test_stats.py::test_momentacc_norm is dependent on the random seed

If adding random.seed(0) to the beginning of test lithoxyl/tests/test_stats.py::test_momentacc_norm, and running pytest lithoxyl/tests/test_stats.py::test_momentacc_norm, you will see this error message:

____________________________________________________________________ test_momentacc_norm ____________________________________________________________________

    def test_momentacc_norm():
        random.seed(0)
        ma = MomentAccumulator()
        for v in [random.gauss(10, 4) for i in range(5000)]:
            ma.add(v)
        _assert_round_cmp(10, abs(ma.mean), mag=1)
        _assert_round_cmp(4, ma.std_dev, mag=1)
>       _assert_round_cmp(0, ma.skewness, mag=1)

lithoxyl/tests/test_stats.py:49: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

a = 0, b = 0.07368173837804089, mag = 1, name = None

    def _assert_round_cmp(a, b, mag=3, name=None):
        thresh = 1.0 / (10 ** mag)
        abs_diff = round(abs(a - b), mag + 1)
        tmpl = 'round-compare failed at %d digits (%f - %f = %f > %f)'
        rel_diff = (2 * abs_diff) / (a + b)
        err_msg = tmpl % (mag, a, b, abs_diff, thresh)
        if name:
            err_msg = '%r %s' % (name, err_msg)
>       assert rel_diff < thresh, err_msg
E       AssertionError: round-compare failed at 1 digits (0.000000 - 0.073682 = 0.070000 > 0.100000)
E       assert 1.9000637482478797 < 0.1

IMHO, the current way to assert that the skewness is close to 0 is not reasonable, because it in fact asserts that 2*round(skewness,2)<0.1*skewness, which is only true when skewness<0.005 and round(skewness,2)=0. However, the skewness of 5000 random samples can often be greater than 0.005.

The example usage in the docs for SensibleSink doesn't seem to work

I took the example code from here and put some boilerplate code around it:

from lithoxyl import Logger
app_log = Logger("myapp")


from lithoxyl import (SensibleFilter,
                      SensibleFormatter,
                      StreamEmitter,
                      SensibleSink)

# Create a filter that controls output verbosity
fltr = SensibleFilter(success='critical',
                      failure='info',
                      exception='debug')

# Create a simple formatter with just two bits of info:
# The time since startup/import and end event message.
# These are just two of the built-in "fields",
# and the syntax is new-style string formatting syntax.
fmtr = SensibleFormatter('+{import_delta_s} - {end_message}')

# Create an emitter to write to stderr. 'stdout' and open file objects
# also behave predictably.
emtr = StreamEmitter('stderr')

# Tie them all together. Note that filters accepts an iterable
sink = SensibleSink(filters=[fltr], formatter=fmtr, emitter=emtr)

# Add the sink to app_log, a vanilla Logger created above
app_log.add_sink(sink)


with app_log.info("Main code"):
    pass

The resulting code, when run, produces no output. It doesn't matter if I use app_log.critical, still no output.

It's quite possible I'm doing something wrong here - I could find no "complete" examples of how to use SensibleSink - but at a minimum I think the documentation should include a fully working example.

This is using Python 3.9 on Windows 10, with the version of lithoxy from PyPI (20.0.0) in case it matters. I also tried with Python 3.8 and 3.7, just in case, and got the same result.

make wrap_all more robust

First: wrapping builtins (e.g. setattr from object) raises exceptions

        File "/services/shopkick_pylons/shopkick_pylons-current/py/lib/python2.6/site-packages/boltons/funcutils.py", line 488, in from_func
             'module': func.__module__,
        AttributeError: 'wrapper_descriptor' object has no attribute '__module__'

Probably the way to fix is to add a filter for hasattr('module').

Second: wrapping @staticmethod breaks because the descriptor protocol that elides off the self parameter gets "erased" in the wrapped function

A bunch of different ways to fix

Finally, it would be convenient if the skip function could take the object itself as well as the name in order to work-around these issues and any other unanticipated ones. (Maybe parameters similar to descriptor protocol get / set for the skip argument to wrap_all?

Need examples of Action.warn etc.

I'm trying to refactor some code that uses the standard logging.getLogger to use lithoxyl and I'm a bit stuck without some more examples comparing the old style with the new.

In particular, how should I go about converting code that looks like:

logger.info('starting some process')
logger.debug('intermediate result %d', a)
logger.debug('another intermediate result %s', b)
logger.info('complete')

Logging the start/finish is fine, but I'm stuck on the "right" way to log the intermediate results. Should they just be assigned to Action's data:

with app_log.info('process') as act:
    act['intermediate result'] = a
    act.success()

That feels a bit clunky as the resulting repr of the data in the log line is pretty unreadable and out of order.

Or can warn be used? It doesn't seem quite like it does what I want as it has a different level than the Action and it's not outputting how I would expect.

with app_log.info('process') as act:
    act.warn('intermediate result %d', a)
    act.success()

Provide diagnostic context

The examples you give in the README are not exactly equivalent, namely the lithoxyl one drops the user name. This is an improved variant:

from lithoxyl import stderr_log

def create_user(name):
    with stderr_log.critical('user creation', context=name, reraise=False) as r:
        success = _create_user()
        if not success:
            r.failure()

How to log arbitrary output

Hi, I just found this project, and I love the approach it takes to logging - in particular the idea of building instrumentation in from the design stage. But there's one thing I can't see how to handle, which is to integrate "unstructured" output into the logs.

To give an example, in pip[1] we build a project by calling the build system in a subprocess. So in a lithoxyl style of code, we'd do something like (highly simplified, obviously):

def build_project(proj):
    with log.critical("Extracting sources"):
        build_dir = get_temp_location()
        proj.extract_source_to(build_dir)
    with log.critical("Building project"):
        proc = subprocess.run([sys.executable, 'setup.py', 'bdist_wheel'], capture_output=True)
        # subprocess output is in proc.output

However, we capture the output of the subprocess, and we want to display it only when there's an error. Ideally, output would be something like:

... Extracting sources succeeded
... Building project failed
subprocess output goes here
with whatever formatting the build process used
    preserved
    intact
for the user to diagnose the issue

Note that I don't really want things like timestamps on the subprocess output, as that makes no sense (we didn't log the output in "real time" so the timestamps would be misleading rather than helpful).

Alternatively, there are cases where I'd log the subprocess output in real time. In those cases, I'd be OK with timestamp-style data, but conversely I'd want the display of the data to be tied to the success or failure of the enclosing action, so the output is only displayed if the build action doesn't succeed (which is obviously complicated by the fact that the output has been generated before we know whether we're going to want to display it).

Is there a way to do this?

[1] BTW, there's no plan that I know of to switch to using lithoxyl with pip, but it's a good example of the type of problem I face frequently.

TypeError: unhashable type: 'Level'

Hi! I'm getting this exception during the import of lithoxyl:

In [1]: import lithoxyl
---------------------------------------------------------------------------
TypeError                                 Traceback (most recent call last)
<ipython-input-1-222423bc74ab> in <module>()
----> 1 import lithoxyl

/env/lib/python3.6/site-packages/lithoxyl/__init__.py in <module>()
      3 from lithoxyl.context import get_context, set_context
      4
----> 5 from lithoxyl.logger import Logger, DEBUG, INFO, CRITICAL
      6 from lithoxyl.emitters import StreamEmitter
      7

/env/lib/python3.6/site-packages/lithoxyl/logger.py in <module>()
     15
     16 from lithoxyl.context import get_context
---> 17 from lithoxyl.common import DEBUG, INFO, CRITICAL
     18 from lithoxyl.action import Action, BeginEvent, EndEvent, CommentEvent
     19

/env/lib/python3.6/site-packages/lithoxyl/common.py in <module>()
     65 LEVEL_LIST = []
     66 LEVEL_ALIAS_MAP = {}
---> 67 register_level(MIN_LEVEL)
     68 register_level(MAX_LEVEL)
     69 for level in BUILTIN_LEVELS:

/env/lib/python3.6/site-packages/lithoxyl/common.py in register_level(level_obj)
     59     LEVEL_ALIAS_MAP[level_obj.name.upper()] = level_obj
     60     LEVEL_ALIAS_MAP[level_obj._value] = level_obj
---> 61     LEVEL_ALIAS_MAP[level_obj] = level_obj
     62     LEVEL_LIST[:] = sorted(set(LEVEL_ALIAS_MAP.values()))
     63

TypeError: unhashable type: 'Level'

$ python --version
Python 3.6.4

$ pip freeze | grep lithoxyl
lithoxyl==0.4.1