Skip to content

[action] [PR:28181] [gnmi] Extend audit syslog capture to one minute - #28323

Merged
mssonicbld merged 1 commit into
sonic-net:202605from
mssonicbld:cherry/202605/28181
Sep 30, 2026
Merged

mssonicbld merged 1 commit into
sonic-net:202605from
mssonicbld:cherry/202605/28181

Conversation

@mssonicbld

Copy link
Copy Markdown
Collaborator

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:

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:

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

  • 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
  • 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.
  • 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.

## 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>
@mssonicbld

Copy link
Copy Markdown
Collaborator Author

Original PR: #28181

@azure-pipelines

Copy link
Copy Markdown
Azure Pipelines:
There may be pipelines that require an authorized user to comment /azp run to run.

@mssonicbld

Copy link
Copy Markdown
Collaborator Author

/azp run

@azure-pipelines

Copy link
Copy Markdown
Azure Pipelines:
Successfully started running 1 pipeline(s).

@mssonicbld
mssonicbld merged commit 580a74d into sonic-net:202605 Sep 30, 2026
27 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants