fix(opal-server): configure logging first in the gunicorn master (0.9.x) by CarlosMion · Pull Request #975 · permitio/opal

CarlosMion · 2026-10-22T14:20:14Z

Fixes Issue

PER-16361 (opal-server logging). This ports the gunicorn master logging fix from #973 to release/0.9.x, the line the 0.9.x images are built from.

The per-update and per-policy-push INFO→DEBUG changes from #973 are in a separate PR into release/0.9.x: #982. The two PRs touch different files and either can merge first.

Changes proposed

The gunicorn master configures logging before it logs anything

scripts/gunicorn_conf.py::when_ready now calls configure_logs() first, before it imports opal_server.scopes.task and runs preload_scopes().

preload_scopes also calls configure_logs() itself, but only when nothing in the process has yet. opal_common.logger.logs_configured() tells it whether that happened. So it keeps when_ready's sinks, and a caller that never configured logging still gets configured, scrubbed output.

On this line nothing configured logging in the master until now. Its output, including the SCOPES preload, went through loguru's default handler: DEBUG level, plaintext, diagnose=True and no credential scrubbing. After this change:

The preload's per-scope DEBUG lines no longer appear at the default LOG_LEVEL=INFO. These include "Sync scope:", "Initializing git fetcher", "Repo found at", "Fetching remote", "Fetch completed" and the backoff-skip lines.
Master lines use the configured format (JSON with LOG_SERIALIZE=true) and carry their real level.
Master lines are now scrubbed by the configured patcher and stream. That includes "Could not clone repo at" (still ERROR, same text) and redis_utils' "Connecting to Redis: {url}" DEBUG line, which on this line passes the URL unredacted. At INFO that line is not emitted at all.
The opal-client images use the same gunicorn_conf.py, so their master is configured too before when_ready returns at the ImportError.
A GUNICORN_CONF of your own that calls preload_scopes() gets logging configured by preload_scopes if it didn't configure it itself. If it did, its sinks are kept.

Side effects:

configure_logs() also takes over stdlib logging in the master (root InterceptHandler at level 0), so third-party records reach the configured sink at their own level, INFO included. Example: datadog.dogstatsd "Error submitting packet" WARNINGs, where no statsd agent is reachable. Workers already do this.
With LOG_TO_FILE=true, the master opens its own file sink.
A configure_logs() error now fails in the master, so gunicorn exits with code 1. Before, a worker failed to boot and gunicorn exited with code 3.

The log file is masked like the console

With LOG_TO_FILE=true, configure_logs() added the file sink as a path, which loguru opens itself, so only the patcher masked it, and the patcher covers the message and str extra values only. Rendered tracebacks and non-str extra values reached the file unmasked.

opal_common/logging_utils/scrubbing.py::CredentialScrubbingFileSink builds loguru's FileSink and is added as a stream sink, so every formatted record is masked before it is written, as CredentialScrubbingStream does for the console.
- FileSink is private loguru API. It is imported only when LOG_TO_FILE is on, so a loguru release that moves it breaks only file logging. Checked on loguru 0.7.3 (tests) and 0.6.0, the requires.txt floor.
- It keeps loguru's record on the masked text, which time-based rotation reads, and forwards stop(), so logger.remove() still closes the file and applies compression.
The file sink also took loguru's defaults, backtrace and diagnose on. It now follows OPAL_LOG_TRACEBACK and OPAL_LOG_DIAGNOSE like the console sink.
- Side effect: with the default OPAL_LOG_DIAGNOSE=false, file tracebacks no longer print frame-local variable values. Set OPAL_LOG_DIAGNOSE=true to get them back (console and file).
configuration.mdx says so under OPAL_LOG_TO_FILE.

Also

scopes/task.py::_periodic_polling drops an unused except … as e and a placeholder-less f-string (flake8 F841/F541). The message is unchanged.
The preload comment cites scripts/gunicorn_conf.py::when_ready.

Differences from #973

