castor::tape::tapeserver::daemon::Payload not being deallocated in cta-readtp

As we have started to read more files for a single run of the cta-readtp tool, a memory problem has shown itself.

cta-readtp starts normally:

-bash-4.2$ cta-readtp I72930 1-
Feb  7 15:05:05.813444 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Started" userName="vlado" tapeVid="I72930" 
Feb  7 15:05:05.815299 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Read configuration" catalogueDbType="DBTYPE_ORACLE" catalogueDatabase="cta" catalogueUsername="CTAPPS" devFilename="/dev/nst0" rawLibrarySlot="smc3" logicalLibrary="IBM460" unitName="I4600214" 
Feb  7 15:05:05.815383 tpsrv454.cern.ch cta-readtp: LVL="DEBUG" PID="48933" TID="48933" MSG="Set process capabilities" capabilities="cap_sys_rawio+ep" 
Feb  7 15:05:05.819107 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Mounting tape" userName="vlado" tapeVid="I72930" tapeDrive="I4600214" logicalLibrary="IBM460" librarySlot="smc3" useLbp="true" driveSupportLbp="true" 
Feb  7 15:05:23.277303 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Mounted tape" userName="vlado" tapeVid="I72930" tapeDrive="I4600214" logicalLibrary="IBM460" librarySlot="smc3" useLbp="true" driveSupportLbp="true" 
Feb  7 15:05:23.277460 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Loading tape" userName="vlado" tapeVid="I72930" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" 
Feb  7 15:05:31.495068 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Loaded tape" userName="vlado" tapeVid="I72930" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" 
Feb  7 15:05:31.778881 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Drive encryption enabled for this mount" encryption="on" encryptionKey="validation_v1" stdout="Encryption key found." 
Feb  7 15:05:31.900288 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Reading file from tape" userName="vlado" tapeVid="I72930" fSeq="1" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" destinationURL="file:///dev/null" 
Feb  7 15:05:33.623723 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Read file from tape successfully" userName="vlado" tapeVid="I72930" fSeq="1" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" destinationURL="file:///dev/null" checksumType="ADLER32" checksumValue="0xbbd0328d" readFileSize="721135437" 
Feb  7 15:05:33.720929 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Reading file from tape" userName="vlado" tapeVid="I72930" fSeq="2" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" destinationURL="file:///dev/null" 
Feb  7 15:05:33.784819 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Read file from tape successfully" userName="vlado" tapeVid="I72930" fSeq="2" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" destinationURL="file:///dev/null" checksumType="ADLER32" checksumValue="0x73124182" readFileSize="7980804" 
Feb  7 15:05:33.874942 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Reading file from tape" userName="vlado" tapeVid="I72930" fSeq="3" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" destinationURL="file:///dev/null" 
Feb  7 15:05:33.926943 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Read file from tape successfully" userName="vlado" tapeVid="I72930" fSeq="3" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" destinationURL="file:///dev/null" checksumType="ADLER32" checksumValue="0x4a7220bf" readFileSize="7943953" 
Feb  7 15:05:34.018378 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Reading file from tape" userName="vlado" tapeVid="I72930" fSeq="4" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" destinationURL="file:///dev/null" 
Feb  7 15:05:34.289929 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Read file from tape successfully" userName="vlado" tapeVid="I72930" fSeq="4" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" destinationURL="file:///dev/null" checksumType="ADLER32" checksumValue="0xdc91f360" readFileSize="147257151" 
Feb  7 15:05:34.381777 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Reading file from tape" userName="vlado" tapeVid="I72930" fSeq="5" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" destinationURL="file:///dev/null" 
Feb  7 15:05:35.326877 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Read file from tape successfully" userName="vlado" tapeVid="I72930" fSeq="5" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" destinationURL="file:///dev/null" checksumType="ADLER32" checksumValue="0x5ccab834" readFileSize="546913961" 
     :
     :
     :

but after some time, it is has memory problems:

