From 41f3c9534518f032ab71522d33508b923eeae1d7 Mon Sep 17 00:00:00 2001 From: ofekisr <35701650+ofekisr@users.noreply.github.com> Date: Tue, 8 Feb 2022 18:38:57 +0200 Subject: [PATCH] feat: log decorator util - adding automatic logs out of the box (#18620) * feat: add logger utils * fix bad definitions of under_info and debug_enable * fix pre-commit --- tests/common/logger_utils.py | 174 ++++++++++++++++++ .../data_loading/pandas/pandas_data_loader.py | 11 +- .../data_loading/pandas/table_df_convertor.py | 2 + 3 files changed, 178 insertions(+), 9 deletions(-) create mode 100644 tests/common/logger_utils.py diff --git a/tests/common/logger_utils.py b/tests/common/logger_utils.py new file mode 100644 index 000000000..61e05bc45 --- /dev/null +++ b/tests/common/logger_utils.py @@ -0,0 +1,174 @@ +# Licensed to the Apache Software Foundation (ASF) under one +# or more contributor license agreements. See the NOTICE file +# distributed with this work for additional information +# regarding copyright ownership. The ASF licenses this file +# to you under the Apache License, Version 2.0 (the +# "License"); you may not use this file except in compliance +# with the License. You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, +# software distributed under the License is distributed on an +# "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY +# KIND, either express or implied. See the License for the +# specific language governing permissions and limitations +# under the License. +from __future__ import annotations + +import logging +from functools import wraps +from inspect import ( + getcallargs, + getmembers, + getmodule, + isclass, + isfunction, + ismethod, + signature, + Signature, +) +from logging import Logger +from typing import Any, Callable, cast, Optional, Type, Union + +_DEFAULT_ENTER_MSG_PREFIX = "enter to " +_DEFAULT_ENTER_MSG_SUFFIX = "" +_DEFAULT_WITH_ARGUMENTS_MSG_PART = " with: " +_DEFAULT_EXIT_MSG_PREFIX = "exit from " +_DEFAULT_EXIT_MSG_SUFFIX = "" +_DEFAULT_RETURN_VALUE_MSG_PART = " with return value: " + +_CLS_PARAM = "cls" +_SELF_PARAM = "self" +_PRIVATE_PREFIX_SYMBOL = "_" +_FIXTURE_ATTRIBUTE = "_pytestfixturefunction" +_LOGGER_VAR_NAME = "logger" + +empty_and_none = {Signature.empty, "None"} + + +Function = Callable[..., Any] +Decorated = Union[Type[Any], Function] + + +def log( + decorated: Optional[Decorated] = None, + *, + prefix_enter_msg: str = _DEFAULT_ENTER_MSG_PREFIX, + suffix_enter_msg: str = _DEFAULT_ENTER_MSG_SUFFIX, + with_arguments_msg_part=_DEFAULT_WITH_ARGUMENTS_MSG_PART, + prefix_exit_msg: str = _DEFAULT_EXIT_MSG_PREFIX, + suffix_exit_msg: str = _DEFAULT_EXIT_MSG_SUFFIX, + return_value_msg_part=_DEFAULT_RETURN_VALUE_MSG_PART, +) -> Decorated: + + decorator: Decorated = _make_decorator( + prefix_enter_msg, + suffix_enter_msg, + with_arguments_msg_part, + prefix_exit_msg, + suffix_exit_msg, + return_value_msg_part, + ) + if decorated is None: + return decorator + return decorator(decorated) + + +def _make_decorator( + prefix_enter_msg: str, + suffix_enter_msg: str, + with_arguments_msg_part, + prefix_out_msg: str, + suffix_out_msg: str, + return_value_msg_part, +) -> Decorated: + def decorator(decorated: Decorated): + decorated_logger = _get_logger(decorated) + + def decorator_class(clazz: Type[Any]) -> Type[Any]: + _decorate_class_members_with_logs(clazz) + return clazz + + def _decorate_class_members_with_logs(clazz: Type[Any]) -> None: + members = getmembers( + clazz, predicate=lambda val: ismethod(val) or isfunction(val) + ) + for member_name, member in members: + setattr(clazz, member_name, decorator_func(member, f"{clazz.__name__}")) + + def decorator_func(func: Function, prefix_name: str = "") -> Function: + func_name = func.__name__ + func_signature: Signature = signature(func) + is_fixture = hasattr(func, _FIXTURE_ATTRIBUTE) + has_return_value = func_signature.return_annotation not in empty_and_none + is_private = func_name.startswith(_PRIVATE_PREFIX_SYMBOL) + full_func_name = f"{prefix_name}.{func_name}" + under_info = None + debug_enable = None + + @wraps(func) + def _wrapper_func(*args, **kwargs) -> Any: + _log_enter_to_function(*args, **kwargs) + val = func(*args, **kwargs) + _log_exit_of_function(val) + return val + + def _log_enter_to_function(*args, **kwargs) -> None: + if _is_log_info(): + decorated_logger.info( + f"{prefix_enter_msg}'{full_func_name}'{suffix_enter_msg}" + ) + elif _is_debug_enable(): + _log_debug(*args, **kwargs) + + def _is_log_info() -> bool: + return not (_is_under_info() or is_private or is_fixture) + + def _is_under_info() -> bool: + nonlocal under_info + if under_info is None: + under_info = decorated_logger.getEffectiveLevel() < logging.INFO + return under_info + + def _is_debug_enable() -> bool: + nonlocal debug_enable + if debug_enable is None: + debug_enable = decorated_logger.isEnabledFor(logging.DEBUG) + return debug_enable + + def _log_debug(*args, **kwargs) -> None: + used_parameters = getcallargs(func, *args, **kwargs) + _SELF_PARAM in used_parameters and used_parameters.pop(_SELF_PARAM) + _CLS_PARAM in used_parameters and used_parameters.pop(_CLS_PARAM) + if used_parameters: + decorated_logger.debug( + f"{prefix_enter_msg}'{full_func_name}'{with_arguments_msg_part}" + f"{used_parameters}{suffix_enter_msg}" + ) + else: + decorated_logger.debug( + f"{prefix_enter_msg}'{full_func_name}'{suffix_enter_msg}" + ) + + def _log_exit_of_function(return_value: Any) -> None: + if _is_debug_enable() and has_return_value: + decorated_logger.debug( + f"{prefix_out_msg}'{full_func_name}'{return_value_msg_part}" + f"'{return_value}'{suffix_out_msg}" + ) + + return _wrapper_func + + if isclass(decorated): + return decorator_class(cast(Type[Any], decorated)) + return decorator_func(cast(Function, decorated)) + + return decorator + + +def _get_logger(decorated: Decorated) -> Logger: + module = getmodule(decorated) + return module.__dict__.get( + _LOGGER_VAR_NAME, logging.getLogger(module.__name__) # type: ignore + ) diff --git a/tests/example_data/data_loading/pandas/pandas_data_loader.py b/tests/example_data/data_loading/pandas/pandas_data_loader.py index d5d90d693..00f3f775c 100644 --- a/tests/example_data/data_loading/pandas/pandas_data_loader.py +++ b/tests/example_data/data_loading/pandas/pandas_data_loader.py @@ -14,15 +14,6 @@ # KIND, either express or implied. See the License for the # specific language governing permissions and limitations # under the License. -# -# http://www.apache.org/licenses/LICENSE-2.0 -# -# Unless required by applicable law or agreed to in writing, -# software distributed under the License is distributed on an -# "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY -# KIND, either express or implied. See the License for the -# specific language governing permissions and limitations -# under the License. from __future__ import annotations from abc import ABC, abstractmethod @@ -31,6 +22,7 @@ from typing import Dict, Optional, TYPE_CHECKING from pandas import DataFrame from sqlalchemy.inspection import inspect +from tests.common.logger_utils import log from tests.example_data.data_loading.base_data_loader import DataLoader if TYPE_CHECKING: @@ -42,6 +34,7 @@ if TYPE_CHECKING: ) +@log class PandasDataLoader(DataLoader): _db_engine: Engine _configurations: PandasLoaderConfigurations diff --git a/tests/example_data/data_loading/pandas/table_df_convertor.py b/tests/example_data/data_loading/pandas/table_df_convertor.py index 3b3c6ed57..e801c8464 100644 --- a/tests/example_data/data_loading/pandas/table_df_convertor.py +++ b/tests/example_data/data_loading/pandas/table_df_convertor.py @@ -20,12 +20,14 @@ from typing import Optional, TYPE_CHECKING from pandas import DataFrame +from tests.common.logger_utils import log from tests.example_data.data_loading.pandas.pandas_data_loader import TableToDfConvertor if TYPE_CHECKING: from tests.example_data.data_loading.data_definitions.types import Table +@log class TableToDfConvertorImpl(TableToDfConvertor): convert_datetime_to_str: bool _time_format: Optional[str]