[action] [PR:28181] [gnmi] Extend audit syslog capture to one minute - #28323
Merged
Merged
Conversation
## 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`
- New physical validation was not run because matching testbeds were
occupied. No new physical pass is claimed; no public physical-test URL
is available.
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 sonic-net#27232
(backport of sonic-net#26891).
---------
Signed-off-by: donghaolicd <leedonhom@gmail.com>
Signed-off-by: mssonicbld <sonicbld@microsoft.com>
2 of 3 tasks
Collaborator
Author
|
Original PR: #28181 |
|
Azure Pipelines: There may be pipelines that require an authorized user to comment /azp run to run. |
Collaborator
Author
|
/azp run |
github-actions
Bot
requested review from
Javier-Tan,
cyw233 and
yutongzhang-microsoft
September 30, 2026 19:45
|
Azure Pipelines: Successfully started running 1 pipeline(s). |
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
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.