Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

v5.4.3's libXrdCl.3.0.0 hangs on macOS 12.5.1 #1779

Closed
Axel-Naumann opened this issue Sep 6, 2022 · 14 comments
Closed

v5.4.3's libXrdCl.3.0.0 hangs on macOS 12.5.1 #1779

Axel-Naumann opened this issue Sep 6, 2022 · 14 comments

Comments

@Axel-Naumann
Copy link

Axel-Naumann commented Sep 6, 2022

Hi,

With ROOT's build of its builtin xrootd-5.4.3 client on macOS 12.5.1 (and only there), just opening the file with

TFile::Open("root://eospublic.cern.ch//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root")

always hangs for several minutes with

* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
  * frame #0: 0x00007ff80250e3ea libsystem_kernel.dylib`__psynch_cvwait + 10
    frame #1: 0x00007ff802548a6f libsystem_pthread.dylib`_pthread_cond_wait + 1249
    frame #2: 0x000000011ecb0dbb libXrdUtils.3.0.0.dylib`XrdSysCondVar::Wait(this=0x00007ff7bfefc0c0) at XrdSysPthread.cc:106:11 [opt]
    frame #3: 0x000000011d5339e0 libXrdCl.3.0.0.dylib`XrdCl::MessageUtils::WaitForStatus(XrdCl::SyncResponseHandler*) [inlined] XrdCl::SyncResponseHandler::WaitForResponse(this=0x00007ff7bfefc0a8) at XrdClMessageUtils.hh:97:20 [opt]
    frame #4: 0x000000011d5339b1 libXrdCl.3.0.0.dylib`XrdCl::MessageUtils::WaitForStatus(handler=0x00007ff7bfefc0a8) at XrdClMessageUtils.hh:157:18 [opt]
    frame #5: 0x000000011d56b797 libXrdCl.3.0.0.dylib`XrdCl::File::Open(this=<unavailable>, url=<unavailable>, flags=<unavailable>, mode=<unavailable>, timeout=0) at XrdClFile.cc:127:12 [opt]
    frame #6: 0x0000000111f3555f libNetxNG.so`TNetXNGFile::TNetXNGFile(this=0x0000000111e3b7a0, url=<unavailable>, lurl=0x0000000000000000, mode="", title=<unavailable>, compress=<unavailable>, (null)=<unavailable>, parallelopen=<unavailable>) at TNetXNGFile.cxx:198:20 [opt]
    frame #7: 0x0000000111f35840 libNetxNG.so`TNetXNGFile::TNetXNGFile(char const*, char const*, char const*, int, int, bool) [inlined] TNetXNGFile::TNetXNGFile(this=<unavailable>, url=<unavailable>, lurl=0x0000000000000000, mode=<unavailable>, title=<unavailable>, compress=<unavailable>) at TNetXNGFile.cxx:142:1 [opt]
    frame #8: 0x0000000111f35831 libNetxNG.so`TNetXNGFile::TNetXNGFile(this=<unavailable>, url=<unavailable>, mode=<unavailable>, title=<unavailable>, compress=<unavailable>, netopt=<unavailable>, parallelopen=<unavailable>) at TNetXNGFile.cxx:132:2 [opt]

Is this a known issue? Are we doing something wrong?

FYI @eguiraud who diagnosed this.

@simonmichal
Copy link
Contributor

@Axel-Naumann : thanks for reporting this issue! Could you please provide client side logs (just export XRD_LOGLEVEL=Dump)?

@eguiraud
Copy link

eguiraud commented Sep 6, 2022

Hi @simonmichal , thank you for the quick reaction, here's the full log:

macphsft18:eguiraud sftnight$ cat repro.C
#include <TFile.h>

void repro() {
	TFile::Open("root://eospublic.cern.ch//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root");
}

#ifndef __CLING__
int main() {
	repro();
}
#endif
macphsft18:eguiraud sftnight$ XRD_LOGLEVEL=Dump ./repro
[2022-09-06 20:06:06.108184 +0200][Debug  ][Utility           ] Initializing xrootd client version: v5.4.3
[2022-09-06 20:06:06.108264 +0200][Warning][Utility           ] Unable to process global config file: [ERROR] OS Error: no such file or directory
[2022-09-06 20:06:06.108289 +0200][Debug  ][Utility           ] Unable to process user config file: [ERROR] OS Error: no such file or directory
[2022-09-06 20:06:06.108373 +0200][Debug  ][PlugInMgr         ] Initializing plug-in manager...
[2022-09-06 20:06:06.108387 +0200][Debug  ][PlugInMgr         ] No default plug-in, loading plug-in configs...
[2022-09-06 20:06:06.108395 +0200][Debug  ][PlugInMgr         ] Processing plug-in definitions in /etc/xrootd/client.plugins.d...
[2022-09-06 20:06:06.108411 +0200][Debug  ][PlugInMgr         ] Unable to process directory /etc/xrootd/client.plugins.d: [ERROR] OS Error: no such file or directory
[2022-09-06 20:06:06.108421 +0200][Debug  ][PlugInMgr         ] Processing plug-in definitions in /Users/sftnight/.xrootd/client.plugins.d...
[2022-09-06 20:06:06.108433 +0200][Debug  ][PlugInMgr         ] Unable to process directory /Users/sftnight/.xrootd/client.plugins.d: [ERROR] OS Error: no such file or directory
[2022-09-06 20:06:06.108441 +0200][Debug  ][Utility           ] Attempting to pre-load: libXrdSeckrb5.so
[2022-09-06 20:06:06.109104 +0200][Debug  ][Utility           ] Attempting to pre-load: libXrdSecgsi.so
[2022-09-06 20:06:06.110045 +0200][Debug  ][Utility           ] Attempting to pre-load: libXrdSecgsiAuthzVO.so
[2022-09-06 20:06:06.111345 +0200][Debug  ][Utility           ] Attempting to pre-load: libXrdSecgsiGMAPDN.so
[2022-09-06 20:06:06.111699 +0200][Debug  ][Utility           ] Attempting to pre-load: libXrdSecpwd.so
[2022-09-06 20:06:06.112304 +0200][Debug  ][Utility           ] Attempting to pre-load: libXrdSecsss.so
[2022-09-06 20:06:06.112806 +0200][Debug  ][Utility           ] Attempting to pre-load: libXrdSecunix.so
[2022-09-06 20:06:06.149345 +0200][Dump   ][Utility           ] URL: root://eospublic.cern.ch//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root
[2022-09-06 20:06:06.149345 +0200][Dump   ][Utility           ] Protocol:  root
[2022-09-06 20:06:06.149345 +0200][Dump   ][Utility           ] User Name:
[2022-09-06 20:06:06.149345 +0200][Dump   ][Utility           ] Password:
[2022-09-06 20:06:06.149345 +0200][Dump   ][Utility           ] Host Name: eospublic.cern.ch
[2022-09-06 20:06:06.149345 +0200][Dump   ][Utility           ] Port:      1094
[2022-09-06 20:06:06.149345 +0200][Dump   ][Utility           ] Path:      /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root
[2022-09-06 20:06:06.149376 +0200][Dump   ][Utility           ] URL: root://eospublic.cern.ch:1094//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root
[2022-09-06 20:06:06.149376 +0200][Dump   ][Utility           ] Protocol:  root
[2022-09-06 20:06:06.149376 +0200][Dump   ][Utility           ] User Name:
[2022-09-06 20:06:06.149376 +0200][Dump   ][Utility           ] Password:
[2022-09-06 20:06:06.149376 +0200][Dump   ][Utility           ] Host Name: eospublic.cern.ch
[2022-09-06 20:06:06.149376 +0200][Dump   ][Utility           ] Port:      1094
[2022-09-06 20:06:06.149376 +0200][Dump   ][Utility           ] Path:      /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root
[2022-09-06 20:06:06.149463 +0200][Dump   ][Utility           ] URL: root://eospublic.cern.ch:1094//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root
[2022-09-06 20:06:06.149463 +0200][Dump   ][Utility           ] Protocol:  root
[2022-09-06 20:06:06.149463 +0200][Dump   ][Utility           ] User Name:
[2022-09-06 20:06:06.149463 +0200][Dump   ][Utility           ] Password:
[2022-09-06 20:06:06.149463 +0200][Dump   ][Utility           ] Host Name: eospublic.cern.ch
[2022-09-06 20:06:06.149463 +0200][Dump   ][Utility           ] Port:      1094
[2022-09-06 20:06:06.149463 +0200][Dump   ][Utility           ] Path:      /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root
[2022-09-06 20:06:06.149486 +0200][Dump   ][Utility           ] URL: root://eospublic.cern.ch:1094//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root
[2022-09-06 20:06:06.149486 +0200][Dump   ][Utility           ] Protocol:  root
[2022-09-06 20:06:06.149486 +0200][Dump   ][Utility           ] User Name:
[2022-09-06 20:06:06.149486 +0200][Dump   ][Utility           ] Password:
[2022-09-06 20:06:06.149486 +0200][Dump   ][Utility           ] Host Name: eospublic.cern.ch
[2022-09-06 20:06:06.149486 +0200][Dump   ][Utility           ] Port:      1094
[2022-09-06 20:06:06.149486 +0200][Dump   ][Utility           ] Path:      /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root
[2022-09-06 20:06:06.149498 +0200][Dump   ][Utility           ] URL: root://eospublic.cern.ch:1094//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root
[2022-09-06 20:06:06.149498 +0200][Dump   ][Utility           ] Protocol:  root
[2022-09-06 20:06:06.149498 +0200][Dump   ][Utility           ] User Name:
[2022-09-06 20:06:06.149498 +0200][Dump   ][Utility           ] Password:
[2022-09-06 20:06:06.149498 +0200][Dump   ][Utility           ] Host Name: eospublic.cern.ch
[2022-09-06 20:06:06.149498 +0200][Dump   ][Utility           ] Port:      1094
[2022-09-06 20:06:06.149498 +0200][Dump   ][Utility           ] Path:      /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root
[2022-09-06 20:06:06.225434 +0200][Dump   ][Utility           ] URL: root://eospublic.cern.ch//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root
[2022-09-06 20:06:06.225434 +0200][Dump   ][Utility           ] Protocol:  root
[2022-09-06 20:06:06.225434 +0200][Dump   ][Utility           ] User Name:
[2022-09-06 20:06:06.225434 +0200][Dump   ][Utility           ] Password:
[2022-09-06 20:06:06.225434 +0200][Dump   ][Utility           ] Host Name: eospublic.cern.ch
[2022-09-06 20:06:06.225434 +0200][Dump   ][Utility           ] Port:      1094
[2022-09-06 20:06:06.225434 +0200][Dump   ][Utility           ] Path:      /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root
[2022-09-06 20:06:06.225485 +0200][Debug  ][Utility           ] Env: trying to get a non-existent string entry: pollerpreference
[2022-09-06 20:06:06.225490 +0200][Debug  ][Poller            ] Available pollers: built-in
[2022-09-06 20:06:06.225494 +0200][Debug  ][Poller            ] Attempting to create a poller according to preference: built-in
[2022-09-06 20:06:06.225507 +0200][Debug  ][Poller            ] Creating poller: built-in
[2022-09-06 20:06:06.225513 +0200][Debug  ][Poller            ] Creating and starting the built-in poller...
[2022-09-06 20:06:06.225612 +0200][Debug  ][Poller            ] Using 1 poller threads
[2022-09-06 20:06:06.225638 +0200][Debug  ][TaskMgr           ] Starting the task manager...
[2022-09-06 20:06:06.225656 +0200][Debug  ][TaskMgr           ] Task manager started
[2022-09-06 20:06:06.225663 +0200][Debug  ][JobMgr            ] Starting the job manager...
[2022-09-06 20:06:06.225730 +0200][Debug  ][JobMgr            ] Job manager started, 3 workers
[2022-09-06 20:06:06.225739 +0200][Debug  ][TaskMgr           ] Registering task: "FileTimer task" to be run at: [2022-09-06 20:06:06 +0200]
[2022-09-06 20:06:06.225784 +0200][Debug  ][Utility           ] Env: overriding entry: multiprotocol=0 with 1
[2022-09-06 20:06:06.225838 +0200][Dump   ][Utility           ] URL: root://eospublic.cern.ch:1094//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root
[2022-09-06 20:06:06.225838 +0200][Dump   ][Utility           ] Protocol:  root
[2022-09-06 20:06:06.225838 +0200][Dump   ][Utility           ] User Name:
[2022-09-06 20:06:06.225838 +0200][Dump   ][Utility           ] Password:
[2022-09-06 20:06:06.225838 +0200][Dump   ][Utility           ] Host Name: eospublic.cern.ch
[2022-09-06 20:06:06.225838 +0200][Dump   ][Utility           ] Port:      1094
[2022-09-06 20:06:06.225838 +0200][Dump   ][Utility           ] Path:      /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root
[2022-09-06 20:06:06.225866 +0200][Dump   ][Utility           ] URL: root://eospublic.cern.ch:1094//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root
[2022-09-06 20:06:06.225866 +0200][Dump   ][Utility           ] Protocol:  root
[2022-09-06 20:06:06.225866 +0200][Dump   ][Utility           ] User Name:
[2022-09-06 20:06:06.225866 +0200][Dump   ][Utility           ] Password:
[2022-09-06 20:06:06.225866 +0200][Dump   ][Utility           ] Host Name: eospublic.cern.ch
[2022-09-06 20:06:06.225866 +0200][Dump   ][Utility           ] Port:      1094
[2022-09-06 20:06:06.225866 +0200][Dump   ][Utility           ] Path:      /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root
[2022-09-06 20:06:06.225891 +0200][Dump   ][Utility           ] URL: root://eospublic.cern.ch:1094//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root
[2022-09-06 20:06:06.225891 +0200][Dump   ][Utility           ] Protocol:  root
[2022-09-06 20:06:06.225891 +0200][Dump   ][Utility           ] User Name:
[2022-09-06 20:06:06.225891 +0200][Dump   ][Utility           ] Password:
[2022-09-06 20:06:06.225891 +0200][Dump   ][Utility           ] Host Name: eospublic.cern.ch
[2022-09-06 20:06:06.225891 +0200][Dump   ][Utility           ] Port:      1094
[2022-09-06 20:06:06.225891 +0200][Dump   ][Utility           ] Path:      /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root
[2022-09-06 20:06:06.225923 +0200][Debug  ][File              ] [0xd27699b0@root://eospublic.cern.ch:1094//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root?xrdcl.requuid=B3AEE882-3B58-4DB5-BF16-C07F64AE50AC] Sending an open command
[2022-09-06 20:06:06.225956 +0200][Dump   ][XRootD            ] [eospublic.cern.ch:1094] Sending message kXR_open (file: /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root, mode: 00, flags: kXR_open_read kXR_async kXR_retstat )
[2022-09-06 20:06:06.225992 +0200][Debug  ][ExDbgMsg          ] [eospublic.cern.ch:1094] MsgHandler created: 0xd3121b60 (message: kXR_open (file: /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) ).
[2022-09-06 20:06:06.226023 +0200][Dump   ][Utility           ] URL: eospublic.cern.ch:1094
[2022-09-06 20:06:06.226023 +0200][Dump   ][Utility           ] Protocol:  root
[2022-09-06 20:06:06.226023 +0200][Dump   ][Utility           ] User Name:
[2022-09-06 20:06:06.226023 +0200][Dump   ][Utility           ] Password:
[2022-09-06 20:06:06.226023 +0200][Dump   ][Utility           ] Host Name: eospublic.cern.ch
[2022-09-06 20:06:06.226023 +0200][Dump   ][Utility           ] Port:      1094
[2022-09-06 20:06:06.226023 +0200][Dump   ][Utility           ] Path:
[2022-09-06 20:06:06.226070 +0200][Dump   ][Utility           ] URL: root://eospublic.cern.ch:1094
[2022-09-06 20:06:06.226070 +0200][Dump   ][Utility           ] Protocol:  root
[2022-09-06 20:06:06.226070 +0200][Dump   ][Utility           ] User Name:
[2022-09-06 20:06:06.226070 +0200][Dump   ][Utility           ] Password:
[2022-09-06 20:06:06.226070 +0200][Dump   ][Utility           ] Host Name: eospublic.cern.ch
[2022-09-06 20:06:06.226070 +0200][Dump   ][Utility           ] Port:      1094
[2022-09-06 20:06:06.226070 +0200][Dump   ][Utility           ] Path:
[2022-09-06 20:06:06.226120 +0200][Debug  ][PostMaster        ] Creating new channel to: root://eospublic.cern.ch:1094
[2022-09-06 20:06:06.226133 +0200][Debug  ][PostMaster        ] [eospublic.cern.ch:1094] Stream parameters: Network Stack: IPAuto, Connection Window: 120, ConnectionRetry: 5, Stream Error Window: 1800
[2022-09-06 20:06:06.226142 +0200][Debug  ][TaskMgr           ] Registering task: "TickGeneratorTask for: root://eospublic.cern.ch:1094" to be run at: [2022-09-06 20:06:21 +0200]
[2022-09-06 20:06:06.226170 +0200][Dump   ][PostMaster        ] [eospublic.cern.ch:1094] Sending message kXR_open (file: /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) (0x1e9b2f0) through substream 0 expecting answer at 0
[2022-09-06 20:06:06.228172 +0200][Debug  ][PostMaster        ] [eospublic.cern.ch:1094] Found 2 address(es): [::ffff:128.142.160.145]:1094, [2001:1458:301:17::100:e]:1094
[2022-09-06 20:06:06.228241 +0200][Debug  ][AsyncSock         ] [eospublic.cern.ch:1094.0] Attempting connection to [2001:1458:301:17::100:e]:1094
[2022-09-06 20:06:06.228305 +0200][Debug  ][Poller            ] Adding socket 0x139b280 to the poller
[2022-09-06 20:06:07.227813 +0200][Dump   ][TaskMgr           ] Running task: "FileTimer task"
[2022-09-06 20:06:07.227908 +0200][Dump   ][TaskMgr           ] Will rerun task "FileTimer task" at [2022-09-06 20:06:22 +0200]
[2022-09-06 20:06:21.349763 +0200][Dump   ][TaskMgr           ] Running task: "TickGeneratorTask for: root://eospublic.cern.ch:1094"
[2022-09-06 20:06:21.349842 +0200][Dump   ][TaskMgr           ] Will rerun task "TickGeneratorTask for: root://eospublic.cern.ch:1094" at [2022-09-06 20:06:36 +0200]
[2022-09-06 20:06:22.359918 +0200][Dump   ][TaskMgr           ] Running task: "FileTimer task"
[2022-09-06 20:06:22.359992 +0200][Dump   ][TaskMgr           ] Will rerun task "FileTimer task" at [2022-09-06 20:06:37 +0200]
[2022-09-06 20:06:36.426025 +0200][Dump   ][TaskMgr           ] Running task: "TickGeneratorTask for: root://eospublic.cern.ch:1094"
[2022-09-06 20:06:36.426105 +0200][Dump   ][TaskMgr           ] Will rerun task "TickGeneratorTask for: root://eospublic.cern.ch:1094" at [2022-09-06 20:06:51 +0200]
[2022-09-06 20:06:37.428018 +0200][Dump   ][TaskMgr           ] Running task: "FileTimer task"
[2022-09-06 20:06:37.428093 +0200][Dump   ][TaskMgr           ] Will rerun task "FileTimer task" at [2022-09-06 20:06:52 +0200]
[2022-09-06 20:06:51.455902 +0200][Dump   ][TaskMgr           ] Running task: "TickGeneratorTask for: root://eospublic.cern.ch:1094"
[2022-09-06 20:06:51.455990 +0200][Dump   ][TaskMgr           ] Will rerun task "TickGeneratorTask for: root://eospublic.cern.ch:1094" at [2022-09-06 20:07:06 +0200]
[2022-09-06 20:06:52.457914 +0200][Dump   ][TaskMgr           ] Running task: "FileTimer task"
[2022-09-06 20:06:52.457996 +0200][Dump   ][TaskMgr           ] Will rerun task "FileTimer task" at [2022-09-06 20:07:07 +0200]
[2022-09-06 20:07:06.577975 +0200][Dump   ][TaskMgr           ] Running task: "TickGeneratorTask for: root://eospublic.cern.ch:1094"
[2022-09-06 20:07:06.578053 +0200][Dump   ][TaskMgr           ] Will rerun task "TickGeneratorTask for: root://eospublic.cern.ch:1094" at [2022-09-06 20:07:21 +0200]
[2022-09-06 20:07:07.588127 +0200][Dump   ][TaskMgr           ] Running task: "FileTimer task"
[2022-09-06 20:07:07.588201 +0200][Dump   ][TaskMgr           ] Will rerun task "FileTimer task" at [2022-09-06 20:07:22 +0200]
[2022-09-06 20:07:21.227223 +0200][Debug  ][AsyncSock         ] [eospublic.cern.ch:1094.0] Async connection call returned
[2022-09-06 20:07:21.227311 +0200][Error  ][AsyncSock         ] [eospublic.cern.ch:1094.0] Unable to connect: operation timed out
[2022-09-06 20:07:21.227323 +0200][Debug  ][AsyncSock         ] [eospublic.cern.ch:1094.0] Closing the socket
[2022-09-06 20:07:21.227337 +0200][Debug  ][Poller            ] <x><--><x> Removing socket from the poller
[2022-09-06 20:07:21.227367 +0200][Error  ][PostMaster        ] [eospublic.cern.ch:1094] elapsed = 75, pConnectionWindow = 120 seconds.
[2022-09-06 20:07:21.227431 +0200][Debug  ][AsyncSock         ] [eospublic.cern.ch:1094.0] Attempting connection to [::ffff:128.142.160.145]:1094
[2022-09-06 20:07:21.227524 +0200][Debug  ][Poller            ] Adding socket 0x139b280 to the poller
[2022-09-06 20:07:21.227916 +0200][Debug  ][AsyncSock         ] [eospublic.cern.ch:1094.0] Async connection call returned
[2022-09-06 20:07:21.227958 +0200][Debug  ][XRootDTransport   ] [eospublic.cern.ch:1094.0] Sending out the initial hand shake + kXR_protocol
[2022-09-06 20:07:21.228020 +0200][Dump   ][AsyncSock         ] [eospublic.cern.ch:1094.0] Wrote a message:  (0x1e9b3e0), 44 bytes
[2022-09-06 20:07:21.231704 +0200][Dump   ][XRootDTransport   ] [msg: 0x1e0d4f0] Expecting 8 bytes of message body
[2022-09-06 20:07:21.231743 +0200][Dump   ][AsyncSock         ] [eospublic.cern.ch:1094.0] Received message header, size: 8
[2022-09-06 20:07:21.231755 +0200][Dump   ][AsyncSock         ] [eospublic.cern.ch:1094.0] Received a message of 16 bytes
[2022-09-06 20:07:21.231765 +0200][Debug  ][XRootDTransport   ] [eospublic.cern.ch:1094.0] Got the server hand shake response (type: manager [], protocol version 400)
[2022-09-06 20:07:21.231796 +0200][Dump   ][XRootDTransport   ] [msg: 0x1e0d4f0] Expecting 8 bytes of message body
[2022-09-06 20:07:21.231806 +0200][Dump   ][AsyncSock         ] [eospublic.cern.ch:1094.0] Received message header, size: 8
[2022-09-06 20:07:21.231819 +0200][Dump   ][AsyncSock         ] [eospublic.cern.ch:1094.0] Received a message of 16 bytes
[2022-09-06 20:07:21.231829 +0200][Debug  ][XRootDTransport   ] [eospublic.cern.ch:1094.0] kXR_protocol successful (type: manager [], protocol version 400)
[2022-09-06 20:07:21.233230 +0200][Debug  ][XRootDTransport   ] [eospublic.cern.ch:1094.0] Sending out kXR_login request, username: sftnight, cgi: xrd.cc=ch&xrd.tz=1&xrd.appname=repro&xrd.info=&xrd.hostname=macphsft18.dyndns.cern.ch&xrd.rn=v5.4.3, dual-stack: true, private IPv4: false, private IPv6: false
[2022-09-06 20:07:21.233299 +0200][Dump   ][AsyncSock         ] [eospublic.cern.ch:1094.0] Wrote a message:  (0x1e0c2d0), 123 bytes
[2022-09-06 20:07:21.233756 +0200][Dump   ][XRootDTransport   ] [msg: 0x1ef4f50] Expecting 135 bytes of message body
[2022-09-06 20:07:21.233780 +0200][Dump   ][AsyncSock         ] [eospublic.cern.ch:1094.0] Received message header, size: 8
[2022-09-06 20:07:21.233794 +0200][Dump   ][AsyncSock         ] [eospublic.cern.ch:1094.0] Received a message of 143 bytes
[2022-09-06 20:07:21.233806 +0200][Debug  ][XRootDTransport   ] [eospublic.cern.ch:1094.0] Logged in, session: 7e5ee30042230300021300002fbbe800
[2022-09-06 20:07:21.233820 +0200][Debug  ][XRootDTransport   ] [eospublic.cern.ch:1094.0] Authentication is required: &P=krb5,xrootd/eospublic.cern.ch@CERN.CH&P=gsi,v:10400,c:ssl,ca:5168735f.0|4339b4bc.0&P=sss,0.13:/etc/eos.keytab&P=unix
[2022-09-06 20:07:21.233853 +0200][Debug  ][XRootDTransport   ] [eospublic.cern.ch:1094.0] Sending authentication data
[2022-09-06 20:07:21.239396 +0200][Debug  ][XRootDTransport   ] [eospublic.cern.ch:1094.0] Trying to authenticate using krb5
[2022-09-06 20:07:21.252489 +0200][Debug  ][XRootDTransport   ] [eospublic.cern.ch:1094.0] Cannot get credentials for protocol krb5: Seckrb5: No or invalid credentials; Matching credential not found (p=xrootd/eospublic.cern.ch@CERN.CH).
[2022-09-06 20:07:21.252584 +0200][Debug  ][XRootDTransport   ] [eospublic.cern.ch:1094.0] Trying to authenticate using gsi
[2022-09-06 20:07:21.391265 +0200][Debug  ][XRootDTransport   ] [eospublic.cern.ch:1094.0] Cannot get credentials for protocol gsi: Secgsi: ErrParseBuffer: unknown CA: cannot verify server certificate: kXGS_init
[2022-09-06 20:07:21.722279 +0200][Dump   ][TaskMgr           ] Running task: "TickGeneratorTask for: root://eospublic.cern.ch:1094"
[2022-09-06 20:07:21.722359 +0200][Dump   ][TaskMgr           ] Will rerun task "TickGeneratorTask for: root://eospublic.cern.ch:1094" at [2022-09-06 20:07:36 +0200]
[2022-09-06 20:07:22.732437 +0200][Dump   ][TaskMgr           ] Running task: "FileTimer task"
[2022-09-06 20:07:22.732510 +0200][Dump   ][TaskMgr           ] Will rerun task "FileTimer task" at [2022-09-06 20:07:37 +0200]
[2022-09-06 20:07:27.588407 +0200][Debug  ][XRootDTransport   ] [eospublic.cern.ch:1094.0] Trying to authenticate using unix
[2022-09-06 20:07:27.591293 +0200][Dump   ][AsyncSock         ] [eospublic.cern.ch:1094.0] Wrote a message:  (0x1e0d4a0), 44 bytes
[2022-09-06 20:07:27.591584 +0200][Dump   ][XRootDTransport   ] [msg: 0x1e032a0] Expecting 0 bytes of message body
[2022-09-06 20:07:27.591602 +0200][Dump   ][AsyncSock         ] [eospublic.cern.ch:1094.0] Received message header, size: 8
[2022-09-06 20:07:27.591609 +0200][Dump   ][AsyncSock         ] [eospublic.cern.ch:1094.0] Received a message of 8 bytes
[2022-09-06 20:07:27.591619 +0200][Debug  ][XRootDTransport   ] [eospublic.cern.ch:1094.0] Authenticated with unix.
[2022-09-06 20:07:27.591630 +0200][Debug  ][PostMaster        ] [eospublic.cern.ch:1094] Stream 0 connected.
[2022-09-06 20:07:27.591642 +0200][Debug  ][Utility           ] Monitor library name not set. No monitoring
[2022-09-06 20:07:27.591668 +0200][Dump   ][AsyncSock         ] [eospublic.cern.ch:1094.0] Wrote a message: kXR_open (file: /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) (0x1e9b2f0), 84 bytes
[2022-09-06 20:07:27.591682 +0200][Dump   ][AsyncSock         ] [eospublic.cern.ch:1094.0] Successfully sent message: kXR_open (file: /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) (0x1e9b2f0).
[2022-09-06 20:07:27.591689 +0200][Dump   ][XRootD            ] [eospublic.cern.ch:1094] Message kXR_open (file: /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) has been successfully sent.
[2022-09-06 20:07:27.591695 +0200][Debug  ][ExDbgMsg          ] [eospublic.cern.ch:1094] Moving MsgHandler: 0xd3121b60 (message: kXR_open (file: /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) ) from out-queu to in-queue.
[2022-09-06 20:07:27.591705 +0200][Dump   ][PostMaster        ] [eospublic.cern.ch:1094.0] All messages consumed, disable uplink
[2022-09-06 20:07:27.604440 +0200][Dump   ][XRootDTransport   ] [msg: 0x1938fd8] Expecting 852 bytes of message body
[2022-09-06 20:07:27.604479 +0200][Dump   ][AsyncSock         ] [eospublic.cern.ch:1094.0] Received message header for 0x1938fd8 size: 8
[2022-09-06 20:07:27.604490 +0200][Debug  ][ExDbgMsg          ] [msg: 0x1938fd8] Assigned MsgHandler: 0xd3121b60.
[2022-09-06 20:07:27.604499 +0200][Debug  ][ExDbgMsg          ] [handler: 0xd3121b60] Removed MsgHandler: 0xd3121b60 from the in-queue.
[2022-09-06 20:07:27.604511 +0200][Dump   ][AsyncSock         ] [eospublic.cern.ch:1094.0] Received message 0x1938fd8 of 860 bytes
[2022-09-06 20:07:27.604520 +0200][Dump   ][PostMaster        ] [eospublic.cern.ch:1094] Handling received message: 0x1938fd8.
[2022-09-06 20:07:27.604604 +0200][Dump   ][XRootD            ] [eospublic.cern.ch:1094] Got kXR_redirect response to message kXR_open (file: /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ): p06636710d91266.cern.ch?&cap.sym=q+CUHEBX8oAEqtPu2nHLfSuxInA=&cap.msg=QHtGNWO287qHIYzxGIORRghAXLvb9ZznlpHRAWQBQjrvMHndOOHyr5qnLo5IKSgF3c0cTK1PG2ZnHNkKhNR9kpW7g26yIqObz2OqhscSmQRsbygazsSACx/KOfQ3lzALS/GnNUQrg88uZb2wK/95O6aybtQ9mRisPnsMGEBnGnFFv4Y6KSKO5qsqlts/QxwCptqi+ZsD3iSW0MOM69SOeIRMeZtoP1HnEojYsVG+Kq6MoOMNrmYY3Eoc8eVVKjhsoEl6XP9AKXZJaS7XeN1qp2fsQERQl72jk4ehsK0Zzv/6gPbBXjCI89P3IEXpZufhQPAcYcdn0Sl/rJCTYRn8jsPBTF2g2BAA31UEdJWu7hpaSArm6cYok6TOnrlFaNcbYqVdVy4k8rtgXJAVv19rZvgXw0XtAAsw4rB2ZJs+YxXBwwUjM6kzxTiIS5VxeFs+k6FrHPMoXPnvet2tO4DsNqmBl+Ns2BN3b39SwB4vcT6c8Z36Sy2X2PH8AO/YqQie6/dZEAx/lt2qHTRgiOpk5RTDxZGEXlpjSVFleVYh1dkg/RFdpkK6liizeeO4HtcV5IrS2mz2g6i/yKLaXzvpS5Unf3QrUyruWxqDr7H55s6DWaVxcfrQBw==&mgm.logid=c454d022-2e0e-11ed-8d47-a4bf01796189&mgm.blockchecksum=ignore&mgm.replicaindex=0&mgm.replicahead=0&mgm.id=3b4e2c49&mgm.mtime=1593523093, port 1095
[2022-09-06 20:07:27.604665 +0200][Dump   ][XRootD            ] [eospublic.cern.ch:1094] Current server has been assigned as a load-balancer for message kXR_open (file: /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root, mode: 00, flags: kXR_open_read kXR_async kXR_retstat )
[2022-09-06 20:07:27.604692 +0200][Dump   ][Utility           ] URL: p06636710d91266.cern.ch:1095/
[2022-09-06 20:07:27.604692 +0200][Dump   ][Utility           ] Protocol:  root
[2022-09-06 20:07:27.604692 +0200][Dump   ][Utility           ] User Name:
[2022-09-06 20:07:27.604692 +0200][Dump   ][Utility           ] Password:
[2022-09-06 20:07:27.604692 +0200][Dump   ][Utility           ] Host Name: p06636710d91266.cern.ch
[2022-09-06 20:07:27.604692 +0200][Dump   ][Utility           ] Port:      1095
[2022-09-06 20:07:27.604692 +0200][Dump   ][Utility           ] Path:
[2022-09-06 20:07:27.604759 +0200][Dump   ][Utility           ] URL: fake://fake:111//fake?&cap.sym=q+CUHEBX8oAEqtPu2nHLfSuxInA=&cap.msg=QHtGNWO287qHIYzxGIORRghAXLvb9ZznlpHRAWQBQjrvMHndOOHyr5qnLo5IKSgF3c0cTK1PG2ZnHNkKhNR9kpW7g26yIqObz2OqhscSmQRsbygazsSACx/KOfQ3lzALS/GnNUQrg88uZb2wK/95O6aybtQ9mRisPnsMGEBnGnFFv4Y6KSKO5qsqlts/QxwCptqi+ZsD3iSW0MOM69SOeIRMeZtoP1HnEojYsVG+Kq6MoOMNrmYY3Eoc8eVVKjhsoEl6XP9AKXZJaS7XeN1qp2fsQERQl72jk4ehsK0Zzv/6gPbBXjCI89P3IEXpZufhQPAcYcdn0Sl/rJCTYRn8jsPBTF2g2BAA31UEdJWu7hpaSArm6cYok6TOnrlFaNcbYqVdVy4k8rtgXJAVv19rZvgXw0XtAAsw4rB2ZJs+YxXBwwUjM6kzxTiIS5VxeFs+k6FrHPMoXPnvet2tO4DsNqmBl+Ns2BN3b39SwB4vcT6c8Z36Sy2X2PH8AO/YqQie6/dZEAx/lt2qHTRgiOpk5RTDxZGEXlpjSVFleVYh1dkg/RFdpkK6liizeeO4HtcV5IrS2mz2g6i/yKLaXzvpS5Unf3QrUyruWxqDr7H55s6DWaVxcfrQBw==&mgm.logid=c454d022-2e0e-11ed-8d47-a4bf01796189&mgm.blockchecksum=ignore&mgm.replicaindex=0&mgm.replicahead=0&mgm.id=3b4e2c49&mgm.mtime=1593523093&xrdcl.requuid=B3AEE882-3B58-4DB5-BF16-C07F64AE50AC&
[2022-09-06 20:07:27.604759 +0200][Dump   ][Utility           ] Protocol:  fake
[2022-09-06 20:07:27.604759 +0200][Dump   ][Utility           ] User Name:
[2022-09-06 20:07:27.604759 +0200][Dump   ][Utility           ] Password:
[2022-09-06 20:07:27.604759 +0200][Dump   ][Utility           ] Host Name: fake
[2022-09-06 20:07:27.604759 +0200][Dump   ][Utility           ] Port:      111
[2022-09-06 20:07:27.604759 +0200][Dump   ][Utility           ] Path:      /fake
[2022-09-06 20:07:27.604844 +0200][Dump   ][Utility           ] URL: fake://fake:111//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root
[2022-09-06 20:07:27.604844 +0200][Dump   ][Utility           ] Protocol:  fake
[2022-09-06 20:07:27.604844 +0200][Dump   ][Utility           ] User Name:
[2022-09-06 20:07:27.604844 +0200][Dump   ][Utility           ] Password:
[2022-09-06 20:07:27.604844 +0200][Dump   ][Utility           ] Host Name: fake
[2022-09-06 20:07:27.604844 +0200][Dump   ][Utility           ] Port:      111
[2022-09-06 20:07:27.604844 +0200][Dump   ][Utility           ] Path:      /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root
[2022-09-06 20:07:27.604914 +0200][Dump   ][Utility           ] URL: root://eospublic.cern.ch:1094//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root
[2022-09-06 20:07:27.604914 +0200][Dump   ][Utility           ] Protocol:  root
[2022-09-06 20:07:27.604914 +0200][Dump   ][Utility           ] User Name:
[2022-09-06 20:07:27.604914 +0200][Dump   ][Utility           ] Password:
[2022-09-06 20:07:27.604914 +0200][Dump   ][Utility           ] Host Name: eospublic.cern.ch
[2022-09-06 20:07:27.604914 +0200][Dump   ][Utility           ] Port:      1094
[2022-09-06 20:07:27.604914 +0200][Dump   ][Utility           ] Path:      /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root
[2022-09-06 20:07:27.604943 +0200][Dump   ][Utility           ] URL: root://p06636710d91266.cern.ch:1095/
[2022-09-06 20:07:27.604943 +0200][Dump   ][Utility           ] Protocol:  root
[2022-09-06 20:07:27.604943 +0200][Dump   ][Utility           ] User Name:
[2022-09-06 20:07:27.604943 +0200][Dump   ][Utility           ] Password:
[2022-09-06 20:07:27.604943 +0200][Dump   ][Utility           ] Host Name: p06636710d91266.cern.ch
[2022-09-06 20:07:27.604943 +0200][Dump   ][Utility           ] Port:      1095
[2022-09-06 20:07:27.604943 +0200][Dump   ][Utility           ] Path:
[2022-09-06 20:07:27.604979 +0200][Debug  ][ExDbgMsg          ] [p06636710d91266.cern.ch:1095] Retry at server MsgHandler: 0xd3121b60 (message: kXR_open (file: /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root?cap.msg=QHtGNWO287qHIYzxGIORRghAXLvb9ZznlpHRAWQBQjrvMHndOOHyr5qnLo5IKSgF3c0cTK1PG2ZnHNkKhNR9kpW7g26yIqObz2OqhscSmQRsbygazsSACx/KOfQ3lzALS/GnNUQrg88uZb2wK/95O6aybtQ9mRisPnsMGEBnGnFFv4Y6KSKO5qsqlts/QxwCptqi+ZsD3iSW0MOM69SOeIRMeZtoP1HnEojYsVG+Kq6MoOMNrmYY3Eoc8eVVKjhsoEl6XP9AKXZJaS7XeN1qp2fsQERQl72jk4ehsK0Zzv/6gPbBXjCI89P3IEXpZufhQPAcYcdn0Sl/rJCTYRn8jsPBTF2g2BAA31UEdJWu7hpaSArm6cYok6TOnrlFaNcbYqVdVy4k8rtgXJAVv19rZvgXw0XtAAsw4rB2ZJs+YxXBwwUjM6kzxTiIS5VxeFs+k6FrHPMoXPnvet2tO4DsNqmBl+Ns2BN3b39SwB4vcT6c8Z36Sy2X2PH8AO/YqQie6/dZEAx/lt2qHTRgiOpk5RTDxZGEXlpjSVFleVYh1dkg/RFdpkK6liizeeO4HtcV5IrS2mz2g6i/yKLaXzvpS5Unf3QrUyruWxqDr7H55s6DWaVxcfrQBw==&cap.sym=q+CUHEBX8oAEqtPu2nHLfSuxInA=&mgm.blockchecksum=ignore&mgm.id=3b4e2c49&mgm.logid=c454d022-2e0e-11ed-8d47-a4bf01796189&mgm.mtime=1593523093&mgm.replicahead=0&mgm.replicaindex=0, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) ).
[2022-09-06 20:07:27.605050 +0200][Dump   ][Utility           ] URL: p06636710d91266.cern.ch:1095
[2022-09-06 20:07:27.605050 +0200][Dump   ][Utility           ] Protocol:  root
[2022-09-06 20:07:27.605050 +0200][Dump   ][Utility           ] User Name:
[2022-09-06 20:07:27.605050 +0200][Dump   ][Utility           ] Password:
[2022-09-06 20:07:27.605050 +0200][Dump   ][Utility           ] Host Name: p06636710d91266.cern.ch
[2022-09-06 20:07:27.605050 +0200][Dump   ][Utility           ] Port:      1095
[2022-09-06 20:07:27.605050 +0200][Dump   ][Utility           ] Path:
[2022-09-06 20:07:27.605095 +0200][Dump   ][Utility           ] URL: root://p06636710d91266.cern.ch:1095
[2022-09-06 20:07:27.605095 +0200][Dump   ][Utility           ] Protocol:  root
[2022-09-06 20:07:27.605095 +0200][Dump   ][Utility           ] User Name:
[2022-09-06 20:07:27.605095 +0200][Dump   ][Utility           ] Password:
[2022-09-06 20:07:27.605095 +0200][Dump   ][Utility           ] Host Name: p06636710d91266.cern.ch
[2022-09-06 20:07:27.605095 +0200][Dump   ][Utility           ] Port:      1095
[2022-09-06 20:07:27.605095 +0200][Dump   ][Utility           ] Path:
[2022-09-06 20:07:27.605124 +0200][Debug  ][PostMaster        ] Creating new channel to: root://p06636710d91266.cern.ch:1095
[2022-09-06 20:07:27.605165 +0200][Debug  ][PostMaster        ] [p06636710d91266.cern.ch:1095] Stream parameters: Network Stack: IPAuto, Connection Window: 120, ConnectionRetry: 5, Stream Error Window: 1800
[2022-09-06 20:07:27.605188 +0200][Debug  ][TaskMgr           ] Registering task: "TickGeneratorTask for: root://p06636710d91266.cern.ch:1095" to be run at: [2022-09-06 20:07:42 +0200]
[2022-09-06 20:07:27.605205 +0200][Dump   ][PostMaster        ] [p06636710d91266.cern.ch:1095] Sending message kXR_open (file: /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root?cap.msg=QHtGNWO287qHIYzxGIORRghAXLvb9ZznlpHRAWQBQjrvMHndOOHyr5qnLo5IKSgF3c0cTK1PG2ZnHNkKhNR9kpW7g26yIqObz2OqhscSmQRsbygazsSACx/KOfQ3lzALS/GnNUQrg88uZb2wK/95O6aybtQ9mRisPnsMGEBnGnFFv4Y6KSKO5qsqlts/QxwCptqi+ZsD3iSW0MOM69SOeIRMeZtoP1HnEojYsVG+Kq6MoOMNrmYY3Eoc8eVVKjhsoEl6XP9AKXZJaS7XeN1qp2fsQERQl72jk4ehsK0Zzv/6gPbBXjCI89P3IEXpZufhQPAcYcdn0Sl/rJCTYRn8jsPBTF2g2BAA31UEdJWu7hpaSArm6cYok6TOnrlFaNcbYqVdVy4k8rtgXJAVv19rZvgXw0XtAAsw4rB2ZJs+YxXBwwUjM6kzxTiIS5VxeFs+k6FrHPMoXPnvet2tO4DsNqmBl+Ns2BN3b39SwB4vcT6c8Z36Sy2X2PH8AO/YqQie6/dZEAx/lt2qHTRgiOpk5RTDxZGEXlpjSVFleVYh1dkg/RFdpkK6liizeeO4HtcV5IrS2mz2g6i/yKLaXzvpS5Unf3QrUyruWxqDr7H55s6DWaVxcfrQBw==&cap.sym=q+CUHEBX8oAEqtPu2nHLfSuxInA=&mgm.blockchecksum=ignore&mgm.id=3b4e2c49&mgm.logid=c454d022-2e0e-11ed-8d47-a4bf01796189&mgm.mtime=1593523093&mgm.replicahead=0&mgm.replicaindex=0, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) (0x1e9b2f0) through substream 0 expecting answer at 0
[2022-09-06 20:07:27.606746 +0200][Debug  ][PostMaster        ] [p06636710d91266.cern.ch:1095] Found 2 address(es): [::ffff:128.142.215.72]:1095, [2001:1458:301:c4::100:8]:1095
[2022-09-06 20:07:27.606806 +0200][Debug  ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Attempting connection to [2001:1458:301:c4::100:8]:1095
[2022-09-06 20:07:27.606892 +0200][Debug  ][Poller            ] Adding socket 0x139aa00 to the poller
[2022-09-06 20:07:36.769998 +0200][Dump   ][TaskMgr           ] Running task: "TickGeneratorTask for: root://eospublic.cern.ch:1094"
[2022-09-06 20:07:36.770083 +0200][Dump   ][TaskMgr           ] Will rerun task "TickGeneratorTask for: root://eospublic.cern.ch:1094" at [2022-09-06 20:07:51 +0200]
[2022-09-06 20:07:37.771994 +0200][Dump   ][TaskMgr           ] Running task: "FileTimer task"
[2022-09-06 20:07:37.772082 +0200][Dump   ][TaskMgr           ] Will rerun task "FileTimer task" at [2022-09-06 20:07:52 +0200]
[2022-09-06 20:07:42.605954 +0200][Dump   ][XRootDTransport   ] [eospublic.cern.ch:1094.0] Stream inactive since 15 seconds, TTL: 1200, allocated SIDs: 0, open files: 0, bound file objects: 0
[2022-09-06 20:07:42.606034 +0200][Dump   ][XRootDTransport   ] [eospublic.cern.ch:1094.0] Stream inactive since 15 seconds, stream timeout: 60, allocated SIDs: 0, wait barrier: 2022-09-06 20:07:27 +0200
[2022-09-06 20:07:42.782069 +0200][Dump   ][TaskMgr           ] Running task: "TickGeneratorTask for: root://p06636710d91266.cern.ch:1095"
[2022-09-06 20:07:42.782154 +0200][Dump   ][TaskMgr           ] Will rerun task "TickGeneratorTask for: root://p06636710d91266.cern.ch:1095" at [2022-09-06 20:07:57 +0200]
[2022-09-06 20:07:51.800137 +0200][Dump   ][TaskMgr           ] Running task: "TickGeneratorTask for: root://eospublic.cern.ch:1094"
[2022-09-06 20:07:51.800221 +0200][Dump   ][TaskMgr           ] Will rerun task "TickGeneratorTask for: root://eospublic.cern.ch:1094" at [2022-09-06 20:08:06 +0200]
[2022-09-06 20:07:52.802168 +0200][Dump   ][TaskMgr           ] Running task: "FileTimer task"
[2022-09-06 20:07:52.802244 +0200][Dump   ][TaskMgr           ] Will rerun task "FileTimer task" at [2022-09-06 20:08:07 +0200]
[2022-09-06 20:07:57.607482 +0200][Dump   ][XRootDTransport   ] [eospublic.cern.ch:1094.0] Stream inactive since 30 seconds, TTL: 1200, allocated SIDs: 0, open files: 0, bound file objects: 0
[2022-09-06 20:07:57.607563 +0200][Dump   ][XRootDTransport   ] [eospublic.cern.ch:1094.0] Stream inactive since 30 seconds, stream timeout: 60, allocated SIDs: 0, wait barrier: 2022-09-06 20:07:27 +0200
[2022-09-06 20:07:57.812181 +0200][Dump   ][TaskMgr           ] Running task: "TickGeneratorTask for: root://p06636710d91266.cern.ch:1095"
[2022-09-06 20:07:57.812274 +0200][Dump   ][TaskMgr           ] Will rerun task "TickGeneratorTask for: root://p06636710d91266.cern.ch:1095" at [2022-09-06 20:08:12 +0200]
[2022-09-06 20:08:06.830285 +0200][Dump   ][TaskMgr           ] Running task: "TickGeneratorTask for: root://eospublic.cern.ch:1094"
[2022-09-06 20:08:06.830364 +0200][Dump   ][TaskMgr           ] Will rerun task "TickGeneratorTask for: root://eospublic.cern.ch:1094" at [2022-09-06 20:08:21 +0200]
[2022-09-06 20:08:07.832300 +0200][Dump   ][TaskMgr           ] Running task: "FileTimer task"
[2022-09-06 20:08:07.832375 +0200][Dump   ][TaskMgr           ] Will rerun task "FileTimer task" at [2022-09-06 20:08:22 +0200]
[2022-09-06 20:08:12.609059 +0200][Dump   ][XRootDTransport   ] [eospublic.cern.ch:1094.0] Stream inactive since 45 seconds, TTL: 1200, allocated SIDs: 0, open files: 0, bound file objects: 0
[2022-09-06 20:08:12.609138 +0200][Dump   ][XRootDTransport   ] [eospublic.cern.ch:1094.0] Stream inactive since 45 seconds, stream timeout: 60, allocated SIDs: 0, wait barrier: 2022-09-06 20:07:27 +0200
[2022-09-06 20:08:12.842352 +0200][Dump   ][TaskMgr           ] Running task: "TickGeneratorTask for: root://p06636710d91266.cern.ch:1095"
[2022-09-06 20:08:12.842435 +0200][Dump   ][TaskMgr           ] Will rerun task "TickGeneratorTask for: root://p06636710d91266.cern.ch:1095" at [2022-09-06 20:08:27 +0200]
[2022-09-06 20:08:21.860463 +0200][Dump   ][TaskMgr           ] Running task: "TickGeneratorTask for: root://eospublic.cern.ch:1094"
[2022-09-06 20:08:21.860555 +0200][Dump   ][TaskMgr           ] Will rerun task "TickGeneratorTask for: root://eospublic.cern.ch:1094" at [2022-09-06 20:08:36 +0200]
[2022-09-06 20:08:22.862497 +0200][Dump   ][TaskMgr           ] Running task: "FileTimer task"
[2022-09-06 20:08:22.862587 +0200][Dump   ][TaskMgr           ] Will rerun task "FileTimer task" at [2022-09-06 20:08:37 +0200]
[2022-09-06 20:08:27.610600 +0200][Dump   ][XRootDTransport   ] [eospublic.cern.ch:1094.0] Stream inactive since 60 seconds, TTL: 1200, allocated SIDs: 0, open files: 0, bound file objects: 0
[2022-09-06 20:08:27.610688 +0200][Dump   ][XRootDTransport   ] [eospublic.cern.ch:1094.0] Stream inactive since 60 seconds, stream timeout: 60, allocated SIDs: 0, wait barrier: 2022-09-06 20:07:27 +0200
[2022-09-06 20:08:27.872539 +0200][Dump   ][TaskMgr           ] Running task: "TickGeneratorTask for: root://p06636710d91266.cern.ch:1095"
[2022-09-06 20:08:27.872624 +0200][Dump   ][TaskMgr           ] Will rerun task "TickGeneratorTask for: root://p06636710d91266.cern.ch:1095" at [2022-09-06 20:08:42 +0200]
[2022-09-06 20:08:36.890609 +0200][Dump   ][TaskMgr           ] Running task: "TickGeneratorTask for: root://eospublic.cern.ch:1094"
[2022-09-06 20:08:36.890694 +0200][Dump   ][TaskMgr           ] Will rerun task "TickGeneratorTask for: root://eospublic.cern.ch:1094" at [2022-09-06 20:08:51 +0200]
[2022-09-06 20:08:37.892623 +0200][Dump   ][TaskMgr           ] Running task: "FileTimer task"
[2022-09-06 20:08:37.892699 +0200][Dump   ][TaskMgr           ] Will rerun task "FileTimer task" at [2022-09-06 20:08:52 +0200]
[2022-09-06 20:08:42.604897 +0200][Debug  ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Async connection call returned
[2022-09-06 20:08:42.604962 +0200][Error  ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Unable to connect: operation timed out
[2022-09-06 20:08:42.604973 +0200][Debug  ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Closing the socket
[2022-09-06 20:08:42.604983 +0200][Debug  ][Poller            ] <x><--><x> Removing socket from the poller
[2022-09-06 20:08:42.605004 +0200][Error  ][PostMaster        ] [p06636710d91266.cern.ch:1095] elapsed = 75, pConnectionWindow = 120 seconds.
[2022-09-06 20:08:42.605062 +0200][Debug  ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Attempting connection to [::ffff:128.142.215.72]:1095
[2022-09-06 20:08:42.605148 +0200][Debug  ][Poller            ] Adding socket 0x139aa00 to the poller
[2022-09-06 20:08:42.605179 +0200][Dump   ][XRootDTransport   ] [eospublic.cern.ch:1094.0] Stream inactive since 75 seconds, TTL: 1200, allocated SIDs: 0, open files: 0, bound file objects: 0
[2022-09-06 20:08:42.605195 +0200][Dump   ][XRootDTransport   ] [eospublic.cern.ch:1094.0] Stream inactive since 75 seconds, stream timeout: 60, allocated SIDs: 0, wait barrier: 2022-09-06 20:07:27 +0200
[2022-09-06 20:08:42.605702 +0200][Debug  ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Async connection call returned
[2022-09-06 20:08:42.605747 +0200][Debug  ][XRootDTransport   ] [p06636710d91266.cern.ch:1095.0] Sending out the initial hand shake + kXR_protocol
[2022-09-06 20:08:42.605797 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Wrote a message:  (0x1e03480), 44 bytes
[2022-09-06 20:08:42.608805 +0200][Dump   ][XRootDTransport   ] [msg: 0x1e9b4d0] Expecting 8 bytes of message body
[2022-09-06 20:08:42.608843 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Received message header, size: 8
[2022-09-06 20:08:42.608856 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Received a message of 16 bytes
[2022-09-06 20:08:42.608870 +0200][Debug  ][XRootDTransport   ] [p06636710d91266.cern.ch:1095.0] Got the server hand shake response (type: server [], protocol version 400)
[2022-09-06 20:08:42.608887 +0200][Dump   ][XRootDTransport   ] [msg: 0x1e9b4d0] Expecting 8 bytes of message body
[2022-09-06 20:08:42.608895 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Received message header, size: 8
[2022-09-06 20:08:42.608904 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Received a message of 16 bytes
[2022-09-06 20:08:42.608915 +0200][Debug  ][XRootDTransport   ] [p06636710d91266.cern.ch:1095.0] kXR_protocol successful (type: server [], protocol version 400)
[2022-09-06 20:08:42.902690 +0200][Dump   ][TaskMgr           ] Running task: "TickGeneratorTask for: root://p06636710d91266.cern.ch:1095"
[2022-09-06 20:08:42.902771 +0200][Dump   ][TaskMgr           ] Will rerun task "TickGeneratorTask for: root://p06636710d91266.cern.ch:1095" at [2022-09-06 20:08:57 +0200]
[2022-09-06 20:08:48.827338 +0200][Debug  ][XRootDTransport   ] [p06636710d91266.cern.ch:1095.0] Sending out kXR_login request, username: sftnight, cgi: xrd.cc=ch&xrd.tz=1&xrd.appname=repro&xrd.info=&xrd.hostname=macphsft18.dyndns.cern.ch&xrd.rn=v5.4.3, dual-stack: true, private IPv4: false, private IPv6: false
[2022-09-06 20:08:48.827422 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Wrote a message:  (0x1e9b610), 123 bytes
[2022-09-06 20:08:48.828273 +0200][Dump   ][XRootDTransport   ] [msg: 0x1e0c320] Expecting 50 bytes of message body
[2022-09-06 20:08:48.828311 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Received message header, size: 8
[2022-09-06 20:08:48.828325 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Received a message of 58 bytes
[2022-09-06 20:08:48.828337 +0200][Debug  ][XRootDTransport   ] [p06636710d91266.cern.ch:1095.0] Logged in, session: 93f23c00be6600000301000037a33d00
[2022-09-06 20:08:48.828345 +0200][Debug  ][XRootDTransport   ] [p06636710d91266.cern.ch:1095.0] Authentication is required: &P=unix&P=sss,0.13:/etc/eos.keytab
[2022-09-06 20:08:48.828352 +0200][Debug  ][XRootDTransport   ] [p06636710d91266.cern.ch:1095.0] Sending authentication data
[2022-09-06 20:08:48.828375 +0200][Debug  ][XRootDTransport   ] [p06636710d91266.cern.ch:1095.0] Trying to authenticate using unix
[2022-09-06 20:08:48.828431 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Wrote a message:  (0x1e0d4a0), 44 bytes
[2022-09-06 20:08:48.828960 +0200][Dump   ][XRootDTransport   ] [msg: 0x1e0c320] Expecting 0 bytes of message body
[2022-09-06 20:08:48.828986 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Received message header, size: 8
[2022-09-06 20:08:48.828996 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Received a message of 8 bytes
[2022-09-06 20:08:48.829009 +0200][Debug  ][XRootDTransport   ] [p06636710d91266.cern.ch:1095.0] Authenticated with unix.
[2022-09-06 20:08:48.829024 +0200][Debug  ][PostMaster        ] [p06636710d91266.cern.ch:1095] Stream 0 connected.
[2022-09-06 20:08:48.829066 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Wrote a message: kXR_open (file: /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root?cap.msg=QHtGNWO287qHIYzxGIORRghAXLvb9ZznlpHRAWQBQjrvMHndOOHyr5qnLo5IKSgF3c0cTK1PG2ZnHNkKhNR9kpW7g26yIqObz2OqhscSmQRsbygazsSACx/KOfQ3lzALS/GnNUQrg88uZb2wK/95O6aybtQ9mRisPnsMGEBnGnFFv4Y6KSKO5qsqlts/QxwCptqi+ZsD3iSW0MOM69SOeIRMeZtoP1HnEojYsVG+Kq6MoOMNrmYY3Eoc8eVVKjhsoEl6XP9AKXZJaS7XeN1qp2fsQERQl72jk4ehsK0Zzv/6gPbBXjCI89P3IEXpZufhQPAcYcdn0Sl/rJCTYRn8jsPBTF2g2BAA31UEdJWu7hpaSArm6cYok6TOnrlFaNcbYqVdVy4k8rtgXJAVv19rZvgXw0XtAAsw4rB2ZJs+YxXBwwUjM6kzxTiIS5VxeFs+k6FrHPMoXPnvet2tO4DsNqmBl+Ns2BN3b39SwB4vcT6c8Z36Sy2X2PH8AO/YqQie6/dZEAx/lt2qHTRgiOpk5RTDxZGEXlpjSVFleVYh1dkg/RFdpkK6liizeeO4HtcV5IrS2mz2g6i/yKLaXzvpS5Unf3QrUyruWxqDr7H55s6DWaVxcfrQBw==&cap.sym=q+CUHEBX8oAEqtPu2nHLfSuxInA=&mgm.blockchecksum=ignore&mgm.id=3b4e2c49&mgm.logid=c454d022-2e0e-11ed-8d47-a4bf01796189&mgm.mtime=1593523093&mgm.replicahead=0&mgm.replicaindex=0, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) (0x1e9b2f0), 908 bytes
[2022-09-06 20:08:48.829108 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Successfully sent message: kXR_open (file: /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root?cap.msg=QHtGNWO287qHIYzxGIORRghAXLvb9ZznlpHRAWQBQjrvMHndOOHyr5qnLo5IKSgF3c0cTK1PG2ZnHNkKhNR9kpW7g26yIqObz2OqhscSmQRsbygazsSACx/KOfQ3lzALS/GnNUQrg88uZb2wK/95O6aybtQ9mRisPnsMGEBnGnFFv4Y6KSKO5qsqlts/QxwCptqi+ZsD3iSW0MOM69SOeIRMeZtoP1HnEojYsVG+Kq6MoOMNrmYY3Eoc8eVVKjhsoEl6XP9AKXZJaS7XeN1qp2fsQERQl72jk4ehsK0Zzv/6gPbBXjCI89P3IEXpZufhQPAcYcdn0Sl/rJCTYRn8jsPBTF2g2BAA31UEdJWu7hpaSArm6cYok6TOnrlFaNcbYqVdVy4k8rtgXJAVv19rZvgXw0XtAAsw4rB2ZJs+YxXBwwUjM6kzxTiIS5VxeFs+k6FrHPMoXPnvet2tO4DsNqmBl+Ns2BN3b39SwB4vcT6c8Z36Sy2X2PH8AO/YqQie6/dZEAx/lt2qHTRgiOpk5RTDxZGEXlpjSVFleVYh1dkg/RFdpkK6liizeeO4HtcV5IrS2mz2g6i/yKLaXzvpS5Unf3QrUyruWxqDr7H55s6DWaVxcfrQBw==&cap.sym=q+CUHEBX8oAEqtPu2nHLfSuxInA=&mgm.blockchecksum=ignore&mgm.id=3b4e2c49&mgm.logid=c454d022-2e0e-11ed-8d47-a4bf01796189&mgm.mtime=1593523093&mgm.replicahead=0&mgm.replicaindex=0, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) (0x1e9b2f0).
[2022-09-06 20:08:48.829165 +0200][Dump   ][XRootD            ] [p06636710d91266.cern.ch:1095] Message kXR_open (file: /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root?cap.msg=QHtGNWO287qHIYzxGIORRghAXLvb9ZznlpHRAWQBQjrvMHndOOHyr5qnLo5IKSgF3c0cTK1PG2ZnHNkKhNR9kpW7g26yIqObz2OqhscSmQRsbygazsSACx/KOfQ3lzALS/GnNUQrg88uZb2wK/95O6aybtQ9mRisPnsMGEBnGnFFv4Y6KSKO5qsqlts/QxwCptqi+ZsD3iSW0MOM69SOeIRMeZtoP1HnEojYsVG+Kq6MoOMNrmYY3Eoc8eVVKjhsoEl6XP9AKXZJaS7XeN1qp2fsQERQl72jk4ehsK0Zzv/6gPbBXjCI89P3IEXpZufhQPAcYcdn0Sl/rJCTYRn8jsPBTF2g2BAA31UEdJWu7hpaSArm6cYok6TOnrlFaNcbYqVdVy4k8rtgXJAVv19rZvgXw0XtAAsw4rB2ZJs+YxXBwwUjM6kzxTiIS5VxeFs+k6FrHPMoXPnvet2tO4DsNqmBl+Ns2BN3b39SwB4vcT6c8Z36Sy2X2PH8AO/YqQie6/dZEAx/lt2qHTRgiOpk5RTDxZGEXlpjSVFleVYh1dkg/RFdpkK6liizeeO4HtcV5IrS2mz2g6i/yKLaXzvpS5Unf3QrUyruWxqDr7H55s6DWaVxcfrQBw==&cap.sym=q+CUHEBX8oAEqtPu2nHLfSuxInA=&mgm.blockchecksum=ignore&mgm.id=3b4e2c49&mgm.logid=c454d022-2e0e-11ed-8d47-a4bf01796189&mgm.mtime=1593523093&mgm.replicahead=0&mgm.replicaindex=0, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) has been successfully sent.
[2022-09-06 20:08:48.829265 +0200][Debug  ][ExDbgMsg          ] [p06636710d91266.cern.ch:1095] Moving MsgHandler: 0xd3121b60 (message: kXR_open (file: /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root?cap.msg=QHtGNWO287qHIYzxGIORRghAXLvb9ZznlpHRAWQBQjrvMHndOOHyr5qnLo5IKSgF3c0cTK1PG2ZnHNkKhNR9kpW7g26yIqObz2OqhscSmQRsbygazsSACx/KOfQ3lzALS/GnNUQrg88uZb2wK/95O6aybtQ9mRisPnsMGEBnGnFFv4Y6KSKO5qsqlts/QxwCptqi+ZsD3iSW0MOM69SOeIRMeZtoP1HnEojYsVG+Kq6MoOMNrmYY3Eoc8eVVKjhsoEl6XP9AKXZJaS7XeN1qp2fsQERQl72jk4ehsK0Zzv/6gPbBXjCI89P3IEXpZufhQPAcYcdn0Sl/rJCTYRn8jsPBTF2g2BAA31UEdJWu7hpaSArm6cYok6TOnrlFaNcbYqVdVy4k8rtgXJAVv19rZvgXw0XtAAsw4rB2ZJs+YxXBwwUjM6kzxTiIS5VxeFs+k6FrHPMoXPnvet2tO4DsNqmBl+Ns2BN3b39SwB4vcT6c8Z36Sy2X2PH8AO/YqQie6/dZEAx/lt2qHTRgiOpk5RTDxZGEXlpjSVFleVYh1dkg/RFdpkK6liizeeO4HtcV5IrS2mz2g6i/yKLaXzvpS5Unf3QrUyruWxqDr7H55s6DWaVxcfrQBw==&cap.sym=q+CUHEBX8oAEqtPu2nHLfSuxInA=&mgm.blockchecksum=ignore&mgm.id=3b4e2c49&mgm.logid=c454d022-2e0e-11ed-8d47-a4bf01796189&mgm.mtime=1593523093&mgm.replicahead=0&mgm.replicaindex=0, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) ) from out-queu to in-queue.
[2022-09-06 20:08:48.829311 +0200][Dump   ][PostMaster        ] [p06636710d91266.cern.ch:1095.0] All messages consumed, disable uplink
[2022-09-06 20:08:48.871322 +0200][Dump   ][XRootDTransport   ] [msg: 0x1938f18] Expecting 55 bytes of message body
[2022-09-06 20:08:48.871361 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Received message header for 0x1938f18 size: 8
[2022-09-06 20:08:48.871372 +0200][Debug  ][ExDbgMsg          ] [msg: 0x1938f18] Assigned MsgHandler: 0xd3121b60.
[2022-09-06 20:08:48.871380 +0200][Debug  ][ExDbgMsg          ] [handler: 0xd3121b60] Removed MsgHandler: 0xd3121b60 from the in-queue.
[2022-09-06 20:08:48.871397 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Received message 0x1938f18 of 63 bytes
[2022-09-06 20:08:48.871410 +0200][Dump   ][PostMaster        ] [p06636710d91266.cern.ch:1095] Handling received message: 0x1938f18.
[2022-09-06 20:08:48.871459 +0200][Dump   ][XRootD            ] [p06636710d91266.cern.ch:1095] Got a kXR_ok response to request kXR_open (file: /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root?cap.msg=QHtGNWO287qHIYzxGIORRghAXLvb9ZznlpHRAWQBQjrvMHndOOHyr5qnLo5IKSgF3c0cTK1PG2ZnHNkKhNR9kpW7g26yIqObz2OqhscSmQRsbygazsSACx/KOfQ3lzALS/GnNUQrg88uZb2wK/95O6aybtQ9mRisPnsMGEBnGnFFv4Y6KSKO5qsqlts/QxwCptqi+ZsD3iSW0MOM69SOeIRMeZtoP1HnEojYsVG+Kq6MoOMNrmYY3Eoc8eVVKjhsoEl6XP9AKXZJaS7XeN1qp2fsQERQl72jk4ehsK0Zzv/6gPbBXjCI89P3IEXpZufhQPAcYcdn0Sl/rJCTYRn8jsPBTF2g2BAA31UEdJWu7hpaSArm6cYok6TOnrlFaNcbYqVdVy4k8rtgXJAVv19rZvgXw0XtAAsw4rB2ZJs+YxXBwwUjM6kzxTiIS5VxeFs+k6FrHPMoXPnvet2tO4DsNqmBl+Ns2BN3b39SwB4vcT6c8Z36Sy2X2PH8AO/YqQie6/dZEAx/lt2qHTRgiOpk5RTDxZGEXlpjSVFleVYh1dkg/RFdpkK6liizeeO4HtcV5IrS2mz2g6i/yKLaXzvpS5Unf3QrUyruWxqDr7H55s6DWaVxcfrQBw==&cap.sym=q+CUHEBX8oAEqtPu2nHLfSuxInA=&mgm.blockchecksum=ignore&mgm.id=3b4e2c49&mgm.logid=c454d022-2e0e-11ed-8d47-a4bf01796189&mgm.mtime=1593523093&mgm.replicahead=0&mgm.replicaindex=0, mode: 00, flags: kXR_open_read kXR_async kXR_retstat )
[2022-09-06 20:08:48.871504 +0200][Debug  ][ExDbgMsg          ] [p06636710d91266.cern.ch:1095] Calling MsgHandler: 0xd3121b60 (message: kXR_open (file: /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root?cap.msg=QHtGNWO287qHIYzxGIORRghAXLvb9ZznlpHRAWQBQjrvMHndOOHyr5qnLo5IKSgF3c0cTK1PG2ZnHNkKhNR9kpW7g26yIqObz2OqhscSmQRsbygazsSACx/KOfQ3lzALS/GnNUQrg88uZb2wK/95O6aybtQ9mRisPnsMGEBnGnFFv4Y6KSKO5qsqlts/QxwCptqi+ZsD3iSW0MOM69SOeIRMeZtoP1HnEojYsVG+Kq6MoOMNrmYY3Eoc8eVVKjhsoEl6XP9AKXZJaS7XeN1qp2fsQERQl72jk4ehsK0Zzv/6gPbBXjCI89P3IEXpZufhQPAcYcdn0Sl/rJCTYRn8jsPBTF2g2BAA31UEdJWu7hpaSArm6cYok6TOnrlFaNcbYqVdVy4k8rtgXJAVv19rZvgXw0XtAAsw4rB2ZJs+YxXBwwUjM6kzxTiIS5VxeFs+k6FrHPMoXPnvet2tO4DsNqmBl+Ns2BN3b39SwB4vcT6c8Z36Sy2X2PH8AO/YqQie6/dZEAx/lt2qHTRgiOpk5RTDxZGEXlpjSVFleVYh1dkg/RFdpkK6liizeeO4HtcV5IrS2mz2g6i/yKLaXzvpS5Unf3QrUyruWxqDr7H55s6DWaVxcfrQBw==&cap.sym=q+CUHEBX8oAEqtPu2nHLfSuxInA=&mgm.blockchecksum=ignore&mgm.id=3b4e2c49&mgm.logid=c454d022-2e0e-11ed-8d47-a4bf01796189&mgm.mtime=1593523093&mgm.replicahead=0&mgm.replicaindex=0, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) ) with status: [SUCCESS] .
[2022-09-06 20:08:48.871553 +0200][Dump   ][XRootD            ] [p06636710d91266.cern.ch:1095] Parsing the response to kXR_open (file: /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root?cap.msg=QHtGNWO287qHIYzxGIORRghAXLvb9ZznlpHRAWQBQjrvMHndOOHyr5qnLo5IKSgF3c0cTK1PG2ZnHNkKhNR9kpW7g26yIqObz2OqhscSmQRsbygazsSACx/KOfQ3lzALS/GnNUQrg88uZb2wK/95O6aybtQ9mRisPnsMGEBnGnFFv4Y6KSKO5qsqlts/QxwCptqi+ZsD3iSW0MOM69SOeIRMeZtoP1HnEojYsVG+Kq6MoOMNrmYY3Eoc8eVVKjhsoEl6XP9AKXZJaS7XeN1qp2fsQERQl72jk4ehsK0Zzv/6gPbBXjCI89P3IEXpZufhQPAcYcdn0Sl/rJCTYRn8jsPBTF2g2BAA31UEdJWu7hpaSArm6cYok6TOnrlFaNcbYqVdVy4k8rtgXJAVv19rZvgXw0XtAAsw4rB2ZJs+YxXBwwUjM6kzxTiIS5VxeFs+k6FrHPMoXPnvet2tO4DsNqmBl+Ns2BN3b39SwB4vcT6c8Z36Sy2X2PH8AO/YqQie6/dZEAx/lt2qHTRgiOpk5RTDxZGEXlpjSVFleVYh1dkg/RFdpkK6liizeeO4HtcV5IrS2mz2g6i/yKLaXzvpS5Unf3QrUyruWxqDr7H55s6DWaVxcfrQBw==&cap.sym=q+CUHEBX8oAEqtPu2nHLfSuxInA=&mgm.blockchecksum=ignore&mgm.id=3b4e2c49&mgm.logid=c454d022-2e0e-11ed-8d47-a4bf01796189&mgm.mtime=1593523093&mgm.replicahead=0&mgm.replicaindex=0, mode: 00, flags: kXR_open_read kXR_async kXR_retstat ) as OpenInfo
[2022-09-06 20:08:48.871586 +0200][Dump   ][XRootD            ] [p06636710d91266.cern.ch:1095] Parsing StatInfo in response to kXR_open (file: /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root?cap.msg=QHtGNWO287qHIYzxGIORRghAXLvb9ZznlpHRAWQBQjrvMHndOOHyr5qnLo5IKSgF3c0cTK1PG2ZnHNkKhNR9kpW7g26yIqObz2OqhscSmQRsbygazsSACx/KOfQ3lzALS/GnNUQrg88uZb2wK/95O6aybtQ9mRisPnsMGEBnGnFFv4Y6KSKO5qsqlts/QxwCptqi+ZsD3iSW0MOM69SOeIRMeZtoP1HnEojYsVG+Kq6MoOMNrmYY3Eoc8eVVKjhsoEl6XP9AKXZJaS7XeN1qp2fsQERQl72jk4ehsK0Zzv/6gPbBXjCI89P3IEXpZufhQPAcYcdn0Sl/rJCTYRn8jsPBTF2g2BAA31UEdJWu7hpaSArm6cYok6TOnrlFaNcbYqVdVy4k8rtgXJAVv19rZvgXw0XtAAsw4rB2ZJs+YxXBwwUjM6kzxTiIS5VxeFs+k6FrHPMoXPnvet2tO4DsNqmBl+Ns2BN3b39SwB4vcT6c8Z36Sy2X2PH8AO/YqQie6/dZEAx/lt2qHTRgiOpk5RTDxZGEXlpjSVFleVYh1dkg/RFdpkK6liizeeO4HtcV5IrS2mz2g6i/yKLaXzvpS5Unf3QrUyruWxqDr7H55s6DWaVxcfrQBw==&cap.sym=q+CUHEBX8oAEqtPu2nHLfSuxInA=&mgm.blockchecksum=ignore&mgm.id=3b4e2c49&mgm.logid=c454d022-2e0e-11ed-8d47-a4bf01796189&mgm.mtime=1593523093&mgm.replicahead=0&mgm.replicaindex=0, mode: 00, flags: kXR_open_read kXR_async kXR_retstat )
[2022-09-06 20:08:48.871706 +0200][Debug  ][File              ] [0xd27699b0@root://eospublic.cern.ch:1094//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root?xrdcl.requuid=B3AEE882-3B58-4DB5-BF16-C07F64AE50AC] Open has returned with status [SUCCESS]
[2022-09-06 20:08:48.871739 +0200][Debug  ][File              ] [0xd27699b0@root://eospublic.cern.ch:1094//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root?xrdcl.requuid=B3AEE882-3B58-4DB5-BF16-C07F64AE50AC] successfully opened at p06636710d91266.cern.ch:1095, handle: 0x0, session id: 1
[2022-09-06 20:08:48.871771 +0200][Debug  ][XRootD            ] Redirect trace-back:
[2022-09-06 20:08:48.871771 +0200][Debug  ][XRootD            ] 	0. Redirected from: root://eospublic.cern.ch:1094//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root to: root://p06636710d91266.cern.ch:1095/
[2022-09-06 20:08:48.871785 +0200][Debug  ][ExDbgMsg          ] [p06636710d91266.cern.ch:1095] Destroying MsgHandler: 0xd3121b60.
[2022-09-06 20:08:48.871815 +0200][Debug  ][File              ] [0xd27699b0@root://eospublic.cern.ch:1094//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root?xrdcl.requuid=B3AEE882-3B58-4DB5-BF16-C07F64AE50AC] Sending a read command for handle 0x0 to p06636710d91266.cern.ch:1095
[2022-09-06 20:08:48.871855 +0200][Dump   ][XRootD            ] [p06636710d91266.cern.ch:1095] Sending message kXR_read (handle: 0x00000000, offset: 0, size: 300)
[2022-09-06 20:08:48.871880 +0200][Debug  ][ExDbgMsg          ] [p06636710d91266.cern.ch:1095] MsgHandler created: 0xd3121b60 (message: kXR_read (handle: 0x00000000, offset: 0, size: 300) ).
[2022-09-06 20:08:48.871907 +0200][Dump   ][PostMaster        ] [p06636710d91266.cern.ch:1095] Sending message kXR_read (handle: 0x00000000, offset: 0, size: 300) (0x1e9b340) through substream 0 expecting answer at 0
[2022-09-06 20:08:48.871970 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Wrote a message: kXR_read (handle: 0x00000000, offset: 0, size: 300) (0x1e9b340), 32 bytes
[2022-09-06 20:08:48.871994 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Successfully sent message: kXR_read (handle: 0x00000000, offset: 0, size: 300) (0x1e9b340).
[2022-09-06 20:08:48.872005 +0200][Dump   ][XRootD            ] [p06636710d91266.cern.ch:1095] Message kXR_read (handle: 0x00000000, offset: 0, size: 300) has been successfully sent.
[2022-09-06 20:08:48.872015 +0200][Debug  ][ExDbgMsg          ] [p06636710d91266.cern.ch:1095] Moving MsgHandler: 0xd3121b60 (message: kXR_read (handle: 0x00000000, offset: 0, size: 300) ) from out-queu to in-queue.
[2022-09-06 20:08:48.872034 +0200][Dump   ][PostMaster        ] [p06636710d91266.cern.ch:1095.0] All messages consumed, disable uplink
[2022-09-06 20:08:48.879517 +0200][Dump   ][XRootDTransport   ] [msg: 0x193da58] Expecting 300 bytes of message body
[2022-09-06 20:08:48.879554 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Received message header for 0x193da58 size: 8
[2022-09-06 20:08:48.879566 +0200][Debug  ][ExDbgMsg          ] [msg: 0x193da58] Assigned MsgHandler: 0xd3121b60.
[2022-09-06 20:08:48.879574 +0200][Debug  ][ExDbgMsg          ] [handler: 0xd3121b60] Removed MsgHandler: 0xd3121b60 from the in-queue.
[2022-09-06 20:08:48.879581 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Will use the raw handler to read body of message 0x193da58
[2022-09-06 20:08:48.879604 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Received message 0x193da58 of 308 bytes
[2022-09-06 20:08:48.879614 +0200][Dump   ][PostMaster        ] [p06636710d91266.cern.ch:1095] Handling received message: 0x193da58.
[2022-09-06 20:08:48.879662 +0200][Dump   ][XRootD            ] [p06636710d91266.cern.ch:1095] Got a kXR_ok response to request kXR_read (handle: 0x00000000, offset: 0, size: 300)
[2022-09-06 20:08:48.879689 +0200][Debug  ][ExDbgMsg          ] [p06636710d91266.cern.ch:1095] Calling MsgHandler: 0xd3121b60 (message: kXR_read (handle: 0x00000000, offset: 0, size: 300) ) with status: [SUCCESS] .
[2022-09-06 20:08:48.879702 +0200][Dump   ][XRootD            ] [p06636710d91266.cern.ch:1095] Parsing the response to kXR_read (handle: 0x00000000, offset: 0, size: 300) as ChunkInfo
[2022-09-06 20:08:48.879715 +0200][Dump   ][File              ] [0xd27699b0@root://eospublic.cern.ch:1094//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root?xrdcl.requuid=B3AEE882-3B58-4DB5-BF16-C07F64AE50AC] Got state response for message kXR_read (handle: 0x00000000, offset: 0, size: 300)
[2022-09-06 20:08:48.879736 +0200][Debug  ][ExDbgMsg          ] [p06636710d91266.cern.ch:1095] Destroying MsgHandler: 0xd3121b60.
[2022-09-06 20:08:48.879797 +0200][Debug  ][File              ] [0xd27699b0@root://eospublic.cern.ch:1094//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root?xrdcl.requuid=B3AEE882-3B58-4DB5-BF16-C07F64AE50AC] Sending a read command for handle 0x0 to p06636710d91266.cern.ch:1095
[2022-09-06 20:08:48.879823 +0200][Dump   ][XRootD            ] [p06636710d91266.cern.ch:1095] Sending message kXR_read (handle: 0x00000000, offset: 20854874, size: 104)
[2022-09-06 20:08:48.879840 +0200][Debug  ][ExDbgMsg          ] [p06636710d91266.cern.ch:1095] MsgHandler created: 0xd3121b60 (message: kXR_read (handle: 0x00000000, offset: 20854874, size: 104) ).
[2022-09-06 20:08:48.879857 +0200][Dump   ][PostMaster        ] [p06636710d91266.cern.ch:1095] Sending message kXR_read (handle: 0x00000000, offset: 20854874, size: 104) (0x1e9b4d0) through substream 0 expecting answer at 0
[2022-09-06 20:08:48.879921 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Wrote a message: kXR_read (handle: 0x00000000, offset: 20854874, size: 104) (0x1e9b4d0), 32 bytes
[2022-09-06 20:08:48.879948 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Successfully sent message: kXR_read (handle: 0x00000000, offset: 20854874, size: 104) (0x1e9b4d0).
[2022-09-06 20:08:48.879959 +0200][Dump   ][XRootD            ] [p06636710d91266.cern.ch:1095] Message kXR_read (handle: 0x00000000, offset: 20854874, size: 104) has been successfully sent.
[2022-09-06 20:08:48.879968 +0200][Debug  ][ExDbgMsg          ] [p06636710d91266.cern.ch:1095] Moving MsgHandler: 0xd3121b60 (message: kXR_read (handle: 0x00000000, offset: 20854874, size: 104) ) from out-queu to in-queue.
[2022-09-06 20:08:48.879977 +0200][Dump   ][PostMaster        ] [p06636710d91266.cern.ch:1095.0] All messages consumed, disable uplink
[2022-09-06 20:08:48.889184 +0200][Dump   ][XRootDTransport   ] [msg: 0x1938f18] Expecting 104 bytes of message body
[2022-09-06 20:08:48.889222 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Received message header for 0x1938f18 size: 8
[2022-09-06 20:08:48.889234 +0200][Debug  ][ExDbgMsg          ] [msg: 0x1938f18] Assigned MsgHandler: 0xd3121b60.
[2022-09-06 20:08:48.889242 +0200][Debug  ][ExDbgMsg          ] [handler: 0xd3121b60] Removed MsgHandler: 0xd3121b60 from the in-queue.
[2022-09-06 20:08:48.889249 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Will use the raw handler to read body of message 0x1938f18
[2022-09-06 20:08:48.889260 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Received message 0x1938f18 of 112 bytes
[2022-09-06 20:08:48.889270 +0200][Dump   ][PostMaster        ] [p06636710d91266.cern.ch:1095] Handling received message: 0x1938f18.
[2022-09-06 20:08:48.889320 +0200][Dump   ][XRootD            ] [p06636710d91266.cern.ch:1095] Got a kXR_ok response to request kXR_read (handle: 0x00000000, offset: 20854874, size: 104)
[2022-09-06 20:08:48.889345 +0200][Debug  ][ExDbgMsg          ] [p06636710d91266.cern.ch:1095] Calling MsgHandler: 0xd3121b60 (message: kXR_read (handle: 0x00000000, offset: 20854874, size: 104) ) with status: [SUCCESS] .
[2022-09-06 20:08:48.889358 +0200][Dump   ][XRootD            ] [p06636710d91266.cern.ch:1095] Parsing the response to kXR_read (handle: 0x00000000, offset: 20854874, size: 104) as ChunkInfo
[2022-09-06 20:08:48.889370 +0200][Dump   ][File              ] [0xd27699b0@root://eospublic.cern.ch:1094//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root?xrdcl.requuid=B3AEE882-3B58-4DB5-BF16-C07F64AE50AC] Got state response for message kXR_read (handle: 0x00000000, offset: 20854874, size: 104)
[2022-09-06 20:08:48.889393 +0200][Debug  ][ExDbgMsg          ] [p06636710d91266.cern.ch:1095] Destroying MsgHandler: 0xd3121b60.
[2022-09-06 20:08:48.889450 +0200][Debug  ][File              ] [0xd27699b0@root://eospublic.cern.ch:1094//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root?xrdcl.requuid=B3AEE882-3B58-4DB5-BF16-C07F64AE50AC] Sending a read command for handle 0x0 to p06636710d91266.cern.ch:1095
[2022-09-06 20:08:48.889494 +0200][Dump   ][XRootD            ] [p06636710d91266.cern.ch:1095] Sending message kXR_read (handle: 0x00000000, offset: 20854978, size: 5074)
[2022-09-06 20:08:48.889513 +0200][Debug  ][ExDbgMsg          ] [p06636710d91266.cern.ch:1095] MsgHandler created: 0xd3006d90 (message: kXR_read (handle: 0x00000000, offset: 20854978, size: 5074) ).
[2022-09-06 20:08:48.889540 +0200][Dump   ][PostMaster        ] [p06636710d91266.cern.ch:1095] Sending message kXR_read (handle: 0x00000000, offset: 20854978, size: 5074) (0x1e9d450) through substream 0 expecting answer at 0
[2022-09-06 20:08:48.889596 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Wrote a message: kXR_read (handle: 0x00000000, offset: 20854978, size: 5074) (0x1e9d450), 32 bytes
[2022-09-06 20:08:48.889611 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Successfully sent message: kXR_read (handle: 0x00000000, offset: 20854978, size: 5074) (0x1e9d450).
[2022-09-06 20:08:48.889619 +0200][Dump   ][XRootD            ] [p06636710d91266.cern.ch:1095] Message kXR_read (handle: 0x00000000, offset: 20854978, size: 5074) has been successfully sent.
[2022-09-06 20:08:48.889627 +0200][Debug  ][ExDbgMsg          ] [p06636710d91266.cern.ch:1095] Moving MsgHandler: 0xd3006d90 (message: kXR_read (handle: 0x00000000, offset: 20854978, size: 5074) ) from out-queu to in-queue.
[2022-09-06 20:08:48.889635 +0200][Dump   ][PostMaster        ] [p06636710d91266.cern.ch:1095.0] All messages consumed, disable uplink
[2022-09-06 20:08:48.890400 +0200][Dump   ][XRootDTransport   ] [msg: 0x1938f18] Expecting 5074 bytes of message body
[2022-09-06 20:08:48.890439 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Received message header for 0x1938f18 size: 8
[2022-09-06 20:08:48.890450 +0200][Debug  ][ExDbgMsg          ] [msg: 0x1938f18] Assigned MsgHandler: 0xd3006d90.
[2022-09-06 20:08:48.890458 +0200][Debug  ][ExDbgMsg          ] [handler: 0xd3006d90] Removed MsgHandler: 0xd3006d90 from the in-queue.
[2022-09-06 20:08:48.890465 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Will use the raw handler to read body of message 0x1938f18
[2022-09-06 20:08:48.890487 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Received message 0x1938f18 of 5082 bytes
[2022-09-06 20:08:48.890507 +0200][Dump   ][PostMaster        ] [p06636710d91266.cern.ch:1095] Handling received message: 0x1938f18.
[2022-09-06 20:08:48.890547 +0200][Dump   ][XRootD            ] [p06636710d91266.cern.ch:1095] Got a kXR_ok response to request kXR_read (handle: 0x00000000, offset: 20854978, size: 5074)
[2022-09-06 20:08:48.890559 +0200][Debug  ][ExDbgMsg          ] [p06636710d91266.cern.ch:1095] Calling MsgHandler: 0xd3006d90 (message: kXR_read (handle: 0x00000000, offset: 20854978, size: 5074) ) with status: [SUCCESS] .
[2022-09-06 20:08:48.890571 +0200][Dump   ][XRootD            ] [p06636710d91266.cern.ch:1095] Parsing the response to kXR_read (handle: 0x00000000, offset: 20854978, size: 5074) as ChunkInfo
[2022-09-06 20:08:48.890581 +0200][Dump   ][File              ] [0xd27699b0@root://eospublic.cern.ch:1094//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root?xrdcl.requuid=B3AEE882-3B58-4DB5-BF16-C07F64AE50AC] Got state response for message kXR_read (handle: 0x00000000, offset: 20854978, size: 5074)
[2022-09-06 20:08:48.890602 +0200][Debug  ][ExDbgMsg          ] [p06636710d91266.cern.ch:1095] Destroying MsgHandler: 0xd3006d90.
[2022-09-06 20:08:48.920197 +0200][Dump   ][Utility           ] URL: root://p06636710d91266.cern.ch:1095//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root?cap.msg=QHtGNWO287qHIYzxGIORRghAXLvb9ZznlpHRAWQBQjrvMHndOOHyr5qnLo5IKSgF3c0cTK1PG2ZnHNkKhNR9kpW7g26yIqObz2OqhscSmQRsbygazsSACx/KOfQ3lzALS/GnNUQrg88uZb2wK/95O6aybtQ9mRisPnsMGEBnGnFFv4Y6KSKO5qsqlts/QxwCptqi+ZsD3iSW0MOM69SOeIRMeZtoP1HnEojYsVG+Kq6MoOMNrmYY3Eoc8eVVKjhsoEl6XP9AKXZJaS7XeN1qp2fsQERQl72jk4ehsK0Zzv/6gPbBXjCI89P3IEXpZufhQPAcYcdn0Sl/rJCTYRn8jsPBTF2g2BAA31UEdJWu7hpaSArm6cYok6TOnrlFaNcbYqVdVy4k8rtgXJAVv19rZvgXw0XtAAsw4rB2ZJs+YxXBwwUjM6kzxTiIS5VxeFs+k6FrHPMoXPnvet2tO4DsNqmBl+Ns2BN3b39SwB4vcT6c8Z36Sy2X2PH8AO/YqQie6/dZEAx/lt2qHTRgiOpk5RTDxZGEXlpjSVFleVYh1dkg/RFdpkK6liizeeO4HtcV5IrS2mz2g6i/yKLaXzvpS5Unf3QrUyruWxqDr7H55s6DWaVxcfrQBw==&cap.sym=q+CUHEBX8oAEqtPu2nHLfSuxInA=&mgm.blockchecksum=ignore&mgm.id=3b4e2c49&mgm.logid=c454d022-2e0e-11ed-8d47-a4bf01796189&mgm.mtime=1593523093&mgm.replicahead=0&mgm.replicaindex=0&xrdcl.requuid=B3AEE882-3B58-4DB5-BF16-C07F64AE50AC
[2022-09-06 20:08:48.920197 +0200][Dump   ][Utility           ] Protocol:  root
[2022-09-06 20:08:48.920197 +0200][Dump   ][Utility           ] User Name:
[2022-09-06 20:08:48.920197 +0200][Dump   ][Utility           ] Password:
[2022-09-06 20:08:48.920197 +0200][Dump   ][Utility           ] Host Name: p06636710d91266.cern.ch
[2022-09-06 20:08:48.920197 +0200][Dump   ][Utility           ] Port:      1095
[2022-09-06 20:08:48.920197 +0200][Dump   ][Utility           ] Path:      /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root
[2022-09-06 20:08:48.920272 +0200][Dump   ][Utility           ] URL: p06636710d91266.cern.ch:1095
[2022-09-06 20:08:48.920272 +0200][Dump   ][Utility           ] Protocol:  root
[2022-09-06 20:08:48.920272 +0200][Dump   ][Utility           ] User Name:
[2022-09-06 20:08:48.920272 +0200][Dump   ][Utility           ] Password:
[2022-09-06 20:08:48.920272 +0200][Dump   ][Utility           ] Host Name: p06636710d91266.cern.ch
[2022-09-06 20:08:48.920272 +0200][Dump   ][Utility           ] Port:      1095
[2022-09-06 20:08:48.920272 +0200][Dump   ][Utility           ] Path:
[2022-09-06 20:08:48.920289 +0200][Dump   ][Utility           ] URL: root://p06636710d91266.cern.ch:1095/
[2022-09-06 20:08:48.920289 +0200][Dump   ][Utility           ] Protocol:  root
[2022-09-06 20:08:48.920289 +0200][Dump   ][Utility           ] User Name:
[2022-09-06 20:08:48.920289 +0200][Dump   ][Utility           ] Password:
[2022-09-06 20:08:48.920289 +0200][Dump   ][Utility           ] Host Name: p06636710d91266.cern.ch
[2022-09-06 20:08:48.920289 +0200][Dump   ][Utility           ] Port:      1095
[2022-09-06 20:08:48.920289 +0200][Dump   ][Utility           ] Path:
[2022-09-06 20:08:48.920300 +0200][Dump   ][Utility           ] URL: root://p06636710d91266.cern.ch:1095/
[2022-09-06 20:08:48.920300 +0200][Dump   ][Utility           ] Protocol:  root
[2022-09-06 20:08:48.920300 +0200][Dump   ][Utility           ] User Name:
[2022-09-06 20:08:48.920300 +0200][Dump   ][Utility           ] Password:
[2022-09-06 20:08:48.920300 +0200][Dump   ][Utility           ] Host Name: p06636710d91266.cern.ch
[2022-09-06 20:08:48.920300 +0200][Dump   ][Utility           ] Port:      1095
[2022-09-06 20:08:48.920300 +0200][Dump   ][Utility           ] Path:
[2022-09-06 20:08:48.920326 +0200][Dump   ][Utility           ] URL: root://p06636710d91266.cern.ch:1095/
[2022-09-06 20:08:48.920326 +0200][Dump   ][Utility           ] Protocol:  root
[2022-09-06 20:08:48.920326 +0200][Dump   ][Utility           ] User Name:
[2022-09-06 20:08:48.920326 +0200][Dump   ][Utility           ] Password:
[2022-09-06 20:08:48.920326 +0200][Dump   ][Utility           ] Host Name: p06636710d91266.cern.ch
[2022-09-06 20:08:48.920326 +0200][Dump   ][Utility           ] Port:      1095
[2022-09-06 20:08:48.920326 +0200][Dump   ][Utility           ] Path:
[2022-09-06 20:08:48.920339 +0200][Dump   ][FileSystem        ] [0x193da40@p06636710d91266.cern.ch:1095] Sending kXR_query (code: kXR_Qconfig, arg length: 28)
[2022-09-06 20:08:48.920345 +0200][Dump   ][XRootD            ] [p06636710d91266.cern.ch:1095] Sending message kXR_query (code: kXR_Qconfig, arg length: 28)
[2022-09-06 20:08:48.920352 +0200][Debug  ][ExDbgMsg          ] [p06636710d91266.cern.ch:1095] MsgHandler created: 0xb3204080 (message: kXR_query (code: kXR_Qconfig, arg length: 28) ).
[2022-09-06 20:08:48.920359 +0200][Dump   ][PostMaster        ] [p06636710d91266.cern.ch:1095] Sending message kXR_query (code: kXR_Qconfig, arg length: 28) (0x1e030c0) through substream 0 expecting answer at 0
[2022-09-06 20:08:48.920394 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Wrote a message: kXR_query (code: kXR_Qconfig, arg length: 28) (0x1e030c0), 52 bytes
[2022-09-06 20:08:48.920403 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Successfully sent message: kXR_query (code: kXR_Qconfig, arg length: 28) (0x1e030c0).
[2022-09-06 20:08:48.920409 +0200][Dump   ][XRootD            ] [p06636710d91266.cern.ch:1095] Message kXR_query (code: kXR_Qconfig, arg length: 28) has been successfully sent.
[2022-09-06 20:08:48.920413 +0200][Debug  ][ExDbgMsg          ] [p06636710d91266.cern.ch:1095] Moving MsgHandler: 0xb3204080 (message: kXR_query (code: kXR_Qconfig, arg length: 28) ) from out-queu to in-queue.
[2022-09-06 20:08:48.920418 +0200][Dump   ][PostMaster        ] [p06636710d91266.cern.ch:1095.0] All messages consumed, disable uplink
[2022-09-06 20:08:48.920965 +0200][Dump   ][XRootDTransport   ] [msg: 0x1952bf8] Expecting 13 bytes of message body
[2022-09-06 20:08:48.920978 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Received message header for 0x1952bf8 size: 8
[2022-09-06 20:08:48.920984 +0200][Debug  ][ExDbgMsg          ] [msg: 0x1952bf8] Assigned MsgHandler: 0xb3204080.
[2022-09-06 20:08:48.920988 +0200][Debug  ][ExDbgMsg          ] [handler: 0xb3204080] Removed MsgHandler: 0xb3204080 from the in-queue.
[2022-09-06 20:08:48.920994 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Received message 0x1952bf8 of 21 bytes
[2022-09-06 20:08:48.920999 +0200][Dump   ][PostMaster        ] [p06636710d91266.cern.ch:1095] Handling received message: 0x1952bf8.
[2022-09-06 20:08:48.921017 +0200][Dump   ][XRootD            ] [p06636710d91266.cern.ch:1095] Got a kXR_ok response to request kXR_query (code: kXR_Qconfig, arg length: 28)
[2022-09-06 20:08:48.921023 +0200][Debug  ][ExDbgMsg          ] [p06636710d91266.cern.ch:1095] Calling MsgHandler: 0xb3204080 (message: kXR_query (code: kXR_Qconfig, arg length: 28) ) with status: [SUCCESS] .
[2022-09-06 20:08:48.921028 +0200][Dump   ][XRootD            ] [p06636710d91266.cern.ch:1095] Parsing the response to kXR_query (code: kXR_Qconfig, arg length: 28) as BinaryData
[2022-09-06 20:08:48.921034 +0200][Dump   ][FileSystem        ] [0x193da40@p06636710d91266.cern.ch:1095] Assigning p06636710d91266.cern.ch:1095 as last URL
[2022-09-06 20:08:48.921042 +0200][Debug  ][ExDbgMsg          ] [p06636710d91266.cern.ch:1095] Destroying MsgHandler: 0xb3204080.
[2022-09-06 20:08:48.921263 +0200][Debug  ][File              ] [0xd27699b0@root://eospublic.cern.ch:1094//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root?xrdcl.requuid=B3AEE882-3B58-4DB5-BF16-C07F64AE50AC] Sending a close command for handle 0x0 to p06636710d91266.cern.ch:1095
[2022-09-06 20:08:48.921281 +0200][Dump   ][XRootD            ] [p06636710d91266.cern.ch:1095] Sending message kXR_close (handle: 0x00000000)
[2022-09-06 20:08:48.921290 +0200][Debug  ][ExDbgMsg          ] [p06636710d91266.cern.ch:1095] MsgHandler created: 0xb3204080 (message: kXR_close (handle: 0x00000000) ).
[2022-09-06 20:08:48.921298 +0200][Dump   ][PostMaster        ] [p06636710d91266.cern.ch:1095] Sending message kXR_close (handle: 0x00000000) (0x1e030c0) through substream 0 expecting answer at 0
[2022-09-06 20:08:48.921328 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Wrote a message: kXR_close (handle: 0x00000000) (0x1e030c0), 24 bytes
[2022-09-06 20:08:48.921335 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Successfully sent message: kXR_close (handle: 0x00000000) (0x1e030c0).
[2022-09-06 20:08:48.921339 +0200][Dump   ][XRootD            ] [p06636710d91266.cern.ch:1095] Message kXR_close (handle: 0x00000000) has been successfully sent.
[2022-09-06 20:08:48.921342 +0200][Debug  ][ExDbgMsg          ] [p06636710d91266.cern.ch:1095] Moving MsgHandler: 0xb3204080 (message: kXR_close (handle: 0x00000000) ) from out-queu to in-queue.
[2022-09-06 20:08:48.921347 +0200][Dump   ][PostMaster        ] [p06636710d91266.cern.ch:1095.0] All messages consumed, disable uplink
[2022-09-06 20:08:48.922246 +0200][Dump   ][XRootDTransport   ] [msg: 0x197ca98] Expecting 0 bytes of message body
[2022-09-06 20:08:48.922272 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Received message header for 0x197ca98 size: 8
[2022-09-06 20:08:48.922279 +0200][Debug  ][ExDbgMsg          ] [msg: 0x197ca98] Assigned MsgHandler: 0xb3204080.
[2022-09-06 20:08:48.922283 +0200][Debug  ][ExDbgMsg          ] [handler: 0xb3204080] Removed MsgHandler: 0xb3204080 from the in-queue.
[2022-09-06 20:08:48.922287 +0200][Dump   ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Received message 0x197ca98 of 8 bytes
[2022-09-06 20:08:48.922292 +0200][Dump   ][PostMaster        ] [p06636710d91266.cern.ch:1095] Handling received message: 0x197ca98.
[2022-09-06 20:08:48.922313 +0200][Dump   ][XRootD            ] [p06636710d91266.cern.ch:1095] Got a kXR_ok response to request kXR_close (handle: 0x00000000)
[2022-09-06 20:08:48.922320 +0200][Debug  ][ExDbgMsg          ] [p06636710d91266.cern.ch:1095] Calling MsgHandler: 0xb3204080 (message: kXR_close (handle: 0x00000000) ) with status: [SUCCESS] .
[2022-09-06 20:08:48.922327 +0200][Debug  ][File              ] [0xd27699b0@root://eospublic.cern.ch:1094//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root?xrdcl.requuid=B3AEE882-3B58-4DB5-BF16-C07F64AE50AC] Close returned from p06636710d91266.cern.ch:1095 with: [SUCCESS]
[2022-09-06 20:08:48.922333 +0200][Dump   ][File              ] [0xd27699b0@root://eospublic.cern.ch:1094//eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root?xrdcl.requuid=B3AEE882-3B58-4DB5-BF16-C07F64AE50AC] Items in the fly 0, queued for recovery 0
[2022-09-06 20:08:48.922344 +0200][Debug  ][ExDbgMsg          ] [p06636710d91266.cern.ch:1095] Destroying MsgHandler: 0xb3204080.
[2022-09-06 20:08:48.922547 +0200][Debug  ][JobMgr            ] Stopping the job manager...
[2022-09-06 20:08:48.922563 +0200][Dump   ][JobMgr            ] Stopping worker #0...
[2022-09-06 20:08:48.922616 +0200][Dump   ][JobMgr            ] Worker #0 stopped
[2022-09-06 20:08:48.922626 +0200][Dump   ][JobMgr            ] Stopping worker #1...
[2022-09-06 20:08:48.922653 +0200][Dump   ][JobMgr            ] Worker #1 stopped
[2022-09-06 20:08:48.922661 +0200][Dump   ][JobMgr            ] Stopping worker #2...
[2022-09-06 20:08:48.922687 +0200][Dump   ][JobMgr            ] Worker #2 stopped
[2022-09-06 20:08:48.922700 +0200][Debug  ][JobMgr            ] Job manager stopped
[2022-09-06 20:08:48.922705 +0200][Debug  ][TaskMgr           ] Stopping the task manager...
[2022-09-06 20:08:48.922730 +0200][Debug  ][TaskMgr           ] Task manager stopped
[2022-09-06 20:08:48.922737 +0200][Debug  ][Poller            ] Stopping the poller...
[2022-09-06 20:08:48.922785 +0200][Debug  ][TaskMgr           ] Requesting unregistration of: "TickGeneratorTask for: root://eospublic.cern.ch:1094"
[2022-09-06 20:08:48.922795 +0200][Debug  ][AsyncSock         ] [eospublic.cern.ch:1094.0] Closing the socket
[2022-09-06 20:08:48.922800 +0200][Debug  ][Poller            ] <[::ffff:128.141.187.194]:62656><--><[::ffff:128.142.160.145]:1094> Removing socket from the poller
[2022-09-06 20:08:48.922817 +0200][Debug  ][PostMaster        ] [eospublic.cern.ch:1094] Destroying stream
[2022-09-06 20:08:48.922822 +0200][Debug  ][AsyncSock         ] [eospublic.cern.ch:1094.0] Closing the socket
[2022-09-06 20:08:48.922831 +0200][Debug  ][TaskMgr           ] Requesting unregistration of: "TickGeneratorTask for: root://p06636710d91266.cern.ch:1095"
[2022-09-06 20:08:48.922835 +0200][Debug  ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Closing the socket
[2022-09-06 20:08:48.922839 +0200][Debug  ][Poller            ] <[::ffff:128.141.187.194]:62658><--><[::ffff:128.142.215.72]:1095> Removing socket from the poller
[2022-09-06 20:08:48.922848 +0200][Debug  ][PostMaster        ] [p06636710d91266.cern.ch:1095] Destroying stream
[2022-09-06 20:08:48.922852 +0200][Debug  ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Closing the socket

@Axel-Naumann
Copy link
Author

Axel-Naumann commented Sep 7, 2022

Looks like broken ipv6 routing? EDIT: confirmed, turning off ipv6 works around this.

Is it xrootd's responsibility to be more resilient in this case?

@abh3
Copy link
Member

abh3 commented Sep 8, 2022

Hmm, according to the log it tried IPv6 and found that it did not work and then tried IPv4 and everything worked after that. So, where do you see that it is not resilient -- I must be missing it.

@Axel-Naumann
Copy link
Author

Indeed! Otoh it seems to try for every operation (given the overall slowdown of the reading to >40 minutes, from originally 30 seconds), and I'd hope that the resilience could happen a bit faster than 2.5 minutes - but I do not know the details nor whether that's cause by our usage in ROOT or xrootd.

This seems to have been caused by broken ipv6 routing; renewing the ipv6 address resurrected things to a point where now ipv6 works on that machine. I could try with a hand-assigned, hopefully not routed ipv6 address to get more of a log dump of what happens after the initial connection should that be useful?

@bbockelm
Copy link
Contributor

bbockelm commented Sep 8, 2022

A common solution would be RFC 8305 - the "happy eyeballs" algorithm. This is implemented by browsers to smooth the transition to V6 -- basically, after ~100ms waiting for a IPv6 TCP connection, it starts a second parallel connection attempt with V4 and then use the first connection to complete.

Of course, this somewhat tricky concurrency and the extra complexity may only be worthwhile for big applications like a browser.

The problem here is that IPv6 is fully functional according to the OS (there's a route to the destination, there's a global IP address, nothing is sending back ICMP packets with "no route to host" to quickly terminate the connection attempt) so the routing configuration error is indistinguishable from the case of "server is unresponsive". Hence, you're hitting the connection timeout before the "second" DNS address is tried.

Perhaps a simpler "fail fast" algorithm than Happy Eyeballs is, for hostnames which resolve to N addresses, have a "short connection timeout" for the first N-1 addresses and use the standard connection timeout for the final address.

The downside of the latter idea is "complexity kills" for what is ultimately an end-user misconfiguration. The potential upside is that it'd help immensely with cases where the N independent addresses represent N independent servers -- an unresponsive server (which users aren't at fault for) would be quickly ignored instead of having the client wait for the full timeout window.

@simonmichal
Copy link
Contributor

Hi guys, sorry the late replay but I took few days off.

Otoh it seems to try for every operation (given the overall slowdown of the reading to >40 minutes, from originally 30 seconds),

@Axel-Naumann : I had a look at the logs and here's what I see:

The first request is being send at:

[2022-09-06 20:06:06.225956 +0200][Dump   ][XRootD            ] [eospublic.cern.ch:1094] Sending message kXR_open (file: /eos/root-eos/cms_opendata_2012_nanoaod_skimmed/ZZTo4mu.root, mode: 00, flags: kXR_open_read kXR_async kXR_retstat )

this triggers the client to open a connection, the client first fails to connect with IPv6 and then retries and succeeds with IPv4 (this takes about ~1.5 min):

[2022-09-06 20:06:06.228241 +0200][Debug  ][AsyncSock         ] [eospublic.cern.ch:1094.0] Attempting connection to [2001:1458:301:17::100:e]:1094
...
[2022-09-06 20:07:21.227311 +0200][Error  ][AsyncSock         ] [eospublic.cern.ch:1094.0] Unable to connect: operation timed out
...
[2022-09-06 20:07:21.227431 +0200][Debug  ][AsyncSock         ] [eospublic.cern.ch:1094.0] Attempting connection to [::ffff:128.142.160.145]:1094
...
[2022-09-06 20:07:27.591630 +0200][Debug  ][PostMaster        ] [eospublic.cern.ch:1094] Stream 0 connected.

then the client gets redirected to a data server and again fails to connect to the IPv6 address but then succeeds with IPv4 (this again takes less than 1.5 min):

[2022-09-06 20:07:27.606806 +0200][Debug  ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Attempting connection to [2001:1458:301:c4::100:8]:1095
...
[2022-09-06 20:08:42.604962 +0200][Error  ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Unable to connect: operation timed out
...
[2022-09-06 20:08:42.605062 +0200][Debug  ][AsyncSock         ] [p06636710d91266.cern.ch:1095.0] Attempting connection to [::ffff:128.142.215.72]:1095
...
[2022-09-06 20:08:48.829024 +0200][Debug  ][PostMaster        ] [p06636710d91266.cern.ch:1095] Stream 0 connected.

After a successful open, the client sends 3 read requests, a query and finally closes the file at:

[2022-09-06 20:08:48.922313 +0200][Dump   ][XRootD            ] [p06636710d91266.cern.ch:1095] Got a kXR_ok response to request kXR_close (handle: 0x00000000)

In total it takes about 2 minutes 40 seconds, now I don't understand where are the 40 minutes you mention coming from? Once the connection is established it is reused for all the request the client issues.

and I'd hope that the resilience could happen a bit faster than 2.5 minutes - but I do not know the details nor whether that's cause by our usage in ROOT or xrootd.

It is tunable, you can set the connection window with XRD_CONNECTIONWINDOW envar (the default is 120 seconds).

Perhaps a simpler "fail fast" algorithm than Happy Eyeballs is, for hostnames which resolve to N addresses, have a "short connection timeout" for the first N-1 addresses and use the standard connection timeout for the final address.

The downside of the latter idea is "complexity kills" for what is ultimately an end-user misconfiguration. The potential upside is that it'd help immensely with cases where the N independent addresses represent N independent servers -- an unresponsive server (which users aren't at fault for) would be quickly ignored instead of having the client wait for the full timeout window.

@bbockelm : we could implement this as a feature to be enabled by the user

@eguiraud
Copy link

I don't understand where are the 40 minutes you mention coming from?

The original application that demonstrated the problem made several TFile::Open calls, each took a few minutes and that added up to a total runtime of up to 40 minutes.

@simonmichal
Copy link
Contributor

@eguiraud : OK this explains the 40 minutes, thanks!

@simonmichal
Copy link
Contributor

P. S. well, it explains the 40 minutes as long as the files that were opened were located on different storage servers (which most likely is true)

@Axel-Naumann
Copy link
Author

Axel-Naumann commented Sep 26, 2022

Just as a cross check, could you verify that the full debug log (attached) of the >20 minute run is indeed due to the different storage servers, and not due to ROOT / xrootd forgetting that ipv6 isn't a viable option?
broken-ipv6.log

@simonmichal
Copy link
Contributor

Well, in a sense it is both. For each file you suffer from the connection timeout because you need to open a new connection to a different data server and the IPv6 address is not reachable. If all the files would be on the same data server, once the connection is open it would be reused for each of them. You could avoid this effect of aggregated connection timeout if you would open those files in parallel.

@simonmichal
Copy link
Contributor

P. S. As you might know, we have now the so called declarative API that makes it much easier to implement parallel access, maybe there's room for some collaboration in this area?

@amadio
Copy link
Member

amadio commented Oct 12, 2023

I think this is understood, and there isn't really a bug to be fixed on the XRootD side (I looked at the logs and confirmed that the timeouts are for different servers), so I'm closing this ticket. Please open a new ticket if necessary.

@amadio amadio closed this as completed Oct 12, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

6 participants