feat: log decorator util - adding automatic logs out of the box

[ofekisr]

SUMMARY

When functions are implemented, they have a specific reason and responsible for change (SRP)
Writing logs is a different concern that is not related to the reason of the functions that logging statements were added to them.
In addition, writing logs imply code duplication (imagine writing the logs in the example)
and remember, logging is a cross-cutting concern so adding logging behavior is best used as AOP

That PR adds a log decorator ability so you can decorate a function or class and you'll get logging out of the box.

Right now as of POC I added and use it under tests.
After adding the decorator, for each public method that is called, new log records will be added.
In case the logger is configured as DEBUG, for each method call (whether is private or public) a new log will be added with the passed arguments and return value.

Example

from tests.common.logger_utils import log

@log
class PandasDataLoader(DataLoader):
    ...

@log
class TableToDfConvertorImpl(TableToDfConvertorI)
   ...

INFO     tests.example_data.data_loading.pandas.pandas_data_loader:logger_utils.py:119 enter to 'PandasDataLoader.load_table'
INFO     tests.example_data.data_loading.pandas.table_df_convertor:logger_utils.py:119 enter to 'TableToDfConvertorImpl.convert'

or

DEBUG    tests.example_data.data_loading.pandas.table_df_convertor:logger_utils.py:145 enter to 'TableToDfConvertorImpl.__init__' with: {'convert_ds_to_datetime': False, 'time_format': '%Y-%m-%d %H:%M:%S'}
DEBUG    tests.example_data.data_loading.pandas.pandas_data_loader:logger_utils.py:145 enter to 'PandasDataLoader.__init__' with: {'db_engine': Engine(mysql+mysqldb://superset:***@127.0.0.1:13306/superset?binary_prefix=true&charset=utf8mb4), 'config': <tests.example_data.data_loading.pandas.pands_data_loading_conf.PandasLoaderConfigurations object at 0x12785e670>, 'table_to_df_convertor': <tests.example_data.data_loading.pandas.table_df_convertor.TableToDfConvertorImpl object at 0x12785e3a0>}
DEBUG    tests.example_data.data_loading.pandas.pandas_data_loader:logger_utils.py:145 enter to 'PandasDataLoader.load_table' with: {'table': Table(table_name='birth_names', table_metadata=TableMetaData(table_name='birth_names', types={'ds': <class 'sqlalchemy.sql.sqltypes.DateTime'>, 'gender': String(length=16), 'name': String(length=255), 'num': <class 'sqlalchemy.sql.sqltypes.Integer'>, 'state': String(length=10), 'num_boys': <class 'sqlalchemy.sql.sqltypes.Integer'>, 'num_girls': <class 'sqlalchemy.sql.sqltypes.Integer'>}), data=<generator object BirthNamesGenerator.generate at 0x127a7ea50>)}
DEBUG    tests.example_data.data_loading.pandas.table_df_convertor:logger_utils.py:145 enter to 'TableToDfConvertorImpl.convert' with: {'table': Table(table_name='birth_names', table_metadata=TableMetaData(table_name='birth_names', types={'ds': <class 'sqlalchemy.sql.sqltypes.DateTime'>, 'gender': String(length=16), 'name': String(length=255), 'num': <class 'sqlalchemy.sql.sqltypes.Integer'>, 'state': String(length=10), 'num_boys': <class 'sqlalchemy.sql.sqltypes.Integer'>, 'num_girls': <class 'sqlalchemy.sql.sqltypes.Integer'>}), data=<generator object BirthNamesGenerator.generate at 0x127a7ea50>)}
DEBUG    tests.example_data.data_loading.pandas.table_df_convertor:logger_utils.py:150 enter to 'TableToDfConvertorImpl._should_convert_datetime_to_str'
DEBUG    tests.example_data.data_loading.pandas.table_df_convertor:logger_utils.py:156 exit from 'TableToDfConvertorImpl._should_convert_datetime_to_str' with return value: 'False'
DEBUG    tests.example_data.data_loading.pandas.table_df_convertor:logger_utils.py:156 exit from 'TableToDfConvertorImpl.convert' with return value: '             ds gender        name    num state  num_boys  num_girls
0    1960-01-01    boy        asoq  86721    KY     86721          0
1    1960-01-01    boy     bdycsfn  31088    TX     31088          0
2    1960-01-01    boy      xbojgx  65611    MA     65611          0
3    1960-01-01    boy    awaahduh  26394    CA     26394          0
4    1960-01-01   girl       hgvei  11012    MT         0      11012
...         ...    ...         ...    ...   ...       ...        ...
1195 2019-01-01   girl        bwty  78079    VT         0      78079
1196 2019-01-01   girl   irwcwcsol  20513    CO         0      20513
1197 2019-01-01   girl  hjpuvonlmv   1093    FL         0       1093
1198 2019-01-01   girl     cjikohg  27274    KY         0      27274
1199 2019-01-01   girl    fpuvnstv  91479    MO         0      91479
[1200 rows x 7 columns]'
DEBUG    tests.example_data.data_loading.pandas.pandas_data_loader:logger_utils.py:145 enter to 'PandasDataLoader._take_data_types' with: {'table': Table(table_name='birth_names', table_metadata=TableMetaData(table_name='birth_names', types={'ds': <class 'sqlalchemy.sql.sqltypes.DateTime'>, 'gender': String(length=16), 'name': String(length=255), 'num': <class 'sqlalchemy.sql.sqltypes.Integer'>, 'state': String(length=10), 'num_boys': <class 'sqlalchemy.sql.sqltypes.Integer'>, 'num_girls': <class 'sqlalchemy.sql.sqltypes.Integer'>}), data=<generator object BirthNamesGenerator.generate at 0x127a7ea50>)}
DEBUG    tests.example_data.data_loading.pandas.pandas_data_loader:logger_utils.py:156 exit from 'PandasDataLoader._take_data_types' with return value: '{'ds': <class 'sqlalchemy.sql.sqltypes.DateTime'>, 'gender': String(length=16), 'name': String(length=255), 'num': <class 'sqlalchemy.sql.sqltypes.Integer'>, 'state': String(length=10), 'num_boys': <class 'sqlalchemy.sql.sqltypes.Integer'>, 'num_girls': <class 'sqlalchemy.sql.sqltypes.Integer'>}'
DEBUG    tests.example_data.data_loading.pandas.pandas_data_loader:logger_utils.py:150 enter to 'PandasDataLoader._detect_schema_name'
DEBUG    tests.example_data.data_loading.pandas.pandas_data_loader:logger_utils.py:156 exit from 'PandasDataLoader._detect_schema_name' with return value: 'superset'

Implemntation details

To understand the code I recommend reading the post decorators-and-closures-in-python

When the decorator is created, it takes the decorated class or function, extracts the logger defined inside the module containing the decorated (in case a logger was not defined, a new one will be created).

with the help of the builtin inspect library the decorator will decorate all the class functions members, then for each function, the inspect will parse the function signature and wrap the function with logs statements

Important notes

• Right now Pytest captures all the logs, so you won't see them unless a test will be failed or configure pytest not to capture the logs.
• You can configure different format messages parts by passing prefixes to the decorator.
• When logging a class methods of function, the "self" and "cls" parameter are omitted

Follow up tasks:

• Make the logic more configurable (when logging private and public methods, when adding the arguments and etc..)
• Logging setup (setup tests logger more explicitly and set the level loggers )
• Add exclude decorator in case I decorate a class but I don't want the specific function to be decorated)

[codecov]

Codecov Report

Merging #18620 (bd56943) into master (1fbdabd) will decrease coverage by 0.17%.
The diff coverage is n/a.

❗ Current head bd56943 differs from pull request most recent head c7a8df7. Consider uploading reports for the commit c7a8df7 to get more accurate results

@@            Coverage Diff             @@
##           master   #18620      +/-   ##
==========================================
- Coverage   66.30%   66.13%   -0.18%     
==========================================
  Files        1595     1595              
  Lines       62632    62632              
  Branches     6309     6309              
==========================================
- Hits        41529    41422     -107     
- Misses      19453    19560     +107     
  Partials     1650     1650              

Flag	Coverage Δ
hive	?
mysql	81.24% <ø> (ø)
postgres	81.29% <ø> (ø)
presto	?
python	81.38% <ø> (-0.35%)	⬇️
sqlite	80.99% <ø> (ø)

Flags with carried forward coverage won't be shown. Click here to find out more.

Impacted Files	Coverage Δ
superset/db_engines/hive.py	0.00% <0.00%> (-85.19%)	⬇️
superset/db_engine_specs/hive.py	70.27% <0.00%> (-15.45%)	⬇️
superset/db_engine_specs/presto.py	83.47% <0.00%> (-5.65%)	⬇️
superset/connectors/sqla/models.py	86.84% <0.00%> (-1.45%)	⬇️
superset/db_engine_specs/base.py	88.05% <0.00%> (-0.38%)	⬇️
superset/models/core.py	88.86% <0.00%> (-0.25%)	⬇️
superset/utils/core.py	89.52% <0.00%> (-0.13%)	⬇️

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 1fbdabd...c7a8df7. Read the comment docs.

[amitmiran137]

Lgtm