Feb  7 15:28:15.172894 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Reading file from tape" userName="vlado" tapeVid="I72930" fSeq="2477" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" destinationURL="file:///dev/null" 
Feb  7 15:28:15.217020 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Read file from tape successfully" userName="vlado" tapeVid="I72930" fSeq="2477" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" destinationURL="file:///dev/null" checksumType="ADLER32" checksumValue="0xcd1ff8db" readFileSize="3387392" 
Feb  7 15:28:15.314279 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Reading file from tape" userName="vlado" tapeVid="I72930" fSeq="2478" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" destinationURL="file:///dev/null" 
Feb  7 15:28:15.363595 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Read file from tape successfully" userName="vlado" tapeVid="I72930" fSeq="2478" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" destinationURL="file:///dev/null" checksumType="ADLER32" checksumValue="0xe2406ced" readFileSize="5268864" 
Feb  7 15:28:15.457562 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Reading file from tape" userName="vlado" tapeVid="I72930" fSeq="2479" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" destinationURL="file:///dev/null" 
Feb  7 15:28:16.799541 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Read file from tape successfully" userName="vlado" tapeVid="I72930" fSeq="2479" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" destinationURL="file:///dev/null" checksumType="ADLER32" checksumValue="0xd078940d" readFileSize="610963596" 
Feb  7 15:28:16.890080 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Reading file from tape" userName="vlado" tapeVid="I72930" fSeq="2480" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" destinationURL="file:///dev/null" 
Feb  7 15:28:16.959554 tpsrv454.cern.ch cta-readtp: LVL="ERROR" PID="48933" TID="48933" MSG="Failed to read file from tape" userName="vlado" tapeVid="I72930" destinationFile="file:///dev/null" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" fSeq="2480" tapeReadError="Failed to allocate memory for a new MemBlock!" 
Feb  7 15:28:17.049571 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Reading file from tape" userName="vlado" tapeVid="I72930" fSeq="2481" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" destinationURL="file:///dev/null" 
Feb  7 15:28:17.090114 tpsrv454.cern.ch cta-readtp: LVL="ERROR" PID="48933" TID="48933" MSG="Failed to read file from tape" userName="vlado" tapeVid="I72930" destinationFile="file:///dev/null" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" fSeq="2481" tapeReadError="Failed to allocate memory for a new MemBlock!" 
Feb  7 15:28:17.187403 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Reading file from tape" userName="vlado" tapeVid="I72930" fSeq="2482" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" destinationURL="file:///dev/null" 
Feb  7 15:28:17.230853 tpsrv454.cern.ch cta-readtp: LVL="ERROR" PID="48933" TID="48933" MSG="Failed to read file from tape" userName="vlado" tapeVid="I72930" destinationFile="file:///dev/null" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" fSeq="2482" tapeReadError="Failed to allocate memory for a new MemBlock!" 
Feb  7 15:28:17.325831 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Reading file from tape" userName="vlado" tapeVid="I72930" fSeq="2483" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" destinationURL="file:///dev/null" 
Feb  7 15:28:19.825547 tpsrv454.cern.ch cta-readtp: LVL="ERROR" PID="48933" TID="48933" MSG="Failed to read file from tape" userName="vlado" tapeVid="I72930" destinationFile="file:///dev/null" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" fSeq="2483" tapeReadError="Failed to allocate memory for a new MemBlock!" 

and is killed:

Feb  7 15:35:07.960554 tpsrv454.cern.ch cta-readtp: LVL="ERROR" PID="48933" TID="48933" MSG="Failed to read file from tape" userName="vlado" tapeVid="I72930" destinationFile="file:///dev/null" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" fSeq="3505" tapeReadError="Failed to allocate memory for a new MemBlock!"
Feb  7 15:35:08.059871 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Reading file from tape" userName="vlado" tapeVid="I72930" fSeq="3506" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" destinationURL="file:///dev/null"
Feb  7 15:35:08.104347 tpsrv454.cern.ch cta-readtp: LVL="ERROR" PID="48933" TID="48933" MSG="Failed to read file from tape" userName="vlado" tapeVid="I72930" destinationFile="file:///dev/null" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" fSeq="3506" tapeReadError="Failed to allocate memory for a new MemBlock!"
Feb  7 15:35:08.201927 tpsrv454.cern.ch cta-readtp: LVL="INFO" PID="48933" TID="48933" MSG="Reading file from tape" userName="vlado" tapeVid="I72930" fSeq="3507" tapeDrive="I4600214" logicalLibrary="IBM460" useLbp="true" driveSupportLbp="true" destinationURL="file:///dev/null"
Zabitý
-bash-4.2$

There is one heap allocation in the code that is not being deallocated:

const auto reader = castor::tape::tapeFile::FileReaderFactory::create(readSession, fileToRecall);
  auto checksum_adler32 = castor::tape::tapeserver::daemon::Payload::zeroAdler32();
  const size_t buffer_size = 1 * 1024 * 1024 * 1024;  // 1Gb
  size_t read_data_size = 0;
  // allocate one gigabyte buffer
  auto payload = new castor::tape::tapeserver::daemon::Payload(buffer_size);
  try {
    while (1) {
      if (payload->remainingFreeSpace() <= reader->getBlockSize()) {
        // buffer is full, flush to file and update checksum
        read_data_size += payload->size();
        checksum_adler32 = payload->adler32(checksum_adler32);
        payload->write(wf);
        payload->reset();
      }
      payload->append(*reader);
    }
  } catch (cta::exception::EndOfFile&) {
    // File completely read
  }

Switching to a unique pointer should fix the problem.

added Operator Tools workflowIn Progress labels

assigned to @lwardena

changed the description

created branch 301-castor-tape-tapeserver-daemon-payload-not-being-deallocated-in-cta-readtp to address this issue

mentioned in merge request !179 (merged)

closed with merge request !179 (merged)

changed milestone to %Release 4.8.5

removed workflowIn Progress label