bneradt opened a new issue, #13524:
URL: https://github.com/apache/trafficserver/issues/13524
## 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 b9b9109864 with no modifications, using the CI configuration
(clang, `CMAKE_BUILD_TYPE=Debug`):
```bash
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`:
```cpp
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 b9b9109864, 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.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
