Merge pull request #82 from Hashmap-Software-Agency/11-improve-logging

11 improve logging

Author: dotchetter

pyttman/__init__.py

@@ -35,7 +35,13 @@ def __getattr__(self, item):
 app: PyttmanApp | None = None
 settings = _SettingsNotConfigured
 is_configured = False
-logger = PyttmanLogger
+
+logger = PyttmanLogger()
+"""
+Logs function return value and/or exceptions to the application 
+log file. 
+"""
+
 
 """
 I love you

pyttman/core/internals.py

@@ -4,10 +4,12 @@
 import warnings
 from dataclasses import dataclass, field
 from datetime import datetime
+from pathlib import Path
 from typing import Any
 import json
 from collections import UserDict
 
+import pytz
 
 import pyttman
 from pyttman.core.containers import MessageMixin, Reply
@@ -35,6 +37,7 @@ def depr_graceful(message: str, version: str):
     out = f"{message} - This was deprecated in version {version}."
     warnings.warn(out, DeprecationWarning)
 
+
 class Settings:
     """
     Dataclass holding settings configured in the settings.py
@@ -89,6 +92,7 @@ def __repr__(self):
     def _dict_to_object(dictionary):
         return json.loads(json.dumps(dictionary), object_hook=Settings)
 
+
 def _generate_name(name):
     """
     Generates a user-friendly name out of
@@ -126,12 +130,18 @@ def _generate_error_entry(message: MessageMixin, exc: BaseException) -> Reply:
     traceback.print_exc()
     warnings.warn(f"{datetime.now()} - A critical error occurred in the "
                   f"application logic. Error id: {error_id}")
-    pyttman.logger.log(level="error",
-                       message=f"CRITICAL ERROR: ERROR ID={error_id} - "
-                               f"The error was caught while processing "
-                               f"message: '{message}'. Error message: '{exc}'")
-
-    auto_reply = pyttman.settings.MIDDLEWARE['FATAL_EXCEPTION_AUTO_REPLY']
+    error_message = (f"CRITICAL ERROR: ERROR ID={error_id} - "
+                     f"The error was caught while processing message: "
+                     f"'{message}'. Error message: '{exc}'")
+    try:
+        pyttman.logger.log(level="error", message=error_message)
+    except Exception:
+        print(error_message)
+
+    try:
+        auto_reply = pyttman.settings.MIDDLEWARE['FATAL_EXCEPTION_AUTO_REPLY']
+    except Exception:
+        auto_reply = "An internal error occurred in the application."
     return Reply(f"{auto_reply} ({error_id})")
 
 

pyttman/tools/logger/logger.py

@@ -15,24 +15,9 @@ class PyttmanLogger:
     choice, configuring it the way you want, then
     pass it to the logger.set_logger method.
 
-    __verify_complete (method):
-        Internal use only. Used upon importing the package
-        in __init__.py, to ensure the PyttmanLogger class has a
-        dedicated `logger` instance to work with.
-
-    loggedmethod (decorator method):
-        This method is designed to be a decorator for bound
-        and unbound methods in a software stack. The log method
-        is static and has a closure method called inner, where
-        the wrapped method is executed. Exceptions & return from
-        the wrapped method are both logged to the log file using
-        the static 'logging' instance, configured for the class.
-        Simply add the decorator above your method to enable logging
-        for it. Presuming you import this package as pyttman;
-
-        @pyttman.logger.log
-        def myfunc(self, *args, **kwargs):
-            ...
+    @pyttman.logger
+    def myfunc(self, *args, **kwargs):
+        ...
 
     log (method):
         If you want to manually log custom messages in your code,
@@ -42,57 +27,56 @@ def myfunc(self, *args, **kwargs):
 
     LOG_INSTANCE = None
 
-    @staticmethod
-    def __verify_config_complete():
-        if pyttman.logger.LOG_INSTANCE is None:
-            raise RuntimeError('Internal Pyttman Error: '
-                               'No Logger instance set.\r\n')
-
-    @staticmethod
-    def loggedmethod(func):
+    def __call__(self, func):
         """
         Wrapper method for providing logging functionality.
         Use @logger to implement this method where logging
         of methods are desired.
