Repository navigation
fix(opal-server): cut per-update and policy-push INFO lines, configure master logging first - #973
Conversation
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, which no longer configures logging itself. The master's logs - the SCOPES-off "Finished pre loading scopes..." warning, the preload's per-scope git lines and anything logged on import - used to go 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. 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. The preload test that pinned configure_logs inside preload_scopes and the stubs other preload tests needed for it are removed. 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. 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.
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>
✅ Deploy Preview for opal-docs ready!
To edit notification comments on pull requests, go to your Netlify project configuration. |
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>
zeevmoney
left a comment
zeevmoney
left a comment
There was a problem hiding this comment.
Approved — no CRITICAL or HIGH issues found.
Non-blocking:
- MEDIUM
packages/opal-server/opal_server/tests/gunicorn_master_logging_test.py:197— master masking check passes with either scrubbing layer; stand-in doesn't match the real clone-error call - LOW
packages/opal-server/opal_server/scopes/service.py:78— the "no tracked files were affected" warning loses its scope at the default level - LOW
packages/opal-server/opal_server/scopes/task.py:206—preload_scopesnow depends on its caller to configure logging - LOW
packages/opal-server/opal_server/tests/scopes_push_log_levels_test.py:177— refresh-all and periodic-poll paths not exercised end to end - LOW
documentation/docs/tutorials/healthcheck_policy_and_update_callbacks.mdx:191— two remaining sample lines are DEBUG in fastapi_websocket_pubsub
Details are in the inline comments on each line.
| assert ("WARNING", "Finished pre loading scopes...") in configured | ||
| # The preload's git error line is emitted, with its credential masked. | ||
| assert any("git.example.com/org/policy.git" in m for _, m in configured) | ||
| assert CREDENTIAL not in master_logs.stream.getvalue() |
There was a problem hiding this comment.
[MEDIUM] The master masking check passes with either scrubbing layer, and the stand-in doesn't match the real clone-error call
Problem: assert CREDENTIAL not in master_logs.stream.getvalue() holds as long as either the _scrub_record_message patcher or the CredentialScrubbingStream wrapper is still installed by configure_logs(). Removing logger.configure(patcher=_scrub_record_message) from configure_logs() leaves the whole opal-server + opal-common suite green (909 passed), and so does removing the stream wrapper; only removing both fails this test. This is the one test that runs the real configure_logs() in the master, and the LOG_TO_FILE sink isn't stream-wrapped, so it depends on the patcher. The stand-in at L148 is also a message-only f-string, while the real preload line ("Could not clone repo at {url}: {err}" in git_fetcher.py) passes err as a keyword, so its value also lands in record["extra"], which only the patcher's str-extra pass covers.
Suggestion: In this test also enable LOG_TO_FILE with LOG_FILE_PATH under tmp_path and assert the credential is absent from that file (this pins the patcher), and give the stand-in the real call shape so the extra path is covered.
Example:
logger.warning(
"Could not clone repo at {url}: {err}",
url=redact_url(CREDENTIALED_REMOTE),
err=repr(Exception(f"clone failed for {CREDENTIALED_REMOTE}")),
)
...
assert CREDENTIAL not in (tmp_path / "opal.log").read_text()| return | ||
|
|
||
| logger.info( | ||
| logger.debug( |
There was a problem hiding this comment.
[LOW] The "no tracked files were affected" warning loses its scope at the default level
Problem: With "scope '…': Found new commits: old HEAD was 'a', new HEAD is 'b'" now at DEBUG, a push whose commits touch no tracked files logs only new commits detected but no tracked files were affected: 'a' -> 'b' (WARNING, from create_policy_update in policy/watcher/callbacks.py), and trigger_notification's INFO line is never reached. That warning carries only the two hashes, and nothing binds the scope id to the record. Before this change the INFO line with the same hash pair tied the warning to a scope; at INFO it can no longer be traced to a scope or repo on a multi-scope server.
Suggestion: Attach the scope to the warning rather than restoring the INFO line: pass an optional label into create_policy_update and prefix the warning with it (covers the text format), or wrap the call in with logger.contextualize(scope_id=self._scope_id): (shows only in serialized sinks).
|
|
||
| This speeds up the first sync of scopes after workers are | ||
| started. | ||
| started. Expects configure_logs() to have run; see |
There was a problem hiding this comment.
[LOW] preload_scopes now depends on its caller to configure logging
Problem: preload_scopes used to call configure_logs() itself; now it only documents "Expects configure_logs() to have run". A custom GUNICORN_CONF (read by scripts/start.sh) that calls preload_scopes() without that call logs the preload's git output through loguru's default handler, which the new comment in when_ready describes as DEBUG level, diagnose=True and no credential scrubbing. The requirement is stated only in this PR's description; GUNICORN_CONF isn't mentioned anywhere under documentation/.
Suggestion: Make it fail safe: have configure_logs() set a module-level flag, and have preload_scopes call configure_logs() only when the flag is unset (test_preload_scopes_does_not_reconfigure_logging then becomes "does not reconfigure when already configured"). If you'd rather keep it caller-owned, add a note about custom gunicorn configs to the deployment docs.
|
|
||
|
|
||
| @pytest.mark.asyncio | ||
| async def test_sync_scope_incremental_push_logs_exactly_one_info_line( |
There was a problem hiding this comment.
[LOW] The refresh-all and periodic-poll paths aren't exercised end to end
Problem: The module docstring says the exactly-one-INFO tests cover "a refresh without a hint, refresh-all, the periodic poll", but this test calls sync_scope directly. Refresh-all and the periodic poll go through ScopesService.sync_scopes / _sync_scopes_concurrently, so a per-scope INFO line added there would not fail any test. The "Repo was fetched after refresh request" demotion is tested only through the private _should_fetch with a hand-filled repos_last_fetched cache (L245).
Suggestion: Add two end-to-end cases: refresh-all through sync_scopes() (expect only the per-pass "OPAL Scopes: syncing 1 scopes in the background" line plus one "Triggering policy update" INFO), and a duplicate refresh whose req_time is taken before the first sync (expect the DEBUG "Repo was fetched after refresh request" line and no INFO). Both pass against this head.
| ``` | ||
| opal_server.data.data_update_publisher | INFO | [10] Publishing data update to topics: ['policy_data'], reason: , entries: [('https://api.country.is/23.54.6.78', 'PUT', '/users/bob/location')] | ||
| uvicorn.protocols.http.httptools_impl | INFO | 172.27.0.1:63456 - "POST /data/config HTTP/1.1" 200 | ||
| fastapi_websocket_pubsub.event_notifier | INFO | calling subscription callbacks for sub_id=0d949d8473824c8280a3ff6ab9146cd0 with topic=policy_data |
There was a problem hiding this comment.
[LOW] Two of the remaining sample lines don't appear at the default level
Problem: The sample now lists what is left at the default level, but fastapi_websocket_pubsub logs "calling subscription callbacks" with logger.debug (event_notifier.py in 1.0.1), and in a different format (calling subscription callbacks: topic=..., subscription_id=..., subscriber_id=...). At the default OPAL_LOG_LEVEL=INFO a reader sees only the access line and "Broadcasting incoming event".
Suggestion: Drop the two "calling subscription callbacks" lines from this sample, or mention them in the OPAL_LOG_LEVEL=DEBUG note below it.
- 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>
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>
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.1,<2 range OPAL allows, 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>
Fixes Issue
PER-16361: opal-server log volume. The diff makes three changes.
Changes proposed
1. The per-data-update line is DEBUG
opal_server/data/data_update_publisher.py::DataUpdatePublisher.publish_data_updates: "[pid] Publishing data update to topics: …, reason: …, entries: …" is now DEBUG (was INFO). Its message and kwargs are unchanged.LOG_LEVEL=INFO, loguru returns before it builds the record, so theentrieskwarg never reaches a serialized sink.logged_entriesis still built eagerly. A lazy build is possible, but it would need every kwarg as a callable plus a separate topics snapshot, to save about 5 µs per entry. Not worth the complexity.2. The gunicorn master configures logging before it logs anything
scripts/gunicorn_conf.py::when_readynow callsconfigure_logs()as its first statement, beforeimport opal_server.scopes.task.ScopesPolicyWatcherTask.preload_scopesno longer calls it; its docstring states that it expects logging to be configured already.opal_server.scopes.taskis imported;gunicorn_conf.pyand return at theImportError.release/0.9.xport are what remove them.GUNICORN_CONFto your own config and callpreload_scopes()from it, callconfigure_logs()first, asscripts/gunicorn_conf.py::when_readydoes.configure_logs()also takes over stdlib logging in the master (rootInterceptHandlerat 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.LOG_TO_FILE=true, a master with SCOPES off and a client master now also open their own file sink.configure_logs()error, such as an unknownLOG_LEVELor an unwritableLOG_FILE_PATH, now fails in the master and gunicorn exits with code 1. Before, a worker failed to boot and gunicorn exited with code 3.3. One OPAL INFO line per scopes policy push
opal_server/scopes/service.py::NewCommitsCallbacks.trigger_notificationopal_server/scopes/service.py::NewCommitsCallbacks.on_updateopal_common/topics/publisher.py::ScopedServerSideTopicPublisher.publishopal_server/scopes/api.py::init_scope_router.refresh_scopeopal_server/policy/watcher/task.py::BasePolicyWatcherTask._on_webhookopal_server/git_fetcher.py::GitPolicyFetcher._should_fetchWARN/ERROR lines unchanged:
_on_webhook: "Webhook trigger task failed" (ERROR).on_update: "repo path is not found" and "Got exception for repo" (ERROR).create_policy_update: "no tracked files were affected" (WARN).GitPolicyFetcher._clone: "Could not clone repo at" (ERROR)._should_fetch: "Target branch was not found" and "Hinted commit hash was not found" stay INFO.Scope of "one INFO per push". It counts OPAL's own loggers, per pod leader, on an incremental push, for a refresh without a hint, refresh-all or the periodic poll. Other INFO lines remain by design:
Third-party lines (the pubsub broadcaster's "Broadcasting incoming event", uvicorn's access log) are not covered.
Data updates.
ScopedServerSideTopicPublisher.publishalso carries scoped data updates (POST /scopes/{id}/data/update). With change 1, data updates have no OPAL INFO line at the default level. Run withOPAL_LOG_LEVEL=DEBUGto see them.Non-scopes mode. "Webhook listener triggered (N)" sits in a shared base class, so this mode is affected too; it still logs its own INFO per check from
GitPolicySource.The
(N)signal. N, the webhook task-list length, is now visible only at DEBUG. Anything that parses it, such as a memory-leak harness, needsOPAL_LOG_LEVEL=DEBUG.Docs
Two tutorials and the compose example comments quoted the data-update line as default-level output. They now show the remaining lines and note
OPAL_LOG_LEVEL=DEBUG. The healthcheck sample also drops two "calling subscription callbacks" lines, whichfastapi_websocket_pubsublogs at DEBUG.Also changed
scopes/task.py::_periodic_polling: removed an unusedexcept … as eand an f-string with no placeholders (flake8 F841/F541). The message text is unchanged.Not addressed (flagged)
git_fetcher.py::GitPolicyFetcher.fetch_and_notify_on_changes"Skipping sync for {url}: a previous git operation is still running after its timeout." is the source of most per-restart WARNING lines on a large fleet, and workers log it too. Its text is unchanged here; dashboards read it.scopes/task.py::triggerWARN uses%s, which loguru never interpolates.refresh_scope's ERROR says "Unauthorized to delete scope".ClientSideTopicPublisher._publishstill logs "Publishing to topics" at INFO. Nothing constructs it (setup_publisher_taskhas no caller).Tests
opal_common/tests/log_capture.py:capture_records()captures records at DEBUG and through a real INFO sink (the deployed level), with the global patcher off.opal_server/tests/gunicorn_master_logging_test.py:configure_logs()against a fresh loguru state whose only sink stands in for the default handler.REDIS_URLlogged as a kwarg the wayRedisDBdoes.preload_scopesdoes not reconfigure logging.configure_logs.opal_server/tests/scopes_push_log_levels_test.py:on_updateon a real repo, and end to end viaScopesService.sync_scopeagainst a local clone.refresh_scope(via TestClient),_should_fetch's three lines and "Could not clone repo at" keep their levels.test_data_update_publisher.py(including redaction of the URLs in the DEBUG line's entries and in the WARN),webhook_task_cleanup_test.pyandopal_common/tests/scoped_publisher_log_level_test.py.server_log_redaction_test.py::test_preload_configures_logs_before_any_workand theconfigure_logsstubs in the twopreload_*_test.pyfiles.preload_scopesno longer calls it, and the tests above cover the new location.configure_logs()fails a test (20/20).pytest packages/opal-server packages/opal-common: 912 passed, 1 skipped.Check List (Check all the applicable boxes)
Note to reviewers
The release image tags that will carry this are not cut yet; the stg/prod bumps are separate.
🤖 Generated with Claude Code