diff --git a/.github/workflows/main.yml b/.github/workflows/main.yml new file mode 100644 index 0000000..21f7114 --- /dev/null +++ b/.github/workflows/main.yml @@ -0,0 +1,36 @@ +name: Test and Lint + +on: + pull_request: + +jobs: + test-and-lint: + runs-on: ubuntu-latest + strategy: + matrix: + python-version: ["3.9", "3.10", "3.11", "3.12"] + env: + SCOUT_LOGS_INGEST_KEY: test-ingest-key + steps: + - uses: actions/checkout@v3 + - name: Set up Python ${{ matrix.python-version }} + uses: actions/setup-python@v4 + with: + python-version: ${{ matrix.python-version }} + + - name: Install dependencies + run: | + pip install poetry + poetry install + + - name: Run linting + run: | + poetry run task lint + + - name: Run type checking + run: | + poetry run task mypy + + - name: Run tests with coverage + run: | + poetry run task test \ No newline at end of file diff --git a/.gitignore b/.gitignore index 54aed5b..a35bf7d 100644 --- a/.gitignore +++ b/.gitignore @@ -1,5 +1,6 @@ # Python __pycache__/ +.DS_Store # generated log files *.log @@ -43,3 +44,8 @@ cover/ # mypy .mypy_cache/ +# vscode +settings.json + +# env +.env* \ No newline at end of file diff --git a/examples/dictConfig.py b/examples/dictConfig.py index fbeb105..32bd4cb 100644 --- a/examples/dictConfig.py +++ b/examples/dictConfig.py @@ -1,5 +1,5 @@ -# An example of how to use the scout handler with dictConfig, -# useful for early testing +# An example of how to use the scout handler with dictConfig, +# useful for early testing import logging import logging.config @@ -10,7 +10,7 @@ "disable_existing_loggers": False, "formatters": { "verbose": { - "format": "%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s" + "format": "%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s" # noqa E501 }, "simple": {"format": "%(levelname)s %(message)s"}, }, diff --git a/examples/flask_app.py b/examples/flask_app.py new file mode 100644 index 0000000..8b7b9c3 --- /dev/null +++ b/examples/flask_app.py @@ -0,0 +1,76 @@ +import os +from flask import Flask +import logging +from logging.config import dictConfig +from scout_apm.flask import ScoutApm + +# Logging configuration +LOGGING_CONFIG = { + "version": 1, + "disable_existing_loggers": False, + "formatters": { + "verbose": { + "format": "%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s" # noqa E501 + }, + "simple": {"format": "%(levelname)s %(message)s"}, + }, + "handlers": { + "otel": { + "level": "DEBUG", + "class": "scout_apm_python_logging.OtelScoutHandler", + "service_name": "example-python-app", + }, + "console": { + "level": "DEBUG", + "class": "logging.StreamHandler", + "formatter": "simple", + }, + }, + "loggers": { + "": { # Root logger + "handlers": ["console", "otel"], + "level": "DEBUG", + }, + }, +} + +# Apply the logging configuration +dictConfig(LOGGING_CONFIG) + +# Create Flask app +app = Flask(__name__) + +# Scout APM configuration +app.config["SCOUT_NAME"] = "Example Python App" +app.config["SCOUT_KEY"] = os.environ.get( + "SCOUT_KEY" +) # Make sure to set this environment variable + +# Initialize Scout APM +ScoutApm(app) + +# Get a logger +logger = logging.getLogger(__name__) + + +@app.route("/") +def hello(): + logger.info("Received request for hello endpoint") + return "Hello, World!" + + +@app.route("/error") +def error(): + logger.error("This is a test error") + return "Error logged", 500 + + +@app.route("/debug") +def debug(): + logger.debug("This is a debug message") + return "Debug message logged", 200 + + +if __name__ == "__main__": + logger.info("Starting Flask application") + app.run(debug=True) diff --git a/pyproject.toml b/pyproject.toml index b82db3f..9caf609 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -6,10 +6,11 @@ authors = ["Quinn Milionis "] readme = "README.md" [tool.poetry.dependencies] -python = "^3.12" +python = "^3.9" opentelemetry-api = "^1.26.0" opentelemetry-sdk = "^1.26.0" opentelemetry-exporter-otlp = "^1.26.0" +scout-apm = "^3.1.0" [tool.poetry.group.dev.dependencies] @@ -21,6 +22,7 @@ pytest-cov = "^5.0.0" flake8 = "^7.1.1" flake8-black = "^0.3.6" mypy = "^1.11.1" +flask = "^3.0.3" [tool.taskipy.tasks] test = "pytest . --cov-report=term-missing --cov=." diff --git a/scout_apm_python_logging/handler.py b/scout_apm_python_logging/handler.py index 5b32077..0f80ea5 100644 --- a/scout_apm_python_logging/handler.py +++ b/scout_apm_python_logging/handler.py @@ -1,20 +1,24 @@ import logging import os +import threading from opentelemetry import _logs from opentelemetry.exporter.otlp.proto.grpc._log_exporter import OTLPLogExporter from opentelemetry.sdk._logs import LoggerProvider, LoggingHandler from opentelemetry.sdk._logs.export import BatchLogRecordProcessor from opentelemetry.sdk.resources import Resource +from scout_apm.core.tracked_request import TrackedRequest +from scout_apm.core import scout_config class OtelScoutHandler(logging.Handler): def __init__(self, service_name): super().__init__() - self.service_name = service_name self.logger_provider = None + self.service_name = self._get_service_name(service_name) self.ingest_key = self._get_ingest_key() self.endpoint = self._get_endpoint() self.setup_logging() + self._handling_log = threading.local() def setup_logging(self): self.logger_provider = LoggerProvider( @@ -40,8 +44,43 @@ def setup_logging(self): ) def emit(self, record): - print("Emitting log") - self.otel_handler.emit(record) + if getattr(self._handling_log, "value", False): + # We're already handling a log message, don't try to get the TrackedRequest + return self.otel_handler.emit(record) + + try: + self._handling_log.value = True + scout_request = TrackedRequest.instance() + + if scout_request: + # Add Scout-specific attributes to the log record + record.scout_request_id = scout_request.request_id + record.scout_start_time = scout_request.start_time.isoformat() + if scout_request.end_time: + record.scout_end_time = scout_request.end_time.isoformat() + + # Add duration if the request is completed + if scout_request.end_time: + record.scout_duration = ( + scout_request.end_time - scout_request.start_time + ).total_seconds() + + record.service_name = self.service_name + + # Add tags + for key, value in scout_request.tags.items(): + setattr(record, f"scout_tag_{key}", value) + + # Add the current span's operation if available + current_span = scout_request.current_span() + if current_span: + record.scout_current_operation = current_span.operation + + self.otel_handler.emit(record) + except Exception as e: + print(f"Error in OtelScoutHandler.emit: {e}") + finally: + self._handling_log.value = False def close(self): if self.logger_provider: @@ -50,13 +89,37 @@ def close(self): # These getters will be replaced by a config module to read these values # from a config file or environment variables as the Scout APM agent does. + + def _get_service_name(self, provided_name): + if provided_name: + return provided_name + + # Try to get the name from Scout APM config + scout_name = scout_config.value("name") + if scout_name: + return scout_name + + return "unnamed-service" + def _get_endpoint(self): - return os.getenv( - "SCOUT_LOGS_REPORTING_ENDPOINT", "otlp.scoutotel.com:4317" + return ( + scout_config.value("logs_reporting_endpoint") or "otlp.scoutotel.com:4317" ) def _get_ingest_key(self): - ingest_key = os.getenv("SCOUT_LOGS_INGEST_KEY") + ingest_key = scout_config.value("logs_ingest_key") + if not ingest_key: + try: + from django.conf import settings + + ingest_key = getattr(settings, "SCOUT_LOGS_INGEST_KEY", None) + except ImportError: + pass + if not ingest_key: - raise ValueError("SCOUT_LOGS_INGEST_KEY is not set") - return ingest_key \ No newline at end of file + raise ValueError( + "SCOUT_LOGS_INGEST_KEY is not set, please do so in \ + your environment or django config file" + ) + + return ingest_key diff --git a/tests/unit/test_handler.py b/tests/unit/test_handler.py new file mode 100644 index 0000000..13cfb70 --- /dev/null +++ b/tests/unit/test_handler.py @@ -0,0 +1,155 @@ +import pytest +import logging +import io +from unittest.mock import patch, MagicMock +from scout_apm_python_logging.handler import OtelScoutHandler + + +@pytest.fixture +def otel_scout_handler(): + with patch("scout_apm_python_logging.handler.OTLPLogExporter"), patch( + "scout_apm_python_logging.handler.LoggerProvider" + ), patch("scout_apm_python_logging.handler.BatchLogRecordProcessor"), patch( + "scout_apm_python_logging.handler.Resource" + ): + handler = OtelScoutHandler(service_name="test-service") + yield handler + + +def test_init(otel_scout_handler): + assert otel_scout_handler.service_name == "test-service" + assert otel_scout_handler.ingest_key is not None + assert otel_scout_handler.endpoint is not None + + +@patch("scout_apm_python_logging.handler.TrackedRequest") +def test_emit_with_scout_request(mock_tracked_request, otel_scout_handler): + mock_request = MagicMock() + mock_request.request_id = "test-id" + mock_request.start_time.isoformat.return_value = "2024-03-06T12:00:00" + mock_request.end_time.isoformat.return_value = "2024-03-06T12:00:01" + mock_request.tags = {"key": "value"} + mock_tracked_request.instance.return_value = mock_request + + with patch.object(otel_scout_handler, "otel_handler") as mock_otel_handler: + record = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="", + lineno=0, + msg="Test message", + args=(), + exc_info=None, + ) + otel_scout_handler.emit(record) + + mock_otel_handler.emit.assert_called_once() + assert record.scout_request_id == "test-id" + assert record.scout_start_time == "2024-03-06T12:00:00" + assert record.scout_end_time == "2024-03-06T12:00:01" + assert record.scout_tag_key == "value" + + +@patch("scout_apm_python_logging.handler.TrackedRequest") +def test_emit_without_scout_request(mock_tracked_request, otel_scout_handler): + mock_tracked_request.instance.return_value = None + with patch.object(otel_scout_handler, "otel_handler") as mock_otel_handler: + record = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="", + lineno=0, + msg="Test message", + args=(), + exc_info=None, + ) + otel_scout_handler.emit(record) + + mock_otel_handler.emit.assert_called_once() + assert not hasattr(record, "scout_request_id") + + +def test_emit_already_handling_log(otel_scout_handler): + with patch.object(otel_scout_handler, "otel_handler") as mock_otel_handler: + # Simulate that we're already handling a log message + otel_scout_handler._handling_log.value = True + + record = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="", + lineno=0, + msg="Test message", + args=(), + exc_info=None, + ) + otel_scout_handler.emit(record) + + mock_otel_handler.emit.assert_called_once_with(record) + + otel_scout_handler._handling_log.value = False + + +def test_emit_exception_handling(otel_scout_handler): + with patch( + "scout_apm_python_logging.handler.TrackedRequest" + ) as mock_tracked_request, patch( + "sys.stdout", new_callable=io.StringIO + ) as mock_stdout: + + mock_tracked_request.instance.side_effect = Exception("Test exception") + + record = logging.LogRecord( + name="test", + level=logging.INFO, + pathname="", + lineno=0, + msg="Test message", + args=(), + exc_info=None, + ) + + otel_scout_handler.emit(record) + + # Check that the exception was caught and the error message was printed + assert ( + "Error in OtelScoutHandler.emit: Test exception" in mock_stdout.getvalue() + ) + + otel_scout_handler._handling_log.value = False + + +def test_close(otel_scout_handler): + with patch.object(otel_scout_handler.logger_provider, "shutdown") as mock_shutdown: + otel_scout_handler.close() + mock_shutdown.assert_called_once() + + +@patch("scout_apm_python_logging.handler.scout_config") +def test_get_service_name(mock_scout_config, otel_scout_handler): + mock_scout_config.value.return_value = "scout-service" + assert otel_scout_handler._get_service_name(None) == "scout-service" + assert ( + otel_scout_handler._get_service_name("provided-service") == "provided-service" + ) + mock_scout_config.value.return_value = None + assert otel_scout_handler._get_service_name(None) == "unnamed-service" + + +@patch("scout_apm_python_logging.handler.scout_config") +def test_get_endpoint(mock_scout_config, otel_scout_handler): + mock_scout_config.value.return_value = "custom.endpoint:1234" + assert otel_scout_handler._get_endpoint() == "custom.endpoint:1234" + + +@patch("scout_apm_python_logging.handler.scout_config") +def test_get_ingest_key(mock_scout_config, otel_scout_handler): + mock_scout_config.value.return_value = "test-ingest-key" + assert otel_scout_handler._get_ingest_key() == "test-ingest-key" + + +@patch("scout_apm_python_logging.handler.scout_config") +def test_get_ingest_key_not_set(mock_scout_config, otel_scout_handler): + mock_scout_config.value.return_value = None + with pytest.raises(ValueError, match="SCOUT_LOGS_INGEST_KEY is not set"): + otel_scout_handler._get_ingest_key()