ASan detected heap-use-after-free in XrdCmsProtocol::Dispatch

[jthiltges]

Running an asan build of 5.5.0 on our local redirector, we've had a repeatable use-after-free show up in cmsd.

cmsd tries to access Data->Ident

xrootd/src/XrdCms/XrdCmsProtocol.cc

Line 1033 in f2ce196

if (!(Data->Ident) || !(*Data->Ident)) Data->Ident = myNode->Ident;

but the memory has already been freed in the destructor

xrootd/src/XrdCms/XrdCmsPrepArgs.hh

Line 69 in f2ce196

~XrdCmsPrepArgs() {if (Data) free(Data);}

ASan output

=================================================================
==6889==ERROR: AddressSanitizer: heap-use-after-free on address 0x615000104d02 at pc 0x00000048216b bp 0x7fde4e0bd790 sp 0x7fde4e0bd780
READ of size 1 at 0x615000104d02 thread T33
    #0 0x48216a in XrdCmsProtocol::Dispatch(XrdCmsProtocol::Bearing, int, int) (/usr/bin/cmsd+0x48216a)
    #1 0x483bac in XrdCmsProtocol::Pander(char const*, int) (/usr/bin/cmsd+0x483bac)
    #2 0x7fde5a2f46a0 in XrdScheduler::Run() (/lib64/libXrdUtils.so.3+0x2226a0)
    #3 0x7fde5a2f49d8 in XrdStartWorking(void*) (/lib64/libXrdUtils.so.3+0x2229d8)
    #4 0x7fde5a184349 in XrdSysThread_Xeq (/lib64/libXrdUtils.so.3+0xb2349)
    #5 0x7fde59495ea4 in start_thread (/lib64/libpthread.so.0+0x7ea4)
    #6 0x7fde591beb0c in clone (/lib64/libc.so.6+0xfeb0c)

0x615000104d02 is located 2 bytes inside of 256-byte region [0x615000104d00,0x615000104e00)
freed by thread T69 here:
    #0 0x7fde5ab96508 in __interceptor_free (/lib64/libasan.so.4+0xde508)
    #1 0x47e4c1 in XrdCmsPrepArgs::DoIt() (/usr/bin/cmsd+0x47e4c1)

previously allocated by thread T33 here:
    #0 0x7fde5ab974f0 in posix_memalign (/lib64/libasan.so.4+0xdf4f0)
    #1 0x7fde5a7ea774 in XrdCmsRRData::getBuff(unsigned long) (/lib64/libXrdServer.so.3+0x200774)

Thread T33 created by T32 here:
    #0 0x7fde5aaefa7f in pthread_create (/lib64/libasan.so.4+0x37a7f)
    #1 0x7fde5a184b8d in XrdSysThread::Run(unsigned long*, void* (*)(void*), void*, int, char const*) (/lib64/libXrdUtils.so.3+0xb2b8d)

...

SUMMARY: AddressSanitizer: heap-use-after-free (/usr/bin/cmsd+0x48216a) in XrdCmsProtocol::Dispatch(XrdCmsProtocol::Bearing, int, int)
Shadow bytes around the buggy address:
  0x0c2a80018950: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c2a80018960: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c2a80018970: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c2a80018980: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c2a80018990: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
=>0x0c2a800189a0:[fd]fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c2a800189b0: fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd fd
  0x0c2a800189c0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c2a800189d0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c2a800189e0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
  0x0c2a800189f0: fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa fa
Shadow byte legend (one shadow byte represents 8 application bytes):
  Addressable:           00
  Partially addressable: 01 02 03 04 05 06 07
  Heap left redzone:       fa
  Freed heap region:       fd
  Stack left redzone:      f1
  Stack mid redzone:       f2
  Stack right redzone:     f3
  Stack after return:      f5
  Stack use after scope:   f8
  Global redzone:          f9
  Global init order:       f6
  Poisoned by user:        f7
  Container overflow:      fc
  Array cookie:            ac
  Intra object redzone:    bb
  ASan internal:           fe
  Left alloca redzone:     ca
  Right alloca redzone:    cb
==6889==ABORTING

gdb output

READ of size 1 at 0x615000104d02 thread T33

