bitpanda-labs / loggo2

Open source Python logging utilities
MIT License
4 stars 12 forks source link

Module decoration? #77

Closed interrogator closed 4 years ago

interrogator commented 5 years ago

So it turns out it is fairly possible to decorate entire third party modules (with about 20 additional lines of code). Here is an example of what happens if you log everything that happens while building a pandas dataframe:

In [1]: from loggo import Loggo                                                                                                      

In [2]: import pandas as pd                                                                                                          

In [3]: loggo = Loggo({'do_print': True})                                                                                            
    29.05 2019 15:56:04 Graylog not configured! Disabling it    30

Graylog not configured! Disabling it

In [4]: lp = loggo(pd)                                                                                                               

In [5]: df = lp.DataFrame(list(range(2, 20)))                                                                                        
    29.05 2019 15:56:18 *Called DatetimeTZDtype.construct_from_string(string=[2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19])  20
    29.05 2019 15:56:18 *Errored during DatetimeTZDtype.construct_from_string(string=[2, 3, 4, 5, 6, 7, 8, 9, 10, 11, 12, 13, 14, 15, 16, 17, 18, 19]) with TypeError "Could not construct DatetimeTZDtype" 20 -- see below: 
Traceback (most recent call last):
  File "/home/dannio/work/loggo/loggo/loggo.py", line 314, in full_decoration
    response = function(*args, **kwargs)
  File "/home/dannio/.local/lib/python3.6/site-packages/pandas/core/dtypes/dtypes.py", line 701, in construct_from_string
    raise TypeError("Could not construct DatetimeTZDtype")
