logging improvements (#2073)

* Scheduled tasks log to Debug, not Info

* Add LOG_LEVEL config to .env

* Update some other log levels and fix typos

* fix logger initializer

---------

Co-authored-by: Jakob Rubin <647846+Grygon@users.noreply.github.com>

mealie/core/root_logger.py

@@ -27,6 +27,8 @@ class LoggerConfig:
 def get_logger_config():
     settings = get_app_settings()
 
+    log_level = logging._nameToLevel[settings.LOG_LEVEL]
+
     if not settings.PRODUCTION:
         from rich.logging import RichHandler
 
@@ -35,6 +37,7 @@ def get_logger_config():
             format=None,
             date_format=None,
             logger_file=None,
+            level=log_level,
         )
 
     output_file_handler = logging.FileHandler(LOGGER_FILE)
@@ -50,6 +53,7 @@ def get_logger_config():
         format="%(levelname)s: %(asctime)s \t%(message)s",
         date_format="%d-%b-%y %H:%M:%S",
         logger_file=LOGGER_FILE,
+        level=log_level,
     )
 
 

mealie/core/settings/settings.py

@@ -30,6 +30,7 @@ class AppSettings(BaseSettings):
     API_DOCS: bool = True
     TOKEN_TIME: int = 48  # Time in Hours
     SECRET: str
+    LOG_LEVEL: str = "INFO"  # Corresponds to standard Python log levels.
 
     GIT_COMMIT_HASH: str = "unknown"
 

mealie/db/init_db.py

@@ -87,7 +87,7 @@ def main():
 
         alembic_cfg = Config(str(PROJECT_DIR / "alembic.ini"))
         if db_is_at_head(alembic_cfg):
-            logger.info("Migration not needed.")
+            logger.debug("Migration not needed.")
         else:
             logger.info("Migration needed. Performing migration...")
             command.upgrade(alembic_cfg, "head")
@@ -95,7 +95,7 @@ def main():
         db = get_repositories(session)
 
         if db.users.get_all():
-            logger.info("Database exists")
+            logger.debug("Database exists")
         else:
             logger.info("Database contains no users, initializing...")
             init_db(db)

mealie/services/email/email_senders.py

@@ -96,7 +96,7 @@ class DefaultEmailSender(ABCEmailSender, BaseService):
             smtp_options.password = self.settings.SMTP_PASSWORD
 
         response = message.send(to=email_to, smtp=smtp_options)
-        self.logger.info(f"send email result: {response}")
+        self.logger.debug(f"send email result: {response}")
 
         if not response.success:
             self.logger.error(f"send email error: {response}")

mealie/services/recipe/recipe_data_service.py

@@ -156,7 +156,6 @@ class RecipeDataService(BaseService):
                 self.logger.error(f"Content-Type: {content_type} is not an image")
                 raise NotAnImageError(f"Content-Type {content_type} is not an image")
 
-            self.logger.info(f"File Name Suffix {file_path.suffix}")
+            self.logger.debug(f"File Name Suffix {file_path.suffix}")
             self.write_image(r.read(), file_path.suffix)
-
             file_path.unlink(missing_ok=True)

mealie/services/recipe/recipe_service.py

@@ -63,7 +63,7 @@ class RecipeService(BaseService):
 
             try:
                 copytree(current_dir, recipe.directory, dirs_exist_ok=True)
-                self.logger.info(f"Renaming Recipe Directory: {original_slug} -> {recipe.slug}")
+                self.logger.debug(f"Renaming Recipe Directory: {original_slug} -> {recipe.slug}")
             except FileNotFoundError:
                 self.logger.error(f"Recipe Directory not Found: {original_slug}")
 

mealie/services/scheduler/scheduler_registry.py

@@ -17,7 +17,7 @@ class SchedulerRegistry:
     @staticmethod
     def _register(name: str, callbacks: list[Callable], callback: Iterable[Callable]):
         for cb in callback:
-            logger.info(f"Registering {name} callback: {cb.__name__}")
+            logger.debug(f"Registering {name} callback: {cb.__name__}")
             callbacks.append(cb)
 
     @staticmethod
@@ -26,7 +26,7 @@ class SchedulerRegistry:
 
     @staticmethod
     def remove_daily(callback: Callable):
-        logger.info(f"Removing daily callback: {callback.__name__}")
+        logger.debug(f"Removing daily callback: {callback.__name__}")
         SchedulerRegistry._daily.remove(callback)
 
     @staticmethod
@@ -35,7 +35,7 @@ class SchedulerRegistry:
 
     @staticmethod
     def remove_hourly(callback: Callable):
-        logger.info(f"Removing hourly callback: {callback.__name__}")
+        logger.debug(f"Removing hourly callback: {callback.__name__}")
         SchedulerRegistry._hourly.remove(callback)
 
     @staticmethod
