From fcbcef5aae523045cfb8aaef1cbecb38f814576d Mon Sep 17 00:00:00 2001 From: Oliver Date: Sat, 29 Aug 2026 08:05:16 +1000 Subject: [PATCH] Tracing fix (#12728) * Bug fix for tracing setup * Support forking against multiple PIDs * Updated documentation --- docs/docs/start/advanced.md | 24 +++ .../InvenTree/InvenTree/test_tracing.py | 144 ++++++++++++++++++ src/backend/InvenTree/InvenTree/tracing.py | 13 +- 3 files changed, 178 insertions(+), 3 deletions(-) create mode 100644 src/backend/InvenTree/InvenTree/test_tracing.py diff --git a/docs/docs/start/advanced.md b/docs/docs/start/advanced.md index 9bacc83924..820e5108df 100644 --- a/docs/docs/start/advanced.md +++ b/docs/docs/start/advanced.md @@ -90,6 +90,30 @@ This can be used to track usage and performance of the InvenTree backend and con {{ configsetting("INVENTREE_TRACING_CONSOLE") }} Print out all exports (additionally) to the console for debugging. Do not use in production | {{ configsetting("INVENTREE_TRACING_RESOURCES") }} Add additional resources to all exports. This can be used to add custom tags to the traces. Format as a dict. | +!!! warning "An endpoint is required" + Setting `INVENTREE_TRACING_ENABLED` to `True` is not enough on its own. `INVENTREE_TRACING_ENDPOINT` must also be set to a reachable OpenTelemetry collector - without it, InvenTree logs a warning at startup and does not send any traces, logs, or metrics. + +Tracing is configured once when the InvenTree backend and worker processes start, so any change to these settings requires a full restart (not just a reload) to take effect. + +### Example: sending traces to a local collector + +The following environment variables send traces, logs and metrics via gRPC to an [OpenTelemetry Collector](https://opentelemetry.io/docs/collector/) running alongside InvenTree, for example as an additional service in your `docker-compose.yml`: + +```bash +INVENTREE_TRACING_ENABLED=True +INVENTREE_TRACING_ENDPOINT=otel-collector:4317 +INVENTREE_TRACING_IS_HTTP=False +``` + +### Troubleshooting + +If traces don't seem to be reaching your collector: + +- Confirm `INVENTREE_TRACING_ENDPOINT` is set - tracing silently does nothing without it, even if `INVENTREE_TRACING_ENABLED` is `True`. +- Set `INVENTREE_TRACING_CONSOLE=True` and check the InvenTree logs for exported spans. This confirms the OpenTelemetry SDK is generating and exporting data locally, independent of whether your collector endpoint is reachable. +- Restart the InvenTree backend and worker processes after changing any tracing setting - it is only read at process startup. +- Check that `INVENTREE_TRACING_IS_HTTP` matches the protocol your collector endpoint expects. It defaults to `True` (HTTP) - set it to `False` if your endpoint only accepts gRPC. + ## Multi Site Support If your InvenTree instance is used in a multi-site environment, you can enable multi-site support. Note that supporting multiple sites is well outside the scope of most InvenTree installations. If you know what you are doing, and have a good reason to enable multi-site support, you can do so by setting the `INVENTREE_SITE_MULTI` environment variable to `True`. diff --git a/src/backend/InvenTree/InvenTree/test_tracing.py b/src/backend/InvenTree/InvenTree/test_tracing.py new file mode 100644 index 0000000000..a823d21a79 --- /dev/null +++ b/src/backend/InvenTree/InvenTree/test_tracing.py @@ -0,0 +1,144 @@ +"""Tests for OpenTelemetry tracing setup.""" + +import logging +from unittest import mock + +from django.test import SimpleTestCase + +import InvenTree.tracing as tracing + +GRPC_EXPORTER_PATCHES = [ + 'opentelemetry.exporter.otlp.proto.grpc.trace_exporter.OTLPSpanExporter', + 'opentelemetry.exporter.otlp.proto.grpc.metric_exporter.OTLPMetricExporter', + 'opentelemetry.exporter.otlp.proto.grpc._log_exporter.OTLPLogExporter', +] + +# Names of the SDK objects that setup_tracing() would otherwise construct for real - +# doing so spins up background export threads and (without a reachable collector) +# logs connection errors, so these are stubbed out for the tests below. +SDK_PATCHES = [ + 'InvenTree.tracing.TracerProvider', + 'InvenTree.tracing.BatchSpanProcessor', + 'InvenTree.tracing.MeterProvider', + 'InvenTree.tracing.PeriodicExportingMetricReader', + 'InvenTree.tracing.logs.LoggerProvider', + 'InvenTree.tracing.logs.LoggingHandler', + 'InvenTree.tracing.logs_export.BatchLogRecordProcessor', + 'InvenTree.tracing.trace.set_tracer_provider', + 'InvenTree.tracing.metrics.set_meter_provider', +] + + +class TracingSetupTest(SimpleTestCase): + """Tests for InvenTree.tracing.setup_tracing. + + setup_tracing() keeps its "already configured" state in the module-level + TRACE_PROV global, so it is reset before/after every test to keep tests isolated. + """ + + def setUp(self): + """Reset global tracing state before each test.""" + super().setUp() + tracing.TRACE_PROC = None + tracing.TRACE_PROV = None + tracing.TRACE_PID = None + + self.logger = logging.getLogger('inventree') + self.handlers_before = list(self.logger.handlers) + + def tearDown(self): + """Reset global tracing state, and remove any handlers added by setup_tracing.""" + tracing.TRACE_PROC = None + tracing.TRACE_PROV = None + tracing.TRACE_PID = None + + for handler in list(self.logger.handlers): + if handler not in self.handlers_before: + self.logger.removeHandler(handler) + + super().tearDown() + + def call_setup(self, pid=None, **kwargs): + """Call setup_tracing with all SDK/exporter classes mocked out. + + Args: + pid: If given, os.getpid() is mocked to return this value for the + duration of the call - used to simulate a forked worker process. + + Returns the mock.patch context's mocked TracerProvider class, so callers can + assert on whether tracing was actually (re)configured. + """ + targets = SDK_PATCHES + GRPC_EXPORTER_PATCHES + if pid is not None: + targets = [*targets, 'InvenTree.tracing.os.getpid'] + + patches = [mock.patch(target) for target in targets] + mocks = [patcher.start() for patcher in patches] + self.addCleanup(lambda: [patcher.stop() for patcher in patches]) + + if pid is not None: + mocks[-1].return_value = pid + + kwargs.setdefault('endpoint', 'http://localhost:4317') + kwargs.setdefault('headers', {'x-test': 'value'}) + kwargs.setdefault('is_http', False) + tracing.setup_tracing(**kwargs) + + return mocks[0] # TracerProvider mock + + def test_first_call_configures_tracing(self): + """The first call to setup_tracing must actually configure tracing. + + Regression test for a bug where the "already configured" guard checked + `trace.get_tracer_provider() is not None`. OpenTelemetry's API never returns + None here - before anything is configured it returns a ProxyTracerProvider - + so that check was always true, and setup_tracing returned immediately without + ever installing an exporter, even on the very first call. + """ + self.assertIsNone(tracing.TRACE_PROV) + + mock_tracer_provider = self.call_setup() + + mock_tracer_provider.assert_called_once() + self.assertIsNotNone(tracing.TRACE_PROV) + + def test_second_call_is_skipped(self): + """A second call to setup_tracing should not reconfigure tracing.""" + self.call_setup() + self.assertIsNotNone(tracing.TRACE_PROV) + + mock_tracer_provider = self.call_setup() + mock_tracer_provider.assert_not_called() + + def test_reconfigures_after_simulated_fork(self): + """setup_tracing must reconfigure in a forked child process, even though it inherits TRACE_PROV from the parent. + + Regression test for gunicorn's `preload_app = True`: settings (and so + setup_tracing) are imported once in the master process before workers are + forked. Each forked worker inherits TRACE_PROV via copy-on-write memory, but + the parent's BatchSpanProcessor background thread does not survive fork() + (only the forking thread continues in the child), so post_fork's explicit + setup_tracing() call must still be able to reconfigure a real exporter in + each worker rather than being skipped as "already configured". + """ + # First call, simulating the pre-fork master process (pid 100) + master_tracer_provider = self.call_setup(pid=100) + master_tracer_provider.assert_called_once() + self.assertEqual(tracing.TRACE_PID, 100) + + # Second call with the SAME pid must still be skipped (same-process guard) + same_pid_tracer_provider = self.call_setup(pid=100) + same_pid_tracer_provider.assert_not_called() + + # Second call from a DIFFERENT pid, simulating a forked worker, must reconfigure + worker_tracer_provider = self.call_setup(pid=200) + worker_tracer_provider.assert_called_once() + self.assertEqual(tracing.TRACE_PID, 200) + + def test_missing_endpoint_or_headers_skips_setup(self): + """setup_tracing should skip setup if endpoint or headers are not provided.""" + tracing.setup_tracing(endpoint=None, headers={'a': 'b'}) + self.assertIsNone(tracing.TRACE_PROV) + + tracing.setup_tracing(endpoint='http://localhost:4317', headers=None) + self.assertIsNone(tracing.TRACE_PROV) diff --git a/src/backend/InvenTree/InvenTree/tracing.py b/src/backend/InvenTree/InvenTree/tracing.py index 77122903e7..41ceb9fac8 100644 --- a/src/backend/InvenTree/InvenTree/tracing.py +++ b/src/backend/InvenTree/InvenTree/tracing.py @@ -2,6 +2,7 @@ import base64 import logging +import os from typing import Optional from opentelemetry import metrics, trace @@ -26,6 +27,7 @@ from InvenTree.version import inventreeVersion TRACE_PROC = None TRACE_PROV = None +TRACE_PID = None def setup_tracing( @@ -57,8 +59,13 @@ def setup_tracing( ) # pragma: no cover return # pragma: no cover - # check if trace is already set up - if so, skip - if trace.get_tracer_provider() is not None: + # Check if trace is already set up in this process - if so, skip. + # Gunicorn's preload_app runs this once in the master before forking workers; + # each forked worker inherits TRACE_PROV but not the exporter's background + # thread (which does not survive fork), so re-setup must still happen once + # per worker PID - hence keying the guard on the PID, not just TRACE_PROV. + global TRACE_PROC, TRACE_PROV, TRACE_PID + if TRACE_PROV is not None and os.getpid() == TRACE_PID: return # Logger configuration @@ -161,9 +168,9 @@ def setup_tracing( logger = logging.getLogger('inventree') logger.addHandler(handler) - global TRACE_PROC, TRACE_PROV TRACE_PROC = trace_processor TRACE_PROV = trace_provider + TRACE_PID = os.getpid() def setup_instruments(db_engine: str): # pragma: no cover