diff --git a/backend/requirements/base.txt b/backend/requirements/base.txt index be0abaf45..7f135363d 100644 --- a/backend/requirements/base.txt +++ b/backend/requirements/base.txt @@ -27,4 +27,34 @@ XlsxWriter==3.1.9 pydub==0.25.1 django-celery-results==2.5.1 django-environ==0.11.2 -pytz==2024.1 \ No newline at end of file +pytz==2024.1 +opentelemetry-api==1.22.0 +opentelemetry-distro==0.43b0 +opentelemetry-exporter-otlp==1.22.0 +opentelemetry-exporter-otlp-proto-common==1.22.0 +opentelemetry-exporter-otlp-proto-grpc==1.22.0 +opentelemetry-exporter-otlp-proto-http==1.22.0 +opentelemetry-instrumentation==0.43b0 +opentelemetry-instrumentation-asgi==0.43b0 +opentelemetry-instrumentation-aws-lambda==0.43b0 +opentelemetry-instrumentation-boto3sqs==0.43b0 +opentelemetry-instrumentation-botocore==0.43b0 +opentelemetry-instrumentation-celery==0.43b0 +opentelemetry-instrumentation-dbapi==0.43b0 +opentelemetry-instrumentation-django==0.43b0 +opentelemetry-instrumentation-grpc==0.43b0 +opentelemetry-instrumentation-jinja2==0.43b0 +opentelemetry-instrumentation-logging==0.43b0 +opentelemetry-instrumentation-psycopg2==0.43b0 +opentelemetry-instrumentation-redis==0.43b0 +opentelemetry-instrumentation-requests==0.43b0 +opentelemetry-instrumentation-sqlite3==0.43b0 +opentelemetry-instrumentation-urllib==0.43b0 +opentelemetry-instrumentation-urllib3==0.43b0 +opentelemetry-instrumentation-wsgi==0.43b0 +opentelemetry-propagator-aws-xray==1.0.1 +opentelemetry-proto==1.22.0 +opentelemetry-sdk==1.22.0 +opentelemetry-semantic-conventions==0.43b0 +opentelemetry-util-http==0.43b0 +loguru==0.7.2 \ No newline at end of file diff --git a/backend/src/zelthy/cli/project_template/project_name/settings.py b/backend/src/zelthy/cli/project_template/project_name/settings.py index 4b844b0cd..b262bad5f 100644 --- a/backend/src/zelthy/cli/project_template/project_name/settings.py +++ b/backend/src/zelthy/cli/project_template/project_name/settings.py @@ -13,6 +13,8 @@ SECRET_KEY = "{{secret_key}}" +OTEL_IS_ENABLED = True + # SECURITY WARNING: don't run with debug turned on in production! DEBUG = True @@ -116,3 +118,19 @@ STATIC_ROOT = os.path.join(BASE_DIR, "static") STATIC_URL = "static/" STATICFILES_DIRS += [os.path.join(BASE_DIR, "assets")] + + +log_folder = os.path.join(BASE_DIR, 'log') +log_file = os.path.join(log_folder, 'server.log') + +# Check if the log folder exists, if not, create it +if not os.path.exists(log_folder): + os.makedirs(log_folder) + +# Check if the log file exists, if not, create it +if not os.path.exists(log_file): + with open(log_file, 'a'): + pass # Create an empty file + + +LOGGING['handlers']['file']['filename'] = log_file \ No newline at end of file diff --git a/backend/src/zelthy/cli/project_template/project_name/telementry_utlis.py b/backend/src/zelthy/cli/project_template/project_name/telementry_utlis.py new file mode 100644 index 000000000..73a4f4071 --- /dev/null +++ b/backend/src/zelthy/cli/project_template/project_name/telementry_utlis.py @@ -0,0 +1,92 @@ +import os +import uuid +import logging +import traceback +import inspect +import functools +from pathlib import Path +from opentelemetry import trace +from opentelemetry.sdk.trace import TracerProvider +from opentelemetry.sdk.trace.export import ConsoleSpanExporter +from opentelemetry.sdk.trace.export import BatchSpanProcessor +from opentelemetry.propagate import extract +from loguru import logger + +from typing import List, Optional, Union +from opentelemetry.trace import Status, StatusCode, Tracer, get_current_span + + +tracer = trace.get_tracer(__name__) + + +def _zelthy_trace_func(wrapped_func, tracer: Tracer): + @functools.wraps(wrapped_func) + def _wrapper(*args, **kwargs): + with tracer.start_as_current_span( + wrapped_func.__module__ + "." + wrapped_func.__qualname__ + ) as span: + try: + result = wrapped_func(*args, **kwargs) + except Exception as ex: + span.set_status(Status(StatusCode.ERROR)) + span.record_exception(ex) + raise ex + + return result + + return _wrapper + +def zelthy_trace_methods( + tracer: Tracer, + only: Optional[Union[str, List[str]]] = None, + exclude: Optional[Union[str, List[str]]] = None, + abc: bool = False, +): + """ + Automatically traces all public methods, or specific methods of a class depending + on the arguments. + + You need to use this if you want to say, trace every implementation of an abstract + method as decorating the method itself will get overriden by the subclasses where-as + this metaclass will wrap the method when the subclass itself is created (the class + not the instances!) + + If you want to use this metaclass and abc.ABC, use this and set abc=True. + + Using a metaclass is the python recommended way of automatically decorating + all/some functions in a class. + + :param tracer: An otel Tracer, add `tracer = trace.get_tracer(__name__)` to the top + of your file to get one. + :param only: The name of the only function you want to trace or a list of names. + :param exclude: The name of the function you do not want to trace or a list of + names. + :param abc: Whether this class should also be an abstract base class. + """ + + if only and not isinstance(only, list): + only = [only] + if exclude and not isinstance(exclude, list): + exclude = [exclude] + + super_class = ABCMeta if abc else type + + class TraceMethodsMetaClass(super_class): + def __new__(cls, name, bases, local): + for attr in local: + if cls._should_trace_attr(attr): + continue + value = local[attr] + if inspect.isfunction(value): + local[attr] = _zelthy_trace_func(value, tracer) + return super().__new__(cls, name, bases, local) + + @staticmethod + def _should_trace_attr(attr): + return ( + attr.startswith("_") + or (only and attr not in only) + or (exclude and attr in exclude) + ) + + return TraceMethodsMetaClass \ No newline at end of file diff --git a/backend/src/zelthy/cli/project_template/project_name/telemetry.py b/backend/src/zelthy/cli/project_template/project_name/telemetry.py new file mode 100644 index 000000000..5a5cd038f --- /dev/null +++ b/backend/src/zelthy/cli/project_template/project_name/telemetry.py @@ -0,0 +1,142 @@ +import os +import sys +import uuid +import logging +from pathlib import Path +from loguru import logger +from .settings import OTEL_IS_ENABLED +from opentelemetry import metrics, trace +from opentelemetry._logs import set_logger_provider +from opentelemetry.exporter.otlp.proto.http._log_exporter import OTLPLogExporter +from opentelemetry.exporter.otlp.proto.http.metric_exporter import OTLPMetricExporter +from opentelemetry.exporter.otlp.proto.http.trace_exporter import OTLPSpanExporter +from opentelemetry.instrumentation.botocore import BotocoreInstrumentor +from opentelemetry.instrumentation.celery import CeleryInstrumentor +from opentelemetry.instrumentation.django import DjangoInstrumentor +from opentelemetry.instrumentation.psycopg2 import Psycopg2Instrumentor +from opentelemetry.instrumentation.redis import RedisInstrumentor +from opentelemetry.instrumentation.requests import RequestsInstrumentor +from opentelemetry.sdk._logs import LoggerProvider, LoggingHandler +from opentelemetry.sdk._logs._internal.export import BatchLogRecordProcessor +from opentelemetry.sdk.metrics import MeterProvider +from opentelemetry.sdk.metrics._internal.export import PeriodicExportingMetricReader +from opentelemetry.trace import ProxyTracerProvider + + +from opentelemetry.sdk.trace.export import BatchSpanProcessor +from opentelemetry.sdk.trace.export import ConsoleSpanExporter +from opentelemetry.sdk.trace import TracerProvider +from opentelemetry import trace + +BASE_DIR = Path(__file__).resolve().parent.parent + + +class LogGuruCompatibleLoggerHandler(LoggingHandler): + def emit(self, record: logging.LogRecord) -> None: + # The Otel exporter does not handle nested dictionaries. Loguru stores all of + # the extra log context developers can add on the extra dict. Here unnest + # them as attributes on the record itself so otel can export them properly. + for k, v in record.extra.items(): + setattr(record, f"zelthy.{k}", v) + del record.extra + + # by default otel doesn't send funcName, rename it so it does. + setattr(record, "python_function", record.funcName) + super().emit(record) + + +def uuid_sink(record): + """ + Custom sink function that adds a UUID to each log record. + """ + # Generate a UUID for the log record + record["extra"]["uuid"] = str(uuid.uuid4()) + return record + + +def setup_logging(): + """ + This function configures loguru and optionally sets up open telemetry log exporting + using a loguru sink. + """ + + # A slightly customized default loguru format which includes the process id. + loguru_format = ( + "{extra[uuid]}|" + "{time:YYYY-MM-DD HH:mm:ss.SSS}|" + "[{extra[schema_name]}:testlogapp.zelthy.com][{extra[ip_address]}]|" + "{level}|" + "{name}:" + "{function}:" + "{line} - " + "{message}" + ) + + # Remove the default loguru stderr sink + logger.remove() + + log_folder = os.path.join(BASE_DIR, 'log') + log_file = os.path.join(log_folder, 'server.log') + + # Check if the log folder exists, if not, create it + if not os.path.exists(log_folder): + os.makedirs(log_folder) + + # Check if the log file exists, if not, create it + if not os.path.exists(log_file): + with open(log_file, 'a'): + pass # Create an empty file + + logger.add( + log_file, format=loguru_format, level="INFO", filter=uuid_sink + ) + + logger.info("Logger setup.") + + +def setup_telemetry(add_django_instrumentation: bool): + """ + Sets up logging and when the env var ZELTHY_ENABLE_OTEL is set to any non-blank + string and this function is called metrics will be setup and sent according to + the OTEL env vars you can find described at: + - https://opentelemetry.io/docs/reference/specification/protocol/exporter/ + - https://opentelemetry.io/docs/reference/specification/sdk-environment-variables/ + + :param add_django_instrumentation: Enables specific instrumentation for a django + process that is processing requests. Don't enable this for a celery process etc. + """ + + if OTEL_IS_ENABLED: + _setup_standard_backend_instrumentation() + + # # Add console exporter + # console_exporter = ConsoleSpanExporter() + # span_processor = BatchSpanProcessor(console_exporter) + # # Initialize the TracerProvider + # tracer_provider = TracerProvider() + + # # Add the BatchSpanProcessor to the TracerProvider + # tracer_provider.add_span_processor(span_processor) + + # # Configure the tracer provider + # trace.set_tracer_provider(tracer_provider) + + print("Configured default backend instrumentation") + if add_django_instrumentation: + print("Adding Django request instrumentation also.") + _setup_django_process_instrumentation() + + print("Telemetry enabled!") + + + +def _setup_standard_backend_instrumentation(): + BotocoreInstrumentor().instrument() + Psycopg2Instrumentor().instrument() + RedisInstrumentor().instrument() + RequestsInstrumentor().instrument() + CeleryInstrumentor().instrument() + + +def _setup_django_process_instrumentation(): + DjangoInstrumentor().instrument() \ No newline at end of file diff --git a/backend/src/zelthy/cli/project_template/project_name/wsgi.py b/backend/src/zelthy/cli/project_template/project_name/wsgi.py index 1f8d967ee..89acbc01e 100644 --- a/backend/src/zelthy/cli/project_template/project_name/wsgi.py +++ b/backend/src/zelthy/cli/project_template/project_name/wsgi.py @@ -1,16 +1,21 @@ """ WSGI config for testproject project. - It exposes the WSGI callable as a module-level variable named ``application``. - For more information on this file, see https://docs.djangoproject.com/en/4.2/howto/deployment/wsgi/ """ - import os - from django.core.wsgi import get_wsgi_application +from .telemetry import setup_logging, setup_telemetry +from django.db import connection + +# The telemetry instrumentation library setup needs to run prior to django's setup. +setup_telemetry(add_django_instrumentation=True) os.environ.setdefault("DJANGO_SETTINGS_MODULE", "{{project_name}}.settings") application = get_wsgi_application() + +# It is critical to setup our own logging after django has been setup and done its own +# logging setup. Otherwise Django will try to destroy and log handlers we added prior. +setup_logging() \ No newline at end of file diff --git a/backend/src/zelthy/config/settings/base.py b/backend/src/zelthy/config/settings/base.py index ee95bef43..6d48861cd 100644 --- a/backend/src/zelthy/config/settings/base.py +++ b/backend/src/zelthy/config/settings/base.py @@ -83,6 +83,7 @@ "corsheaders.middleware.CorsMiddleware", "debug_toolbar.middleware.DebugToolbarMiddleware", "zelthy.middleware.tenant.TimezoneMiddleware", + "zelthy.middleware.logging_middleware.LoggingMiddleware" ] @@ -163,3 +164,48 @@ PACKAGE_BUCKET_NAME = "zelthy3-packages" CODEASSIST_ENABLED = True + +LOGGING = { + 'version': 1, + 'disable_existing_loggers': False, + 'handlers': { + 'loguru': { + 'level': 'INFO', + 'class': 'zelthy.core.loguru_handler.LoguruHandler', + }, + 'file': { + 'level': 'INFO', + 'class': 'logging.handlers.RotatingFileHandler', + 'maxBytes': 1024*1024*5, # 5 MB + 'formatter': 'verbose', # Use the custom formatter + 'filters': ['custom_filter'], + }, + }, + 'root': { + 'handlers': ['loguru', 'file'], # Add 'file' handler here if you want to use it + 'level': 'INFO', + }, + 'formatters': { + 'verbose': { + 'format': "%(uuid)s [%(schema_name)s:%(domain_url)s][%(remote_addr)s][%(asctime)s] %(levelname)s [%(pathname)s:%(funcName)s:%(lineno)s] %(message)s %(exc_traceback_content)s", + 'datefmt': "%d/%b/%Y %H:%M:%S" + } + }, + 'filters': { + 'custom_filter': { + '()': 'zelthy.core.log_file.CustomFilter', + }, + }, + 'loggers': { + 'django.request': { + 'handlers': ['file'], + 'level': 'INFO', + 'propagate': True, + }, + 'zelthy': { + 'handlers': ['file'], + 'level': 'INFO', + 'propagate': True, + } + }, +} diff --git a/backend/src/zelthy/core/log_file.py b/backend/src/zelthy/core/log_file.py new file mode 100644 index 000000000..749ba976d --- /dev/null +++ b/backend/src/zelthy/core/log_file.py @@ -0,0 +1,59 @@ +import os +import uuid +import logging +import traceback +from django.views.generic import View +from django.http import JsonResponse +from pathlib import Path +from django.db import connection + + +# Add the middleware for capturing IP address +class IPAddressMiddleware: + def __init__(self, get_response): + self.get_response = get_response + + def __call__(self, request): + logging.request = request + response = self.get_response(request) + return response + +class CustomFilter(logging.Filter): + + def filter(self, record): + try: + record_msg = str(record.msg) + except Exception as e: + print(e) + print("Exception in str conversion of log record of type: ", type(record.msg)) + record_msg = "In Exception" + + # Extract client IP address from the request object in logging context + request = getattr(logging, 'request', None) + if request: + x_forwarded_for = request.META.get('HTTP_X_FORWARDED_FOR') + if x_forwarded_for: + record.remote_addr = x_forwarded_for.split(',')[0] + else: + record.remote_addr = request.META.get('REMOTE_ADDR') + else: + record.remote_addr = "N/A" # Default value if request object is not available + + + + record.msg = record_msg + record.uuid = str(uuid.uuid4()) + record.schema_name = connection.tenant.schema_name + record.domain_url = getattr(connection.tenant, 'domain_url', '') + + # Formatting logs containing exception traceback into single line + if record.exc_info: + ex_type, ex, tb = record.exc_info + record.exc_traceback_content = traceback.format_tb(tb) + else: + record.exc_traceback_content = "" + + splitted_path = str(record.pathname).split('/') + if 'zelthy3' in splitted_path: + record.pathname = "/".join(splitted_path[splitted_path.index('zelthy3'):]) + return True diff --git a/backend/src/zelthy/core/loguru_handler.py b/backend/src/zelthy/core/loguru_handler.py new file mode 100644 index 000000000..2eb35cf47 --- /dev/null +++ b/backend/src/zelthy/core/loguru_handler.py @@ -0,0 +1,11 @@ +import logging +from loguru import logger + +class LoguruHandler(logging.Handler): + def emit(self, record): + # Translate the log record level to Loguru's levels + level = logger.level(record.levelname).name + logger.log(level, record.getMessage()) + +# Add this handler to the root logger +logging.getLogger().addHandler(LoguruHandler()) diff --git a/backend/src/zelthy/middleware/logging_middleware.py b/backend/src/zelthy/middleware/logging_middleware.py new file mode 100644 index 000000000..614018d99 --- /dev/null +++ b/backend/src/zelthy/middleware/logging_middleware.py @@ -0,0 +1,22 @@ +import uuid +from loguru import logger +from django.http import HttpRequest + +class LoggingMiddleware: + def __init__(self, get_response): + self.get_response = get_response + + def __call__(self, request: HttpRequest): + + # Generate a UUID + log_uuid = uuid.uuid4() + + # Capture schema name and IP address + schema_name = request.tenant.schema_name + ip_address = request.META.get('REMOTE_ADDR', '127.0.0.1') + + # Use a context manager to bind the context + with logger.contextualize(schema_name=schema_name, ip_address=ip_address, log_uuid=log_uuid): + response = self.get_response(request) + + return response