10.1.0: Cache startup assertion failure

[bneradt]

We tested 10.1.0 on a box in production, with our production branch merged up with this ASF 10.1.x commit:

commit 42f2920bce6df86e0e21a8de85e33a1795e9eff5
Author: Chris McFarlen <chris@mcfarlen.us>
Date:   Tue Mar 11 11:51:42 2025 -0500

    Move defaulting install prefix before layout setup (#12085)
    
    Co-authored-by: Chris McFarlen <cmcfarlen@apple.com>
    (cherry picked from commit 9a1ef119f3b7a017583c9aa5d088b2437101b92a)

gdb shows the following backtrace through an assertion going through PreservationTable::PreservationTable (note that the allocation size is the super large size=size@entry=18446744073709550864):

(gdb) bt
#0  0x00007f0361ea952f in raise () from /lib64/libc.so.6
#1  0x00007f0361e7ce65 in abort () from /lib64/libc.so.6
#2  0x00007f0363a6d3ec in ink_abort (message_format=message_format@entry=0x7f0363a81460 "couldn't allocate %zu bytes") at /home/bneradt/build/_scm/trafficserver10.0/src/tscore/ink_error.cc:99
#3  0x00007f0363a71217 in ats_malloc (size=size@entry=18446744073709550864) at /home/bneradt/build/_scm/trafficserver10.0/src/tscore/ink_memory.cc:66
#4  0x0000000000723fe3 in PreservationTable::PreservationTable (this=0x7f0347725278, size=<optimized out>) at /home/bneradt/build/_scm/trafficserver10.0/src/iocore/cache/PreservationTable.cc:52
#5  0x0000000000733dff in StripeSM::StripeSM (this=this@entry=0x7f0347724000, disk=disk@entry=0x7f01e6685f00, blocks=blocks@entry=54853632, dir_skip=<optimized out>, avg_obj_size=-1, fragment_size=-1) at /home/bneradt/build/_scm/trafficserver10.0/include/tscore/Ptr.h:207
#6  0x00000000006f03b2 in Cache::open (this=0x7f034771edc0, clear=false) at /home/bneradt/build/_scm/trafficserver10.0/src/iocore/cache/Cache.cc:276
#7  0x00000000006fa732 in CacheDisk::openDone (this=<optimized out>) at /home/bneradt/build/_scm/trafficserver10.0/src/iocore/cache/CacheDisk.cc:218
#8  CacheDisk::openStart (this=0x7f01e6686380, event=<optimized out>) at /home/bneradt/build/_scm/trafficserver10.0/src/iocore/cache/CacheDisk.cc:177
#9  0x0000000000738631 in Continuation::handleEvent (data=0x7f01e66863d8, event=3900, this=0x7f01e6686380) at /home/bneradt/build/_scm/trafficserver10.0/include/iocore/eventsystem/Continuation.h:228
#10 Continuation::handleEvent (data=0x7f01e66863d8, event=3900, this=0x7f01e6686380) at /home/bneradt/build/_scm/trafficserver10.0/include/iocore/eventsystem/Continuation.h:224
#11 AIOCallback::io_complete (this=0x7f01e66863d8, event=<optimized out>, data=<optimized out>) at /home/bneradt/build/_scm/trafficserver10.0/src/iocore/aio/AIO.cc:100
#12 0x000000000085ffac in Continuation::handleEvent (data=0x7f01dcb01000, event=1, this=<optimized out>) at /home/bneradt/build/_scm/trafficserver10.0/include/iocore/eventsystem/Continuation.h:228
#13 Continuation::handleEvent (data=0x7f01dcb01000, event=1, this=<optimized out>) at /home/bneradt/build/_scm/trafficserver10.0/include/iocore/eventsystem/Continuation.h:224
#14 EThread::process_event (this=0x7f035d98ec80, e=0x7f01dcb01000, calling_code=1) at /home/bneradt/build/_scm/trafficserver10.0/src/iocore/eventsystem/UnixEThread.cc:166
#15 0x00000000008607b6 in EThread::process_queue (this=this@entry=0x7f035d98ec80, NegativeQueue=NegativeQueue@entry=0x7f03592ca590, ev_count=ev_count@entry=0x7f03592ca58c, nq_count=nq_count@entry=0x7f03592ca588) at /home/bneradt/build/_scm/trafficserver10.0/src/iocore/eventsystem/UnixEThread.cc:201
#16 0x0000000000860c2a in EThread::execute_regular (this=this@entry=0x7f035d98ec80) at /home/bneradt/build/_scm/trafficserver10.0/src/iocore/eventsystem/UnixEThread.cc:259
#17 0x0000000000861839 in EThread::execute (this=0x7f035d98ec80) at /home/bneradt/build/_scm/trafficserver10.0/src/iocore/eventsystem/UnixEThread.cc:358
#18 EThread::execute (this=0x7f035d98ec80) at /home/bneradt/build/_scm/trafficserver10.0/src/iocore/eventsystem/UnixEThread.cc:335
#19 0x000000000085e3d2 in spawn_thread_internal (a=0x7f036110cb40) at /home/bneradt/build/_scm/trafficserver10.0/src/iocore/eventsystem/Thread.cc:75
#20 0x00007f03622391ca in start_thread () from /lib64/libpthread.so.0
#21 0x00007f0361e948d3 in clone () from /lib64/libc.so.6

Reverting the following frees the box from crashing on startup: #11825.

[JosiahWI]

Probably caused by the same root cause as #12123.

[JosiahWI]

In #11825 I unwarily moved the place where the static_cast from the unsigned stripe length to the signed preservation table size happened. I believe if the resulting size does not fit in the positive part of an int, the size will be negative, which violates a debug assert (not triggered in the reported case because it was a release build), and is divided by the bucket size to make a smaller negative number and cast back to unsigned for the allocation call. That's why it would attempt to allocate a very large amount of memory... approaching the maximum allocation value. The issue will only be observed if the configuration specifies a stripe length that can't be represented as a positive int, so the unit tests in CI do not catch it.

[bneradt]

@JosiahWI provided the following patch. I built it and deployed it in production and vefified that with it ATS starts up stable in our production environment:

From 255fe9c5d8363080c851dc24877dbaa64f3bc031 Mon Sep 17 00:00:00 2001
From: Josiah VanderZee <jvanderzee@apache.org>
Date: Mon, 24 Mar 2025 18:12:40 -0500
Subject: [PATCH] Fix narrowing conversion in StripeSM construction

---
 src/iocore/cache/PreservationTable.cc | 2 +-
 src/iocore/cache/PreservationTable.h  | 2 +-
 src/iocore/cache/StripeSM.cc          | 2 +-
 3 files changed, 3 insertions(+), 3 deletions(-)

diff --git a/src/iocore/cache/PreservationTable.cc b/src/iocore/cache/PreservationTable.cc
index f8ad81fde..0c5dc3b71 100644
--- a/src/iocore/cache/PreservationTable.cc
+++ b/src/iocore/cache/PreservationTable.cc
@@ -45,7 +45,7 @@ DbgCtl dbg_ctl_cache_evac{"cache_evac"};
 
 } // namespace
 
-PreservationTable::PreservationTable(int size) : evacuate_size{(size / EVACUATION_BUCKET_SIZE) + 2}
+PreservationTable::PreservationTable(off_t size) : evacuate_size{static_cast<int>(size / EVACUATION_BUCKET_SIZE) + 2}
 {
   ink_assert(size > 0);
   int evac_len   = this->evacuate_size * sizeof(DLL<EvacuationBlock>);
diff --git a/src/iocore/cache/PreservationTable.h b/src/iocore/cache/PreservationTable.h
index acf762cce..1b55258f0 100644
--- a/src/iocore/cache/PreservationTable.h
+++ b/src/iocore/cache/PreservationTable.h
@@ -110,7 +110,7 @@ public:
    * @param size The total number of directory entries the table must
    * be able to store. The size must be a positive number.
    */
-  PreservationTable(int size);
+  PreservationTable(off_t size);
 
   ~PreservationTable();
 
diff --git a/src/iocore/cache/StripeSM.cc b/src/iocore/cache/StripeSM.cc
index 0ec046c39..40a3877d2 100644
--- a/src/iocore/cache/StripeSM.cc
+++ b/src/iocore/cache/StripeSM.cc
@@ -117,7 +117,7 @@ StripeSM::StripeSM(CacheDisk *disk, off_t blocks, off_t dir_skip, int avg_obj_si
     Stripe{disk, blocks, dir_skip, avg_obj_size, fragment_size},
     fd{disk->fd},
     disk{disk},
-    _preserved_dirs{static_cast<int>(len)}
+    _preserved_dirs{len}
 {
   open_dir.mutex = this->mutex;
   SET_HANDLER(&StripeSM::aggWrite);
-- 
2.48.1

[masaori335]

Pretty interesting. I agree with @JosiahWI 's comment. It looks like #11825 changed when static_cast<int> is executed to what.

static_cast<int>(len / EVACUATION_BUCKET_SIZE) + 2

vs

(static_cast<int>(len) / EVACUATION_BUCKET_SIZE) + 2

[JosiahWI]

My description is slightly incorrect. It turns out off_t is signed. However, the narrowing cast does seem to be the root cause.