@@ -44,16 +44,16 @@ class SchedulerRegistry:
 
     @staticmethod
     def remove_minutely(callback: Callable):
-        logger.info(f"Removing minutely callback: {callback.__name__}")
+        logger.debug(f"Removing minutely callback: {callback.__name__}")
         SchedulerRegistry._minutely.remove(callback)
 
     @staticmethod
     def print_jobs():
         for job in SchedulerRegistry._daily:
-            logger.info(f"Daily job: {job.__name__}")
+            logger.debug(f"Daily job: {job.__name__}")
 
         for job in SchedulerRegistry._hourly:
-            logger.info(f"Hourly job: {job.__name__}")
+            logger.debug(f"Hourly job: {job.__name__}")
 
         for job in SchedulerRegistry._minutely:
-            logger.info(f"Minutely job: {job.__name__}")
+            logger.debug(f"Minutely job: {job.__name__}")

mealie/services/scheduler/scheduler_service.py

@@ -31,20 +31,20 @@ def _scheduled_task_wrapper(callable):
 
 @repeat_every(minutes=MINUTES_DAY, wait_first=True, logger=logger)
 def run_daily():
-    logger.info("Running daily callbacks")
+    logger.debug("Running daily callbacks")
     for func in SchedulerRegistry._daily:
         _scheduled_task_wrapper(func)
 
 
 @repeat_every(minutes=MINUTES_HOUR, wait_first=True, logger=logger)
 def run_hourly():
-    logger.info("Running hourly callbacks")
+    logger.debug("Running hourly callbacks")
     for func in SchedulerRegistry._hourly:
         _scheduled_task_wrapper(func)
 
 
 @repeat_every(minutes=MINUTES_5, wait_first=True, logger=logger)
 def run_minutely():
-    logger.info("Running minutely callbacks")
+    logger.debug("Running minutely callbacks")
     for func in SchedulerRegistry._minutely:
         _scheduled_task_wrapper(func)

mealie/services/scheduler/tasks/purge_group_exports.py

@@ -13,7 +13,7 @@ def purge_group_data_exports(max_minutes_old=ONE_DAY_AS_MINUTES):
     """Purges all group exports after x days"""
     logger = root_logger.get_logger()
 
-    logger.info("purging group data exports")
+    logger.debug("purging group data exports")
     limit = datetime.datetime.now() - datetime.timedelta(minutes=max_minutes_old)
 
     with session_context() as session:
@@ -41,6 +41,6 @@ def purge_excess_files() -> None:
         # TODO: fix comparison types
         if file.stat().st_mtime < limit:  # type: ignore
             file.unlink()
-            logger.info(f"excess group file removed '{file}'")
+            logger.debug(f"excess group file removed '{file}'")
 
     logger.info("finished purging excess files")

mealie/services/scheduler/tasks/purge_password_reset.py

@@ -11,11 +11,11 @@ MAX_DAYS_OLD = 2
 
 def purge_password_reset_tokens():
     """Purges all events after x days"""
-    logger.info("purging password reset tokens")
+    logger.debug("purging password reset tokens")
     limit = datetime.datetime.now() - datetime.timedelta(days=MAX_DAYS_OLD)
 
     with session_context() as session:
         session.query(PasswordResetModel).filter(PasswordResetModel.created_at <= limit).delete()
         session.commit()
         session.close()
-        logger.info("password reset tokens purges")
+        logger.info("password reset tokens purged")

mealie/services/scheduler/tasks/purge_registration.py

@@ -11,7 +11,7 @@ MAX_DAYS_OLD = 4
 
 def purge_group_registration():
     """Purges all events after x days"""
-    logger.info("purging expired registration tokens")
+    logger.debug("purging expired registration tokens")
     limit = datetime.datetime.now() - datetime.timedelta(days=MAX_DAYS_OLD)
 
     with session_context() as session:

mealie/services/scheduler/tasks/reset_locked_users.py

@@ -6,12 +6,12 @@ from mealie.services.user_services.user_service import UserService
 
 def locked_user_reset():
     logger = root_logger.get_logger()
-    logger.info("resetting locked users")
+    logger.debug("resetting locked users")
 
     with session_context() as session:
         repos = AllRepositories(session)
         user_service = UserService(repos)
 
         unlocked = user_service.reset_locked_users()
-        logger.info(f"scheduled task unlocked {unlocked} users in the database")
+        logger.debug(f"scheduled task unlocked {unlocked} users in the database")
         logger.info("locked users reset")

mealie/services/scraper/scraper.py

@@ -37,7 +37,7 @@ async def create_from_url(url: str) -> tuple[Recipe, ScrapedExtras | None]:
 
     new_recipe.id = uuid4()
     logger = get_logger()
-    logger.info(f"Image {new_recipe.image}")
+    logger.debug(f"Image {new_recipe.image}")
 
     recipe_data_service = RecipeDataService(new_recipe.id)