[gnmi] Extend audit syslog capture to one minute - #28181
Merged
vaibhavhd merged 2 commits intoSep 29, 2026
Merged
Conversation
Signed-off-by: donghaolicd <leedonhom@gmail.com>
|
Azure Pipelines: There may be pipelines that require an authorized user to comment /azp run to run. |
Collaborator
|
/azp run |
github-actions
Bot
requested review from
cyw233,
hdwhdw and
yutongzhang-microsoft
September 23, 2026 18:16
|
Azure Pipelines: Successfully started running 1 pipeline(s). |
Signed-off-by: donghaolicd <leedonhom@gmail.com>
Collaborator
|
/azp run |
|
Azure Pipelines: Successfully started running 1 pipeline(s). |
hdwhdw
approved these changes
Sep 23, 2026
Contributor
Author
|
Requesting 202605 backport approval from @sonic-net/release-manager-202605. This merged change extends the audit syslog capture to 60 seconds (65-second completion wait); the affected test is already on 202605 via #27232. Existing Nokia-7215 evidence in the PR shows a successful Set taking 36.378 seconds, outliving the previous 30-second capture. The exact audit-record comparison is unchanged. Please add |
yxieca
added a commit
to yxieca/sonic-mgmt
that referenced
this pull request
Sep 30, 2026
What: Merge master at 2a6a8b6 into the syslog readiness branch without rewriting published history. Why: Upstream PR sonic-net#28181 added SYSLOG_CAPTURE_SECONDS adjacent to the readiness timeout constants, causing an add/add content conflict. How: Retain all three constants. Preserve the upstream remote audit capture at 60 seconds with a 65-second completion allowance and the existing run_syslog 20-second readiness/40-second capture behavior and cleanup. Validation: 14 offline readiness tests and 41 combined readiness/DHCP cleanup tests pass; applicable pre-commit hooks, pre-push checks and git diff --check pass. AST comparison verifies both capture paths retain their respective behavior. No DUT rerun, per the previously authorized local-validation scope. Signed-off-by: Ying Xie <ying.xie@microsoft.com>
2 of 21 tasks
Collaborator
|
This PR has backport request label(s) for branch(es): 202605, but is missing required test information. Please make sure you tick the tested branch(es) in the Tested branch section and provide test evidence (e.g., 202605: <test result>) in the Test result section as well in your PR description. ---Powered by SONiC BuildBot
|
Collaborator
|
Cherry-pick PR to msft-202608: Azure/sonic-mgmt.msft#1461 |
yxieca
added
Included in msft-202608 branch
and removed
Created PR to msft-202608 branch
labels
congh-nvidia
pushed a commit
to congh-nvidia/sonic-mgmt
that referenced
this pull request
Sep 30, 2026
…age (sonic-net#28276) <!-- Please make sure you've read and understood our contributing guidelines; https://github.com/sonic-net/SONiC/blob/gh-pages/CONTRIBUTING.md --> ### Description of PR Summary: `run_syslog()` in `tests/common/helpers/syslog_helpers.py` previously slept a flat 5s after launching the async tcpdump task and then called `logger` to emit the test syslog packet. On slower / BMC platforms tcpdump occasionally has not fully attached its BPF filter within that window, so the first (and only) packet is missed and `test_syslog` fails with `Dummy syslog server IP not seen in the pcap file`. This change polls for a fresh, nonempty capture file using tcpdump `-U`, which flushes the initial pcap header after filter installation. It checks the owned async result instead of searching process command lines. A monotonic 20s startup deadline includes launch and SSH latency; the capture timeout is 40s to leave room for syslog generation and delivery. No extra settling sleep is needed. Early capture completion or late readiness fails explicitly, with capture join and syslog/route cleanup in finally blocks. The deadline bounds readiness acceptance, not an in-flight SSH call or total function duration. Fixes # (issue) ### Type of change - [x] Bug fix - [ ] Testbed and Framework(new/improvement) - [ ] New Test case - [ ] Skipped for non-supported platforms - [ ] Test case improvement ### Back port request - [ ] 202311 - [ ] 202405 - [ ] 202411 - [ ] 202505 - [ ] 202511 - [ ] 202512 - [ ] 202605 Tracking issue/work item for backport/cherry-pick request (GitHub issue or Microsoft ADO): N/A Failure type: flake (timing race, not release-specific) ### Tested branch - [x] master - [ ] 202311 - [ ] 202405 - [ ] 202411 - [ ] 202505 - [ ] 202511 - [ ] 202512 - [ ] 202605 - [ ] N/A ### Test result Review update `a0d2cf847`: 14 new offline readiness/cleanup regressions passed; 41 passed when combined with the existing DHCP cleanup suite. All applicable repository pre-commit hooks and `git diff --check` passed. The actual local ThreadPool/AsyncResult ready/get/close/join contract was also checked. These tests use mocks and do not validate real tcpdump packet delivery. No DUT/VS rerun was performed for this review update because the testbed service is unhealthy; the author authorized pushing with local validation. The Chipmunk result above is historical validation of the original version, not this revision. - master: SONiC-OS-20260810.08 (Chipmunk BMC) — `test_syslog[7.0.80.165-7.0.80.166]` PASSED after fix (previously failed 2/16 first-mode batch runs on `.07` and `.08` with the identical missing-pcap signature). ### Approach #### What is the motivation for this PR? Flaky syslog test on Chipmunk BMC: 2/16 first-mode batch runs across `.07`/`.08` images failed with `Dummy syslog server IP not seen in the pcap file`. Root cause is a race — the fixed 5s sleep isn't long enough on slower platforms for tcpdump to attach before the `logger` command runs. #### How did you do it? This change polls for a fresh, nonempty capture file using tcpdump `-U`, which flushes the initial pcap header after filter installation. It checks the owned async result instead of searching process command lines. A monotonic 20s startup deadline includes launch and SSH latency; the capture timeout is 40s to leave room for syslog generation and delivery. No extra settling sleep is needed. Early capture completion or late readiness fails explicitly, with capture join and syslog/route cleanup in finally blocks. The deadline bounds readiness acceptance, not an in-flight SSH call or total function duration. #### How did you verify/test it? Review update `a0d2cf847`: 14 new offline readiness/cleanup regressions passed; 41 passed when combined with the existing DHCP cleanup suite. All applicable repository pre-commit hooks and `git diff --check` passed. The actual local ThreadPool/AsyncResult ready/get/close/join contract was also checked. These tests use mocks and do not validate real tcpdump packet delivery. No DUT/VS rerun was performed for this review update because the testbed service is unhealthy; the author authorized pushing with local validation. The Chipmunk result above is historical validation of the original version, not this revision. #### Any platform specific information? Symptom first observed on Chipmunk BMC (Aspeed AST2720) but the race is generic — any platform where tcpdump attach exceeds 5s could hit it. #### Supported testbed topology if it's a new test case? N/A (existing test helper). ### Documentation N/A ### Merge-conflict resolution (2026-09-29) Merged current upstream changes without rewriting PR history in `eb88e6bca`. PR sonic-net#28181 added `SYSLOG_CAPTURE_SECONDS` at the same insertion point as the readiness timeout constants; resolution retains all three constants. The readiness path remains 20s startup/40s capture; upstream audit capture remains 60s with 65s completion wait. 14 readiness tests / 41 combined offline tests and applicable pre-commit checks pass. No DUT rerun, per the authorized local-validation scope. DCO and Azure Static Analysis pass on `eb88e6bca` ([build 1234379](https://dev.azure.com/mssonic/build/_build/results?buildId=1234379)). GitHub confirms the conflict is resolved. Full CI was still in progress at verification; this is not merge approval. --------- Signed-off-by: Ying Xie <ying.xie@microsoft.com>
Collaborator
|
This PR has backport request label(s) for branch(es): msft-202608, but is missing required test information. Please make sure you tick the tested branch(es) in the Tested branch section and provide test evidence (e.g., 202608: <test result>) in the Test result section as well in your PR description. ---Powered by SONiC BuildBot
|
Contributor
Author
202605 target-branch validation — 2026-09-30Validated the existing audit-forwarding tests on a physical Nokia-7215 / MX, running the SONiC 202605 release (exact internal image identifier: The runtime test checkout was based on the current 202605 release test branch with only master merge commit
Downloaded JUnit summary: 2 tests, 0 failures, 0 errors, 0 skips, session time 780.233 s. Both test setup/call/teardown completed without pytest errors. Pretest separately reports 11 passed/3 skipped; posttest reports 5 passed/0 skipped. Post-test sanity passed. Selected fields from fresh DUT audit records, with endpoint/identity information omitted: {"method":"/gnmi.gNMI/Get","code":"OK","duration_ms":99,"suppressed":0,"path":["/COUNTERS_PORT_NAME_MAP"]}
{"method":"/gnmi.gNMI/Set","code":"OK","duration_ms":25396,"suppressed":0,"path":["/CONFIG_DB/localhost/DEVICE_METADATA/localhost/cloudtype"]}The original exact local-versus-forwarded-record equality assertions passed. This is target-release compatibility evidence; the Set in this run took 25.396 seconds, so this run does not reproduce the historical 36.378-second operation or establish a performance improvement. Raw JUnit, preparation and debug logs are retained in the authenticated internal test-plan artifacts. No public physical-test URL is available; raw lab logs and private links are not published here. Internal evidence is available to maintainers through the associated work item/test-plan record. |
Collaborator
|
The Tested branch section has been ticked and Test result is provided for branch(es): 202605. Added label(s): Tested for 202605 Branch. ---Powered by SONiC BuildBot
|
2 of 3 tasks
Collaborator
|
Cherry-pick PR to 202605: #28323 |
mssonicbld
added a commit
that referenced
this pull request
Sep 30, 2026
…28323) ## Summary - Extend the remote syslog packet capture from 30 to 60 seconds so slow gNMI Set completions fit within the capture window. - Wait up to 65 seconds for capture completion, preserving the existing five-second allowance. The exact local-versus-forwarded audit-record comparison remains intact. ## Failure evidence (sanitized) Observed on a physical **Nokia-7215**, running the **SONiC 202605** release, in: `gnmi/test_gnmi_aaa.py::test_gnmi_audit_log_remote_forwarding[set]` This evidence comes from the existing failing nightly run, not a new validation of this patch. The pytest debug log records the output of `sudo tail -c +40479 /var/log/gnmi.log` at **2026-09-22 02:39:42 UTC**: ```text 2026 Sep 22 02:39:41.281767 [redacted] INFO gnmi#supervisord: gnmi-native I0922 02:39:41.280890 25269 setup.go:32] RPC_COMPLETION {"v":2,"type":"unary","method":"/gnmi.gNMI/Set","peer_type":"tcp","peer":"[redacted]","principal":"test.client.gnmi.sonic","auth_type":"tls","path":["/CONFIG_DB/localhost/DEVICE_METADATA/localhost/cloudtype"],"code":"OK","duration_ms":36378,"suppressed":0} ``` `duration_ms=36378` is the **server-measured RPC duration: 36.378 seconds**, not syslog delivery latency. The runner independently records: ```text 22/09/2026 02:39:04 ... Allure step: Generate a /gnmi.gNMI/Set audit record 22/09/2026 02:39:41 ... Allure step: Verify the remotely forwarded audit record ``` | UTC time | Observation | |---|---| | 02:38:59.364 | DUT logs invocation of `sudo timeout 30 tcpdump ...` | | 02:39:02.487 | Capture-file readiness check succeeds | | Approximately 02:39:29–32 | Scheduled 30-second capture deadline | | 02:39:41.280890 | Set completion is generated with `code=OK`, `duration_ms=36378` | | 02:39:42–47 | Local completion is found; finished pcap yields no matching Set record | Even `capture-ready + 30 seconds` precedes the target completion by **8.79 seconds**. Waiting for `capture_result.ready()` after the RPC does not extend the capture itself. The generic `RPC_COMPLETION` marker check passed, but the method-specific comparison failed with one local Set record and `streamed=[]`. The capture runs on the DUT and observes UDP packets addressed to the remote syslog destination; it does not verify collector application receipt. The original pcap was removed by cleanup, and the old code did not log capture exit timing. This evidence establishes an inadequate capture window, not proof of product-side packet loss or eventual remote delivery. ### Existing comparison evidence - A same-SKU run completed Set in **25.427 seconds**, before its scheduled 30-second capture deadline, and passed the equality check. - That comparison used a different device/image and is not an A/B validation of this patch. - Independent DHCP-container RELP teardown errors are not counted as the Set audit mismatch. ## Validation - Passed: `python3 -m py_compile tests/common/helpers/syslog_helpers.py tests/gnmi/test_gnmi_aaa.py` - Passed: `flake8 --max-line-length=120 tests/common/helpers/syslog_helpers.py tests/gnmi/test_gnmi_aaa.py` - Passed: `git diff --check` - At initial submission, physical validation was blocked by occupied testbeds. Target-branch physical validation has now completed; see the results below. The 60-second limit addresses the observed 36.378-second operation with additional headroom. It remains a bounded window, not a guarantee for arbitrarily slow operations. ## Backport Please backport to **202605**, where this test was introduced by #27232 (backport of #26891). ### Back port request - [x] 202605 Failure type: day-one observation-window defect in the audit-forwarding coverage introduced by #26891 and backported in #27232. The detailed failure timeline is above. ### Tested branch - [ ] master - [x] 202605 ### Test result - **202605:** SONiC 202605 release on physical Nokia-7215 / MX; exact internal image identifier `[redacted]`. Executed with a current 202605 test-branch checkout plus only this PR's merged patch. Both `test_gnmi_audit_log_remote_forwarding[get]` and `[set]` passed: **2 tests, 0 failures, 0 errors, 0 skips**, 780.233 seconds including fixtures. Runtime logs confirm `timeout 60 tcpdump`; exact local-versus-forwarded audit equality assertions passed. Post-test sanity passed; posttest separately passed 5/5. See [sanitized test evidence](#28181 (comment)). - **master:** existing static/PR CI evidence is separate; this new physical run validates the requested 202605 branch only. This run's server-side Set duration was **25.396 seconds**. It validates target-release compatibility and forwarding assertions, not a reproduction of the historical 36.378-second latency or a performance improvement. Raw logs/JUnit remain in authenticated internal artifacts; no public physical-test URL is available.
mssonicbld
added
Included in 202605 branch
and removed
Created PR to 202605 branch
labels
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
5 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
The exact local-versus-forwarded audit-record comparison remains intact.
Failure evidence (sanitized)
Observed on a physical Nokia-7215, running the SONiC 202605 release, in:
gnmi/test_gnmi_aaa.py::test_gnmi_audit_log_remote_forwarding[set]This evidence comes from the existing failing nightly run, not a new validation of this patch. The pytest debug log records the output of
sudo tail -c +40479 /var/log/gnmi.logat 2026-09-22 02:39:42 UTC:duration_ms=36378is the server-measured RPC duration: 36.378 seconds, not syslog delivery latency. The runner independently records:sudo timeout 30 tcpdump ...code=OK,duration_ms=36378Even
capture-ready + 30 secondsprecedes the target completion by 8.79 seconds. Waiting forcapture_result.ready()after the RPC does not extend the capture itself. The genericRPC_COMPLETIONmarker check passed, but the method-specific comparison failed with one local Set record andstreamed=[].The capture runs on the DUT and observes UDP packets addressed to the remote syslog destination; it does not verify collector application receipt. The original pcap was removed by cleanup, and the old code did not log capture exit timing. This evidence establishes an inadequate capture window, not proof of product-side packet loss or eventual remote delivery.
Existing comparison evidence
Validation
python3 -m py_compile tests/common/helpers/syslog_helpers.py tests/gnmi/test_gnmi_aaa.pyflake8 --max-line-length=120 tests/common/helpers/syslog_helpers.py tests/gnmi/test_gnmi_aaa.pygit diff --checkThe 60-second limit addresses the observed 36.378-second operation with additional headroom. It remains a bounded window, not a guarantee for arbitrarily slow operations.
Backport
Please backport to 202605, where this test was introduced by #27232 (backport of #26891).
Back port request
Failure type: day-one observation-window defect in the audit-forwarding coverage introduced by #26891 and backported in #27232. The detailed failure timeline is above.
Tested branch
Test result
[redacted]. Executed with a current 202605 test-branch checkout plus only this PR's merged patch. Bothtest_gnmi_audit_log_remote_forwarding[get]and[set]passed: 2 tests, 0 failures, 0 errors, 0 skips, 780.233 seconds including fixtures. Runtime logs confirmtimeout 60 tcpdump; exact local-versus-forwarded audit equality assertions passed. Post-test sanity passed; posttest separately passed 5/5. See sanitized test evidence.This run's server-side Set duration was 25.396 seconds. It validates target-release compatibility and forwarding assertions, not a reproduction of the historical 36.378-second latency or a performance improvement. Raw logs/JUnit remain in authenticated internal artifacts; no public physical-test URL is available.