Errors in remote client reading of TTree from TFile via xrootd while simultaneously updating TTree on server

jmusser · February 9, 2021, 10:39pm

I am writing a simple remote data monitoring program based on the xrootd protocol, with a server node continuously writing to a local ttree to file with a remote client reader. The simultaneous read/write works fine when the client code is run on the server (bypassing xrootd), but fails when the read access remote via xrootd, with the following error:

Error in TNetXNGFile::Init: file root://128.135.152.71:1095//home/jmusser/data/out.root is truncated at 112908476 bytes: should be 114851302, trying to recover

Proof-of-concept client and server-side code blocks are appended below.
The reads are fine when the client reader has direct access to the root file, and also from a remote client if the root file is closed and write operations are not occurring. Failure occurs as above for remote access to a file open for writing.
Many thanks for any help!

Reader script

#include "HTCom_DCTRawFrame.h"
{
  TFile *  ipf = TFile::Open("root://111.111.111.111:1095//home/jmusser/data/out.
root");
  int ikey;
  HTCom_DCTRawFrame * rawframe;
 
  TTree *t(nullptr);
    
  delete ipf->FindObject("t");
  ipf->ReadKeys();
  ipf->GetObject("t",t);
  if(t){
      t->SetBranchAddress("key",&ikey);
      t->SetBranchAddress("data",&rawframe);
      int N= t->GetEntries();
      cout << "Entries: " << N << endl;
      t->GetEntry(N-1);
      cout << "Reading tree at address " <<N-1 << " of " << N << "->  ivec[0]="<
< ikey << endl;
    }
}

Writer script

#include <stdlib.h>
#include "HTCom_DCTRawFrame.h"

{
  HTCom_DCTRawFrame * rawframe = new HTCom_DCTRawFrame();
  TFile *  opf = TFile::Open("out.root", "RECREATE");
  TTree *  t   = new TTree("t", "");
  int ikey;
  t->Branch("key", &ikey, "ikey/I");
  t->Branch("data","HTCom_DCTRawFrame",&rawframe);

  int CNT = 5000;
  for(int n=0;n<CNT;n++){
    ikey=n;
    if(n%1000==0)cout << "Writing event #" << n  <<endl;
    t->Fill();
    opf->Write(0,TObject::kWriteDelete);
    rawframe->Clear();
    sleep(0.1+gRandom->Uniform(.1));
  }
  opf->Write(0, TObject::kWriteDelete); //safer, but slower
  opf->Close();
}

_ROOT Version:_6.20-04
_Platform:_CentOS8
Compiler: gcc 9.2.0

Axel · February 10, 2021, 10:02am

I’ve invited a couple of our xrootd experts to have a look at your issue; if that fails maybe @pcanal could have a look?

simonm · February 10, 2021, 3:58pm

Well, it seems to me that the remote I/O plug-in was not loaded. The error message comes from here:

github.com

root-project/root/blob/master/io/io/src/TFile.cxx#L788-L791


if (fEND > size) {
   if (tryrecover) {
      Error("Init","file %s is truncated at %lld bytes: should be %lld, "
            "trying to recover", GetName(), size, fEND);

which is part of the TFile::Init routine, which in turn is called from TFile constructor:

github.com

root-project/root/blob/master/io/io/src/TFile.cxx#L489


      fD = TFile::SysOpen(fname, O_RDONLY | O_BINARY, S_IREAD | S_IWRITE);
#endif
      if (fD == -1) {
         SysError("TFile", "file %s can not be opened for reading", fname);
         goto zombie;
      }
      fWritable = kFALSE;
   }
   // calling virtual methods from constructor not a good idea, but it is how code was developed
   TFile::Init(create);                        // NOLINT: silence clang-tidy warnings
   return;
zombie:
   // error in file opening occurred, make this object a zombie
   {
      R__LOCKGUARD(gROOTMutex);
      gROOT->GetListOfClosedObjects()->Add(this);
   }
   MakeZombie();

Now, if understand the code correctly this constructor should be used for local files:

github.com

root-project/root/blob/master/io/io/src/TFile.cxx#L4122-L4130


if (type == kLocal) {
   // Local files
   if (lfname.IsNull()) {
      urlname.SetHost("");
      urlname.SetProtocol("file");
      lfname = urlname.GetUrl();
   }
   f = new TFile(lfname.Data(), option, ftitle, compress);

and in case of root:// the object should be constructed with a factory method:

github.com

root-project/root/blob/master/io/io/src/TFile.cxx#L4132-L4138


} else if (type == kNet) {
   // Network files
   if ((h = gROOT->GetPluginManager()->FindHandler("TFile", name))) {
      if (h->LoadPlugin() == -1)
         return nullptr;
      f = (TFile*) h->ExecPlugin(5, name.Data(), option, ftitle, compress, netopt);

In order to verify this hypothesis, could you please rerun your program with XRD_LOGLEVEL=Dump, and give us the output?

jmusser · February 10, 2021, 7:49pm

The log files that you wanted captured are verbose, but I’ve grabbed the log dump snippets for two cases and append below. Case 1 is accessing a closed remote file successfully. The log entries covers the activity through the first successful read. Case 2 is when the remote file is open and is being written to. Log entries here extend to the first error message. The messages begin in both cases by warning of a lack of a user config file and default plug-ins, but this seems probably not the issue, as the successful read has the same messages. In any case, if an you could take a look and offer suggestions, that would be super. Sorry for the length of the log file dumps…

Case 1 (successful remote read of a closed file)

root [0]   gSystem->Load("../GITrepo/helix-flight-software/build/lib/libDCTDisplayer.so");
root [1]   .x testxrootd_read.C
[2021-02-10 14:00:03.305049 -0500][Debug  ][Utility           ] Unable to process user config file: [ERROR] OS Error: No such file or directory
[2021-02-10 14:00:03.305162 -0500][Debug  ][PlugInMgr         ] Initializing plug-in manager...
[2021-02-10 14:00:03.305169 -0500][Debug  ][PlugInMgr         ] No default plug-in, loading plug-in configs...
[2021-02-10 14:00:03.305174 -0500][Debug  ][PlugInMgr         ] Processing plug-in definitions in /etc/xrootd/client.plugins.d...
[2021-02-10 14:00:03.305208 -0500][Debug  ][PlugInMgr         ] Processing plug-in definitions in /home/jmusser/.xrootd/client.plugins.d...
[2021-02-10 14:00:03.305215 -0500][Debug  ][PlugInMgr         ] Unable to process directory /home/jmusser/.xrootd/client.plugins.d: [ERROR] OS Error: No such file or directory
[2021-02-10 14:00:03.310601 -0500][Dump   ][Utility           ] URL: root://128.135.152.71:1095//home/jmusser/data/out.root
[2021-02-10 14:00:03.310601 -0500][Dump   ][Utility           ] Protocol:  root
[2021-02-10 14:00:03.310601 -0500][Dump   ][Utility           ] User Name: 
[2021-02-10 14:00:03.310601 -0500][Dump   ][Utility           ] Password:  
[2021-02-10 14:00:03.310601 -0500][Dump   ][Utility           ] Host Name: 128.135.152.71
[2021-02-10 14:00:03.310601 -0500][Dump   ][Utility           ] Port:      1095
[2021-02-10 14:00:03.310601 -0500][Dump   ][Utility           ] Path:      /home/jmusser/data/out.root
[2021-02-10 14:00:03.310627 -0500][Dump   ][Utility           ] URL: root://128.135.152.71:1095//home/jmusser/data/out.root
[2021-02-10 14:00:03.310627 -0500][Dump   ][Utility           ] Protocol:  root
[2021-02-10 14:00:03.310627 -0500][Dump   ][Utility           ] User Name: 
[2021-02-10 14:00:03.310627 -0500][Dump   ][Utility           ] Password:  
[2021-02-10 14:00:03.310627 -0500][Dump   ][Utility           ] Host Name: 128.135.152.71
[2021-02-10 14:00:03.310627 -0500][Dump   ][Utility           ] Port:      1095
[2021-02-10 14:00:03.310627 -0500][Dump   ][Utility           ] Path:      /home/jmusser/data/out.root
[2021-02-10 14:00:03.310647 -0500][Dump   ][Utility           ] URL: root://128.135.152.71:1095//home/jmusser/data/out.root
[2021-02-10 14:00:03.310647 -0500][Dump   ][Utility           ] Protocol:  root
[2021-02-10 14:00:03.310647 -0500][Dump   ][Utility           ] User Name: 
[2021-02-10 14:00:03.310647 -0500][Dump   ][Utility           ] Password:  
[2021-02-10 14:00:03.310647 -0500][Dump   ][Utility           ] Host Name: 128.135.152.71
[2021-02-10 14:00:03.310647 -0500][Dump   ][Utility           ] Port:      1095
[2021-02-10 14:00:03.310647 -0500][Dump   ][Utility           ] Path:      /home/jmusser/data/out.root
[2021-02-10 14:00:03.310662 -0500][Dump   ][Utility           ] URL: root://128.135.152.71:1095//home/jmusser/data/out.root
[2021-02-10 14:00:03.310662 -0500][Dump   ][Utility           ] Protocol:  root
[2021-02-10 14:00:03.310662 -0500][Dump   ][Utility           ] User Name: 
[2021-02-10 14:00:03.310662 -0500][Dump   ][Utility           ] Password:  
[2021-02-10 14:00:03.310662 -0500][Dump   ][Utility           ] Host Name: 128.135.152.71
[2021-02-10 14:00:03.310662 -0500][Dump   ][Utility           ] Port:      1095
[2021-02-10 14:00:03.310662 -0500][Dump   ][Utility           ] Path:      /home/jmusser/data/out.root
[2021-02-10 14:00:03.310675 -0500][Dump   ][Utility           ] URL: root://128.135.152.71:1095//home/jmusser/data/out.root
[2021-02-10 14:00:03.310675 -0500][Dump   ][Utility           ] Protocol:  root
[2021-02-10 14:00:03.310675 -0500][Dump   ][Utility           ] User Name: 
[2021-02-10 14:00:03.310675 -0500][Dump   ][Utility           ] Password:  
[2021-02-10 14:00:03.310675 -0500][Dump   ][Utility           ] Host Name: 128.135.152.71
[2021-02-10 14:00:03.310675 -0500][Dump   ][Utility           ] Port:      1095
[2021-02-10 14:00:03.310675 -0500][Dump   ][Utility           ] Path:      /home/jmusser/data/out.root
[2021-02-10 14:00:03.495140 -0500][Dump   ][Utility           ] URL: root://128.135.152.71:1095//home/jmusser/data/out.root
[2021-02-10 14:00:03.495140 -0500][Dump   ][Utility           ] Protocol:  root
[2021-02-10 14:00:03.495140 -0500][Dump   ][Utility           ] User Name: 
[2021-02-10 14:00:03.495140 -0500][Dump   ][Utility           ] Password:  
[2021-02-10 14:00:03.495140 -0500][Dump   ][Utility           ] Host Name: 128.135.152.71
[2021-02-10 14:00:03.495140 -0500][Dump   ][Utility           ] Port:      1095
[2021-02-10 14:00:03.495140 -0500][Dump   ][Utility           ] Path:      /home/jmusser/data/out.root
[2021-02-10 14:00:03.495226 -0500][Debug  ][Poller            ] Available pollers: built-in
[2021-02-10 14:00:03.495230 -0500][Debug  ][Poller            ] Attempting to create a poller according to preference: built-in
[2021-02-10 14:00:03.495234 -0500][Debug  ][Poller            ] Creating poller: built-in
[2021-02-10 14:00:03.495245 -0500][Debug  ][Poller            ] Creating and starting the built-in poller...
[2021-02-10 14:00:03.495433 -0500][Debug  ][Poller            ] Using 1 poller threads
[2021-02-10 14:00:03.495444 -0500][Debug  ][TaskMgr           ] Starting the task manager...
[2021-02-10 14:00:03.495475 -0500][Debug  ][TaskMgr           ] Task manager started
[2021-02-10 14:00:03.495481 -0500][Debug  ][JobMgr            ] Starting the job manager...
[2021-02-10 14:00:03.495602 -0500][Debug  ][JobMgr            ] Job manager started, 3 workers
[2021-02-10 14:00:03.495621 -0500][Debug  ][TaskMgr           ] Registering task: "FileTimer task" to be run at: [2021-02-10 14:00:03 -0500]
[2021-02-10 14:00:03.495682 -0500][Debug  ][Utility           ] Env: overriding entry: MultiProtocol=0 with 1
[2021-02-10 14:00:03.495727 -0500][Dump   ][Utility           ] URL: root://128.135.152.71:1095//home/jmusser/data/out.root
[2021-02-10 14:00:03.495727 -0500][Dump   ][Utility           ] Protocol:  root
[2021-02-10 14:00:03.495727 -0500][Dump   ][Utility           ] User Name: 
[2021-02-10 14:00:03.495727 -0500][Dump   ][Utility           ] Password:  
[2021-02-10 14:00:03.495727 -0500][Dump   ][Utility           ] Host Name: 128.135.152.71
[2021-02-10 14:00:03.495727 -0500][Dump   ][Utility           ] Port:      1095
[2021-02-10 14:00:03.495727 -0500][Dump   ][Utility           ] Path:      /home/jmusser/data/out.root
[2021-02-10 14:00:03.495739 -0500][Dump   ][Utility           ] URL: root://128.135.152.71:1095//home/jmusser/data/out.root
[2021-02-10 14:00:03.495739 -0500][Dump   ][Utility           ] Protocol:  root
[2021-02-10 14:00:03.495739 -0500][Dump   ][Utility           ] User Name: 
[2021-02-10 14:00:03.495739 -0500][Dump   ][Utility           ] Password:  
[2021-02-10 14:00:03.495739 -0500][Dump   ][Utility           ] Host Name: 128.135.152.71
[2021-02-10 14:00:03.495739 -0500][Dump   ][Utility           ] Port:      1095
[2021-02-10 14:00:03.495739 -0500][Dump   ][Utility           ] Path:      /home/jmusser/data/out.root
[2021-02-10 14:00:03.495751 -0500][Dump   ][Utility           ] URL: root://128.135.152.71:1095//home/jmusser/data/out.root
[2021-02-10 14:00:03.495751 -0500][Dump   ][Utility           ] Protocol:  root
[2021-02-10 14:00:03.495751 -0500][Dump   ][Utility           ] User Name: 
[2021-02-10 14:00:03.495751 -0500][Dump   ][Utility           ] Password:  
[2021-02-10 14:00:03.495751 -0500][Dump   ][Utility           ] Host Name: 128.135.152.71
[2021-02-10 14:00:03.495751 -0500][Dump   ][Utility           ] Port:      1095
[2021-02-10 14:00:03.495751 -0500][Dump   ][Utility           ] Path:      /home/jmusser/data/out.root
[2021-02-10 14:00:03.495760 -0500][Debug  ][File              ] [0x41db4e0@root://128.135.152.71:1095//home/jmusser/data/out.root] Sending an open command
[2021-02-10 14:00:03.495793 -0500][Dump   ][XRootD            ] [128.135.152.71:1095] Sending message kXR_open (file: /home/jmusser/data/out.root, mode: 00, flags: kXR_open_read kXR_async kXR_retstat )
[2021-02-10 14:00:03.495821 -0500][Dump   ][Utility           ] URL: 128.135.152.71:1095
[2021-02-10 14:00:03.495821 -0500][Dump   ][Utility           ] Protocol:  root
[2021-02-10 14:00:03.495821 -0500][Dump   ][Utility           ] User Name: 
[2021-02-10 14:00:03.495821 -0500][Dump   ][Utility           ] Password:  
[2021-02-10 14:00:03.495821 -0500][Dump   ][Utility           ] Host Name: 128.135.152.71
[2021-02-10 14:00:03.495821 -0500][Dump   ][Utility           ] Port:      1095
[2021-02-10 14:00:03.495821 -0500][Dump   ][Utility           ] Path:      
[2021-02-10 14:00:03.495836 -0500][Debug  ][PostMaster        ] Creating new channel to: 128.135.152.71:1095 1 stream(s)
[2021-02-10 14:00:03.495853 -0500][Debug  ][PostMaster        ] [128.135.152.71:1095 #0] Stream parameters: Network Stack: IPAuto, Connection Window: 120, ConnectionRetry: 5, Stream Error Window: 1800
[2021-02-10 14:00:03.496130 -0500][Debug  ][TaskMgr           ] Registering task: "TickGeneratorTask for: 128.135.152.71:1095" to be run at: [2021-02-10 14:00:18 -0500]
[2021-02-10 14:00:03.496151 -0500][Debug  ][ExDbgMsg          ] [128.135.152.71:1095] MsgHandler created: 0x2580270 (message: kXR_open (file: /home/jmusser/data/out.root, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) ).
[2021-02-10 14:00:03.496163 -0500][Dump   ][PostMaster        ] [128.135.152.71:1095 #0] Sending message kXR_open (file: /home/jmusser/data/out.root, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) (0x41dcba0) through substream 0 expecting answer at 0
[2021-02-10 14:00:03.496197 -0500][Debug  ][PostMaster        ] [128.135.152.71:1095] Found 1 address(es): [::ffff:128.135.152.71]:1095
[2021-02-10 14:00:03.496247 -0500][Debug  ][AsyncSock         ] [128.135.152.71:1095 #0.0] Attempting connection to [::ffff:128.135.152.71]:1095
[2021-02-10 14:00:03.496368 -0500][Debug  ][Poller            ] Adding socket 0x41d4410 to the poller
[2021-02-10 14:00:03.496564 -0500][Dump   ][TaskMgr           ] Running task: "FileTimer task"
[2021-02-10 14:00:03.496580 -0500][Dump   ][TaskMgr           ] Will rerun task "FileTimer task" at [2021-02-10 14:00:18 -0500]
.
.   skipping lines 100-415 in log file
.
[2021-02-10 14:00:04.928023 -0500][Dump   ][XRootD            ] [128.135.152.71:1095] Got a kXR_ok response to request kXR_read (handle: 0x00000000, offset: 2996510, size: 235)
[2021-02-10 14:00:04.928031 -0500][Debug  ][ExDbgMsg          ] [128.135.152.71:1095] Calling MsgHandler: 0x44c6070 (message: kXR_read (handle: 0x00000000, offset: 2996510, size: 235) ) with status: [SUCCESS] .
[2021-02-10 14:00:04.928036 -0500][Dump   ][XRootD            ] [128.135.152.71:1095] Parsing the response to kXR_read (handle: 0x00000000, offset: 2996510, size: 235) as ChunkInfo
[2021-02-10 14:00:04.928043 -0500][Dump   ][File              ] [0x41db4e0@root://128.135.152.71:1095//home/jmusser/data/out.root] Got state response for message kXR_read (handle: 0x00000000, offset: 2996510, size: 235)
[2021-02-10 14:00:04.928057 -0500][Debug  ][ExDbgMsg          ] [128.135.152.71:1095] Destroying MsgHandler: 0x44c6070.
Reading tree at address 4999 of 5000->  ivec[0]=4999

Case 2 (failed remote read of file open and being written to.


root [0]   gSystem->Load("../GITrepo/helix-flight-software/build/lib/libDCTDisplayer.so");
root [1]   .x testxrootd_read.C
[2021-02-10 13:56:16.465613 -0500][Debug  ][Utility           ] Unable to process user config file: [ERROR] OS Error: No such file or directory
[2021-02-10 13:56:16.465754 -0500][Debug  ][PlugInMgr         ] Initializing plug-in manager...
[2021-02-10 13:56:16.465763 -0500][Debug  ][PlugInMgr         ] No default plug-in, loading plug-in configs...
[2021-02-10 13:56:16.465768 -0500][Debug  ][PlugInMgr         ] Processing plug-in definitions in /etc/xrootd/client.plugins.d...
[2021-02-10 13:56:16.465807 -0500][Debug  ][PlugInMgr         ] Processing plug-in definitions in /home/jmusser/.xrootd/client.plugins.d...
[2021-02-10 13:56:16.465814 -0500][Debug  ][PlugInMgr         ] Unable to process directory /home/jmusser/.xrootd/client.plugins.d: [ERROR] OS Error: No such file or directory
[2021-02-10 13:56:16.471404 -0500][Dump   ][Utility           ] URL: root://128.135.152.71:1095//home/jmusser/data/out.root
[2021-02-10 13:56:16.471404 -0500][Dump   ][Utility           ] Protocol:  root
[2021-02-10 13:56:16.471404 -0500][Dump   ][Utility           ] User Name: 
[2021-02-10 13:56:16.471404 -0500][Dump   ][Utility           ] Password:  
[2021-02-10 13:56:16.471404 -0500][Dump   ][Utility           ] Host Name: 128.135.152.71
[2021-02-10 13:56:16.471404 -0500][Dump   ][Utility           ] Port:      1095
[2021-02-10 13:56:16.471404 -0500][Dump   ][Utility           ] Path:      /home/jmusser/data/out.root
[2021-02-10 13:56:16.471434 -0500][Dump   ][Utility           ] URL: root://128.135.152.71:1095//home/jmusser/data/out.root
[2021-02-10 13:56:16.471434 -0500][Dump   ][Utility           ] Protocol:  root
[2021-02-10 13:56:16.471434 -0500][Dump   ][Utility           ] User Name: 
[2021-02-10 13:56:16.471434 -0500][Dump   ][Utility           ] Password:  
[2021-02-10 13:56:16.471434 -0500][Dump   ][Utility           ] Host Name: 128.135.152.71
[2021-02-10 13:56:16.471434 -0500][Dump   ][Utility           ] Port:      1095
[2021-02-10 13:56:16.471434 -0500][Dump   ][Utility           ] Path:      /home/jmusser/data/out.root
[2021-02-10 13:56:16.471454 -0500][Dump   ][Utility           ] URL: root://128.135.152.71:1095//home/jmusser/data/out.root
[2021-02-10 13:56:16.471454 -0500][Dump   ][Utility           ] Protocol:  root
[2021-02-10 13:56:16.471454 -0500][Dump   ][Utility           ] User Name: 
[2021-02-10 13:56:16.471454 -0500][Dump   ][Utility           ] Password:  
[2021-02-10 13:56:16.471454 -0500][Dump   ][Utility           ] Host Name: 128.135.152.71
[2021-02-10 13:56:16.471454 -0500][Dump   ][Utility           ] Port:      1095
[2021-02-10 13:56:16.471454 -0500][Dump   ][Utility           ] Path:      /home/jmusser/data/out.root
[2021-02-10 13:56:16.471470 -0500][Dump   ][Utility           ] URL: root://128.135.152.71:1095//home/jmusser/data/out.root
[2021-02-10 13:56:16.471470 -0500][Dump   ][Utility           ] Protocol:  root
[2021-02-10 13:56:16.471470 -0500][Dump   ][Utility           ] User Name: 
[2021-02-10 13:56:16.471470 -0500][Dump   ][Utility           ] Password:  
[2021-02-10 13:56:16.471470 -0500][Dump   ][Utility           ] Host Name: 128.135.152.71
[2021-02-10 13:56:16.471470 -0500][Dump   ][Utility           ] Port:      1095
[2021-02-10 13:56:16.471470 -0500][Dump   ][Utility           ] Path:      /home/jmusser/data/out.root
[2021-02-10 13:56:16.471483 -0500][Dump   ][Utility           ] URL: root://128.135.152.71:1095//home/jmusser/data/out.root
[2021-02-10 13:56:16.471483 -0500][Dump   ][Utility           ] Protocol:  root
[2021-02-10 13:56:16.471483 -0500][Dump   ][Utility           ] User Name: 
[2021-02-10 13:56:16.471483 -0500][Dump   ][Utility           ] Password:  
[2021-02-10 13:56:16.471483 -0500][Dump   ][Utility           ] Host Name: 128.135.152.71
[2021-02-10 13:56:16.471483 -0500][Dump   ][Utility           ] Port:      1095
[2021-02-10 13:56:16.471483 -0500][Dump   ][Utility           ] Path:      /home/jmusser/data/out.root
[2021-02-10 13:56:16.744854 -0500][Dump   ][Utility           ] URL: root://128.135.152.71:1095//home/jmusser/data/out.root
[2021-02-10 13:56:16.744854 -0500][Dump   ][Utility           ] Protocol:  root
[2021-02-10 13:56:16.744854 -0500][Dump   ][Utility           ] User Name: 
[2021-02-10 13:56:16.744854 -0500][Dump   ][Utility           ] Password:  
[2021-02-10 13:56:16.744854 -0500][Dump   ][Utility           ] Host Name: 128.135.152.71
[2021-02-10 13:56:16.744854 -0500][Dump   ][Utility           ] Port:      1095
[2021-02-10 13:56:16.744854 -0500][Dump   ][Utility           ] Path:      /home/jmusser/data/out.root
[2021-02-10 13:56:16.744957 -0500][Debug  ][Poller            ] Available pollers: built-in
[2021-02-10 13:56:16.744964 -0500][Debug  ][Poller            ] Attempting to create a poller according to preference: built-in
[2021-02-10 13:56:16.745003 -0500][Debug  ][Poller            ] Creating poller: built-in
[2021-02-10 13:56:16.745026 -0500][Debug  ][Poller            ] Creating and starting the built-in poller...
[2021-02-10 13:56:16.745277 -0500][Debug  ][Poller            ] Using 1 poller threads
[2021-02-10 13:56:16.745292 -0500][Debug  ][TaskMgr           ] Starting the task manager...
[2021-02-10 13:56:16.745352 -0500][Debug  ][TaskMgr           ] Task manager started
[2021-02-10 13:56:16.745360 -0500][Debug  ][JobMgr            ] Starting the job manager...
[2021-02-10 13:56:16.745454 -0500][Debug  ][JobMgr            ] Job manager started, 3 workers
[2021-02-10 13:56:16.745471 -0500][Debug  ][TaskMgr           ] Registering task: "FileTimer task" to be run at: [2021-02-10 13:56:16 -0500]
[2021-02-10 13:56:16.745553 -0500][Debug  ][Utility           ] Env: overriding entry: MultiProtocol=0 with 1
[2021-02-10 13:56:16.745620 -0500][Dump   ][Utility           ] URL: root://128.135.152.71:1095//home/jmusser/data/out.root
[2021-02-10 13:56:16.745620 -0500][Dump   ][Utility           ] Protocol:  root
[2021-02-10 13:56:16.745620 -0500][Dump   ][Utility           ] User Name: 
[2021-02-10 13:56:16.745620 -0500][Dump   ][Utility           ] Password:  
[2021-02-10 13:56:16.745620 -0500][Dump   ][Utility           ] Host Name: 128.135.152.71
[2021-02-10 13:56:16.745620 -0500][Dump   ][Utility           ] Port:      1095
[2021-02-10 13:56:16.745620 -0500][Dump   ][Utility           ] Path:      /home/jmusser/data/out.root
[2021-02-10 13:56:16.745640 -0500][Dump   ][Utility           ] URL: root://128.135.152.71:1095//home/jmusser/data/out.root
[2021-02-10 13:56:16.745640 -0500][Dump   ][Utility           ] Protocol:  root
[2021-02-10 13:56:16.745640 -0500][Dump   ][Utility           ] User Name: 
[2021-02-10 13:56:16.745640 -0500][Dump   ][Utility           ] Password:  
[2021-02-10 13:56:16.745640 -0500][Dump   ][Utility           ] Host Name: 128.135.152.71
[2021-02-10 13:56:16.745640 -0500][Dump   ][Utility           ] Port:      1095
[2021-02-10 13:56:16.745640 -0500][Dump   ][Utility           ] Path:      /home/jmusser/data/out.root
[2021-02-10 13:56:16.745659 -0500][Dump   ][Utility           ] URL: root://128.135.152.71:1095//home/jmusser/data/out.root
[2021-02-10 13:56:16.745659 -0500][Dump   ][Utility           ] Protocol:  root
[2021-02-10 13:56:16.745659 -0500][Dump   ][Utility           ] User Name: 
[2021-02-10 13:56:16.745659 -0500][Dump   ][Utility           ] Password:  
[2021-02-10 13:56:16.745659 -0500][Dump   ][Utility           ] Host Name: 128.135.152.71
[2021-02-10 13:56:16.745659 -0500][Dump   ][Utility           ] Port:      1095
[2021-02-10 13:56:16.745659 -0500][Dump   ][Utility           ] Path:      /home/jmusser/data/out.root
[2021-02-10 13:56:16.745673 -0500][Debug  ][File              ] [0x3436430@root://128.135.152.71:1095//home/jmusser/data/out.root] Sending an open command
[2021-02-10 13:56:16.745709 -0500][Dump   ][XRootD            ] [128.135.152.71:1095] Sending message kXR_open (file: /home/jmusser/data/out.root, mode: 00, flags: kXR_open_read kXR_async kXR_retstat )
[2021-02-10 13:56:16.745747 -0500][Dump   ][Utility           ] URL: 128.135.152.71:1095
[2021-02-10 13:56:16.745747 -0500][Dump   ][Utility           ] Protocol:  root
[2021-02-10 13:56:16.745747 -0500][Dump   ][Utility           ] User Name: 
[2021-02-10 13:56:16.745747 -0500][Dump   ][Utility           ] Password:  
[2021-02-10 13:56:16.745747 -0500][Dump   ][Utility           ] Host Name: 128.135.152.71
[2021-02-10 13:56:16.745747 -0500][Dump   ][Utility           ] Port:      1095
[2021-02-10 13:56:16.745747 -0500][Dump   ][Utility           ] Path:      
[2021-02-10 13:56:16.745766 -0500][Debug  ][PostMaster        ] Creating new channel to: 128.135.152.71:1095 1 stream(s)
[2021-02-10 13:56:16.745790 -0500][Debug  ][PostMaster        ] [128.135.152.71:1095 #0] Stream parameters: Network Stack: IPAuto, Connection Window: 120, ConnectionRetry: 5, Stream Error Window: 1800
[2021-02-10 13:56:16.746191 -0500][Debug  ][TaskMgr           ] Registering task: "TickGeneratorTask for: 128.135.152.71:1095" to be run at: [2021-02-10 13:56:31 -0500]
[2021-02-10 13:56:16.746221 -0500][Debug  ][ExDbgMsg          ] [128.135.152.71:1095] MsgHandler created: 0x2ee6b10 (message: kXR_open (file: /home/jmusser/data/out.root, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) ).
[2021-02-10 13:56:16.746240 -0500][Dump   ][PostMaster        ] [128.135.152.71:1095 #0] Sending message kXR_open (file: /home/jmusser/data/out.root, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) (0x4fdd2a0) through substream 0 expecting answer at 0
[2021-02-10 13:56:16.746284 -0500][Debug  ][PostMaster        ] [128.135.152.71:1095] Found 1 address(es): [::ffff:128.135.152.71]:1095
[2021-02-10 13:56:16.746360 -0500][Debug  ][AsyncSock         ] [128.135.152.71:1095 #0.0] Attempting connection to [::ffff:128.135.152.71]:1095
[2021-02-10 13:56:16.746613 -0500][Debug  ][Poller            ] Adding socket 0x4f9b1a0 to the poller
[2021-02-10 13:56:16.746889 -0500][Dump   ][TaskMgr           ] Running task: "FileTimer task"
[2021-02-10 13:56:16.746913 -0500][Dump   ][TaskMgr           ] Will rerun task "FileTimer task" at [2021-02-10 13:56:31 -0500]
[2021-02-10 13:56:16.859621 -0500][Debug  ][AsyncSock         ] [128.135.152.71:1095 #0.0] Async connection call returned
[2021-02-10 13:56:16.859786 -0500][Debug  ][XRootDTransport   ] [128.135.152.71:1095 #0.0] Sending out the initial hand shake + kXR_protocol
[2021-02-10 13:56:16.859947 -0500][Dump   ][AsyncSock         ] [128.135.152.71:1095 #0.0] Wrote a message:  (0x50001410), 44 bytes
[2021-02-10 13:56:17.216406 -0500][Dump   ][XRootDTransport   ] [msg: 0x50001410] Expecting 8 bytes of message body
[2021-02-10 13:56:17.216492 -0500][Dump   ][AsyncSock         ] [128.135.152.71:1095 #0.0] Received message header, size: 8
[2021-02-10 13:56:17.216512 -0500][Dump   ][AsyncSock         ] [128.135.152.71:1095 #0.0] Received a message of 16 bytes
[2021-02-10 13:56:17.216540 -0500][Debug  ][XRootDTransport   ] [128.135.152.71:1095 #0.0] Got the server hand shake response (type: server [], protocol version 500)
[2021-02-10 13:56:17.216564 -0500][Dump   ][XRootDTransport   ] [msg: 0x50001410] Expecting 8 bytes of message body
[2021-02-10 13:56:17.216572 -0500][Dump   ][AsyncSock         ] [128.135.152.71:1095 #0.0] Received message header, size: 8
[2021-02-10 13:56:17.216585 -0500][Dump   ][AsyncSock         ] [128.135.152.71:1095 #0.0] Received a message of 16 bytes
[2021-02-10 13:56:17.216605 -0500][Debug  ][XRootDTransport   ] [128.135.152.71:1095 #0.0] kXR_protocol successful (type: server [], protocol version 500)
[2021-02-10 13:56:17.217914 -0500][Debug  ][XRootDTransport   ] [128.135.152.71:1095 #0.0] Sending out kXR_login request, username: jmusser, cgi: ?xrd.cc=us&xrd.tz=-5&xrd.appname=root.exe&xrd.info=&xrd.hostname=localhost&xrd.rn=v4.10.0, dual-stack: true, private IPv4: true, private IPv6: true
[2021-02-10 13:56:17.218184 -0500][Dump   ][AsyncSock         ] [128.135.152.71:1095 #0.0] Wrote a message:  (0x50001970), 113 bytes
[2021-02-10 13:56:17.366283 -0500][Dump   ][XRootDTransport   ] [msg: 0x50001970] Expecting 16 bytes of message body
[2021-02-10 13:56:17.366396 -0500][Dump   ][AsyncSock         ] [128.135.152.71:1095 #0.0] Received message header, size: 8
[2021-02-10 13:56:17.366417 -0500][Dump   ][AsyncSock         ] [128.135.152.71:1095 #0.0] Received a message of 24 bytes
[2021-02-10 13:56:17.366473 -0500][Debug  ][XRootDTransport   ] [128.135.152.71:1095 #0.0] Logged in, session: 1c000000824c0000150000001c000000
[2021-02-10 13:56:17.366501 -0500][Debug  ][PostMaster        ] [128.135.152.71:1095 #0] Stream 0 connected.
[2021-02-10 13:56:17.366522 -0500][Debug  ][Utility           ] Monitor library name not set. No monitoring
[2021-02-10 13:56:17.366761 -0500][Dump   ][AsyncSock         ] [128.135.152.71:1095 #0.0] Wrote a message: kXR_open (file: /home/jmusser/data/out.root, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) (0x4fdd2a0), 51 bytes
[2021-02-10 13:56:17.366785 -0500][Dump   ][AsyncSock         ] [128.135.152.71:1095 #0.0] Successfully sent message: kXR_open (file: /home/jmusser/data/out.root, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) (0x4fdd2a0).
[2021-02-10 13:56:17.366816 -0500][Dump   ][XRootD            ] [128.135.152.71:1095] Message kXR_open (file: /home/jmusser/data/out.root, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) has been successfully sent.
[2021-02-10 13:56:17.366826 -0500][Debug  ][ExDbgMsg          ] [128.135.152.71:1095] Moving MsgHandler: 0x2ee6b10 (message: kXR_open (file: /home/jmusser/data/out.root, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) ) from out-queu to in-queue.
[2021-02-10 13:56:17.366872 -0500][Dump   ][PostMaster        ] [128.135.152.71:1095 #0.0] All messages consumed, disable uplink
[2021-02-10 13:56:17.613784 -0500][Dump   ][XRootDTransport   ] [msg: 0x50001970] Expecting 93 bytes of message body
[2021-02-10 13:56:17.613882 -0500][Dump   ][AsyncSock         ] [128.135.152.71:1095 #0.0] Received message header for 0x50001970 size: 8
[2021-02-10 13:56:17.613936 -0500][Dump   ][AsyncSock         ] [128.135.152.71:1095 #0.0] Received message 0x50001970 of 101 bytes
[2021-02-10 13:56:17.613965 -0500][Dump   ][PostMaster        ] [128.135.152.71:1095 #0] Handling received message: 0x50001970.
[2021-02-10 13:56:17.614104 -0500][Dump   ][XRootD            ] [128.135.152.71:1095] Got a kXR_ok response to request kXR_open (file: /home/jmusser/data/out.root, mode: 00, flags: kXR_open_read kXR_async kXR_retstat )
[2021-02-10 13:56:17.614143 -0500][Debug  ][ExDbgMsg          ] [128.135.152.71:1095] Calling MsgHandler: 0x2ee6b10 (message: kXR_open (file: /home/jmusser/data/out.root, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) ) with status: [SUCCESS] .
[2021-02-10 13:56:17.614160 -0500][Dump   ][XRootD            ] [128.135.152.71:1095] Parsing the response to kXR_open (file: /home/jmusser/data/out.root, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) as OpenInfo
[2021-02-10 13:56:17.614170 -0500][Dump   ][XRootD            ] [128.135.152.71:1095] Parsing StatInfo in response to kXR_open (file: /home/jmusser/data/out.root, mode: 00, flags: kXR_open_read kXR_async kXR_retstat )
[2021-02-10 13:56:17.614257 -0500][Debug  ][File              ] [0x3436430@root://128.135.152.71:1095//home/jmusser/data/out.root] Open has returned with status [SUCCESS] 
[2021-02-10 13:56:17.614270 -0500][Debug  ][File              ] [0x3436430@root://128.135.152.71:1095//home/jmusser/data/out.root] successfully opened at 128.135.152.71:1095, handle: 0x0, session id: 1
[2021-02-10 13:56:17.614319 -0500][Debug  ][ExDbgMsg          ] [128.135.152.71:1095] Destroying MsgHandler: 0x2ee6b10.
[2021-02-10 13:56:17.614580 -0500][Debug  ][File              ] [0x3436430@root://128.135.152.71:1095//home/jmusser/data/out.root] Sending a read command for handle 0x0 to 128.135.152.71:1095
[2021-02-10 13:56:17.614948 -0500][Dump   ][XRootD            ] [128.135.152.71:1095] Sending message kXR_read (handle: 0x00000000, offset: 0, size: 300)
[2021-02-10 13:56:17.614987 -0500][Debug  ][ExDbgMsg          ] [128.135.152.71:1095] MsgHandler created: 0x3d48bb0 (message: kXR_read (handle: 0x00000000, offset: 0, size: 300) ).
[2021-02-10 13:56:17.615028 -0500][Dump   ][PostMaster        ] [128.135.152.71:1095 #0] Sending message kXR_read (handle: 0x00000000, offset: 0, size: 300) (0x4fa2980) through substream 0 expecting answer at 0
[2021-02-10 13:56:17.615510 -0500][Dump   ][AsyncSock         ] [128.135.152.71:1095 #0.0] Wrote a message: kXR_read (handle: 0x00000000, offset: 0, size: 300) (0x4fa2980), 32 bytes
[2021-02-10 13:56:17.615552 -0500][Dump   ][AsyncSock         ] [128.135.152.71:1095 #0.0] Successfully sent message: kXR_read (handle: 0x00000000, offset: 0, size: 300) (0x4fa2980).
[2021-02-10 13:56:17.615564 -0500][Dump   ][XRootD            ] [128.135.152.71:1095] Message kXR_read (handle: 0x00000000, offset: 0, size: 300) has been successfully sent.
[2021-02-10 13:56:17.615575 -0500][Debug  ][ExDbgMsg          ] [128.135.152.71:1095] Moving MsgHandler: 0x3d48bb0 (message: kXR_read (handle: 0x00000000, offset: 0, size: 300) ) from out-queu to in-queue.
[2021-02-10 13:56:17.615626 -0500][Dump   ][PostMaster        ] [128.135.152.71:1095 #0.0] All messages consumed, disable uplink
[2021-02-10 13:56:17.861770 -0500][Dump   ][XRootDTransport   ] [msg: 0x50001410] Expecting 300 bytes of message body
[2021-02-10 13:56:17.861852 -0500][Dump   ][AsyncSock         ] [128.135.152.71:1095 #0.0] Received message header for 0x50001410 size: 8
[2021-02-10 13:56:17.861872 -0500][Dump   ][AsyncSock         ] [128.135.152.71:1095 #0.0] Will use the raw handler to read body of message 0x50001410
[2021-02-10 13:56:17.861928 -0500][Dump   ][AsyncSock         ] [128.135.152.71:1095 #0.0] Received message 0x50001410 of 308 bytes
[2021-02-10 13:56:17.861941 -0500][Dump   ][PostMaster        ] [128.135.152.71:1095 #0] Handling received message: 0x50001410.
[2021-02-10 13:56:17.862116 -0500][Dump   ][XRootD            ] [128.135.152.71:1095] Got a kXR_ok response to request kXR_read (handle: 0x00000000, offset: 0, size: 300)
[2021-02-10 13:56:17.862148 -0500][Debug  ][ExDbgMsg          ] [128.135.152.71:1095] Calling MsgHandler: 0x3d48bb0 (message: kXR_read (handle: 0x00000000, offset: 0, size: 300) ) with status: [SUCCESS] .
[2021-02-10 13:56:17.862161 -0500][Dump   ][XRootD            ] [128.135.152.71:1095] Parsing the response to kXR_read (handle: 0x00000000, offset: 0, size: 300) as ChunkInfo
[2021-02-10 13:56:17.862183 -0500][Dump   ][File              ] [0x3436430@root://128.135.152.71:1095//home/jmusser/data/out.root] Got state response for message kXR_read (handle: 0x00000000, offset: 0, size: 300)
[2021-02-10 13:56:17.862226 -0500][Debug  ][ExDbgMsg          ] [128.135.152.71:1095] Destroying MsgHandler: 0x3d48bb0.
Error in <TNetXNGFile::Init>: file root://128.135.152.71:1095//home/jmusser/data/out.root is truncated at 875910 bytes: should be 884181, trying to recover

simonm · February 10, 2021, 8:43pm

Well, this proves my theory wrong, but at least I understood better your use case

So basically writer is constantly updating the file, and the reader, well, is reading it …

It seems to me that the error condition you are falling into:

github.com

root-project/root/blob/master/io/io/src/TFile.cxx#L787-L791


//something had been written to the file. Trailer is missing, must recover
if (fEND > size) {
   if (tryrecover) {
      Error("Init","file %s is truncated at %lld bytes: should be %lld, "
            "trying to recover", GetName(), size, fEND);

is there to detect exactly this, at least that’s what the comment states:
something had been written to the file. Trailer is missing, must recover

Now the questions is: is TFile the right thing for your use case? I think this has to be answered by someone from the ROOT team
Maybe Gerri will know as the commit message mentions him:

pcanal · February 10, 2021, 10:42pm

Reading from a TFile is that is being written to is supported to some extent.

////////////////////////////////////////////////////////////////////////////////
/// Read the linked list of keys.
///
/// Every directory has a linked list (fKeys). This linked list has been
/// written on the file via WriteKeys as a single data record.
///
/// It is interesting to call this function in the following situation.
/// Assume another process1 is connecting this directory in Update mode
///   - Process1 is adding/updating objects in this directory
///   - You want to see the latest status from process1.
/// Example Process1:
/// ~~~{.cpp}
/// obj1.Write();
/// obj2.Write();
/// gDirectory->SaveSelf();
/// ~~~
///
/// Example Process2:
/// ~~~{.cpp}
/// gDirectory->ReadKeys();
/// obj1->Draw();
/// ~~~
/// This is an efficient way (without opening/closing files) to view
/// the latest updates of a file being modified by another process
/// as it is typically the case in a data acquisition system.

Now it is likely that this has not been stressed test where the writing frequency is high compared to the reading speed.

jmusser · February 12, 2021, 6:13pm

Thanks! I throttled the writer process write frequency way down, and reset the ttree in the writer process before each write so the tree always contains only the entry of interest (the last), and was able to achieve some level of read reliability. It seems very fragile though - this is not production-ready by any means.

Axel · February 12, 2021, 8:15pm

Writing isn’t atomic - writing is what the storage layer offers. So indeed you might run into concurrent access / incomplete updates. I’d recommend you use a locking mechanism of some sort, such as touching a lock file during write / read, and removing it after writing / reading, and only writing / reading if the lock file does not exist. This isn’t as straight forward as it might sound; you also need to protect against multiple clients creating the lock file concurrently. But the Internet should have an introduction to this.

jmusser · February 12, 2021, 11:10pm

Got it, thanks

system · February 26, 2021, 11:11pm

This topic was automatically closed 14 days after the last reply. New replies are no longer allowed.