Matches address of Data.Ident

(gdb) print *Data
$9 = {
  Request = {
    streamid = 77126880,
    rrCode = 20 '\024',
    modifier = 32 ' ',
    datalen = 28928
  },
  Path = 0x615000105000 "/store/data/Run2018A/SingleMuon/MINIAOD/UL2018_MiniAODv2_GT36-v1/60000/0A90FC4F-17F6-1240-94C9-33818749C276.root",
  Opaque = 0x0,
  Path2 = 0xbebebebebebebebe <Address 0xbebebebebebebebe out of bounds>,
  Opaque2 = 0x0,
  Avoid = 0xbebebebebebebebe <Address 0xbebebebebebebebe out of bounds>,
  Reqid = 0x615000104d2b "044683e1b811:ec73271f.634421f9:398431",
  Notify = 0x615000104d53 "*",
  Prty = 0x615000104d57 "0",
  Mode = 0x615000104d5b "rq",
  Ident = 0x615000104d02 "",
  Opts = 3200171710,
  PathLen = 113,
  dskFree = 3200171710,
  {
    dskUtil = 3200171710,
    waitVal = -1094795586
  },
  Buff = 0x615000105000 "/store/data/Run2018A/SingleMuon/MINIAOD/UL2018_MiniAODv2_GT36-v1/60000/0A90FC4F-17F6-1240-94C9-33818749C276.root",
  Blen = 256,
  Dlen = 113,
  Routing = 2,
  Next = 0x0
}

(gdb) bt
#0  0x00007fde590f6387 in __GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:55
#1  0x00007fde590f7a78 in __GI_abort () at abort.c:90
#2  0x00007fde5abb848e in __sanitizer::Abort() () from /lib64/libasan.so.4
#3  0x00007fde5abc0288 in __sanitizer::Die() () from /lib64/libasan.so.4
#4  0x00007fde5aba1275 in __asan::ReportGenericError(unsigned long, unsigned long, unsigned long, unsigned long, bool, unsigned long, unsigned int, bool) () from /lib64/libasan.so.4
#5  0x00007fde5aba1d67 in __asan_report_load1 () from /lib64/libasan.so.4
#6  0x000000000048216b in XrdCmsProtocol::Dispatch (this=this@entry=0x60e000066fe0, cDir=cDir@entry=XrdCmsProtocol::isUp, maxWait=maxWait@entry=60000, maxTries=maxTries@entry=2) at /usr/src/debug/xrootd/xrootd/src/XrdCms/XrdCmsProtocol.cc:1033
#7  0x0000000000483bad in XrdCmsProtocol::Pander (this=0x60e000066fe0, manager=<optimized out>, mport=<optimized out>) at /usr/src/debug/xrootd/xrootd/src/XrdCms/XrdCmsProtocol.cc:406
#8  0x00007fde5a2f46a1 in XrdScheduler::Run (this=0x6ce960 <XrdGlobal::Sched>) at /usr/src/debug/xrootd/xrootd/src/Xrd/XrdScheduler.cc:406
#9  0x00007fde5a2f49d9 in XrdStartWorking (carg=<optimized out>) at /usr/src/debug/xrootd/xrootd/src/Xrd/XrdScheduler.cc:89
#10 0x00007fde5a18434a in XrdSysThread_Xeq (myargs=0x603000079030) at /usr/src/debug/xrootd/xrootd/src/XrdSys/XrdSysPthread.cc:86
#11 0x00007fde59495ea5 in start_thread (arg=0x7fde4e0be700) at pthread_create.c:307
#12 0x00007fde591beb0d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

[abh3]

I see that ASAN is complaining but the complaint makes no sense. The Data being referenced in line 1033 is a XrdCmsRRData object while the "Data" being referenced in line 68 is a XrdCmsPerpArgs object. Two completely different allocations with complete different code paths. So, I don't see how this could be a valid complaint. The XrdCmsRRDataObject is, in fact, allocated in the code path where the seemingly invalid reference occurs and is never deleted as it always recycled for reuse. Makes you wonder what is going on.

[jthiltges]

Thanks much for looking at this. I don't have any more data to add, so closing the issue for now.