TypeError: Could not construct DatetimeTZDtype

    29.05 2019 15:56:18 *Called RangeIndex._validate_dtype(dtype=None)  20
    29.05 2019 15:56:18 *Returned None from RangeIndex._validate_dtype(dtype=None)  20
    29.05 2019 15:56:18 *Called RangeIndex._simple_new(start=0, stop=18, step=1, protected_name=None)   20
    29.05 2019 15:56:18 *Called Index._reset_identity() 20
    29.05 2019 15:56:18 *Called RangeIndex._format_data()   20
    29.05 2019 15:56:18 *Returned None from RangeIndex._format_data()   20
    29.05 2019 15:56:18 *Called RangeIndex._format_attrs()  20
    29.05 2019 15:56:18 *Called RangeIndex._get_data_as_items() 20
    29.05 2019 15:56:18 *Returned from RangeIndex._get_data_as_items() with list ([('start', 0), ('stop', 18), ('step', 1)])20
    29.05 2019 15:56:18 *Returned from RangeIndex._format_attrs() with list ([('start', 0), ('stop', 18), ('step', 1)]) 20
    29.05 2019 15:56:18 *Called Index._format_space()   20
    29.05 2019 15:56:18 *Returned from Index._format_space() with str (' ') 20
    29.05 2019 15:56:18 *Returned from Index._reset_identity() with RangeIndex (RangeIndex(start=0, stop=18, step=1))   20
    29.05 2019 15:56:18 *Called RangeIndex._format_data()   20
    29.05 2019 15:56:18 *Returned None from RangeIndex._format_data()   20
    29.05 2019 15:56:18 *Called RangeIndex._format_attrs()  20
    29.05 2019 15:56:18 *Called RangeIndex._get_data_as_items() 20
    29.05 2019 15:56:18 *Returned from RangeIndex._get_data_as_items() with list ([('start', 0), ('stop', 18), ('step', 1)])20
    29.05 2019 15:56:18 *Returned from RangeIndex._format_attrs() with list ([('start', 0), ('stop', 18), ('step', 1)]) 20
    29.05 2019 15:56:18 *Called Index._format_space()   20
    29.05 2019 15:56:18 *Returned from Index._format_space() with str (' ') 20
    29.05 2019 15:56:18 *Returned from RangeIndex._simple_new(start=0, stop=18, step=1, protected_name=None) with RangeIndex (RangeIndex(start=0, stop=18, step=1)) 20
    29.05 2019 15:56:18 *Called RangeIndex._validate_dtype(dtype=None)  20
    29.05 2019 15:56:18 *Returned None from RangeIndex._validate_dtype(dtype=None)  20
    29.05 2019 15:56:18 *Called RangeIndex._simple_new(start=0, stop=1, step=1, protected_name=None)    20
    29.05 2019 15:56:18 *Called Index._reset_identity() 20
    29.05 2019 15:56:18 *Called RangeIndex._format_data()   20
    29.05 2019 15:56:18 *Returned None from RangeIndex._format_data()   20
    29.05 2019 15:56:18 *Called RangeIndex._format_attrs()  20
    29.05 2019 15:56:18 *Called RangeIndex._get_data_as_items() 20
    29.05 2019 15:56:18 *Returned from RangeIndex._get_data_as_items() with list ([('start', 0), ('stop', 1), ('step', 1)]) 20
    29.05 2019 15:56:18 *Returned from RangeIndex._format_attrs() with list ([('start', 0), ('stop', 1), ('step', 1)])  20
    29.05 2019 15:56:18 *Called Index._format_space()   20
    29.05 2019 15:56:18 *Returned from Index._format_space() with str (' ') 20
    29.05 2019 15:56:18 *Returned from Index._reset_identity() with RangeIndex (RangeIndex(start=0, stop=1, step=1))    20
    29.05 2019 15:56:18 *Called RangeIndex._format_data()   20
    29.05 2019 15:56:18 *Returned None from RangeIndex._format_data()   20
    29.05 2019 15:56:18 *Called RangeIndex._format_attrs()  20
    29.05 2019 15:56:18 *Called RangeIndex._get_data_as_items() 20
    29.05 2019 15:56:18 *Returned from RangeIndex._get_data_as_items() with list ([('start', 0), ('stop', 1), ('step', 1)]) 20
    29.05 2019 15:56:18 *Returned from RangeIndex._format_attrs() with list ([('start', 0), ('stop', 1), ('step', 1)])  20
    29.05 2019 15:56:18 *Called Index._format_space()   20
    29.05 2019 15:56:18 *Returned from Index._format_space() with str (' ') 20
    29.05 2019 15:56:18 *Returned from RangeIndex._simple_new(start=0, stop=1, step=1, protected_name=None) with RangeIndex (RangeIndex(start=0, stop=1, step=1))   20
    29.05 2019 15:56:18 *Called IntervalDtype.is_dtype(dtype=dtype('int64'))    20
    29.05 2019 15:56:18 *Returned from IntervalDtype.is_dtype(dtype=dtype('int64')) with bool (False)   20
    29.05 2019 15:56:18 *Called PeriodDtype.is_dtype(dtype=dtype('int64'))  20
    29.05 2019 15:56:18 *Returned from PeriodDtype.is_dtype(dtype=dtype('int64')) with bool (False) 20

Right now doing some further operations with the dataframe can cause stack overflow (lol), but probably because i'm recursively decorating everything with Loggo. It should be possible to fix this so everything callable is decorated exactly once. But ... is it worth it?

gcarq commented 5 years ago

This is pretty cool! Its definitely useful as a quick way to examine the code path of a 3rd party library. I'm not sure if there is a use-case for production code though, because most major modules have good logging of its own

interrogator commented 5 years ago

Yeah, that's kind of what I'm thinking, it's cool, and could be useful for exploring a third party library ... but at the same time, not sure how useful exactly.

The plus side, is it's only a few lines of code, you just add an inspect.ismodule(decorated_thing) and recursively apply loggo decorators to its classes, methods and functions. Right now, some edge cases cause it to break though, and if it isn't robust, we can't include it.

So, I will try a little more to get it working, but yeah, we're not there yet. Working on this I think actually helps me uncover some other possible bugs, so it's not gonna be time wasted :)

interrogator commented 4 years ago

This is cool but never gonna go anywhere, so closing.