Improved logging

Needs testing with Postman.
n0nuser · Mar 26, 2022 · d451ddc · d451ddc · n0nuser · Mar 26, 2022
1 parent 39e5868
commit d451ddc
Show file tree

Hide file tree

Showing 11 changed files with 213 additions and 66 deletions.
diff --git a/monitor_agent/core/command.py b/monitor_agent/core/command.py
@@ -80,7 +80,6 @@ def _executeCommand(command: str, timeout: int) -> typing.Tuple[str, str, int, f
             # https://stackoverflow.com/questions/64948722/error-unicodedecodeerror-utf-8-codec-cant-decode-byte-0xbe-in-position-2-in
             # shell=True MUST NOT BE USED:
             # https://stackoverflow.com/questions/48763362/python-subprocess-kill-with-timeout
-            # print("Windows CMD built-in.", command)
             process = subprocess.run(
                 command,
                 capture_output=True,
@@ -92,7 +91,6 @@ def _executeCommand(command: str, timeout: int) -> typing.Tuple[str, str, int, f
                 check=True,
             )
         else:
-            # print("Linux or Windows command:", command)
             process = subprocess.run(
                 command.split(),
                 capture_output=True,

diff --git a/monitor_agent/core/helper.py b/monitor_agent/core/helper.py
@@ -1,14 +1,40 @@
-import sys
-from datetime import datetime
+import logging
 
-LOG_FILE = "monitor-agent.log"
-MODE = "a+"
 
+def getLogger(CONFIG):
+    log_level = ""
+    tranlation = {
+        "debug": logging.DEBUG,
+        "info": logging.INFO,
+        "warning": logging.WARNING,
+        "error": logging.ERROR,
+        "critical": logging.CRITICAL,
+    }
+    try:
+        if CONFIG.logging.level in tranlation.keys():
+            log_level = tranlation[CONFIG.logging.level]
+        else:
+            logging.warning("Level not established in Settings.json")
+            log_level = logging.info
+    except AttributeError as e:
+        logging.warning(
+            "Level not established in Settings.json.\nDefault Info level will be used.",
+            exc_info=True,
+        )
+        log_level = logging.info
 
-def save2log(filename: str = LOG_FILE, mode: str = MODE, data="", type=""):
+    log_filename = ""
     try:
-        with open(filename, mode) as f:
-            timestamp = datetime.now().strftime("%d/%m/%Y:%H:%M:%S")
-            f.write(f"{type} - - [{timestamp}] : {data}\n")
-    except OSError as msg:
-        print(f"ERROR: Couldn't open file {filename} - {msg}", file=sys.stderr)
+        log_filename = CONFIG.logging.filename
+    except AttributeError as e:
+        logging.warning(
+            'Log filename not established in Settings.json.\nDefault "monitor.log" file will be used.',
+            exc_info=True,
+        )
+        log_filename = "monitor.log"
+
+    return logging.basicConfig(
+        level=log_level,
+        filename=log_filename,
+        format="%(asctime)s - %(levelname)s - %(message)s",
+    )
diff --git a/monitor_agent/core/metricFunctions.py b/monitor_agent/core/metricFunctions.py
@@ -2,12 +2,10 @@
 import json
 import typing
 import requests
+import logging
 
-from monitor_agent.core.helper import save2log
-from .models.metricModel import Status, MetricDynamic, MetricStatic
-
-# Typing Tuple is used to overcome Python ^3.6 until Python 3.10 problem
-# with Tuples not being a standard type
+from monitor_agent.main import LOGGER
+from core.models import Status, MetricDynamic, MetricStatic
 
 
 def execution_time_decorator(function) -> typing.Tuple[float, dict]:
@@ -36,7 +34,7 @@ def send_metrics_adapter(function_list: list) -> typing.Tuple[dict, dict]:
             elapsed_time.update(f_time)
             data.update(f_data)
         except TypeError as msg:
-            save2log(type="WARNING", data=f"TypeError: {msg}")
+            LOGGER.warning(f"TypeError: {msg}", exc_info=True)
             continue
     return elapsed_time, data
 
@@ -48,7 +46,7 @@ def send_metrics(
     json_request = {"data": data, "status": status}
     r = requests.post(url, json=json_request)
     # DEBUG
-    print(r.status_code)
+    logging.debug(f"Status Code: {r.status_code}")
     if file_enabled:
         with open(file_path, "w") as f:
             f.write(json.dumps(json_request, indent=4, sort_keys=True))
diff --git a/monitor_agent/core/models/metricModel.py → monitor_agent/core/models.py b/monitor_agent/core/models/metricModel.py → monitor_agent/core/models.py
@@ -2,9 +2,8 @@
 import platform
 import time
 import datetime
-import os
 
-from monitor_agent.core.helper import save2log
+from monitor_agent.main import LOGGER
 
 
 class Status:
@@ -116,9 +115,8 @@ def _process(ram: int, pc_cpu_percent):
                     # Requires elevated permissions
                     process[p.pid]["path"] = p.exe()
                 except (PermissionError, psutil.AccessDenied):
-                    save2log(
-                        type="WARNING",
-                        data=f"Could not get Username or Path for process {p.name()}",
+                    LOGGER.warning(
+                        f"Could not get Username or Path for process {p.name()}"
                     )
     return process
 

diff --git a/monitor_agent/core/models/__init__.py b/monitor_agent/core/models/__init__.py
diff --git a/monitor_agent/core/schemas/__init__.py b/monitor_agent/core/schemas/__init__.py
diff --git a/monitor_agent/main.py b/monitor_agent/main.py
@@ -1,22 +1,24 @@
-import re
-import sys
 import json
+from monitor_agent.core.helper import getLogger
 import uvicorn
 import logging
 import requests
 from .settings import Settings
 from .core.command import Command
 from fastapi import FastAPI, UploadFile
 from fastapi_utils.tasks import repeat_every
-from .core.metricFunctions import send_metrics, send_metrics_adapter, static, dynamic
+
 
 try:
     CONFIG = Settings()
 except json.decoder.JSONDecodeError as msg:
-    print('Error in "settings.json".', msg, file=sys.stderr)
+    logging.critical(f'Error in "settings.json". {msg}')
     exit()
 
-logger = logging.getLogger(__name__)
+LOGGER = getLogger(CONFIG)
+
+from .core.metricFunctions import send_metrics, send_metrics_adapter, static, dynamic
+
 api = FastAPI()
 
 endpoints = {
@@ -63,7 +65,7 @@ async def mod_settings(settings: UploadFile):
 
 
 @api.on_event("startup")
-@repeat_every(seconds=CONFIG.metrics.post_interval, logger=logger, wait_first=True)
+@repeat_every(seconds=CONFIG.metrics.post_interval, logger=LOGGER, wait_first=True)
 def periodic():
     # https://github.com/tiangolo/fastapi/issues/520
     # https://fastapi-utils.davidmontague.xyz/user-guide/repeated-tasks/#the-repeat_every-decorator
@@ -78,9 +80,9 @@ def periodic():
     )
 
     alert = {}
-    if data["cpu_percent"] >= thresholds_dict["cpu_percent"]:
+    if data["cpu_percent"] >= CONFIG.thresholds.cpu_percent:
         alert["cpu_percent"] = data["cpu_percent"]
-    if data["ram"]["percent"] >= thresholds_dict["ram_percent"]:
+    if data["ram"]["percent"] >= CONFIG.thresholds.ram_percent:
         alert["ram_percent"] = data["ram"]["percent"]
     try:
         if data["process"]:
@@ -99,4 +101,7 @@ def start():
     uviconfig.pop("__dict__", None)
     uviconfig.pop("__weakref__", None)
     uviconfig.pop("__doc__", None)
-    uvicorn.run(**uviconfig)
+    try:
+        uvicorn.run(**uviconfig)
+    except:
+        LOGGER.critical("Unable to run server.", exc_info=True)
diff --git a/monitor_agent/monitor.log b/monitor_agent/monitor.log
@@ -0,0 +1,138 @@
+2022-03-26 15:10:14,033 - INFO - Will watch for changes in these directories: ['/home/pablo/devel/monitor_agent/monitor_agent']
+2022-03-26 15:10:14,033 - INFO - Uvicorn running on http://0.0.0.0:8000 (Press CTRL+C to quit)
+2022-03-26 15:10:14,033 - INFO - Started reloader process [35964] using statreload
+2022-03-26 15:10:14,306 - INFO - Started server process [35969]
+2022-03-26 15:10:14,306 - INFO - Waiting for application startup.
+2022-03-26 15:10:14,306 - TRACE - ASGI [1] Started scope={'type': 'lifespan', 'asgi': {'version': '3.0', 'spec_version': '2.0'}}
+2022-03-26 15:10:14,306 - TRACE - ASGI [1] Receive {'type': 'lifespan.startup'}
+2022-03-26 15:10:14,306 - TRACE - ASGI [1] Send {'type': 'lifespan.startup.complete'}
+2022-03-26 15:10:14,307 - INFO - Application startup complete.
+2022-03-26 15:10:28,957 - WARNING - StatReload detected file change in 'core/helper.py'. Reloading...
+2022-03-26 15:10:28,991 - INFO - Shutting down
+2022-03-26 15:10:29,092 - INFO - Waiting for application shutdown.
+2022-03-26 15:10:29,092 - TRACE - ASGI [1] Receive {'type': 'lifespan.shutdown'}
+2022-03-26 15:10:29,093 - TRACE - ASGI [1] Send {'type': 'lifespan.shutdown.complete'}
+2022-03-26 15:10:29,093 - TRACE - ASGI [1] Completed
+2022-03-26 15:10:29,094 - INFO - Application shutdown complete.
+2022-03-26 15:10:29,094 - INFO - Finished server process [35969]
+2022-03-26 15:10:29,492 - INFO - Started server process [35993]
+2022-03-26 15:10:29,493 - INFO - Waiting for application startup.
+2022-03-26 15:10:29,493 - TRACE - ASGI [1] Started scope={'type': 'lifespan', 'asgi': {'version': '3.0', 'spec_version': '2.0'}}
+2022-03-26 15:10:29,493 - TRACE - ASGI [1] Receive {'type': 'lifespan.startup'}
+2022-03-26 15:10:29,493 - TRACE - ASGI [1] Send {'type': 'lifespan.startup.complete'}
+2022-03-26 15:10:29,493 - INFO - Application startup complete.
+2022-03-26 15:10:33,738 - WARNING - StatReload detected file change in 'core/helper.py'. Reloading...
+2022-03-26 15:10:33,815 - INFO - Shutting down
+2022-03-26 15:10:33,917 - INFO - Waiting for application shutdown.
+2022-03-26 15:10:33,918 - TRACE - ASGI [1] Receive {'type': 'lifespan.shutdown'}
+2022-03-26 15:10:33,918 - TRACE - ASGI [1] Send {'type': 'lifespan.shutdown.complete'}
+2022-03-26 15:10:33,919 - TRACE - ASGI [1] Completed
+2022-03-26 15:10:33,919 - INFO - Application shutdown complete.
+2022-03-26 15:10:33,919 - INFO - Finished server process [35993]
+2022-03-26 15:10:34,262 - INFO - Started server process [36005]
+2022-03-26 15:10:34,262 - INFO - Waiting for application startup.
+2022-03-26 15:10:34,262 - TRACE - ASGI [1] Started scope={'type': 'lifespan', 'asgi': {'version': '3.0', 'spec_version': '2.0'}}
+2022-03-26 15:10:34,262 - TRACE - ASGI [1] Receive {'type': 'lifespan.startup'}
+2022-03-26 15:10:34,263 - TRACE - ASGI [1] Send {'type': 'lifespan.startup.complete'}
+2022-03-26 15:10:34,263 - INFO - Application startup complete.
+2022-03-26 15:10:37,679 - INFO - Shutting down
+2022-03-26 15:10:37,780 - INFO - Waiting for application shutdown.
+2022-03-26 15:10:37,781 - TRACE - ASGI [1] Receive {'type': 'lifespan.shutdown'}
+2022-03-26 15:10:37,781 - TRACE - ASGI [1] Send {'type': 'lifespan.shutdown.complete'}
+2022-03-26 15:10:37,782 - TRACE - ASGI [1] Completed
+2022-03-26 15:10:37,782 - INFO - Application shutdown complete.
+2022-03-26 15:10:37,783 - INFO - Finished server process [36005]
+2022-03-26 15:10:37,879 - INFO - Stopping reloader process [35964]
+2022-03-26 15:10:40,672 - INFO - Will watch for changes in these directories: ['/home/pablo/devel/monitor_agent/monitor_agent']
+2022-03-26 15:10:40,673 - INFO - Uvicorn running on http://0.0.0.0:8000 (Press CTRL+C to quit)
+2022-03-26 15:10:40,673 - INFO - Started reloader process [36045] using statreload
+2022-03-26 15:10:40,944 - INFO - Started server process [36050]
+2022-03-26 15:10:40,944 - INFO - Waiting for application startup.
+2022-03-26 15:10:40,945 - TRACE - ASGI [1] Started scope={'type': 'lifespan', 'asgi': {'version': '3.0', 'spec_version': '2.0'}}
+2022-03-26 15:10:40,945 - TRACE - ASGI [1] Receive {'type': 'lifespan.startup'}
+2022-03-26 15:10:40,945 - TRACE - ASGI [1] Send {'type': 'lifespan.startup.complete'}
+2022-03-26 15:10:40,945 - INFO - Application startup complete.
+2022-03-26 15:10:51,286 - WARNING - StatReload detected file change in 'main.py'. Reloading...
+2022-03-26 15:10:51,299 - INFO - Shutting down
+2022-03-26 15:10:51,400 - INFO - Waiting for application shutdown.
+2022-03-26 15:10:51,401 - TRACE - ASGI [1] Receive {'type': 'lifespan.shutdown'}
+2022-03-26 15:10:51,401 - TRACE - ASGI [1] Send {'type': 'lifespan.shutdown.complete'}
+2022-03-26 15:10:51,402 - TRACE - ASGI [1] Completed
+2022-03-26 15:10:51,402 - INFO - Application shutdown complete.
+2022-03-26 15:10:51,402 - INFO - Finished server process [36050]
+2022-03-26 15:10:51,798 - INFO - Started server process [36066]
+2022-03-26 15:10:51,798 - INFO - Waiting for application startup.
+2022-03-26 15:10:51,798 - TRACE - ASGI [1] Started scope={'type': 'lifespan', 'asgi': {'version': '3.0', 'spec_version': '2.0'}}
+2022-03-26 15:10:51,799 - TRACE - ASGI [1] Receive {'type': 'lifespan.startup'}
+2022-03-26 15:10:51,799 - TRACE - ASGI [1] Send {'type': 'lifespan.startup.complete'}
+2022-03-26 15:10:51,799 - INFO - Application startup complete.
+2022-03-26 15:11:46,805 - WARNING - StatReload detected file change in 'main.py'. Reloading...
+2022-03-26 15:11:46,839 - INFO - Shutting down
+2022-03-26 15:11:46,941 - INFO - Waiting for application shutdown.
+2022-03-26 15:11:46,941 - TRACE - ASGI [1] Receive {'type': 'lifespan.shutdown'}
+2022-03-26 15:11:46,942 - TRACE - ASGI [1] Send {'type': 'lifespan.shutdown.complete'}
+2022-03-26 15:11:46,942 - TRACE - ASGI [1] Completed
+2022-03-26 15:11:46,943 - INFO - Application shutdown complete.
+2022-03-26 15:11:46,943 - INFO - Finished server process [36066]
+2022-03-26 15:11:47,302 - INFO - Started server process [36085]
+2022-03-26 15:11:47,302 - INFO - Waiting for application startup.
+2022-03-26 15:11:47,302 - TRACE - ASGI [1] Started scope={'type': 'lifespan', 'asgi': {'version': '3.0', 'spec_version': '2.0'}}
+2022-03-26 15:11:47,303 - TRACE - ASGI [1] Receive {'type': 'lifespan.startup'}
+2022-03-26 15:11:47,303 - TRACE - ASGI [1] Send {'type': 'lifespan.startup.complete'}
+2022-03-26 15:11:47,303 - INFO - Application startup complete.
+2022-03-26 15:12:05,661 - INFO - Shutting down
+2022-03-26 15:12:05,762 - INFO - Waiting for application shutdown.
+2022-03-26 15:12:05,762 - TRACE - ASGI [1] Receive {'type': 'lifespan.shutdown'}
+2022-03-26 15:12:05,762 - TRACE - ASGI [1] Send {'type': 'lifespan.shutdown.complete'}
+2022-03-26 15:12:05,762 - TRACE - ASGI [1] Completed
+2022-03-26 15:12:05,763 - INFO - Application shutdown complete.
+2022-03-26 15:12:05,763 - INFO - Finished server process [36085]
+2022-03-26 15:12:05,813 - INFO - Stopping reloader process [36045]
+2022-03-26 15:12:38,060 - INFO - Will watch for changes in these directories: ['/home/pablo/devel/monitor_agent/monitor_agent']
+2022-03-26 15:12:38,061 - INFO - Uvicorn running on http://0.0.0.0:8000 (Press CTRL+C to quit)
+2022-03-26 15:12:38,061 - INFO - Started reloader process [36505] using statreload
+2022-03-26 15:12:38,332 - INFO - Started server process [36510]
+2022-03-26 15:12:38,333 - INFO - Waiting for application startup.
+2022-03-26 15:12:38,333 - TRACE - ASGI [1] Started scope={'type': 'lifespan', 'asgi': {'version': '3.0', 'spec_version': '2.0'}}
+2022-03-26 15:12:38,333 - TRACE - ASGI [1] Receive {'type': 'lifespan.startup'}
+2022-03-26 15:12:38,333 - TRACE - ASGI [1] Send {'type': 'lifespan.startup.complete'}
+2022-03-26 15:12:38,333 - INFO - Application startup complete.
+2022-03-26 15:12:39,642 - INFO - Shutting down
+2022-03-26 15:12:39,743 - INFO - Waiting for application shutdown.
+2022-03-26 15:12:39,744 - TRACE - ASGI [1] Receive {'type': 'lifespan.shutdown'}
+2022-03-26 15:12:39,744 - TRACE - ASGI [1] Send {'type': 'lifespan.shutdown.complete'}
+2022-03-26 15:12:39,745 - TRACE - ASGI [1] Completed
+2022-03-26 15:12:39,745 - INFO - Application shutdown complete.
+2022-03-26 15:12:39,746 - INFO - Finished server process [36510]
+2022-03-26 15:12:39,815 - INFO - Stopping reloader process [36505]
+2022-03-26 15:12:44,043 - INFO - Will watch for changes in these directories: ['/home/pablo/devel/monitor_agent/monitor_agent']
+2022-03-26 15:12:44,044 - INFO - Uvicorn running on http://0.0.0.0:8000 (Press CTRL+C to quit)
+2022-03-26 15:12:44,044 - INFO - Started reloader process [36527] using statreload
+2022-03-26 15:12:44,314 - INFO - Started server process [36532]
+2022-03-26 15:12:44,315 - INFO - Waiting for application startup.
+2022-03-26 15:12:44,315 - TRACE - ASGI [1] Started scope={'type': 'lifespan', 'asgi': {'version': '3.0', 'spec_version': '2.0'}}
+2022-03-26 15:12:44,315 - TRACE - ASGI [1] Receive {'type': 'lifespan.startup'}
+2022-03-26 15:12:44,315 - TRACE - ASGI [1] Send {'type': 'lifespan.startup.complete'}
+2022-03-26 15:12:44,315 - INFO - Application startup complete.
+2022-03-26 15:12:45,816 - WARNING - StatReload detected file change in 'main.py'. Reloading...
+2022-03-26 15:12:45,824 - INFO - Shutting down
+2022-03-26 15:12:45,925 - INFO - Waiting for application shutdown.
+2022-03-26 15:12:45,925 - TRACE - ASGI [1] Receive {'type': 'lifespan.shutdown'}
+2022-03-26 15:12:45,926 - TRACE - ASGI [1] Send {'type': 'lifespan.shutdown.complete'}
+2022-03-26 15:12:45,926 - TRACE - ASGI [1] Completed
+2022-03-26 15:12:45,926 - INFO - Application shutdown complete.
+2022-03-26 15:12:45,927 - INFO - Finished server process [36532]
+2022-03-26 15:12:46,320 - INFO - Started server process [36543]
+2022-03-26 15:12:46,320 - INFO - Waiting for application startup.
+2022-03-26 15:12:46,321 - TRACE - ASGI [1] Started scope={'type': 'lifespan', 'asgi': {'version': '3.0', 'spec_version': '2.0'}}
+2022-03-26 15:12:46,321 - TRACE - ASGI [1] Receive {'type': 'lifespan.startup'}
+2022-03-26 15:12:46,321 - TRACE - ASGI [1] Send {'type': 'lifespan.startup.complete'}
+2022-03-26 15:12:46,321 - INFO - Application startup complete.
+2022-03-26 15:12:47,830 - INFO - Shutting down
+2022-03-26 15:12:47,931 - INFO - Waiting for application shutdown.
+2022-03-26 15:12:47,932 - TRACE - ASGI [1] Receive {'type': 'lifespan.shutdown'}
+2022-03-26 15:12:47,932 - TRACE - ASGI [1] Send {'type': 'lifespan.shutdown.complete'}
+2022-03-26 15:12:47,933 - TRACE - ASGI [1] Completed
+2022-03-26 15:12:47,933 - INFO - Application shutdown complete.
+2022-03-26 15:12:47,933 - INFO - Finished server process [36543]
+2022-03-26 15:12:47,982 - INFO - Stopping reloader process [36527]
diff --git a/monitor_agent/settings.json b/monitor_agent/settings.json
@@ -2,6 +2,14 @@
     "alerts": {
         "url": "127.0.0.1:8000/alerts"
     },
+    "auth": {
+        "agent_token": "",
+        "api_token": ""
+    },
+    "logging": {
+        "filename": "monitor.log",
+        "level": "info"
+    },
     "metrics": {
         "enable_logfile": false,
         "get_endpoint": true,

diff --git a/monitor_agent/settings.py b/monitor_agent/settings.py
@@ -1,7 +1,7 @@
 import os
 import sys
 import json
-from monitor_agent.core.helper import save2log
+import logging
 
 
 rel_path = "settings.json"
@@ -12,11 +12,13 @@
 class Settings:
     def __init__(self):
         self.as_dict: dict = self._read_settings_file()
-        obj = toObj(self.as_dict)
-        self.alerts = obj.alerts
-        self.metrics = obj.metrics
-        self.thresholds = obj.thresholds
-        self.uvicorn = obj.uvicorn
+        _obj = toObj(self.as_dict)
+        self.alerts = _obj.alerts
+        self.auth = _obj.auth
+        self.logging = _obj.logging
+        self.metrics = _obj.metrics
+        self.thresholds = _obj.thresholds
+        self.uvicorn = _obj.uvicorn
 
     def _read_settings_file(self):
         try:
@@ -25,8 +27,7 @@ def _read_settings_file(self):
             data_dict = json.loads(data)
             data_str, data_dict = _write_file(data_dict, abs_file_path)
         except (json.JSONDecodeError, ValueError, FileNotFoundError) as msg:
-            print(f"ERROR: Invalid JSON settings file - {msg}", file=sys.stderr)
-            save2log(type="ERROR", data=f"Invalid JSON file - {msg}")
+            logging.error(f"Invalid JSON settings file.", exc_info=True)
             exit()
 
         return data_dict