Feature/opentelemetry (#71)

* adds initial logging code

* use ASGI instrument because OpenTelemetry has problems with tracing uvicorn requests

* re-add DjangoInstrumentor again to log username + id in response hook

* fix isort

* dont use INSIGHTS_ENABLED string, just the CONNECTION_STRING

* add .devcontainer to gitignore and remove typings

* make sure to also check if there is user object on request in response hook

.gitignore

@@ -95,3 +95,6 @@ venv.bak/
 
 # Pycharm
 .idea/
+
+# VSCode
+.devcontainer/

app/main/asgi.py

@@ -10,7 +10,17 @@
 import os
 
 from django.core.asgi import get_asgi_application
+from opentelemetry.instrumentation.asgi import OpenTelemetryMiddleware
 
 os.environ.setdefault('DJANGO_SETTINGS_MODULE', 'main.settings')
 
-application = get_asgi_application()
+django_application = get_asgi_application()
+django_application = OpenTelemetryMiddleware(django_application)
+
+
+async def application(scope, receive, send):
+    """
+    Guvicorn doesn't work well with OpenTelemetry without implementing the ASGI middleware to catch requests
+    """
+    if scope["type"] == "http":
+        await django_application(scope, receive, send)

app/main/settings.py

@@ -9,8 +9,21 @@
 For the full list of settings and their values, see
 https://docs.djangoproject.com/en/4.1/ref/settings/
 """
+
 import os
 
+# Export modules to Azure Application Insights
+from azure.monitor.opentelemetry.exporter import AzureMonitorLogExporter, AzureMonitorTraceExporter
+# Opentelemetry modules needed for logging and tracing
+from opentelemetry import trace
+from opentelemetry.instrumentation.django import DjangoInstrumentor
+from opentelemetry.instrumentation.psycopg2 import Psycopg2Instrumentor
+from opentelemetry.sdk._logs import LoggerProvider, LoggingHandler
+from opentelemetry.sdk._logs.export import BatchLogRecordProcessor
+from opentelemetry.sdk.resources import Resource
+from opentelemetry.sdk.trace import TracerProvider
+from opentelemetry.sdk.trace.export import BatchSpanProcessor
+
 # Build paths inside the project like this: BASE_DIR / 'subdir'.
 BASE_DIR = os.path.dirname(os.path.dirname(os.path.abspath(__file__)))
 
@@ -25,6 +38,9 @@
 
 # SECURITY WARNING: don't run with debug turned on in production!
 DEBUG = os.getenv('DJANGO_DEBUG', False) in TRUE_VALUES
+LOGGING_LEVEL = os.getenv('LOGGING_LEVEL', 'INFO')
+
+AZURE_APPLICATION_INSIGHTS_CONNECTION_STRING = os.getenv('AZURE_APPLICATION_INSIGHTS_CONNECTION_STRING', None)
 
 ALLOWED_HOSTS = os.getenv('ALLOWED_HOSTS', '127.0.0.1,0.0.0.0,localhost').split(',')
 
@@ -229,51 +245,113 @@
 CORS_ALLOW_CREDENTIALS = True
 
 
-# Logging
-LOGGING_LEVEL = os.getenv('LOGGING_LEVEL', 'INFO')
+# Per default log to console
+LOGGING_HANDLERS = {
+    'console': {
+        'class': 'logging.StreamHandler',
+    },
+}
+LOGGER_HANDLERS = ['console', ]
+
+MONITOR_SERVICE_NAME = 'gisib-signals'
+resource: Resource = Resource.create({"service.name": MONITOR_SERVICE_NAME})
+
+tracer_provider: TracerProvider = TracerProvider(resource=resource)
+trace.set_tracer_provider(tracer_provider)
+
+
+# As required, the user id and name is attached to each request that is recorded as a span
+def response_hook(span, request, response):
+    if all([span, span.is_recording(), request.user, request.user.is_authenticated]):
+        span.set_attributes({
+            'user_id': request.user.id,
+            'username': request.user.username
+        })
+
+
+# Logs and traces will be exported to Azure Application Insights
+if AZURE_APPLICATION_INSIGHTS_CONNECTION_STRING:
+
+    # Enable exporting of traces
+    span_exporter: AzureMonitorTraceExporter = AzureMonitorTraceExporter(
+        connection_string=AZURE_APPLICATION_INSIGHTS_CONNECTION_STRING
+    )
+    tracer_provider.add_span_processor(BatchSpanProcessor(span_exporter=span_exporter))
+
+    # Enable exporting of logs
+    log_exporter: AzureMonitorLogExporter = AzureMonitorLogExporter(
+        connection_string=AZURE_APPLICATION_INSIGHTS_CONNECTION_STRING
+    )
+    logger_provider: LoggerProvider = LoggerProvider(resource=resource)
+    logger_provider.add_log_record_processor(BatchLogRecordProcessor(log_exporter, schedule_delay_millis=3000))
+
+    # Custom logging handler to attach to logging config
+    class AzureLoggingHandler(LoggingHandler):
+        def __init__(self):
+            super().__init__(logger_provider=logger_provider)
+
+    LOGGING_HANDLERS.update({
+        'azure': {
+            '()': AzureLoggingHandler,
+        }
+    })
+
+    LOGGER_HANDLERS.append('azure')
+
+# Instrument the postgres database
+# This will attach logs from the logger module to traces
+Psycopg2Instrumentor().instrument(tracer_provider=tracer_provider, skip_dep_check=True)
+DjangoInstrumentor().instrument(tracer_provider=tracer_provider, response_hook=response_hook)
+
 LOGGING = {
     'version': 1,
     'disable_existing_loggers': False,
-    'handlers': {
-        'console': {
-            'class': 'logging.StreamHandler',
+    'formatters': {
+        'elaborate': {
+            'format': '{levelname} {module}.{filename} {message}',
+            'style': '{'
+        }
+    },
+    'filters': {
+        'require_debug_true': {
+            '()': 'django.utils.log.RequireDebugTrue',
         },
     },
+    'handlers': LOGGING_HANDLERS,
     'loggers': {
-        'django': {
-            'handlers': ['console', ],
-            'level': 'DEBUG',
-        },
-        'signals_gisib': {
-            'handlers': ['console', ],
+        '': {
             'level': LOGGING_LEVEL,
+            'handlers': LOGGER_HANDLERS,
+            'propagate': False,
+        },
+        'django.utils.autoreload': {
+            'level': 'ERROR',
+            'propagate': False,
         },
     },
 }
 
-# Opencensus
-APPLICATION_INSIGHTS_CONNECTION_STRING = os.getenv('APPLICATION_INSIGHTS_CONNECTION_STRING', False)
-if APPLICATION_INSIGHTS_CONNECTION_STRING:
-    MIDDLEWARE += ['opencensus.ext.django.middleware.OpencensusMiddleware', ]
-    OPENCENSUS = {
-        'TRACE': {
-            'SAMPLER': 'opencensus.trace.samplers.ProbabilitySampler(rate=1)',
-            'EXPORTER': f'''opencensus.ext.azure.trace_exporter.AzureExporter(
-                connection_string="{APPLICATION_INSIGHTS_CONNECTION_STRING}"
-            )''',
-            'EXCLUDELIST_PATHS': [],
-        }
-    }
-
-    LOGGING['handlers'].update({
-        'application_insights': {
-            'class': 'opencensus.ext.azure.log_exporter.AzureLogHandler',
-            'connection_string': APPLICATION_INSIGHTS_CONNECTION_STRING,
+if AZURE_APPLICATION_INSIGHTS_CONNECTION_STRING:
+    LOGGING['loggers'].update({
+        "azure.monitor.opentelemetry.exporter.export._base": {
+            "handlers": LOGGER_HANDLERS,
+            "level": "ERROR",  # Set to INFO to log what is being logged to Azure
+        },
+        "azure.core.pipeline.policies.http_logging_policy": {
+            "handlers": LOGGER_HANDLERS,
+            "level": "ERROR",  # Set to INFO to log what is being logged to Azure
         },
     })
-    LOGGING['loggers']['django']['handlers'] += ['application_insights', ]
-    LOGGING['loggers']['signals_gisib']['handlers'] += ['application_insights', ]
-
+else:
+    # When in debug mode without Azure Insights, queries will be logged to console
+    LOGGING['loggers'].update({
+        'django.db.backends': {
+            'handlers': LOGGER_HANDLERS,
+            'level': LOGGING_LEVEL,
+            'propagate': False,
+            'filters': ['require_debug_true', ],
+        }
+    })
 
 # Swagger
 

app/signals_gisib/tests/test_logging.py

@@ -0,0 +1,62 @@
+import logging
+
+from django.urls import path
+from rest_framework.test import APITestCase
+
+
+def view_that_raises_exception(request):
+    raise ValueError('Test exception')
+
+
+urlpatterns = [
+    path('test-exception/', view_that_raises_exception),
+]
+
+
+class MockHandler(logging.Handler):
+    def __init__(self):
+        super().__init__()
+        self.records = []
+
+    def emit(self, record):
+        self.records.append(record)
+
+
+class LoggingTestCase(APITestCase):
+
+    def setUp(self):
+        self.logger = logging.getLogger(__name__)
+        self.mock_handler = MockHandler()
+        self.original_handlers = []
+
+        for handler in self.logger.handlers[:]:
+            self.logger.removeHandler(handler)
+            self.original_handlers.append(handler)
+
+        self.logger.addHandler(self.mock_handler)
+
+    def tearDown(self):
+        self.logger.removeHandler(self.mock_handler)
+
+        for handler in self.original_handlers:
+            self.logger.addHandler(handler)
+
+    def test_console_logging(self):
+        test_message = 'Hello test world'
+        self.logger.info(test_message)
+
+        self.assertEqual(len(self.mock_handler.records), 1)
+        self.assertEqual(self.mock_handler.records[0].getMessage(), test_message)
+
+    def test_logging_level(self):
+        self.logger.setLevel(logging.INFO)
+
+        self.logger.debug('Debug message')
+        self.logger.info('Info message')
+        self.logger.error('Error message')
+        self.logger.critical('Critical message')
+
+        self.assertEqual(len(self.mock_handler.records), 3)
+        self.assertEqual(self.mock_handler.records[0].levelname, 'INFO')
+        self.assertEqual(self.mock_handler.records[1].levelname, 'ERROR')
+        self.assertEqual(self.mock_handler.records[2].levelname, 'CRITICAL')