-        :param func:
-            method that will be wrapped
-        :returns:
-            function
         """
-        @functools.wraps(func)
-        def inner(*args, **kwargs):
+        def inner(*args, log_level="debug", log_exception=True, **kwargs):
             """
             Inner method, executing the func parameter function,
             as well as executing the logger.
             :returns:
                 Output from executed function in parameter func
             """
-            PyttmanLogger.__verify_config_complete()
-
+            PyttmanLogger._verify_config_complete()
             try:
                 results = func(*args, **kwargs)
+                message = f"Return value from '{func.__name__}': '{results}'"
+                self.log(message=message, level=log_level)
                 return results
             except Exception as e:
-                pyttman.logger.LOG_INSTANCE.error(
-                    f'Exception occurred in {func.__name__}. Traceback '
-                    f'{traceback.format_exc()} {e}')
+                if log_exception:
+                    message = (f"Exception occurred in {func.__name__}. "
+                               f"Traceback: {traceback.format_exc()} {e}")
+                    self.log(message=message, level="error")
                 raise e
         return inner
 
     @staticmethod
-    def log(message: str, level="debug") -> None:
+    def _verify_config_complete():
+        if pyttman.logger.LOG_INSTANCE is None:
+            raise RuntimeError('Internal Pyttman Error: '
+                               'No Logger instance set.\r\n')
+
+    def loggedmethod(self, func: callable):
+        """
+        Backward compatibility only; use @logger
+        """
+        def inner(*args, **kwargs):
+            return self.__call__(func)(*args, **kwargs)
+        return inner
+
+    def log(self, message: str, level="debug") -> None:
         """
         Allow for manual logging during runtime.
-        :param message: str, message to be logged
-        :param level: level for logging
-        :returns:
-            arbitrary
         """
-        PyttmanLogger.__verify_config_complete()
-        log_levels = {'info': lambda _message: pyttman.logger.LOG_INSTANCE.info(_message),
-                      'debug': lambda _message: pyttman.logger.LOG_INSTANCE.debug(_message),
-                      'error': lambda _message: pyttman.logger.LOG_INSTANCE.error(_message)}
+        PyttmanLogger._verify_config_complete()
+        log_levels = {"info": self.LOG_INSTANCE.info,
+                      "debug": self.LOG_INSTANCE.debug,
+                      "error": self.LOG_INSTANCE.error}
         try:
             log_levels[level](message)
         except KeyError:
-            log_levels['debug'](message)
+            log_levels["debug"](message)

setup.py

@@ -39,7 +39,8 @@
         "discord.py",
         "requests",
         "py7zr",
-        "ordered_set"
+        "ordered_set",
+        "pytz"
     ],
     entry_points={
         "console_scripts": [

tests/tools/logger/test_logger.py

@@ -1,4 +1,3 @@
-
 import logging
 import os
 import sys
@@ -8,23 +7,33 @@
 from tests.module_helper import PyttmanInternalBaseTestCase
 
 
-@pyttman.logger.loggedmethod
-def some_func():
-    raise Exception("This is a log message")
-
-
 class TestPyttmanLogger(PyttmanInternalBaseTestCase):
 
+    cleanup_after = False
+
     def test_logger_as_class(self):
         expected_output_in_file = "DEBUG:PyttmanTestLogger:This is a log message"
         pyttman.logger.log("This is a log message")
         self.logfile_meets_expectation(expected_output_in_file)
 
     def test_logger_as_decorator(self):
-        expected_output_in_file = 'raise Exception("This is a log message")'
+        @pyttman.logger
+        def broken():
+            raise Exception("This is a log message")
+
+        @pyttman.logger()
+        def working():
+            return "I work"
 
-        self.assertRaises(Exception, some_func)
+        working()
         self.assertTrue(Path(self.log_file_name).exists())
+
+        expected_output_in_file = "Return value from 'working': 'I work'"
+        self.logfile_meets_expectation(expected_output_in_file)
+
+        with self.assertRaises(Exception):
+            broken()
+        expected_output_in_file = 'raise Exception("This is a log message")'
         self.logfile_meets_expectation(expected_output_in_file)
 
     def test_shell_handler(self):
@@ -39,12 +48,15 @@ def logfile_meets_expectation(self, expected_output_in_file):
         with open(self.log_file_name, "r") as file:
             match = False
             for line in file.readlines():
-                if line.strip() == expected_output_in_file:
+                if expected_output_in_file in line:
                     match = True
+                    break
         self.assertTrue(match)
 
     def cleanup(self):
-        print(Path().cwd())
+        if not self.cleanup_after:
+            return
+
         for logfile in Path().cwd().parent.parent.glob("*.log"):
             try:
                 os.remove(logfile)