summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorZuul <zuul@review.openstack.org>2018-07-12 21:35:19 +0000
committerGerrit Code Review <review@openstack.org>2018-07-12 21:35:19 +0000
commitff6e0e593afa5104f743b262dce5fe26d59c64f1 (patch)
tree2db181e3a5096fcc6abb1e684d56dc2d1283450e
parentf106003f5ee1a7d7c3ac5125065b1b6aca95e34e (diff)
parentb9e1552016abfdc6366dd3b1e4129c691664359b (diff)
Merge "[Logging] Enable filtering of trace_api logs"
-rw-r--r--cinder/tests/unit/test_utils.py32
-rw-r--r--cinder/utils.py128
2 files changed, 108 insertions, 52 deletions
diff --git a/cinder/tests/unit/test_utils.py b/cinder/tests/unit/test_utils.py
index c1ebd67..55578da 100644
--- a/cinder/tests/unit/test_utils.py
+++ b/cinder/tests/unit/test_utils.py
@@ -1137,6 +1137,38 @@ class LogTracingTestCase(test.TestCase):
1137 self.assertEqual('OK', result) 1137 self.assertEqual('OK', result)
1138 self.assertEqual(2, utils.LOG.debug.call_count) 1138 self.assertEqual(2, utils.LOG.debug.call_count)
1139 1139
1140 def test_utils_trace_api_filtered(self):
1141 self.mock_object(utils, 'LOG')
1142
1143 def filter_func(all_args):
1144 return False
1145
1146 @utils.trace_api(filter_function=filter_func)
1147 def _trace_test_api(*args, **kwargs):
1148 return 'OK'
1149
1150 utils.setup_tracing(['api'])
1151
1152 result = _trace_test_api()
1153 self.assertEqual('OK', result)
1154 self.assertEqual(0, utils.LOG.debug.call_count)
1155
1156 def test_utils_trace_filtered(self):
1157 self.mock_object(utils, 'LOG')
1158
1159 def filter_func(all_args):
1160 return False
1161
1162 @utils.trace(filter_function=filter_func)
1163 def _trace_test(*args, **kwargs):
1164 return 'OK'
1165
1166 utils.setup_tracing(['api'])
1167
1168 result = _trace_test()
1169 self.assertEqual('OK', result)
1170 self.assertEqual(0, utils.LOG.debug.call_count)
1171
1140 def test_utils_trace_method_default_logger(self): 1172 def test_utils_trace_method_default_logger(self):
1141 mock_log = self.mock_object(utils, 'LOG') 1173 mock_log = self.mock_object(utils, 'LOG')
1142 1174
diff --git a/cinder/utils.py b/cinder/utils.py
index c983330..cd537bc 100644
--- a/cinder/utils.py
+++ b/cinder/utils.py
@@ -850,17 +850,26 @@ def trace_method(f):
850 return trace_method_logging_wrapper 850 return trace_method_logging_wrapper
851 851
852 852
853def trace_api(f): 853def trace_api(*dec_args, **dec_kwargs):
854 """Decorates a function if TRACE_API is true.""" 854 """Decorates a function if TRACE_API is true."""
855 @functools.wraps(f)
856 def trace_api_logging_wrapper(*args, **kwargs):
857 if TRACE_API:
858 return trace(f)(*args, **kwargs)
859 return f(*args, **kwargs)
860 return trace_api_logging_wrapper
861 855
856 def _decorator(f):
857 @functools.wraps(f)
858 def trace_api_logging_wrapper(*args, **kwargs):
859 if TRACE_API:
860 return trace(f, *dec_args, **dec_kwargs)(*args, **kwargs)
861 return f(*args, **kwargs)
862 return trace_api_logging_wrapper
862 863
863def trace(f): 864 if len(dec_args) == 0:
865 # filter_function is passed and args does not contain f
866 return _decorator
867 else:
868 # filter_function is not passed
869 return _decorator(dec_args[0])
870
871
872def trace(*dec_args, **dec_kwargs):
864 """Trace calls to the decorated function. 873 """Trace calls to the decorated function.
865 874
866 This decorator should always be defined as the outermost decorator so it 875 This decorator should always be defined as the outermost decorator so it
@@ -873,55 +882,70 @@ def trace(f):
873 :returns: a function decorator 882 :returns: a function decorator
874 """ 883 """
875 884
876 func_name = f.__name__ 885 def _decorator(f):
877
878 @functools.wraps(f)
879 def trace_logging_wrapper(*args, **kwargs):
880 if len(args) > 0:
881 maybe_self = args[0]
882 else:
883 maybe_self = kwargs.get('self', None)
884
885 if maybe_self and hasattr(maybe_self, '__module__'):
886 logger = logging.getLogger(maybe_self.__module__)
887 else:
888 logger = LOG
889 886
890 # NOTE(ameade): Don't bother going any further if DEBUG log level 887 func_name = f.__name__
891 # is not enabled for the logger.
892 if not logger.isEnabledFor(py_logging.DEBUG):
893 return f(*args, **kwargs)
894 888
895 all_args = inspect.getcallargs(f, *args, **kwargs) 889 @functools.wraps(f)
890 def trace_logging_wrapper(*args, **kwargs):
891 filter_function = dec_kwargs.get('filter_function')
896 892
897 logger.debug('==> %(func)s: call %(all_args)r', 893 if len(args) > 0:
898 {'func': func_name, 'all_args': all_args}) 894 maybe_self = args[0]
895 else:
896 maybe_self = kwargs.get('self', None)
899 897
900 start_time = time.time() * 1000 898 if maybe_self and hasattr(maybe_self, '__module__'):
901 try: 899 logger = logging.getLogger(maybe_self.__module__)
902 result = f(*args, **kwargs) 900 else:
903 except Exception as exc: 901 logger = LOG
902
903 # NOTE(ameade): Don't bother going any further if DEBUG log level
904 # is not enabled for the logger.
905 if not logger.isEnabledFor(py_logging.DEBUG):
906 return f(*args, **kwargs)
907
908 all_args = inspect.getcallargs(f, *args, **kwargs)
909
910 pass_filter = filter_function is None or filter_function(all_args)
911
912 if pass_filter:
913 logger.debug('==> %(func)s: call %(all_args)r',
914 {'func': func_name, 'all_args': all_args})
915
916 start_time = time.time() * 1000
917 try:
918 result = f(*args, **kwargs)
919 except Exception as exc:
920 total_time = int(round(time.time() * 1000)) - start_time
921 logger.debug('<== %(func)s: exception (%(time)dms) %(exc)r',
922 {'func': func_name,
923 'time': total_time,
924 'exc': exc})
925 raise
904 total_time = int(round(time.time() * 1000)) - start_time 926 total_time = int(round(time.time() * 1000)) - start_time
905 logger.debug('<== %(func)s: exception (%(time)dms) %(exc)r', 927
906 {'func': func_name, 928 if isinstance(result, dict):
907 'time': total_time, 929 mask_result = strutils.mask_dict_password(result)
908 'exc': exc}) 930 elif isinstance(result, six.string_types):
909 raise 931 mask_result = strutils.mask_password(result)
910 total_time = int(round(time.time() * 1000)) - start_time 932 else:
911 933 mask_result = result
912 if isinstance(result, dict): 934
913 mask_result = strutils.mask_dict_password(result) 935 if pass_filter:
914 elif isinstance(result, six.string_types): 936 logger.debug('<== %(func)s: return (%(time)dms) %(result)r',
915 mask_result = strutils.mask_password(result) 937 {'func': func_name,
916 else: 938 'time': total_time,
917 mask_result = result 939 'result': mask_result})
918 940 return result
919 logger.debug('<== %(func)s: return (%(time)dms) %(result)r', 941 return trace_logging_wrapper
920 {'func': func_name, 942
921 'time': total_time, 943 if len(dec_args) == 0:
922 'result': mask_result}) 944 # filter_function is passed and args does not contain f
923 return result 945 return _decorator
924 return trace_logging_wrapper 946 else:
947 # filter_function is not passed
948 return _decorator(dec_args[0])
925 949
926 950
927class TraceWrapperMetaclass(type): 951class TraceWrapperMetaclass(type):