syslog_helpers: wait for tcpdump readiness before generating log message

[yxieca]

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

• 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

• 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 #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). GitHub confirms the conflict is resolved. Full CI was still in progress at verification; this is not merge approval.

[azure-pipelines]

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

[mssonicbld]

/azp run

[azure-pipelines]

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

[ediwibowo-msft]

A few suggestions on the tcpdump readiness poll — mostly a correctness fix on the pgrep early-break, plus an optional robustness tweak.

[ediwibowo-msft]

pgrep self-match bug. The check runs via /bin/sh -c "…", and that wrapper shell's own command line contains the literal string tcpdump.*/tmp/test_syslog_tcpdump.pcap. Therefore, pgrep -f matches its own wrapper and reports "alive" even after the real tcpdump has died. The early-break never fires and the loop polls the full window. Use the self-exclusion [t]cpdump so that the regex matches the real process but not the literal pattern text in the wrapper cmdline:

"pgrep -f '[t]cpdump.*{}' >/dev/null".format(DUT_PCAP_FILEPATH)

[yxieca]

Addressed all three suggestions in a0d2cf8:

Feedback	Change
pgrep wrapper self-match	Removed process-name searches; check the owned AsyncResult before and after the readiness probe.
SSH overhead exceeds polling budget	One remote file check per poll; monotonic 20s startup deadline, with a 40s capture timeout for delivery headroom. Late readiness is rejected.
Buffered pcap header	Added -U to flush the initial header. Removed the extra settling sleep; tcpdump installs its filter before creating/flushing the header.

Early completion/startup timeout now fails explicitly; capture join and syslog/route cleanup run on these failure paths. The deadline bounds readiness acceptance, not an in-flight SSH request or total function runtime. AsyncResult completion indicates command-task completion rather than instantaneous remote PID liveness.

Validation: 14 new offline regressions, 41 combined tests, and all applicable pre-commit checks pass. No DUT/VS rerun: the testbed service is unhealthy and pushing with local checks was explicitly authorized. Remote verification: DCO and Azure Static Analysis both pass on this revision (build 1233975). Full CI was still in progress at verification.

[ediwibowo-msft]

Keep the poll within tcpdump's timeout. The 40 × 0.5s math only counts the sleeps. Each iteration also does two duthost.shell SSH round-trips, so the real wall-clock time per iteration is (RTT × 2) + 0.5s. On a slow DUT that can push total elapsed time well past 20s and outlast timeout 20 tcpdump. Collapsing both checks into one round-trip keeps the actual wall time closer to the intended bound:

readiness_cmd = (
    "if test -s {pcap}; then exit 0; "
    "elif pgrep -f '[t]cpdump.*{pcap}' >/dev/null; then exit 1; "
    "else exit 2; fi"
).format(pcap=DUT_PCAP_FILEPATH)

tcpdump_ready = False
for _ in range(40):  # up to ~20s
    rc = duthost.shell(readiness_cmd, module_ignore_errors=True)["rc"]
    if rc == 0:
        tcpdump_ready = True
        break
    if rc == 2:  # tcpdump already gone
        break
    time.sleep(0.5)

[ediwibowo-msft]

nit: make test -s reliable across platforms. Without -U, tcpdump writes the pcap header through buffered stdio, so on some libpcap builds the file can stay 0 bytes until the first packet flushes the buffer. If that happens, test -s never trips, the poll uses the full window, and tcpdump may already have exited by the time logger fires. Adding -U (packet-buffered) here guarantees the header hits disk immediately and makes the readiness signal robust rather than dependent on flush action.

tcpdump_task, tcpdump_result = duthost.shell(
    "sudo timeout 20 tcpdump -U -y LINUX_SLL -i any -s0 -A -w {} \"udp and port 514\""
    .format(DUT_PCAP_FILEPATH), module_async=True)`

[mssonicbld]

/azp run

[azure-pipelines]

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

[ediwibowo-msft]

Approving. This is a solid, well-reasoned fix for the test_syslog flake, and the earlier review points are all addressed:

• Readiness is now gated on the owned AsyncResult (tcpdump_result.ready()) plus a test -s header check, replacing the fragile pgrep process-name match.
• A monotonic startup_deadline bounds readiness on real wall-clock time (including launch/SSH latency), and late readiness is explicitly rejected.
• -U flushes the initial pcap header, making the test -s signal reliable and removing the need for a settling sleep.
• Early tcpdump exit now fails explicitly, and capture join + syslog/route cleanup run on all failure paths via finally.
• Nice addition of the offline regression suite (verified passing locally).

The fixed-timeout + join() design is intentionally simple and robust. The stop is kernel-enforced, self-cleaning, and deterministic, so this is good to merge as-is.

Note for future improvement (non-blocking)

tcpdump_task.join() blocks until the remote command returns, which only happens when timeout (now 40s) fires. The ThreadPool cannot stop the remote process. So each run_syslog spends ~40s in capture regardless of how quickly readiness was reached (typically ~1-2s). With test_syslog parametrized over 5 cases (plus test_mgmt_ipv6_only), that's ~3+ minutes of mostly-idle wait per run.

The capture only needs to stay alive briefly after logger for delivery (a second or two with -U), not a fixed tail on every call. Two options for a future PR, in increasing complexity:

A. One-liner: lower TCPDUMP_CAPTURE_TIMEOUT (e.g. 25 = 20s readiness budget + 5s delivery). Keeps the simple fixed-timeout model, recovers ~15s/call.
B. Stop-by-PID: launch tcpdump recording its PID (sh -c 'tcpdump -U ... & echo $! > pidfile; wait') and kill -INT it by exact PID a short grace after logger, keeping timeout as a backstop. Recovers ~36s/call (~3 min across test_syslog) but adds a pid-file lifecycle and quoting to validate on hardware.

[mssonicbld]

/azp run

[azure-pipelines]

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

[mssonicbld]

Cherry-pick PR to msft-202608: Azure/sonic-mgmt.msft#1462