diff --git a/aprsd/email.py b/aprsd/email.py index a498951..da5065c 100644 --- a/aprsd/email.py +++ b/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() diff --git a/aprsd/main.py b/aprsd/main.py index e9532cd..dfe2572 100644 --- a/aprsd/main.py +++ b/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) diff --git a/aprsd/plugins/email.py b/aprsd/plugins/email.py index be57426..677d106 100644 --- a/aprsd/plugins/email.py +++ b/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 diff --git a/aprsd/plugins/fortune.py b/aprsd/plugins/fortune.py index a1100f9..9764234 100644 --- a/aprsd/plugins/fortune.py +++ b/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 diff --git a/aprsd/plugins/location.py b/aprsd/plugins/location.py index 50a6de2..2dec600 100644 --- a/aprsd/plugins/location.py +++ b/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 diff --git a/aprsd/plugins/ping.py b/aprsd/plugins/ping.py index 754da05..19e6ca2 100644 --- a/aprsd/plugins/ping.py +++ b/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() diff --git a/aprsd/plugins/query.py b/aprsd/plugins/query.py index 759d779..35b2404 100644 --- a/aprsd/plugins/query.py +++ b/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") diff --git a/aprsd/plugins/time.py b/aprsd/plugins/time.py index 396d9c0..e5bc3ef 100644 --- a/aprsd/plugins/time.py +++ b/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: diff --git a/aprsd/plugins/version.py b/aprsd/plugins/version.py index d037ac7..80cf766 100644 --- a/aprsd/plugins/version.py +++ b/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__) diff --git a/aprsd/plugins/weather.py b/aprsd/plugins/weather.py index 0dedc28..cd0a741 100644 --- a/aprsd/plugins/weather.py +++ b/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) diff --git a/aprsd/threads.py b/aprsd/threads.py index ea595e9..c1882b2 100644 --- a/aprsd/threads.py +++ b/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) diff --git a/aprsd/trace.py b/aprsd/trace.py new file mode 100644 index 0000000..bc01ed1 --- /dev/null +++ b/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 diff --git a/aprsd/utils.py b/aprsd/utils.py index 3bced87..8b84cea 100644 --- a/aprsd/utils.py +++ b/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",