Added tracing facility

You can enable debug tracing iff loglevel == DEBUG AND
config file has aprsd:trace:True

aprsd/email.py

@@ -7,7 +7,7 @@ import re
 import smtplib
 import time
 
-from aprsd import messaging, stats, threads
+from aprsd import messaging, stats, threads, trace
 import imapclient
 from validate_email import validate_email
 
@@ -17,6 +17,7 @@ LOG = logging.getLogger("APRSD")
 CONFIG = None
 
 
+@trace.trace
 def _imap_connect():
     imap_port = CONFIG["aprsd"]["email"]["imap"].get("port", 143)
     use_ssl = CONFIG["aprsd"]["email"]["imap"].get("use_ssl", False)
@@ -48,9 +49,12 @@ def _imap_connect():
         return
 
     server.select_folder("INBOX")
+
+    server.fetch = trace.trace(server.fetch)
     return server
 
 
+@trace.trace
 def _smtp_connect():
     host = CONFIG["aprsd"]["email"]["smtp"]["host"]
     smtp_port = CONFIG["aprsd"]["email"]["smtp"]["port"]
@@ -165,6 +169,7 @@ def validate_email_config(config, disable_validation=False):
         return False
 
 
+@trace.trace
 def parse_email(msgid, data, server):
     envelope = data[b"ENVELOPE"]
     # email address match
@@ -251,6 +256,7 @@ def parse_email(msgid, data, server):
 # end parse_email
 
 
+@trace.trace
 def send_email(to_addr, content):
     global check_email_delay
 
@@ -295,6 +301,7 @@ def send_email(to_addr, content):
 # end send_email
 
 
+@trace.trace
 def resend_email(count, fromcall):
     global check_email_delay
     date = datetime.datetime.now()
@@ -371,6 +378,7 @@ class APRSDEmailThread(threads.APRSDThread):
         self.msg_queues = msg_queues
         self.config = config
 
+    @trace.trace
     def run(self):
         global check_email_delay
 
@@ -483,6 +491,3 @@ class APRSDEmailThread(threads.APRSDThread):
         # Remove ourselves from the global threads list
         threads.APRSDThreadList().remove(self)
         LOG.info("Exiting")
-
-
-# end check_email()

aprsd/main.py

@@ -32,7 +32,7 @@ import time
 
 # local imports here
 import aprsd
-from aprsd import client, email, flask, messaging, plugin, stats, threads, utils
+from aprsd import client, email, flask, messaging, plugin, stats, threads, trace, utils
 import aprslib
 from aprslib.exceptions import LoginError
 import click
