Debug builds: cache unit tests intermittently SIGSEGV in lock_waiting() reading the mutex holder's SourceLocation

[bneradt]

Summary

Debug builds intermittently SIGSEGV in the debug-only lock-contention tracking:
a thread that fails a try-lock reads the current holder's SourceLocation out
of the ProxyMutex without holding anything, and SourceLocation::str() then
faults dereferencing a stale file pointer.

The cache unit tests are the only thing in the tree that enables the locks
debug tag, so this surfaces as a rare test_cache_* segfault on the Fedora CI
job. It is not a cache bug; the cache tests are just the trigger.

How we saw it in CI

The Fedora job failed on an unrelated PR (#13523, an HttpSM change) with:

26/186 Test  #29: test_cache_Update_L_to_S ...............***Exception: SegFault  1.01 sec
...
99% tests passed, 1 tests failed out of 186

The following tests FAILED:
	 29 - test_cache_Update_L_to_S (SEGFAULT)

https://ci.trafficserver.apache.org/job/Github_Builds/job/fedora/9141/

The test's own output ends like this — note the two lock-tracking warnings
immediately before the crash:

[...] DIAG: <CacheRead.cc:224 (openReadFromWriter)> (cache_read_agg) 0x2236840: key: B7088DC0 In openReadFromWriter
[...] DIAG: <CacheVC.cc:510 (handleRead)> (cache_ram) all memory cache miss
WARNING: holding lock CacheRead.cc:789 (openReadStartEarliest) too long for UNKNOWN
[...] DIAG: <StripeSM.cc:742 (aggWriteDone)> (cache_agg) ...
WARNING: holding lock UnixEThread.cc:156 (process_event) too long for UNKNOWN

DummyLocation:18446744073709551615: FAILED:
  {Unknown expression after the reported line}
due to a fatal error condition:
  SIGSEGV - Segmentation violation signal

The PR under test cannot be responsible: add_cache_test builds each cache test
from unit_tests/main.cc, unit_tests/stub.cc, unit_tests/CacheTestHandler.cc
and the test source, linked against ts::inkcache and Catch2 only. Nothing from
libhttp is in the binary.

Reproduction

On master at b9b9109 with no modifications, using the CI configuration
(clang, CMAKE_BUILD_TYPE=Debug):

cmake -B build --preset ci-fedora-cxx20 -DBUILD_TESTING=ON
cmake --build build
cd build
# Loop this; it fails roughly 1 in 12-20 iterations.
for i in $(seq 1 30); do ctest -R "^test_cache_" -j 8 --output-on-failure; done

Observed:

What	Result
test_cache_Update_L_to_S alone, 25 runs	25 pass
ctest -R "^test_cache_" -j 8, 12 iterations	1 crash (Update_S_to_L)
ctest -R "^test_cache_" -j 8, 30 iterations	1 crash (Alternate_S_to_L)

It never fails standalone, and it lands on a different test in the
Update/Alternate family each time, which is what pointed at shared code rather
than any one test.

An ASan build did not reproduce it in 15 iterations of the same loop, and runs
supervised by gdb did not reproduce it in 120 attempts — both perturb the timing
window. A concurrently running unsupervised Alternate_L_to_S did crash and
dump a core, which is where the backtrace below comes from.

Backtrace

#0  0x0000ffffb0137e50 in strrchr () from /lib64/libc.so.6
#1  0x00000000008e0708 in SourceLocation::str (this=0x2cc09858, buf=..., buflen=128)
      at src/tsutil/SourceLocation.cc:48
#2  0x00000000008669e4 in lock_waiting (srcloc=..., handler=0x0)
      at src/iocore/eventsystem/Lock.cc:47
#3  0x0000000000472dd0 in Mutex_trylock (location=..., ahandler=0x0, m=0x2cc09800, t=...)
      at include/iocore/eventsystem/Lock.h:264
#4  0x0000000000472d04 in Mutex_trylock (...) at include/iocore/eventsystem/Lock.h:303
#5  0x00000000004707f0 in MutexTryLock::MutexTryLock (...) at include/iocore/eventsystem/Lock.h:590
#6  0x000000000049fbb8 in CacheVC::openReadStartHead (this=..., event=2, e=...)
      at src/iocore/cache/CacheRead.cc:1014
#7  0x0000000000468064 in Continuation::handleEvent (...)
#8  0x0000000000868464 in EThread::process_event (...) at src/iocore/eventsystem/UnixEThread.cc:171
#9  0x0000000000868b48 in EThread::execute_regular (...)

m = 0x2cc09800 is the ProxyMutex; this = 0x2cc09858 in frame #1 is
m->srcloc inside it.

Analysis

Mutex_trylock, include/iocore/eventsystem/Lock.h:261:

  if (m->thread_holding != t) {
    if (!ink_mutex_try_acquire(&m->the_mutex)) {
#ifdef DEBUG
      lock_waiting(m->srcloc, m->handler);   // line 264
#endif
      return false;
    }

The thread reaching line 264 just failed to acquire the mutex, so it holds
nothing, yet it reads m->srcloc and m->handler. Those fields are owned by
whoever holds the mutex and are written non-atomically:

• Lock.h:276-277 (Mutex_trylock, after acquiring)
• Lock.h:323-324 (Mutex_lock, after acquiring)
• Lock.h:370-371 (Mutex_unlock, cleared before ink_mutex_release)

SourceLocation::operator= copies file, func and line as three separate
stores, so a racing reader can observe a mixture of old and new fields.
SourceLocation::valid() only checks file && line
(include/tsutil/SourceLocation.h:49), so a stale file with a non-zero line
passes validation and strrchr(file, '/')
(src/tsutil/SourceLocation.cc:48) faults.

Three conditions have to coincide, which is why this is so rare and why it only
ever shows up in these tests:

1. A Debug build. The whole block is #ifdef DEBUG, defined by
   CMakeLists.txt:63 when CMAKE_BUILD_TYPE is Debug — that is the ci
   preset family, including ci-fedora-cxx20.
2. The locks debug tag enabled. lock_waiting() only calls
   SourceLocation::str() inside if (dbg_ctl_locks.on())
   (src/iocore/eventsystem/Lock.cc:45-49). The cache unit tests are the only
   place that turns it on:
   src/iocore/cache/unit_tests/main.cc:132 does
   diags()->activate_taglist("cache.*|agg.*|locks", DiagsTagType_Debug).
3. Lock contention. Line 264 is reached only when ink_mutex_try_acquire
   fails, which is why parallelism matters and a solo run never trips it.

The two WARNING: holding lock ... too long for UNKNOWN lines in the CI output
come from lock_holding() in Mutex_unlock, which is called while holding the
lock and is safe. They are the tell that the locks tag was active and that
contention was occurring — the precondition for the crashing lock_waiting path.

Possible fix

lock_waiting() is the only one of these that reads holder state without
holding the lock. Reporting the waiter's location — already passed in, always
a __FILE__ literal, never raced — instead of m->srcloc removes the race
outright. That does drop "who is holding it" from the message, so if that
information is worth keeping the alternative is to make the debug fields
atomically publishable rather than three plain stores. Happy to put up a PR
either way once there is a preference.

Environment

• master at b9b9109, unmodified.
• cmake --preset ci-fedora-cxx20 -DBUILD_TESTING=ON, clang, CMAKE_BUILD_TYPE=Debug.
• Reproduced in a Fedora 44 container. Note this was aarch64, whereas the CI
  job that failed is x86_64; same source and same preset, different architecture.
  The CI log's evidence is consistent with this mechanism but we have not proven
  the CI crash is the identical one.
• The code involved is long-standing, so 10.2.x and earlier are very likely
  affected too.