Increase stderr logging (#263)

* Fix local appinsights logging

* Increase stderr log level but not appinsights

* Simplify logger name injection

Author: c-w

docker-compose.yml

@@ -9,7 +9,7 @@ x-shared-app-environment:
   LOKOLE_EMAIL_SERVER_QUEUES_NAMESPACE: ${LOKOLE_EMAIL_SERVER_QUEUES_NAMESPACE}
   LOKOLE_LOG_LEVEL: ${LOKOLE_LOG_LEVEL}
   LOKOLE_EMAIL_SERVER_APPINSIGHTS_KEY: ${APPINSIGHTS_INSTRUMENTATIONKEY}
-  LOKOLE_EMAIL_SERVER_APPINSIGHTS_HOST: http://appinsights
+  LOKOLE_EMAIL_SERVER_APPINSIGHTS_HOST: http://appinsights:8000
 
   LOKOLE_STORAGE_PROVIDER: AZURE_BLOBS
 
@@ -112,10 +112,11 @@ services:
     depends_on:
       - postgres
     environment:
+      PORT: "8000"
       DATABASE_URL: "postgres://${POSTGRES_USER}:${POSTGRES_PASSWORD}@postgres:5432/${POSTGRES_DB}"
       APPINSIGHTS_INSTRUMENTATIONKEY: "${APPINSIGHTS_INSTRUMENTATIONKEY}"
     ports:
-      - ${APPINSIGHTS_PORT}:80
+      - ${APPINSIGHTS_PORT}:8000
 
   postgres:
     image: postgres:11-alpine

helm/values.yaml

@@ -11,7 +11,7 @@ worker:
   queueWorkers: 1
 
 logging:
-  level: WARNING
+  level: DEBUG
 
 letsencrypt:
   email: [email protected]

opwen_email_server/config.py

@@ -30,6 +30,7 @@
 
 LOG_LEVEL = env('LOKOLE_LOG_LEVEL', 'INFO')
 
+APPINSIGHTS_LOG_LEVEL = env('LOKOLE_EMAIL_SERVER_APPINSIGHTS_LOG_LEVEL', 'WARNING')
 APPINSIGHTS_KEY = env('LOKOLE_EMAIL_SERVER_APPINSIGHTS_KEY', '')
 APPINSIGHTS_HOST = env('LOKOLE_EMAIL_SERVER_APPINSIGHTS_HOST', '')
 

opwen_email_server/constants/logging.py

@@ -1,4 +1,4 @@
 from typing_extensions import Final  # noqa: F401
 
-STDERR = '%(asctime)s\t%(levelname)s\t%(message)s'  # type: Final
-SEPARATOR = '|'  # type: Final
+APPINSIGHTS = '%(name)s\t%(message)s'  # type: Final
+STDERR = '%(asctime)s\t%(levelname)s\t%(name)s\t%(message)s'  # type: Final

opwen_email_server/services/sendgrid.py

@@ -191,7 +191,7 @@ def _run(self, client_id: str, domain: str) -> None:
                 break
 
             if retry > self._max_retries:
-                self.log_debug('Too many attempts to set up mailbox for %s', domain)
+                self.log_warning('Too many attempts to set up mailbox for %s', domain)
                 create_response.raise_for_status()
 
             sleep(self._retry_interval_seconds)

opwen_email_server/utils/log.py

@@ -1,12 +1,12 @@
 from logging import CRITICAL
 from logging import DEBUG
 from logging import INFO
+from logging import NOTSET
 from logging import WARNING
 from logging import Formatter
 from logging import Handler
 from logging import Logger
 from logging import StreamHandler
-from logging import getLevelName
 from logging import getLogger
 from typing import Any
 from typing import Iterable
@@ -17,12 +17,14 @@
 from applicationinsights.channel import AsynchronousSender
 from applicationinsights.channel import NullSender
 from applicationinsights.channel import TelemetryChannel
+from applicationinsights.logging import LoggingHandler
 from cached_property import cached_property
 
 from opwen_email_server.config import APPINSIGHTS_HOST
 from opwen_email_server.config import APPINSIGHTS_KEY
+from opwen_email_server.config import APPINSIGHTS_LOG_LEVEL
 from opwen_email_server.config import LOG_LEVEL
-from opwen_email_server.constants.logging import SEPARATOR
+from opwen_email_server.constants.logging import APPINSIGHTS
 from opwen_email_server.constants.logging import STDERR
 from opwen_email_server.utils.collections import append
 from opwen_email_server.utils.collections import singleton
@@ -45,16 +47,23 @@ def _default_log_handlers(self) -> Iterable[Handler]:
 
         stderr = StreamHandler()
         stderr.setFormatter(Formatter(STDERR))
+        stderr.setLevel(LOG_LEVEL)
         handlers.append(stderr)
 
+        appinsights = LoggingHandler(self._telemetry_key, telemetry_channel=self._telemetry_channel)
+        appinsights.setFormatter(Formatter(APPINSIGHTS))
+        appinsights.setLevel(APPINSIGHTS_LOG_LEVEL)
+        handlers.append(appinsights)
+
         return handlers
 
     @cached_property
     def _logger(self) -> Logger:
-        log = getLogger()
+        log = getLogger(self.__class__.__name__)
+        log.setLevel(NOTSET)
+        log.propagate = False
         for handler in self._default_log_handlers:
             log.addHandler(handler)
-        log.setLevel(LOG_LEVEL)
         return log
 
     @cached_property
@@ -81,17 +90,8 @@ def log_exception(self, ex: Exception, message: str, *args: Any):
             self._telemetry_channel.flush()
 
     def _log(self, level: int, log_message: str, log_args: Iterable[Any]):
-        if not self._logger.isEnabledFor(level):
-            return
-
-        message_parts = ['%s']
-        args = [self.__class__.__name__]
-        message_parts.append(log_message)
-        args.extend(log_args)
-        message = SEPARATOR.join(message_parts)
-        self._logger.log(level, message, *args)
-        self._telemetry_client.track_trace(message % tuple(args), severity=getLevelName(level))
+        self._logger.log(level, log_message, *log_args)
 
     def log_event(self, event_name: str, properties: Optional[dict] = None):
-        self.log_info('%s%s%s', event_name, SEPARATOR, properties)
+        self.log_info('%s|%s', event_name, properties)
         self._telemetry_client.track_event(event_name, properties)