Move logging utilities out of the side drawer of util/ and into logging/ (#5606)

1 files changed, 194 insertions, 0 deletions

diff --git a/synapse/logging/utils.py b/synapse/logging/utils.py
new file mode 100644
index 0000000000..7df0fa6087
--- /dev/null
+++ b/synapse/logging/utils.py
@@ -0,0 +1,194 @@
+# -*- coding: utf-8 -*-
+# Copyright 2014-2016 OpenMarket Ltd
+#
+# Licensed 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.
+
+
+import inspect
+import logging
+import time
+from functools import wraps
+from inspect import getcallargs
+
+from six import PY3
+
+_TIME_FUNC_ID = 0
+
+
+def _log_debug_as_f(f, msg, msg_args):
+    name = f.__module__
+    logger = logging.getLogger(name)
+
+    if logger.isEnabledFor(logging.DEBUG):
+        if PY3:
+            lineno = f.__code__.co_firstlineno
+            pathname = f.__code__.co_filename
+        else:
+            lineno = f.func_code.co_firstlineno
+            pathname = f.func_code.co_filename
+
+        record = logging.LogRecord(
+            name=name,
+            level=logging.DEBUG,
+            pathname=pathname,
+            lineno=lineno,
+            msg=msg,
+            args=msg_args,
+            exc_info=None,
+        )
+
+        logger.handle(record)
+
+
+def log_function(f):
+    """ Function decorator that logs every call to that function.
+    """
+    func_name = f.__name__
+
+    @wraps(f)
+    def wrapped(*args, **kwargs):
+        name = f.__module__
+        logger = logging.getLogger(name)
+        level = logging.DEBUG
+
+        if logger.isEnabledFor(level):
+            bound_args = getcallargs(f, *args, **kwargs)
+
+            def format(value):
+                r = str(value)
+                if len(r) > 50:
+                    r = r[:50] + "..."
+                return r
+
+            func_args = ["%s=%s" % (k, format(v)) for k, v in bound_args.items()]
+
+            msg_args = {"func_name": func_name, "args": ", ".join(func_args)}
+
+            _log_debug_as_f(f, "Invoked '%(func_name)s' with args: %(args)s", msg_args)
+
+        return f(*args, **kwargs)
+
+    wrapped.__name__ = func_name
+    return wrapped
+
+
+def time_function(f):
+    func_name = f.__name__
+
+    @wraps(f)
+    def wrapped(*args, **kwargs):
+        global _TIME_FUNC_ID
+        id = _TIME_FUNC_ID
+        _TIME_FUNC_ID += 1
+
+        start = time.clock()
+
+        try:
+            _log_debug_as_f(f, "[FUNC START] {%s-%d}", (func_name, id))
+
+            r = f(*args, **kwargs)
+        finally:
+            end = time.clock()
+            _log_debug_as_f(
+                f, "[FUNC END] {%s-%d} %.3f sec", (func_name, id, end - start)
+            )
+
+        return r
+
+    return wrapped
+
+
+def trace_function(f):
+    func_name = f.__name__
+    linenum = f.func_code.co_firstlineno
+    pathname = f.func_code.co_filename
+
+    @wraps(f)
+    def wrapped(*args, **kwargs):
+        name = f.__module__
+        logger = logging.getLogger(name)
+        level = logging.DEBUG
+
+        s = inspect.currentframe().f_back
+
+        to_print = [
+            "\t%s:%s %s. Args: args=%s, kwargs=%s"
+            % (pathname, linenum, func_name, args, kwargs)
+        ]
+        while s:
+            if True or s.f_globals["__name__"].startswith("synapse"):
+                filename, lineno, function, _, _ = inspect.getframeinfo(s)
+                args_string = inspect.formatargvalues(*inspect.getargvalues(s))
+
+                to_print.append(
+                    "\t%s:%d %s. Args: %s" % (filename, lineno, function, args_string)
+                )
+
+            s = s.f_back
+
+        msg = "\nTraceback for %s:\n" % (func_name,) + "\n".join(to_print)
+
+        record = logging.LogRecord(
+            name=name,
+            level=level,
+            pathname=pathname,
+            lineno=lineno,
+            msg=msg,
+            args=None,
+            exc_info=None,
+        )
+
+        logger.handle(record)
+
+        return f(*args, **kwargs)
+
+    wrapped.__name__ = func_name
+    return wrapped
+
+
+def get_previous_frames():
+    s = inspect.currentframe().f_back.f_back
+    to_return = []
+    while s:
+        if s.f_globals["__name__"].startswith("synapse"):
+            filename, lineno, function, _, _ = inspect.getframeinfo(s)
+            args_string = inspect.formatargvalues(*inspect.getargvalues(s))
+
+            to_return.append(
+                "{{  %s:%d %s - Args: %s }}" % (filename, lineno, function, args_string)
+            )
+
+        s = s.f_back
+
+    return ", ".join(to_return)
+
+
+def get_previous_frame(ignore=[]):
+    s = inspect.currentframe().f_back.f_back
+
+    while s:
+        if s.f_globals["__name__"].startswith("synapse"):
+            if not any(s.f_globals["__name__"].startswith(ig) for ig in ignore):
+                filename, lineno, function, _, _ = inspect.getframeinfo(s)
+                args_string = inspect.formatargvalues(*inspect.getargvalues(s))
+
+                return "{{  %s:%d %s - Args: %s }}" % (
+                    filename,
+                    lineno,
+                    function,
+                    args_string,
+                )
+
+        s = s.f_back
+
+    return None