Skip to content

Fix: Telemetry INFO logging to print only once per process - #6083

Merged
rsareddy0329 merged 11 commits into
aws:masterfrom
rsareddy0329:master-mtrl-vpc-cmk-support
Jul 30, 2026
Merged

Fix: Telemetry INFO logging to print only once per process#6083
rsareddy0329 merged 11 commits into
aws:masterfrom
rsareddy0329:master-mtrl-vpc-cmk-support

Conversation

@rsareddy0329

Copy link
Copy Markdown
Contributor

Issue #, if available:

Description of changes:

By submitting this pull request, I confirm that you can use, modify, copy, and redistribute this contribution, under the terms of your choice.

jam-jee added a commit that referenced this pull request Jul 23, 2026
The review job runs under pull_request_target (trusted context with the
Bedrock role + secrets). It was checking out the fork's head SHA, which
actions/checkout now refuses ('pwn request' guard) — so the workflow failed on
every fork PR (~90% of PRs), e.g. run 29965762436 on #6083.

Rework to the safe diff-only pattern (mirrors aws/*-agentcore pr-security-review):
- Check out the BASE repo, never fork head code — untrusted PR code is never
  executed in the privileged job.
- Fetch the PR diff via the API into /tmp/pr.diff as read-only ground truth.
- Remove Bash from allowedTools; Claude reads the diff + uses Read/Grep/Glob
  against the trusted base tree for context. Skip cleanly on empty diffs.

Does NOT use allow-unsafe-pr-checkout, which would expose secrets to fork code.
@github-actions

github-actions Bot commented Jul 23, 2026

Copy link
Copy Markdown

Claude finished @rsareddy0329's task in 59s —— View job


Code Review — Telemetry INFO logging once per process

  • Read PR diff and changed files
  • Analyze correctness, tests, and behavior changes
  • Post review

The change is small, correct, and well-targeted. Moving the logger.info(TELEMETRY_OPT_OUT_MESSAGING) call behind a module-level _telemetry_msg_shown guard achieves the stated goal — the opt-out message prints at most once per process instead of on every decorated call.

Things I like

  • The message is now also gated on not telemetry_opt_out_flag, so users who have already opted out no longer get told how to opt out. That's a sensible improvement over the previous unconditional log, though it's a real behavior change worth being aware of (opted-out users will no longer see the notice at all).
  • Tests cover both the "shown exactly once across multiple calls" and "not shown when opted out" paths, and correctly reset the module global before/after to avoid cross-test leakage.

Minor considerations (non-blocking)

  1. Thread-safety of the check-then-set (telemetry_logging.py:303-305). The if not _telemetry_msg_shown: ... _telemetry_msg_shown = True sequence is not atomic. In a multi-threaded process where several threads hit a decorated call concurrently before the flag is set, the message could print more than once. For a one-time INFO notice this is low-stakes and I wouldn't block on it, but it's worth a mention.

  2. Test isolation depends on global reset. Because _telemetry_msg_shown is module-level state, the new tests rely on manually resetting it. Existing tests that call mock_create_model() with opt-out False will flip the flag to True as a side effect. The new tests handle this by resetting at the start, so ordering is safe today — just noting the shared mutable global is a mild fragility if more tests are added later. A setUp/tearDown reset (or a fixture) would make this robust regardless of test order.

Neither point is a blocker. The core fix is correct and the tests validate the intended behavior. LGTM. 👍

@github-actions

github-actions Bot commented Jul 23, 2026

Copy link
Copy Markdown

Claude finished @rsareddy0329's task in 1m 38s —— View job


Code Review — Telemetry opt-out message once per process

  • Read PR diff and changed files
  • Analyze correctness, tests, and behavior changes
  • Post review

The core idea — gating TELEMETRY_OPT_OUT_MESSAGING behind a module-level _telemetry_msg_shown flag so it prints at most once per process, and not at all for opted-out users — is sound. However, this revision introduced a test/implementation mismatch that will make the new test fail, plus a behavior change worth calling out.

🔴 Blocking: new test asserts on the wrong logger method

The implementation now emits the message via logger.warning (telemetry_logging.py:304):

if not telemetry_opt_out_flag and not _telemetry_msg_shown:
    logger.warning(TELEMETRY_OPT_OUT_MESSAGING)
    _telemetry_msg_shown = True

But test_telemetry_opt_out_message_shown_only_once patches and asserts against logger.info (test_telemetry_logging.py:657-666):

with patch.object(telemetry_module.logger, "info") as mock_logger_info:
    mock_local_client.mock_create_model()
    ...
    info_calls = [call for call in mock_logger_info.call_args_list
                  if "telemetry" in str(call).lower() and "opt out" in str(call).lower()]
    self.assertEqual(len(info_calls), 1, ...)  # will get 0, not 1

Since the message no longer goes through logger.info, mock_logger_info captures zero matching calls, so assertEqual(len(info_calls), 1) fails. The message-text filter ("opt out") also won't match — TELEMETRY_OPT_OUT_MESSAGING uses "opt out of telemetry", so "telemetry" and "opt out" happens to match by coincidence, but the assertion still fails on count.

Note the sibling test test_telemetry_opt_out_message_not_shown_when_opted_out passes only vacuously — it patches logger.info and asserts len == 0, which is trivially true now that nothing is logged via info. It doesn't actually verify the opted-out path.

Fix: patch logger.warning in both tests (or revert the log level back to info to match the PR's stated intent — see below).

🟡 Behavior change: INFO → WARNING

The PR title says "INFO logging," but the level was changed to WARNING. A routine telemetry opt-out notice at WARNING level is fairly loud — it will surface in setups that filter to WARNING+ and may read as something being wrong. If the intent is just an informational notice, logger.info is more appropriate. If WARNING is deliberate, please update the PR title/description to reflect it.

🟢 Minor (non-blocking)

  • Thread-safety: the check-then-set on _telemetry_msg_shown (lines 303–305) isn't atomic, so under concurrent first calls the message could print more than once. Low-stakes for a one-time notice; not worth a lock.
  • Shared global in tests: both tests reset _telemetry_msg_shown manually before/after. A setUp/tearDown (or fixture) reset would make this robust regardless of test ordering as more tests are added.

Summary: fix the logger.infologger.warning mismatch in the tests (and confirm the intended log level) before merging. The rest is optional polish.

Note: the inline-comment tool wasn't available in this environment, so findings are consolidated here with file/line references.


@github-actions

github-actions Bot commented Jul 24, 2026

Copy link
Copy Markdown

Claude finished @rsareddy0329's task in 1m 0s —— View job


Code Review — Telemetry opt-out message once per process

  • Read PR diff and changed files
  • Analyze correctness, tests, and behavior changes
  • Post review

The core change — gating TELEMETRY_OPT_OUT_MESSAGING behind the module-level _telemetry_msg_shown flag so it emits at most once per process, and not at all for opted-out users — is sound and well-targeted. But the latest revision still has a blocking test/implementation mismatch and a behavior change that contradicts the PR title.

🔴 Blocking: tests patch the wrong logger method

The implementation emits the message via logger.warning (telemetry_logging.py:303):

if not telemetry_opt_out_flag and not _telemetry_msg_shown:
    logger.warning(TELEMETRY_OPT_OUT_MESSAGING)
    _telemetry_msg_shown = True

But both new tests patch and assert against logger.info (test_telemetry_logging.py:657 and :685):

with patch.object(telemetry_module.logger, "info") as mock_logger_info:
    ...
    self.assertEqual(len(info_calls), 1, ...)  # gets 0 → FAILS

Since the message no longer flows through logger.info, mock_logger_info records zero matching calls and test_telemetry_opt_out_message_shown_only_once fails its assertEqual(len(info_calls), 1).

The sibling test test_telemetry_opt_out_message_not_shown_when_opted_out will "pass," but only vacuously — it asserts len == 0 against logger.info, which is trivially true now that nothing is logged via info. It does not actually verify the opted-out path; it would pass even if the guard were broken. (The text filter "opt out" in str(call).lower() does match the real message — "To opt out of telemetry..." — so the filter is fine; the failure is purely the info vs warning method.)

Fix: patch logger.warning in both tests, or revert the log level to logger.info to match the PR's stated intent (see next point). Whichever you pick, make sure the opted-out test patches the same method the code actually calls so it's a real assertion, not a vacuous one.

🟡 Behavior change: INFO → WARNING contradicts the PR title

The PR title is "Fix: Telemetry INFO logging to print only once per process," but the code changes the level to logger.warning. A routine telemetry-opt-out notice at WARNING level is loud — it surfaces in any setup that filters to WARNING+ and reads as though something is wrong. If this is just an informational notice, logger.info is the right level (and matches the title). If WARNING is intentional, please update the title/description to say so.

🟢 Minor (non-blocking)

  • Thread-safety: the check-then-set on _telemetry_msg_shown (telemetry_logging.py:303-305) isn't atomic, so under concurrent first calls the message could print more than once. Low-stakes for a one-time notice — not worth a lock.
  • Test isolation: both tests reset _telemetry_msg_shown manually before/after. Moving that reset into setUp/tearDown (or a fixture) would keep it robust regardless of test ordering as more tests are added.
  • Opted-out users no longer see the notice at all (previously the message logged unconditionally). That's a reasonable improvement, but worth calling out as an intentional behavior change.

Summary: fix the logger.infologger.warning mismatch in both tests (and confirm the intended log level vs. the PR title) before merging. Everything else is optional polish.

Note: the inline-comment tool isn't available in this environment, so findings are consolidated here with file/line references.

jam-jee
jam-jee previously approved these changes Jul 27, 2026
@github-actions

github-actions Bot commented Jul 28, 2026

Copy link
Copy Markdown

Claude finished @rsareddy0329's task in 56s —— View job


Code Review — Telemetry opt-out message once per process

  • Read PR diff and changed files
  • Analyze correctness, tests, and behavior changes
  • Post review

The core idea — gating TELEMETRY_OPT_OUT_MESSAGING behind a module-level _telemetry_msg_shown flag so it emits at most once per process, and not at all for opted-out users — is sound and well-targeted. But the latest revision still contains the blocking test/implementation mismatch from the previous reviews, plus a behavior change that contradicts the PR title.

🔴 Blocking: tests patch logger.info, but the code calls logger.warning

The implementation emits the message via logger.warning (sagemaker-core/src/sagemaker/core/telemetry/telemetry_logging.py:303-305):

if not telemetry_opt_out_flag and not _telemetry_msg_shown:
    logger.warning(TELEMETRY_OPT_OUT_MESSAGING)
    _telemetry_msg_shown = True

But both new tests patch and assert against logger.info (sagemaker-core/tests/unit/telemetry/test_telemetry_logging.py:665 and :693):

with patch.object(telemetry_module.logger, "info") as mock_logger_info:
    ...
    self.assertEqual(len(info_calls), 1, ...)  # gets 0 → FAILS
  • test_telemetry_opt_out_message_shown_only_once will fail: since the message no longer flows through logger.info, mock_logger_info records zero matching calls, so assertEqual(len(info_calls), 1) fails.
  • test_telemetry_opt_out_message_not_shown_when_opted_out "passes" only vacuously — it asserts len == 0 against logger.info, which is trivially true now that nothing is logged via info. It would pass even if the opt-out guard were broken, so it isn't actually testing the opted-out path.

(The text filter "telemetry" ... "opt out" does match the real message — "...To opt out of telemetry..." — so the filter is fine; the failure is purely the info vs. warning method.)

Fix: patch logger.warning in both tests (and revert the log level to logger.info if that's the intended level — see next point). Whichever you choose, make both tests patch the same method the code actually calls so the opted-out assertion is real, not vacuous.

🟡 Behavior change: INFO → WARNING contradicts the PR title

The PR title says "Telemetry INFO logging," but the change uses logger.warning. A routine opt-out notice at WARNING level is loud — it surfaces in any setup filtering to WARNING+ and reads as though something is wrong. For an informational notice, logger.info is the right level and matches the title. If WARNING is intentional, please update the title/description to say so.

🟢 Minor (non-blocking)

  • Thread-safety: the check-then-set on _telemetry_msg_shown (telemetry_logging.py:303-305) isn't atomic, so under concurrent first calls the message could print more than once. Low-stakes for a one-time notice — not worth a lock.
  • Test isolation: both tests reset _telemetry_msg_shown manually before/after. Moving that reset into setUp/tearDown (or a fixture) would keep it robust regardless of test ordering as more tests are added.
  • Opted-out users no longer see the notice at all (previously it logged unconditionally). Reasonable improvement, but worth calling out as an intentional behavior change.

Summary: the logger.info vs. logger.warning mismatch is still present and will fail test_telemetry_opt_out_message_shown_only_once. Align the tests with the actual log method (and confirm the intended level vs. the PR title) before merging. Everything else is optional polish.

Note: the inline-comment tool isn't available in this environment, so findings are consolidated here with file/line references.

@github-actions

github-actions Bot commented Jul 28, 2026

Copy link
Copy Markdown

Claude finished @rsareddy0329's task in 1m 32s —— View job


Code Review — Telemetry opt-out message once per process

  • Read PR diff and changed files
  • Analyze correctness, tests, and log-level change
  • Post review

The core idea — gating TELEMETRY_OPT_OUT_MESSAGING behind a module-level _telemetry_msg_shown flag so it emits at most once per process, and skipping it entirely for opted-out users — is sound and well-targeted. Two things still need attention before merge.

🔴 Blocking: tests patch logger.info, but the code calls logger.warning

The implementation emits the message via logger.warning (telemetry_logging.py:303-305):

if not telemetry_opt_out_flag and not _telemetry_msg_shown:
    logger.warning(TELEMETRY_OPT_OUT_MESSAGING)
    _telemetry_msg_shown = True

But both new tests patch and assert against logger.info (test_telemetry_logging.py:665 and :693):

with patch.object(telemetry_module.logger, "info") as mock_logger_info:
    ...
    self.assertEqual(len(info_calls), 1, ...)  # gets 0 → FAILS
  • test_telemetry_opt_out_message_shown_only_once will fail: the message no longer flows through logger.info, so mock_logger_info.call_args_list is empty, info_calls is [], and assertEqual(len(info_calls), 1) fails (0 ≠ 1).
  • test_telemetry_opt_out_message_not_shown_when_opted_out passes only vacuously — it asserts len == 0 against logger.info, which is trivially true since nothing is logged via info. It would pass even if the opt-out guard were broken, so it does not actually exercise the opted-out path.

(The text filter "telemetry" ... "opt out" does match the real message text — "...To opt out of telemetry..." — so the filter itself is fine; the failure is purely info vs. warning.)

Fix: patch logger.warning in both tests (and make the opted-out test assert against the same method the code calls, so it's a real assertion, not a vacuous one). If info is the intended level, revert the log call to logger.info instead — see next point.

This mismatch has been flagged in prior review rounds and is still present in the current revision.

🟡 Log level: INFO → WARNING contradicts the PR title, and utils.py broadens it

Two related level changes:

  1. telemetry_logging.py:304 uses logger.warning, but the PR title says "Telemetry INFO logging." A routine opt-out notice at WARNING is loud — it surfaces in any setup filtered to WARNING+ and reads as though something is wrong. For an informational notice, logger.info is the right level and matches the title. If WARNING is deliberate, please update the title/description.

  2. utils.py:169 changes the get_textual_rich_logger default from "INFO" to "WARNING". This is a broad, module-wide change: resources.py, intelligent_defaults_helper.py, constants.py, and the tools modules all obtain their logger via this helper, so every INFO-level log across sagemaker-core is now suppressed by default. That's well beyond "print the telemetry message once" and looks tangential to this PR's stated purpose. Please confirm this is intended and, if so, call it out explicitly in the description — otherwise consider dropping it from this PR.

🟢 Minor (non-blocking)

  • Thread-safety: the check-then-set on _telemetry_msg_shown (telemetry_logging.py:303-305) isn't atomic, so under concurrent first calls the message could print more than once. Low-stakes for a one-time notice — not worth a lock.
  • Test isolation: both tests reset _telemetry_msg_shown manually before/after. Moving that into setUp/tearDown (or a fixture) would keep it robust as more tests are added.
  • Behavior change: opted-out users no longer see the notice at all (previously it logged unconditionally). Reasonable improvement, but worth noting as intentional.

Summary: the logger.info vs. logger.warning test mismatch is still present and will fail test_telemetry_opt_out_message_shown_only_once. Align the tests with the actual log method (and settle the intended level vs. the PR title), and confirm the intent of the utils.py default-level change, before merging.

Note: the inline-comment tool isn't available in this environment, so findings are consolidated here with file/line references.

@jam-jee jam-jee left a comment

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Since we are not setting default log level for now, lets keep logger.info for telemetry.

logger.debug("TelemetryOptOut flag is set to: %s", telemetry_opt_out_flag)

if not telemetry_opt_out_flag and not _telemetry_msg_shown:
logger.warning(TELEMETRY_OPT_OUT_MESSAGING)

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

set to logger.info()

@github-actions

Copy link
Copy Markdown

Claude Code is working…

I'll analyze this and get back to you.

View job run

@github-actions

github-actions Bot commented Jul 29, 2026

Copy link
Copy Markdown

Claude finished @rsareddy0329's task in 48s —— View job


Code Review — Telemetry opt-out message once per process

  • Read PR diff and changed files
  • Verify implementation vs. tests (log level, guard)
  • Post review

The core change — gating TELEMETRY_OPT_OUT_MESSAGING behind a module-level _telemetry_msg_shown flag so it emits at most once per process, and not at all for opted-out users — is sound and well-targeted.

✅ The prior blocking issue is now resolved

The implementation now emits the message via logger.info (telemetry_logging.py:303-305):

if not telemetry_opt_out_flag and not _telemetry_msg_shown:
    logger.info(TELEMETRY_OPT_OUT_MESSAGING)
    _telemetry_msg_shown = True

and both new tests patch and assert against logger.info (test_telemetry_logging.py:657, :685). The implementation and tests now agree, and this matches @jam-jee's review request ("keep logger.info for telemetry") and the PR title. The utils.py default-level change flagged in an earlier round is no longer part of this PR (only 2 files changed). 👍

  • test_telemetry_opt_out_message_shown_only_once: resets the flag, calls mock_create_model() 3×, asserts exactly 1 matching info call — this now passes.
  • test_telemetry_opt_out_message_not_shown_when_opted_out: resolve_value_from_config returns True, asserts 0 matching info calls — this is now a real assertion against the same method the code calls, not a vacuous one.

🟢 Minor (non-blocking)

  • Thread-safety: the check-then-set on _telemetry_msg_shown (lines 303-305) isn't atomic, so under concurrent first calls the message could theoretically print more than once. Low-stakes for a one-time INFO notice — not worth a lock.
  • Test isolation: both tests reset _telemetry_msg_shown manually before/after. Moving that into setUp/tearDown (or a fixture) would keep it robust regardless of test ordering as more tests are added — since this is shared module-level mutable state, any future test that triggers a decorated call with opt-out False will flip the flag as a side effect.
  • Intentional behavior change: opted-out users no longer see the notice at all (previously it logged unconditionally). Reasonable, but worth noting in the description as intentional.

Summary: LGTM. The implementation and tests are now consistent (both on logger.info), the log level matches the PR title and the reviewer's request, and the tests validate both the "once per process" and "not shown when opted out" paths. Remaining points are optional polish.

@rsareddy0329
rsareddy0329 merged commit 32fca55 into aws:master Jul 30, 2026
34 of 43 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants