Improved logging setup with debug log files

2026-04-03 03:00:22 -04:00 · 2024-03-03 23:19:04 +01:00
parent 622915c5ad
commit 3b57d01596
16 changed files with 226 additions and 78 deletions
--- a/backend/custom_exceptions.py
+++ b/backend/custom_exceptions.py
@@ -8,13 +8,13 @@ All custom exceptions are defined here
 Note: Not all CE's inherit from CustomException.
 """

-import logging
 from typing import Any, Dict
+from backend.logging import LOGGER


 class CustomException(Exception):
 	def __init__(self, e=None) -> None:
-		logging.warning(self.__doc__)
+		LOGGER.warning(self.__doc__)
 		super().__init__(e)
 		return

@@ -29,7 +29,7 @@ class UsernameInvalid(Exception):
 	def __init__(self, username: str):
 		self.username = username
 		super().__init__(self.username)
-		logging.warning(
+		LOGGER.warning(
 			f'The username contains invalid characters: {username}'
 		)
 		return
@@ -58,7 +58,7 @@ class NotificationServiceInUse(Exception):
 	def __init__(self, type: str=''):
 		self.type = type
 		super().__init__(self.type)
-		logging.warning(
+		LOGGER.warning(
 			f'The notification is wished to be deleted but a reminder of type {type} is still using it'
 		)
 		return
@@ -80,7 +80,7 @@ class KeyNotFound(Exception):
 	def __init__(self, key: str=''):
 		self.key = key
 		super().__init__(self.key)
-		logging.warning(
+		LOGGER.warning(
 			"This key was not found in the API request,"
 			+ f" eventhough it's required: {key}"
 		)
@@ -100,7 +100,7 @@ class InvalidKeyValue(Exception):
 		self.key = key
 		self.value = value
 		super().__init__(self.key)
-		logging.warning(
+		LOGGER.warning(
 			'This key in the API request has an invalid value: ' + 
 			f'{key} = {value}'
 		)
@@ -132,3 +132,7 @@ class NewAccountsNotAllowed(CustomException):
 class InvalidDatabaseFile(CustomException):
 	"""The uploaded database file is invalid or not supported"""
 	api_response = {'error': 'InvalidDatabaseFile', 'result': {}, 'code': 400}
+
+class LogFileNotFound(CustomException):
+	"""No log file was found"""
+	api_response = {'error': 'LogFileNotFound', 'result': {}, 'code': 404}
--- a/backend/db.py
+++ b/backend/db.py
@@ -4,7 +4,6 @@
 Setting up and interacting with the database.
 """

-import logging
 from datetime import datetime
 from os import makedirs, remove
 from os.path import dirname, isfile, join
@@ -19,7 +18,7 @@ from flask import g
 from backend.custom_exceptions import (AccessUnauthorized, InvalidDatabaseFile,
                                       UserNotFound)
 from backend.helpers import RestartVars, folder_path
-from backend.logging import set_log_level
+from backend.logging import LOGGER, set_log_level

 DB_FILENAME = 'db', 'MIND.db'
 __DATABASE_VERSION__ = 10
@@ -39,14 +38,14 @@ class DBConnection(Connection, metaclass=DB_Singleton):
 	file = ''

 	def __init__(self, timeout: float) -> None:
-		logging.debug(f'Creating connection {self}')
+		LOGGER.debug(f'Creating connection {self}')
 		super().__init__(self.file, timeout=timeout)
 		super().cursor().execute("PRAGMA foreign_keys = ON;")
 		self.closed = False
 		return

 	def close(self) -> None:
-		logging.debug(f'Closing connection {self}')
+		LOGGER.debug(f'Closing connection {self}')
 		self.closed = True
 		super().close()
 		return
@@ -61,7 +60,6 @@ def setup_db_location() -> None:
 		move(folder_path('db', 'Noted.db'), folder_path(*DB_FILENAME))

 	db_location = folder_path(*DB_FILENAME)
-	logging.debug(f'Database location: {db_location}')
 	makedirs(dirname(db_location), exist_ok=True)

 	DBConnection.file = db_location