scopes/task.py: this line has no fix: redact auth values in error logs, callback reports and server responses #968, so preload_scopes never called configure_logs() before. The fallback above is new here.
server_log_redaction_test.py doesn't exist on this line. The preload_*_test.py files never stubbed configure_logs.
The INFO→DEBUG changes that fix(opal-server): cut per-update and policy-push INFO lines, configure master logging first #973 also carries are in fix(opal-server): cut per-update and policy-push INFO lines (0.9.x) #982 on this line.
The file-sink masking is new here; fix(opal-server): cut per-update and policy-push INFO lines, configure master logging first #973 doesn't have it yet.

Note to reviewers

opal_client/tests/data_updater_test.py::test_data_updater_with_report_callback fails locally on macOS (assert 1 == (1 + 1)), the same way on an untouched release/0.9.x. It passes in CI.

Tests

opal_server/tests/gunicorn_master_logging_test.py:

runs the real configure_logs() against a fresh loguru state whose only sink stands in for the default handler;
asserts nothing reaches that stand-in, with SCOPES on (INFO and DEBUG) and off, at import time, and in the client path;
asserts credentials are masked in the stream output and in a LOG_TO_FILE sink (its level pinned, so the environment can't empty it). The masked lines checked are the clone-failure line, in the real call shape where err lands in record["extra"], a credentialed REDIS_URL logged as a kwarg the way RedisDB does, and a rendered traceback and a dict extra value, which only the sink wrappers mask;
asserts the patcher masks the message for a sink added after configure_logs();
asserts the file sink follows OPAL_LOG_TRACEBACK and OPAL_LOG_DIAGNOSE;
asserts stdlib logging is routed into the configured sink;
asserts preload_scopes keeps logging that is already configured, and configures it when nothing did;
each check has a control arm; most of them skip configure_logs.

opal_common/tests/sensitive_text_redaction_test.py: CredentialScrubbingFileSink masks extra values and tracebacks (control arm: the plain path sink writes the credential), keeps time-based rotation working, and closes and compresses the file on logger.remove().

preload_reset_test.py and preload_metrics_namespace_test.py now have logging already configured, as when_ready does, so the preload leaves global logging alone and each test passes when run on its own.

Verified on Python 3.9.6 with pydantic 1.10.26:

pytest packages/opal-server packages/opal-common: 636 passed;
diff coverage: 100% of the production lines (gunicorn_conf.py, logger.py, scrubbing.py, scopes/task.py); the one uncovered line is a test stub's return None;
mutation-checked: removing the stream wrapper, the file wrapper or its masking, the record hand-off, the stop() forward, the file sink's backtrace or diagnose, or the patcher each fails a test.

Check List (Check all the applicable boxes)

I sign off on contributing this submission to open-source
My code follows the code style of this project.
My change requires changes to the documentation.
I have updated the documentation accordingly.
All new and existing tests passed.
This PR does not contain plagiarized content.
The title of my pull request is a short description of the requested changes.

🤖 Generated with Claude Code

capture_records() collects every record at DEBUG and, through a real INFO sink, what a sink at OPAL's default level receives, with the global credential patcher disabled. Tests that pin a log line's level use it to assert both the emitted level and that the line is absent at the deployed level. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

when_ready now calls configure_logs() before importing the scopes task and before preload_scopes. Until now nothing configured logging in the gunicorn master, so its logs - the preload's per-scope git lines, "Finished pre loading scopes..." and anything logged on import - went through loguru's default handler: DEBUG level, plaintext, no credential scrubbing. The client images share this file, so their master is configured too before when_ready returns. preload_scopes' docstring now states that it expects logging to be configured. The tests run the real configure_logs() against a loguru whose only sink stands in for that default handler, with SCOPES on and off, and each has a positive control where configure_logs is skipped. Port of the master change in #973 to release/0.9.x. Part of PER-16361. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

"[pid] Publishing data update to topics: ..." was logged at INFO for every data update, with its entries as a structured kwarg. It is now DEBUG; its text and kwargs are unchanged. The "No topics were provided" warning in the same function stays at WARNING. The tutorials and the single-topic compose example quoted the line as default-level output; they now show the remaining lines and point to OPAL_LOG_LEVEL=DEBUG for the per-update line. Port of the master change in #973 to release/0.9.x. Part of PER-16361. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

A scopes policy push logged four to five INFO lines. Keep NewCommitsCallbacks.trigger_notification's "Triggering policy update for scope" at INFO and move the rest of the chain to DEBUG: - "scope '...': Found new commits" (NewCommitsCallbacks.on_update) - "Publishing to topics" (ScopedServerSideTopicPublisher.publish) - "Refresh scope" (POST /scopes/{id}/refresh) - "Webhook listener triggered (N)" (BasePolicyWatcherTask._on_webhook) - "Repo was fetched after refresh request" (GitPolicyFetcher._should_fetch) Message texts are unchanged, as are their WARN/ERROR siblings and "Target branch was not found" (INFO). The tests pin each level, and exactly one OPAL INFO line per incremental push both from on_update and end to end from ScopesService.sync_scope against a local clone. Port of the master change in #973 to release/0.9.x. Part of PER-16361. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

Remove the unused `as e` binding and the placeholder-less f-string (flake8 F841, F541). The logged message is unchanged. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

Worker threads that earlier tests leave behind can log at any moment - here a late concurrent.futures callback error reached the default handler stand-in through a root InterceptHandler and failed test_when_ready_scopes_on_no_record_reaches_default_handler in a full run. when_ready and the stubbed preload run on the test's thread, and a real gunicorn master is a fresh process, so both the stand-in and the configured output now keep only that thread's records. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

- The per-update line is now DEBUG and the docs point readers there, so assert its logged entries carry the redacted URL; removing the call-site redact_url used to pass every test. - The master preload test's fake RedisDB now logs a credentialed REDIS_URL as a kwarg, as RedisDB does, so the masking of the master's own log setup is pinned for that line too. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

…mment Matches the docstring above it. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

configure_logs() in the master also takes over stdlib logging (a root InterceptHandler), so third-party records now reach the configured sink at their level; say so in when_ready's comment and pin it, with a control where configure_logs is skipped. The master-logging fixture now starts from a fresh process's root logger (no leftover handlers, level WARNING), so an InterceptHandler an earlier test left cannot route stdlib on its own. Also give the Redis line its own unmasked control arm and word the fake RedisDB comment so it holds where RedisDB already redacts at the call site. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

The control arm asserted the configured stream stayed empty, which holds whenever configure_logs is skipped. It now asserts no stdlib record reaches loguru at all, which fails if the fixture's fresh root logger keeps a handler an earlier test left. The test also logs an INFO record, the level whose routing the master gains. Smaller cleanups: name the saved root logger state, drop a redundant addHandler guard, give the git line its own unmasked control, keep the thread-filter notes on what they filter, and tighten wording. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

linear-code · 2026-10-22T14:20:22Z

PER-16361

Copilot

Copilot was unable to review this pull request because the user who requested the review has reached their quota limit.

master_logs replaced loguru's core and stripped the root handlers before its try block, so a failing monkeypatch after the swap skipped the teardown and left the rest of the session logging to a dead stand-in. The config patches now run first and the swap sits inside the try. The docstring also says which pytest handlers stay detached afterwards. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

"Hinted commit hash was not found" stays INFO by decision, and the PR lists it as kept, but no test caught a demotion. The new test reaches it through a real clone. The on_update parametrization gets plain ids in place of the error-message node ids. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

fastapi_websocket_pubsub logs "calling subscription callbacks" at DEBUG across the >=1.0.0,<2 range release/0.9.x pins, so a server at the default level never prints those two sample lines. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

The root-logger teardown keeps pytest's handlers and puts the saved ones back, mirroring the setup's split. A redundant hasattr assert goes: the next line reads both attributes. The hinted-hash test takes the clone from the fetcher instead of rebuilding its path. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

Copilot

Copilot was unable to review this pull request because the user who requested the review has reached their quota limit.

preload_scopes now calls configure_logs() when no configure_logs() has run in the process (opal_common.logger.logs_configured()), so a custom GUNICORN_CONF that calls it without when_ready's setup no longer logs the preload through loguru's unscrubbed default handler. when_ready still configures first, and its sinks are kept. The master logging test also enables a LOG_TO_FILE sink. That sink isn't stream-wrapped, so asserting the credential is absent from it pins the patcher. The fake clone failure now has the real call shape, whose err kwarg lands in record["extra"]. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

With "Found new commits" at DEBUG, create_policy_update's "no tracked files were affected" WARN carried only the two hashes at the default level. on_update now binds scope_id to it with logger.contextualize; the message text is unchanged. The push-chain tests also cover sync_scopes end to end (refresh-all and the periodic poll: one per-pass line plus one INFO per push) and a duplicate refresh (DEBUG only). Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

Copilot

Copilot was unable to review this pull request because the user who requested the review has insufficient remaining quota.

This PR now carries only the gunicorn master logging fix. The per-update and per-policy-push level changes, their tests, the log_capture helper and the docs move unchanged to a separate PR into release/0.9.x. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

Copilot

Copilot was unable to review this pull request because the user who requested the review has insufficient remaining quota.

zeevmoney

Approved — no CRITICAL or HIGH issues found.

Non-blocking:

MEDIUM packages/opal-server/opal_server/scopes/task.py:212 — the preload fallback makes two existing preload tests depend on test order
LOW packages/opal-server/opal_server/tests/gunicorn_master_logging_test.py:229 — no test pins the CredentialScrubbingStream wrapper on the master's stream sink
LOW packages/opal-server/opal_server/tests/gunicorn_master_logging_test.py:168 — the stand-in clone failure logs at WARNING; the real line is ERROR
LOW packages/opal-server/opal_server/tests/gunicorn_master_logging_test.py:215 — the file-sink check depends on the environment's LOG_FILE_LEVEL

Details are in the inline comments on each line.

GitPolicyFetcher._clone logs "Could not clone repo at {url}: {err}" with logger.error; the master-logging stand-in used logger.warning. Scrubbing doesn't depend on the level, but the stand-in now matches it. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

Copilot

Copilot was unable to review this pull request because the user who requested the review has insufficient remaining quota.

…6361-opal-server-log-volume-0.9.x

preload_scopes() now runs configure_logs() when nothing in the process has. These tests call it with SCOPES on, so the first of them in a session ran the real configure_logs(), whose logger.remove() dropped the capture sinks the drain-warning tests add: each failed when run on its own. As in when_ready, logging is now already configured, so the preload keeps the test's sinks and leaves global logging alone. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

The file-sink credential check relied on LOG_FILE_LEVEL keeping its INFO default; an OPAL_LOG_FILE_LEVEL above the clone line's level in the environment failed it with correct code. The fixture already pins the stream sink's settings the same way. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

With LOG_TO_FILE, configure_logs() added the file sink as a path, which loguru opens itself, so it couldn't be stream-wrapped: only the patcher masked it, and the patcher covers the message and str extras only. Rendered tracebacks and non-str extra values reached the file raw. CredentialScrubbingFileSink builds loguru's FileSink (private API, imported only when LOG_TO_FILE is on) and is added as a stream sink, so every formatted record is masked before it is written, as on the console. It keeps loguru's Message record for time-based rotation and forwards stop() so remove() still closes and compresses the file. The file sink also took loguru's defaults, backtrace and diagnose on, and so wrote frame-local values whatever OPAL_LOG_DIAGNOSE said. It now follows OPAL_LOG_TRACEBACK and OPAL_LOG_DIAGNOSE like the console sink. Tests: the master test logs a traceback and a dict extra that only the sink wrappers can mask; a new test pins the patcher for sinks added after configure_logs(), since the file check no longer isolates it. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

Copilot

Copilot was unable to review this pull request because the user who requested the review has insufficient remaining quota.

CarlosMion and others added 10 commits October 21, 2026 15:22

chore(opal-server): drop unused names in the periodic sync error log

3650bef

Remove the unused `as e` binding and the placeholder-less f-string (flake8 F841, F541). The logged message is unchanged. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

chore(opal-server): cite when_ready as path::symbol in the preload co…

70c1f52

…mment Matches the docstring above it. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

Copilot AI balanced review requested due to automatic review settings October 22, 2026 14:20

Copilot AI reviewed Oct 22, 2026

Copilot started reviewing on behalf of CarlosMion October 22, 2026 14:21

View session

CarlosMion and others added 5 commits October 22, 2026 12:16

test: parameterize the captured record type

f64e7cd

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

Copilot AI balanced review requested due to automatic review settings October 22, 2026 17:59

Copilot started reviewing on behalf of CarlosMion October 22, 2026 17:59

View session

Copilot AI reviewed Oct 22, 2026

CarlosMion and others added 2 commits October 26, 2026 14:42

Copilot AI balanced review requested due to automatic review settings October 26, 2026 19:52

Copilot started reviewing on behalf of CarlosMion October 26, 2026 19:52

View session

Copilot AI reviewed Oct 26, 2026

CarlosMion self-assigned this Oct 26, 2026

Copilot AI balanced review requested due to automatic review settings October 26, 2026 23:35

CarlosMion mentioned this pull request Oct 26, 2026

fix(opal-server): cut per-update and policy-push INFO lines (0.9.x) #982

Merged

7 tasks done

CarlosMion changed the title ~~fix(opal-server): cut per-update and policy-push INFO lines, configure master logging first (0.9.x)~~ fix(opal-server): configure logging first in the gunicorn master (0.9.x) Oct 26, 2026

Copilot started reviewing on behalf of CarlosMion October 26, 2026 23:35

View session

Copilot AI reviewed Oct 26, 2026

CarlosMion requested a review from zeevmoney October 26, 2026 23:38

zeevmoney approved these changes Oct 27, 2026

View reviewed changes

Copilot AI balanced review requested due to automatic review settings October 27, 2026 00:49

Copilot started reviewing on behalf of CarlosMion October 27, 2026 00:50

View session

Copilot AI reviewed Oct 27, 2026

CarlosMion and others added 4 commits October 26, 2026 22:08

Merge remote-tracking branch 'origin/release/0.9.x' into carlos/per-1…

60657d6

…6361-opal-server-log-volume-0.9.x

Copilot AI balanced review requested due to automatic review settings October 27, 2026 01:25

Copilot started reviewing on behalf of CarlosMion October 27, 2026 01:26

View session

Copilot AI reviewed Oct 27, 2026

CarlosMion merged commit 5c2b763 into release/0.9.x Oct 27, 2026
12 of 13 checks passed

CarlosMion deleted the carlos/per-16361-opal-server-log-volume-0.9.x branch October 27, 2026 13:43

CarlosMion mentioned this pull request Oct 27, 2026

fix(opal-server): cut per-update and policy-push INFO lines, configure master logging first #973

Merged

7 tasks done

Navigation Menu

Repository navigation

fix(opal-server): configure logging first in the gunicorn master (0.9.x) - #975

fix(opal-server): configure logging first in the gunicorn master (0.9.x)#975
CarlosMion merged 23 commits into
release/0.9.xfrom
carlos/per-16361-opal-server-log-volume-0.9.x

CarlosMion commented Oct 22, 2026 •

edited

Loading

Uh oh!

linear-code Bot commented Oct 22, 2026

Uh oh!

Copilot AI left a comment

Uh oh!

Copilot AI left a comment

Uh oh!

Copilot AI left a comment

Uh oh!

Copilot AI left a comment

Uh oh!

zeevmoney left a comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Copilot AI left a comment

Uh oh!

Copilot AI left a comment

Uh oh!

Uh oh!

Reviewers

Uh oh!

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

Conversation

CarlosMion commented Oct 22, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Fixes Issue

Changes proposed

The gunicorn master configures logging before it logs anything

The log file is masked like the console

Also

Differences from #973

Note to reviewers

Tests

Check List (Check all the applicable boxes)

Uh oh!

linear-code Bot commented Oct 22, 2026

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Uh oh!

zeevmoney left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Uh oh!

Copilot AI left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Reviewers

Uh oh!

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

CarlosMion commented Oct 22, 2026 •

edited

Loading