diff --git a/helm/config/mapProxyUwsgi.ini b/helm/config/mapProxyUwsgi.ini index 7474272..27d4838 100644 --- a/helm/config/mapProxyUwsgi.ini +++ b/helm/config/mapProxyUwsgi.ini @@ -13,7 +13,10 @@ processes = {{ .Values.mapproxy.uwsgi.processes }} ; Maximum number of workers a threads = {{ .Values.mapproxy.uwsgi.threads }} enable-threads = true master = true -lazy-app = true ; Fork workers after app load (required for OTel) todo check this variable effect +; Load the app once in the master, then fork. Workers share the parsed mapproxy.yaml +; copy-on-write. app.py builds the OTel providers in a postfork hook so their export +; threads and gRPC channels are still created per worker — see src/app.py. +; lazy-app = false py-callos-afterfork = true ; allow workers to trap signals ; cheaper = 2 ; Minimum number of workers allowed disable-logging = {{ .Values.mapproxy.uwsgi.disableLogging }} diff --git a/readme.md b/readme.md index 845af0a..a231a32 100644 --- a/readme.md +++ b/readme.md @@ -271,7 +271,32 @@ docker compose up -d Every inbound HTTP request is wrapped in a span by `OpenTelemetryMiddleware` (outermost layer, inside CORS). Spans are exported in OTLP gRPC format to `OTEL_EXPORTER_OTLP_ENDPOINT`. -The `BatchSpanProcessor` is initialised **after** uWSGI forks workers (`--lazy-app`). This is required — initialising the processor in the master process causes its background export thread to die silently on fork. +The providers are always built **per worker, after the fork** — never in the uWSGI master. `app.py` installs instrumentation at import time against `ProxyTracer` objects, which resolve once a real provider is set. + +*When* that happens is decided by the dispatch block at the bottom of `app.py`, from `uwsgi.worker_id()`: + +| Import context | Behaviour | +| --- | --- | +| uWSGI worker — `lazy-app = true` | initialise immediately; the fork already happened | +| uWSGI master — `lazy-app = false` | defer to a `postfork` hook | +| no uWSGI (compose, tests) | initialise immediately | + +So the module is correct under either `lazy-app` setting and outside uWSGI entirely. Check `helm/config/mapProxyUwsgi.ini` for which path a given deployment actually takes. + +Why per-worker rather than in the master: + +- **The exporters' gRPC channels are not fork-safe.** grpc-python does not support forking with live channels. This is the binding constraint — the SDK's at-fork handling restarts export threads but does *not* rebuild an inherited channel. +- **It avoids depending on private SDK internals.** The at-fork machinery has already moved between versions, so relying on it for correctness is fragile even where it works. + +> **Correction.** Earlier revisions of this document claimed a master-initialised `BatchSpanProcessor` has its export thread "die silently on fork". That is **not** accurate. Verified against the SDK pinned in this image (1.44.0): `BatchSpanProcessor` delegates to `BatchProcessor` in `opentelemetry.sdk._shared_internal`, which registers an `os.register_at_fork` handler that restarts the export thread in the child — a span emitted in a forked child was exported with no `force_flush`. `PeriodicExportingMetricReader` is protected the same way, and proxy metric instruments (`_ProxyHistogram`) were confirmed to resolve post-fork too. +> +> Beware when checking this yourself: in SDK 1.7.1 the handler lived in `opentelemetry.sdk.trace.export`, so grepping that module on a current SDK reports zero and makes the protection look absent. +> +> The reasons to build post-fork are the two above, not export-thread death. + +Both providers are flushed via an `atexit` handler, so the final batch is exported on a clean interpreter shutdown. + +> **This is best-effort, not a guarantee.** uWSGI's python plugin skips `Py_Finalize()` — and therefore every Python `atexit` handler — when the worker is hijacked, when the worker is still busy serving a request, or when running in async mode. A `max-requests` or `reload-on-rss` recycle that lands while a sibling thread is mid-request will drop whatever is still queued, exactly as before this handler existed. Harakiri kills and `worker-reload-mercy` expiry (`SIGKILL`) bypass it too. Deterministic flushing on recycle would need a uWSGI-level shutdown hook rather than Python `atexit`. The gRPC channel uses a **bare `host:port`** with `insecure=True`. Passing an `http://` or `https://` prefix causes silent TLS negotiation failure. @@ -345,7 +370,7 @@ The container starts uWSGI with the following fixed flags (not configurable at r | `--socket 0.0.0.0:3031` | uwsgi binary protocol — use as nginx upstream | | `--http-socket 0.0.0.0:8080` | plain HTTP — use for liveness probes and direct access | | `--master` | master process manages workers | -| `--lazy-app` | workers load `app.py` **after** fork — required for OTel thread safety | +| `lazy-app = false` | master loads `app.py` once, then forks — workers share the parsed config copy-on-write | | `--harakiri 120` | kill workers that take > 120 s | | `--max-requests 1000` | recycle worker after 1000 requests | | `--reload-on-rss 2048` | recycle worker if RSS exceeds 2 GB | diff --git a/src/app.py b/src/app.py index 8bd1adc..f597d27 100644 --- a/src/app.py +++ b/src/app.py @@ -1,6 +1,13 @@ """ MapProxy WSGI application wrapped with OpenTelemetry instrumentation. +Load order matters here. The OTel providers own gRPC channels that are not +fork-safe, so they are built by _init_telemetry() in the worker rather than at +import time. Instrumentation is installed at import against ProxyTracers that +resolve when that call lands. The dispatch block at the bottom of this module +picks the right moment for both lazy-app settings; read it before moving +anything across that boundary. + Override the behaviour with environment variables: OTEL_SERVICE_NAME - service name reported to the collector TELEMETRY_TRACING_ENDPOINT - OTLP gRPC collector endpoint @@ -36,6 +43,7 @@ # crashes the whole app at worker startup. from mapproxy.wsgiapp import make_wsgi_app +import atexit import os import socket import logging @@ -113,63 +121,158 @@ def _probe_collector(endpoint: str) -> None: endpoint, type(exc).__name__, exc, ) -_probe_collector(_OTLP_ENDPOINT) - # ── Resource ────────────────────────────────────────────────────────────────── resource = Resource.create({ "service.name": os.getenv("OTEL_SERVICE_NAME", "mapproxy"), "service.version": _SERVICE_VERSION, }) -# ── Tracing ─────────────────────────────────────────────────────────────────── -# Sample 1-in-N requests (default 1/10 = 10%) — tune via TELEMETRY_TRACING_SAMPLING_RATIO_DENOMINATOR. -# OTLPSpanExporter (gRPC) requires a bare host:port — strip http:// and set -# insecure=True explicitly, otherwise the channel defaults to TLS and the -# handshake fails silently against a plaintext collector endpoint. -try: - _grpc_endpoint = _OTLP_ENDPOINT.replace("https://", "").replace("http://", "").rstrip("/") - _otel_log.info("[otel-trace] gRPC endpoint: %s insecure=True sampling=1/%s", - _grpc_endpoint, _SAMPLE_DENOM) - tracer_provider = TracerProvider( - resource=resource, - sampler=TraceIdRatioBased(1 / _SAMPLE_DENOM) if _TRACING_ENABLED else TraceIdRatioBased(0), - ) - tracer_provider.add_span_processor( - BatchSpanProcessor( - OTLPSpanExporter(endpoint=_grpc_endpoint, insecure=True), - max_export_batch_size=512, - export_timeout_millis=10_000, +# ── Telemetry providers ─────────────────────────────────────────────────────── +# Populated by _init_telemetry(), which MUST run post-fork. See the dispatch +# block at the bottom of this module for how that is arranged. +# +# Nothing at import scope may call trace.set_tracer_provider() / +# metrics.set_meter_provider(). Until the first such call the OTel API hands +# out ProxyTracer / proxy-instrument objects that resolve lazily on first use, +# and that indirection is what lets the instrumentors below be installed +# pre-fork while the providers they end up using are built per worker. The +# first set-provider call wins and later ones are a no-op, so a master-side +# call would permanently bind every proxy to the master's provider — including +# its fork-unsafe gRPC channels — defeating the arrangement below. +tracer_provider = None +meter_provider = None + + +def _shutdown_telemetry() -> None: + """Flush both providers so the final batch is exported before we exit. + + Workers recycle often (max-requests, reload-on-rss). Without this the spans + and metrics still sitting in the BatchSpanProcessor / PeriodicExporting- + MetricReader queues are discarded on every recycle. + + Registered via atexit, which under uWSGI is BEST-EFFORT ONLY. The python + plugin returns from uwsgi_python_atexit() without reaching Py_Finalize() -- + so without running any atexit handler -- if the worker is hijacked, is still + busy in a request, or is running async. Recycles that land while a sibling + thread is mid-request therefore still drop the queue. SIGKILL paths + (harakiri, worker-reload-mercy expiry) skip it outright. Do not treat this + as a guarantee; a uWSGI-level shutdown hook would be needed for that. + """ + if tracer_provider is not None: + try: + tracer_provider.shutdown() + _otel_log.info("[otel-trace] TracerProvider shut down — final batch flushed") + except Exception: + _otel_log.exception("[otel-trace] TracerProvider shutdown FAILED — spans may be lost") + if meter_provider is not None: + try: + meter_provider.shutdown() + _otel_log.info("[otel-metrics] MeterProvider shut down — final batch flushed") + except Exception: + _otel_log.exception("[otel-metrics] MeterProvider shutdown FAILED — metrics may be lost") + + +def _init_telemetry() -> None: + """Build the providers, their gRPC exporters, and the export threads. + + Runs post-fork. Two reasons, in order of weight: + + 1. The OTLP exporters hold gRPC channels, and grpc-python does not support + forking with live channels. The SDK's at-fork handling restarts export + threads but does NOT rebuild those channels, so this is not covered. + 2. It avoids depending on private SDK internals for correctness — that + machinery has already moved between versions (see below). + + Do NOT reintroduce the claim that a master-built provider loses its export + threads on fork. Verified against the SDK pinned in this image (1.44.0): + BatchSpanProcessor delegates to BatchProcessor in + opentelemetry.sdk._shared_internal, which registers an os.register_at_fork + handler that restarts the export thread in the child; + PeriodicExportingMetricReader registers one as well. A span emitted in a + forked child was exported with no force_flush. Note the module: in SDK + 1.7.1 that handler lived in opentelemetry.sdk.trace.export, which is why + grepping the old location reports zero and looks like it is missing. + + Calling this resolves every ProxyTracer handed out at import time. + """ + global tracer_provider, meter_provider + + _probe_collector(_OTLP_ENDPOINT) + + # ── Tracing ─────────────────────────────────────────────────────────────── + # Sample 1-in-N requests — tune via TELEMETRY_TRACING_SAMPLING_RATIO_DENOMINATOR. + # OTLPSpanExporter (gRPC) requires a bare host:port — strip http:// and set + # insecure=True explicitly, otherwise the channel defaults to TLS and the + # handshake fails silently against a plaintext collector endpoint. + try: + _grpc_endpoint = _OTLP_ENDPOINT.replace("https://", "").replace("http://", "").rstrip("/") + _otel_log.info("[otel-trace] gRPC endpoint: %s insecure=True sampling=1/%s", + _grpc_endpoint, _SAMPLE_DENOM) + _provider = TracerProvider( + resource=resource, + sampler=TraceIdRatioBased(1 / _SAMPLE_DENOM) if _TRACING_ENABLED else TraceIdRatioBased(0), ) - ) - # OTEL_TRACE_DEBUG=true → also print every span to stdout so you can - # confirm spans are being created independently of collector connectivity. - if _TRACE_DEBUG: - _otel_log.warning("[otel-trace] OTEL_TRACE_DEBUG=true — ConsoleSpanExporter active (not for production)") - tracer_provider.add_span_processor(SimpleSpanProcessor(ConsoleSpanExporter())) - trace.set_tracer_provider(tracer_provider) - _otel_log.info("[otel-trace] TracerProvider ready") -except Exception: - _otel_log.exception("[otel-trace] FAILED to initialise — tracing disabled") - tracer_provider = TracerProvider(resource=resource, sampler=TraceIdRatioBased(0)) - trace.set_tracer_provider(tracer_provider) - -# ── Metrics ─────────────────────────────────────────────────────────────────── -try: - _grpc_endpoint = _OTLP_ENDPOINT.replace("https://", "").replace("http://", "").rstrip("/") - meter_provider = MeterProvider( - resource=resource, - metric_readers=[ - PeriodicExportingMetricReader( - OTLPMetricExporter(endpoint=_grpc_endpoint, insecure=True), - export_interval_millis=60_000, + _provider.add_span_processor( + BatchSpanProcessor( + OTLPSpanExporter(endpoint=_grpc_endpoint, insecure=True), + max_export_batch_size=512, + export_timeout_millis=10_000, ) - ], - ) - metrics.set_meter_provider(meter_provider) - _otel_log.info("[otel-metrics] MeterProvider ready → %s", _grpc_endpoint) -except Exception: - _otel_log.exception("[otel-metrics] FAILED to initialise — metrics disabled") - metrics.set_meter_provider(MeterProvider(resource=resource)) + ) + # OTEL_TRACE_DEBUG=true → also print every span to stdout so you can + # confirm spans are being created independently of collector connectivity. + if _TRACE_DEBUG: + _otel_log.warning("[otel-trace] OTEL_TRACE_DEBUG=true — ConsoleSpanExporter active (not for production)") + _provider.add_span_processor(SimpleSpanProcessor(ConsoleSpanExporter())) + trace.set_tracer_provider(_provider) + _otel_log.info("[otel-trace] TracerProvider ready") + except Exception: + _otel_log.exception("[otel-trace] FAILED to initialise — tracing disabled") + try: + trace.set_tracer_provider(TracerProvider(resource=resource, sampler=TraceIdRatioBased(0))) + except Exception: + _otel_log.exception("[otel-trace] fallback provider also FAILED") + finally: + # Bind the global to what the API actually holds, never to the object we + # built. set_tracer_provider is FIRST-WINS: a second call logs + # "Overriding of current TracerProvider is not allowed" and does nothing. + # So if the block above raised *after* the set succeeded, the fallback + # provider is inert while the real one stays installed — and shutting + # down the object we built would flush an orphan and leave the live + # provider's queue unexported, the exact opposite of the intent. + # A ProxyTracerProvider (nothing installed) is not an SDK provider and + # has no shutdown(), so leave the global None in that case. + _installed = trace.get_tracer_provider() + tracer_provider = _installed if isinstance(_installed, TracerProvider) else None + + # ── Metrics ─────────────────────────────────────────────────────────────── + try: + _grpc_endpoint = _OTLP_ENDPOINT.replace("https://", "").replace("http://", "").rstrip("/") + _provider = MeterProvider( + resource=resource, + metric_readers=[ + PeriodicExportingMetricReader( + OTLPMetricExporter(endpoint=_grpc_endpoint, insecure=True), + export_interval_millis=60_000, + ) + ], + ) + metrics.set_meter_provider(_provider) + _otel_log.info("[otel-metrics] MeterProvider ready → %s", _grpc_endpoint) + except Exception: + _otel_log.exception("[otel-metrics] FAILED to initialise — metrics disabled") + try: + metrics.set_meter_provider(MeterProvider(resource=resource)) + except Exception: + _otel_log.exception("[otel-metrics] fallback provider also FAILED") + finally: + # Same first-wins hazard as the tracer provider above — see that comment. + _installed = metrics.get_meter_provider() + meter_provider = _installed if isinstance(_installed, MeterProvider) else None + + # Registered here rather than at import scope so it only ever runs in a + # process that actually owns providers. + atexit.register(_shutdown_telemetry) # ── Redis instrumentation ──────────────────────────────────────────────────────────── # request_hook enriches every Redis span with the command name and the first @@ -184,7 +287,6 @@ def _redis_request_hook(span, instance, args, kwargs): try: RedisInstrumentor().instrument( - tracer_provider=tracer_provider, request_hook=_redis_request_hook, ) _otel_log.info("[otel-redis] RedisInstrumentor active (command+key hooks enabled)") @@ -199,14 +301,13 @@ def _redis_request_hook(span, instance, args, kwargs): # Disable all three with TELEMETRY_SQL_ENABLED=false. if _SQL_ENABLED: try: - SQLite3Instrumentor().instrument(tracer_provider=tracer_provider) + SQLite3Instrumentor().instrument() _otel_log.info("[otel-sql] SQLite3Instrumentor active") except Exception: _otel_log.exception("[otel-sql] SQLite3Instrumentor FAILED to initialise") try: from opentelemetry.instrumentation.sqlalchemy import SQLAlchemyInstrumentor SQLAlchemyInstrumentor().instrument( - tracer_provider=tracer_provider, enable_commenter=True, commenter_options={}, ) @@ -216,7 +317,6 @@ def _redis_request_hook(span, instance, args, kwargs): try: from opentelemetry.instrumentation.psycopg2 import Psycopg2Instrumentor Psycopg2Instrumentor().instrument( - tracer_provider=tracer_provider, skip_dep_check=True, enable_commenter=True, ) @@ -279,7 +379,6 @@ def _boto_response_hook(span, service_name, operation_name, result): try: from opentelemetry.instrumentation.botocore import BotocoreInstrumentor BotocoreInstrumentor().instrument( - tracer_provider=tracer_provider, request_hook=_boto_request_hook, response_hook=_boto_response_hook, ) @@ -298,8 +397,8 @@ def _boto_response_hook(span, service_name, operation_name, result): try: from opentelemetry.instrumentation.requests import RequestsInstrumentor from opentelemetry.instrumentation.urllib3 import URLLib3Instrumentor - RequestsInstrumentor().instrument(tracer_provider=tracer_provider) - URLLib3Instrumentor().instrument(tracer_provider=tracer_provider) + RequestsInstrumentor().instrument() + URLLib3Instrumentor().instrument() _otel_log.info("[otel-http] RequestsInstrumentor + URLLib3Instrumentor active") except Exception: _otel_log.exception("[otel-http] HTTP instrumentors FAILED to initialise") @@ -324,6 +423,8 @@ def _boto_response_hook(span, service_name, operation_name, result): if _TILE_CACHE_TRACING: try: from mapproxy.cache.file import FileCache as _FileCache + # Runs at import, i.e. possibly pre-fork, so this is a ProxyTracer that + # resolves once _init_telemetry() sets the real provider in the worker. _tile_tracer = trace.get_tracer("mapproxy.cache.file") _orig_load_tile = _FileCache.load_tile _orig_load_tiles = _FileCache.load_tiles @@ -426,3 +527,51 @@ def _start_response(status, headers, exc_info=None): return start_response(status, filtered, exc_info) return _inner(environ, _start_response) + +# ── Telemetry initialisation (must land post-fork) ──────────────────────────── +# Everything above this point is fork-safe: instrumentors hold ProxyTracers, the +# FileCache patch is plain attribute assignment, and make_wsgi_app() builds an +# object graph that copies cleanly. The providers are not fork-safe, so where +# _init_telemetry() runs depends on which process imported this module: +# +# lazy-app = false → imported by the master, pre-fork. Defer to the postfork +# hook so each worker builds its own export threads. +# lazy-app = true → imported by the worker, i.e. after the fork already +# happened. A postfork hook would register too late and +# never fire, so initialise immediately instead. +# no uWSGI → dev server or docker-compose. Initialise immediately. +# +# The worker_id() check is what makes this module correct under either lazy-app +# setting rather than only the one currently configured. +# +# uwsgidecorators is imported only on the branch that actually needs it. It does +# more than expose decorators at import time: it raises a bare Exception (NOT an +# ImportError) when the master process is disabled, so importing it up front +# would take down every uWSGI run without `master = true` — and `need-app = true` +# turns that into a refusal to boot. Hence the narrow placement and the broad +# except. +try: + import uwsgi +except ImportError: + _otel_log.info("[otel] not running under uWSGI — initialising telemetry eagerly") + _init_telemetry() +else: + _worker_id = uwsgi.worker_id() + if _worker_id > 0: + _otel_log.info("[otel] imported inside worker %s (lazy-app=true) — " + "fork already happened, initialising telemetry now", _worker_id) + _init_telemetry() + else: + try: + from uwsgidecorators import postfork + except Exception: + # No master process, so there is no fork to hook and nothing will + # register the providers later. Initialise now rather than boot a + # worker with telemetry silently absent. + _otel_log.warning("[otel] uwsgidecorators unavailable (uWSGI master " + "disabled?) — initialising telemetry eagerly") + _init_telemetry() + else: + postfork(_init_telemetry) + _otel_log.info("[otel] imported in uWSGI master (lazy-app=false) — " + "telemetry deferred to postfork hook")