@@ -111,7 +109,7 @@ def migrate_db(current_db_version: int) -> None:
 	Migrate a MIND database from it's current version 
 	to the newest version supported by the MIND version installed.
 	"""
-	logging.info('Migrating database to newer version...')
+	LOGGER.info('Migrating database to newer version...')
 	cursor = get_db()
 	if current_db_version == 1:
 		# V1 -> V2
@@ -394,11 +392,11 @@ def setup_db() -> None:
 		)
 	)

-	set_log_level(get_setting('log_level'))
+	set_log_level(get_setting('log_level'), clear_file=False)

 	current_db_version = get_setting('database_version')
 	if current_db_version < __DATABASE_VERSION__:
-		logging.debug(
+		LOGGER.debug(
 			f'Database migration: {current_db_version} -> {__DATABASE_VERSION__}'
 		)
 		migrate_db(current_db_version)
@@ -458,7 +456,7 @@ def import_db(
 	Raises:
 		InvalidDatabaseFile: The new database file is invalid or unsupported.
 	"""
-	logging.info(f'Importing new database; {copy_hosting_settings=}')
+	LOGGER.info(f'Importing new database; {copy_hosting_settings=}')
 	try:
 		cursor = Connection(new_db_file, timeout=20.0).cursor()

@@ -469,7 +467,7 @@ def import_db(
 			raise InvalidDatabaseFile

 	except (OperationalError, InvalidDatabaseFile):
-		logging.error('Uploaded database is not a MIND database file')
+		LOGGER.error('Uploaded database is not a MIND database file')
 		cursor.connection.close()
 		revert_db_import(
 			swap=False,
@@ -478,7 +476,7 @@ def import_db(
 		raise InvalidDatabaseFile

 	if database_version > __DATABASE_VERSION__:
-		logging.error('Uploaded database is higher version than this MIND installation can support')
+		LOGGER.error('Uploaded database is higher version than this MIND installation can support')
 		revert_db_import(
 			swap=False,
 			imported_db_file=new_db_file
--- a/backend/helpers.py
+++ b/backend/helpers.py
@@ -4,7 +4,6 @@
 General functions
 """

-import logging
 from enum import Enum
 from os.path import abspath, dirname, join
 from sys import version_info
@@ -29,7 +28,9 @@ def check_python_version() -> bool:
 		bool: Whether or not the python version is version 3.8 or above or not.
 	"""
 	if not (version_info.major == 3 and version_info.minor >= 8):
-		logging.critical(
+		from backend.logging import LOGGER
+
+		LOGGER.critical(
 			'The minimum python version required is python3.8 ' + 
 			'(currently ' + str(version_info.major) + '.' + str(version_info.minor) + '.' + str(version_info.micro) + ').'
 		)
--- a/backend/logging.py
+++ b/backend/logging.py
@@ -1,27 +1,138 @@
 #-*- coding: utf-8 -*-

 import logging
+import logging.config
+from os.path import exists
+from typing import Any

+from backend.helpers import folder_path
+
+
+class InfoOnlyFilter(logging.Filter):
+	def filter(self, record: logging.LogRecord) -> bool:
+		return record.levelno == logging.INFO
+
+
+class DebuggingOnlyFilter(logging.Filter):
+	def filter(self, record: logging.LogRecord) -> bool:
+		return LOGGER.level == logging.DEBUG
+
+
+class ErrorColorFormatter(logging.Formatter):
+	def format(self, record: logging.LogRecord) -> Any:
+		result = super().format(record)
+		return f'\033[1;31:40m{result}\033[0m'
+
+
+LOGGER_NAME = "MIND"
+LOGGER_DEBUG_FILENAME = "MIND_debug.log"
+LOGGER = logging.getLogger(LOGGER_NAME)
+LOGGING_CONFIG = {
+	"version": 1,
+	"disable_existing_loggers": False,
+	"formatters": {
+		"simple": {
+			"format": "[%(asctime)s][%(levelname)s] %(message)s",
+			"datefmt": "%H:%M:%S"
+		},
+		"simple_red": {
+			"()": ErrorColorFormatter,
+			"format": "[%(asctime)s][%(levelname)s] %(message)s",
+			"datefmt": "%H:%M:%S"
+		},
+		"detailed": {
+			"format": "%(asctime)s | %(threadName)s | %(filename)sL%(lineno)s | %(levelname)s | %(message)s",
+			"datefmt": "%Y-%m-%dT%H:%M:%S%z",
+		}
+	},
+	"filters": {
+		"only_info": {
+			"()": InfoOnlyFilter
+		},
+		"only_if_debugging": {
+			"()": DebuggingOnlyFilter
+		}
+	},
+	"handlers": {
+		"console_error": {
+			"class": "logging.StreamHandler",
+			"level": "WARNING",
+			"formatter": "simple_red",
+			"stream": "ext://sys.stderr"
+		},
+		"console": {
+			"class": "logging.StreamHandler",
+			"level": "INFO",
+			"formatter": "simple",
+			"filters": ["only_info"],
+			"stream": "ext://sys.stdout"
+		},
+		"debug_file": {
+			"class": "logging.StreamHandler",
+			"level": "DEBUG",
+			"formatter": "detailed",
+			"filters": ["only_if_debugging"],
+			"stream": ""
+		}
+	},  
+	"loggers": {
+		LOGGER_NAME: {
+			"level": "INFO"
+		}
+	},
+	"root": {
+		"level": "DEBUG",
+		"handlers": [
+			"console",
+			"console_error",
+			"debug_file"
+		]
+	}
+}

 def setup_logging() -> None:
 	"Setup the basic config of the logging module"
-	logging.basicConfig(
-		level=logging.INFO,
-		format='[%(asctime)s][%(threadName)s][%(levelname)s] %(message)s',
-		datefmt='%Y-%m-%d %H:%M:%S',
-		force=True
-	)
+	logging.config.dictConfig(LOGGING_CONFIG)
 	return

-def set_log_level(level: int) -> None:
+def get_debug_log_filepath() -> str:
+	"""
+	Get the filepath to the debug logging file.
+	Not in a global variable to avoid unnecessary computation.
+	"""
+	return folder_path(LOGGER_DEBUG_FILENAME)
+
+def set_log_level(
+	level: int,
+	clear_file: bool = True
+) -> None:
 	"""Change the logging level

 	Args:
 		level (int): The level to set the logging to.
 			Should be a logging level, like `logging.INFO` or `logging.DEBUG`.
+
+		clear_file (bool, optional): Empty the debug logging file.
+			Defaults to True.
 	"""
-	logging.debug(f'Setting logging level: {level}')
-	logging.getLogger().setLevel(
-		level=level
-	)
+	LOGGER.debug(f'Setting logging level: {level}')
+	LOGGER.setLevel(level)
+
+	if level == logging.DEBUG:
+		stream_handler = logging.getLogger().handlers[
+			LOGGING_CONFIG["root"]["handlers"].index('debug_file')
+		]
+
+		file = get_debug_log_filepath()
+
+		if clear_file:
+			if exists(file):
+				open(file, "w").close()
+			else:
+				open(file, "x").close()
+
+		stream_handler.setStream(
+			open(file, "a")
+		)
+
 	return
--- a/backend/notification_service.py
+++ b/backend/notification_service.py
@@ -1,6 +1,5 @@
 #-*- coding: utf-8 -*-

-import logging
 from re import compile
 from typing import Dict, List, Optional, Union

@@ -10,6 +9,7 @@ from backend.custom_exceptions import (NotificationServiceInUse,
                                       NotificationServiceNotFound)
 from backend.db import get_db
 from backend.helpers import when_not_none
+from backend.logging import LOGGER

 remove_named_groups = compile(r'(?<=\()\?P<\w+>')

@@ -220,7 +220,7 @@ class NotificationService:
 		Returns:
 			dict: The new info about the service
 		"""	
-		logging.info(f'Updating notification service {self.id}: {title=}, {url=}')
+		LOGGER.info(f'Updating notification service {self.id}: {title=}, {url=}')

 		# Get current data and update it with new values
 		data = self.get()
@@ -253,7 +253,7 @@ class NotificationService:
 		Raises:
 			NotificationServiceInUse: The service is still used by a reminder
 		"""	
-		logging.info(f'Deleting notification service {self.id}')
+		LOGGER.info(f'Deleting notification service {self.id}')
 		
 		# Check if no reminders exist with this service
 		cursor = get_db()
@@ -344,7 +344,7 @@ class NotificationServices:
 		Returns:
 			NotificationService: The instance representing the new service
 		"""	
-		logging.info(f'Adding notification service with {title=}, {url=}')
+		LOGGER.info(f'Adding notification service with {title=}, {url=}')

 		new_id = get_db().execute("""
 			INSERT INTO notification_services(user_id, title, url)
@@ -364,7 +364,7 @@ class NotificationServices:
 		Args:
 			url (str): The Apprise URL to use to send the test notification
 		"""
-		logging.info(f'Testing service with {url=}')
+		LOGGER.info(f'Testing service with {url=}')
 		a = Apprise()
 		a.add(url)
 		a.notify(title='MIND: Test title', body='MIND: Test body')
--- a/backend/reminders.py
+++ b/backend/reminders.py
@@ -2,7 +2,6 @@

 from __future__ import annotations

-import logging
 from datetime import datetime
 from sqlite3 import IntegrityError
 from threading import Timer
@@ -18,6 +17,7 @@ from backend.custom_exceptions import (InvalidKeyValue, InvalidTime,
 from backend.db import get_db
 from backend.helpers import (RepeatQuantity, Singleton, SortingMethod,
                             search_filter, when_not_none)
+from backend.logging import LOGGER

 if TYPE_CHECKING:
 	from flask.ctx import AppContext
@@ -98,7 +98,7 @@ def _find_next_time(
 			one_to_go = False

 	result = int(new_time.timestamp())
-	logging.debug(
+	LOGGER.debug(
 		f'{original_time=}, {current_time=} ' +
 		f'and interval of {repeat_interval} {repeat_quantity} ' +
 		f'leads to {result}'
@@ -237,7 +237,7 @@ class Reminder:
 		Returns:
 			dict: The new reminder info.
 		"""
-		logging.info(
+		LOGGER.info(
 			f'Updating notification service {self.id}: '
 			+ f'{title=}, {time=}, {notification_services=}, {text=}, '
 			+ f'{repeat_quantity=}, {repeat_interval=}, {weekdays=}, {color=}'
@@ -375,7 +375,7 @@ class Reminder:
 	def delete(self) -> None:
 		"""Delete the reminder
 		"""
-		logging.info(f'Deleting reminder {self.id}')
+		LOGGER.info(f'Deleting reminder {self.id}')
 		get_db().execute("DELETE FROM reminders WHERE id = ?", (self.id,))
 		ReminderHandler().find_next_reminder()
 		return
@@ -518,7 +518,7 @@ class Reminders:
 		Returns:
 			dict: The info about the reminder.
 		"""
-		logging.info(
+		LOGGER.info(
 			f'Adding reminder with {title=}, {time=}, {notification_services=}, '
 			+ f'{text=}, {repeat_quantity=}, {repeat_interval=}, {weekdays=}, {color=}'
 		)
@@ -636,7 +636,7 @@ class Reminders:
 			text (str, optional): The body of the reminder.
 				Defaults to ''.
 		"""
-		logging.info(f'Testing reminder with {title=}, {notification_services=}, {text=}')
+		LOGGER.info(f'Testing reminder with {title=}, {notification_services=}, {text=}')
 		a = Apprise()
 		cursor = get_db(dict)

--- a/backend/server.py
+++ b/backend/server.py
@@ -2,7 +2,6 @@

 from __future__ import annotations

-import logging
 from os import execv, urandom
 from sys import argv
 from threading import Timer, current_thread
@@ -15,6 +14,7 @@ from werkzeug.middleware.dispatcher import DispatcherMiddleware

 from backend.db import DB_Singleton, DBConnection, close_db, revert_db_import
 from backend.helpers import RestartVars, Singleton, folder_path
+from backend.logging import LOGGER
 from backend.settings import restore_hosting_settings

 if TYPE_CHECKING:
@@ -32,8 +32,9 @@ class ThreadedTaskDispatcher(TTD):

 	def shutdown(self, cancel_pending: bool = True, timeout: int = 5) -> bool:
 		print()
-		logging.info('Shutting down MIND')
+		LOGGER.info('Shutting down MIND')
 		result = super().shutdown(cancel_pending, timeout)
+		DBConnection(timeout=20.0).close()
 		return result


@@ -153,7 +154,7 @@ class Server(metaclass=Singleton):
 			port (int): The port to listen on.
 		"""
 		self.server = self.__create_waitress_server(host, port)
-		logging.info(f'MIND running on http://{host}:{port}{self.url_prefix}')
+		LOGGER.info(f'MIND running on http://{host}:{port}{self.url_prefix}')
 		self.server.run()

 		return
@@ -207,21 +208,21 @@ class Server(metaclass=Singleton):
 		if self.handle_flags:
 			handle_flags_pre_restart(flag)

-		logging.info('Restarting MIND')
+		LOGGER.info('Restarting MIND')
 		from MIND import __file__ as mind_file
 		execv(folder_path(mind_file), [argv[0], *self.restart_args])

 	def __revert_db(self) -> None:
 		"""Revert database import and restart.
 		"""
-		logging.warning(f'Timer for database import expired; reverting back to original file')
+		LOGGER.warning(f'Timer for database import expired; reverting back to original file')
 		self.restart(handle_flags=True)
 		return

 	def __revert_hosting(self) -> None:
 		"""Revert the hosting changes.
 		"""
-		logging.warning(f'Timer for hosting changes expired; reverting back to original settings')
+		LOGGER.warning(f'Timer for hosting changes expired; reverting back to original settings')
 		self.restart(handle_flags=True)
 		return

@@ -236,11 +237,11 @@ def handle_flags(flag: Union[None, str]) -> None:
 		flag (Union[None, str]): The flag or `None` if there is no flag set.
 	"""
 	if flag == RestartVars.DB_IMPORT:
-		logging.info('Starting timer for database import')
+		LOGGER.info('Starting timer for database import')
 		SERVER.revert_db_timer.start()

 	elif flag == RestartVars.HOST_CHANGE:
-		logging.info('Starting timer for hosting changes')
+		LOGGER.info('Starting timer for hosting changes')
 		SERVER.revert_hosting_timer.start()

 	return
--- a/backend/static_reminders.py
+++ b/backend/static_reminders.py
@@ -1,6 +1,5 @@
 #-*- coding: utf-8 -*-

-import logging
 from sqlite3 import IntegrityError
 from typing import List, Optional, Union

@@ -10,6 +9,7 @@ from backend.custom_exceptions import (NotificationServiceNotFound,
                                       ReminderNotFound)
 from backend.db import get_db
 from backend.helpers import TimelessSortingMethod, search_filter
+from backend.logging import LOGGER


 class StaticReminder:
@@ -108,7 +108,7 @@ class StaticReminder:
 		Returns:
 			dict: The new static reminder info
 		"""
-		logging.info(
+		LOGGER.info(
 			f'Updating static reminder {self.id}: '
 			+ f'{title=}, {notification_services=}, {text=}, {color=}'
 		)
@@ -168,7 +168,7 @@ class StaticReminder:
 	def delete(self) -> None:
 		"""Delete the static reminder
 		"""
-		logging.info(f'Deleting static reminder {self.id}')
+		LOGGER.info(f'Deleting static reminder {self.id}')
 		get_db().execute("DELETE FROM static_reminders WHERE id = ?", (self.id,))
 		return

@@ -281,7 +281,7 @@ class StaticReminders:
 		Returns:
 			StaticReminder: The info about the static reminder
 		"""
-		logging.info(
+		LOGGER.info(
 			f'Adding static reminder with {title=}, {notification_services=}, {text=}, {color=}'
 		)

@@ -324,7 +324,7 @@ class StaticReminders:
 		Raises:
 			ReminderNotFound: The static reminder with the given id was not found
 		"""
-		logging.info(f'Triggering static reminder {id}')
+		LOGGER.info(f'Triggering static reminder {id}')
 		cursor = get_db(dict)
 		reminder = cursor.execute("""
 			SELECT title, text
--- a/backend/templates.py
+++ b/backend/templates.py
@@ -1,6 +1,5 @@
 #-*- coding: utf-8 -*-

-import logging
 from sqlite3 import IntegrityError
 from typing import List, Optional, Union

@@ -8,6 +7,7 @@ from backend.custom_exceptions import (NotificationServiceNotFound,
                                       TemplateNotFound)
 from backend.db import get_db
 from backend.helpers import TimelessSortingMethod, search_filter
+from backend.logging import LOGGER


 class Template:
@@ -104,7 +104,7 @@ class Template:
 		Returns:
 			dict: The new template info
 		"""
-		logging.info(
+		LOGGER.info(
 			f'Updating template {self.id}: '
 			+ f'{title=}, {notification_services=}, {text=}, {color=}'
 		)
@@ -162,7 +162,7 @@ class Template:
 	def delete(self) -> None:
 		"""Delete the template
 		"""
-		logging.info(f'Deleting template {self.id}')
+		LOGGER.info(f'Deleting template {self.id}')
 		get_db().execute("DELETE FROM templates WHERE id = ?;", (self.id,))
 		return

@@ -275,7 +275,7 @@ class Templates:
 		Returns:
 			Template: The info about the template
 		"""
-		logging.info(
+		LOGGER.info(
 			f'Adding template with {title=}, {notification_services=}, {text=}, {color=}'
 		)

--- a/backend/users.py
+++ b/backend/users.py
@@ -1,12 +1,12 @@
 #-*- coding: utf-8 -*-

-import logging
 from typing import List

 from backend.custom_exceptions import (AccessUnauthorized,
                                       NewAccountsNotAllowed, UsernameInvalid,
                                       UsernameTaken, UserNotFound)
 from backend.db import get_db
+from backend.logging import LOGGER
 from backend.notification_service import NotificationServices
 from backend.reminders import Reminders
 from backend.security import generate_salt_hash, get_hash
@@ -97,7 +97,7 @@ class User:
 			"UPDATE users SET hash = ? WHERE id = ?",
 			(hash_password, self.user_id)
 		)
-		logging.info(f'The user {self.username} ({self.user_id}) changed their password')
+		LOGGER.info(f'The user {self.username} ({self.user_id}) changed their password')
 		return

 	def delete(self) -> None:
@@ -106,7 +106,7 @@ class User:
 		if self.username == 'admin':
 			raise UserNotFound

-		logging.info(f'Deleting the user {self.username} ({self.user_id})')
+		LOGGER.info(f'Deleting the user {self.username} ({self.user_id})')
 		
 		cursor = get_db()
 		cursor.execute(
@@ -141,7 +141,7 @@ class Users:
 		Raises:
 			UsernameInvalid: The username is not valid
 		"""
-		logging.debug(f'Checking the username {username}')
+		LOGGER.debug(f'Checking the username {username}')
 		if username in ONEPASS_INVALID_USERNAMES or username.isdigit():
 			raise UsernameInvalid(username)
 		if list(filter(lambda c: not c in ONEPASS_USERNAME_CHARACTERS, username)):
@@ -173,7 +173,7 @@ class Users:
 		Returns:
 			int: The id of the new user. User registered successful
 		"""
-		logging.info(f'Registering user with username {username}')
+		LOGGER.info(f'Registering user with username {username}')
 		
 		if not from_admin and not get_setting('allow_new_accounts'):
 			raise NewAccountsNotAllowed
@@ -200,7 +200,7 @@ class Users:
 			(username, salt, hashed_password)
 		).lastrowid

-		logging.debug(f'Newly registered user has id {user_id}')
+		LOGGER.debug(f'Newly registered user has id {user_id}')
 		return user_id

 	def get_all(self) -> List[dict]: