Skip to content

UCT/IB: Dump complete packets in trace-data logs - #11975

Merged
tvegas1 merged 5 commits into
openucx:masterfrom
tvegas1:wireup_malformed_overrun
Sep 28, 2026
Merged

tvegas1 merged 5 commits into
openucx:masterfrom
tvegas1:wireup_malformed_overrun

Conversation

@tvegas1

@tvegas1 tvegas1 commented Sep 20, 2026

Copy link
Copy Markdown
Contributor

What?

uct_ib_log_dump_sg_list() copies the packet into a fixed char data[256] before handing it to the dump callback, which then parses past the end of the copy for any larger packet. That is an out-of-bounds read of the stack buffer, and it prints a bogus description. Only reachable with trace-data logging enabled (UCX_LOG_LEVEL=data or more verbose); nothing is wrong on the wire.

A 325-byte WIREUP REQ, before and after:

am 1 WIREUP REQ [<malformed address> uuid 0x0 src_ep_id 0x15554c607140 ...]
am 1 WIREUP REQ [funk03:1604837 uuid 0xd3a9b6897678a217 src_ep_id 0x15554c607140 ...] s...

Why?

The dump callbacks parse a message by its own headers and get no length they can rely on — ucp_address_unpack() takes none at all — so a truncated copy makes them walk off its end. Only the send path was affected; receive completions pass the real buffer through.

How?

Size the gather buffer to the message with ucs_alloc_on_stack(), so only large packets reach the heap. Skip the callback when nothing was collected, since it has no header to read. A description can still be cut by the log line length, so stamp the line end with an ellipsis; one that fits keeps its own terminator and hides the stamp. Verified on ConnectX with loopback ucx_perftest and the rc_mlx5/ud_mlx5 p2p gtests under UCX_LOG_LEVEL=data.

uct_ib_log_dump_sg_list() gathered the packet into a fixed char data[256]
before handing it to the dump callback. The callbacks parse the message by
its own headers and are not given a length they can rely on, so a message
longer than the copy was parsed past its end. A wireup request, which is
several hundred bytes, was reported as "WIREUP REQ [<malformed address>]".

Size the gather buffer to the message instead, using ucs_alloc_on_stack()
so that only large packets reach the heap. Skip the callback when no data
was collected, since it has no header to read in that case.

A description can still be cut by the length of the log line, so stamp the
end of the line with an ellipsis. A description which fits keeps its own
terminator and hides the stamp behind it.
@svc-nvidia-pr-review

Copy link
Copy Markdown

🤖 Starting review — findings will be posted here when done.

Comment thread src/uct/ib/base/ib_log.c Resolved
Comment thread src/uct/ib/base/ib_log.c Resolved
Comment thread src/uct/ib/mlx5/ib_mlx5_log.c Resolved
@svc-nvidia-pr-review

Copy link
Copy Markdown

is this path exercised anywhere in CI? gtest runs with UCX_LOG_LEVEL=warn, so the packet dump code is never hit; maybe add a uct test that wraps a few am_bcopy/am_zcopy sends with ucs::scoped_log_level(UCS_LOG_LEVEL_TRACE_DATA), which would also cover the truncation fix.

- Cap the gathered dump length by the iface segment size, so that a traced
  packet does not allocate and copy an entire zcopy message
- Drop the unused valid_length argument from the packet dump callbacks
- Use UCT_IB_LOG_LINE_LEN in uct_ib_mlx5_cqe_dump()
- Add a gtest which sends am_zcopy with trace-data logging enabled, covering
  both the gather path and the line cut
@svc-nvidia-pr-review

Copy link
Copy Markdown

🤖 Starting review — findings will be posted here when done.

Comment thread test/gtest/uct/ib/test_ib.cc Resolved
Comment thread src/uct/ib/base/ib_log.c Resolved
Comment thread src/uct/ib/base/ib_log.c Resolved
@svc-ucx

svc-ucx commented Sep 20, 2026

Copy link
Copy Markdown

🤖 CI Triage Agent — UCX PR (Tests BlueField on worker 0) · commit c18a16d3

[incomplete: stop_reason=max_tokens]

- Fit am_zcopy header and payload in max_zcopy, which is 1024 on some
  setups, so the send is not rejected
- Protect the captured log lines with the logger mutex, since trace-data
  is also emitted from the async progress thread
@svc-nvidia-pr-review

Copy link
Copy Markdown

🤖 Starting review — findings will be posted here when done.

Comment thread src/uct/ib/base/ib_log.c Resolved
@svc-nvidia-pr-review

Copy link
Copy Markdown

Residual coverage note: the new test covers only am_zcopy; the log_sge-based bcopy path and the data_dump_sge == 0 early return are not exercised.

Residual coverage note: ASSERT_LT(line.size(), UCT_IB_LOG_LINE_LEN) applies to every captured trace-data line, not only IB packet dumps; that holds today because only one IB iface is active in the fixture.

Skip the gather when a single segment is dumped, which is the case for
every IB transport, so the common path passes the segment as it is and
allocates nothing. Keep the sized gather for the multi-segment case, so a
message larger than the stack limit is still dumped in full.
@svc-nvidia-pr-review

Copy link
Copy Markdown

🤖 Starting review — findings will be posted here when done.

Comment thread test/gtest/uct/ib/test_ib.cc Resolved
Comment thread src/uct/ib/base/ib_log.c Resolved
@svc-ucx

svc-ucx commented Sep 22, 2026

Copy link
Copy Markdown

🤖 CI Triage Agent — UCX PR (AddressSanitizer gpu on worker 3) · commit 00e218e3

TL;DR: The ASAN GPU job failed on a single unrelated gtest, mem_type/test_memtype_cache_deferred_create.mt_cache_init/mt_8/2 (cuda-managed), which is an 8-thread test whose "region must NOT be found" assertions race against the other 7 threads' concurrent managed-memory allocations in the same global memtype cache; it is a flaky test, not a regression from PR #11975.

Full analysis

Summary: make test in the centos8_cuda11_asan container exited with error 1 because 1 of 10193 gtests failed: mem_type/test_memtype_cache_deferred_create.mt_cache_init/mt_8/2 (GetParam() = 2 → UCS_MEMORY_TYPE_CUDA_MANAGED); all other 10192 tests passed.

Root cause: Evidence from the log: the only failure is in the multi-threaded memtype-cache test; no ASAN report, no crash, no timeout (the suite ran to completion and tore down normally, largest inter-line gap is a few seconds). Reading the test, UCS_MT_TEST_P(test_memtype_cache_deferred_create, mt_cache_init, 8) runs test_alloc_before_init(1000000, false, 0) in 8 threads simultaneously, each allocating a 1 MB CUDA-managed buffer and then asserting on the single global memtype cache:

  • test_unknown_region_found(b) requires the lookup to return UCS_OK (the region must already be in the cache), which depends on the racing order of "buffer allocated" vs. "another thread triggered deferred cache creation + UCM_EVENT_FLAG_EXISTING_ALLOC scan" (test/gtest/ucs/test_memtype_cache.cc:517-535).
  • test_region_not_found(b) / test_ptr_not_found() look up [ptr, size + UCS_PGT_ADDR_ALIGN) and require either UCS_ERR_NO_ELEM or UCS_MEMORY_TYPE_UNKNOWN (test_memtype_cache.cc:45-52, :92-93). With 8 threads allocating same-type (cuda-managed) buffers concurrently, CUDA frequently hands out adjacent VA ranges, and ucs_memtype_cache_update_internal() explicitly merges adjacent/overlapping regions of the same mem_type and mem_flags (src/ucs/memory/memtype_cache.c:222-232). The merged region then contains the deliberately-overrun lookup range, so the lookup returns UCS_OK with type = cuda-managed and EXPECT_EQ(UCS_MEMORY_TYPE_UNKNOWN, mem_info.type) fails.
    Neither the memtype cache nor CUDA memory handling is touched by this PR (branch wireup_malformed_overrun, a UCP wireup-address change), so this is pre-existing MT-test flakiness amplified by the slow ASAN build.

Implicated commit: unknown — not the PR head 00e218e3; the racy test and the region-merge logic predate it (nearest relevant changes: b6b85316 tomerg-nvidia "UCP/UCT/UCS: Add memory registration flags", 09c96769 Leonid Genkin "UCM: Propagate memory attributes in allocation events", both of which added the mem_flags-sensitive merge path)

File: test/gtest/ucs/test_memtype_cache.cc:572 (mt_cache_init), with the failing assertions at test/gtest/ucs/test_memtype_cache.cc:45-52 and :92-93; merge logic at src/ucs/memory/memtype_cache.c:222-232

Suggested fix: Re-run the gpu on worker 3 job to unblock PR #11975 — it is not a regression. For a durable fix, make the MT test not assert on "not found" ranges that other threads can influence: in test_alloc_before_init, skip test_region_not_found() / test_ptr_not_found() when running multi-threaded (e.g. guard with barrier()-synchronized single-thread sections or if (num_threads() == 1)), or serialize the allocate-and-check sequence with a mutex so only one 1 MB cuda-managed buffer is live per check. Alternatively restrict mt_cache_init to verifying concurrent deferred cache creation (the lookup/UCS_OK part) and drop the adjacency/overrun negative checks, which are already covered by the single-threaded allocate_and_update / lookup_adjacent_regions variants.

Related: none found (no existing issue/PR matches test_memtype_cache_deferred_create / mt_cache_init in this repo)

@svc-nvidia-pr-review

Copy link
Copy Markdown

🤖 Starting review — findings will be posted here when done.

@svc-ucx

svc-ucx commented Sep 23, 2026

Copy link
Copy Markdown

🤖 CI Triage Agent — UCX PR (Tests gpu on worker 0) · commit 9f12761a

TL;DR: The GPU gtest job failed on a single protocol-selection assertion — shm_ib/test_ucp_proto_am_rndv.am_explicit_scheme_disables_force_provenance/0 (shm,ib,cuda_copy,rocm_copy) — a CUDA/RNDV selection test with RNDV_SCHEME=get_zcopy that is unrelated to this PR's wireup-address change; re-run against a clean master baseline and, if it reproduces, relax/guard the am/rndv expectation in test_ucp_proto.cc.

Full analysis

Summary: make test in the gpu worker-0 job exited with Error 1 because exactly 1 of 10304 gtests failed: shm_ib/test_ucp_proto_am_rndv.am_explicit_scheme_disables_force_provenance/0, where GetParam() = shm,ib,cuda_copy,rocm_copy. All other tests passed or were skipped, and the run showed continuous progress (4,705 s total, no multi-minute gaps → no hang, no timeout).

Root cause: The failing test (test/gtest/ucp/test_ucp_proto.cc:805-813) runs with RNDV_PIPELINE_SHM_CUDA_STAGING_FORCE=y and RNDV_SCHEME=get_zcopy, then calls check_am_rndv_remote_proto_config(0, 0), which hard-asserts that (a) the selected AM-send protocol for 1 MB CUDA memory is literally "am/rndv" (EXPECT_STREQ at line 438) and (b) no rkey config carries UCP_RKEY_CONFIG_FLAG_PROTO_ESTIMATION (line 457). These are configuration-sensitive assertions on protocol selection, which is exactly the area recently churned on master: fe0ea858 "UCP/RMA: Make put/rndv and get/rndv a fallback of zcopy (#11940)" (2026-09-22, one day before this build) touches this same test file and changes what gets selected under RNDV_SCHEME=get_zcopy, and 0311ed79 "UCP/PROTO/RNDV: Isolate remote system device namespace (#11685)" introduced this "force provenance" test family, which already required dedicated Azure protocol-selection diagnostic PRs (#11858, #11861, #11864). Nothing in this code path involves wireup address parsing, which is what branch wireup_malformed_overrun (PR #11975) modifies; a malformed-wireup-message change that broke ep configuration would have failed far more than one CUDA-specific selection test. Note: the per-assertion gtest output (Value of:/Actual: lines) is above the retrievable tail of the Azure log, so the precise failing EXPECT could not be quoted — only the summary [ FAILED ] line.

Implicated commit: Not from this PR. Most likely fe0ea858 (Thomas Vegas, #11940, 2026-09-22), with 0311ed79 (jeffnvidia, #11685) as the origin of the test; PR #11975 commit 9f12761 is not plausibly implicated.

File: test/gtest/ucp/test_ucp_proto.cc:805 (test body), with the failing assertions at test/gtest/ucp/test_ucp_proto.cc:438 and test/gtest/ucp/test_ucp_proto.cc:457

Suggested fix: 1) Re-run the gpu job on PR #11975 (and on a bare master build of the same container/GPU node) to confirm the failure is not caused by the PR — expect it to reproduce without the wireup change. 2) If it reproduces on master, fix the test rather than the PR: in select_am_rndv_remote_proto_config(), replace the unconditional EXPECT_STREQ("am/rndv", ...) with a skip when the selected protocol is not am/rndv under a forced RNDV_SCHEME (mirroring the existing "stub protocol" skip at line 700), and re-validate the UCP_RKEY_CONFIG_FLAG_PROTO_ESTIMATION == 0 expectation against the new put/rndv-get/rndv-as-zcopy-fallback selection logic from #11940. 3) Do not increase any time limit — the job was not time-killed.

Related: #11940, #11685, #11858, #11861, #11864

@tvegas1
tvegas1 enabled auto-merge (squash) September 28, 2026 07:04
@tvegas1
tvegas1 merged commit 672f0fb into openucx:master Sep 28, 2026
162 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.

4 participants