Migrate AWX utility for slow method logging to DAB (ansible#660)

Followup from ansible#356

The intent is that AWX will delete this method and import from DAB.

Author: AlanCoding

ansible_base/jwt_consumer/common/auth.py

@@ -13,6 +13,7 @@
 
 from ansible_base.jwt_consumer.common.cache import JWTCache
 from ansible_base.jwt_consumer.common.cert import JWTCert, JWTCertException
+from ansible_base.lib.logging.runtime import log_excess_runtime
 from ansible_base.lib.utils.auth import get_user_by_ansible_id
 from ansible_base.lib.utils.translations import translatableConditionally as _
 from ansible_base.resource_registry.models import Resource, ResourceType
@@ -50,6 +51,7 @@ def __init__(self, user_fields=default_mapped_user_fields) -> None:
         self.user = None
         self.token = None
 
+    @log_excess_runtime(logger, debug_cutoff=0.01)
     def parse_jwt_token(self, request):
         """
         parses the given request setting self.user and self.token

ansible_base/lib/logging/runtime.py

@@ -0,0 +1,49 @@
+import functools
+import time
+from collections.abc import Callable
+from logging import Logger, getLogger
+
+__all__ = ['log_excess_runtime']
+
+
+# This allows for configuring all logs from this to go to a particular destination
+# this is not a child of ansible_base so it can be configured separately, and default to not configured
+dab_logger = getLogger('dab_runtime_logger')
+
+
+DEFAULT_MSG = 'Running {name} took {delta:.2f}s'
+
+
+def log_excess_runtime(ext_logger: Logger, cutoff: float = 5.0, debug_cutoff: float = 2.0, msg: str = DEFAULT_MSG, add_log_data: bool = False):
+    """Utility to write logs to the passed-in logger if the function it decorates takes too long.
+
+    Call this with the configuration options to return a decorator."""
+
+    def log_excess_runtime_decorator(func: Callable):
+        """Instantiated decorator for the DAB excess runtime logger utility"""
+
+        @functools.wraps(func)
+        def _new_func(*args, **kwargs):
+            log_data = {'name': repr(func.__name__)}
+            start_time = time.time()
+
+            if add_log_data:
+                return_value = func(*args, log_data=log_data, **kwargs)
+            else:
+                return_value = func(*args, **kwargs)
+
+            log_data['delta'] = time.time() - start_time
+
+            formatted_msg = msg.format(**log_data)
+
+            for logger in (dab_logger, ext_logger):
+                if log_data['delta'] > cutoff:
+                    logger.info(formatted_msg)
+                elif log_data['delta'] > debug_cutoff:
+                    logger.debug(formatted_msg)
+
+            return return_value
+
+        return _new_func
+
+    return log_excess_runtime_decorator

docs/logging.md

@@ -69,3 +69,50 @@ Within those logs, you should be able to see the culprit:
 test_app-1    |   File "/src/test_app/views.py", line 185, in timeout_view
 test_app-1    |     time.sleep(60*10)  # 10 minutes
 ```
+
+## Method Runtime Helper
+
+As a general utility, sometimes you want to log if a particular method takes longer than a certain time.
+This is true in almost any case where a method is doing something known to be performance-sensitive,
+such as processing Ansible facts in AWX.
+
+```python
+import logging
+from ansible_base.lib.logging.runtime import log_excess_runtime
+
+logger = logging.getLogger('my_app.tasks.cleanup')
+
+@log_excess_runtime(logger, cutoff=2.0)
+def cleanup(self):
+    # Do stuff that could take a long time
+```
+
+Then if the `cleaup` method takes over 2.0 seconds, you should see a log like this:
+
+```
+DEBUG    dab_runtime_logger:runtime.py:42 Running 'cleanup' took 2.30s
+```
+
+Because you are passing in your own logger, you can control everything about how those logs are handed.
+If you need to customize the thresholds or log message, you can pass kwards to
+the `@log_excess_runtime` call.
+ - `cutoff` - time cutoff, any time greater than this causes an INFO level log
+ - `debug_cutoff` - any time greater than this causes a DEBUG level log
+ - `msg` - the log message with format strings in it
+ - `add_log_data` - add a kwarg `log_data` to the method call as a dict that the method can attach additional log data to
+
+The `msg` and `add_log_data` are intended to interact.
+For an example, imagine that the `cleanup` method deletes files an keeps a count, `deleted_count`.
+The number of deleted fields could be added to the log message with this.
+
+```python
+import logging
+from ansible_base.lib.logging.runtime import log_excess_runtime
+
+logger = logging.getLogger('my_app.tasks.cleanup')
+
+@log_excess_runtime(logger, cutoff=2.0, msg='Cleanup took {delta:.2f}s, deleted {files_deleted}')
+def cleanup(self, log_data):
+    # Do stuff that could take a long time
+    log_data['files_deleted'] = deleted_count
+```

test_app/tests/lib/logging/test_runtime.py

@@ -0,0 +1,41 @@
+import logging
+import time
+
+from ansible_base.lib.logging.runtime import log_excess_runtime
+
+logger = logging.getLogger('test_app.tests.lib.logging')
+
+
+def sleep_for(delta):
+    time.sleep(delta)
+
+
+def test_no_log_needed(caplog):
+    df = log_excess_runtime(logger)(sleep_for)
+    df(0)
+    assert caplog.text == ''
+
+
+def test_debug_log(caplog):
+    df = log_excess_runtime(logger, debug_cutoff=0.0)(sleep_for)
+    with caplog.at_level(logging.DEBUG):
+        df(0)
+        assert "Running 'sleep_for' took " in caplog.text
+
+
+def test_info_log(caplog):
+    df = log_excess_runtime(logger, debug_cutoff=0.0, cutoff=0.05)(sleep_for)
+    with caplog.at_level(logging.INFO):
+        df(0.1)
+        assert "Running 'sleep_for' took " in caplog.text
+
+
+def extra_message(log_data):
+    log_data['foo'] = 'bar'
+
+
+def test_extra_msg_and_data(caplog):
+    df = log_excess_runtime(logger, debug_cutoff=0.0, add_log_data=True, msg='extra_message log foo={foo}')(extra_message)
+    with caplog.at_level(logging.DEBUG):
+        df()
+        assert "extra_message log foo=bar" in caplog.text