From edf06944e05141a125f76e7971dd88a5533c7825 Mon Sep 17 00:00:00 2001 From: Mikhail Epifanov Date: Wed, 10 Jul 2024 10:29:11 +0200 Subject: [PATCH 1/4] enable logging for whole project and add more logging to connectors --- cookbook/connectors/connector_manager.py | 17 ++++++--- cookbook/connectors/homeassistant.py | 2 +- recipes/settings.py | 45 ++++++++++++++++-------- 3 files changed, 45 insertions(+), 19 deletions(-) diff --git a/cookbook/connectors/connector_manager.py b/cookbook/connectors/connector_manager.py index e247db305..487aeca0d 100644 --- a/cookbook/connectors/connector_manager.py +++ b/cookbook/connectors/connector_manager.py @@ -5,6 +5,7 @@ import threading from asyncio import Task from dataclasses import dataclass from enum import Enum +from logging import Logger from types import UnionType from typing import List, Any, Dict, Optional, Type @@ -39,10 +40,12 @@ class Work: # 4. Work is marked as consumed, and next entry of the queue is consumed. # Each 'Work' is processed in sequential by the worker, so the throughput is about [workers * the slowest connector] class ConnectorManager: + _logger: Logger _queue: queue.Queue _listening_to_classes = REGISTERED_CLASSES | ConnectorConfig def __init__(self): + self._logger = logging.getLogger("recipes.connector") self._queue = queue.Queue(maxsize=settings.EXTERNAL_CONNECTORS_QUEUE_SIZE) self._worker = threading.Thread(target=self.worker, args=(0, self._queue,), daemon=True) self._worker.start() @@ -65,7 +68,7 @@ class ConnectorManager: try: self._queue.put_nowait(Work(instance, action_type)) except queue.Full: - logging.info(f"queue was full, so skipping {action_type} of type {type(instance)}") + self._logger.info(f"queue was full, so skipping {action_type} of type {type(instance)}") return def stop(self): @@ -74,10 +77,12 @@ class ConnectorManager: @staticmethod def worker(worker_id: int, worker_queue: queue.Queue): + logger = logging.getLogger("recipes.connector.worker") + loop = asyncio.new_event_loop() asyncio.set_event_loop(loop) - logging.info(f"started ConnectionManager worker {worker_id}") + logger.info(f"started ConnectionManager worker {worker_id}") # When multiple workers are used, please make sure the cache is shared across all threads, otherwise it might lead to un-expected behavior. _connectors_cache: Dict[int, List[Connector]] = dict() @@ -91,6 +96,8 @@ class ConnectorManager: if item is None: break + logger.debug(f"received {item.instance=} with {item.actionType=}") + # If a Connector was changed/updated, refresh connector from the database for said space refresh_connector_cache = isinstance(item.instance, ConnectorConfig) @@ -111,7 +118,7 @@ class ConnectorManager: try: connector: Optional[Connector] = ConnectorManager.get_connected_for_config(config) except BaseException: - logging.exception(f"failed to initialize {config.name}") + logger.exception(f"failed to initialize {config.name}") continue if connector is not None: @@ -123,10 +130,12 @@ class ConnectorManager: worker_queue.task_done() continue + logger.debug(f"running {len(connectors)} connectors for {item.instance=} with {item.actionType=}") + loop.run_until_complete(run_connectors(connectors, space, item.instance, item.actionType)) worker_queue.task_done() - logging.info(f"terminating ConnectionManager worker {worker_id}") + logger.info(f"terminating ConnectionManager worker {worker_id}") asyncio.set_event_loop(None) loop.close() diff --git a/cookbook/connectors/homeassistant.py b/cookbook/connectors/homeassistant.py index f824a4262..e821e2076 100644 --- a/cookbook/connectors/homeassistant.py +++ b/cookbook/connectors/homeassistant.py @@ -20,7 +20,7 @@ class HomeAssistant(Connector): if config.url[-1] != "/": config.url += "/" self._config = config - self._logger = logging.getLogger("connector.HomeAssistant") + self._logger = logging.getLogger("recipes.connector.HomeAssistant") async def homeassistant_api_call(self, method: str, path: str, data: Dict) -> str: headers = { diff --git a/recipes/settings.py b/recipes/settings.py index d9b2b6b24..5454edc95 100644 --- a/recipes/settings.py +++ b/recipes/settings.py @@ -30,6 +30,8 @@ SECRET_KEY = os.getenv('SECRET_KEY') if os.getenv('SECRET_KEY') else 'INSECURE_S DEBUG = bool(int(os.getenv('DEBUG', True))) DEBUG_TOOLBAR = bool(int(os.getenv('DEBUG_TOOLBAR', True))) +LOG_LEVEL = os.getenv("DJANGO_LOG_LEVEL", "INFO") + SOCIAL_DEFAULT_ACCESS = bool(int(os.getenv('SOCIAL_DEFAULT_ACCESS', False))) SOCIAL_DEFAULT_GROUP = os.getenv('SOCIAL_DEFAULT_GROUP', 'guest') @@ -40,6 +42,31 @@ SPACE_DEFAULT_ALLOW_SHARING = bool(int(os.getenv('SPACE_DEFAULT_ALLOW_SHARING', INTERNAL_IPS = os.getenv('INTERNAL_IPS').split(',') if os.getenv('INTERNAL_IPS') else ['127.0.0.1'] +# Django Logging +LOGGING = { + "version": 1, + "disable_existing_loggers": False, + 'formatters': { + 'verbose': { + 'format': '{levelname} {asctime} {module} {message}', + 'style': '{', + }, + }, + "handlers": { + "console": { + "class": "logging.StreamHandler", + 'formatter': 'verbose', + }, + }, + "loggers": { + 'recipes': { + 'handlers': ['console'], + 'level': LOG_LEVEL, + }, + }, +} + + # allow djangos wsgi server to server mediafiles GUNICORN_MEDIA = bool(int(os.getenv('GUNICORN_MEDIA', False))) @@ -254,22 +281,12 @@ if LDAP_AUTH: if 'AUTH_LDAP_TLS_CACERTFILE' in os.environ: AUTH_LDAP_GLOBAL_OPTIONS = {ldap.OPT_X_TLS_CACERTFILE: os.getenv('AUTH_LDAP_TLS_CACERTFILE')} if DEBUG: - LOGGING = { - "version": 1, - "disable_existing_loggers": False, - "handlers": { - "console": { - "class": "logging.StreamHandler" - } - }, - "loggers": { - "django_auth_ldap": { - "level": "DEBUG", - "handlers": ["console"] - } - }, + LOGGING["loggers"]["django_auth_ldap"] = { + "level": "DEBUG", + "handlers": ["console"] } + AUTHENTICATION_BACKENDS += [ 'django.contrib.auth.backends.ModelBackend', 'allauth.account.auth_backends.AuthenticationBackend', From 74153d79b80ed09b77d92d45b54a6c5260808a72 Mon Sep 17 00:00:00 2001 From: Mikhail Epifanov Date: Wed, 10 Jul 2024 10:56:39 +0200 Subject: [PATCH 2/4] add process and thread name aswell --- recipes/settings.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/recipes/settings.py b/recipes/settings.py index 5454edc95..d15c8effd 100644 --- a/recipes/settings.py +++ b/recipes/settings.py @@ -48,7 +48,7 @@ LOGGING = { "disable_existing_loggers": False, 'formatters': { 'verbose': { - 'format': '{levelname} {asctime} {module} {message}', + 'format': '{processName} {threadName} {levelname} {asctime} {module} {message}', 'style': '{', }, }, From f614413fb1b96f4671b1ddd49ecf5728ba19aa31 Mon Sep 17 00:00:00 2001 From: Mikhail Epifanov Date: Wed, 10 Jul 2024 11:15:40 +0200 Subject: [PATCH 3/4] use self._logger everywhere --- cookbook/connectors/homeassistant.py | 11 ++++++----- recipes/settings.py | 2 +- 2 files changed, 7 insertions(+), 6 deletions(-) diff --git a/cookbook/connectors/homeassistant.py b/cookbook/connectors/homeassistant.py index e821e2076..e2bdcc22d 100644 --- a/cookbook/connectors/homeassistant.py +++ b/cookbook/connectors/homeassistant.py @@ -17,10 +17,11 @@ class HomeAssistant(Connector): if not config.token or not config.url or not config.todo_entity: raise ValueError("config for HomeAssistantConnector in incomplete") + self._logger = logging.getLogger(f"recipes.connector.homeassistant.{config.name}") + if config.url[-1] != "/": config.url += "/" self._config = config - self._logger = logging.getLogger("recipes.connector.HomeAssistant") async def homeassistant_api_call(self, method: str, path: str, data: Dict) -> str: headers = { @@ -37,7 +38,7 @@ class HomeAssistant(Connector): item, description = _format_shopping_list_entry(shopping_list_entry) - logging.debug(f"adding {item=} to {self._config.name}") + self._logger.debug(f"adding {item=}") data = { "entity_id": self._config.todo_entity, @@ -48,7 +49,7 @@ class HomeAssistant(Connector): try: await self.homeassistant_api_call("POST", "services/todo/add_item", data) except ClientError as err: - self._logger.warning(f"[HomeAssistant {self._config.name}] Received an exception from the api: {err=}, {type(err)=}") + self._logger.warning(f"received an exception from the api: {err=}, {type(err)=}") async def on_shopping_list_entry_updated(self, space: Space, shopping_list_entry: ShoppingListEntry) -> None: if not self._config.on_shopping_list_entry_updated_enabled: @@ -66,7 +67,7 @@ class HomeAssistant(Connector): item, _ = _format_shopping_list_entry(shopping_list_entry) - logging.debug(f"removing {item=} from {self._config.name}") + self._logger.debug(f"removing {item=}") data = { "entity_id": self._config.todo_entity, @@ -77,7 +78,7 @@ class HomeAssistant(Connector): await self.homeassistant_api_call("POST", "services/todo/remove_item", data) except ClientError as err: # This error will always trigger if the item is not present/found - self._logger.debug(f"[HomeAssistant {self._config.name}] Received an exception from the api: {err=}, {type(err)=}") + self._logger.debug(f"received an exception from the api: {err=}, {type(err)=}") async def close(self) -> None: pass diff --git a/recipes/settings.py b/recipes/settings.py index d15c8effd..e2fcbd0c6 100644 --- a/recipes/settings.py +++ b/recipes/settings.py @@ -48,7 +48,7 @@ LOGGING = { "disable_existing_loggers": False, 'formatters': { 'verbose': { - 'format': '{processName} {threadName} {levelname} {asctime} {module} {message}', + "format": "{threadName} {levelname} {asctime} {name} {message}", 'style': '{', }, }, From 1b529bba101a295b2d4211f4320e34d91bb5aa59 Mon Sep 17 00:00:00 2001 From: Mikhail Epifanov Date: Sat, 13 Jul 2024 22:39:49 +0200 Subject: [PATCH 4/4] update variable name and change default to warning, add docs --- docs/system/configuration.md | 12 ++++++++++++ recipes/settings.py | 2 +- 2 files changed, 13 insertions(+), 1 deletion(-) diff --git a/docs/system/configuration.md b/docs/system/configuration.md index af5d39849..8325f3fcc 100644 --- a/docs/system/configuration.md +++ b/docs/system/configuration.md @@ -500,6 +500,18 @@ Set to `1` to enable additional query output on the search page. SQL_DEBUG=0 ``` +#### Application Log Level + +> default `WARNING` - options: [see Django Docs](https://docs.djangoproject.com/en/5.0/topics/logging/#loggers) + +Increase or decrease the logging done by application. +Please set to `DEBUG` when making a bug report. + +``` + LOG_LEVEL="DEBUG" +``` + + #### Gunicorn Log Level > default `info` - options: [see Gunicorn Docs](https://docs.gunicorn.org/en/stable/settings.html#loglevel) diff --git a/recipes/settings.py b/recipes/settings.py index e2fcbd0c6..934364121 100644 --- a/recipes/settings.py +++ b/recipes/settings.py @@ -30,7 +30,7 @@ SECRET_KEY = os.getenv('SECRET_KEY') if os.getenv('SECRET_KEY') else 'INSECURE_S DEBUG = bool(int(os.getenv('DEBUG', True))) DEBUG_TOOLBAR = bool(int(os.getenv('DEBUG_TOOLBAR', True))) -LOG_LEVEL = os.getenv("DJANGO_LOG_LEVEL", "INFO") +LOG_LEVEL = os.getenv("LOG_LEVEL", "WARNING") SOCIAL_DEFAULT_ACCESS = bool(int(os.getenv('SOCIAL_DEFAULT_ACCESS', False))) SOCIAL_DEFAULT_GROUP = os.getenv('SOCIAL_DEFAULT_GROUP', 'guest')