@@ -424,6 +424,11 @@ def server(
     email.CONFIG = config
 
     setup_logging(config, loglevel, quiet)
+    if config["aprsd"].get("trace", False):
+        click.echo("PISS")
+        trace.setup_tracing(["method", "api"])
+    else:
+        click.echo("NO PISS")
     LOG.info("APRSD Started version: {}".format(aprsd.__version__))
     stats.APRSDStats(config)
 

aprsd/plugins/email.py

@@ -2,7 +2,7 @@ import logging
 import re
 import time
 
-from aprsd import email, messaging, plugin
+from aprsd import email, messaging, plugin, trace
 
 LOG = logging.getLogger("APRSD")
 
@@ -18,6 +18,7 @@ class EmailPlugin(plugin.APRSDPluginBase):
     # five mins {int:int}
     email_sent_dict = {}
 
+    @trace.trace
     def command(self, fromcall, message, ack):
         LOG.info("Email COMMAND")
         reply = None

aprsd/plugins/fortune.py

@@ -2,7 +2,7 @@ import logging
 import shutil
 import subprocess
 
-from aprsd import plugin
+from aprsd import plugin, trace
 
 LOG = logging.getLogger("APRSD")
 
@@ -14,6 +14,7 @@ class FortunePlugin(plugin.APRSDPluginBase):
     command_regex = "^[fF]"
     command_name = "fortune"
 
+    @trace.trace
     def command(self, fromcall, message, ack):
         LOG.info("FortunePlugin")
         reply = None

aprsd/plugins/location.py

@@ -2,7 +2,7 @@ import logging
 import re
 import time
 
-from aprsd import plugin, plugin_utils, utils
+from aprsd import plugin, plugin_utils, trace, utils
 
 LOG = logging.getLogger("APRSD")
 
@@ -14,6 +14,7 @@ class LocationPlugin(plugin.APRSDPluginBase):
     command_regex = "^[lL]"
     command_name = "location"
 
+    @trace.trace
     def command(self, fromcall, message, ack):
         LOG.info("Location Plugin")
         # get last location of a callsign, get descriptive name from weather service

aprsd/plugins/ping.py

@@ -1,7 +1,7 @@
 import logging
 import time
 
-from aprsd import plugin
+from aprsd import plugin, trace
 
 LOG = logging.getLogger("APRSD")
 
@@ -13,6 +13,7 @@ class PingPlugin(plugin.APRSDPluginBase):
     command_regex = "^[pP]"
     command_name = "ping"
 
+    @trace.trace
     def command(self, fromcall, message, ack):
         LOG.info("PINGPlugin")
         stm = time.localtime()

aprsd/plugins/query.py

@@ -2,7 +2,7 @@ import datetime
 import logging
 import re
 
-from aprsd import messaging, plugin
+from aprsd import messaging, plugin, trace
 
 LOG = logging.getLogger("APRSD")
 
@@ -14,6 +14,7 @@ class QueryPlugin(plugin.APRSDPluginBase):
     command_regex = r"^\!.*"
     command_name = "query"
 
+    @trace.trace
     def command(self, fromcall, message, ack):
         LOG.info("Query COMMAND")
 

aprsd/plugins/time.py

@@ -1,7 +1,7 @@
 import logging
 import time
 
-from aprsd import fuzzyclock, plugin, plugin_utils, utils
+from aprsd import fuzzyclock, plugin, plugin_utils, trace, utils
 from opencage.geocoder import OpenCageGeocode
 import pytz
 
@@ -38,6 +38,7 @@ class TimePlugin(plugin.APRSDPluginBase):
 
         return reply
 
+    @trace.trace
     def command(self, fromcall, message, ack):
         LOG.info("TIME COMMAND")
         # So we can mock this in unit tests
@@ -52,6 +53,7 @@ class TimeOpenCageDataPlugin(TimePlugin):
     command_regex = "^[tT]"
     command_name = "Time"
 
+    @trace.trace
     def command(self, fromcall, message, ack):
         api_key = self.config["services"]["aprs.fi"]["apiKey"]
         try:
@@ -92,6 +94,7 @@ class TimeOWMPlugin(TimePlugin):
     command_regex = "^[tT]"
     command_name = "Time"
 
+    @trace.trace
     def command(self, fromcall, message, ack):
         api_key = self.config["services"]["aprs.fi"]["apiKey"]
         try:

aprsd/plugins/version.py

@@ -1,7 +1,7 @@
 import logging
 
 import aprsd
-from aprsd import plugin
+from aprsd import plugin, trace
 
 LOG = logging.getLogger("APRSD")
 
@@ -17,6 +17,7 @@ class VersionPlugin(plugin.APRSDPluginBase):
     # five mins {int:int}
     email_sent_dict = {}
 
+    @trace.trace
     def command(self, fromcall, message, ack):
         LOG.info("Version COMMAND")
         return "APRSD version '{}'".format(aprsd.__version__)

aprsd/plugins/weather.py

@@ -2,7 +2,7 @@ import json
 import logging
 import re
 
-from aprsd import plugin, plugin_utils, utils
+from aprsd import plugin, plugin_utils, trace, utils
 import requests
 
 LOG = logging.getLogger("APRSD")
@@ -25,6 +25,7 @@ class USWeatherPlugin(plugin.APRSDPluginBase):
     command_regex = "^[wW]"
     command_name = "weather"
 
+    @trace.trace
     def command(self, fromcall, message, ack):
         LOG.info("Weather Plugin")
         try:
@@ -84,6 +85,7 @@ class USMetarPlugin(plugin.APRSDPluginBase):
     command_regex = "^[metar]"
     command_name = "Metar"
 
+    @trace.trace
     def command(self, fromcall, message, ack):
         LOG.info("WX Plugin '{}'".format(message))
         a = re.search(r"^.*\s+(.*)", message)
@@ -175,6 +177,7 @@ class OWMWeatherPlugin(plugin.APRSDPluginBase):
     command_regex = "^[wW]"
     command_name = "Weather"
 
+    @trace.trace
     def command(self, fromcall, message, ack):
         LOG.info("OWMWeather Plugin '{}'".format(message))
         a = re.search(r"^.*\s+(.*)", message)
@@ -295,6 +298,7 @@ class AVWXWeatherPlugin(plugin.APRSDPluginBase):
     command_regex = "^[metar]"
     command_name = "Weather"
 
+    @trace.trace
     def command(self, fromcall, message, ack):
         LOG.info("OWMWeather Plugin '{}'".format(message))
         a = re.search(r"^.*\s+(.*)", message)

aprsd/threads.py

@@ -5,7 +5,7 @@ import queue
 import threading
 import time
 
-from aprsd import client, messaging, plugin, stats
+from aprsd import client, messaging, plugin, stats, trace
 import aprslib
 
 LOG = logging.getLogger("APRSD")
@@ -219,11 +219,11 @@ class APRSDRXThread(APRSDThread):
         self.msg_queues["tx"].put(ack)
         LOG.debug("Packet processing complete")
 
+    @trace.trace
     def process_packet(self, packet):
         """Process a packet recieved from aprs-is server."""
 
         try:
-            LOG.info("Got message: {}".format(packet))
             stats.APRSDStats().msgs_rx_inc()
 
             msg = packet.get("message_text", None)

aprsd/trace.py

@@ -0,0 +1,181 @@
+import abc
+import functools
+import inspect
+import logging
+import time
+import types
+
+VALID_TRACE_FLAGS = {"method", "api"}
+TRACE_API = False
+TRACE_METHOD = False
+TRACE_ENABLED = False
+LOG = logging.getLogger("APRSD")
+
+
+def trace(*dec_args, **dec_kwargs):
+    """Trace calls to the decorated function.
+
+    This decorator should always be defined as the outermost decorator so it
+    is defined last. This is important so it does not interfere
+    with other decorators.
+
+    Using this decorator on a function will cause its execution to be logged at
+    `DEBUG` level with arguments, return values, and exceptions.
+
+    :returns: a function decorator
+    """
+
+    def _decorator(f):
+
+        func_name = f.__name__
+
+        @functools.wraps(f)
+        def trace_logging_wrapper(*args, **kwargs):
+            filter_function = dec_kwargs.get("filter_function")
+            logger = LOG
+
+            # NOTE(ameade): Don't bother going any further if DEBUG log level
+            # is not enabled for the logger.
+            if not logger.isEnabledFor(logging.DEBUG) or not TRACE_ENABLED:
+                return f(*args, **kwargs)
+
+            all_args = inspect.getcallargs(f, *args, **kwargs)
+
+            pass_filter = filter_function is None or filter_function(all_args)
+
+            if pass_filter:
+                logger.debug(
+                    "==> %(func)s: call %(all_args)r",
+                    {
+                        "func": func_name,
+                        "all_args": str(all_args),
+                    },
+                )
+
+            start_time = time.time() * 1000
+            try:
+                result = f(*args, **kwargs)
+            except Exception as exc:
+                total_time = int(round(time.time() * 1000)) - start_time
+                logger.debug(
+                    "<== %(func)s: exception (%(time)dms) %(exc)r",
+                    {
+                        "func": func_name,
+                        "time": total_time,
+                        "exc": exc,
+                    },
+                )
+                raise
+            total_time = int(round(time.time() * 1000)) - start_time
+
+            if isinstance(result, dict):
+                mask_result = result
+            elif isinstance(result, str):
+                mask_result = result
+            else:
+                mask_result = result
+
+            if pass_filter:
+                logger.debug(
+                    "<== %(func)s: return (%(time)dms) %(result)r",
+                    {
+                        "func": func_name,
+                        "time": total_time,
+                        "result": mask_result,
+                    },
+                )
+            return result
+
+        return trace_logging_wrapper
+
+    if len(dec_args) == 0:
+        # filter_function is passed and args does not contain f
+        return _decorator
+    else:
+        # filter_function is not passed
+        return _decorator(dec_args[0])
+
+
+def trace_api(*dec_args, **dec_kwargs):
+    """Decorates a function if TRACE_API is true."""
+
+    def _decorator(f):
+        @functools.wraps(f)
+        def trace_api_logging_wrapper(*args, **kwargs):
+            if TRACE_API:
+                return trace(f, *dec_args, **dec_kwargs)(*args, **kwargs)
+            return f(*args, **kwargs)
+
+        return trace_api_logging_wrapper
+
+    if len(dec_args) == 0:
+        # filter_function is passed and args does not contain f
+        return _decorator
+    else:
+        # filter_function is not passed
+        return _decorator(dec_args[0])
+
+
+def trace_method(f):
+    """Decorates a function if TRACE_METHOD is true."""
+
+    @functools.wraps(f)
+    def trace_method_logging_wrapper(*args, **kwargs):
+        if TRACE_METHOD:
+            return trace(f)(*args, **kwargs)
+        return f(*args, **kwargs)
+
+    return trace_method_logging_wrapper
+
+
+class TraceWrapperMetaclass(type):
+    """Metaclass that wraps all methods of a class with trace_method.
+
+    This metaclass will cause every function inside of the class to be
+    decorated with the trace_method decorator.
+
+    To use the metaclass you define a class like so:
+    class MyClass(object, metaclass=utils.TraceWrapperMetaclass):
+    """
+
+    def __new__(meta, classname, bases, classDict):
+        newClassDict = {}
+        for attributeName, attribute in classDict.items():
+            if isinstance(attribute, types.FunctionType):
+                # replace it with a wrapped version
+                attribute = functools.update_wrapper(
+                    trace_method(attribute),
+                    attribute,
+                )
+            newClassDict[attributeName] = attribute
+
+        return type.__new__(meta, classname, bases, newClassDict)
+
+
+class TraceWrapperWithABCMetaclass(abc.ABCMeta, TraceWrapperMetaclass):
+    """Metaclass that wraps all methods of a class with trace."""
+
+    pass
+
+
+def setup_tracing(trace_flags):
+    """Set global variables for each trace flag.
+
+    Sets variables TRACE_METHOD and TRACE_API, which represent
+    whether to log methods or api traces.
+
+    :param trace_flags: a list of strings
+    """
+    global TRACE_METHOD
+    global TRACE_API
+    global TRACE_ENABLED
+
+    try:
+        trace_flags = [flag.strip() for flag in trace_flags]
+    except TypeError:  # Handle when trace_flags is None or a test mock
+        trace_flags = []
+    for invalid_flag in set(trace_flags) - VALID_TRACE_FLAGS:
+        LOG.warning("Invalid trace flag: %s", invalid_flag)
+    TRACE_METHOD = "method" in trace_flags
+    TRACE_API = "api" in trace_flags
+    TRACE_ENABLED = True

aprsd/utils.py

@@ -22,6 +22,7 @@ DEFAULT_CONFIG_DICT = {
     },
     "aprsd": {
         "logfile": "/tmp/aprsd.log",
+        "trace": False,
         "plugin_dir": "~/.config/aprsd/plugins",
         "enabled_plugins": plugin.CORE_PLUGINS,
         "units": "imperial",